Задача запускалась дважды: два сервера считали себя главными

MAATRIX

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

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

Схема на бумаге выглядела надёжно. Два прикладных сервера — назовём их app-1 и app-2 — работают в режиме active/standby: оба поднимают одинаковый код, оба содержат планировщик (APScheduler) с задачей на 03:00, но выполнять её должен только один из них. Роль «главного» определялась не отдельным сервисом вроде etcd или Consul — их сочли избыточными для одной задачи в сутки — а сессионной advisory-блокировкой самой Postgres.

Идея простая и хорошо документированная: pg_try_advisory_lock(id) берёт блокировку, привязанную к конкретному серверному соединению (backend connection) в Postgres. Пока соединение живо, блокировка держится; при разрыве соединения Postgres снимает её сама. Код планировщика на каждом узле выглядел примерно так:

# держим одно выделенное соединение на процесс жизни планировщика
lock_conn = psycopg2.connect(DSN)
lock_conn.autocommit = True

def try_become_leader():
    with lock_conn.cursor() as cur:
        cur.execute("SELECT pg_try_advisory_lock(%s)", (NIGHTLY_JOB_LOCK_ID,))
        return cur.fetchone()[0]

@scheduler.scheduled_job("cron", hour=3, minute=0)
def nightly_job():
    if not try_become_leader():
        log.info("not a leader, skipping")
        return
    run_report_and_notify()

Соединение lock_conn создавалось один раз при старте процесса и жило постоянно — казалось бы, гарантия того, что блокировка либо держится на этом же соединении, либо снимается сама при его потере. За полтора года такая схема ни разу не подводила: если app-1 был жив, он забирал блокировку первым и выполнял задачу; app-2 получал false и тихо уходил в лог.

Три недели назад в инфраструктуру добавили pgbouncer перед Postgres — не ради этой задачи, а потому что число коротких соединений от веб-воркеров выросло и Postgres начал упираться в max_connections. Pgbouncer подняли в режиме transaction, самом экономном по соединениям к серверу: приложение думает, что держит своё соединение, а pgbouncer на самом деле выдаёт свободный backend-коннект на каждую транзакцию и забирает его обратно, как только транзакция завершилась. DSN у планировщика молча переключили на порт pgbouncer вместе с остальным приложением — никто не выделил для лидер-элекшна отдельный прямой путь к базе.

Что мы увидели в логах и метриках

Утром пришли две одинаковые нотификации в служебный Telegram-канал вместо одной — обе с разницей в несколько секунд. В таблице отчёта, куда пишет ночная задача, за эту ночь оказалось два набора строк с одинаковым содержимым и разным created_at. В логах приложения — на обоих узлах строка try_become_leader() -> True в одном и том же временном окне, хотя раньше второй узел всегда честно писал false.

Метрики Postgres показали кратковременный всплеск нагрузки на CPU базы — вдвое выше обычного ночного профиля — что логично: тяжёлые агрегирующие запросы отчёта выполнялись параллельно двумя процессами вместо одного. В логах pgbouncer (pgbouncer.log с log_connections=1) ничего похожего на ошибку не было — только рядовая ротация backend-соединений, десятки записей client connects/disconnects в минуту, что для transaction pooling нормально.

Ключевая деталь, которая потом всё объяснила: между try_become_leader() на app-1 и следующим обращением этого же процесса к базе (запись первой строки отчёта) в логе pgbouncer видно, что backend-соединение под этим клиентом сменилось. Именно этого в модели «одно постоянное соединение — одна сессия» быть не должно.

Первая гипотеза: гонка в самом cron/APScheduler

Первое, что заподозрили — дублирование job'а внутри самого APScheduler: известный класс багов, когда джоб-стор без персистентного backend'а или при неудачном рестарте процесса регистрирует одну и ту же задачу дважды. Проверили конфигурацию джоб-стора — использовался MemoryJobStore, задача регистрировалась один раз при старте, id задачи был явно задан и уникален, replace_existing=True стоял. Посмотрели supervisorctl status и systemctl status на обоих узлах — процесс планировщика не перезапускался в эту ночь ни разу. Версию отбросили: с обеих сторон job стартовал строго по одному разу за процесс, дублирования на уровне самого шедулера не было.

Вторая гипотеза: рассинхронизация часов между узлами

Следующая мысль — что часы на app-1 и app-2 разошлись и оба независимо, без всякой блокировки, попали в своё окно cron-триггера. Проверили chronyc tracking на обоих серверах: расхождение с NTP в пределах пары миллисекунд, синхронизация штатная. Кроме того, в логах оба вызова try_become_leader() возвращали True — то есть блокировка формально бралась, а не игнорировалась. Если бы дело было в рассинхронизации триггера, второй узел должен был получить False и выйти. Версию отбросили: расхождение по времени было и есть, но не то, которое могло бы это объяснить, а главное — сама блокировка выдала «зелёный свет» обоим.

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

