Реконструкция инцидента развалилась: в логах не было смещения часового пояса

Сводил хронологию инцидента из четырёх источников: веб-сервер, балансировщик, приложение и почтовый шлюз. Собрал события, отсортировал, посмотрел, что за чем шло, - работа механическая.

Так продолжается, пока не выясняется, что порядок событий физически невозможен: ответ приходит раньше запроса, сессия закрывается до того, как открылась, а письмо оказывается доставлено на два часа раньше отправки. Ошибки в логах при этом нет. Каждый источник записал своё время правильно - по своим часам и в своих обозначениях.

Три причины, по которым метки времени не сходятся

Их удобно разделять, потому что чинятся они по-разному.

Расхождение хода. Часы на узле идут неточно и уходят. Без синхронизации типичный дрейф - секунды в сутки; за месяц набегает минута-другая. Для корреляции «вход и следом запуск процесса» этого достаточно, чтобы поменять эти два события местами.

Разные точки отсчёта. Один узел пишет по UTC, другой по местному времени, третий - по времени того, кто настраивал контейнер. Часы у всех верные. Числа несопоставимые.

Момент записи вместо момента события. Метка ставится не тогда, когда событие произошло, а тогда, когда событие дошло до конвейера. При буферизации и повторной отправке это разные вещи, и разница плавает.

Первое лечится синхронизацией, второе - форматом, а третье - тем, что вы вообще понимаете, чью метку читаете; оно же обычно и оказывается самым неприятным.

Формат, который ничего не говорит

Классический syslog в форме BSD, он же RFC 3164, выглядит так:

Sep  6 03:14:07 gw-01 sshd[2411]: Accepted publickey for svc-backup from 203.0.113.44

В строке нет года и нет часового пояса. Год восстанавливается по имени файла и по ротации, часовой пояс - никак: чтобы его узнать, надо обратиться к узлу, который эту строку написал, и посмотреть его настройки. На момент разбора этого узла может уже не быть.

Формат объявлен устаревшим, и утилиты об этом предупреждают:

$ logger --help | grep -i rfc
     --rfc3164            use the obsolete BSD syslog protocol
     --rfc5424[=<snip>]   use the syslog protocol (the default for remote)

Замена - RFC 5424, где метка времени полная и со смещением (в начале - приоритет и номер версии, они входят в формат и в реальном сообщении присутствуют):

<38>1 2026-09-06T03:14:07.221394+05:00 gw-01 sshd 2411 - - Accepted publickey for svc-backup

Год есть, доли секунды есть, смещение есть. Такую строку можно нормализовать, не зная ничего про узел, который её написал.

+05:00 в конце - не украшение и не избыточность. Это единственное, что делает метку самодостаточной. Строка без смещения задаёт время только вместе с настройками узла, а они к ней не приложены.

Почему «поставим всем UTC» решает не всё

Совет правильный, я его и даю. Но он про источники, которые вы настраиваете, а в разборе участвуют и другие.

Заголовки почты содержат смещение отправителя, и оно чужое. Логи внешнего провайдера приходят в его поясе. Экспорт из SaaS-панели отдаёт время в поясе учётной записи того, кто нажал кнопку экспорта, - и при повторной выгрузке другим человеком числа будут другими. Скриншот из интерфейса показывает время браузера смотрящего.

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

Отдельно стоит помнить про переход на летнее время в тех источниках, где он есть. Один час в году повторяется дважды, и метка без смещения внутри этого часа неоднозначна принципиально: два разных момента записываются одинаково. Сортировка внутри такого интервала - угадывание.

Служба синхронизации запущена - это ещё не синхронизация

Клиент NTP на узле обычно установлен и включён. Это ещё ничего не значит: он может месяцами не получать ответа от сервера, и в норме об этом никто не узнает.

$ journalctl -u systemd-timesyncd -n 2 -o short-iso
2026-09-06T00:11:35+00:00 gw-01 systemd-timesyncd[495]: Timed out waiting for reply from 192.0.2.31:123 (ntp.example.com).
2026-09-06T00:12:40+00:00 gw-01 systemd-timesyncd[495]: Contacted time server 198.51.100.123:123 (ntp2.example.com).

