CLI模式下Yii2的log问题追踪

爱被打了一巴掌 2022-05-16 15:52 195阅读 0赞

命令行下运行长时间任务，发现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][https_github.com_yiisoft_yii2_issues_8036]）。本次发现的问题暂不确定是Yii2的bug还是使用方法不当，毕竟（应该）很少人会使用命令行运行长时间任务。

## 查找问题 ##

根据log组件的架构，可能出现问题的三个点事：

1.  Logger类，Yii2默认的log组件类，对外暴露打印日志的log/info/warning/error等方法；
2.  Dispatcher类，对消息进行分类，根据配置分发到具体负责输出的输出类
3.  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开发中不会出现类似问题。

### 参考 ###

1.  [http://www.yiiframework.com/doc-2.0/guide-runtime-logging.html][http_www.yiiframework.com_doc-2.0_guide-runtime-logging.html]
2.  [http://php.net/manual/zh/function.register-shutdown-function.php][http_php.net_manual_zh_function.register-shutdown-function.php]
3.  [http://php.net/manual/zh/function.pcntl-signal.php][http_php.net_manual_zh_function.pcntl-signal.php]
4.  [https://stackoverflow.com/questions/3909798/phps-register-shutdown-function-to-fire-when-a-script-is-killed-from-the-comman][https_stackoverflow.com_questions_3909798_phps-register-shutdown-function-to-fire-when-a-script-is-killed-from-the-comman]

参考文献：

[https://tlanyan.me/trace-log-problem-of-yii2-in-cli/][https_tlanyan.me_trace-log-problem-of-yii2-in-cli]

[https_github.com_yiisoft_yii2_issues_8036]: https://github.com/yiisoft/yii2/issues/8036
[http_www.yiiframework.com_doc-2.0_guide-runtime-logging.html]: 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.register-shutdown-function.php
[http_php.net_manual_zh_function.pcntl-signal.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]: https://stackoverflow.com/questions/3909798/phps-register-shutdown-function-to-fire-when-a-script-is-killed-from-the-comman
[https_tlanyan.me_trace-log-problem-of-yii2-in-cli]: https://tlanyan.me/trace-log-problem-of-yii2-in-cli/