CLI模式下Yii2的log問題追蹤

時間  2020-05-21
標籤 cli 模式 yii2 yii log 問題 追蹤 欄目 PHP 简体版
原文   原文鏈接
轉載請註明出處： https://tlanyan.me/trace-log-...

命令行下運行長時間任務，發現Yii2的log組件不能正常輸出日誌。空閒之餘逐步追蹤問題，終於發現緣由，如下是問題追蹤記錄。php

問題復現

爲了復現問題，預先準備了log組件的配置：html

// 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 "";
                    }
                ],
                    ...
            ],
        ],
    ],
...

以及測試用例：git

// 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終止腳本，日誌沒有出現新信息。github

問題分析

仔細分析，運行上述代碼有兩個問題：1. log組件中flushInterval參數設置每10條信息合併輸出一次，實際中一直沒有輸出；2. 按ctrl+c終止腳本，緩衝的信息沒有輸出。web

因爲以前已經向Yii開發團隊提交過一個log組件的bug（issue連接：https://github.com/yiisoft/yi...）。本次發現的問題暫不肯定是Yii2的bug仍是使用方法不當，畢竟（應該）不多人會使用命令行運行長時間任務。數據庫

查找問題

根據log組件的架構，可能出現問題的三個點事：yii2

  1. Logger類，Yii2默認的log組件類，對外暴露打印日誌的log/info/warning/error等方法；
  2. Dispatcher類，對消息進行分類，根據配置分發到具體負責輸出的輸出類
  3. Target的具體實現子類，這些子類實現消息的具體輸出，例如保存到文件/數據庫，或者發送郵件等。

根據這些線索，能夠比較清晰的查看調用鏈條。session

首先是Yii::info函數的調用，定義在BaseYii中，具體實現委託給Logger類的log方法:</pre>架構

// 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方法的實現：app

// 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 &lt; $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開發中不會出現相似問題。

參考

  1. http://www.yiiframework.com/d...
  2. http://php.net/manual/zh/func...
  3. http://php.net/manual/zh/func...
  4. https://stackoverflow.com/que...
相關文章
相關標籤/搜索
每日一句
    每一个你不满意的现在，都有一个你没有努力的曾经。
本站公眾號
   歡迎關注本站公眾號,獲取更多信息
聯繫我們 最近搜索 最新文章 沪ICP备13005482号-10 MyBatis教程 SQL 教程 MySQL教程 Java 教程 Thymeleaf 教程 Hibernate教程 Spring教程 Redis教程