CLI模式下Yii2的log問題追蹤
命令列下執行長時間任務,發現Yii2的log元件不能正常輸出日誌。空閒之餘逐步追蹤問題,終於發現原因,以下是問題追蹤記錄。
問題復現
為了復現問題,預先準備了log元件的配置:
// file: console/config/console-local.php ... 'components' => [ 'log' => [ 'flushInterval' => 10, 'targets' => [ 'info' => [ 'class' => 'yii\log\FileTarget', 'levels' => ['info'], 'logVars' => [], 'categories' => ['app'], 'logFile' => '@console/logs/info/' . date('Ymd') . '.log', "prefix" => function ($message) { return ""; } ], ... ], ], ], ...
以及測試用例:
// file: console/controllers/TestController.php namespace console\controllers; use Yii; use yii\console\Controller; class TestController extends Controller { public function actionShort() { Yii::info("This is a short test message", "app"); sleep(3); Yii::info("Another short test message", "app"); echo "Done!", PHP_EOL; } public function actionLong() { $count = 10000; for ($index = 0; $index < $count; ++ $index) { Yii::info("This is a long test message", "app"); sleep(1); Yii::info("Another long test message", "app"); } echo "Done!", PHP_EOL; } }
命令列下執行./yii test/short
,日誌正常輸出到指定的檔案中;執行./yii test/long
,使用tailf
或者tail -f
命令檢視日誌檔案,未發現輸出;按ctrl+c
終止指令碼,日誌沒有出現新資訊。
問題分析
仔細分析,執行上述程式碼有兩個問題:1. log元件中flushInterval
引數設定每10條資訊合併輸出一次,實際中一直沒有輸出;2. 按ctrl+c
終止指令碼,緩衝的資訊沒有輸出。
由於之前已經向Yii開發團隊提交過一個log元件的bug(issue連結:https://github.com/yiisoft/yii2/issues/8036)。本次發現的問題暫不確定是Yii2的bug還是使用方法不當,畢竟(應該)很少人會使用命令列執行長時間任務。
查詢問題
根據log元件的架構,可能出現問題的三個點事:
- Logger類,Yii2預設的log元件類,對外暴露列印日誌的log/info/warning/error等方法;
- Dispatcher類,對訊息進行分類,根據配置分發到具體負責輸出的輸出類
- Target的具體實現子類,這些子類實現訊息的具體輸出,例如儲存到檔案/資料庫,或者傳送郵件等。
根據這些線索,可以比較清晰的檢視呼叫鏈條。
首先是Yii::info
函式的呼叫,定義在BaseYii
中,具體實現委託給Logger類的log方法:
// file: https://github.com/yiisoft/yii2/blob/master/framework/log/Logger.php ... /** * 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. * @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]]. * @param int $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. */ public function log($message, $level, $category = 'application') { $time = microtime(true); $traces = []; if ($this->traceLevel > 0) { $count = 0; $ts = debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS); array_pop($ts); // remove the last trace since it would be the entry script, not very useful foreach ($ts as $trace) { if (isset($trace['file'], $trace['line']) && strpos($trace['file'], YII2_PATH) !== 0) { unset($trace['object'], $trace['args']); $traces[] = $trace; if (++$count >= $this->traceLevel) { break; } } } } $this->messages[] = [$message, $level, $category, $time, $traces, memory_get_usage()]; if ($this->flushInterval > 0 && count($this->messages) >= $this->flushInterval) { $this->flush(); } } ...
log方法功能是格式化訊息,然後呼叫flush
方法輸出日誌。接著看flush
方法的實現:
// file: https://github.com/yiisoft/yii2/blob/master/framework/log/Logger.php .... /** * Flushes log messages from memory to targets. * @param bool $final whether this is a final call during a request. */ public function flush($final = false) { $messages = $this->messages; // https://github.com/yiisoft/yii2/issues/5619 // new messages could be logged while the existing ones are being handled by targets $this->messages = []; if ($this->dispatcher instanceof Dispatcher) { $this->dispatcher->dispatch($messages, $final); } } ....
flush方法委託Dispatcher將訊息分發到具體的目標。繼續跟蹤前,先看看Logger類的init方法:
// file: https://github.com/yiisoft/yii2/blob/master/framework/log/Logger.php ... /** * Initializes the logger by registering [[flush()]] as a shutdown function. */ public function init() { parent::init(); register_shutdown_function(function () { // make regular flush before other shutdown functions, which allows session data collection and so on $this->flush(); // make sure log entries written by shutdown functions are also flushed // ensure "flush()" is called last when there are multiple shutdown functions register_shutdown_function([$this, 'flush'], true); }); } ...
logger元件初始化時,註冊register_shutdown_function
回撥函式,確保指令碼執行完畢時訊息被正確列印。這也是在指令碼中無論何時出現exit/die,或者呼叫Yii::$app->end()都會讓日誌正常輸出的祕密。接下來看Dispatcher類的dispatch方法:
// file: https://github.com/yiisoft/yii2/blob/master/framework/log/Dispatcher.php ... /** * Dispatches the logged messages to [[targets]]. * @param array $messages the logged messages * @param bool $final whether this method is called at the end of the current application */ public function dispatch($messages, $final) { $targetErrors = []; foreach ($this->targets as $target) { if ($target->enabled) { try { $target->collect($messages, $final); } catch (\Exception $e) { $target->enabled = false; $targetErrors[] = [ 'Unable to send log via ' . get_class($target) . ': ' . ErrorHandler::convertExceptionToString($e), Logger::LEVEL_WARNING, __METHOD__, microtime(true), [], ]; } } } if (!empty($targetErrors)) { $this->dispatch($targetErrors, true); } } ...
dispatch讓具體負責輸出的target類收集資訊,如果期間出現異常,關閉該渠道,將資訊以warning級別輸出。接下來跟蹤target的collect方法,該方法定義在抽象類Target中:
// file: https://github.com/yiisoft/yii2/blob/master/framework/log/Target.php ... /** * Processes the given log messages. * This method will filter the given messages with [[levels]] and [[categories]]. * And if requested, it will also export the filtering result to specific medium (e.g. email). * @param array $messages log messages to be processed. See [[Logger::messages]] for the structure * of each message. * @param bool $final whether this method is called at the end of the current application */ public function collect($messages, $final) { $this->messages = array_merge($this->messages, static::filterMessages($messages, $this->getLevels(), $this->categories, $this->except)); $count = count($this->messages); if ($count > 0 && ($final || $this->exportInterval > 0 && $count >= $this->exportInterval)) { if (($context = $this->getContextMessage()) !== '') { $this->messages[] = [$context, Logger::LEVEL_INFO, 'application', YII_BEGIN_TIME]; } // set exportInterval to 0 to avoid triggering export again while exporting $oldExportInterval = $this->exportInterval; $this->exportInterval = 0; $this->export(); $this->exportInterval = $oldExportInterval; $this->messages = []; } } ....
collect方法的作用:1. 呼叫filterMessages方法過濾日誌資訊; 2. 判斷是否達到輸出條件,然後呼叫子類的export方法實現日誌的具體輸出。從collect方法,可以看到第一問題的原因:target類有exportInterval引數,預設是1000,示例程式碼要執行非常長的時間才會收集到如此多的訊息,如果需要及時檢視,可將配置程式碼改成如下:
// file: console/config/console-local.php ... 'components' => [ 'log' => [ 'flushInterval' => 10, 'targets' => [ 'info' => [ 'class' => 'yii\log\FileTarget', 'exportInterval' => 1, 'levels' => ['info'], 'logVars' => [], 'categories' => ['app'], 'logFile' => '@console/logs/info/' . date('Ymd') . '.log', "prefix" => function ($message) { return ""; } ], ... ], ], ], ...
接著再看中斷指令碼日誌不輸出的問題。前面已經提到,日誌輸出的技巧是註冊了register_shutdown_function
回撥。先看看這個函式的官方解釋:
註冊一個 callback ,它會在指令碼執行完成或者 exit() 後被呼叫。
可以多次呼叫 register_shutdown_function() ,這些被註冊的回撥會按照他們註冊時的順序被依次呼叫。 如果你在註冊的方法內部呼叫 exit(), 那麼所有處理會被中止,並且其他註冊的中止回撥也不會再被呼叫。
Note:
如果程序被訊號SIGTERM或SIGKILL殺死,那麼中止函式將不會被呼叫。儘管你無法中斷SIGKILL,但你可以通過pcntl_signal() 來捕獲SIGTERM,通過在其中呼叫exit()來進行一個正常的中止。
根據解釋,register_shutdown_function註冊的函式將在指令碼執行完成或者exit後被呼叫。但是SIGTERM/SIGKILL等訊號,不會回撥註冊的函式,並且經過測試ctrl+c
(發出SIGINT訊號)也不會觸發回撥。
指令碼未正常執行完被終止,該如何處理?根據文件提示,需要使用pcntl_signal函式捕捉訊號,再呼叫exit函式讓指令碼正常退出,此時register_shutdown_function註冊的函式會被正常回調。
將示例函式的方法改成:
// file: console/controllers/TestController.php ... public function actionLong() { declare(ticks=1); pcntl_signal(SIGINT, function() {exit();}); pcntl_signal(SIGTERM, function() {exit();}); pcntl_signal(SIGKILL, function() {exit();}); $count = 10000; for ($index = 0; $index < $count; ++ $index) { Yii::info("This is a long test message", "app"); sleep(1); Yii::info("Another long test message", "app"); } echo "Done!", PHP_EOL; } ....
然後在指令碼執行過程中,按下ctrl_+c
,或者通過kill命令傳送訊號,日誌都正常輸出,表明register_shutdown_function中的回撥函式被正常呼叫。
總結
發現的兩個問題,第一個並非Yii2的bug,而是未全面理解文件導致(Logger類的flushInterval和具體Target類的exportInterval都需要設定一個合適的值,才能及時檢視訊息);第二個問題有點蛋疼,應該算PHP的坑。好在非命令列情況下,pcntl拓展不可用,在web開發中不會出現類似問題。
參考
- http://www.yiiframework.com/doc-2.0/guide-runtime-logging.html
- http://php.net/manual/zh/function.register-shutdown-function.php
- http://php.net/manual/zh/function.pcntl-signal.php
- https://stackoverflow.com/questions/3909798/phps-register-shutdown-function-to-fire-when-a-script-is-killed-from-the-comman
參考文獻: