Рубрики
Uncategorized

Отслеживание проблем журнала Yii2 в режиме CLI

Автор оригинала: David Wong.

Для перепечатки, пожалуйста, укажите источник: https://tlanyan.me/trace-log-…

Запустив длинную задачу в командной строке, было обнаружено, что компонент журнала Yii2 не смог правильно вывести журнал. В свободное время я постепенно отслеживаю проблему и, наконец, выясняю причину. Вот запись отслеживания проблем.

Повторение проблемы

Чтобы воспроизвести проблему, конфигурация компонента журнала подготовлена заранее:

// 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 тест/короткий Журнал обычно выводится в указанный файл; выполните ./yii тест/длинный Используйте tailf возможно tail-f Команда для просмотра файлов журнала, вывод не найден; нажмите ctrl+c Завершите сценарий, и в журнале не появится новая информация.

анализ проблем

После тщательного анализа при выполнении приведенного выше кода возникают две проблемы: 1. В компоненте журнала flushInterval Настройки параметров выводятся один раз каждые 10 единиц информации, но на практике вывода не было; 2. Нажмите ctrl+c Сценарий завершается, и буферизованная информация не выводится.

Поскольку ошибка в компоненте журнала была передана команде разработчиков Yii (ссылка на проблему: https://github.com/yiisoft/yi…). Является ли Yii2 ошибкой или неправильным способом его использования, неизвестно. В конце концов, мало кто использует командную строку для выполнения длительных задач.

Проблема поиска

В соответствии с архитектурой компонентов журнала возможны три проблемы:

  1. Класс регистратора, класс компонентов журнала по умолчанию Yii2, метод регистрации/информации/предупреждения/ошибок для отображения журналов печати;
  2. Класс диспетчера, который классифицирует сообщения и распределяет их в соответствии с конфигурацией в выходной класс, специально отвечающий за вывод
  3. Подклассы конкретной реализации цели, которые реализуют конкретный вывод сообщений, таких как сохранение в файл/базу данных или отправка почты и т. Д.

Согласно этим подсказкам, мы можем четко видеть цепочку вызовов.

Первый-это Yii::информация Вызовы функций, определенные в BaseYii В этой статье метод ведения журнала, доверенный классу Logger, реализован конкретно:

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

Функция метода журнала состоит в форматировании сообщений, а затем вызове их 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 делегирует диспетчеру возможность распространять сообщения определенным целям. Прежде чем продолжить трассировку, посмотрите на метод init класса Logger:

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

Когда компонент регистратора инициализирован, зарегистрируйте register_shutdown_function Функцию обратного вызова, чтобы убедиться, что сообщение печатается правильно при выполнении сценария. Это также секрет того, что каждый раз, когда в скрипте появляется выход/смерть или вызывается Yii:: $app – > end (), журнал будет выводиться нормально. Далее рассмотрим метод отправки класса Dispatcher:

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

Отправка позволяет целевому классу, специально ответственному за вывод, собирать информацию. Если в течение этого периода произойдет исключение, закройте канал и выведите информацию на уровень предупреждения. Затем отследите метод сбора целевого объекта, который определен в целевом абстрактном классе:

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

Функция метода сбора: 1. Вызовите метод filterMessages для фильтрации информации журнала; 2. Определите, выполнено ли условие вывода, а затем вызовите метод экспорта подкласса для реализации конкретного вывода журнала. Из метода сбора вы можете увидеть причину этой проблемы: целевой класс имеет параметр 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 Обратный вызов. Давайте сначала рассмотрим официальное объяснение этой функции:

Зарегистрируйте обратный вызов, который будет вызван после выполнения сценария или выхода ().

Regis_shutdown_function() можно вызывать много раз, и эти зарегистрированные обратные вызовы вызываются в том порядке, в котором они были зарегистрированы. Если вы вызовете exit () в зарегистрированном методе, вся обработка будет прервана, и другие зарегистрированные обратные вызовы прерываний больше не будут вызываться.

Примечание:

Если процесс будет остановлен сигналом SIGTERM или SIGKILL, функция прерывания не будет вызвана. Хотя вы не можете прервать SIGKILL, вы можете захватить SIGTERM с помощью pcntl_signal() и выполнить обычное прерывание, вызвав exit ().

Согласно объяснению, функция, зарегистрированная в register_shutdown_function, будет вызвана после выполнения или выхода из сценария. Однако SIGTERM/SIGKILL и другие сигналы не вызывают обратно зарегистрированные функции и были протестированы. ctrl+c (сигнал SIGINT) не вызовет обратный вызов.

Если скрипт завершается после обычного выполнения, как с этим бороться? Согласно приглашению документа, нам нужно использовать функцию pcntl_signal для захвата сигнала, а затем вызвать функцию выхода, чтобы сценарий вышел нормально. В это время зарегистрированная функция 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, а отсутствие всестороннего понимания документа (flushInterval класса Logger и exportInterval целевого класса должны установить соответствующее значение для своевременного просмотра сообщения); второй-небольшая проблема, которая должна быть проблемой в PHP. К счастью, в случае не командной строки расширение pcntl недоступно, и в веб-разработке не возникнет подобной проблемы.

Справочные ресурсы

  1. Справочные ресурсы
  2. Справочные ресурсы
  3. Справочные ресурсы
  4. Справочные ресурсы