lekss361/gendesign

Fork 0

CI: backend-tests краснеет ПОСЛЕ зелёного pytest, и по логу нельзя понять, в каком шаге #2871

New issue

Closed

opened 2026-08-13 16:34:58 +00:00 by bot-backend · 4 comments

bot-backend commented

2026-08-13 16:34:58 +00:00

Collaborator

Симптом

На ветке PR #2865 job backend-tests покраснел три раза подряд (два раннера, свежая
база, здоровый хост), и каждый раз лог выглядит так:

Required test coverage of 65% reached. Total coverage: 74.57%
4647 passed, 28 skipped, 7 warnings in 899.63s (0:14:59)
   ← девять секунд без единой строки
Skipping step 'Cache uv packages' due to 'success()'
🏁  Job failed

Тесты прошли, гейт покрытия пройден, а job красный. Skipping ... due to 'success()'
означает, что к моменту post-фазы статус job'а уже не success.

Почему нельзя понять, где именно

После pytest идут ровно два шага, оба if: always():

Coverage summary → job output
Снести тестовый Postgres

act_runner не печатает баннеры для обычных run:-шагов (только для uses:-действий),
а оба этих шага в штатном режиме молчат: первый пишет в $GITHUB_STEP_SUMMARY, второй
глушит вывод в /dev/null. В зелёном прогоне картина ровно такая же — я сравнивал
логи успешного и упавшего прогонов построчно, единственная разница в том, что
в упавшем post-шаги пропущены.

Итог: отличить «упал шаг покрытия» от «упала уборка контейнера» по логу нечем.

Что уже исключено (замерами, не рассуждением)

