1949啦网--小小 痛苦,是因为能力和欲望不匹配造成的

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组件的架构,可能出现问题的三个点事:

  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
  2. http://php.net/manual/zh/function.register-shutdown-function.php
  3. 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://www.qiquanji.com/post/4891.html

本站声明:网站内容来源于网络,如有侵权,请联系我们,我们将及时处理。

微信扫码关注

更新实时通知

作者:xialibing 分类:高级教程 浏览: