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

[otezvikentiy]

Хорошая статья, и я добавлю вторую половину задачи - со стороны приёмника. Дисклеймер: я делаю self-hosted-мониторинг, то есть ровно ту штуку, которая эти логи принимает, так что смотрю с этой колокольни.

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

Неочевидное место в OTLP: там кроме TimeUnixNano есть ObservedTimeUnixNano, и его страшно хочется использовать как запасное значение, когда основное поле пустое. Так делать нельзя - его заполняет клиент, то есть те же самые сбитые часы. Мы его не читаем: observed_ts всегда серверное время приёма, а если TimeUnixNano нулевой, туда же уезжает и время события. Иначе защита от кривых часов протекает ровно там, где вы её ставили.

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

Логи клампятся в окно [now-90d, now+24h], а не отбрасываются: лог со сбитым временем всё ещё несёт тело и severity, и потерять запись хуже, чем показать её на границе окна. Диапазон выборки при чтении логов всё равно задаёт человек, и он видит, что запись прижата к краю.

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

И последнее, ради чего окно вообще существует, - оно не про эстетику. Таблица логов партиционирована по месяцу. Один батч, размазанный по десяткам месяцев, упирается в max_partitions_per_insert_block ClickHouse, вставка всего батча падает и встаёт в голове буфера писателя - приём логов останавливается для всего инстанса. То есть кривое время у одного отправителя без окна становится отказом в обслуживании для всех.

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