lekss361/gendesign

Fork 0

tradein/devops: логи умирают вместе с контейнером при каждом деплое — ночной прогон невозможно разобрать утром #2741

New issue

Closed

opened 2026-08-06 15:41:31 +00:00 by bot-backend · 2 comments

bot-backend commented

2026-08-06 15:41:31 +00:00

Collaborator

Найдено при разборе нулевого обогащения Авито (#2695): причину невозможно установить, потому что логов уже нет.

Что произошло

Прогоны avito_detail_backfill 11:05 и 12:40 дали 1600 отказов подряд. Разбор упёрся в стену:

поштучные отказы пишутся уровнем warning, а событием мониторинга становится только error — в GlitchTip их нет;
логи контейнера уничтожены его пересозданием в 12:57 (обычный деплой);
тел событий в GlitchTip за нужный период тоже нет — они там только до 01.08.

Итог: сегодняшний прогон нельзя разобрать через три часа после того, как он случился. Причина 1600 отказов осталась неустановленной, и в отчёте пришлось честно написать «невосстановимо».

Почему это системно, а не разово

Логи живут в контейнере и умирают вместе с ним. Сегодня было около двадцати деплоев — то есть окно, в котором логи вообще существуют, редко превышает час-полтора. При этом:

скрейперы работают преимущественно ночью (ближайшие прогоны 01:54 и 07:54 UTC), а разбор идёт днём — к этому моменту логов заведомо нет;
ровно это уже помешало сегодня трижды: причина 503-отказов домовой оценки за 05.08 (#2698), причина падений сайдкара (#2676), и теперь Авито.

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

Что предлагается

Вынести логи из жизненного цикла контейнера — том на хосте либо драйвер, переживающий пересоздание. Ротация по размеру нужна (сегодня json-file max-size 20m × max-file 3), но она должна считать возраст, а не рестарты.
Соразмерность: скрейперы многословны, гигабайты не нужны. Достаточно суток-двух — этого хватает, чтобы утром разобрать ночной прогон.
Отдельно стоит проверить, не теряется ли так же уровень: сегодня выяснилось, что событием мониторинга становится только error, а поштучные отказы скрейперов идут warning. Если решение будет «поднять уровень», надо считать объём — 1600 отказов за прогон превратятся в 1600 событий.

Оговорка

Это не отменяет того, что причину надо было писать в саму запись прогона, а не только в лог, — так и сделано в PR #2739 (fail_hint в статусе). Но запись прогона хранит одну строку итога, а разбор часто требует последовательности. Одно другое не заменяет.

Связано: #2695, #2698, #2676, #2673.

Найдено при разборе нулевого обогащения Авито (#2695): причину **невозможно установить**, потому что логов уже нет. ## Что произошло Прогоны `avito_detail_backfill` 11:05 и 12:40 дали 1600 отказов подряд. Разбор упёрся в стену: - поштучные отказы пишутся уровнем `warning`, а событием мониторинга становится только `error` — в GlitchTip их нет; - **логи контейнера уничтожены его пересозданием в 12:57** (обычный деплой); - тел событий в GlitchTip за нужный период тоже нет — они там только до 01.08. Итог: сегодняшний прогон нельзя разобрать через три часа после того, как он случился. Причина 1600 отказов осталась неустановленной, и в отчёте пришлось честно написать «невосстановимо». ## Почему это системно, а не разово Логи живут в контейнере и умирают вместе с ним. **Сегодня было около двадцати деплоев** — то есть окно, в котором логи вообще существуют, редко превышает час-полтора. При этом: - скрейперы работают преимущественно ночью (ближайшие прогоны 01:54 и 07:54 UTC), а разбор идёт днём — к этому моменту логов заведомо нет; - ровно это уже помешало сегодня трижды: причина 503-отказов домовой оценки за 05.08 (#2698), причина падений сайдкара (#2676), и теперь Авито. То есть **невозможность посмертного разбора — не случайность конкретного дня, а свойство конструкции**: ночная работа плюс дневные деплои гарантируют, что интересное всегда стёрто. ## Что предлагается 1. **Вынести логи из жизненного цикла контейнера** — том на хосте либо драйвер, переживающий пересоздание. Ротация по размеру нужна (сегодня `json-file max-size 20m × max-file 3`), но она должна считать возраст, а не рестарты. 2. Соразмерность: скрейперы многословны, гигабайты не нужны. Достаточно суток-двух — этого хватает, чтобы утром разобрать ночной прогон. 3. Отдельно стоит проверить, не теряется ли так же **уровень**: сегодня выяснилось, что событием мониторинга становится только `error`, а поштучные отказы скрейперов идут `warning`. Если решение будет «поднять уровень», надо считать объём — 1600 отказов за прогон превратятся в 1600 событий. ## Оговорка Это не отменяет того, что причину надо было писать в саму запись прогона, а не только в лог, — так и сделано в PR #2739 (`fail_hint` в статусе). Но запись прогона хранит одну строку итога, а разбор часто требует последовательности. Одно другое не заменяет. Связано: #2695, #2698, #2676, #2673.

bot-backend referenced this issue

2026-08-06 21:19:46 +00:00

fix(tradein/devops): логи в journald — переживают пересоздание контейнера (#2741) #2758

Light1YT referenced this issue from a commit

2026-08-06 21:19:46 +00:00

fix(tradein/devops): логи в journald — переживают пересоздание контейнера (#2741)

bot-backend referenced this issue from a commit

2026-08-06 21:24:58 +00:00

fix(tradein/devops): логи в journald — переживают пересоздание контейнера (#2741) (#2758)

bot-backend referenced this issue

2026-08-06 21:42:53 +00:00

fix(tradein/devops): починить окно времени в инструкции чтения журнала (#2741) #2760

Light1YT referenced this issue from a commit

2026-08-06 21:42:54 +00:00

fix(tradein/devops): починить окно времени в инструкции чтения журнала (#2741)

bot-backend referenced this issue from a commit

2026-08-06 21:53:04 +00:00

fix(tradein/devops): починить окно времени в инструкции чтения журнала (#2741) (#2760)

bot-backend referenced this issue

2026-08-06 22:10:27 +00:00

ops: 13 ГБ из 113 занятых — логи двух контейнеров без ротации; наши compose вообще без потолка #2761

Light1YT referenced this issue from a commit

2026-08-06 22:23:06 +00:00

fix(devops): потолок логов основного стека — journald, как у trade-in (#2761)

bot-backend referenced this issue

2026-08-06 22:23:55 +00:00

fix(devops): потолок логов основного стека — journald, как у trade-in (#2761) #2762

bot-backend referenced this issue

2026-08-07 02:37:30 +00:00

tradein/cian: обогащение новостроек не дало ни одной записи 8 суток подряд — 200 попыток, все прогоны done, причина в разборе а не в сети #2767

bot-backend commented

2026-08-07 03:36:22 +00:00

Author

Collaborator

Окупилось через шесть часов после мержа — и сразу поправило чужой диагноз

Правка приземлилась в 21:24 UTC. В 03:34 понадобилась.

domclick_city_sweep отработал со статусом failed, blocked: 0, lots_fetched: 0. Разбор занял одну команду:

03:34:35  POST http://tradein-browser:3000/fetch → 500 Internal Server Error
03:34:53  повтор                                 → 500 Internal Server Error
03:34:53  ERROR domclick-sweep run_id=3348: SERP phase failed
          httpx.HTTPStatusError: Server error '500' for url 'http://tradein-browser:3000/fetch'

Вчера этот разбор был бы невозможен. Прогон в 03:34, деплои идут в течение дня, и к моменту, когда кто-то посмотрел бы, контейнер был бы пересоздан вместе с логами. Ровно это трижды помешало вчера — причина 1600 отказов Авито так и осталась неустановленной.

Что диагноз меняет по существу

Провал Домклика этой ночью — отказ нашего собственного сайдкара, а не антибот и не протухшие куки. Двойной 500 от tradein-browser, площадка в этом не участвовала.

Это важно, потому что вокруг Домклика сложилось объяснение «внешняя блокировка плюс куки» (#2657, #2695), и оно попало в сводку для владельца как «нужна учётная запись». Учётная запись нужна — но сегодняшний отказ к ней отношения не имеет, и приписывать его площадке было бы третьим за сутки случаем, когда наш сбой записывается как чужой.

Правильная формулировка: у Домклика как минимум три разные причины нулевого сбора, и они требуют разных действий — антибот (внешнее), протухшие куки (владелец), отказ сайдкара (наше). Сваливать их в одну строку сводки нельзя.

Оговорка

Один прогон не доказывает, что сайдкар — основная причина. Он доказывает, что причина не одна. Для разделения нужен ряд, и теперь он будет: логи живут, статусы честные.

## Окупилось через шесть часов после мержа — и сразу поправило чужой диагноз Правка приземлилась в 21:24 UTC. В 03:34 понадобилась. `domclick_city_sweep` отработал со статусом `failed`, `blocked: 0`, `lots_fetched: 0`. Разбор занял одну команду: ``` 03:34:35 POST http://tradein-browser:3000/fetch → 500 Internal Server Error 03:34:53 повтор → 500 Internal Server Error 03:34:53 ERROR domclick-sweep run_id=3348: SERP phase failed httpx.HTTPStatusError: Server error '500' for url 'http://tradein-browser:3000/fetch' ``` **Вчера этот разбор был бы невозможен.** Прогон в 03:34, деплои идут в течение дня, и к моменту, когда кто-то посмотрел бы, контейнер был бы пересоздан вместе с логами. Ровно это трижды помешало вчера — причина 1600 отказов Авито так и осталась неустановленной. ## Что диагноз меняет по существу Провал Домклика этой ночью — **отказ нашего собственного сайдкара**, а не антибот и не протухшие куки. Двойной 500 от `tradein-browser`, площадка в этом не участвовала. Это важно, потому что вокруг Домклика сложилось объяснение «внешняя блокировка плюс куки» (#2657, #2695), и оно попало в сводку для владельца как «нужна учётная запись». Учётная запись нужна — но сегодняшний отказ к ней отношения не имеет, и приписывать его площадке было бы третьим за сутки случаем, когда наш сбой записывается как чужой. Правильная формулировка: у Домклика **как минимум три разные причины** нулевого сбора, и они требуют разных действий — антибот (внешнее), протухшие куки (владелец), отказ сайдкара (наше). Сваливать их в одну строку сводки нельзя. ## Оговорка Один прогон не доказывает, что сайдкар — основная причина. Он доказывает, что причина **не одна**. Для разделения нужен ряд, и теперь он будет: логи живут, статусы честные.

bot-backend referenced this issue

2026-08-07 05:21:41 +00:00

bot-backend commented

2026-08-07 09:10:11 +00:00

Author

Collaborator

ЗАКРЫТО — логи ночного прогона читаются ПОСЛЕ сегодняшнего пересоздания контейнера

Критерий задачи буквальный: «сегодняшний прогон нельзя разобрать через три часа». Проверил ровно это.

Контейнер tradein-scraper пересоздан сегодня деплоем в 08:51 UTC. docker logs после этого отдаёт 4 строки — то есть по-старому история была бы уничтожена. Журнал:

docker run --rm -v /:/host:ro alpine chroot /host sh -c \
  'TZ=UTC journalctl -t tradein-scraper -o short-iso --since "2026-08-06 20:00" --until "2026-08-07 08:50"'

→ 3527 строк

В них полностью лежит ночной прогон 3337 (newbuilding_enrich, 00:39:58 → 00:47), включая построчные отказы разбора и поимённо адреса ЖК. Это те самые логи, которые вчера исчезали до того, как их успевали прочитать.

Драйверы на проде сейчас:

journald:   tradein-backend · tradein-scraper · tradein-browser · tradein-frontend
            gendesign-backend-1 · worker · postgres · glitchtip-web · glitchtip-worker
json-file:  forgejo (вне репозитория) · gendesign-site-finder-1 (осиротевший)

Объём журнала — 2408 МБ при потолке 4 ГБ с самовытеснением, то есть соразмерность из п.2 задачи соблюдена: глубина порядка двух месяцев, а не гигабайты навсегда.

п.3 (уровень) — закрыт по существу, а не поднятием уровня

Задача предупреждала: «если решение будет поднять уровень, 1600 отказов превратятся в 1600 событий». Сделано иначе и правильнее — поштучные отказы остались warning, а событием мониторинга стал итог прогона: общий финализатор пишет logger.error один раз на прогон, с fail_hint и счётчиками. Один разбор вместо тысячи.

Окупаемость, замеченная в этом же треде

Комментарий выше фиксирует разбор в 03:34 (двойной 500 от tradein-browser), который вчера был бы невозможен. Добавлю к этому сегодняшнюю пользу: именно журнал позволил мне увидеть, что прогон 3337 шёл ещё на старом коде — без него вердикт по #2767 пришлось бы строить на догадке.

PR: #2758, #2760.

## ЗАКРЫТО — логи ночного прогона читаются ПОСЛЕ сегодняшнего пересоздания контейнера Критерий задачи буквальный: «сегодняшний прогон нельзя разобрать через три часа». Проверил ровно это. Контейнер `tradein-scraper` пересоздан сегодня деплоем в **08:51 UTC**. `docker logs` после этого отдаёт 4 строки — то есть по-старому история была бы уничтожена. Журнал: ``` docker run --rm -v /:/host:ro alpine chroot /host sh -c \ 'TZ=UTC journalctl -t tradein-scraper -o short-iso --since "2026-08-06 20:00" --until "2026-08-07 08:50"' → 3527 строк ``` В них полностью лежит ночной прогон 3337 (`newbuilding_enrich`, 00:39:58 → 00:47), включая построчные отказы разбора и поимённо адреса ЖК. Это те самые логи, которые вчера исчезали до того, как их успевали прочитать. Драйверы на проде сейчас: ``` journald: tradein-backend · tradein-scraper · tradein-browser · tradein-frontend gendesign-backend-1 · worker · postgres · glitchtip-web · glitchtip-worker json-file: forgejo (вне репозитория) · gendesign-site-finder-1 (осиротевший) ``` Объём журнала — 2408 МБ при потолке 4 ГБ с самовытеснением, то есть соразмерность из п.2 задачи соблюдена: глубина порядка двух месяцев, а не гигабайты навсегда. ### п.3 (уровень) — закрыт по существу, а не поднятием уровня Задача предупреждала: «если решение будет поднять уровень, 1600 отказов превратятся в 1600 событий». Сделано иначе и правильнее — поштучные отказы остались `warning`, а событием мониторинга стал **итог прогона**: общий финализатор пишет `logger.error` один раз на прогон, с `fail_hint` и счётчиками. Один разбор вместо тысячи. ### Окупаемость, замеченная в этом же треде Комментарий выше фиксирует разбор в 03:34 (двойной 500 от `tradein-browser`), который вчера был бы невозможен. Добавлю к этому сегодняшнюю пользу: именно журнал позволил мне увидеть, что прогон 3337 шёл ещё на старом коде — без него вердикт по #2767 пришлось бы строить на догадке. PR: #2758, #2760.

bot-backend referenced this issue

2026-08-07 09:10:19 +00:00

bot-backend closed this issue

2026-08-07 09:10:28 +00:00

bot-backend referenced this issue

2026-08-24 16:14:39 +00:00

Телеметрия: метрики и Grafana — сегодня тихий отказ не виден ничем #3078