Приоритеты syslog: почему половина сообщений не доезжает до вашего файла

MAATRIX

Вы открываете /var/log/syslog, ищете сообщение, которое приложение точно должно было записать — а его там нет. Не в смысле «затёрлось ротацией», а в смысле «его там никогда не было». Причина почти всегда одна: syslog решает, куда отправить строку, ещё до того, как она попадёт в файл, и это решение принимается по двум признакам — facility и severity. Если правила маршрутизации настроены не так, как вы думаете, сообщение уходит в другой файл или отбрасывается молча, без ошибки и без предупреждения.

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

Когда процесс отправляет строку через syslog (вызовом syslog() из libc, через logger в shell-скрипте или через сокет /dev/log), он помечает её двумя атрибутами.

Facility — это заявленный источник сообщения, то есть какая подсистема его отправила. Стандарт RFC 5424 определяет ограниченный набор facility, и приложение выбирает одну из них при отправке:

• kern — сообщения ядра;
• user — сообщения пользовательских процессов (значение по умолчанию, если приложение явно не указало другое);
• mail — почтовая подсистема (Postfix, Exim, Dovecot);
• daemon — системные демоны без своей выделенной facility;
• auth и authpriv — аутентификация и авторизация (sshd, sudo, su, PAM);
• cron — планировщик задач;
• syslog — сообщения самого syslog-демона;
• lpr, news, uucp, ftp — устаревшие подсистемы, сегодня почти не используются;
• local0–local7 — восемь facility, зарезервированных для произвольного использования сторонними приложениями и вашими собственными скриптами.

Severity — это уровень важности, от 0 до 7: emerg, alert, crit, err, warning, notice, info, debug. Приложение само решает, каким уровнем пометить конкретную строку — неудачная попытка входа обычно уходит с warning или err, штатный старт сервиса — с notice или info, отладочная трассировка — с debug.

Ключевой момент: facility и severity — это не путь к файлу. Это метаданные, прикреплённые к сообщению в момент отправки. Куда именно оно попадёт дальше, решает конфигурация syslog-демона (обычно rsyslog, реже syslog-ng), а не приложение. Приложение может честно залогировать событие и вообще не знать, что оно упадёт в /dev/null через два шага.

Как rsyslog решает, куда писать: селекторы

Конфигурация rsyslog — это набор правил вида селектор действие, где селектор описывает пару facility.severity, а действие — обычно путь к файлу. Классический пример из /etc/rsyslog.conf или файлов в /etc/rsyslog.d/:

auth,authpriv.*                /var/log/auth.log
*.*;auth,authpriv.none         -/var/log/syslog
daemon.*                       -/var/log/daemon.log
kern.*                         -/var/log/kern.log
mail.*                         -/var/log/mail.log
cron.*                         /var/log/cron.log
*.=debug                       -/var/log/debug
*.=info;*.=notice;*.=warn;\
        auth,authpriv,mail,cron,daemon.none    -/var/log/messages

Синтаксис читается так:

• facility.severity — сообщение с этой facility и с этим severity или выше (severity — это иерархия важности, сравнение по умолчанию — «не ниже указанного уровня»);
• facility.=severity — точное совпадение уровня, без «и выше»;
• facility.!severity — исключение уровня и всего, что выше;
• facility.none — исключить эту facility из правила полностью;
• * — любая facility или любой severity в соответствующей позиции;
• запятая объединяет несколько facility в одном селекторе (auth,authpriv.*);
• точка с запятой объединяет несколько условий для одного действия — они складываются через «И» с накопительным исключением.

Дефис перед путём (-/var/log/syslog) означает асинхронную запись — rsyslog не делает fsync() после каждой строки, что быстрее, но при внезапном отключении питания последние строки можно потерять. Это отдельный источник пропаж, не связанный с фильтрацией, но его тоже стоит держать в голове.

