From 00d590e8be73ff83d51eadfb84aa05801ecfad9e Mon Sep 17 00:00:00 2001 From: heaven Date: Fri, 11 Sep 2026 01:11:42 +0300 Subject: [PATCH] Answer a stop with the unit that is live when the intent lands, stop calling our own grace kill a broken deployment, and repair a settlement mark instead of remembering it. --- platform/docs/platform-PROGRESS.md | 245 ++++++++++++++++++ platform/internal/pgstore/migrations.sha256 | 1 + .../migrations/00035_settled_repair_index.sql | 17 ++ platform/internal/pgstore/runs.go | 75 +++++- platform/internal/pgstore/sink.go | 41 +++ platform/internal/pgstore/stoprace_test.go | 143 ++++++++++ platform/internal/runs/gracekill_test.go | 86 ++++++ platform/internal/runs/reconcile.go | 71 ++++- platform/internal/runs/reconcile_test.go | 16 +- platform/internal/runs/settledmark_test.go | 141 ++++++++++ 10 files changed, 813 insertions(+), 23 deletions(-) create mode 100644 platform/internal/pgstore/migrations/00035_settled_repair_index.sql create mode 100644 platform/internal/pgstore/stoprace_test.go create mode 100644 platform/internal/runs/gracekill_test.go create mode 100644 platform/internal/runs/settledmark_test.go diff --git a/platform/docs/platform-PROGRESS.md b/platform/docs/platform-PROGRESS.md index 4d25f8f7..048849f2 100644 --- a/platform/docs/platform-PROGRESS.md +++ b/platform/docs/platform-PROGRESS.md @@ -49,6 +49,251 @@ committed_usd, which is what would let this side say "at most Y"». Движок чтение оценочных строк из потока. Промт ещё не написан — если у вас есть довод против любой из четырёх позиций, скажите ДО того, как я его напишу. +## ДОРАБОТКА ПО ИНВАРИАНТУ `D39.240` — ОТЧЁТ (11.09, `textmachine-5c`) + +> Три предмета: строки **401** (вторая половина), **394**, **392**. Вход HEAD `d61469f`, дерево зоны +> на входе чистое. Записка-план ниже по странице; порядок исполнен как объявлен. + +### 401 — отметка о расчёте больше не остаётся пустой навсегда + +Расчёт — ДВА действия: `Settle` закрывает резервацию своей транзакцией, `MarkSettled` ставит +`settled_at` вторым оператором. Смерть процесса между ними оставляла леджер верным, а столбец пустым +**навсегда**: рабочий список ключуется на ОТКРЫТОЙ резервации, а её уже нет — прогон выпадает из +всех списков, которые могли бы к нему вернуться. + +**Сделано:** отметка не запоминается, а ВЫВОДИТСЯ. `Store.StampSettledRuns` одним оператором +доштамповывает прогоны, чьи жизнь и деньги кончились («прогон завершён И у него нет открытых +резерваций»), и фаза расчёта зовёт его последним действием прохода. Ни новой колонки, ни нового +состояния; «навсегда» стало «до следующего прохода». Число починенного идёт WARN-ом — это факт о +деплое (процесс умер посреди расчёта), а не о прогонах. + +⚠ **Названная цена:** отметка ставится временем ПОЧИНКИ, а не моментом закрытия денег; точное время +живёт в `closed_at` самой резервации. Прогон, починенный здесь, опаздывает штампом не больше чем на +один проход. + +⛔ **Своя находка адверсариального прохода — своя же правка чуть не стала дороже дефекта.** Запрос +фильтрует `finished_at is not null and settled_at is null`, и ни один существующий индекс `runs` ему +не помогает: один частичный по `finished_at is null` (противоположная половина), второй по книге. ⇒ +починка была бы **последовательным сканом `runs` на КАЖДОМ тике**, а `runs` только растёт. Заведён +частичный индекс миграцией `00035`, предикат в предикат: в здоровом деплое множество ПУСТО, потому +что обычный путь ставит отметку в том же проходе, — индекс держит ровно то, что оставил сбой. + +### 394 — «убили своим грейсом» больше не читается как поломка деплоя + +**Замерено исполнением, с контрольной посадкой.** Юнит нашей формы (`TimeoutStopSec=3`, процесс ловит +SIGTERM и не выходит) даёт маркер `{"result":"timeout","code":"killed","status":"KILL"}`; тот же юнит +с процессом, который по SIGTERM выходит, даёт `{"result":"exit-code","code":"exited","status":"5"}`. +Тройка `timeout/killed/KILL` и есть «сработал НАШ `TimeoutStopSec`», и прибор эти случаи различает. + +**Сделано:** `timeout` выведен из группы «поломка деплоя» в `interrupted`. Довод — не вкус, а +невыполнение довода самой группы: там написано «the next spawn dies the same way», что верно для +OOM (следующий процесс упрётся в тот же лимит) и ложно для убийства по грейсу (следующий процесс +никто не останавливает, работа предшественника в чекпоинтах). Контракт при этом НЕ трогается: +`interrupted` — существующее значение, и его определение дословно описывает этот случай («retrying IS +the remedy, and finished work is not bought again»). + +⛔ **Проверено прибором по требованию оркестратора: в эту развилку `timeout` приходит ДВУМЯ ветвями, а +не одной.** Замер трёх состояний намерения: намерение СТАРШЕ маркера → `outcome` отдаёт `stopped` и +до причины отказа не доходит вовсе; намерения НЕТ → `failed`; намерение МЛАДШЕ маркера → `failed`. +Последнее — не угол: часы разные (маркер несёт хостовые, намерение платформенные), и «нажали стоп +после убийства» — обычное состояние. Обе достигающие ветви хотят одного ответа, поэтому правка одна, +но запинены обе. + +⚠ **Чего НЕ сделано и почему** — не переведён в `stopped`. Грейс срабатывает только после того, как +остановку у systemd попросили, но при перезагрузке хоста менеджер останавливает ВСЕ юниты, и прогон, +не успевший свернуться, получил бы `stopped` и остался мёртвым после штатного ребута. Это ровно +асимметрия, ради которой написан `interruptedBySomeoneElse`. + +### 392 — гонка имени юнита: ВОСПРОИЗВЕДЕНА, потом закрыта + +Строка описывала механизм грубее, чем он есть. Бóльшая часть окна уже была закрыта: `reopen` +отказывает рестарту при записанном намерении, а подзапрос читает «последнюю не кончившуюся попытку», +то есть при любом порядке КОММИТОВ ответ верен. **Настоящая дыра — в изоляции READ COMMITTED:** +`RequestStop` был одним UPDATE; когда он ждёт замок строки `runs` (его держит рестарт, пока кончает +одну попытку и открывает следующую), Postgres после разблокировки пере-проверяет `WHERE` против +НОВОЙ версии строки, **а подзапрос в `RETURNING` считается по снимку начала оператора**. + +**Предъявлено исполнением на живой БД, в обе стороны:** +``` +до правки: рестарт закоммитил "unit-NEW"; RequestStop ответил "unit-OLD"; живой юнит "unit-NEW" +после правки: рестарт закоммитил "unit-NEW"; RequestStop ответил "unit-NEW" +``` +**Сделано:** `RequestStop` стал транзакцией — `select … for update of r` по строке прогона, затем +чтение имени и запись намерения. В READ COMMITTED блокирующее чтение после взятия замка пере-читает +последнюю зафиксированную версию, поэтому каждый следующий оператор транзакции видит рестарт, который +был в полёте. Имя юнита и намерение принадлежат одному моменту. +⚠ Ожидание замка правкой НЕ добавлено: одиночный UPDATE ждал того же замка. Изменилось не то, ждёт ли +вызов, а что он видит, проснувшись. + +### Мутация — пять посадок на копии, засчитано по ТЕКСТУ + +Копия жила в `~/.cache/tm-5c/mut2/platform` (не в общем скретчпаде), перед каждой правкой утверждались +`test -f go.mod` и точный `pwd`, после — `diff -rq` с деревом «идентично» и копия удалена. + +| посадка | что сломано | вердикт и **текст** | +|---|---|---| +| A (392) | снято блокирующее чтение, назад к одному оператору | КРАСНО: «the stop answered "unit-OLD" while the live unit is "unit-NEW": the caller would signal a unit that is already dead…» | +| B (394) | `timeout` возвращён в группу поломок деплоя | КРАСНО ×2: «a "timeout" kill is reported to the client as "service_error", want "interrupted"» и то же во второй ветви | +| C (401) | из фазы расчёта убрана починка | КРАСНО: «a run whose money had closed is still carrying no settled mark after a full sweep…» | +| D (401) | починка штампует и ЖИВЫЕ прогоны | ⛔ **ВЫЖИЛА** на первом заходе | +| D′ (401) | то же, против пере-строенной фикстуры | КРАСНО: «a run that is still LIVE was stamped settled … because it happened to hold nothing» | + +⛔ **Выжившая посадка — дефект В МОЁМ СОБСТВЕННОМ ПИНЕ, и он важнее трёх пойманных.** Починка +исключает живой прогон ДВАЖДЫ — потому что у него открыт холд, и потому что его жизнь не кончилась. +Первое исключение ПРЯЧЕТ второе: моя зеркальная фикстура держала прогон с открытым холдом, поэтому +снятие условия «прогон завершён» не меняло ничего. Фикстура пере-строена на состояние, где условия +расходятся, и это состояние ОБЫЧНОЕ, а не угловое: **между попытками** — свип рассчитал кончившуюся +попытку (резервация закрыта) и ещё не открыл следующую; прогон жив и не держит ничего, и только +«кончился ли прогон» удерживает починку от него. На пере-строенной фикстуре посадка краснеет, и +краснеет ИМЕННО во второй подветви — то есть первая действительно её прятала. + +### Числа, сняты ПОСЛЕ последней правки + +``` +$ TM_PLATFORM_TEST_DSN=…55433 TM_PLATFORM_TEST_ENGINE_BIN=… TM_PLATFORM_TEST_BOOK_TEMPLATE=… \ + TM_PLATFORM_TEST_PGDUMP=… TM_PLATFORM_TEST_PGRESTORE=… make check + MAKE-EXIT=0 · пакетов `ok` 20 · строк FAIL 0 · линтер «0 issues» · скипов 5 + gofmt / go vet / sqlc diff чисты · ALARM PD-count: 15 (baseline 15) — не сдвинут + скипы поимённо, условие у всех ОДНО и названное — нет `configs/mining-contrast.zh.txt`: + TestTheRealEngineNamesItsRestorePointInTheLineThisPlatformParses · + TestALivePreviewWritesNothingAndALiveApplyWrites · + TestALiveBuildOfAHollowBookWritesTheMarkedCopyInsteadOfRefusing · + TestWithoutPartialTheSameBookIsRefusedWithTheBuildsOwnNumber · + TestTheSnapshotGuardIsLoudWithoutTheFlagsAndPassesWithThem +``` + +### ⚠ Правка ЧУЖОГО теста, вызванная заказанной сменой поведения — объявляю по `D39.183` + +`TestWhyARunFailedDecidesWhetherARetryIsWorthOffering` (`internal/runs/reconcile_test.go`) держал ряд +«killed by the stop timeout → `service_error`». После правки 394 он честно покраснел в батарее — не +подогнан, а **описывал поведение, которое заказано сменить** (строка 394, ратифицировано письмом +оркестратора «делай, обе половины»). Ряд приведён к новому поведению, и вместе с ним исправлен +КОММЕНТАРИЙ теста, который нёс тот самый довод, что правка и опровергает. +**Куда уехала гарантия:** в `TestAKillByOurOwnGraceIsNotReportedAsABrokenDeployment`, где живёт и +довод, и замер маркера, и контроль `oom-kill`, который обязан ОСТАТЬСЯ `service_error`. Остальные +шесть рядов старого теста не тронуты — довод группы для них выполняется. + +### Что НЕ удалось + +**1. Цепочка «свип → `Stop` → настоящий systemd» по-прежнему не пройдена ни одним тестом.** Объявлено +заранее в записке-плане и остаётся верным: такого стенда в зоне нет, и я его не строила. Предмет 392 +живёт в изоляции транзакции, и ЕГО стенд есть — доказательство полное для гонки и неполное для цепочки. + +**2. Ущерб по 392 предъявлен на уровне СТОРА, а не продукта.** Тест показывает, что `RequestStop` +возвращал мёртвое имя; что обработчик после этого шлёт сигнал в пустоту и пользователь держит `202` — +следствие, выведенное чтением, а не поставленный сценарий. + +**3. Гонка воспроизведена НА ФИКСТУРЕ, а не на настоящем рестарте.** Транзакция-соперник пишет те же +три оператора, что и `reopen` (замок строки прогона, конец попытки, вставка следующей), но это моя +запись, а не вызов `ReopenRun`. Если `reopen` однажды перестанет брать замок строки `runs` первым, +фикстура продолжит воспроизводить старую форму гонки, а не новую. + +**4. По 394 не проверено исполнением, что `timeout` не приходит от НАЧАЛЬНОГО тайм-аута.** У наших +юнитов `Type=simple` (дефолт `systemd-run`), для которого стартовая фаза завершается сразу, поэтому +`timeout` может прийти только от остановочной, — но это РАССУЖДЕНИЕ о systemd, а не мой замер. +Сконструировать стартовый тайм-аут на `Type=simple` я не пробовала. + +**5. Взяты три предмета из десяти.** 398, 399, 400 и три носителя мусора на диске не тронуты по +границам захода; 400 и мусор — ещё и потому, что я их не читала. + +## ДОРАБОТКА ПО ИНВАРИАНТУ `D39.240` — ЗАПИСКА-ПЛАН (11.09, `textmachine-5c`) + +> Три предмета из улова отменённого пака, открытые владельцем словом «если остались баги или +> рефакторинг про останов — доделать просто»: строки **392**, **394** и **401** (вторая половина). +> Инвариант: остановка ЖЁСТКАЯ, деньги терять допустимо, но **без гонок, без половинчатых состояний, +> с верным возобновлением**. Вход HEAD `d61469f`, дерево зоны на входе чистое. +> ⛔ Границы заданы оркестратором и приняты: **398** и **399** (логика служебного обхода), **400** и +> носители мусора на диске (**401**а/б/в) НЕ берутся — последние два потому, что я их не читала, и +> давать себе предмет, которого не смотрела, под видом «доделать» нельзя. + +### 392 — гонка имени юнита: механизм назван точно, и он тоньше, чем строка + +Строка говорит «между коммитом намерения и вызовом systemd свип успевает рестартовать». Разбор кода +показывает, что бóльшая часть этого окна УЖЕ закрыта, и закрыта хорошо: `reopen` отказывается +рестартовать прогон с записанным намерением (`ErrStopRequested`), а `RequestStop` читает имя юнита +подзапросом «последняя не кончившаяся попытка» — то есть при любом порядке КОММИТОВ ответ верен. + +⇒ **Настоящая дыра — не в порядке коммитов, а в изоляции READ COMMITTED.** `RequestStop` сегодня один +UPDATE. Когда он блокируется на замке строки `runs`, который держит идущий `reopen`, Postgres после +разблокировки пере-проверяет `WHERE` против НОВОЙ версии строки (EvalPlanQual) — но **подзапрос в +`RETURNING` считается по снимку, взятому в начале оператора**. Значит намерение ложится на новую +попытку, а имя юнита возвращается от СТАРОЙ. Обработчик шлёт сигнал мёртвому юниту, живой работает, +пользователь держит `202`. + +**Чинить так:** `RequestStop` становится транзакцией — `select … for update` по строке прогона (в +READ COMMITTED он после взятия замка пере-читает последнюю зафиксированную версию), затем чтение +имени живой попытки, затем UPDATE. Тогда имя юнита и запись намерения принадлежат одному моменту. +**Предъявлять исполнением**, а не рассуждением: тест на настоящем Postgres, где рестарт и стоп идут +параллельно, и утверждение — какое имя юнита вернулось. + +⚠ **Про стенд, честно и заранее.** Цепочку «свип → `Stop` → настоящий systemd» по-прежнему не гоняет +ни один тест, и я такого стенда не строю: он не влезает в этот заход. Но предмет 392 живёт НЕ там — +он живёт в изоляции транзакции, и её стенд в зоне есть (живой Postgres). ⇒ доказательство будет +полным для гонки и неполным для цепочки; второе пойдёт в «что не удалось», как и предупредил +оркестратор. + +### 394 — «убили своим грейсом» читается как поломка деплоя + +**Замерено исполнением** (юнит нашей формы, `TimeoutStopSec=3`, процесс ловит SIGTERM и не выходит): +маркер, который пишет systemd, — `{"result":"timeout","code":"killed","status":"KILL"}`. +**Контрольная посадка на том же стенде** (тот же юнит, процесс выходит по SIGTERM) — +`{"result":"exit-code","code":"exited","status":"5"}`. То есть тройка `timeout/killed/KILL` и есть +«сработал НАШ `TimeoutStopSec`», и прибор эти два случая различает. + +Сегодня она попадает в общий список с `oom-kill` и даёт `failed` + `service_error` +(`reconcile.go`, `failureReason`). ⛔ **И довод, записанный над этим списком, ДЛЯ `timeout` не +работает**: там сказано «an out-of-memory kill and a stop-timeout SIGKILL both told the client that +retrying would help, which for those two is exactly false: the next spawn dies the same way». Для OOM +это верно — следующий процесс упрётся в тот же лимит. Для убийства по грейсу неверно: следующий +процесс НИКТО не останавливает, и работа его предшественника лежит в чекпоинтах, то есть повтор не +покупается заново. + +⇒ **Делаю: `timeout` уходит из группы `service_error` в `interrupted`** — «ретрай и есть лекарство» — +и довод пишется на месте, вместе с тем, почему общий довод не покрывает этот случай. +⛔ **ОБЪЯВЛЯЮ ГРОМКО: это правка ПРОДУКТОВО ВИДИМОГО поведения поверх решения с записанным доводом.** +Она в моей зоне и по предмету строки, но если оркестратор считает, что вопрос «предлагать ли +пользователю повтор» — не мой, пусть скажет, и я откачу этот пункт, оставив вторую половину. +⚠ **Чего я НЕ делаю и почему:** не перевожу такой прогон в `stopped`. Соблазн есть — грейс срабатывает +только после того, как остановку у systemd попросили, — но при перезагрузке хоста менеджер +останавливает все юниты, и прогон, не успевший свернуться, получил бы `stopped` и остался бы мёртвым +после штатного ребута. Это ровно та асимметрия, ради которой написан `interruptedBySomeoneElse`. + +### 401 (вторая половина) — отметка о расчёте может остаться пустой навсегда + +Расчёт и отметка — ДВА действия: `Settle` закрывает резервацию своей транзакцией, `MarkSettled` +ставит `settled_at` отдельным оператором (`reconcile.go`, четыре места). Смерть процесса между ними +оставляет леджер верным, а столбец пустым — **навсегда**, потому что рабочий список `UnsettledRuns` +ключуется на ОТКРЫТОЙ резервации, а она уже закрыта. Читателей у столбца вне тестов ноль (пере-снято: +три писателя, одна очистка, ноль чтений; контроль — 15 упоминаний в тестах). + +**Чинить самолечением, а не новым состоянием.** Отметка ВЫВОДИМА: «прогон кончился И у него нет +открытых резерваций». Значит фаза расчёта одним оператором доштамповывает такие прогоны, и «навсегда» +превращается в «до следующего прохода». Ни новой колонки, ни нового смысла. +⚠ Альтернатива — удалить столбец, у которого ноль читателей, — отвергается: он несёт СМЫСЛ, который +охраняет ветка `--release-hold` («a field that lies is a field the next reader believes»), и удаление +было бы решением про будущее, которого я не знаю. + +### Порядок и почему такой + +**401 → 394 → 392.** От дешёвого и однозначного к тому, что меняет продуктовое поведение, и дальше к +тому, что требует конкурентного стенда: если заход придётся сдавать неполным, неотданным останется +предмет с самым узким радиусом, а не самый дешёвый. + +### Что предъявляю исполнением + +1. **392** — конкурентный тест на живом Postgres: рестарт и стоп в параллель, утверждение про + ВОЗВРАЩЁННОЕ имя юнита; мутация — вернуть одиночный UPDATE, ждать красноты по тексту. +2. **394** — маркер грейс-убийства уже замерен (выше, с контрольной посадкой); в батарее — пин на + разбор этого маркера, с контролем на `oom-kill`, который обязан ОСТАТЬСЯ `service_error`. +3. **401** — тест: расчёт прошёл, отметка не поставлена (симулируем смерть между двумя действиями), + следующий проход её ставит; контроль — живой прогон отметку НЕ получает. + +### Мандат самопроверки + +Мутация обязательна и засчитывается по ТЕКСТУ падения, а не по цвету. Отдельным заходом — +адверсариальный проход по своей готовой работе. Секция «что не удалось» непустая по построению: +цепочка «свип → systemd» в ней уже есть. + ## ДОФИКС ПО ОТМЕНЁННОМУ ПАКУ: `--no-block` С ПИНОМ (11.09, `textmachine-5c`) > Взят владельцем ОТДЕЛЬНО от отменённого пака и взят ровно в той форме, которую зона просила: правка diff --git a/platform/internal/pgstore/migrations.sha256 b/platform/internal/pgstore/migrations.sha256 index 3a3e8bb6..8319e6dc 100644 --- a/platform/internal/pgstore/migrations.sha256 +++ b/platform/internal/pgstore/migrations.sha256 @@ -50,3 +50,4 @@ c21877113b5966bc8a200ba69ce752d4ac295bdfd34e681afbd887523edb6ceb 00019_read_mod 069615c844e46cd601da4df38572e217b9c29f90a6fb3aa9befe101b942eccee 00032_exports.sql d56496573d793ce1b825664e2e28bdb0f8335fc4155a578cd3d23747363b8424 00033_order_and_price.sql ee5ea50e815479db3550eb28f1f039e417d36fcbf7799a3ac5b9f01913938eef 00034_spawn_proof_and_park.sql +463589447fed990aa1e53d3ad835cf27115c9ebf750f1724894aa11764204551 00035_settled_repair_index.sql diff --git a/platform/internal/pgstore/migrations/00035_settled_repair_index.sql b/platform/internal/pgstore/migrations/00035_settled_repair_index.sql new file mode 100644 index 00000000..36da4082 --- /dev/null +++ b/platform/internal/pgstore/migrations/00035_settled_repair_index.sql @@ -0,0 +1,17 @@ +-- +goose Up + +-- The settled mark is repaired on every sweep pass (runs.stampSettled): a run whose money closed +-- while the process died before stamping it is invisible to the settlement worklist, which keys on an +-- OPEN reservation, so re-deriving the fact is the only thing that ever comes back to it. +-- +-- ⛔ WITHOUT THIS INDEX THAT REPAIR IS A SEQUENTIAL SCAN OF `runs` ON EVERY TICK, and `runs` only ever +-- grows: it holds every run the deployment has ever started. Neither existing index helps — one is +-- partial on `finished_at is null` (the opposite half) and the other is keyed by book. +-- +-- PARTIAL, and matched to the query's own predicate, which is what makes it nearly free: in a healthy +-- deployment the set it indexes is EMPTY, because the ordinary path stamps the run in the same pass +-- that settles it. The index only ever holds the rows a crash left behind. +create index runs_unstamped_settled_idx on runs (id) where settled_at is null and finished_at is not null; + +-- +goose Down +drop index runs_unstamped_settled_idx; diff --git a/platform/internal/pgstore/runs.go b/platform/internal/pgstore/runs.go index d21007bd..43ea2628 100644 --- a/platform/internal/pgstore/runs.go +++ b/platform/internal/pgstore/runs.go @@ -1306,31 +1306,78 @@ var ErrStopRequested = errors.New("pgstore: the run has been asked to stop") // // The revision it answers with is the BOOK's — see ReadRun for why every run-carrying response uses // one counter. +// ⛔ THE UNIT NAME AND THE INTENT COME FROM ONE MOMENT, and making that true takes a transaction — +// one statement cannot, however it is written. The caller signals the unit this answers with, so a +// stale name means the signal goes to a unit that is already dead while the run's new process keeps +// working, with the user holding a `202` that says it was accepted. +// +// The mechanism is READ COMMITTED and it is not obvious, so it is written down. As a single UPDATE +// this call could block on the run row's lock — the reconciler's restart holds it while it ends one +// attempt and opens the next. When the lock is released Postgres re-checks the UPDATE's own WHERE +// against the NEW row version, so the intent lands correctly; but a SUBQUERY in RETURNING is still +// evaluated on the snapshot the statement started with, which predates the restart. Measured on a +// live database: a concurrent restart committed `unit-NEW`, this call answered `unit-OLD`, and the +// live attempt was `unit-NEW`. +// +// `select … for update` is what fixes it, and for a specific reason: in READ COMMITTED a locking read +// re-reads the latest committed version once the lock is granted, so every statement after it in this +// transaction sees the restart that was in flight. +// +// ⚠ The rest of the window was already closed and is left alone: `reopen` refuses to restart a run +// whose intent is on file (ErrStopRequested), so after this commits no restart can move the unit +// under the caller. func (s *Store) RequestStop(ctx context.Context, userID, runID string, now time.Time) (Run, string, error) { - // The bar comes from the shared fragment and is not spelled out again here: a second copy is how - // a projection drifts, and this one already needed the segment predicate twice. - const q = ` - update runs r set stop_requested_at = coalesce(r.stop_requested_at, $3) - from books b - where r.id = $1 and b.id = r.book_id and b.owner_id = $2 and r.finished_at is null - returning ` + runRow + `, - coalesce((select a.unit_name from run_attempts a - where a.run_id = r.id and a.ended_at is null - order by a.attempt_no desc limit 1), '')` var out Run var unit string - err := scanRun(s.pool.QueryRow(ctx, q, runID, userID, now), &out, &unit) - if errors.Is(err, pgx.ErrNoRows) { + err := s.inTx(ctx, func(tx pgx.Tx) error { + // The bar is the same one the update below carries; what this adds is the LOCK. `of r` keeps + // it to the run: the book is joined to prove ownership, not to be held. + var locked bool + switch err := tx.QueryRow(ctx, ` + select true from runs r + join books b on b.id = r.book_id + where r.id = $1 and b.owner_id = $2 and r.finished_at is null + for update of r`, runID, userID).Scan(&locked); { + case errors.Is(err, pgx.ErrNoRows): + return errStopNotMatched + case err != nil: + return fmt.Errorf("pgstore: lock the run to stop it: %w", err) + } + const q = ` + update runs r set stop_requested_at = coalesce(r.stop_requested_at, $3) + from books b + where r.id = $1 and b.id = r.book_id and b.owner_id = $2 and r.finished_at is null + returning ` + runRow + `, + coalesce((select a.unit_name from run_attempts a + where a.run_id = r.id and a.ended_at is null + order by a.attempt_no desc limit 1), '')` + switch err := scanRun(tx.QueryRow(ctx, q, runID, userID, now), &out, &unit); { + case errors.Is(err, pgx.ErrNoRows): + // Unreachable while the lock is held — nothing else can finish the run under it — but + // answered rather than assumed, because "cannot happen" is how a lock's guarantee gets + // quoted after the lock has been narrowed by somebody else. + return errStopNotMatched + case err != nil: + return fmt.Errorf("pgstore: request stop: %w", err) + } + return nil + }) + if errors.Is(err, errStopNotMatched) { // Nothing matched, and the two reasons need different answers. Asked separately and only on - // this path, so the ordinary stop stays one round trip. + // this path, so the ordinary stop stays one extra round trip and no more. return Run{}, "", s.whyNotLive(ctx, userID, runID) } if err != nil { - return Run{}, "", fmt.Errorf("pgstore: request stop: %w", err) + return Run{}, "", err } return out, unit, nil } +// errStopNotMatched is «no live run of this account matched», carried out of the transaction so the +// two reasons behind it — no such run, or a run that is over — are told apart outside it. Never +// returned to a caller: RequestStop replaces it with ErrNoRun or ErrRunNotLive. +var errStopNotMatched = errors.New("pgstore: no live run of this account matched") + func (s *Store) whyNotLive(ctx context.Context, userID, runID string) error { var visible bool if err := s.pool.QueryRow(ctx, ` diff --git a/platform/internal/pgstore/sink.go b/platform/internal/pgstore/sink.go index b8e6ce58..29f73402 100644 --- a/platform/internal/pgstore/sink.go +++ b/platform/internal/pgstore/sink.go @@ -697,7 +697,48 @@ func (s *Store) FinishUnspawnedStop(ctx context.Context, runID string, attemptID // the column must be able to tell what the machine saw from what the platform concluded. const StopRequestedResult = "stop-requested" +// StampSettledRuns finishes the job MarkSettled can leave half done, and answers how many runs it +// had to finish. +// +// ⛔ WITHOUT IT THE MARK CAN BE WRONG FOREVER, and «forever» is not a figure of speech. Settling is +// TWO acts: `Settle` closes the reservation in its own transaction, and `MarkSettled` stamps the run +// in a second statement. A process that dies between them leaves the ledger right and the column +// empty — and nothing ever comes back to it, because the settlement worklist keys on an OPEN +// RESERVATION and this run no longer has one. The run is out of every list that would look at it. +// +// The cure is a re-derivation rather than a new piece of state, because the mark IS derivable: a run +// whose own life is over and which holds no open reservation has had its money resolved, whatever a +// column says. So the sweep re-states the fact instead of remembering that it once failed to, and +// «forever» becomes «until the next pass». +// +// ⚠ It stamps `now` and not the moment the money actually closed, and that is a real loss named +// rather than hidden: the reservation's own `closed_at` is where the exact time lives. What this +// column answers is «is this run's money resolved», which is the question every reader of it would +// ask; a run repaired here carries a stamp late by at most one sweep. +// +// ⚠ A LIVE run is never touched, for the same reason MarkSettled's abandon path spells out: the mark +// is a statement about the WHOLE run's money, and a live attempt's hold is still open and still the +// reconciler's to close. +// +// The attempt key is split the way this package already splits it everywhere else (`RunSpent`), and +// not matched with LIKE: a run id is opaque, and `_` and `%` are ordinary characters in one. +func (s *Store) StampSettledRuns(ctx context.Context, now time.Time) (int64, error) { + tag, err := s.pool.Exec(ctx, ` + update runs r set settled_at = $1 + where r.finished_at is not null and r.settled_at is null + and not exists (select 1 from reservations res + where split_part(res.engine_run_id, '#', 1) = r.id and res.state = 'open')`, now) + if err != nil { + return 0, fmt.Errorf("pgstore: stamp settled runs: %w", err) + } + return tag.RowsAffected(), nil +} + // MarkSettled records that the money of a run has been resolved. +// +// ⚠ It is the ORDINARY path and not the only one: a process that dies between the settlement and this +// statement leaves the column empty with nothing to come back for it, so StampSettledRuns above +// re-derives the fact on a later pass. func (s *Store) MarkSettled(ctx context.Context, runID string, now time.Time) error { _, err := s.pool.Exec(ctx, `update runs set settled_at = $2 where id = $1 and settled_at is null`, runID, now) if err != nil { diff --git a/platform/internal/pgstore/stoprace_test.go b/platform/internal/pgstore/stoprace_test.go new file mode 100644 index 00000000..1164bf50 --- /dev/null +++ b/platform/internal/pgstore/stoprace_test.go @@ -0,0 +1,143 @@ +package pgstore + +import ( + "context" + "testing" + "time" +) + +// runWithAttempt is one live run of one funded account, with attempt 1 carrying a named unit. +func runWithAttempt(t *testing.T, unit string) (*Store, context.Context, string, time.Time) { + t.Helper() + s, ctx := testDB(t) + now := fundedAccount(t, s, ctx, "u1", "10") + bookID, err := s.AddBook(ctx, NewBook{OwnerID: "u1", Title: "b", SourceLang: "zh", TargetLang: "ru", + ChapterCount: 10, Workdir: "/srv/books/b", Now: now}) + if err != nil { + t.Fatal(err) + } + started, err := s.StartRun(ctx, StartRunInput{UserID: "u1", BookID: bookID, OrderedChapters: 1, + Ceiling: 1_000_000, Now: now}, 0, nil) + if err != nil { + t.Fatal(err) + } + // StartRun opens attempt 1 without a unit name — the row exists before anything is spawned. The + // test owns the numbering from here, so it names that attempt itself. + if _, err := s.pool.Exec(ctx, `update run_attempts set unit_name = $2 where run_id = $1`, started.ID, unit); err != nil { + t.Fatal(err) + } + return s, ctx, started.ID, now +} + +func liveUnitOf(t *testing.T, s *Store, ctx context.Context, runID string) string { + t.Helper() + var unit string + if err := s.pool.QueryRow(ctx, ` + select coalesce(unit_name, '') from run_attempts + where run_id = $1 and ended_at is null order by attempt_no desc limit 1`, runID).Scan(&unit); err != nil { + t.Fatal(err) + } + return unit +} + +// ⛔ THE UNIT THIS ANSWERS WITH IS THE ONE THE CALLER SIGNALS, so a stale name is a signal sent to a +// dead unit while the run's new process keeps working — and the user holds a `202` that says the stop +// was accepted. This is that race, run against a real database rather than argued. +// +// The mechanism is READ COMMITTED, and it is why one statement could not do this. As a single UPDATE +// the call blocks on the run row's lock, which the reconciler's restart holds while it ends one +// attempt and opens the next; when the lock is released the UPDATE's own WHERE is re-checked against +// the new row, so the intent lands correctly — but a SUBQUERY in RETURNING is still evaluated on the +// snapshot the statement began with, which predates the restart. +// +// ⚠ MEASURED IN BOTH DIRECTIONS BEFORE THIS WAS WRITTEN, which is why it is a test and not a +// precaution: with the single-statement form this fixture answered `unit-OLD` while the live attempt +// was `unit-NEW`; with the locking read it answers `unit-NEW`. +// +// The waiting time is PRINTED and asserted, because it is what proves the contended path was taken at +// all: a call that did not block never met the race, and «it answered the right unit» would then be +// true of a test that measured nothing. +func TestAStopAnswersTheUnitThatIsLiveWhenTheIntentLands(t *testing.T) { + const hold = 400 * time.Millisecond + s, ctx, runID, now := runWithAttempt(t, "unit-OLD") + + tx, err := s.pool.Begin(ctx) + if err != nil { + t.Fatal(err) + } + defer func() { _ = tx.Rollback(ctx) }() + // What a restart does: it takes the run row's lock, ends the live attempt and opens the next one. + for _, q := range []struct { + sql string + args []any + }{ + {`update runs set revision = revision + 1 where id = $1`, []any{runID}}, + {`update run_attempts set ended_at = $2 where run_id = $1 and attempt_no = 1`, []any{runID, now}}, + {`insert into run_attempts (run_id, attempt_no, unit_name, started_at) values ($1, 2, 'unit-NEW', $2)`, + []any{runID, now}}, + } { + if _, err := tx.Exec(ctx, q.sql, q.args...); err != nil { + t.Fatal(err) + } + } + + type answer struct { + unit string + waited time.Duration + err error + } + done := make(chan answer, 1) + go func() { + // A context of its own: this call must block on the row lock, not on the test's clock. + start := time.Now() + _, unit, err := s.RequestStop(context.Background(), "u1", runID, now.Add(time.Second)) + done <- answer{unit, time.Since(start), err} + }() + time.Sleep(hold) // let the stop reach the lock and wait there + if err := tx.Commit(ctx); err != nil { + t.Fatal(err) + } + + got := <-done + if got.err != nil { + t.Fatal(got.err) + } + live := liveUnitOf(t, s, ctx, runID) + t.Logf("a restart committed %q while a stop waited %.2fs for the run's lock; the stop answered %q", + live, got.waited.Seconds(), got.unit) + if got.waited < hold { + t.Fatalf("the stop returned after %.2fs and the restart held the lock for %s: it never waited on the "+ + "lock, so this fixture did not reproduce the race and proves nothing", got.waited.Seconds(), hold) + } + if live != "unit-NEW" { + t.Fatalf("the live attempt after the restart is %q, want unit-NEW: the fixture did not restart anything", live) + } + if got.unit != live { + t.Errorf("the stop answered %q while the live unit is %q: the caller would signal a unit that is already "+ + "dead, the run's new process would keep working, and the user would hold a 202 saying it was accepted", + got.unit, live) + } + // The intent itself must still be there — the fix is about WHICH unit, not about whether the stop + // was recorded. + var at *time.Time + if err := s.pool.QueryRow(ctx, `select stop_requested_at from runs where id = $1`, runID).Scan(&at); err != nil { + t.Fatal(err) + } + if at == nil { + t.Error("the stop answered a unit but recorded no intent: the sweep would restart the run it just stopped") + } +} + +// The uncontended path must not have changed: no restart, no lock to wait for, and the answer is the +// unit that is there. Without this the test above could pass over a call that always answered the +// newest attempt for the wrong reason. +func TestAnUncontendedStopStillAnswersItsUnit(t *testing.T) { + s, ctx, runID, now := runWithAttempt(t, "unit-ONLY") + run, unit, err := s.RequestStop(ctx, "u1", runID, now) + if err != nil { + t.Fatal(err) + } + if unit != "unit-ONLY" || run.ID != runID { + t.Errorf("an ordinary stop answered run %q unit %q", run.ID, unit) + } +} diff --git a/platform/internal/runs/gracekill_test.go b/platform/internal/runs/gracekill_test.go new file mode 100644 index 00000000..be074aa8 --- /dev/null +++ b/platform/internal/runs/gracekill_test.go @@ -0,0 +1,86 @@ +package runs + +import ( + "testing" + "time" + + "textmachine/platform/internal/pgstore" + "textmachine/platform/internal/runner" +) + +// ⛔ A RUN THIS PLATFORM KILLED BY ITS OWN DEADLINE IS NOT A BROKEN DEPLOYMENT. +// +// `TimeoutStopSec` is the grace this package sets on every run unit; when it expires systemd SIGKILLs +// the process and writes `timeout/killed/KILL`. That used to be reported as `service_error`, whose +// contract meaning is «do not promise a retry will help» — so a user whose run we cut off by our own +// rule was told their deployment was broken and sent away from the one action that would have worked. +// +// ⚠ THE CONTROL IS IN THE TABLE AND IT IS THE WHOLE POINT: `oom-kill` must still answer +// `service_error`, because for THAT one the group's argument holds — the next spawn meets the same +// limit. A change that moved both would not be a fix, it would be the same mistake mirrored. +func TestAKillByOurOwnGraceIsNotReportedAsABrokenDeployment(t *testing.T) { + at := time.Date(2026, 9, 11, 12, 0, 0, 0, time.UTC) + for _, tc := range []struct { + name string + result string + want string + }{ + // What systemd actually writes when TimeoutStopSec expires — measured on a unit of this shape. + {"our own stop deadline", "timeout", "interrupted"}, + // The sibling the group's argument is about, and it must not move. + {"killed for its memory", "oom-kill", "service_error"}, + {"the watchdog fired", "watchdog", "service_error"}, + {"the host ran out", "resources", "service_error"}, + // An ending nobody described stays what it was. ⚠ systemd's own word here is `signal` and NOT + // `success`: `success` on a killed unit is a different branch entirely — `outcome` answers + // `stopped` for it («a stop nobody recorded») and never reaches a failure reason. Written + // wrongly the first time and caught by this test's own guard below, which is what that guard + // is for. + {"a signal nobody described", "signal", "interrupted"}, + } { + t.Run(tc.name, func(t *testing.T) { + m := runner.Marker{Unit: "u", Result: tc.result, Code: "killed", Status: "KILL", At: at} + status, _, exit := outcome(pgstore.LiveRun{RunID: "r"}, m) + if status != "failed" { + t.Fatalf("a %q kill ended as %q, not failed: this test is about the reason a FAILED run carries, "+ + "so it now measures nothing", tc.result, status) + } + if got := failureReason(status, exit, m); got != tc.want { + t.Errorf("a %q kill is reported to the client as %q, want %q", tc.result, got, tc.want) + } + }) + } +} + +// ⚠ TWO BRANCHES CARRY `timeout` INTO THAT ANSWER AND BOTH ARE PINNED, because a fix that covered one +// of them would look complete and be half. Which branch a run takes is decided by the stop intent's +// timestamp against the marker's — and the two are not even the same clock (the marker carries the +// host's, the intent this platform's), so «the intent is newer» is an ordinary state and not a corner. +// +// The middle row is the control that proves the other two are not vacuous: with an intent OLDER than +// the marker the run is `stopped` and never reaches the failure reason at all. +func TestBothWaysAGraceKillReachesItsReasonAreCovered(t *testing.T) { + at := time.Date(2026, 9, 11, 12, 0, 0, 0, time.UTC) + older, newer := at.Add(-time.Minute), at.Add(time.Minute) + m := runner.Marker{Unit: "u", Result: "timeout", Code: "killed", Status: "KILL", At: at} + for _, tc := range []struct { + name string + intent *time.Time + wantStatus string + wantReason string + }{ + {"nobody recorded a stop — a reboot, or a hand stop", nil, "failed", "interrupted"}, + {"the stop was asked for BEFORE the kill", &older, "stopped", ""}, + {"the stop was asked for AFTER the kill", &newer, "failed", "interrupted"}, + } { + t.Run(tc.name, func(t *testing.T) { + status, _, exit := outcome(pgstore.LiveRun{RunID: "r", StopRequestedAt: tc.intent}, m) + if status != tc.wantStatus { + t.Errorf("status %q, want %q", status, tc.wantStatus) + } + if got := failureReason(status, exit, m); got != tc.wantReason { + t.Errorf("failure reason %q, want %q", got, tc.wantReason) + } + }) + } +} diff --git a/platform/internal/runs/reconcile.go b/platform/internal/runs/reconcile.go index 53ac3132..16f17594 100644 --- a/platform/internal/runs/reconcile.go +++ b/platform/internal/runs/reconcile.go @@ -214,9 +214,42 @@ func (s *Service) settlePhase(ctx context.Context) error { } s.settleOne(ctx, u) } + s.stampSettled(ctx) return nil } +// stampSettled repairs the settled mark of runs whose money closed while nothing recorded it. +// +// ⛔ IT IS THE ONLY THING THAT EVER COMES BACK TO THEM. Settling is two acts — the reservation closes +// in its own transaction, the run is stamped in a second statement — and a process that dies between +// leaves the ledger right and the column empty. The worklist above cannot help: it keys on an OPEN +// reservation, and that run has none, so it is out of every list that would look at it. This is the +// half-applied state the invariant is about, in its purest form: two writes, one survivor, no reader +// to notice. +// +// It runs AFTER the worklist and not before, so a repair never competes with an actual settlement for +// the phase's remaining time; and its failure is LOGGED rather than returned, because a repair that +// could not run is not a sweep that failed — the next pass re-derives the same fact from the same +// three sources. A pass that has already run out is left alone entirely: this is the cheapest work in +// the phase and the last that should push it over. +func (s *Service) stampSettled(ctx context.Context) { + if over(ctx) { + return + } + repaired, err := s.Store.StampSettledRuns(ctx, s.now()) + if err != nil { + s.log().ErrorContext(ctx, "the settled mark of finished runs could not be repaired; the next pass tries again", "err", err) + return + } + if repaired > 0 { + // Said out loud because it means a process died mid-settlement, which is a fact about the + // deployment and not about these runs. Silence would make the repair invisible and the crash + // with it. + s.log().WarnContext(ctx, "runs whose money had closed were carrying no settled mark; it has been re-derived", + "runs", repaired) + } +} + // settleOne closes the money of one finished attempt under its own budget, and takes it out of the // head of the list when it could not. // @@ -1095,12 +1128,40 @@ func failureReason(status string, exit *int, m runner.Marker) string { } return "service_error" } - // ⚠ No exit code at all, and systemd's own word for what happened is what separates the two - // answers. It was IGNORED here — the marker was taken as a parameter and never read — so an - // out-of-memory kill and a stop-timeout SIGKILL both told the client that retrying would help, - // which for those two is exactly false: the next spawn dies the same way. `interrupted` is left for what it means — an ending nobody described. + // ⚠ No exit code at all, and systemd's own word for what happened is what separates the answers. + // It was IGNORED here once — the marker was taken as a parameter and never read — so every kill + // told the client that retrying would help, which for most of them is exactly false: the next + // spawn dies the same way. `interrupted` is left for what it means — an ending nobody described. + // + // ⛔ EXCEPT `timeout`, WHICH IS OUR OWN POLICY AND NOT A FAULT OF THE DEPLOYMENT, and it used to + // sit in this list beside the out-of-memory kill. What systemd calls `timeout` on a unit of this + // shape is TimeoutStopSec expiring — the grace this platform itself sets — and the marker it + // writes is `timeout/killed/KILL` (measured: the same rig with a process that exits on SIGTERM + // writes `exit-code/exited/5`, so the two are told apart by what the machine saw and not by + // inference). + // + // The list's own argument is what excludes it. That argument is «the next spawn dies the same + // way», and it is true of the others: a run killed for its memory meets the same limit, a + // watchdog fires on the same wedge. It is FALSE here. Nobody is stopping the next spawn, and the + // work of this one is in its checkpoints — so a retry is not a promise this platform cannot keep, + // it is the remedy, which is the contract's own definition of `interrupted` («retrying IS the + // remedy, and finished work is not bought again»). Reporting `service_error` instead told a user + // that their deployment was broken when what had happened is that we killed their run by our own + // deadline, and sent them away from the one action that would have helped. + // + // ⚠ TWO BRANCHES ARRIVE HERE CARRYING `timeout`, not one, and both want this answer — measured + // rather than assumed. With a stop intent OLDER than the marker the run never reaches this + // function at all (`outcome` answers `stopped`). It arrives with NO intent — a reboot, or a hand + // stop, that our grace then cut short — and it arrives with an intent NEWER than the marker, + // which is a stop pressed after the kill had already happened, or the two clocks disagreeing + // (they are not the same clock: the marker carries the host's, the intent this platform's). + // + // ⚠ It is deliberately NOT `stopped`. The grace only fires after somebody asked systemd to stop + // the unit — but on a host reboot the manager stops every unit it owns, and calling that a user's + // stop would leave every run on the host dead after a routine restart, with its budget unspent + // and nobody to resume it. That is the asymmetry interruptedBySomeoneElse exists for. switch m.Result { - case "oom-kill", "timeout", "core-dump", "watchdog", "resources", "protocol", "exec-condition": + case "oom-kill", "core-dump", "watchdog", "resources", "protocol", "exec-condition": return "service_error" } return "interrupted" diff --git a/platform/internal/runs/reconcile_test.go b/platform/internal/runs/reconcile_test.go index 42583152..7c7d0cd7 100644 --- a/platform/internal/runs/reconcile_test.go +++ b/platform/internal/runs/reconcile_test.go @@ -625,9 +625,17 @@ func TestAnAttemptStartsWhereTheJournalAlreadyEnds(t *testing.T) { // The three values of RunFailureReason answer ONE question — is a retry worth offering — and the // discriminator for the no-exit-code half is systemd's own word for what happened. // -// ⚠ The marker was taken as a parameter and never read, so an out-of-memory kill and a stop-timeout -// SIGKILL both told the client that retrying would help — which for those two is exactly false: the -// next spawn dies the same way. Found by cross-model review; nothing pinned it before. +// ⚠ The marker was taken as a parameter and never read, so every kill told the client that retrying +// would help — which for most of them is exactly false: the next spawn dies the same way. Found by +// cross-model review; nothing pinned it before. +// +// ⚠ THE STOP-TIMEOUT ROW MOVED, and it moved because the argument above does not reach it. This test +// used to pin `timeout` beside `oom-kill` as a deployment fault. But `timeout` is THIS platform's own +// TimeoutStopSec expiring — our deadline, not a fault of the host — and «the next spawn dies the same +// way» is false for it: nobody is stopping the next spawn, and the work of this one is in its +// checkpoints. The argument still holds for every other row here, which is why only one moved. +// The reasoning, the measurement of what systemd writes, and the `oom-kill` control that keeps the +// change honest all live in TestAKillByOurOwnGraceIsNotReportedAsABrokenDeployment. func TestWhyARunFailedDecidesWhetherARetryIsWorthOffering(t *testing.T) { code := func(n int) *int { return &n } for _, tc := range []struct { @@ -644,7 +652,7 @@ func TestWhyARunFailedDecidesWhetherARetryIsWorthOffering(t *testing.T) { exit: code(ingest.ExitConfigInvalid), want: "service_error"}, {name: "a plain infrastructure failure", status: "failed", exit: code(1), want: "service_error"}, {name: "out of memory", status: "failed", marker: runner.Marker{Result: "oom-kill"}, want: "service_error"}, - {name: "killed by the stop timeout", status: "failed", marker: runner.Marker{Result: "timeout"}, want: "service_error"}, + {name: "killed by our own stop deadline", status: "failed", marker: runner.Marker{Result: "timeout"}, want: "interrupted"}, {name: "an ending nobody described", status: "failed", marker: runner.Marker{Result: "signal"}, want: "interrupted"}, } { diff --git a/platform/internal/runs/settledmark_test.go b/platform/internal/runs/settledmark_test.go new file mode 100644 index 00000000..6ee80990 --- /dev/null +++ b/platform/internal/runs/settledmark_test.go @@ -0,0 +1,141 @@ +package runs + +import ( + "testing" + "time" +) + +// settledAt is what the run row says about its own money. +func settledAt(t *testing.T, f *fixture, runID string) *time.Time { + t.Helper() + var at *time.Time + if err := f.store.Pool().QueryRow(f.ctx, `select settled_at from runs where id = $1`, runID).Scan(&at); err != nil { + t.Fatal(err) + } + return at +} + +func openReservations(t *testing.T, f *fixture, runID string) int { + t.Helper() + var n int + if err := f.store.Pool().QueryRow(f.ctx, ` + select count(*) from reservations + where split_part(engine_run_id, '#', 1) = $1 and state = 'open'`, runID).Scan(&n); err != nil { + t.Fatal(err) + } + return n +} + +// ⛔ THE HALF-APPLIED STATE IN ITS PUREST FORM: two writes, one survivor, and no reader left to +// notice. Settling closes the reservation in one transaction and stamps the run in a second +// statement, so a process that dies between them leaves the ledger right and the column empty — and +// nothing ever comes back to it, because the settlement worklist keys on an OPEN reservation and +// this run has none. The run is out of every list that would look at it. +// +// The crash is simulated the only honest way available: by clearing the column AFTER a real +// settlement, which is exactly the state such a crash leaves — the money closed, the mark absent. +// What is asserted is that the sweep re-derives it. +func TestASettledRunWhoseMarkNeverLandedIsRepairedByTheNextPass(t *testing.T) { + f := newFixture(t, "10", 500) + l := spawned(t, f, 100) + ends(t, f, l, exitedWith("0")) + if err := f.svc.Sweep(f.ctx); err != nil { + t.Fatal(err) + } + if settledAt(t, f, l.RunID) == nil { + t.Fatal("the ordinary path did not stamp the run at all, so this test cannot be about repairing it") + } + if n := openReservations(t, f, l.RunID); n != 0 { + t.Fatalf("%d reservations are still open after the settlement: the fixture is not in the state this "+ + "test is about", n) + } + + // The crash: the money is closed and the mark is gone. + if _, err := f.store.Pool().Exec(f.ctx, `update runs set settled_at = null where id = $1`, l.RunID); err != nil { + t.Fatal(err) + } + // The control that makes the repair mean something: this run is invisible to the worklist, so + // nothing but the repair could possibly stamp it again. + unsettled, err := f.store.UnsettledRuns(f.ctx, f.now) + if err != nil { + t.Fatal(err) + } + for _, u := range unsettled { + if u.RunID == l.RunID { + t.Fatalf("the run is still on the settlement worklist, so a later pass would settle it the ordinary "+ + "way and this test would pass without any repair existing: %d entries", len(unsettled)) + } + } + + if err := f.svc.Sweep(f.ctx); err != nil { + t.Fatal(err) + } + if at := settledAt(t, f, l.RunID); at == nil { + t.Error("a run whose money had closed is still carrying no settled mark after a full sweep: the column " + + "disagrees with the ledger, and nothing will ever come back to it") + } +} + +// The mirror, and it is what stops the repair from becoming a lie: a LIVE run must not be stamped. +// The mark is a statement about the WHOLE run's money, and a run stamped here would claim a +// resolution its own life contradicts — the next attempt has not spent anything yet. +// +// ⛔ TWO FIXTURES, AND THE SECOND IS THE ONE THAT MATTERS. The repair excludes a live run twice over: +// because it holds an open reservation, and because its own life is not over. The first exclusion +// hides the second — and this test asserted only the first until a mutation showed it: dropping the +// «the run has finished» term left every assertion green, because the fixture's run also had a hold. +// +// The second fixture is the state where the terms come apart, and it is an ORDINARY one rather than a +// corner: BETWEEN ATTEMPTS. The sweep settles the attempt that ended — closing its reservation — and +// then reopens the run with a new one. In that window the run is live and holds nothing, and only +// «has this run finished» keeps the repair off it. +func TestALiveRunIsNeverStampedSettled(t *testing.T) { + t.Run("while its hold is still open", func(t *testing.T) { + f := newFixture(t, "10", 500) + l := spawned(t, f, 100) + f.runner.alive = true + if err := f.svc.Sweep(f.ctx); err != nil { + t.Fatal(err) + } + if n := openReservations(t, f, l.RunID); n != 1 { + t.Fatalf("the live run holds %d open reservations, want 1: the fixture is not in the state this "+ + "test is about, so the assertion below would prove nothing", n) + } + if at := settledAt(t, f, l.RunID); at != nil { + t.Errorf("a live run was stamped settled at %v while its hold is still open", at) + } + }) + t.Run("between attempts, holding nothing at all", func(t *testing.T) { + f := newFixture(t, "10", 500) + l := spawned(t, f, 100) + f.runner.alive = true + // The window the sweep passes through on every restart: the ended attempt's reservation is + // closed and the next one has not been opened. Written straight to the row because what is + // under test is the repair's PREDICATE, not the road by which the state arises. + if _, err := f.store.Pool().Exec(f.ctx, ` + update reservations set state = 'settled', closed_at = now() + where split_part(engine_run_id, '#', 1) = $1 and state = 'open'`, l.RunID); err != nil { + t.Fatal(err) + } + if n := openReservations(t, f, l.RunID); n != 0 { + t.Fatalf("%d reservations are still open: this fixture exists to have NONE, and with one the "+ + "assertion below passes on the wrong term", n) + } + var finished *time.Time + if err := f.store.Pool().QueryRow(f.ctx, `select finished_at from runs where id = $1`, l.RunID). + Scan(&finished); err != nil { + t.Fatal(err) + } + if finished != nil { + t.Fatalf("the run has already finished at %v: the fixture is not «live and holding nothing»", finished) + } + if err := f.svc.Sweep(f.ctx); err != nil { + t.Fatal(err) + } + if at := settledAt(t, f, l.RunID); at != nil { + t.Errorf("a run that is still LIVE was stamped settled at %v because it happened to hold nothing: "+ + "between two attempts every run looks like this, and the mark would claim its money was "+ + "resolved while the next attempt has not spent anything yet", at) + } + }) +}