Тут вспомнили про недавнее изменение — переезд DSN приложения на pgbouncer. Разница между session и transaction pooling у pgbouncer в документации описана прямо: «Session state, включая prepared statements, advisory locks, LISTEN/NOTIFY и temp tables, не переживает границу транзакции в transaction pooling, потому что клиент не привязан к одному и тому же backend-соединению между транзакциями». Advisory lock в этом списке — не редкий частный случай, а один из хрестоматийных примеров несовместимости.

Механика оказалась такой. lock_conn в приложении — это TCP-соединение к pgbouncer, а не к Postgres напрямую. Пока внутри одной транзакции — блокировка держится на реальном backend-соединении Postgres, которое pgbouncer выдал под эту транзакцию. Но как только транзакция завершилась (а autocommit=True в психопг2 фактически означает «каждый оператор — своя короткая транзакция»), pgbouncer возвращает этот backend в общий пул и может выдать его следующему клиенту — а клиенту, который держал лок, при следующем запросе выдаёт уже другой, свободный backend. Advisory lock, взятый на прежнем backend-соединении, никуда не делась с точки зрения Postgres — она физически осталась висеть на том backend'е, который теперь обслуживает кого-то другого. А клиентское приложение при следующем вызове pg_try_advisory_lock на новом backend-соединении получает True, потому что с точки зрения этого нового соединения блокировка свободна.

Отсюда и картина: app-1 в 03:00:00 получил backend A, взял лок, backend A остался в пуле «занятым» с точки зрения Postgres. Через долю секунды app-1 отправил следующий запрос (уже запись в отчёт), pgbouncer выдал под него backend B — свободный. Параллельно app-2 в то же окно тоже дернул pg_try_advisory_lock, и pgbouncer выдал ему тоже какой-то свободный backend, не A — соответственно лок для app-2 тоже оказался «свободен», и он тоже получил True. Оба узла честно думали, что они лидер, потому что каждый смотрел на блокировку через своё, каждый раз новое, backend-соединение.

Отдельно проверили похожий по природе, уже разобранный ранее на проекте случай — как pgbouncer в режиме transaction ломает prepared statements: там та же причина, session state не переживает границу транзакции, просто симптом другой (ошибка prepared statement does not exist вместо тихого дублирования). Это подтвердило диагноз: это не разовая случайность, а системное следствие режима пулинга, которое проявляется везде, где приложение полагается на состояние конкретного backend-соединения.

Как починили и что изменили в архитектуре

Быстрый фикс — увести лидер-элекшн с пути через pgbouncer вообще. Для него создали отдельный DSN, указывающий напрямую на Postgres, в обход pooler'а:

# /etc/pgbouncer/pgbouncer.ini — как было для приложения
[databases]
app_db = host=127.0.0.1 port=5432 dbname=app pool_mode=transaction

# DSN для лидер-элекшна — напрямую в Postgres, без pgbouncer
LOCK_DSN = "host=db-primary.internal port=5432 dbname=app application_name=leader_lock"
lock_conn = psycopg2.connect(LOCK_DSN)
lock_conn.autocommit = True

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

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

ALTER TABLE nightly_report
  ADD CONSTRAINT nightly_report_run_date_uniq UNIQUE (report_date);

Теперь даже если лидер-элекшн снова даст сбой, вторая попытка записи упадёт на constraint, а не создаст дубль — код обернули в try/except IntegrityError с логированием вместо падения процесса. Это тот случай, когда «почини причину» недостаточно — нужна ещё идемпотентность на стороне самой операции, потому что распределённые блокировки в принципе не дают железной гарантии «ровно один раз» (это справедливо не только для advisory lock в Postgres, но и для Redis-локов, ZooKeeper-эфемерных нод и любого лизинга с TTL — везде есть окно, где инвариант может нарушиться).

Третье — мониторинг случая «задача стартовала больше одного раза». Раньше отслеживали только «задача не стартовала вообще» через healthchecks.io: пинг в начале и в конце прогона, алерт по таймауту. Добавили вторую проверку — счётчик стартов job'а с одинаковым report_date за сутки: если он больше одного, в мониторинг уходит warning ещё до того, как кто-то заметит дубль в почте вручную.

Заодно провели ревизию: где ещё в проекте prepared statements, advisory locks, SET на уровне сессии или temp tables идут через DSN на pgbouncer с pool_mode=transaction. Нашли ещё одно место — фоновый воркер, использующий SET search_path при старте сессии, и тоже вывели его на прямое соединение, не дожидаясь, пока это тоже станет отдельным инцидентом.

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