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-read array $dbProfiling The first element indicates the number of SQL statements executed, and |
34
|
|
|
* the second element the total time spent in SQL execution. This property is read-only. |
35
|
|
|
* @property-read float $elapsedTime The total elapsed time in seconds for current request. This property is |
36
|
|
|
* read-only. |
37
|
|
|
* @property-read array $profiling The profiling results. Each element is an array consisting of these |
38
|
|
|
* elements: `info`, `category`, `timestamp`, `trace`, `level`, `duration`, `memory`, `memoryDiff`. The `memory` |
39
|
|
|
* and `memoryDiff` values are available since version 2.0.11. This property is read-only. |
40
|
|
|
* |
41
|
|
|
* @author Qiang Xue <[email protected]> |
42
|
|
|
* @since 2.0 |
43
|
|
|
*/ |
44
|
|
|
class Logger extends Component |
45
|
|
|
{ |
46
|
|
|
/** |
47
|
|
|
* Error message level. An error message is one that indicates the abnormal termination of the |
48
|
|
|
* application and may require developer's handling. |
49
|
|
|
*/ |
50
|
|
|
const LEVEL_ERROR = 0x01; |
51
|
|
|
/** |
52
|
|
|
* Warning message level. A warning message is one that indicates some abnormal happens but |
53
|
|
|
* the application is able to continue to run. Developers should pay attention to this message. |
54
|
|
|
*/ |
55
|
|
|
const LEVEL_WARNING = 0x02; |
56
|
|
|
/** |
57
|
|
|
* Informational message level. An informational message is one that includes certain information |
58
|
|
|
* for developers to review. |
59
|
|
|
*/ |
60
|
|
|
const LEVEL_INFO = 0x04; |
61
|
|
|
/** |
62
|
|
|
* Tracing message level. A tracing message is one that reveals the code execution flow. |
63
|
|
|
*/ |
64
|
|
|
const LEVEL_TRACE = 0x08; |
65
|
|
|
/** |
66
|
|
|
* Profiling message level. This indicates the message is for profiling purpose. |
67
|
|
|
*/ |
68
|
|
|
const LEVEL_PROFILE = 0x40; |
69
|
|
|
/** |
70
|
|
|
* Profiling message level. This indicates the message is for profiling purpose. It marks the beginning |
71
|
|
|
* of a profiling block. |
72
|
|
|
*/ |
73
|
|
|
const LEVEL_PROFILE_BEGIN = 0x50; |
74
|
|
|
/** |
75
|
|
|
* Profiling message level. This indicates the message is for profiling purpose. It marks the end |
76
|
|
|
* of a profiling block. |
77
|
|
|
*/ |
78
|
|
|
const LEVEL_PROFILE_END = 0x60; |
79
|
|
|
|
80
|
|
|
/** |
81
|
|
|
* @var array logged messages. This property is managed by [[log()]] and [[flush()]]. |
82
|
|
|
* Each log message is of the following structure: |
83
|
|
|
* |
84
|
|
|
* ``` |
85
|
|
|
* [ |
86
|
|
|
* [0] => message (mixed, can be a string or some complex data, such as an exception object) |
87
|
|
|
* [1] => level (integer) |
88
|
|
|
* [2] => category (string) |
89
|
|
|
* [3] => timestamp (float, obtained by microtime(true)) |
90
|
|
|
* [4] => traces (array, debug backtrace, contains the application code call stacks) |
91
|
|
|
* [5] => memory usage in bytes (int, obtained by memory_get_usage()), available since version 2.0.11. |
92
|
|
|
* ] |
93
|
|
|
* ``` |
94
|
|
|
*/ |
95
|
|
|
public $messages = []; |
96
|
|
|
/** |
97
|
|
|
* @var int how many messages should be logged before they are flushed from memory and sent to targets. |
98
|
|
|
* Defaults to 1000, meaning the [[flush()]] method will be invoked once every 1000 messages logged. |
99
|
|
|
* Set this property to be 0 if you don't want to flush messages until the application terminates. |
100
|
|
|
* This property mainly affects how much memory will be taken by the logged messages. |
101
|
|
|
* A smaller value means less memory, but will increase the execution time due to the overhead of [[flush()]]. |
102
|
|
|
*/ |
103
|
|
|
public $flushInterval = 1000; |
104
|
|
|
/** |
105
|
|
|
* @var int how much call stack information (file name and line number) should be logged for each message. |
106
|
|
|
* If it is greater than 0, at most that number of call stacks will be logged. Note that only application |
107
|
|
|
* call stacks are counted. |
108
|
|
|
*/ |
109
|
|
|
public $traceLevel = 0; |
110
|
|
|
/** |
111
|
|
|
* @var Dispatcher the message dispatcher. |
112
|
|
|
*/ |
113
|
|
|
public $dispatcher; |
114
|
|
|
/** |
115
|
|
|
* @var array of event names used to get statistical results of DB queries. |
116
|
|
|
* @since 2.0.41 |
117
|
|
|
*/ |
118
|
|
|
public $dbEventNames = ['yii\db\Command::query', 'yii\db\Command::execute']; |
119
|
|
|
/** |
120
|
|
|
* @var bool whether the profiling-aware mode should be switched on. |
121
|
|
|
* If on, [[flush()]] makes sure that profiling blocks are flushed in pairs. In case that any dangling messages are |
122
|
|
|
* detected these are kept for the next flush interval to find their pair. To prevent memory leaks, when number of |
123
|
|
|
* dangling messages reaches flushInterval value, logger flushes them immediately and triggers a warning. |
124
|
|
|
* Keep in mind that profiling-aware mode is more time and memory consuming. |
125
|
|
|
* @since 2.0.43 |
126
|
|
|
*/ |
127
|
|
|
public $profilingAware = false; |
128
|
|
|
|
129
|
|
|
|
130
|
|
|
/** |
131
|
|
|
* Initializes the logger by registering [[flush()]] as a shutdown function. |
132
|
|
|
*/ |
133
|
|
|
public function init() |
134
|
|
|
{ |
135
|
|
|
parent::init(); |
136
|
|
|
register_shutdown_function(function () { |
137
|
|
|
// make regular flush before other shutdown functions, which allows session data collection and so on |
138
|
|
|
$this->flush(); |
139
|
|
|
// make sure log entries written by shutdown functions are also flushed |
140
|
|
|
// ensure "flush()" is called last when there are multiple shutdown functions |
141
|
|
|
register_shutdown_function([$this, 'flush'], true); |
142
|
|
|
}); |
143
|
|
|
} |
144
|
|
|
|
145
|
|
|
/** |
146
|
|
|
* Logs a message with the given type and category. |
147
|
|
|
* If [[traceLevel]] is greater than 0, additional call stack information about |
148
|
|
|
* the application code will be logged as well. |
149
|
|
|
* @param string|array $message the message to be logged. This can be a simple string or a more |
150
|
|
|
* complex data structure that will be handled by a [[Target|log target]]. |
151
|
|
|
* @param int $level the level of the message. This must be one of the following: |
152
|
|
|
* `Logger::LEVEL_ERROR`, `Logger::LEVEL_WARNING`, `Logger::LEVEL_INFO`, `Logger::LEVEL_TRACE`, `Logger::LEVEL_PROFILE`, |
153
|
|
|
* `Logger::LEVEL_PROFILE_BEGIN`, `Logger::LEVEL_PROFILE_END`. |
154
|
|
|
* @param string $category the category of the message. |
155
|
|
|
*/ |
156
|
|
|
public function log($message, $level, $category = 'application') |
157
|
|
|
{ |
158
|
|
|
$time = microtime(true); |
159
|
|
|
$traces = []; |
160
|
|
|
if ($this->traceLevel > 0) { |
161
|
|
|
$count = 0; |
162
|
|
|
$ts = debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS); |
163
|
|
|
array_pop($ts); // remove the last trace since it would be the entry script, not very useful |
164
|
|
|
foreach ($ts as $trace) { |
165
|
|
|
if (isset($trace['file'], $trace['line']) && strpos($trace['file'], YII2_PATH) !== 0) { |
166
|
|
|
unset($trace['object'], $trace['args']); |
167
|
|
|
$traces[] = $trace; |
168
|
|
|
if (++$count >= $this->traceLevel) { |
169
|
|
|
break; |
170
|
|
|
} |
171
|
|
|
} |
172
|
|
|
} |
173
|
|
|
} |
174
|
|
|
$data = [$message, $level, $category, $time, $traces, memory_get_usage()]; |
175
|
|
|
if ($this->profilingAware && in_array($level, [self::LEVEL_PROFILE_BEGIN, self::LEVEL_PROFILE_END])) { |
176
|
|
|
$this->messages[($level == self::LEVEL_PROFILE_BEGIN ? 'begin-' : 'end-') . md5(json_encode($message))] = $data; |
177
|
|
|
} else { |
178
|
|
|
$this->messages[] = $data; |
179
|
|
|
} |
180
|
|
|
|
181
|
|
|
if ($this->flushInterval > 0 && count($this->messages) >= $this->flushInterval) { |
182
|
|
|
$this->flush(); |
183
|
|
|
} |
184
|
|
|
} |
185
|
|
|
|
186
|
|
|
/** |
187
|
|
|
* Flushes log messages from memory to targets. |
188
|
|
|
* @param bool $final whether this is a final call during a request. |
189
|
|
|
*/ |
190
|
|
|
public function flush($final = false) |
191
|
|
|
{ |
192
|
|
|
if ($this->profilingAware) { |
193
|
|
|
$keep = []; |
194
|
|
|
$messages = []; |
195
|
|
|
foreach ($this->messages as $index => $message) { |
196
|
|
|
if (is_int($index)) { |
197
|
|
|
$messages[] = $message; |
198
|
|
|
} else { |
199
|
|
|
if (strpos($index, 'begin-') === 0) { |
200
|
|
|
$oppositeProfile = 'end-' . substr($index, 6); |
201
|
|
|
} else { |
202
|
|
|
$oppositeProfile = 'begin-' . substr($index, 4); |
203
|
|
|
} |
204
|
|
|
if (array_key_exists($oppositeProfile, $this->messages)) { |
205
|
|
|
$messages[] = $message; |
206
|
|
|
} else { |
207
|
|
|
$keep[$index] = $message; |
208
|
|
|
} |
209
|
|
|
} |
210
|
|
|
} |
211
|
|
|
if ($this->flushInterval > 0 && count($keep) >= $this->flushInterval) { |
212
|
|
|
$this->messages = []; |
213
|
|
|
$this->log( |
214
|
|
|
'Number of dangling profiling block messages reached flushInterval value and therefore these were flushed. Please consider setting higher flushInterval value or making profiling blocks shorter.', |
215
|
|
|
self::LEVEL_WARNING |
216
|
|
|
); |
217
|
|
|
$messages = array_merge($messages, array_values($keep)); |
218
|
|
|
} else { |
219
|
|
|
$this->messages = $keep; |
220
|
|
|
} |
221
|
|
|
} else { |
222
|
|
|
$messages = $this->messages; |
223
|
|
|
$this->messages = []; |
224
|
|
|
} |
225
|
|
|
|
226
|
|
|
if ($this->dispatcher instanceof Dispatcher) { |
|
|
|
|
227
|
|
|
$this->dispatcher->dispatch($messages, $final); |
228
|
|
|
} |
229
|
|
|
} |
230
|
|
|
|
231
|
|
|
/** |
232
|
|
|
* Returns the total elapsed time since the start of the current request. |
233
|
|
|
* This method calculates the difference between now and the timestamp |
234
|
|
|
* defined by constant `YII_BEGIN_TIME` which is evaluated at the beginning |
235
|
|
|
* of [[\yii\BaseYii]] class file. |
236
|
|
|
* @return float the total elapsed time in seconds for current request. |
237
|
|
|
*/ |
238
|
|
|
public function getElapsedTime() |
239
|
|
|
{ |
240
|
|
|
return microtime(true) - YII_BEGIN_TIME; |
241
|
|
|
} |
242
|
|
|
|
243
|
|
|
/** |
244
|
|
|
* Returns the profiling results. |
245
|
|
|
* |
246
|
|
|
* By default, all profiling results will be returned. You may provide |
247
|
|
|
* `$categories` and `$excludeCategories` as parameters to retrieve the |
248
|
|
|
* results that you are interested in. |
249
|
|
|
* |
250
|
|
|
* @param array $categories list of categories that you are interested in. |
251
|
|
|
* You can use an asterisk at the end of a category to do a prefix match. |
252
|
|
|
* For example, 'yii\db\*' will match categories starting with 'yii\db\', |
253
|
|
|
* such as 'yii\db\Connection'. |
254
|
|
|
* @param array $excludeCategories list of categories that you want to exclude |
255
|
|
|
* @return array the profiling results. Each element is an array consisting of these elements: |
256
|
|
|
* `info`, `category`, `timestamp`, `trace`, `level`, `duration`, `memory`, `memoryDiff`. |
257
|
|
|
* The `memory` and `memoryDiff` values are available since version 2.0.11. |
258
|
|
|
*/ |
259
|
|
|
public function getProfiling($categories = [], $excludeCategories = []) |
260
|
|
|
{ |
261
|
|
|
$timings = $this->calculateTimings($this->messages); |
262
|
|
|
if (empty($categories) && empty($excludeCategories)) { |
263
|
|
|
return $timings; |
264
|
|
|
} |
265
|
|
|
|
266
|
|
|
foreach ($timings as $outerIndex => $outerTimingItem) { |
267
|
|
|
$currentIndex = $outerIndex; |
268
|
|
|
$matched = empty($categories); |
269
|
|
|
foreach ($categories as $category) { |
270
|
|
|
$prefix = rtrim($category, '*'); |
271
|
|
|
if ( |
272
|
|
|
($outerTimingItem['category'] === $category || $prefix !== $category) |
273
|
|
|
&& strpos($outerTimingItem['category'], $prefix) === 0 |
274
|
|
|
) { |
275
|
|
|
$matched = true; |
276
|
|
|
break; |
277
|
|
|
} |
278
|
|
|
} |
279
|
|
|
|
280
|
|
|
if ($matched) { |
281
|
|
|
foreach ($excludeCategories as $category) { |
282
|
|
|
$prefix = rtrim($category, '*'); |
283
|
|
|
foreach ($timings as $innerIndex => $innerTimingItem) { |
284
|
|
|
$currentIndex = $innerIndex; |
285
|
|
|
if ( |
286
|
|
|
($innerTimingItem['category'] === $category || $prefix !== $category) |
287
|
|
|
&& strpos($innerTimingItem['category'], $prefix) === 0 |
288
|
|
|
) { |
289
|
|
|
$matched = false; |
290
|
|
|
break; |
291
|
|
|
} |
292
|
|
|
} |
293
|
|
|
} |
294
|
|
|
} |
295
|
|
|
|
296
|
|
|
if (!$matched) { |
297
|
|
|
unset($timings[$currentIndex]); |
298
|
|
|
} |
299
|
|
|
} |
300
|
|
|
|
301
|
|
|
return array_values($timings); |
302
|
|
|
} |
303
|
|
|
|
304
|
|
|
/** |
305
|
|
|
* Returns the statistical results of DB queries. |
306
|
|
|
* The results returned include the number of SQL statements executed and |
307
|
|
|
* the total time spent. |
308
|
|
|
* @return array the first element indicates the number of SQL statements executed, |
309
|
|
|
* and the second element the total time spent in SQL execution. |
310
|
|
|
*/ |
311
|
|
|
public function getDbProfiling() |
312
|
|
|
{ |
313
|
|
|
$timings = $this->getProfiling($this->dbEventNames); |
314
|
|
|
$count = count($timings); |
315
|
|
|
$time = 0; |
316
|
|
|
foreach ($timings as $timing) { |
317
|
|
|
$time += $timing['duration']; |
318
|
|
|
} |
319
|
|
|
|
320
|
|
|
return [$count, $time]; |
321
|
|
|
} |
322
|
|
|
|
323
|
|
|
/** |
324
|
|
|
* Calculates the elapsed time for the given log messages. |
325
|
|
|
* @param array $messages the log messages obtained from profiling |
326
|
|
|
* @return array timings. Each element is an array consisting of these elements: |
327
|
|
|
* `info`, `category`, `timestamp`, `trace`, `level`, `duration`, `memory`, `memoryDiff`. |
328
|
|
|
* The `memory` and `memoryDiff` values are available since version 2.0.11. |
329
|
|
|
*/ |
330
|
|
|
public function calculateTimings($messages) |
331
|
|
|
{ |
332
|
|
|
$timings = []; |
333
|
|
|
$stack = []; |
334
|
|
|
|
335
|
|
|
foreach ($messages as $i => $log) { |
336
|
|
|
list($token, $level, $category, $timestamp, $traces) = $log; |
337
|
|
|
$memory = isset($log[5]) ? $log[5] : 0; |
338
|
|
|
$log[6] = $i; |
339
|
|
|
$hash = md5(json_encode($token)); |
340
|
|
|
if ($level == self::LEVEL_PROFILE_BEGIN) { |
341
|
|
|
$stack[$hash] = $log; |
342
|
|
|
} elseif ($level == self::LEVEL_PROFILE_END) { |
343
|
|
|
if (isset($stack[$hash])) { |
344
|
|
|
$timings[$stack[$hash][6]] = [ |
345
|
|
|
'info' => $stack[$hash][0], |
346
|
|
|
'category' => $stack[$hash][2], |
347
|
|
|
'timestamp' => $stack[$hash][3], |
348
|
|
|
'trace' => $stack[$hash][4], |
349
|
|
|
'level' => count($stack) - 1, |
350
|
|
|
'duration' => $timestamp - $stack[$hash][3], |
351
|
|
|
'memory' => $memory, |
352
|
|
|
'memoryDiff' => $memory - (isset($stack[$hash][5]) ? $stack[$hash][5] : 0), |
353
|
|
|
]; |
354
|
|
|
unset($stack[$hash]); |
355
|
|
|
} |
356
|
|
|
} |
357
|
|
|
} |
358
|
|
|
|
359
|
|
|
ksort($timings); |
360
|
|
|
|
361
|
|
|
return array_values($timings); |
362
|
|
|
} |
363
|
|
|
|
364
|
|
|
|
365
|
|
|
/** |
366
|
|
|
* Returns the text display of the specified level. |
367
|
|
|
* @param int $level the message level, e.g. [[LEVEL_ERROR]], [[LEVEL_WARNING]]. |
368
|
|
|
* @return string the text display of the level |
369
|
|
|
*/ |
370
|
|
|
public static function getLevelName($level) |
371
|
|
|
{ |
372
|
|
|
static $levels = [ |
373
|
|
|
self::LEVEL_ERROR => 'error', |
374
|
|
|
self::LEVEL_WARNING => 'warning', |
375
|
|
|
self::LEVEL_INFO => 'info', |
376
|
|
|
self::LEVEL_TRACE => 'trace', |
377
|
|
|
self::LEVEL_PROFILE_BEGIN => 'profile begin', |
378
|
|
|
self::LEVEL_PROFILE_END => 'profile end', |
379
|
|
|
self::LEVEL_PROFILE => 'profile', |
380
|
|
|
]; |
381
|
|
|
|
382
|
|
|
return isset($levels[$level]) ? $levels[$level] : 'unknown'; |
383
|
|
|
} |
384
|
|
|
} |
385
|
|
|
|