Make unknown-job sweep tests deterministic after platform-storage PR 6 (CI incident evidence) #662

New issue

Closed

opened 2026-10-16 08:21:57 +00:00 by toasterson · 0 comments

toasterson commented

2026-10-16 08:21:57 +00:00

Owner

Evidence: three reported CI incidents, distinct causes

The operator asked to preserve all three incidents. Original runner logs establish that these are not three occurrences of the same sweep failure:

PR / head	Run / job	Actual failure
#654 `b754b16761f01cff446b2bbb8211e8906b93d347`	UI 4287 / test-session-platform, API run 9955, job 31981	`runtime::tests::sweep_closes_a_job_unknown_past_the_stall_threshold_and_only_that_one`, runtime.rs:2273: actual `["fresh", "stale"]`, expected `["stale"]`; 170 passed / 1 failed / 6 ignored.
#654 `6b3f821ec5b72417e4ae13582cec5c1c8b3dc76b`	UI 4288, API run 9956, job 31999 (`test-akh-medu`)	Different flake: `thinking::tests::analogy_goal_recovers_structured_binding`, src/thinking/mod.rs:360: actual `Some(SymbolId(16))`, expected `Some(SymbolId(14))`, `halt=DiminishingReturns { marginal_value: -0.05 }`. The platform/sweep suite passed on this retry.
#661 `e0831dfeb6b7d7915bcc3bf69866cfe0cd2337bc`	UI 4303 / test-session-platform, API run 9972, job 32210	Different contention test: `tests::sqlite_independent_connections_serialize_admission`, crates/akh-service-store/src/lib.rs:318, worker `unwrap()` saw `Fault { code: "storage_error", message: "database is locked" }`; parent join failed at line 324. 23 passed / 1 failed. The earlier platform suite passed 171 / 0 / 6, including sweep. This SQLite fixture is being fixed on #661 with explicit lock/release coordination; production busy timeout stays unchanged.

Expanded Forgejo UI logs contained repeated/misassigned output; attribution comes from the original Solstice per-step logs, not inference from job names:

Sweep: request d24f9843-fe16-479b-8983-54ff0fc8499b, Forgejo task 37054, step:verify-independent-daemon-profiles-and-platform-contracts, seq 222–240.
Analogy: request 8e5c211a-a39c-4cc3-8d2f-8b07451e7189, task 37072, core library test step, seq 255–271.
SQLite: request 530e731e-096c-4ea4-b4a4-8fb907a81ef1, task 37266, step:verify-service-store-and-private-slot-contracts-with-disposable-postgres-and-openbao, seq 924–955. Failure occurred 2026-10-16 08:17 UTC. The same run's earlier broad platform step completed successfully.

#654 eventually passed all 14 jobs in UI 4289 / API 9958 at d41d5ed46563b97efa049bbc29aa355692d1da9c, with the same code tree as b754b167. This supports nondeterminism; it does not prove the analogy's root cause.

Proposed real sweep fix

Current sweep/test source.

Factor the synchronous sweep into a private resolve_stale_unknown_jobs_at(now_ms) (or inject a clock). Keep the public production wrapper reading the real clock once and passing it through.
Use that same supplied timestamp when initializing a missing unknown_since record. Do not mix a fixed test clock with an internal now_ms() call.
Seed fixed timestamps and invoke the sweep at a fixed instant. Check below-threshold, exact-threshold and past-threshold cases, active-worker exclusion, Internal/disposable-profile exclusion, missing clock initialization, repeat sweep and archival/clock cleanup. Preserve unknown-outcome semantics.
For genuinely asynchronous adjacent tests, wait for explicit worker/commit events with bounded failure guards rather than relying on sleeps. tokio::time::pause alone does not control a wall-clock/SystemTime now_ms() implementation.
Run the targeted runtime tests under the CI feature set and repeated concurrent load. Results must not depend on runner scheduling or disk latency. Do not widen the 1,000 ms fixture threshold or the production timeout.

Keep this follow-up scoped to the sweep/clock contract. The analogy failure needs independent deterministic search/seed/order investigation; do not claim this clock fix repairs it. SQLite admission coverage is addressed in #661 using channels and an immediate test-only lock probe, not longer production waiting.

SQLite incident follow-up

The SQLite admission fixture fix is pushed on #661 as c62371a0. All 24 service-store library tests and 20 coordinated admission trials (four concurrent test processes) passed locally. It changes test coordination only; the production five-second busy timeout is unchanged. Whole-run CI is being checked in UI 4304. This does not close the separate sweep-clock follow-up requested after PR 6.

CI confirmation: all 15/15 jobs passed in run 4304 at c62371a0037bd22fd549e482c8836ee41f285ce9, including the revised SQLite fixture and complete storage harness. The sweep-clock follow-up remains open for after PR 6.