Гипотеза	Чем опровергнута
Диск (инцидент #2869)	третий прогон при 28 ГБ свободных — то же падение
Конкретный раннер	падало на `vps-runner-2` и на `vps-runner-1`; `vps-runner-2` в тот же час давал зелёный прогон
Пропал/сломался тест	`pytest --collect-only` на обеих ветках: расхождение ровно 3 теста и всё объясняется базой; локально полный сьют на этой ветке — 4622 passed
Гейт покрытия	74.57% ≥ 65 во ВСЕХ прогонах, и в упавших, и в зелёных — цифра совпадает до сотых
Устаревшая база ветки	обновил ветку от base — упало снова

Отдельно найденный механизм (может быть тем самым, может нет)

coverage report уважает fail_under из pyproject.toml и выходит с кодом 2, когда
порог не набран. Шаг устроен как report="$(uv run coverage report ... | tail -40)",
а run: в Actions исполняется под bash -eo pipefail → ненулевой код coverage
роняет шаг. Воспроизвёл локально:

pytest exit=0
coverage-summary step exit=2

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

В CI покрытие 74.57% > 65, так что этот путь не должен срабатывать. Однако шаг-отчёт
в принципе не должен уметь ронять сборку: его задача — печатать, а не гейтить.

Что сделано

PR #2872: обе безмолвные ступени получают явные маркеры начала/конца, шаг покрытия
печатает код возврата coverage report и больше не может уронить job'у из-за отчёта.
Гейт остаётся там, где ему место, — в pytest --cov-fail-under=65.

После мержа перезапустить #2865 и прочитать маркеры: они назовут виновника точно.

## Симптом На ветке PR #2865 job `backend-tests` покраснел **три раза подряд** (два раннера, свежая база, здоровый хост), и каждый раз лог выглядит так: ``` Required test coverage of 65% reached. Total coverage: 74.57% 4647 passed, 28 skipped, 7 warnings in 899.63s (0:14:59) ← девять секунд без единой строки Skipping step 'Cache uv packages' due to 'success()' 🏁 Job failed ``` Тесты прошли, гейт покрытия пройден, а job красный. `Skipping ... due to 'success()'` означает, что к моменту post-фазы статус job'а уже не success. ## Почему нельзя понять, где именно После pytest идут ровно два шага, оба `if: always()`: 1. `Coverage summary → job output` 2. `Снести тестовый Postgres` `act_runner` **не печатает баннеры** для обычных `run:`-шагов (только для `uses:`-действий), а оба этих шага в штатном режиме молчат: первый пишет в `$GITHUB_STEP_SUMMARY`, второй глушит вывод в `/dev/null`. В зелёном прогоне картина ровно такая же — я сравнивал логи успешного и упавшего прогонов построчно, единственная разница в том, что в упавшем post-шаги пропущены. Итог: **отличить «упал шаг покрытия» от «упала уборка контейнера» по логу нечем.** ## Что уже исключено (замерами, не рассуждением) | Гипотеза | Чем опровергнута | |---|---| | Диск (инцидент #2869) | третий прогон при 28 ГБ свободных — то же падение | | Конкретный раннер | падало на `vps-runner-2` и на `vps-runner-1`; `vps-runner-2` в тот же час давал зелёный прогон | | Пропал/сломался тест | `pytest --collect-only` на обеих ветках: расхождение ровно 3 теста и всё объясняется базой; локально полный сьют на этой ветке — 4622 passed | | Гейт покрытия | 74.57% ≥ 65 во ВСЕХ прогонах, и в упавших, и в зелёных — цифра совпадает до сотых | | Устаревшая база ветки | обновил ветку от base — упало снова | ## Отдельно найденный механизм (может быть тем самым, может нет) `coverage report` **уважает `fail_under` из `pyproject.toml`** и выходит с кодом 2, когда порог не набран. Шаг устроен как `report="$(uv run coverage report ... | tail -40)"`, а `run:` в Actions исполняется под `bash -eo pipefail` → ненулевой код `coverage` роняет шаг. Воспроизвёл локально: ``` pytest exit=0 coverage-summary step exit=2 ``` (локально порог не набран, потому что гонял подмножество тестов — но механизм именно такой). В CI покрытие 74.57% > 65, так что этот путь **не должен** срабатывать. Однако шаг-отчёт в принципе не должен уметь ронять сборку: его задача — печатать, а не гейтить. ## Что сделано PR #2872: обе безмолвные ступени получают явные маркеры начала/конца, шаг покрытия печатает код возврата `coverage report` и больше не может уронить job'у из-за отчёта. Гейт остаётся там, где ему место, — в `pytest --cov-fail-under=65`. После мержа перезапустить #2865 и прочитать маркеры: они назовут виновника точно.

Light1YT referenced this issue from a commit

2026-08-13 16:35:16 +00:00

ci: сделать видимыми два безмолвных шага после pytest

bot-backend referenced this issue

2026-08-13 16:35:42 +00:00

ci: сделать видимыми два безмолвных шага после pytest (#2871) #2872

bot-backend referenced this issue from a commit

2026-08-13 16:53:48 +00:00

ci: сделать видимыми два безмолвных шага после pytest (#2871) (#2872)

Light1YT referenced this issue from a commit

2026-08-13 17:12:54 +00:00

ci: печатать код возврата pytest явно

bot-backend referenced this issue

2026-08-13 17:13:14 +00:00

ci: печатать код возврата pytest явно (#2871) #2875

bot-backend commented

2026-08-13 17:13:33 +00:00

Author

Collaborator

Маркеры сработали — и оправдали обоих подозреваемых

Прогон 7530 (ветка #2865, уже с ci.yml из #2872):

17:10:06  4647 passed, 28 skipped, 7 warnings in 892.48s
17:10:09  ### шаг «Coverage summary» начался
17:10:15  ### coverage report вернул код 0
17:10:15  ### шаг «Coverage summary» закончился успешно
17:10:15  ### шаг «Снести тестовый Postgres» начался (CI_PG=ci-pg-backend-7532)
17:10:15  ### шаг «Снести тестовый Postgres» закончился успешно
17:10:16  Skipping step 'Cache uv packages' due to 'success()'
17:10:21  🏁  Job failed

coverage report вернул 0 — то есть гипотеза про fail_under + pipefail, которую
я нашёл и обезвредил в #2872, к этому падению отношения не имеет. Оба шага после pytest
отработали. Во всём логе нет ни одного ::error и ни одного ❌.

Между «последний шаг закончился успешно» и «job уже не success» — 250 миллисекунд.

Кого не проверил

Сам шаг с pytest. Его сводка печатается до выхода процесса, поэтому зелёное
«4647 passed» ничего не говорит о коде возврата: внутренняя ошибка на teardown, сбой
плагина, ошибка записи coverage.xml — всё это даст ненулевой код уже после сводки,
и выглядеть будет ровно так.

Классическая ловушка «зелёный отчёт ≠ зелёный процесс», и я в неё сам зашёл: три раза
подряд читал сводку pytest как доказательство успеха шага.

PR #2875 печатает код возврата явно (гейт сохранён через exit $rc).

Заодно про cache

Проверил и его, раз он единственный шаг с continue-on-error: true: в упавшем и в зелёном
прогонах восстановление кэша идентично (Cache restored successfully, тот же ключ,
~311 МБ). Не он.

Что дальше

Если следующий прогон скажет ### pytest вернул код 0 — значит виновата не работа шагов,
а учёт самого act_runner, и разбираться надо с раннером. Но это будет установлено,
а не предположено. Параллельно гоняю ту же команду локально на той же ветке с явным
echo $? — сравню коды.

## Маркеры сработали — и оправдали обоих подозреваемых Прогон 7530 (ветка #2865, уже с ci.yml из #2872): ``` 17:10:06 4647 passed, 28 skipped, 7 warnings in 892.48s 17:10:09 ### шаг «Coverage summary» начался 17:10:15 ### coverage report вернул код 0 17:10:15 ### шаг «Coverage summary» закончился успешно 17:10:15 ### шаг «Снести тестовый Postgres» начался (CI_PG=ci-pg-backend-7532) 17:10:15 ### шаг «Снести тестовый Postgres» закончился успешно 17:10:16 Skipping step 'Cache uv packages' due to 'success()' 17:10:21 🏁 Job failed ``` `coverage report` вернул **0** — то есть гипотеза про `fail_under` + `pipefail`, которую я нашёл и обезвредил в #2872, к этому падению отношения не имеет. Оба шага после pytest отработали. Во всём логе нет ни одного `::error` и ни одного `❌`. Между «последний шаг закончился успешно» и «job уже не success» — **250 миллисекунд**. ## Кого не проверил Сам шаг с pytest. Его сводка печатается **до** выхода процесса, поэтому зелёное «4647 passed» ничего не говорит о коде возврата: внутренняя ошибка на teardown, сбой плагина, ошибка записи `coverage.xml` — всё это даст ненулевой код уже после сводки, и выглядеть будет ровно так. Классическая ловушка «зелёный отчёт ≠ зелёный процесс», и я в неё сам зашёл: три раза подряд читал сводку pytest как доказательство успеха шага. PR #2875 печатает код возврата явно (гейт сохранён через `exit $rc`). ## Заодно про cache Проверил и его, раз он единственный шаг с `continue-on-error: true`: в упавшем и в зелёном прогонах восстановление кэша идентично (`Cache restored successfully`, тот же ключ, ~311 МБ). Не он. ## Что дальше Если следующий прогон скажет `### pytest вернул код 0` — значит виновата не работа шагов, а учёт самого `act_runner`, и разбираться надо с раннером. Но это будет **установлено**, а не предположено. Параллельно гоняю ту же команду локально на той же ветке с явным `echo $?` — сравню коды.

Light1YT referenced this issue from a commit

2026-08-13 17:28:21 +00:00

test(ptica): объявить пропуск нового EXPLAIN-теста в skip_allowlist

bot-backend commented

2026-08-13 17:28:48 +00:00

Author

Collaborator

Причина найдена. Это не CI, это я — и сторож сработал правильно

Прогнал ту же команду локально с явным echo $?:

4622 passed, 48 skipped, 45 warnings in 784.18s
Required test coverage of 65% reached. Total coverage: 74.29%
FAILED / ERROR в выводе: 0
PYTEST EXIT CODE = 1

Зелёная сводка, ноль падений, покрытие набрано — и код 1.

Виновник — backend/tests/conftest.py:95, хук pytest_sessionfinish:

unlisted = sorted(_observed_skips - _allowed_skips())
...
if exitstatus == 0:
    session.exitstatus = 1

Мои два новых параметризованных EXPLAIN-теста скипаются без TEST_DATABASE_URL
и не были объявлены в skip_allowlist.txt. Сторож сделал ровно то, ради чего написан
(«пропуск без записи неотличим от пройденной проверки», #2722/#2729/#2740) — уронил прогон.

Сообщение всё это время лежало в логе

строка 1014:  НЕУЧТЁННЫЙ ПРОПУСК (1): проверка не исполнилась и не объявлена в skip_allowlist.txt:
строка 1015:    - tests/integration/test_analyze_parcels_sql.py::TestVelocityCompetitorsSql::test_explain_competitors
строка 1016:  Почини тест либо внеси его в skip_allowlist.txt с причиной

За две секунды до сводки. Я его не увидел, потому что искал по FAILED|ERROR|::error|❌
и смотрел хвост лога, а сообщение по-русски и стоит в середине. Классическая ошибка поиска:
шаблон подобран под чужой словарь.

Что из этого следует для задачи

Исходная жалоба — «job краснеет, и по логу нельзя понять, где» — остаётся верной:
шаг с pytest не печатал свой код возврата, и зелёная сводка читалась как зелёный шаг.
Ровно поэтому я четыре прогона проверял диск, раннер, покрытие, кэш и два безмолвных шага.
PR #2875 (печать кода возврата) я оставляю: он не «на всякий случай», а именно то, чего
не хватило, чтобы увидеть это за одну минуту вместо трёх часов.

Что стоит добавить сверх него — чтобы сторож было видно: сейчас он печатает обычным
print() в середине вывода. Хорошо бы ::error::-префикс (Forgejo/act подсвечивает и
поднимает в аннотации) — тогда он не потеряется среди 1000 строк. Заведу отдельно, если
не будет возражений.

Сам пропуск объявлен: PR #2865, коммит c9c7aab2, запись рядом с двумя такими же
соседями (TestIrdOverlapSql, TestNeighborsSummarySql), с ответом на вопрос из шапки
файла — почему нельзя выполнить здесь и где выполняется вместо этого.

## Причина найдена. Это не CI, это я — и сторож сработал правильно Прогнал ту же команду локально с явным `echo $?`: ``` 4622 passed, 48 skipped, 45 warnings in 784.18s Required test coverage of 65% reached. Total coverage: 74.29% FAILED / ERROR в выводе: 0 PYTEST EXIT CODE = 1 ``` Зелёная сводка, ноль падений, покрытие набрано — и код 1. Виновник — `backend/tests/conftest.py:95`, хук `pytest_sessionfinish`: ```python unlisted = sorted(_observed_skips - _allowed_skips()) ... if exitstatus == 0: session.exitstatus = 1 ``` Мои два новых параметризованных EXPLAIN-теста скипаются без `TEST_DATABASE_URL` и не были объявлены в `skip_allowlist.txt`. Сторож сделал ровно то, ради чего написан («пропуск без записи неотличим от пройденной проверки», #2722/#2729/#2740) — уронил прогон. ## Сообщение всё это время лежало в логе ``` строка 1014: НЕУЧТЁННЫЙ ПРОПУСК (1): проверка не исполнилась и не объявлена в skip_allowlist.txt: строка 1015: - tests/integration/test_analyze_parcels_sql.py::TestVelocityCompetitorsSql::test_explain_competitors строка 1016: Почини тест либо внеси его в skip_allowlist.txt с причиной ``` За **две секунды** до сводки. Я его не увидел, потому что искал по `FAILED|ERROR|::error|❌` и смотрел хвост лога, а сообщение по-русски и стоит в середине. Классическая ошибка поиска: шаблон подобран под чужой словарь. ## Что из этого следует для задачи Исходная жалоба — «job краснеет, и по логу нельзя понять, где» — **остаётся верной**: шаг с pytest не печатал свой код возврата, и зелёная сводка читалась как зелёный шаг. Ровно поэтому я четыре прогона проверял диск, раннер, покрытие, кэш и два безмолвных шага. PR #2875 (печать кода возврата) я оставляю: он не «на всякий случай», а именно то, чего не хватило, чтобы увидеть это за одну минуту вместо трёх часов. Что стоит добавить сверх него — **чтобы сторож было видно**: сейчас он печатает обычным `print()` в середине вывода. Хорошо бы `::error::`-префикс (Forgejo/act подсвечивает и поднимает в аннотации) — тогда он не потеряется среди 1000 строк. Заведу отдельно, если не будет возражений. Сам пропуск объявлен: PR #2865, коммит `c9c7aab2`, запись рядом с двумя такими же соседями (`TestIrdOverlapSql`, `TestNeighborsSummarySql`), с ответом на вопрос из шапки файла — почему нельзя выполнить здесь и где выполняется вместо этого.

bot-backend referenced this issue from a commit

2026-08-13 17:32:11 +00:00

ci: печатать код возврата pytest явно (#2871) (#2875)

bot-backend commented

2026-08-13 17:32:21 +00:00

Author

Collaborator

Диагностика на месте и проверена на живом прогоне (#2875, зелёный, 17m42s):

### pytest вернул код 0
### шаг «Coverage summary» начался
### coverage report вернул код 0
### шаг «Coverage summary» закончился успешно
### шаг «Снести тестовый Postgres» начался (CI_PG=ci-pg-backend-7539)
### шаг «Снести тестовый Postgres» закончился успешно

Теперь каждый шаг после тестов называет свой код возврата. Тот же набор строк на красном
прогоне сразу покажет, где именно оборвалось — вместо девяти секунд тишины, из-за которых
я проверял диск, раннер, покрытие, кэш и два невиновных шага.

Что осталось по этой задаче: сторож пропусков печатает обычным print() и теряется
в тысяче строк — предлагаю префикс ::error::, чтобы Forgejo поднимал его в аннотации.
Это ровно тот случай, когда защита сработала верно, но её не услышали. Сделаю отдельным
PR, если возражений нет.

Диагностика на месте и проверена на живом прогоне (#2875, зелёный, 17m42s): ``` ### pytest вернул код 0 ### шаг «Coverage summary» начался ### coverage report вернул код 0 ### шаг «Coverage summary» закончился успешно ### шаг «Снести тестовый Postgres» начался (CI_PG=ci-pg-backend-7539) ### шаг «Снести тестовый Postgres» закончился успешно ``` Теперь каждый шаг после тестов называет свой код возврата. Тот же набор строк на красном прогоне сразу покажет, где именно оборвалось — вместо девяти секунд тишины, из-за которых я проверял диск, раннер, покрытие, кэш и два невиновных шага. **Что осталось по этой задаче:** сторож пропусков печатает обычным `print()` и теряется в тысяче строк — предлагаю префикс `::error::`, чтобы Forgejo поднимал его в аннотации. Это ровно тот случай, когда защита сработала верно, но её не услышали. Сделаю отдельным PR, если возражений нет.

Light1YT referenced this issue from a commit

2026-08-13 17:36:23 +00:00

test(ci): сторож пропусков кричит ::error:: под Actions

bot-backend referenced this issue

2026-08-13 17:36:51 +00:00

test(ci): сторож пропусков кричит ::error:: под Actions (#2871) #2876

bot-backend referenced this issue from a commit

2026-08-13 21:05:57 +00:00

test(ci): сторож пропусков кричит ::error:: под Actions (#2871) (#2876)

lekss361 added the

bug

scope/devops

labels 2026-08-16 10:25:29 +00:00

lekss361 commented

2026-08-16 10:36:41 +00:00

Owner

Закрываю по итогам разбора трекера 16.08.2026

Вердикт: сделано кодом.

Слепая зона закрыта, и найден сам виновник: coverage report уважает fail_under и выходит с кодом 2 под bash -eo pipefail, гася зелёный pytest — теперь вычисление и вывод разделены, код возврата печатается.

Доказательство: Коммиты a6e751da «ci: сделать видимыми два безмолвных шага после pytest (#2871) (#2872)» и 7de5aa05 «ci: печатать код возврата pytest явно (#2871) (#2875)»; .forgejo/workflows/ci.yml:246 echo "### pytest вернул код $rc", 256-273 маркеры начала/конца шага Coverage summary и явный cov_rc, 281-284 маркеры шага сноса Postgres.

Независимая проверка. Вердикт отдельно проверялся вторым проходом, задачей которого было именно опровергнуть закрытие, а не подтвердить его:

Обе половины задачи проверил в forgejo/main своими глазами. Видимость: .forgejo/workflows/ci.yml:285 echo "### pytest вернул код $rc" + exit $rc (гейт сохранён), :295/:312 маркеры начала-конца шага Coverage summary, :305 ### coverage report вернул код $cov_rc с разделением вычисления и вывода (шаг больше не может уронить job из-за pipefail на fail_under), :320/:322 маркеры шага «Снести тестовый Postgres» — то есть девятисекундная тишина между pytest и post-фазой закрыта целиком. Причина красноты установлена, а не предположена: backend/tests/conftest.py::pytest_sessionfinish поднимает session.exitstatus=1 на неучтённых пропусках, подтверждено локальным прогоном с явным echo $? (PYTEST EXIT CODE = 1 при нулевых FAILED) и живым зелёным прогоном 7539 после #2875. Проверил и единственный остаток, который бот сам заявил в последнем комментарии («сторож печатает обычным print() и теряется») — он тоже уже в main: conftest.py:110-117, под GITHUB_ACTIONS/CI дублирует сообщение в ::error:: с прямой ссылкой на #2871. Ничего живого по этой задаче не осталось; прод-разрыва тут нет по определению — workflow-файлы исполняются из ветки.

Если что-то из перечисленного всё же живо — переоткройте задачу, разбор мог упустить частный случай.

## Закрываю по итогам разбора трекера 16.08.2026 **Вердикт:** сделано кодом. Слепая зона закрыта, и найден сам виновник: `coverage report` уважает fail_under и выходит с кодом 2 под `bash -eo pipefail`, гася зелёный pytest — теперь вычисление и вывод разделены, код возврата печатается. **Доказательство:** Коммиты a6e751da «ci: сделать видимыми два безмолвных шага после pytest (#2871) (#2872)» и 7de5aa05 «ci: печатать код возврата pytest явно (#2871) (#2875)»; .forgejo/workflows/ci.yml:246 `echo "### pytest вернул код $rc"`, 256-273 маркеры начала/конца шага Coverage summary и явный `cov_rc`, 281-284 маркеры шага сноса Postgres. **Независимая проверка.** Вердикт отдельно проверялся вторым проходом, задачей которого было именно опровергнуть закрытие, а не подтвердить его: > Обе половины задачи проверил в forgejo/main своими глазами. Видимость: .forgejo/workflows/ci.yml:285 `echo "### pytest вернул код $rc"` + `exit $rc` (гейт сохранён), :295/:312 маркеры начала-конца шага Coverage summary, :305 `### coverage report вернул код $cov_rc` с разделением вычисления и вывода (шаг больше не может уронить job из-за pipefail на fail_under), :320/:322 маркеры шага «Снести тестовый Postgres» — то есть девятисекундная тишина между pytest и post-фазой закрыта целиком. Причина красноты установлена, а не предположена: backend/tests/conftest.py::pytest_sessionfinish поднимает session.exitstatus=1 на неучтённых пропусках, подтверждено локальным прогоном с явным echo $? (PYTEST EXIT CODE = 1 при нулевых FAILED) и живым зелёным прогоном 7539 после #2875. Проверил и единственный остаток, который бот сам заявил в последнем комментарии («сторож печатает обычным print() и теряется») — он тоже уже в main: conftest.py:110-117, под GITHUB_ACTIONS/CI дублирует сообщение в `::error::` с прямой ссылкой на #2871. Ничего живого по этой задаче не осталось; прод-разрыва тут нет по определению — workflow-файлы исполняются из ветки. Если что-то из перечисленного всё же живо — переоткройте задачу, разбор мог упустить частный случай.

lekss361 closed this issue

2026-08-16 10:36:42 +00:00

bot-backend referenced this issue

2026-08-19 07:56:41 +00:00

ci: смоук периметра МЕРЫ запускается сразу после деплоя (#2917) #2922