Путь строки лога от приложения до файла: где она может потеряться

MAATRIX

Сервис упал в три часа ночи, а последней строки перед крахом в файле лога просто нет — хотя в коде совершенно точно стоит log.error(...) прямо перед тем местом, где всё развалилось. Первая реакция — «логгер сломан» или «диск потерял данные». На деле почти всегда виновата не поломка, а нормальная работа нескольких буферов и очередей, через которые строка лога проходит, прежде чем физически лечь на диск. На каждом из этих участков у неё есть шанс исчезнуть, если сбой случится в неудачный момент. Разберём весь путь по шагам — от вызова в приложении до реального появления байтов в файле — и покажем, где именно происходит потеря и что на самом деле означает «гарантированная» запись лога.

Из чего состоит путь строки лога: пять точек, где она может исчезнуть

Когда код вызывает print(), console.log(), logger.info() или syslog(), кажется, что строка тут же оказывается в файле. На самом деле между вызовом и физическим байтом на диске обычно есть цепочка промежуточных хранилищ, и «строка лога записана» — это утверждение про самый последний узел цепочки, а не про первый:

1. Буфер стандартного вывода внутри процесса — stdio-буфер в libc (для C/C++/многих интерпретируемых языков) или его аналог в рантайме языка.
2. Очередь асинхронного логгера, если используется — многие библиотеки логирования не пишут синхронно, а кладут запись в очередь и отдают управление обратно коду.
3. Транспорт до посредника — pipe или unix-сокет, по которому вывод процесса уходит в journald, syslog-демон или Docker log driver.
4. Буфер/очередь самого посредника — journald, rsyslog, драйвер логов Docker тоже не пишут на диск немедленно построчно.
5. Страничный кэш ядра и физическая запись на носитель — даже успешный write() в файл ещё не значит, что байты долетели до флеш-памяти или пластин диска.

Ключевая мысль, которая пригодится дальше: «запись прошла» на любом шаге, кроме последнего, означает только «передана дальше», а не «сохранена». Именно граница между этими двумя состояниями и есть источник большинства «пропавших» строк лога.

Буферизация в самом процессе: stdout, stderr и разница между терминалом и файлом

Первая и самая недооценённая точка потери — это буферизация стандартного вывода внутри самого процесса, на уровне библиотеки ввода-вывода языка.

Классический stdio (glibc и большинство рантаймов, которые на него опираются) использует три режима буферизации:

• unbuffered — каждый вызов сразу превращается в системный вызов write();
• line-buffered — буфер сбрасывается при каждом символе перевода строки;
• fully buffered (block-buffered) — данные копятся в буфере фиксированного размера и сбрасываются, когда буфер заполнен (или явно вызван flush).

Режим выбирается автоматически в зависимости от того, куда подключён поток вывода. Когда stdout привязан к терминалу, библиотека обычно включает line-buffered режим — вывод виден построчно почти сразу. Но как только процесс запускают с перенаправлением в файл или через | — а именно так чаще всего работают сервисы под systemd, в контейнере или за nohup, — stdio переключается на полностью буферизованный режим: строки копятся в памяти и не покидают процесс, пока буфер не заполнится или процесс не завершится штатно.

Отсюда классическая грабля: приложение пишет отладочные print() в файл через редирект (./app > out.log 2>&1 &), всё выглядит нормально при плановой остановке, но при kill -9 или аварийном завершении последние строки — те, что как раз объясняли бы причину сбоя, — потеряны, потому что сидели в непереданном блочном буфере и никогда не доходили до write().

Практические способы избежать этого:

# Принудительно построчная буферизация для чужой программы
stdbuf -oL -eL ./my_app > app.log 2>&1

# Python: переменная окружения или флаг интерпретатора
PYTHONUNBUFFERED=1 python app.py
python -u app.py

# Python 3.7+: явно включить line buffering для уже открытого потока
python -c "import sys; sys.stdout.reconfigure(line_buffering=True)"

Отдельно стоит помнить: stderr в большинстве рантаймов по умолчанию небуферизован или буферизуется построчно независимо от того, терминал это или файл — поэтому многие логгеры по умолчанию пишут warning/error в stderr, а debug/info — в stdout: у критичных сообщений выше шанс реально покинуть процесс до его гибели.

Асинхронные логгеры: скорость в обмен на окно потери