Правило *.*;auth,authpriv.none -/var/log/syslog означает «всё, кроме auth и authpriv». Именно поэтому в auth.log вы видите попытки входа, а в syslog — нет: не потому что событие пропало, а потому что конфигурация явно исключила эту facility из общего файла.

Где именно сообщения теряются: три частых сценария

Сценарий первый — уровень severity отфильтрован по умолчанию. Многие дистрибутивные конфигурации маршрутизируют в /var/log/syslog только info и выше, явно исключая debug (*.=debug -/var/log/debug, отдельным правилом, в отдельный файл, который никто не проверяет). Если ваше приложение логирует диагностику на уровне debug — рассчитывая, что она попадёт в общий syslog, — она туда никогда не попадёт, потому что правило её отфильтровало ещё до записи на диск. Проверить, какой уровень реально долетает, можно только чтением активной конфигурации, а не документации приложения.

Сценарий второй — facility замаскирована в отдельный файл и исключена из общего. Если приложение отправляет события с facility=local0, а в конфигурации для local0 не прописано отдельное правило, но есть общее *.*;auth,authpriv,mail,cron,daemon,local0.none -/var/log/messages (администратор когда-то добавил local0.none, чтобы не засорять общий лог) — сообщения от этого приложения не попадут никуда, если для local0 больше нет ни одного действия. Не в другой файл — в никуда. Это самая коварная ситуация: journalctl или logger -p local0.info "test" покажет, что сообщение отправлено, а в файловой системе не появится вообще ничего.

Сценарий третий — явное отбрасывание через discard-действие. В rsyslog есть возможность прервать обработку сообщения на любом правиле директивой stop (в новом синтаксисе) или символом ~ (в старом):

:msg, contains, "Connection reset by peer" stop

Такие правила добавляют, чтобы не засорять логи известным шумом (переподключения мониторинга, health-check от балансировщика). Проблема в том, что фильтр по подстроке в msg рано или поздно ловит что-то более важное с похожим текстом — например, реальный сбой сети, который тоже содержит фразу «Connection reset by peer», но уже не от health-check, а от продуктивного трафика. Discard-правило одинаково безжалостно к обоим случаям, и в логах не остаётся даже следа того, что строка была отброшена — сама природа stop в том, что дальнейшая обработка (включая запись куда бы то ни было) прекращается.

Почему «приложение залогировало» не значит «файл получил»

Частая ошибка при разборе инцидентов — рассуждать так: «приложение делает syslog(LOG_ERR, ...) при каждой ошибке подключения к базе, значит в /var/log/syslog должны быть все ошибки за последний час». Это предположение проверяет только половину цепочки — то, что приложение действительно вызывает syslog(). Вторая половина — путь от локального сокета /dev/log до конкретного файла — целиком зависит от конфигурации демона, которая могла быть написана три администратора назад под другую задачу.

Правильная последовательность диагностики:

1. Узнать facility и severity, с которыми приложение реально отправляет сообщения — обычно это указано в его конфиге логирования или в документации (для systemd-сервисов часто SyslogFacility= и SyslogLevel= в unit-файле).
2. Найти в rsyslog все правила, которые матчат эту пару, командой:

