Сводил хронологию инцидента из четырёх источников: веб-сервер, балансировщик, приложение и почтовый шлюз. Собрал события, отсортировал, посмотрел, что за чем шло, - работа механическая.
Так продолжается, пока не выясняется, что порядок событий физически невозможен: ответ приходит раньше запроса, сессия закрывается до того, как открылась, а письмо оказывается доставлено на два часа раньше отправки. Ошибки в логах при этом нет. Каждый источник записал своё время правильно - по своим часам и в своих обозначениях.
Три причины, по которым метки времени не сходятся
Их удобно разделять, потому что чинятся они по-разному.
Расхождение хода. Часы на узле идут неточно и уходят. Без синхронизации типичный дрейф - секунды в сутки; за месяц набегает минута-другая. Для корреляции «вход и следом запуск процесса» этого достаточно, чтобы поменять эти два события местами.
Разные точки отсчёта. Один узел пишет по 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 на узлах, куда давно не заходили руками. Один-два узла обычно находятся.
И посмотреть, что происходит с сортировкой в вашем интерфейсе, если у двух событий совпали секунды. Иногда порядок берётся из идентификатора записи, а он не связан со временем события вовсе - и хронология, на которую вы смотрите, собрана не по тому полю.