Переход на летнее время запустил ночной отчёт два раза

MAATRIX

В ночь перевода часов подписчики ночного отчёта получили два одинаковых письма подряд, а служба поддержки — десяток вопросов «у вас всё в порядке?». Отчёт не сломался и не завис — он честно отработал два раза. Разбираем, как планировщик на pytz и фоновая переинициализация расписания подловили друг друга ровно на переходе через границу летнего времени, и почему один час разницы оказался достаточным поводом для дубля.

Что случилось

Сервис у нас на UK-инфраструктуре каждую ночь в 02:30 по Europe/London собирал сводный отчёт по активности клиентов за сутки — метрики, суммы, статусы — и рассылал его подписчикам по email плюс писал копию в таблицу nightly_reports. Задача штатная, отлажена больше года, ни разу не давала сбоев ни на переходе к летнему времени в прошлые годы, ни на возврате к зимнему.

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

Первая реакция — «опять дубль в cron», потому что именно так чаще всего выглядят подобные истории. Но проверка показала, что дело куда интереснее: единственный источник запуска, и тот отработал ровно по правилам, которые в него заложили. Просто сами правила в ночь перевода часов начали противоречить друг другу.

Что показали логи и метрики

Первым делом подняли логи самого сервиса отчётов — journalctl -u nightly-report.service --since "02:00" --until "04:00" — и увидели два полных цикла выполнения: сбор данных, рендер, отправка, запись в БД. Оба цикла завершились без единой ошибки или warning, оба заняли примерно одинаковое время. Это сразу исключило версию про зависший процесс, который перезапустили руками или через watchdog — здесь было два чистых, самостоятельных запуска.

journalctl -u nightly-report.service --since "02:00" --until "04:00" \
  | grep -E "report started|report finished"

Вывод показал старт первого запуска в 02:30 по местному времени и старт второго — примерно в 03:16. Разница чуть больше 40 минут, не ровный час и не ровные сутки — это было первой зацепкой: если бы дублировали две одинаковые cron-задачи, разница была бы фиксированной и повторялась бы каждую ночь, а не только в ночь перевода часов.

Дальше посмотрели, кто вообще инициирует запуск. Планировщик у сервиса был не системный cron и не голый systemd timer, а собственный демон на Python: он хранит расписание в базе, использует pytz для локализации времени и раз в 15 минут перечитывает конфиг расписания на случай, если кто-то поменял время рассылки через админку. Это архитектурное решение — идея была в том, чтобы не перезапускать сервис при изменении расписания. Именно в этом «удобстве» и крылась причина.

Проверили метрики планировщика в Grafana (стандартный дашборд для фоновых джобов): счётчик scheduler_job_triggered_total{job="nightly_report"} в эту ночь показал значение 2 вместо привычной 1 — подтверждение, что триггернуло именно ядро планировщика, а не что-то снаружи вроде ручного запуска или второй копии сервиса.

Гипотезы, которые отбросили

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

• Второй cron-энтри или забытый systemd timer. Проверили crontab -l, /etc/cron.d/, systemctl list-timers --all на всех нодах — задача объявлена ровно один раз, на одном хосте.
• Повторная доставка из очереди сообщений. Отчёт не триггерится событием из очереди — это чистое время-based расписание, никакого брокера в цепочке запуска нет. Версию отклонили сразу, как только посмотрели на архитектуру, но всё равно перепроверили — вдруг кто-то незаметно перевесил задачу на event-driven триггер. Не подтвердилось.
• Два активных реплика сервиса, оба считают себя лидером. Сервис используется с leader election через запись в PostgreSQL (pg_try_advisory_lock), лог lease-менеджера показал, что лидер на протяжении ночи не менялся — один и тот же под держал advisory lock всё время. Split-brain отпал.
• Ретрай в коде отправки отчёта после мнимой ошибки. Если бы первая попытка отправки завершилась с ошибкой (таймаут SMTP, 5xx от API), а ретрай-логика перезапускала бы весь job целиком — картина была бы похожа. Но в логах первого запуска не было ни одной ошибки, оба запуска — успешные от начала до конца. Значит, дело не в обработке сбоя, а в том, что планировщик дважды решил, что настало время запускать job.
• Дрейф системных часов из-за NTP. Проверили chronyc tracking — рассинхронизации не было, смещение в пределах десятков миллисекунд, коррекции скачком не происходило. Значит, дело не в самих часах, а в логике, которая их интерпретирует.

После того как внешние причины отпали, стало ясно: смотреть нужно внутрь планировщика, в код, который считает «когда наступит следующий запуск».

Настоящая причина: как столкнулись два расчёта времени

Внутри демона расписание хранится так: для каждой задачи есть next_run_at — datetime с таймзоной, вычисленный один раз при старте или при перечитывании конфига. Логика простая на вид:

import pytz

TZ = pytz.timezone("Europe/London")

def compute_next_run(previous_run_local):
    # previous_run_local — aware datetime в TZ
    next_run = previous_run_local + timedelta(days=1)
    return next_run

Это классическая ловушка pytz, которая всплывает почти исключительно на границе перехода часов. pytz.timezone(...).localize() или ранее вычисленный aware datetime «запоминает» смещение (UTC+0 или UTC+1) на момент локализации. Когда вы прибавляете timedelta(days=1) напрямую к такому объекту, Python механически сдвигает дату на 24 часа, но не пересчитывает смещение — оно остаётся тем же, что было у исходного значения. Правильный способ — обязательно прогонять результат через TZ.normalize(next_run), чтобы смещение пересчиталось под новую дату. В этом коде normalize() не было.

