Logger.php 11.6 KB
Newer Older
w  
Qiang Xue committed
1 2 3
<?php
/**
 * @link http://www.yiiframework.com/
Qiang Xue committed
4
 * @copyright Copyright (c) 2008 Yii Software LLC
w  
Qiang Xue committed
5 6 7
 * @license http://www.yiiframework.com/license/
 */

Qiang Xue committed
8
namespace yii\log;
Qiang Xue committed
9

Qiang Xue committed
10 11
use Yii;
use yii\base\Component;
12

w  
Qiang Xue committed
13
/**
Qiang Xue committed
14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32
 * Logger records logged messages in memory and sends them to different targets as needed.
 *
 * Logger is registered as a core application component and can be accessed using `Yii::$app->log`.
 * You can call the method [[log()]] to record a single log message. For convenience, a set of shortcut
 * methods are provided for logging messages of various severity levels via the [[Yii]] class:
 *
 * - [[Yii::trace()]]
 * - [[Yii::error()]]
 * - [[Yii::warning()]]
 * - [[Yii::info()]]
 * - [[Yii::beginProfile()]]
 * - [[Yii::endProfile()]]
 *
 * When enough messages are accumulated in the logger, or when the current request finishes,
 * the logged messages will be sent to different [[targets]], such as log files, emails.
 *
 * You may configure the targets in application configuration, like the following:
 *
 * ~~~
Alexander Makarov committed
33 34 35 36 37
 * [
 *     'components' => [
 *         'log' => [
 *             'targets' => [
 *                 'file' => [
Qiang Xue committed
38
 *                     'class' => 'yii\log\FileTarget',
Alexander Makarov committed
39 40
 *                     'levels' => ['trace', 'info'],
 *                     'categories' => ['yii\*'],
Alexander Makarov committed
41
 *                 ],
Alexander Makarov committed
42
 *                 'email' => [
Qiang Xue committed
43
 *                     'class' => 'yii\log\EmailTarget',
Alexander Makarov committed
44
 *                     'levels' => ['error', 'warning'],
45 46 47
 *                     'message' => [
 *                         'to' => 'admin@example.com',
 *                     ],
Alexander Makarov committed
48 49 50 51 52
 *                 ],
 *             ],
 *         ],
 *     ],
 * ]
Qiang Xue committed
53 54 55 56 57 58 59 60
 * ~~~
 *
 * Each log target can have a name and can be referenced via the [[targets]] property
 * as follows:
 *
 * ~~~
 * Yii::$app->log->targets['file']->enabled = false;
 * ~~~
w  
Qiang Xue committed
61
 *
Qiang Xue committed
62 63
 * When the application ends or [[flushInterval]] is reached, Logger will call [[flush()]]
 * to send logged messages to different log targets, such as file, email, Web.
w  
Qiang Xue committed
64
 *
65 66 67 68
 * @property array $dbProfiling The first element indicates the number of SQL statements executed, and the
 * second element the total time spent in SQL execution. This property is read-only.
 * @property float $elapsedTime The total elapsed time in seconds for current request. This property is
 * read-only.
69 70
 * @property array $profiling The profiling results. Each element is an array consisting of these elements:
 * `info`, `category`, `timestamp`, `trace`, `level`, `duration`. This property is read-only.
71
 *
w  
Qiang Xue committed
72 73 74
 * @author Qiang Xue <qiang.xue@gmail.com>
 * @since 2.0
 */
