yii2 mq队列消费时，常驻内存下日志不能正常输出

现象

在cli下运行mq的消费命令，不能正常输出日志；

log配置

'log' => [
            'targets' => [
               [
                    'class' => 'yii\log\FileTarget',
                    'levels' => ['error', 'info', 'warning'],
                    'logFile' => '@console/logs/info/' . date('Ymd') . '.log',
 				],
            ],
        ],

代码

/**
 * @param \PhpAmqpLib\Message\AMQPMessage $message
 */
function process_message($message)
{
   \Yii::info($message->body);

    $message->ack();

    // Send a message with the string "quit" to cancel the consumer.
    if ($message->body === 'quit') {
        $message->getChannel()->basic_cancel($message->getConsumerTag());
    }
}

$channel->basic_consume($queue, $consumerTag, false, false, false, false, 'process_message');

// Loop as long as the channel has callbacks registered
while ($channel->is_consuming()) {
    $channel->wait();
}

运行代码我们期待对应的文件目录下应该有响应的队列消息的…

原因

根据上面的代码，我们知道，只要注册了消费的回调，进程常驻内存，flushInterval，exportInterval 默认次数都为1000，而常驻内存的时候不会执register_shutdown_function ，那么我们的日志内容会一直等不到

yii\db\Logger.php

public function log($message, $level, $category = 'application')
    { 
       ....
       
        //将信息保存到messages数组
        $this->messages[] = [$message, $level, $category, $time, $traces];
        //当保存的信息数量达到$this->flushInterval属性值时，执行flush方法清空日志，默认值为1000
        if ($this->flushInterval > 0 && count($this->messages) >= $this->flushInterval) {
            $this->flush();
        }
    }
    //清空日志信息，其实是调用yii\db\Dispatcher的dispatch方法，并传递信息数组$this->messages，和$final参数，$final为true表示脚本已执行结束，不管messages已经多少条都会写入
    public function flush($final = false)
    {
        if ($this->dispatcher instanceof Dispatcher) {
            $this->dispatcher->dispatch($this->messages, $final);
        }
        $this->messages = [];
    }
    

通过 logger object 对象，日志消息被保存在一个数组里。 为了这个数组的内存消耗，当数组积累了一定数量的日志消息， 日志对象每次都将刷新被记录的消息到 log targets 中

yii\log\Targe.php

 public function collect($messages, $final)
    {
        //对$messages进行过滤，过滤掉不属于当前调用的target的信息
        $this->messages = array_merge($this->messages, $this->filterMessages($messages, $this->getLevels(), $this->categories, $this->except));
        $count = count($this->messages);
        //当日志信息数量达到执行数量$this->exportInterval时执行，默认值为1000
        if ($count > 0 && ($final || $this->exportInterval > 0 && $count >= $this->exportInterval)) {
            //记录$_GET,$_POST,$_SERVER等系统访问信息
            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;
            //调用export方法，此方法最终实现对message的处理，参见代码yii\log\FileTarget
            $this->export();
            $this->exportInterval = $oldExportInterval;

            $this->messages = [];
        }
    }

当 logger object 对象刷新日志消息到 log targets 的时候，它们并 不能立即获取导出的消息。相反，消息导出仅仅在一个日志目标累积了一定数量的过滤消息的时候才会发生;

那为什么我们执行cli 命令的时候可以正常打印日志呢，关键在于我们大部分的cli 命令都没有常驻内存，最后都在短时间结束了，在最后执行了register_shutdown_function

yii\db\Logger.php

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);
        });
    }

解决

1. 修改flushInterval，exportInterval 为合适的值让日志内容能根据需求刷到对应文件

'log' => [
            'flushInterval' => 1,
            'targets' => [
                [
                    'class' => 'yii\log\FileTarget',
                    'levels' => ['error', 'info', 'warning'],
                    'logFile' => '@console/logs/info/' . date('Ymd') . '.log',
                    'exportInterval' => 1,
                ],
            ],
        ],

2. 在需要的地方或最后调用函数flush,使内容直接刷出

\Yii::info($message->body);
\Yii::getLogger()->flush(true);//whether this is a final call during a request

小结

1. 引起问题的根本原因还是没有看官方的说明文档直接就用
2. 看源码是解决问题最有效的方法，但未必是最快捷的方法，最后注意到官方有对应的说明的