Здесь всё закончилось хорошо, но в первой строке сервер не ответил. Если бы вторая не появилась, часы продолжили бы идти сами по себе, а служба бы работала и считалась настроенной.

Смотреть надо не на факт запуска службы, а на факт синхронизации:

$ timedatectl show -p NTP -p NTPSynchronized
NTP=yes
NTPSynchronized=yes

NTP=yes - служба включена. NTPSynchronized=yes - она действительно получила время от сервера. Это два независимых утверждения, и мониторить надо второе.

Две оговорки, без которых проверка даёт неверный результат. Она годится для systemd-timesyncd: если синхронизацию обеспечивает chrony или ntpd, NTP будет no при полностью исправных часах, и вы получите ложную тревогу - там смотрят chronyc tracking. И NTPSynchronized отражает флаг ядра, который не сбрасывается в ту же секунду, как сервер перестал отвечать, - то есть yes не означает «синхронизировано прямо сейчас». Поэтому в мониторинге держат ещё и саму величину расхождения. В типовых наборах проверок для Zabbix и Prometheus этого обычно нет, дописывают руками.

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

Чем CLOCK_MONOTONIC отличается от CLOCK_REALTIME

Раз уж речь зашла о времени, стоит развести два источника времени, которые в коде путают регулярно.

CLOCK_REALTIME - календарное время. Его правит NTP, оно может скакнуть назад, и именно оно нужно в логах.

CLOCK_MONOTONIC - счётчик, который не прыгает и назад не идёт; NTP подстраивает его только скоростью хода. Отсчёт ведётся от загрузки, но время сна системы в него не входит - для этого есть CLOCK_BOOTTIME, а полностью неподстраиваемый вариант называется CLOCK_MONOTONIC_RAW.

$ python3 -c "
import time
print('REALTIME :', time.clock_gettime(time.CLOCK_REALTIME))
print('MONOTONIC:', time.clock_gettime(time.CLOCK_MONOTONIC))"
REALTIME : 1788664447.221394
MONOTONIC: 104857.318204411

Число справа - около 29 часов работы, к календарю оно отношения не имеет. Ошибка в обе стороны стоит по-разному: календарное время для измерения таймаута даёт отрицательную длительность в момент коррекции часов, а монотонное в логе даёт метку, которую не с чем сопоставить.

Что делать до инцидента

Договориться о формате и записать его в требования к логированию: RFC 5424 или ISO 8601 со смещением, доли секунды - обязательны. Секундной гранулярности не хватает: события внутри одной секунды в разборе встречаются постоянно, и порядок между ними теряется.

Нормализовать на приёме, сохраняя оригинал. Приведённое к UTC время - рабочее поле для сортировки; исходная строка остаётся рядом, потому что при спорном выводе смотреть придётся именно на неё.

Мониторить синхронизацию как обычную метрику. Не «служба запущена», а «расхождение с сервером меньше порога».

Проверять сквозную согласованность. Раз в какое-то время прогонять по своим источникам событие с известным временем и смотреть, как каждый его записал. Расхождение чаще всего находится у самого старого сетевого оборудования, которое поддерживает только BSD-формат и другого не поддержит.

Про источники, которые вам не подчиняются, записать, чью метку они ставят. Одна страница текста, которую пишут один раз и читают в момент разбора.

Что посмотреть у себя

Взять по одной строке из каждого источника, который попадает в систему сбора, и выписать их в столбик. Быстро становится видно, у скольких из них в метке нет смещения.

Проверить NTPSynchronized на узлах, куда давно не заходили руками. Один-два узла обычно находятся.

И посмотреть, что происходит с сортировкой в вашем интерфейсе, если у двух событий совпали секунды. Иногда порядок берётся из идентификатора записи, а он не связан со временем события вовсе - и хронология, на которую вы смотрите, собрана не по тому полю.