Второй источник потерь — не stdio, а сам логгер, если он спроектирован как асинхронный. Это очень частая настройка для нагруженных сервисов: AsyncAppender/AsyncLogger в log4j2, асинхронные синки в Serilog, QueueHandler/QueueListener в стандартной библиотеке логирования Python, обёртки с воркер-потоком у некоторых JS-логгеров, буферизованный WriteSyncer в связках на Go.

Идея логгера здравая: поток приложения не должен блокироваться на дисковом I/O ради строки лога. Вызов logger.info(...) в асинхронном режиме просто кладёт запись в очередь в памяти и немедленно возвращает управление; отдельный поток-писатель забирает записи из очереди и уже он делает настоящий write().

Это значит, что «вызов логгера вернул управление» и «строка покинула процесс» — два разных события, разнесённых во времени. Если процесс погибает между постановкой в очередь и тем моментом, когда писатель успел до неё дойти, — запись пропадает, даже если сам вызов logger.error(...) в коде отработал без исключений.

Есть и вторая грань той же проблемы: у очереди конечная ёмкость. Под шквалом сообщений (например, приложение логирует исключение в цикле) очередь может заполниться, и логгер обычно выбирает одно из двух: либо блокирует вызывающий поток (что убивает саму идею асинхронности), либо молча отбрасывает часть событий — конкретное поведение и настройки по умолчанию отличаются между библиотеками и версиями, это стоит смотреть в документации конкретного логгера.

Что с этим делать на практике:

• для критичных уровней (ERROR/FATAL/panic) использовать синхронную запись или явный flush() сразу после вызова, асинхронность оставить для многочисленных, но не критичных DEBUG/INFO;
• регистрировать обработчик сигнала SIGTERM (штатная остановка через systemd, Docker, оркестратор), который дожидается опустошения очереди перед выходом;
• помнить, что SIGKILL и OOM-killer этот обработчик не вызывают вообще — процесс завершается мгновенно. Именно поэтому после убийства процесса ядром в логе приложения часто нет ни строчки о причине, и объяснение нужно искать не в логе сервиса, а в dmesg/journalctl -k. Механика такого убийства подробно разобрана в статье как ядро выбирает жертву OOM-killer.

Посредник: journald, syslog и драйверы логирования Docker

Во многих реальных развёртываниях приложение вообще не пишет в файл напрямую. Сервис под systemd отправляет stdout/stderr в journald, приложение вызывает syslog() и полагается на локальный syslog-демон, а контейнер в Docker передаёт вывод через log driver. Всё это — ещё один хоп в цепочке, со своей буферизацией и своими правилами игры.

systemd + journald. Вывод сервиса подключён к сокету, который читает journald; сам journald затем решает, что делать с сообщением — держать журнал только в памяти или писать на диск, зависит от параметра Storage= в /etc/systemd/journald.conf (volatile, persistent или auto):

# /etc/systemd/journald.conf
[Journal]
Storage=persistent

Даже при persistent journald не делает fsync на каждую строку — иначе логирование стало бы одним из самых дорогих системных вызовов. Кроме того, у journald есть встроенное ограничение скорости приёма сообщений от источника (RateLimitIntervalSec=/RateLimitBurst=); при аномальном потоке строк часть будет отброшена, а в журнале появится запись вида «Suppressed N messages» — это тоже легитимная точка потери, на уровне посредника, а не приложения.

syslog. Классический вызов syslog() пишет в локальный сокет /dev/log. Если демон, который его слушает (rsyslog, syslog-ng), перезапускается, перегружен или недоступен, сообщение обычно просто теряется — у локального сокетного транспорта нет гарантии доставки и повторной отправки, сравнимой с надёжной очередью.

Docker log driver. Контейнер не пишет в файл на хосте напрямую — его stdout/stderr читает демон Docker через pipe и передаёт выбранному log driver (json-file по умолчанию, но также journald, syslog, local и другие). Если демон под нагрузкой или driver настроен неоптимально, задержка и потери возможны и здесь. Практический разбор настройки — в статье лучшие практики логирования в Docker.

Если в разных сервисах используются разные посредники — кто-то пишет напрямую в файл, кто-то через journald, кто-то через Docker log driver, — у них будут разные окна потери и разное поведение при перегрузке. Единая политика логирования для инфраструктуры снижает число сюрпризов при разборе инцидента.

Финальная миля: страничный кэш ядра и что значит «настоящая» запись на диск

