CLI模式下Yii2的log問題追蹤

ztyzz 發(fā)布于2019-06-28 18:26 / 1234人閱讀

摘要：繼續(xù)跟蹤前，先看看類的方法組件初始化時，注冊回調(diào)函數(shù)，確保腳本執(zhí)行完畢時消息被正確打印。將示例函數(shù)的方法改成然后在腳本執(zhí)行過程中，按下，或者通過命令發(fā)送信號，日志都正常輸出，表明中的回調(diào)函數(shù)被正常調(diào)用。

轉(zhuǎn)載請注明出處：https://tlanyan.me/trace-log-...

命令行下運(yùn)行長時間任務(wù)，發(fā)現(xiàn)Yii2的log組件不能正常輸出日志。空閑之余逐步追蹤問題，終于發(fā)現(xiàn)原因，以下是問題追蹤記錄。

問題復(fù)現(xiàn)

為了復(fù)現(xiàn)問題，預(yù)先準(zhǔn)備了log組件的配置：

// file: console/config/console-local.php
...
"components" => [
        "log" => [
            "flushInterval" => 10,
            "targets" => [
                "info" => [
                    "class" => "yiilogFileTarget",
                    "levels" => ["info"],
                    "logVars" => [],
                    "categories" => ["app"],
                    "logFile" => "@console/logs/info/" . date("Ymd") . ".log",
                    "prefix" => function ($message) {
                        return "";
                    }
                ],
                    ...
            ],
        ],
    ],
...

以及測試用例：

// file: console/controllers/TestController.php
namespace consolecontrollers;

use Yii;
use yiiconsoleController;

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

命令行下執(zhí)行./yii test/short，日志正常輸出到指定的文件中；執(zhí)行./yii test/long，使用tailf或者tail -f命令查看日志文件，未發(fā)現(xiàn)輸出；按ctrl+c終止腳本，日志沒有出現(xiàn)新信息。

問題分析

仔細(xì)分析，運(yùn)行上述代碼有兩個問題：1. log組件中flushInterval參數(shù)設(shè)置每10條信息合并輸出一次，實際中一直沒有輸出；2. 按ctrl+c終止腳本，緩沖的信息沒有輸出。

由于之前已經(jīng)向Yii開發(fā)團(tuán)隊提交過一個log組件的bug（issue鏈接：https://github.com/yiisoft/yi...）。本次發(fā)現(xiàn)的問題暫不確定是Yii2的bug還是使用方法不當(dāng)，畢竟（應(yīng)該）很少人會使用命令行運(yùn)行長時間任務(wù)。

查找問題

根據(jù)log組件的架構(gòu)，可能出現(xiàn)問題的三個點事：

Logger類，Yii2默認(rèn)的log組件類，對外暴露打印日志的log/info/warning/error等方法；

Dispatcher類，對消息進(jìn)行分類，根據(jù)配置分發(fā)到具體負(fù)責(zé)輸出的輸出類

Target的具體實現(xiàn)子類，這些子類實現(xiàn)消息的具體輸出，例如保存到文件/數(shù)據(jù)庫，或者發(fā)送郵件等。

根據(jù)這些線索，可以比較清晰的查看調(diào)用鏈條。

首先是Yii::info函數(shù)的調(diào)用，定義在BaseYii中，具體實現(xiàn)委托給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方法功能是格式化消息，然后調(diào)用flush方法輸出日志。接著看flush方法的實現(xiàn)：

// 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將消息分發(fā)到具體的目標(biāo)。繼續(xù)跟蹤前，先看看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回調(diào)函數(shù)，確保腳本執(zhí)行完畢時消息被正確打印。這也是在腳本中無論何時出現(xiàn)exit/die，或者調(diào)用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讓具體負(fù)責(zé)輸出的target類收集信息，如果期間出現(xiàn)異常，關(guān)閉該渠道，將信息以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. 調(diào)用filterMessages方法過濾日志信息； 2. 判斷是否達(dá)到輸出條件，然后調(diào)用子類的export方法實現(xiàn)日志的具體輸出。從collect方法，可以看到第一問題的原因：target類有exportInterval參數(shù)，默認(rèn)是1000，示例代碼要運(yùn)行非常長的時間才會收集到如此多的消息，如果需要及時查看，可將配置代碼改成如下：

// file: console/config/console-local.php
...
"components" => [
        "log" => [
            "flushInterval" => 10,
            "targets" => [
                "info" => [
                    "class" => "yiilogFileTarget",
                            "exportInterval" => 1,
                    "levels" => ["info"],
                            "logVars" => [],
                    "categories" => ["app"],
                    "logFile" => "@console/logs/info/" . date("Ymd") . ".log",
                    "prefix" => function ($message) {
                        return "";
                    }
                ],
                    ...
            ],
        ],
    ],
...

