Logger.php 15 KB

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