grep -rE "local0|daemon|user" /etc/rsyslog.conf /etc/rsyslog.d/*.conf

1. Проверить, есть ли выше по списку правило со stop или ~, которое могло прервать обработку раньше, чем сообщение дошло до нужного действия — rsyslog применяет правила по порядку сверху вниз, и порядок файлов в /etc/rsyslog.d/ определяется алфавитной сортировкой их имён.
2. Убедиться, что сам rsyslog перечитал конфигурацию после правки: systemctl reload rsyslog — иначе вы тестируете уже неактуальные правила.
3. Отправить тестовое сообщение с теми же facility.severity и проследить его: logger -p local0.info "routing test $(date +%s)", затем grep "routing test" по всем файлам в /var/log/, а не только по тому, который вы «обычно проверяете».

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

journald как ещё один слой перед rsyslog

На системах с systemd сообщения чаще всего сначала попадают в journald (бинарный журнал, читаемый через journalctl), а уже потом, если настроена пересылка, — в rsyslog. Это добавляет ещё одну точку, где маршрут может незаметно оборваться.

Пересылка из journald в syslog-совместимый сокет управляется параметром ForwardToSyslog в /etc/systemd/journald.conf (или в файлах /etc/systemd/journald.conf.d/*.conf). Если он выключен (ForwardToSyslog=no) или закомментирован со значением по умолчанию, отличным от ожидаемого в вашем дистрибутиве, — rsyslog вообще не получает поток от journald через этот канал, и все правила из предыдущих разделов становятся неприменимы: fильтровать в rsyslog нечего, потому что сообщения туда не доходят.

Второй момент — rate limiting на уровне journald. Параметры RateLimitIntervalSec и RateLimitBurst в том же journald.conf ограничивают, сколько сообщений от одной единицы (service unit) journald примет за интервал времени; при превышении лимита остальные сообщения в этом интервале отбрасываются, а journald делает одну запись вида «N сообщений подавлено» — если вы не увидите её среди тысяч других строк, покажется, что процесс просто перестал логировать. Конкретные значения лимитов по умолчанию отличаются между дистрибутивами и версиями systemd, поэтому их стоит смотреть в journald.conf на вашей системе, а не полагаться на цифру из чужой инструкции.

Проверить, теряет ли journald сообщения из-за лимита, можно так:

journalctl --verify
journalctl -u имя-сервиса --since "1 hour ago" | grep -i "suppressed"

Если видите строку про подавленные сообщения — проблема не в rsyslog и не в правилах маршрутизации, а в лимите на уровне journald, и решать её нужно там: либо поднять лимит для конкретного unit'а через LogRateLimitIntervalSec= и LogRateLimitBurst= в его секции [Service], либо снизить частоту логирования в самом приложении.

Как выстроить маршрутизацию так, чтобы не терять сообщения молча

Практический подход, который снижает риск тихих потерь:

• Заведите явный catch-all в самом конце конфигурации. Последним файлом (по алфавиту — например, zz-catchall.conf) добавьте правило *.* /var/log/catchall.log, которое ловит вообще всё, до чего не дотянулись более ранние правила. Если в catchall.log появляется что-то неожиданное — значит, для этой facility.severity нет специального маршрута, и стоит либо добавить его, либо осознанно проигнорировать.
• Избегайте .none без документирования причины. Каждое исключение facility из общего правила — потенциальная дыра. Комментарий в конфиге («local0 исключён, потому что уходит в /var/log/app-local0.log отдельным правилом выше») экономит часы при следующем разборе инцидента.
• Держите discard-правила (stop, ~) как можно более точными — по конкретному тегу программы (:programname, isequal, "healthcheck") вместо совпадения по подстроке в тексте сообщения, которая может встретиться где угодно.
• Проверяйте синтаксис перед перезапуском: rsyslogd -N1 валидирует конфигурацию без старта демона и покажет ошибку раньше, чем вы потеряете логи из-за невалидного файла.
• Не путайте пропажу сообщения из-за маршрутизации с его исчезновением после ротации — это разные механизмы на разных этапах жизни строки лога; про второй разобрано отдельно в статье про ротацию логов, чтобы не забивался диск.
• Логируйте централизованно, если серверов больше одного. Отдельный слой правил маршрутизации на каждой машине — гарантированный источник расхождений; при пересылке на общий приёмник хотя бы точка проверки маршрута одна. Мы писали отдельно про сбор логов с нескольких серверов — там разобрана схема с центральным rsyslog-приёмником через TCP.

Эти меры не устраняют саму возможность ошибиться в правиле — она встроена в модель facility/severity. Но они превращают «сообщение пропало неизвестно почему» в «сообщение попало в catchall, потому что для него не было правила» — то есть в задачу с понятным следующим шагом.

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