Logger.php 11.8 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
/**
14
 * Logger records logged messages in memory and sends them to different targets if [[dispatcher]] is set.
Qiang Xue committed
15
 *
16
 * A Logger instance can be accessed via `Yii::getLogger()`. You can call the method [[log()]] to record a single log message.
17 18
 * For convenience, a set of shortcut methods are provided for logging messages of various severity levels
 * via the [[Yii]] class:
Qiang Xue committed
19 20 21 22 23 24 25 26
 *
 * - [[Yii::trace()]]
 * - [[Yii::error()]]
 * - [[Yii::warning()]]
 * - [[Yii::info()]]
 * - [[Yii::beginProfile()]]
 * - [[Yii::endProfile()]]
 *
Qiang Xue committed
27
 * When the application ends or [[flushInterval]] is reached, Logger will call [[flush()]]
28 29
 * to send logged messages to different log targets, such as [[FileTarget|file]], [[EmailTarget|email]],
 * or [[DbTarget|database]], with the help of the [[dispatcher]].
w  
Qiang Xue committed
30
 *
31 32 33 34
 * @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.
35 36
 * @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.
37
 *
w  
Qiang Xue committed
38 39 40
 * @author Qiang Xue <qiang.xue@gmail.com>
 * @since 2.0
 */
Qiang Xue committed
41
class Logger extends Component
w  
Qiang Xue committed
42
{
43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75
    /**
     * 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;
Qiang Xue committed
76

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
    /**
     * @var array logged messages. This property is managed by [[log()]] and [[flush()]].
     * Each log message is of the following structure:
     *
     * ~~~
     * [
     *   [0] => message (mixed, can be a string or some complex data, such as an exception object)
     *   [1] => level (integer)
     *   [2] => category (string)
     *   [3] => timestamp (float, obtained by microtime(true))
     *   [4] => traces (array, debug backtrace, contains the application code call stacks)
     * ]
     * ~~~
     */
    public $messages = [];
    /**
     * @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;
    /**
     * @var integer how much call stack information (file name and line number) should be logged for each message.
     * If it is greater than 0, at most that number of call stacks will be logged. Note that only application
     * call stacks are counted.
     */
105 106 107 108 109 110
    public $traceLevel = 0;
    /**
     * @var Dispatcher the message dispatcher
     */
    public $dispatcher;

Qiang Xue committed
111

112 113 114 115 116 117
    /**
     * Initializes the logger by registering [[flush()]] as a shutdown function.
     */
    public function init()
    {
        parent::init();
118 119 120 121
        register_shutdown_function(function () {
            // make sure "flush()" is called last when there are multiple shutdown functions
            register_shutdown_function([$this, 'flush'], true);
        });
122
    }
Qiang Xue committed
123

124 125 126 127
    /**
     * Logs a message with the given type and category.
     * If [[traceLevel]] is greater than 0, additional call stack information about
     * the application code will be logged as well.
128 129
     * @param string|array $message the message to be logged. This can be a simple string or a more
     * complex data structure that will be handled by a [[Target|log target]].
130 131 132 133
     * @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`.
     * @param string $category the category of the message.
134 135 136 137 138 139 140
     */
    public function log($message, $level, $category = 'application')
    {
        $time = microtime(true);
        $traces = [];
        if ($this->traceLevel > 0) {
            $count = 0;
141
            $ts = debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS);
142 143
            array_pop($ts); // remove the last trace since it would be the entry script, not very useful
            foreach ($ts as $trace) {
144
                if (isset($trace['file'], $trace['line']) && strpos($trace['file'], YII2_PATH) !== 0) {
145 146 147 148 149 150 151 152 153 154 155 156 157
                    unset($trace['object'], $trace['args']);
                    $traces[] = $trace;
                    if (++$count >= $this->traceLevel) {
                        break;
                    }
                }
            }
        }
        $this->messages[] = [$message, $level, $category, $time, $traces];
        if ($this->flushInterval > 0 && count($this->messages) >= $this->flushInterval) {
            $this->flush();
        }
    }
w  
Qiang Xue committed
158

159 160 161 162 163 164
    /**
     * Flushes log messages from memory to targets.
     * @param boolean $final whether this is a final call during a request.
     */
    public function flush($final = false)
    {
165
        $messages = $this->messages;
166 167 168
        // https://github.com/yiisoft/yii2/issues/5619
        // new messages could be logged while the existing ones are being handled by targets
        $this->messages = [];
169
        if ($this->dispatcher instanceof Dispatcher) {
170
            $this->dispatcher->dispatch($messages, $final);
171 172
        }
    }