The unknown-job sweep unit test depends on elapsed wall time between fixture writes, redb commit, runtime construction and the sweep. A loaded runner can legitimately age the supposedly fresh job past the 1,000 ms threshold, producing a false CI failure. Fix this in a separate small PR **after platform-storage PR 6**, without widening a timeout, disabling assertions or changing runtime expiry policy. ## Evidence: three reported CI incidents, distinct causes The operator asked to preserve all three incidents. Original runner logs establish that these are **not three occurrences of the same sweep failure**: | PR / head | Run / job | Actual failure | | --- | --- | --- | | #654 `b754b16761f01cff446b2bbb8211e8906b93d347` | [UI 4287 / test-session-platform](https://code.aopc.cloud/toasterson/akh-medu/actions/runs/4287/jobs/0), API run 9955, job 31981 | `runtime::tests::sweep_closes_a_job_unknown_past_the_stall_threshold_and_only_that_one`, runtime.rs:2273: actual `["fresh", "stale"]`, expected `["stale"]`; 170 passed / 1 failed / 6 ignored. | | #654 `6b3f821ec5b72417e4ae13582cec5c1c8b3dc76b` | [UI 4288](https://code.aopc.cloud/toasterson/akh-medu/actions/runs/4288), API run 9956, job 31999 (`test-akh-medu`) | **Different flake:** `thinking::tests::analogy_goal_recovers_structured_binding`, src/thinking/mod.rs:360: actual `Some(SymbolId(16))`, expected `Some(SymbolId(14))`, `halt=DiminishingReturns { marginal_value: -0.05 }`. The platform/sweep suite passed on this retry. | | #661 `e0831dfeb6b7d7915bcc3bf69866cfe0cd2337bc` | [UI 4303 / test-session-platform](https://code.aopc.cloud/toasterson/akh-medu/actions/runs/4303/jobs/0), API run 9972, job 32210 | **Different contention test:** `tests::sqlite_independent_connections_serialize_admission`, crates/akh-service-store/src/lib.rs:318, worker `unwrap()` saw `Fault { code: "storage_error", message: "database is locked" }`; parent join failed at line 324. 23 passed / 1 failed. The earlier platform suite passed 171 / 0 / 6, including sweep. This SQLite fixture is being fixed on #661 with explicit lock/release coordination; production busy timeout stays unchanged. | Expanded Forgejo UI logs contained repeated/misassigned output; attribution comes from the original Solstice per-step logs, not inference from job names: - Sweep: request `d24f9843-fe16-479b-8983-54ff0fc8499b`, Forgejo task 37054, `step:verify-independent-daemon-profiles-and-platform-contracts`, seq 222–240. - Analogy: request `8e5c211a-a39c-4cc3-8d2f-8b07451e7189`, task 37072, core library test step, seq 255–271. - SQLite: request `530e731e-096c-4ea4-b4a4-8fb907a81ef1`, task 37266, `step:verify-service-store-and-private-slot-contracts-with-disposable-postgres-and-openbao`, seq 924–955. Failure occurred 2026-10-16 08:17 UTC. The same run's earlier broad platform step completed successfully. #654 eventually passed all 14 jobs in [UI 4289 / API 9958](https://code.aopc.cloud/toasterson/akh-medu/actions/runs/4289) at `d41d5ed46563b97efa049bbc29aa355692d1da9c`, with the same code tree as `b754b167`. This supports nondeterminism; it does not prove the analogy's root cause. ## Proposed real sweep fix [Current sweep/test source](https://code.aopc.cloud/toasterson/akh-medu/src/commit/e0831dfeb6b7d7915bcc3bf69866cfe0cd2337bc/crates/akh-session-services/src/runtime.rs). 1. Factor the synchronous sweep into a private `resolve_stale_unknown_jobs_at(now_ms)` (or inject a clock). Keep the public production wrapper reading the real clock once and passing it through. 2. Use that same supplied timestamp when initializing a missing `unknown_since` record. Do not mix a fixed test clock with an internal `now_ms()` call. 3. Seed fixed timestamps and invoke the sweep at a fixed instant. Check below-threshold, exact-threshold and past-threshold cases, active-worker exclusion, Internal/disposable-profile exclusion, missing clock initialization, repeat sweep and archival/clock cleanup. Preserve unknown-outcome semantics. 4. For genuinely asynchronous adjacent tests, wait for explicit worker/commit events with bounded failure guards rather than relying on sleeps. `tokio::time::pause` alone does not control a wall-clock/SystemTime `now_ms()` implementation. 5. Run the targeted runtime tests under the CI feature set and repeated concurrent load. Results must not depend on runner scheduling or disk latency. Do not widen the 1,000 ms fixture threshold or the production timeout. Keep this follow-up scoped to the sweep/clock contract. The analogy failure needs independent deterministic search/seed/order investigation; do not claim this clock fix repairs it. SQLite admission coverage is addressed in #661 using channels and an immediate test-only lock probe, not longer production waiting. ## SQLite incident follow-up The SQLite admission fixture fix is pushed on #661 as [`c62371a0`](https://code.aopc.cloud/toasterson/akh-medu/commit/c62371a0037bd22fd549e482c8836ee41f285ce9). All 24 service-store library tests and 20 coordinated admission trials (four concurrent test processes) passed locally. It changes test coordination only; the production five-second busy timeout is unchanged. Whole-run CI is being checked in [UI 4304](https://code.aopc.cloud/toasterson/akh-medu/actions/runs/4304). This does not close the separate sweep-clock follow-up requested after PR 6. CI confirmation: all 15/15 jobs passed in [run 4304](https://code.aopc.cloud/toasterson/akh-medu/actions/runs/4304) at `c62371a0037bd22fd549e482c8836ee41f285ce9`, including the revised SQLite fixture and complete storage harness. The sweep-clock follow-up remains open for after PR 6.

toasterson referenced this issue

2026-10-16 08:23:34 +00:00

feat(sharing): Postgres companion and verified link migration (PR 5/9) #661

toasterson referenced this issue from a pull request that will close it,

2026-10-16 09:49:06 +00:00

fix(runtime): make unknown-job sweep tests deterministic #663

toasterson closed this issue

2026-10-16 10:24:36 +00:00