Баг всплыл не из мониторинга, а из жалобы: клиент написал, что AI-карточка сгенерировалась и легла в пикер, а счётчик кадров в пакете при этом не уменьшился — как будто генерация не потрачена. Разбор лога занял вечер 5 сентября, потому что первая гипотеза (двойной клик на кнопке) не подтвердилась: id генерации был один.

Считаем худший случай, а не средний

В сервисе AI-карточек для объявлений на Авито генерация фото идёт через провайдера _KieTaskProvider, и у неё несколько уровней ретраев одновременно — не потому что так задумано красиво, а потому что каждый уровень добавляли отдельно под свой инцидент за последние месяцы.

Взял константы из providers.py и service.py и посчитал по коду, а не по ощущению:

провайдер (_KieTaskProvider.generate):
  poll:     2 попытки × _POLL_TIMEOUT_S=150с = 300 с
  download: 2 попытки × httpx timeout=60с     = 120 с
  → одна успешная генерация ≈ 420 с (обе части — внутри ОДНОГО provider.generate())

сервис (_generate_card_core / generate_photo):
  QA-повтор:   2 попытки (брак → тихая перегенерация) × 420 с = 840 с
  QA-проверка: 2 запроса (_qa_check, timeout=45.0) × 45 с     =  90 с
  запись файла + _log_spend (диск/БД, без сетевых таймаутов) ≈  30 с
ИТОГО ≈ 960 с ≈ 16 минут

А SWEEP_AFTER_MIN у воркера и QUOTA_RESERVE_TTL_MIN у api стояли в 15 минут. Оба значения кто-то когда-то выставил на глаз, и с тех пор к провайдеру добавили QA-перегенерацию брака — она добавляет второй проход в 420 секунд, но окно резерва никто не пересчитал.

15 меньше 16.

Разница в минуту. Этого хватило, чтобы раз в какое-то количество генераций уборщик и ещё живая генерация столкнулись лбами.

Что происходило на стыке

Уборщик (worker, периодическая задача) находит строки резерва старше SWEEP_AFTER_MIN и считает их брошенными: клиент не дождался, значит кадр надо вернуть в пакет. Логика в целом правильная — без неё зависшие резервы копились бы и клиент бы терял кадры навсегда.

Проблема в том, что «брошенный» и «долго идущий» неотличимы по одному только времени, если время резерва короче реального худшего случая. Уборщик брал строку резерва ещё идущей генерации (не брошенной — просто попавшей во второй круг QA-перегенерации), удалял её и возвращал кадр в счётчик пакета.

Дальше провайдер всё-таки успешно докручивал генерацию, сервис звал release_claim, чтобы закрыть резерв — и находил row is None. Строку уже съел уборщик несколькими секундами раньше. release_claim на это в текущем виде молча завершался: считал, что резерв кто-то уже закрыл, и не делал ничего.

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

Вот как это выглядело в логе api в момент, когда release_claim натыкался на уже съеденную уборщиком строку:

release_claim: reserve_id=8f21a4e... row is None (already consumed)
generate_photo: provider result delivered, spend logged, claim=NOOP
worker.sweep: reclaimed reserve 8f21a4e..., pack quota +1 (age=902s)

age=902s — 15 минут и 2 секунды. Резерву не хватило двух секунд до того, чтобы его признали брошенным, хотя генерация была ещё жива и всё равно докрутилась через 58 секунд после этой строки.

Починка: не «увеличить число», а привязать проверку к тем же константам

Первым порывом было просто поднять оба тайм-аута до 20 минут и закрыть тикет. Но 20 минут — это тоже число, взятое на глаз, только более консервативное: следующая правка QA-логики (например, третья попытка перегенерации вместо двух) тихо сломает и его, и никто не узнает до следующей жалобы через несколько месяцев.

Сделал два раздельных шага:

1. Подняли оба окна SWEEP_AFTER_MIN и QUOTA_RESERVE_TTL_MIN до 30 минут — почти двукратный запас к расчётным 960 секундам. Существующий тест test_окно_уборки_не_короче_окна_резерва (SWEEP_AFTER_MIN >= QUOTA_RESERVE_TTL_MIN) остался зелёным без изменений.

2. Добавили новый тест-якорь test_окно_уборщика_переживает_худшую_генерацию, который не хранит число 16 минут внутри себя, а вычисляет худший случай регексом из тех же констант providers.py и service.py — ровно та формула, что выше. Если кто-то в будущем добавит третий проход QA или увеличит _POLL_TIMEOUT_S, тест пересчитает свой порог сам и упадёт, если окно уборщика не подрастили следом.

Проверка теста на мутации: откатил SWEEP_AFTER_MIN обратно на 15 — тест покраснел, как и должен. Без этого шага я бы не был уверен, что тест вообще что-то проверяет, а не просто существует.

Что не сработало с первого раза

Пока разбирался с окном уборщика, ревью зацепилось за соседний кусок того же RETURNING в SQL уборщика — и там нашёлся второй, независимый баг, который жил в коде дольше первого.

Резервы бывают разных kind, и один из них — dislike: клиент нажимает «не нравится» на сгенерированной карточке, ему дают один бесплатный повтор, и на время повтора выставляется флаг ads.params.ai_dislike_retry_used = true, чтобы повтором нельзя было воспользоваться дважды. Снимать этот флаг после завершения должен был release_claim в своём finally.

Уборщик, забирая строку резерва через RETURNING, брал только pack_id и tenant_id — про kind и, соответственно, про флаг дизлайка он не знал вообще. Если процесс api падал между захватом повторной генерации и вызовом release_claim (а не только по тайм-ауту, а именно падал — рестарт пода, OOM, что угодно), уборщик потом честно возвращал кадр в пакет, но флаг ai_dislike_retry_used оставался true навсегда. Клиент терял единственный бесплатный повтор без единой отданной ему генерации, и никакого сообщения об этом в интерфейсе не было — просто кнопка повтора переставала работать.

Это не тот баг, который искал изначально, и его бы не нашли, если бы не читали RETURNING построчно ради первого фикса. Записываю сюда именно потому, что «нашёл один баг — проверь соседей в том же куске SQL» не звучит как процесс, который можно формализовать в чек-лист, но именно так это и произошло.

Было:

DELETE FROM ai_card_reserves
 WHERE reserved_at < now() - interval '15 minutes'
RETURNING pack_id, tenant_id;

Стало:

DELETE FROM ai_card_reserves
 WHERE reserved_at < now() - interval '30 minutes'
RETURNING pack_id, tenant_id, kind, COALESCE(subject, '');
-- в той же транзакции, только для kind = 'dislike':
UPDATE ads SET params = params || '{"ai_dislike_retry_used": false}'::jsonb
 WHERE id = :subject;

Best-effort, зеркально тому, что делает release_claim в своём finally. Отдельный тест-якорь test_дизлайк_повтор_возвращается_после_смерти_api, тоже проверенный мутацией: убрал ветку kind == "dislike" — тест покраснел.

Числа до и после

ruff check --select=E9,F63,F7,F82 прошёл чисто, это была последняя проверка перед мёржем.

Отменить у провайдера (kie.ai) уже запущенную генерацию нельзя — публичного endpoint под это в их API нет. Так что «просто отменять при первом же сомнении» не было вариантом с самого начала: единственный рабочий рычаг — не отбирать резерв, пока генерация физически не могла завершиться раньше расчётного максимума.