接著再看中斷腳本日志不輸出的問題。前面已經(jīng)提到，日志輸出的技巧是注冊了register_shutdown_function回調(diào)。先看看這個函數(shù)的官方解釋：

注冊一個 callback ，它會在腳本執(zhí)行完成或者 exit() 后被調(diào)用。可以多次調(diào)用 register_shutdown_function() ，這些被注冊的回調(diào)會按照他們注冊時的順序被依次調(diào)用。 如果你在注冊的方法內(nèi)部調(diào)用 exit()， 那么所有處理會被中止，并且其他注冊的中止回調(diào)也不會再被調(diào)用。
Note:
如果進(jìn)程被信號SIGTERM或SIGKILL殺死，那么中止函數(shù)將不會被調(diào)用。盡管你無法中斷SIGKILL，但你可以通過pcntl_signal() 來捕獲SIGTERM，通過在其中調(diào)用exit()來進(jìn)行一個正常的中止。

根據(jù)解釋，register_shutdown_function注冊的函數(shù)將在腳本執(zhí)行完成或者exit后被調(diào)用。但是SIGTERM/SIGKILL等信號，不會回調(diào)注冊的函數(shù)，并且經(jīng)過測試ctrl+c（發(fā)出SIGINT信號）也不會觸發(fā)回調(diào)。

腳本未正常執(zhí)行完被終止，該如何處理？根據(jù)文檔提示，需要使用pcntl_signal函數(shù)捕捉信號，再調(diào)用exit函數(shù)讓腳本正常退出，此時register_shutdown_function注冊的函數(shù)會被正常回調(diào)。

將示例函數(shù)的方法改成：

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

然后在腳本執(zhí)行過程中，按下ctrl_+c，或者通過kill命令發(fā)送信號，日志都正常輸出，表明register_shutdown_function中的回調(diào)函數(shù)被正常調(diào)用。

總結(jié)

發(fā)現(xiàn)的兩個問題，第一個并非Yii2的bug，而是未全面理解文檔導(dǎo)致（Logger類的flushInterval和具體Target類的exportInterval都需要設(shè)置一個合適的值，才能及時查看消息）；第二個問題有點蛋疼，應(yīng)該算PHP的坑。好在非命令行情況下，pcntl拓展不可用，在web開發(fā)中不會出現(xiàn)類似問題。

參考

http://www.yiiframework.com/d...

http://php.net/manual/zh/func...

https://stackoverflow.com/que...

GPU云服務(wù)器云服務(wù)器 linux下cli log問題構(gòu)建混合云,該模式下具備的能力多地辦學(xué)模式下的視頻會議系統(tǒng)如何組建

文章版權(quán)歸作者所有，未經(jīng)允許請勿轉(zhuǎn)載,若此文章存在違規(guī)行為，您可以聯(lián)系管理員刪除。

轉(zhuǎn)載請注明本文地址：http://specialneedsforspecialkids.com/yun/28275.html

發(fā)表評論

登陸后可評論

0條評論

ztyzz

男|高級講師

我要關(guān)注我要私信

TA的文章

【算法學(xué)習(xí)】1486. 數(shù)組異或操作（java / c / c++ / python / go /

閱讀 2135·2021-10-14 09:43
前端面試題總結(jié)

閱讀 2197·2019-08-30 15:55
TCP/IP基礎(chǔ)總結(jié)性學(xué)習(xí)（2）

閱讀 726·2019-08-30 14:23
[note]大小不固定的圖片、多行文字的水平垂直居中

閱讀 2019·2019-08-30 13:21
CSS相對定位

閱讀 1235·2019-08-30 12:50
css兩種垂直居中對齊解決方案

閱讀 2199·2019-08-29 18:46
小程序使用之自定義組件

閱讀 2280·2019-08-29 17:28
【每日一包0014】to-pascal-case,to-sentence-case,to-snake

閱讀 2359·2019-08-29 17:21

国产xxxx99真实实拍_久久不雅视频_高清韩国a级特黄毛片_嗯老师别我我受不了了小说

資訊專欄INFORMATION COLUMN

上云采購季！| 2核2G4M爆款云服務(wù)器低至59元/年，更有多臺、長期優(yōu)惠，快來選購！

CLI模式下Yii2的log問題追蹤

相關(guān)文章

基于Sanic的微服務(wù)基礎(chǔ)架構(gòu)

**對Yii2 migrate數(shù)據(jù)庫遷移的一些看法和操作分享**

發(fā)表評論

0條評論

ztyzz

男|高級講師

TA的文章

【算法學(xué)習(xí)】1486. 數(shù)組異或操作（java / c / c++ / python / go /

前端面試題總結(jié)

TCP/IP基礎(chǔ)總結(jié)性學(xué)習(xí)（2）

[note]大小不固定的圖片、多行文字的水平垂直居中

CSS相對定位

css兩種垂直居中對齊解決方案

小程序使用之自定義組件

【每日一包0014】to-pascal-case,to-sentence-case,to-snake

最新活動