В обычную ночь эта недоработка никак себя не проявляет: смещение Europe/London не меняется день ото дня, ошибка компенсируется сама собой. Но в ночь перехода на летнее время смещение меняется с UTC+0 на UTC+1 ровно между вчера и сегодня. next_run, посчитанный «в лоб» без normalize(), оказывается на час раньше, чем должен быть по факту нового смещения — то есть меньше, чем «правильное» 02:30 нового дня.

Сама по себе эта ошибка привела бы просто к тому, что job стартовал бы на час раньше обычного — неприятно, но не дублировало бы запуск. Дублирование родилось из сочетания с второй частью системы: тем самым фоновым перечитыванием конфига раз в 15 минут. Когда демон в 03:00 в очередной раз обновлял расписание из БД, он заново вычислял next_run_at для всех задач — но теперь уже из свежего datetime.now(TZ), который pytz на этот раз локализовал корректно, с уже актуальным смещением UTC+1. Получилось два независимых расчёта одного и того же «следующего запуска»: старый, посчитанный без normalize() и потому смещённый на час назад, и новый, пересчитанный при рефреше конфига и потому корректный. Оба значения оказались в прошлом относительно момента проверки — и обработчик, который сравнивает now >= next_run_at и запускает job, если условие истинно, честно выполнил его дважды: один раз по старому расчёту, второй — после того как рефреш конфига подставил новое, тоже уже наступившее время.

Больше нигде в системе такой конфликт не мог возникнуть: без периодического рефреша расписания второй расчёт просто не появился бы, а без бага в pytz без normalize() первый расчёт был бы верным и совпал бы со вторым. Понадобилось именно совпадение двух вещей — и оно совпадало на переходе через DST, потому что только там смещение вообще меняется.

Как реконструировали цепочку событий

Чтобы не полагаться на догадку, воспроизвели баг локально, без ожидания следующего перехода времени:

# подменяем системное время контейнера на момент перед переходом
sudo date -s "2026-03-29 01:50:00"
timedatectl set-timezone Europe/London
python3 -c "
import pytz
from datetime import timedelta
tz = pytz.timezone('Europe/London')
prev = tz.localize(__import__('datetime').datetime(2026, 3, 28, 2, 30, 0))
naive_next = prev + timedelta(days=1)
print('без normalize:', naive_next)
print('с normalize:  ', tz.normalize(naive_next))
"

Разница между двумя строками вывода — как раз тот самый час, который и стал причиной инцидента. Дальше подняли тестовый инстанс демона с ускоренными часами (через faketime), прогнали переход и увидели тот же паттерн: scheduler_job_triggered_total вырастал на 2 вместо 1 именно в момент перехода, и только в него.

Заодно подняли git blame на функцию compute_next_run — правки последний раз вносили за полтора года до инцидента, когда добавляли поддержку часовых поясов вместо жёстко зашитого UTC. Тогда переход на летнее время тоже случался, но фонового рефреша конфига ещё не существовало — его добавили позже отдельным PR, и разработчик, который его писал, не пересекался с кодом планировщика и не знал о недостающем normalize(). Классическая ситуация, когда баг не «сломался», а был заложен заранее и просто ждал, пока появится вторая деталь, которая его проявит.

Что изменили после инцидента

• Убрали pytz из планировщика полностью, перешли на zoneinfo из стандартной библиотеки (доступен начиная с Python 3.9). У zoneinfo при арифметике с timedelta смещение пересчитывается автоматически при следующем сравнении или форматировании — тот самый класс ошибок с забытым normalize() для него в принципе не существует.
• Добавили идемпотентность на уровне записи отчёта. Теперь перед вставкой в nightly_reports идёт INSERT ... ON CONFLICT (report_date) DO NOTHING с уникальным индексом по дате — даже если планировщик когда-нибудь снова решит запустить job дважды, вторая попытка не создаст дубль и не отправит повторное письмо.
• Развели пересчёт расписания и его применение. Фоновый рефреш конфига теперь только обновляет сами правила (время, таймзону, включена ли задача), но не трогает уже вычисленный next_run_at, если он ещё не наступил и не изменился в конфиге. Пересчёт next_run_at происходит один раз — сразу после фактического запуска задачи, а не при каждом опросе конфига.
• Добавили алерт на повторный запуск. Метрика scheduler_job_triggered_total теперь снята через Prometheus recording rule с окном в час: если значение выросло больше чем на 1 за 60 минут для одной и той же задачи — это сигнал в дежурный канал, даже если оба запуска завершились без единой ошибки.
• Занесли переходы DST в календарь проверок. Дважды в год, за несколько дней до перевода часов, теперь есть чек-лист: прогнать сценарий из предыдущего раздела на стейджинге с подменённым временем для всех задач, у которых есть таймзона в расписании, — не только для ночного отчёта.

Если у вас есть похожие задачи (со временем, привязанным к конкретному часовому поясу, а не к UTC) — стоит свериться со списком мест, где вообще есть человекочитаемое расписание: от systemd-таймеров до cron-файлов и самописных демонов, — этот баг не привязан конкретно к pytz, любая самописная арифметика над aware-datetime без честного пересчёта смещения ведёт себя одинаково непредсказуемо на границе DST. Похожий сюжет, но с обратным эффектом — не дублирование, а полное пропадание задачи — разбирали в статье о том, как забыли про часовой пояс и отчёты сместились; если только настраиваете таймзоны на сервере с нуля, полезно заранее свериться с настройкой часовых поясов на сервере, чтобы не переносить проблему с хоста в код. Похожая по методологии история про тихий сбой без единой ошибки в логах — в разборе о том, как cron не отработал ночью. А сам подход к реконструкции инцидента по логам — метрики плюс journalctl плюс git blame — подробно описан в статье про то, как читать логи и находить причину сбоя.

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