RUEN
Пакет · logger

Жизненный цикл записи лога

Проследим единственный $log->info(…) от места вызова до байта в потоке. Знание порядка — особенно того, где выполняются процессоры — объясняет поведение, которое иначе удивляет, например, какие поля маскируются.

Путь

text
ваш вызов  $log->info('msg', ['id' => 42])
  │
  ▼
Winter Logger::log()      влить boundContext (['class' => FQCN]) под context вызова
  │
  ▼
Monolog Logger::addRecord проверка уровня → построить LogRecord(context, extra={})
  │
  ▼
процессоры (LIFO)         выполняются в обратном порядке добавления:
  │                       1. SensitiveMaskingProcessor  (если добавлен приложением)
  │                       2. ContextInjectingProcessor  (добавлен менеджером)
  ▼
обработчик (проверка уровня) SafeStreamHandler / Syslog / RotatingFile / Null
  │
  ▼
форматтер                 SpringLineFormatter или JsonFormatter
  │
  ▼
запись                    @fwrite(stream, formatted)  — никогда не бросает

Шаг 1 — Привязанный контекст вливается первым

Logger::log() из Winter вливает свой boundContext в context вызова прежде, чем передать управление Monolog. Для логгера на класс boundContext — это ['class' => FQCN]; withContext() добавляет ещё. При конфликте ключей побеждает context самого вызова:

php
public function log(mixed $level, string|Stringable $message, array $context = []): void
{
  $this->monolog->log(
      $level,
      (string) $message,
      empty($this->boundContext) ? $context : array_merge($this->boundContext, $context),
  );
}

Так что к моменту, когда Monolog видит запись, context уже несёт class (и любые привязанные поля). extra пока пуст — его заполняет процессор следующим шагом.

Шаг 2 — Процессоры выполняются в порядке LIFO

Вот часть, которую стоит усвоить. pushProcessor() из Monolog добавляет в начало списка процессоров (array_unshift), а addRecord() обходит этот список от начала к концу. Итоговый эффект: последний добавленный процессор выполняется первым.

Менеджер добавляет ContextInjectingProcessor при построении канала. Если ваше приложение позже добавит SensitiveMaskingProcessor через monolog()->pushProcessor(), он был добавлен позже — поэтому выполняется первым:

text
порядок добавления:  ContextInjecting (менеджером)  →  Masking (приложением)
порядок выполнения:  Masking  →  ContextInjecting
  • SensitiveMaskingProcessor скрывает чувствительные ключи в context и extra.
  • ContextInjectingProcessor затем вливает снимок текущего хранилища контекста в extra (с ранним завершением, когда хранилище пусто).

Маскирование выполняется до инъекции контекста

Поскольку маскирование выполняется первым, оно видит context вызова (уже заполненный), но не поля контекста запроса — те вливаются в extra позже. Секреты, переданные напрямую в вызов лога, маскируются; секрет, заданный через contextStorage()->set(), будет влит после маскирования и проскользнёт. Держите секреты вне хранилища контекста запроса.

Шаг 3 — Фильтрация по уровню происходит дважды

Уровень проверяется у логгера Monolog (ни против чего — Monolog передаёт всё обработчикам) и затем у обработчика, построенного с level канала. Запись ниже минимального уровня канала отбрасывается обработчиком до форматирования. Вот почему level живёт в конфиге канала, а не в вызове.

Шаг 4 — Форматирование

Форматтер обработчика превращает LogRecord в строку. SpringLineFormatter объединяет context + extra в JSON-хвост, берёт короткое имя класса из context['class'] и штампует PID через getmypid(). JsonFormatter вместо этого выдаёт один JSON-объект на строку.

Шаг 5 — Безопасная запись

Для потоковых выводов обработчик — это SafeStreamHandler, чей streamWrite() использует @fwrite и никогда не бросает — так что broken pipe стоит одной строки, а не процесса. Обработчики syslog, file и null делают свой финальный шаг.

Почему порядок важен на практике

  • class всегда присутствует для логгеров на класс — он вливается на шаге 1, прежде чем что-либо ещё сможет его коснуться.
  • Контекст запроса — построчный, живой — он читается заново на шаге 2 на каждой записи, так что изменение его посреди запроса меняет последующие строки.
  • Маскируйте то, что передаёте, а не то, что вливаете — порядок LIFO означает, что маскирование и инъекция не компонуются так, как вы могли бы предположить.

Смотрите также