Logger.php 13 KB

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