轉載請註明出處：https://tlanyan.me/trace-log-…
命令列下執行長時間任務，發現Yii2的log元件不能正常輸出日誌。空閒之餘逐步追蹤問題，終於發現原因，以下是問題追蹤記錄。
問題復現
為了復現問題，預先準備了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;
}
}
命令列下執行./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/yi…）。本次發現的問題暫不確定是Yii2的bug還是使用方法不當，畢竟（應該）很少人會使用命令列執行長時間任務。
查詢問題
根據log元件的架構，可能出現問題的三個點事：
- Logger類，Yii2預設的log元件類，對外暴露列印日誌的log/info/warning/error等方法；
- Dispatcher類，對訊息進行分類，根據配置分發到具體負責輸出的輸出類
- Target的具體實現子類，這些子類實現訊息的具體輸出，例如儲存到檔案/資料庫，或者傳送郵件等。
根據這些線索，可以比較清晰的檢視呼叫鏈條。
首先是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方法的實現：
// 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` => `yiilogFileTarget`,
`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開發中不會出現類似問題。