Даже когда строка лога добралась до финального write() в файл, это ещё не запись на физический носитель. Ядро Linux по умолчанию перехватывает данные в страничный кэш (page cache) в оперативной памяти и сразу возвращает управление — это «отложенная» (write-back) запись, и именно она делает файловый ввод-вывод быстрым. Реальный перенос «грязных» страниц на диск делают фоновые потоки ядра; частота и агрессивность переноса регулируются параметрами вроде vm.dirty_ratio, vm.dirty_background_ratio и vm.dirty_writeback_centisecs — конкретные значения по умолчанию зависят от дистрибутива и объёма памяти, их стоит смотреть через sysctl -a | grep dirty на своей системе, а не считать одинаковыми везде.

Отсюда следствие, которое ломает интуицию: успешный write() (и даже видимый в файле правильный размер) не означает, что данные переживут внезапное отключение питания или панику ядра. Пока страница остаётся «грязной» в кэше, потеря питания стирает её так же, как стёрла бы недописанные данные в оперативной памяти — с точки зрения диска этой записи никогда не было.

Чтобы принудительно сбросить данные на носитель, приложение или логгер должны явно вызвать fsync() (весь файл) или fdatasync() (только данные). Но даже успешный fsync() — не абсолютная гарантия: стек хранения может состоять из нескольких уровней со своим кэшем — кэш записи диска, кэш RAID-контроллера, слой виртуального диска в гипервизоре, кэш облачного блочного хранилища. Если какой-то из этих уровней отчитывается о завершении записи раньше, чем данные реально закреплены физически, fsync() в приложении не спасает — этой проблеме посвящена статья барьер записи и кэш диска, который врёт.

Поэтому строгое определение «гарантированной» записи строки лога звучит так: приложение (или логгер от его имени) выполнило запись и дождалось успешного fsync()/fdatasync(), и весь нижележащий стек хранения честно выполнил этот флаш, а не сделал вид. Большинство логгеров по умолчанию не делают fsync на каждую строку — это резко снижает пропускную способность, поэтому синхронизация обычно выполняется периодически или при закрытии файла, что снова возвращает к тому же компромиссу: скорость против окна потери.

Что делать: как в реальности снизить окно потери на каждом этапе

Полностью убрать буферизацию нельзя — это убьёт производительность приложения и диска. Но окно потери можно осмысленно сузить там, где цена ошибки высока:

На уровне процесса.

• Для критичных путей вызывайте flush() явно перед завершением, а не полагайтесь на автоматический сброс буфера.
• Для сервисов с перенаправлением вывода в файл учитывайте, что stdio переключится в блочно-буферизованный режим — используйте stdbuf или настройте line-buffered режим в самом логгере.

На уровне логгера.

• Разделяйте уровни по стратегии записи: DEBUG/INFO — асинхронно, ERROR/FATAL/панику — синхронно или с гарантированным flush.
• Ставьте обработчик SIGTERM, который дренирует очередь при штатной остановке (systemd stop, docker stop). Это не спасает от SIGKILL и OOM-killer.

На уровне посредника.

• Для journald — сознательно выберите Storage=persistent, если журнал должен переживать перезагрузку, и следите за journalctl на предмет строк «Suppressed» — это прямой сигнал, что часть сообщений отбрасывается лимитом скорости.
• Для Docker — задавайте log-driver и опции ротации явно в docker-compose.yml, а не полагайтесь на настройки демона по умолчанию:

services:
  app:
    image: myapp:latest
    logging:
      driver: json-file
      options:
        max-size: "10m"
        max-file: "3"

На уровне диска.

• Для данных, которые нельзя терять (аудит-события, биллинг), не полагайтесь на «обычное логирование» — используйте явный fsync с проверкой кода возврата, транзакцию в базе или очередь с подтверждённой персистентностью. Файл лога с периодическим флашем для этого не годится по конструкции.
• Проверьте, что ротация логов не создаёт проблем поверх уже описанных: неправильная стратегия (truncate вместо copytruncate при открытом дескрипторе у приложения) обнуляет файл, в который процесс продолжает писать по старому дескриптору, — новые строки уходят в никуда. Как настроить это корректно — в статье ротация логов, чтобы не забивался диск.

Проверить цепочку на своей системе несложно: запустите тестовое приложение, которое пишет по строке в секунду через ваш реальный путь (stdout → редирект/journald/docker → файл), и оборвите его kill -9 под нагрузкой. Сравните последнюю строку в логе приложения с временем убийства по journalctl — разница и покажет реальный размер вашего окна потери.

Частые вопросы