Qiang Xue committed
75
class Logger extends Component
w  
Qiang Xue committed
76
{
Qiang Xue committed
77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110
	/**
	 * Error message level. An error message is one that indicates the abnormal termination of the
	 * application and may require developer's handling.
	 */
	const LEVEL_ERROR = 0x01;
	/**
	 * Warning message level. A warning message is one that indicates some abnormal happens but
	 * the application is able to continue to run. Developers should pay attention to this message.
	 */
	const LEVEL_WARNING = 0x02;
	/**
	 * Informational message level. An informational message is one that includes certain information
	 * for developers to review.
	 */
	const LEVEL_INFO = 0x04;
	/**
	 * Tracing message level. An tracing message is one that reveals the code execution flow.
	 */
	const LEVEL_TRACE = 0x08;
	/**
	 * Profiling message level. This indicates the message is for profiling purpose.
	 */
	const LEVEL_PROFILE = 0x40;
	/**
	 * Profiling message level. This indicates the message is for profiling purpose. It marks the
	 * beginning of a profiling block.
	 */
	const LEVEL_PROFILE_BEGIN = 0x50;
	/**
	 * Profiling message level. This indicates the message is for profiling purpose. It marks the
	 * end of a profiling block.
	 */
	const LEVEL_PROFILE_END = 0x60;

w  
Qiang Xue committed
111 112

	/**
Qiang Xue committed
113
	 * @var array logged messages. This property is managed by [[log()]] and [[flush()]].
w  
Qiang Xue committed
114 115 116
	 * Each log message is of the following structure:
	 *
	 * ~~~
Alexander Makarov committed
117
	 * [
Qiang Xue committed
118
	 *   [0] => message (mixed, can be a string or some complex data, such as an exception object)
Qiang Xue committed
119
	 *   [1] => level (integer)
w  
Qiang Xue committed
120 121
	 *   [2] => category (string)
	 *   [3] => timestamp (float, obtained by microtime(true))
122
	 *   [4] => traces (array, debug backtrace, contains the application code call stacks)
Alexander Makarov committed
123
	 * ]
w  
Qiang Xue committed
124
	 * ~~~
w  
Qiang Xue committed
125
	 */
Alexander Makarov committed
126
	public $messages = [];
Qiang Xue committed
127 128 129 130
	/**
	 * @var array debug data. This property stores various types of debug data reported at
	 * different instrument places.
	 */
Alexander Makarov committed
131
	public $data = [];
Qiang Xue committed
132
	/**
Qiang Xue committed
133
	 * @var array|Target[] the log targets. Each array element represents a single [[Target|log target]] instance
Qiang Xue committed
134
	 * or the configuration for creating the log target instance.
Qiang Xue committed
135
	 */
Alexander Makarov committed
136
	public $targets = [];
Qiang Xue committed
137 138 139 140 141 142 143 144
	/**
	 * @var integer how many messages should be logged before they are flushed from memory and sent to targets.
	 * Defaults to 1000, meaning the [[flush]] method will be invoked once every 1000 messages logged.
	 * Set this property to be 0 if you don't want to flush messages until the application terminates.
	 * This property mainly affects how much memory will be taken by the logged messages.
	 * A smaller value means less memory, but will increase the execution time due to the overhead of [[flush()]].
	 */
	public $flushInterval = 1000;
145 146
	/**
	 * @var integer how much call stack information (file name and line number) should be logged for each message.
147 148 149 150
	 * If it is greater than 0, at most that number of call stacks will be logged. Note that only application
	 * call stacks are counted.
	 *
	 * If not set, it will default to 3 when `YII_ENV` is set as "dev", and 0 otherwise.
151
	 */
152
	public $traceLevel;
Qiang Xue committed
153

Qiang Xue committed
154 155 156 157 158 159
	/**
	 * Initializes the logger by registering [[flush()]] as a shutdown function.
	 */
	public function init()
	{
		parent::init();
160
		if ($this->traceLevel === null) {
161
			$this->traceLevel = YII_ENV_DEV ? 3 : 0;
162
		}
Qiang Xue committed
163 164 165 166 167
		foreach ($this->targets as $name => $target) {
			if (!$target instanceof Target) {
				$this->targets[$name] = Yii::createObject($target);
			}
		}
Alexander Makarov committed
168
		register_shutdown_function([$this, 'flush'], true);
Qiang Xue committed
169 170
	}

w  
Qiang Xue committed
171 172
	/**
	 * Logs a message with the given type and category.
173 174
	 * If [[traceLevel]] is greater than 0, additional call stack information about
	 * the application code will be logged as well.
w  
Qiang Xue committed
175
	 * @param string $message the message to be logged.
Qiang Xue committed
176 177 178
	 * @param integer $level the level of the message. This must be one of the following:
	 * `Logger::LEVEL_ERROR`, `Logger::LEVEL_WARNING`, `Logger::LEVEL_INFO`, `Logger::LEVEL_TRACE`,
	 * `Logger::LEVEL_PROFILE_BEGIN`, `Logger::LEVEL_PROFILE_END`.
w  
Qiang Xue committed
179 180
	 * @param string $category the category of the message.
	 */
Qiang Xue committed
181
	public function log($message, $level, $category = 'application')
w  
Qiang Xue committed
182
	{
Qiang Xue committed
183
		$time = microtime(true);
Alexander Makarov committed
184
		$traces = [];
185
		if ($this->traceLevel > 0) {
w  
Qiang Xue committed
186
			$count = 0;
187 188 189
			$ts = debug_backtrace();
			array_pop($ts); // remove the last trace since it would be the entry script, not very useful
			foreach ($ts as $trace) {
Qiang Xue committed
190
				if (isset($trace['file'], $trace['line']) && strpos($trace['file'], YII_PATH) !== 0) {
191 192 193
					unset($trace['object'], $trace['args']);
					$traces[] = $trace;
					if (++$count >= $this->traceLevel) {
w  
Qiang Xue committed
194 195 196 197 198
						break;
					}
				}
			}
		}
Alexander Makarov committed
199
		$this->messages[] = [$message, $level, $category, $time, $traces];
200
		if ($this->flushInterval > 0 && count($this->messages) >= $this->flushInterval) {
Qiang Xue committed
201
			$this->flush();
w  
Qiang Xue committed
202 203 204 205
		}
	}

	/**
206
	 * Flushes log messages from memory to targets.
Qiang Xue committed
207
	 * @param boolean $final whether this is a final call during a request.
w  
Qiang Xue committed
208
	 */
Qiang Xue committed
209
	public function flush($final = false)
w  
Qiang Xue committed
210
	{
Qiang Xue committed
211 212 213 214 215
		/** @var Target $target */
		foreach ($this->targets as $target) {
			if ($target->enabled) {
				$target->collect($this->messages, $final);
			}
Qiang Xue committed
216
		}
Alexander Makarov committed
217
		$this->messages = [];
w  
Qiang Xue committed
218 219 220 221 222 223
	}

	/**
	 * Returns the total elapsed time since the start of the current request.
	 * This method calculates the difference between now and the timestamp
	 * defined by constant `YII_BEGIN_TIME` which is evaluated at the beginning
224
	 * of [[\yii\BaseYii]] class file.
w  
Qiang Xue committed
225 226
	 * @return float the total elapsed time in seconds for current request.
	 */
Qiang Xue committed
227
	public function getElapsedTime()
w  
Qiang Xue committed
228 229 230 231 232 233
	{
		return microtime(true) - YII_BEGIN_TIME;
	}

	/**
	 * Returns the profiling results.
w  
Qiang Xue committed
234 235 236 237 238 239 240 241
	 *
	 * By default, all profiling results will be returned. You may provide
	 * `$categories` and `$excludeCategories` as parameters to retrieve the
	 * results that you are interested in.
	 *
	 * @param array $categories list of categories that you are interested in.
	 * You can use an asterisk at the end of a category to do a prefix match.
	 * For example, 'yii\db\*' will match categories starting with 'yii\db\',
Qiang Xue committed
242
	 * such as 'yii\db\Connection'.
243
	 * @param array $excludeCategories list of categories that you want to exclude
244 245
	 * @return array the profiling results. Each element is an array consisting of these elements:
	 * `info`, `category`, `timestamp`, `trace`, `level`, `duration`.
w  
Qiang Xue committed
246
	 */
Alexander Makarov committed
247
	public function getProfiling($categories = [], $excludeCategories = [])
w  
Qiang Xue committed
248
	{
249
		$timings = $this->calculateTimings($this->messages);
w  
Qiang Xue committed
250 251
		if (empty($categories) && empty($excludeCategories)) {
			return $timings;
w  
Qiang Xue committed
252
		}
w  
Qiang Xue committed
253 254 255 256 257

		foreach ($timings as $i => $timing) {
			$matched = empty($categories);
			foreach ($categories as $category) {
				$prefix = rtrim($category, '*');
258
				if (strpos($timing['category'], $prefix) === 0 && ($timing['category'] === $category || $prefix !== $category)) {
w  
Qiang Xue committed
259 260 261 262 263 264 265 266 267
					$matched = true;
					break;
				}
			}

			if ($matched) {
				foreach ($excludeCategories as $category) {
					$prefix = rtrim($category, '*');
					foreach ($timings as $i => $timing) {
268
						if (strpos($timing['category'], $prefix) === 0 && ($timing['category'] === $category || $prefix !== $category)) {
w  
Qiang Xue committed
269 270 271 272 273 274 275 276 277
							$matched = false;
							break;
						}
					}
				}
			}

			if (!$matched) {
				unset($timings[$i]);
w  
Qiang Xue committed
278 279
			}
		}
w  
Qiang Xue committed
280
		return array_values($timings);
w  
Qiang Xue committed
281 282
	}

283 284 285 286 287 288 289 290 291
	/**
	 * Returns the statistical results of DB queries.
	 * The results returned include the number of SQL statements executed and
	 * the total time spent.
	 * @return array the first element indicates the number of SQL statements executed,
	 * and the second element the total time spent in SQL execution.
	 */
	public function getDbProfiling()
	{
Alexander Makarov committed
292
		$timings = $this->getProfiling(['yii\db\Command::query', 'yii\db\Command::execute']);
293 294 295
		$count = count($timings);
		$time = 0;
		foreach ($timings as $timing) {
296
			$time += $timing['duration'];
297
		}
Alexander Makarov committed
298
		return [$count, $time];
299 300
	}

301 302 303 304 305 306 307
	/**
	 * Calculates the elapsed time for the given log messages.
	 * @param array $messages the log messages obtained from profiling
	 * @return array timings. Each element is an array consisting of these elements:
	 * `info`, `category`, `timestamp`, `trace`, `level`, `duration`.
	 */
	public function calculateTimings($messages)
w  
Qiang Xue committed
308
	{
Alexander Makarov committed
309 310
		$timings = [];
		$stack = [];
311 312 313 314 315

		foreach ($messages as $i => $log) {
			list($token, $level, $category, $timestamp, $traces) = $log;
			$log[5] = $i;
			if ($level == Logger::LEVEL_PROFILE_BEGIN) {
w  
Qiang Xue committed
316
				$stack[] = $log;
317
			} elseif ($level == Logger::LEVEL_PROFILE_END) {
Qiang Xue committed
318
				if (($last = array_pop($stack)) !== null && $last[0] === $token) {
319 320 321 322 323 324 325 326
					$timings[$last[5]] = [
						'info' => $last[0],
						'category' => $last[2],
						'timestamp' => $last[3],
						'trace' => $last[4],
						'level' => count($stack),
						'duration' => $timestamp - $last[3],
					];
w  
Qiang Xue committed
327 328 329 330
				}
			}
		}

331
		ksort($timings);
w  
Qiang Xue committed
332

333
		return array_values($timings);
w  
Qiang Xue committed
334
	}
Qiang Xue committed
335

336

Qiang Xue committed
337 338 339 340 341 342 343
	/**
	 * Returns the text display of the specified level.
	 * @param integer $level the message level, e.g. [[LEVEL_ERROR]], [[LEVEL_WARNING]].
	 * @return string the text display of the level
	 */
	public static function getLevelName($level)
	{
Alexander Makarov committed
344
		static $levels = [
Qiang Xue committed
345 346 347 348 349 350
			self::LEVEL_ERROR => 'error',
			self::LEVEL_WARNING => 'warning',
			self::LEVEL_INFO => 'info',
			self::LEVEL_TRACE => 'trace',
			self::LEVEL_PROFILE_BEGIN => 'profile begin',
			self::LEVEL_PROFILE_END => 'profile end',
Alexander Makarov committed
351
		];
Qiang Xue committed
352 353
		return isset($levels[$level]) ? $levels[$level] : 'unknown';
	}
w  
Qiang Xue committed
354
}