w  
Qiang Xue committed
173

174 175 176 177 178 179 180 181 182 183 184
    /**
     * 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
     * of [[\yii\BaseYii]] class file.
     * @return float the total elapsed time in seconds for current request.
     */
    public function getElapsedTime()
    {
        return microtime(true) - YII_BEGIN_TIME;
    }
w  
Qiang Xue committed
185

186 187 188 189 190 191 192
    /**
     * Returns the profiling results.
     *
     * 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.
     *
193 194 195 196 197
     * @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\',
     * such as 'yii\db\Connection'.
     * @param array $excludeCategories list of categories that you want to exclude
198
     * @return array the profiling results. Each element is an array consisting of these elements:
199
     * `info`, `category`, `timestamp`, `trace`, `level`, `duration`.
200 201 202 203 204 205 206
     */
    public function getProfiling($categories = [], $excludeCategories = [])
    {
        $timings = $this->calculateTimings($this->messages);
        if (empty($categories) && empty($excludeCategories)) {
            return $timings;
        }
w  
Qiang Xue committed
207

208 209 210 211 212 213 214 215 216
        foreach ($timings as $i => $timing) {
            $matched = empty($categories);
            foreach ($categories as $category) {
                $prefix = rtrim($category, '*');
                if (strpos($timing['category'], $prefix) === 0 && ($timing['category'] === $category || $prefix !== $category)) {
                    $matched = true;
                    break;
                }
            }
w  
Qiang Xue committed
217

218 219 220 221 222 223 224 225 226 227 228
            if ($matched) {
                foreach ($excludeCategories as $category) {
                    $prefix = rtrim($category, '*');
                    foreach ($timings as $i => $timing) {
                        if (strpos($timing['category'], $prefix) === 0 && ($timing['category'] === $category || $prefix !== $category)) {
                            $matched = false;
                            break;
                        }
                    }
                }
            }
w  
Qiang Xue committed
229

230 231 232 233
            if (!$matched) {
                unset($timings[$i]);
            }
        }
w  
Qiang Xue committed
234

235 236
        return array_values($timings);
    }
237

238 239 240 241 242
    /**
     * 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,
243
     * and the second element the total time spent in SQL execution.
244 245 246 247 248 249 250 251 252
     */
    public function getDbProfiling()
    {
        $timings = $this->getProfiling(['yii\db\Command::query', 'yii\db\Command::execute']);
        $count = count($timings);
        $time = 0;
        foreach ($timings as $timing) {
            $time += $timing['duration'];
        }
253

254 255
        return [$count, $time];
    }
w  
Qiang Xue committed
256

257 258
    /**
     * Calculates the elapsed time for the given log messages.
259
     * @param array $messages the log messages obtained from profiling
260
     * @return array timings. Each element is an array consisting of these elements:
261
     * `info`, `category`, `timestamp`, `trace`, `level`, `duration`.
262 263 264 265 266
     */
    public function calculateTimings($messages)
    {
        $timings = [];
        $stack = [];
w  
Qiang Xue committed
267

268 269 270 271 272 273 274 275 276 277 278 279 280 281 282 283 284 285
        foreach ($messages as $i => $log) {
            list($token, $level, $category, $timestamp, $traces) = $log;
            $log[5] = $i;
            if ($level == Logger::LEVEL_PROFILE_BEGIN) {
                $stack[] = $log;
            } elseif ($level == Logger::LEVEL_PROFILE_END) {
                if (($last = array_pop($stack)) !== null && $last[0] === $token) {
                    $timings[$last[5]] = [
                        'info' => $last[0],
                        'category' => $last[2],
                        'timestamp' => $last[3],
                        'trace' => $last[4],
                        'level' => count($stack),
                        'duration' => $timestamp - $last[3],
                    ];
                }
            }
        }
Qiang Xue committed
286

287
        ksort($timings);
288

289 290 291 292 293 294
        return array_values($timings);
    }


    /**
     * Returns the text display of the specified level.
295 296
     * @param integer $level the message level, e.g. [[LEVEL_ERROR]], [[LEVEL_WARNING]].
     * @return string the text display of the level
297 298 299 300 301 302 303 304 305 306 307 308 309 310
     */
    public static function getLevelName($level)
    {
        static $levels = [
            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',
        ];

        return isset($levels[$level]) ? $levels[$level] : 'unknown';
    }
w  
Qiang Xue committed
311
}