1
|
|
|
<?php |
2
|
|
|
/** |
3
|
|
|
* @link http://www.yiiframework.com/ |
4
|
|
|
* @copyright Copyright (c) 2008 Yii Software LLC |
5
|
|
|
* @license http://www.yiiframework.com/license/ |
6
|
|
|
*/ |
7
|
|
|
|
8
|
|
|
namespace yii\log; |
9
|
|
|
|
10
|
|
|
use Yii; |
11
|
|
|
use yii\base\Component; |
12
|
|
|
|
13
|
|
|
/** |
14
|
|
|
* Logger records logged messages in memory and sends them to different targets if [[dispatcher]] is set. |
15
|
|
|
* |
16
|
|
|
* A Logger instance can be accessed via `Yii::getLogger()`. You can call the method [[log()]] to record a single log message. |
17
|
|
|
* For convenience, a set of shortcut methods are provided for logging messages of various severity levels |
18
|
|
|
* via the [[Yii]] class: |
19
|
|
|
* |
20
|
|
|
* - [[Yii::trace()]] |
21
|
|
|
* - [[Yii::error()]] |
22
|
|
|
* - [[Yii::warning()]] |
23
|
|
|
* - [[Yii::info()]] |
24
|
|
|
* - [[Yii::beginProfile()]] |
25
|
|
|
* - [[Yii::endProfile()]] |
26
|
|
|
* |
27
|
|
|
* For more details and usage information on Logger, see the [guide article on logging](guide:runtime-logging). |
28
|
|
|
* |
29
|
|
|
* When the application ends or [[flushInterval]] is reached, Logger will call [[flush()]] |
30
|
|
|
* to send logged messages to different log targets, such as [[FileTarget|file]], [[EmailTarget|email]], |
31
|
|
|
* or [[DbTarget|database]], with the help of the [[dispatcher]]. |
32
|
|
|
* |
33
|
|
|
* @property array $dbProfiling The first element indicates the number of SQL statements executed, and the |
34
|
|
|
* second element the total time spent in SQL execution. This property is read-only. |
35
|
|
|
* @property float $elapsedTime The total elapsed time in seconds for current request. This property is |
36
|
|
|
* read-only. |
37
|
|
|
* @property array $profiling The profiling results. Each element is an array consisting of these elements: |
38
|
|
|
* `info`, `category`, `timestamp`, `trace`, `level`, `duration`, `memory`, `memoryDiff`. This property is read-only. |
39
|
|
|
* |
40
|
|
|
* @author Qiang Xue <[email protected]> |
41
|
|
|
* @since 2.0 |
42
|
|
|
*/ |
43
|
|
|
class Logger extends Component |
44
|
|
|
{ |
45
|
|
|
/** |
46
|
|
|
* Error message level. An error message is one that indicates the abnormal termination of the |
47
|
|
|
* application and may require developer's handling. |
48
|
|
|
*/ |
49
|
|
|
const LEVEL_ERROR = 0x01; |
50
|
|
|
/** |
51
|
|
|
* Warning message level. A warning message is one that indicates some abnormal happens but |
52
|
|
|
* the application is able to continue to run. Developers should pay attention to this message. |
53
|
|
|
*/ |
54
|
|
|
const LEVEL_WARNING = 0x02; |
55
|
|
|
/** |
56
|
|
|
* Informational message level. An informational message is one that includes certain information |
57
|
|
|
* for developers to review. |
58
|
|
|
*/ |
59
|
|
|
const LEVEL_INFO = 0x04; |
60
|
|
|
/** |
61
|
|
|
* Tracing message level. An tracing message is one that reveals the code execution flow. |
62
|
|
|
*/ |
63
|
|
|
const LEVEL_TRACE = 0x08; |
64
|
|
|
/** |
65
|
|
|
* Profiling message level. This indicates the message is for profiling purpose. |
66
|
|
|
*/ |
67
|
|
|
const LEVEL_PROFILE = 0x40; |
68
|
|
|
/** |
69
|
|
|
* Profiling message level. This indicates the message is for profiling purpose. It marks the |
70
|
|
|
* beginning of a profiling block. |
71
|
|
|
*/ |
72
|
|
|
const LEVEL_PROFILE_BEGIN = 0x50; |
73
|
|
|
/** |
74
|
|
|
* Profiling message level. This indicates the message is for profiling purpose. It marks the |
75
|
|
|
* end of a profiling block. |
76
|
|
|
*/ |
77
|
|
|
const LEVEL_PROFILE_END = 0x60; |
78
|
|
|
|
79
|
|
|
/** |
80
|
|
|
* @var array logged messages. This property is managed by [[log()]] and [[flush()]]. |
81
|
|
|
* Each log message is of the following structure: |
82
|
|
|
* |
83
|
|
|
* ``` |
84
|
|
|
* [ |
85
|
|
|
* [0] => message (mixed, can be a string or some complex data, such as an exception object) |
86
|
|
|
* [1] => level (integer) |
87
|
|
|
* [2] => category (string) |
88
|
|
|
* [3] => timestamp (float, obtained by microtime(true)) |
89
|
|
|
* [4] => traces (array, debug backtrace, contains the application code call stacks) |
90
|
|
|
* [5] => memory usage in bytes (int, obtained by memory_get_usage()), available since version 2.0.11. |
91
|
|
|
* ] |
92
|
|
|
* ``` |
93
|
|
|
*/ |
94
|
|
|
public $messages = []; |
95
|
|
|
/** |
96
|
|
|
* @var int how many messages should be logged before they are flushed from memory and sent to targets. |
97
|
|
|
* Defaults to 1000, meaning the [[flush]] method will be invoked once every 1000 messages logged. |
98
|
|
|
* Set this property to be 0 if you don't want to flush messages until the application terminates. |
99
|
|
|
* This property mainly affects how much memory will be taken by the logged messages. |
100
|
|
|
* A smaller value means less memory, but will increase the execution time due to the overhead of [[flush()]]. |
101
|
|
|
*/ |
102
|
|
|
public $flushInterval = 1000; |
103
|
|
|
/** |
104
|
|
|
* @var int how much call stack information (file name and line number) should be logged for each message. |
105
|
|
|
* If it is greater than 0, at most that number of call stacks will be logged. Note that only application |
106
|
|
|
* call stacks are counted. |
107
|
|
|
*/ |
108
|
|
|
public $traceLevel = 0; |
109
|
|
|
/** |
110
|
|
|
* @var Dispatcher the message dispatcher |
111
|
|
|
*/ |
112
|
|
|
public $dispatcher; |
113
|
|
|
|
114
|
|
|
|
115
|
|
|
/** |
116
|
|
|
* Initializes the logger by registering [[flush()]] as a shutdown function. |
117
|
22 |
|
*/ |
118
|
|
|
public function init() |
119
|
22 |
|
{ |
120
|
22 |
|
parent::init(); |
121
|
|
|
register_shutdown_function(function () { |
122
|
|
|
// make regular flush before other shutdown functions, which allows session data collection and so on |
123
|
|
|
$this->flush(); |
124
|
|
|
// make sure log entries written by shutdown functions are also flushed |
125
|
|
|
// ensure "flush()" is called last when there are multiple shutdown functions |
126
|
22 |
|
register_shutdown_function([$this, 'flush'], true); |
127
|
22 |
|
}); |
128
|
|
|
} |
129
|
|
|
|
130
|
|
|
/** |
131
|
|
|
* Logs a message with the given type and category. |
132
|
|
|
* If [[traceLevel]] is greater than 0, additional call stack information about |
133
|
|
|
* the application code will be logged as well. |
134
|
|
|
* @param string|array $message the message to be logged. This can be a simple string or a more |
135
|
|
|
* complex data structure that will be handled by a [[Target|log target]]. |
136
|
|
|
* @param int $level the level of the message. This must be one of the following: |
137
|
|
|
* `Logger::LEVEL_ERROR`, `Logger::LEVEL_WARNING`, `Logger::LEVEL_INFO`, `Logger::LEVEL_TRACE`, |
138
|
|
|
* `Logger::LEVEL_PROFILE_BEGIN`, `Logger::LEVEL_PROFILE_END`. |
139
|
|
|
* @param string $category the category of the message. |
140
|
963 |
|
*/ |
141
|
|
|
public function log($message, $level, $category = 'application') |
142
|
963 |
|
{ |
143
|
963 |
|
$time = microtime(true); |
144
|
963 |
|
$traces = []; |
145
|
1 |
|
if ($this->traceLevel > 0) { |
146
|
1 |
|
$count = 0; |
147
|
1 |
|
$ts = debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS); |
148
|
1 |
|
array_pop($ts); // remove the last trace since it would be the entry script, not very useful |
149
|
1 |
|
foreach ($ts as $trace) { |
150
|
1 |
|
if (isset($trace['file'], $trace['line']) && strpos($trace['file'], YII2_PATH) !== 0) { |
151
|
1 |
|
unset($trace['object'], $trace['args']); |
152
|
1 |
|
$traces[] = $trace; |
153
|
1 |
|
if (++$count >= $this->traceLevel) { |
154
|
|
|
break; |
155
|
1 |
|
} |
156
|
1 |
|
} |
157
|
1 |
|
} |
158
|
963 |
|
} |
159
|
963 |
|
$this->messages[] = [$message, $level, $category, $time, $traces, memory_get_usage()]; |
160
|
51 |
|
if ($this->flushInterval > 0 && count($this->messages) >= $this->flushInterval) { |
161
|
51 |
|
$this->flush(); |
162
|
963 |
|
} |
163
|
|
|
} |
164
|
|
|
|
165
|
|
|
/** |
166
|
|
|
* Flushes log messages from memory to targets. |
167
|
|
|
* @param bool $final whether this is a final call during a request. |
168
|
56 |
|
*/ |
169
|
|
|
public function flush($final = false) |
170
|
56 |
|
{ |
171
|
|
|
$messages = $this->messages; |
172
|
|
|
// https://github.com/yiisoft/yii2/issues/5619 |
173
|
56 |
|
// new messages could be logged while the existing ones are being handled by targets |
174
|
56 |
|
$this->messages = []; |
175
|
55 |
|
if ($this->dispatcher instanceof Dispatcher) { |
176
|
55 |
|
$this->dispatcher->dispatch($messages, $final); |
177
|
56 |
|
} |
178
|
|
|
} |
179
|
|
|
|
180
|
|
|
/** |
181
|
|
|
* Returns the total elapsed time since the start of the current request. |
182
|
|
|
* This method calculates the difference between now and the timestamp |
183
|
|
|
* defined by constant `YII_BEGIN_TIME` which is evaluated at the beginning |
184
|
|
|
* of [[\yii\BaseYii]] class file. |
185
|
|
|
* @return float the total elapsed time in seconds for current request. |
186
|
1 |
|
*/ |
187
|
|
|
public function getElapsedTime() |
188
|
1 |
|
{ |
189
|
|
|
return microtime(true) - YII_BEGIN_TIME; |
190
|
|
|
} |
191
|
|
|
|
192
|
|
|
/** |
193
|
|
|
* Returns the profiling results. |
194
|
|
|
* |
195
|
|
|
* By default, all profiling results will be returned. You may provide |
196
|
|
|
* `$categories` and `$excludeCategories` as parameters to retrieve the |
197
|
|
|
* results that you are interested in. |
198
|
|
|
* |
199
|
|
|
* @param array $categories list of categories that you are interested in. |
200
|
|
|
* You can use an asterisk at the end of a category to do a prefix match. |
201
|
|
|
* For example, 'yii\db\*' will match categories starting with 'yii\db\', |
202
|
|
|
* such as 'yii\db\Connection'. |
203
|
|
|
* @param array $excludeCategories list of categories that you want to exclude |
204
|
|
|
* @return array the profiling results. Each element is an array consisting of these elements: |
205
|
|
|
* `info`, `category`, `timestamp`, `trace`, `level`, `duration`, `memory`, `memoryDiff`. |
206
|
4 |
|
* The `memory` and `memoryDiff` values are available since version 2.0.11. |
207
|
|
|
*/ |
208
|
4 |
|
public function getProfiling($categories = [], $excludeCategories = []) |
209
|
4 |
|
{ |
210
|
1 |
|
$timings = $this->calculateTimings($this->messages); |
211
|
|
|
if (empty($categories) && empty($excludeCategories)) { |
212
|
|
|
return $timings; |
213
|
3 |
|
} |
214
|
3 |
|
|
215
|
3 |
|
foreach ($timings as $i => $timing) { |
216
|
3 |
|
$matched = empty($categories); |
217
|
3 |
|
foreach ($categories as $category) { |
218
|
2 |
|
$prefix = rtrim($category, '*'); |
219
|
2 |
|
if (($timing['category'] === $category || $prefix !== $category) && strpos($timing['category'], $prefix) === 0) { |
220
|
|
|
$matched = true; |
221
|
3 |
|
break; |
222
|
|
|
} |
223
|
3 |
|
} |
224
|
2 |
|
|
225
|
1 |
|
if ($matched) { |
226
|
1 |
|
foreach ($excludeCategories as $category) { |
227
|
1 |
|
$prefix = rtrim($category, '*'); |
228
|
1 |
|
foreach ($timings as $i => $timing) { |
229
|
1 |
|
if (($timing['category'] === $category || $prefix !== $category) && strpos($timing['category'], $prefix) === 0) { |
230
|
|
|
$matched = false; |
231
|
1 |
|
break; |
232
|
2 |
|
} |
233
|
2 |
|
} |
234
|
|
|
} |
235
|
3 |
|
} |
236
|
3 |
|
|
237
|
3 |
|
if (!$matched) { |
238
|
3 |
|
unset($timings[$i]); |
239
|
|
|
} |
240
|
3 |
|
} |
241
|
|
|
|
242
|
|
|
return array_values($timings); |
243
|
|
|
} |
244
|
|
|
|
245
|
|
|
/** |
246
|
|
|
* Returns the statistical results of DB queries. |
247
|
|
|
* The results returned include the number of SQL statements executed and |
248
|
|
|
* the total time spent. |
249
|
|
|
* @return array the first element indicates the number of SQL statements executed, |
250
|
1 |
|
* and the second element the total time spent in SQL execution. |
251
|
|
|
*/ |
252
|
1 |
|
public function getDbProfiling() |
253
|
1 |
|
{ |
254
|
1 |
|
$timings = $this->getProfiling(['yii\db\Command::query', 'yii\db\Command::execute']); |
255
|
1 |
|
$count = count($timings); |
256
|
1 |
|
$time = 0; |
257
|
1 |
|
foreach ($timings as $timing) { |
258
|
|
|
$time += $timing['duration']; |
259
|
1 |
|
} |
260
|
|
|
|
261
|
|
|
return [$count, $time]; |
262
|
|
|
} |
263
|
|
|
|
264
|
|
|
/** |
265
|
|
|
* Calculates the elapsed time for the given log messages. |
266
|
|
|
* @param array $messages the log messages obtained from profiling |
267
|
|
|
* @return array timings. Each element is an array consisting of these elements: |
268
|
4 |
|
* `info`, `category`, `timestamp`, `trace`, `level`, `duration`, `memory`, `memoryDiff`. |
269
|
|
|
* The `memory` and `memoryDiff` values are available since version 2.0.11. |
270
|
4 |
|
*/ |
271
|
4 |
|
public function calculateTimings($messages) |
272
|
|
|
{ |
273
|
4 |
|
$timings = []; |
274
|
3 |
|
$stack = []; |
275
|
3 |
|
|
276
|
3 |
|
foreach ($messages as $i => $log) { |
277
|
2 |
|
list($token, $level, $category, $timestamp, $traces) = $log; |
|
|
|
|
278
|
3 |
|
$memory = isset($log[5]) ? $log[5] : 0; |
279
|
2 |
|
$log[6] = $i; |
280
|
2 |
|
if ($level == Logger::LEVEL_PROFILE_BEGIN) { |
281
|
2 |
|
$stack[] = $log; |
282
|
2 |
|
} elseif ($level == Logger::LEVEL_PROFILE_END) { |
283
|
2 |
|
if (($last = array_pop($stack)) !== null && $last[0] === $token) { |
284
|
2 |
|
$timings[$last[6]] = [ |
285
|
2 |
|
'info' => $last[0], |
286
|
2 |
|
'category' => $last[2], |
287
|
|
|
'timestamp' => $last[3], |
288
|
2 |
|
'trace' => $last[4], |
289
|
2 |
|
'level' => count($stack), |
290
|
4 |
|
'duration' => $timestamp - $last[3], |
291
|
|
|
'memory' => $memory, |
292
|
4 |
|
'memoryDiff' => $memory - (isset($last[5]) ? $last[5] : 0), |
293
|
|
|
]; |
294
|
4 |
|
} |
295
|
|
|
} |
296
|
|
|
} |
297
|
|
|
|
298
|
|
|
ksort($timings); |
299
|
|
|
|
300
|
|
|
return array_values($timings); |
301
|
|
|
} |
302
|
|
|
|
303
|
3 |
|
|
304
|
|
|
/** |
305
|
|
|
* Returns the text display of the specified level. |
306
|
|
|
* @param int $level the message level, e.g. [[LEVEL_ERROR]], [[LEVEL_WARNING]]. |
307
|
|
|
* @return string the text display of the level |
308
|
|
|
*/ |
309
|
|
|
public static function getLevelName($level) |
310
|
|
|
{ |
311
|
|
|
static $levels = [ |
312
|
|
|
self::LEVEL_ERROR => 'error', |
313
|
3 |
|
self::LEVEL_WARNING => 'warning', |
314
|
|
|
self::LEVEL_INFO => 'info', |
315
|
3 |
|
self::LEVEL_TRACE => 'trace', |
316
|
|
|
self::LEVEL_PROFILE_BEGIN => 'profile begin', |
317
|
|
|
self::LEVEL_PROFILE_END => 'profile end', |
318
|
|
|
self::LEVEL_PROFILE => 'profile' |
319
|
|
|
]; |
320
|
|
|
|
321
|
|
|
return isset($levels[$level]) ? $levels[$level] : 'unknown'; |
322
|
|
|
} |
323
|
|
|
} |
324
|
|
|
|
This checks looks for assignemnts to variables using the
list(...)
function, where not all assigned variables are subsequently used.Consider the following code example.
Only the variables
$a
and$c
are used. There was no need to assign$b
.Instead, the list call could have been.