yuris/spacetimedb-defold

Fork 0

conformance: phase 2 once saw a subscribed payload without the edited row #52

New issue

Open

opened 2026-08-20 06:38:26 +00:00 by yuris · 1 comment

yuris commented

2026-08-20 06:38:26 +00:00

Owner

Split out of #39, which was retitled and closed on what was actually proven (the restart gate returned before the module database had begun opening). This issue carries the part that is still unexplained, named from the symptom rather than from a theory.

The symptom

One conformance run had phase 2 observe a subscribed payload that did not contain the edited row, preceded by a second 1001 disconnect. The original failing log is in #39.

#39's stated mechanism was wrong — this is the most important thing here

#39 said "phase 2 asserts the row is restored within its budget, and the extra round trip can push it past that". There is no phase-2 budget. dev/example/main/smoke.script:218-227 runs the assertion inside evt.type == "subscribed" and self.phase == 2 and checks the cache immediately. The only clock is the 90 s global TIMEOUT at :481-483, which emits a different message.

So the reported failure requires a subscribed payload that lacked the edited row — not a slow one. Anyone chasing a timing budget here is chasing something that does not exist.

Ruled out, with evidence

Recorded so the next occurrence is not re-investigated from zero. Each of these was actively disproved, not merely unobserved.

#39's stated mechanism — phase 2 has no time budget (above).
A partial-replay race — at the bounce exactly one subscription set exists: the legacy subscribe at smoke.script:105; phase 3's subscribe_query at :251 comes strictly after PHASE2 OK.
A gracefully-dying server serving a reconnect — SIGTERM closes the listener within one round trip. Measured: signal at 06:08:03.0423, last 200 on attempt 24, first connection refusal on attempt 25 at .0502 (7.9 ms, one curl iteration), process gone .0539, five further pings all refused. There is no half-open window.
A stale or empty snapshot at the earliest instant — 25 raw JSON-protocol subscribes (author) plus 10 more at the earliest instant TCP accepts, ~800 connect refusals deep, with no SQL probe at all (reviewer): 35/35 returned InitialSubscription with num_rows=1 carrying the correct row, 1–2 ms after onopen. Zero 1001 frames, zero SubscriptionError.
A lost commit — phase 1's edit survived 8/8 SIGKILLs issued immediately after the reducer returned.
The readiness window closed by #50 — measured at ~48 ms, against an SDK reconnect backoff of 1 s base / 30 s cap (stdb/init.lua:140). Three orders of magnitude apart, so #50 cannot have been the cause even though it was a real defect worth fixing.

Status

Not reproducible on demand. 70 unpatched runs green (50 idle, 10 idle, 10 with the client's backoff cut to 20 ms so it retried 28 times per run), plus 26 + 6 green post-#50. One occurrence, one log.

Left open deliberately rather than closed as fixed: #50 did not fix this, and saying otherwise would bury the one real observation under a change that provably cannot explain it.

If it recurs

Capture the raw frames, not just the verdict. The single most diagnostic output is the subscribed payload's num_rows and row contents beside the preceding close frame's code — that distinguishes a server that answered wrongly from a client that read the wrong reply, and nothing in the ruled-out list above covers the former.

Not blocking

Not a v1.0 blocker. dev/ is export-ignored, so this is harness reliability, not shipped behaviour. It is also the reason #16's continue-on-error should stay on the HTML5 CI step until a run has actually passed there.

Split out of #39, which was retitled and closed on what was actually **proven** (the `restart` gate returned before the module database had begun opening). This issue carries the part that is still **unexplained**, named from the symptom rather than from a theory. ## The symptom One conformance run had phase 2 observe a `subscribed` payload that did not contain the edited row, preceded by a second `1001` disconnect. The original failing log is in #39. ## #39's stated mechanism was wrong — this is the most important thing here #39 said *"phase 2 asserts the row is restored within its budget, and the extra round trip can push it past that"*. **There is no phase-2 budget.** `dev/example/main/smoke.script:218-227` runs the assertion inside `evt.type == "subscribed" and self.phase == 2` and checks the cache immediately. The only clock is the 90 s global `TIMEOUT` at `:481-483`, which emits a *different* message. So the reported failure requires a `subscribed` payload that **lacked** the edited row — not a slow one. Anyone chasing a timing budget here is chasing something that does not exist. ## Ruled out, with evidence Recorded so the next occurrence is not re-investigated from zero. Each of these was actively disproved, not merely unobserved. 1. **#39's stated mechanism** — phase 2 has no time budget (above). 2. **A partial-replay race** — at the bounce exactly one subscription set exists: the legacy `subscribe` at `smoke.script:105`; phase 3's `subscribe_query` at `:251` comes strictly after PHASE2 OK. 3. **A gracefully-dying server serving a reconnect** — SIGTERM closes the listener within one round trip. Measured: signal at `06:08:03.0423`, last 200 on attempt 24, first connection refusal on attempt 25 at `.0502` (7.9 ms, one curl iteration), process gone `.0539`, five further pings all refused. There is no half-open window. 4. **A stale or empty snapshot at the earliest instant** — 25 raw JSON-protocol subscribes (author) plus 10 more at the earliest instant TCP accepts, ~800 connect refusals deep, with no SQL probe at all (reviewer): 35/35 returned `InitialSubscription` with `num_rows=1` carrying the correct row, 1–2 ms after `onopen`. Zero `1001` frames, zero `SubscriptionError`. 5. **A lost commit** — phase 1's edit survived 8/8 SIGKILLs issued immediately after the reducer returned. 6. **The readiness window closed by #50** — measured at ~48 ms, against an SDK reconnect backoff of 1 s base / 30 s cap (`stdb/init.lua:140`). Three orders of magnitude apart, so #50 cannot have been the cause even though it was a real defect worth fixing. ## Status Not reproducible on demand. 70 unpatched runs green (50 idle, 10 idle, 10 with the client's backoff cut to 20 ms so it retried 28 times per run), plus 26 + 6 green post-#50. One occurrence, one log. Left open deliberately rather than closed as fixed: **#50 did not fix this**, and saying otherwise would bury the one real observation under a change that provably cannot explain it. ## If it recurs Capture the raw frames, not just the verdict. The single most diagnostic output is the `subscribed` payload's `num_rows` and row contents beside the preceding close frame's code — that distinguishes a server that answered wrongly from a client that read the wrong reply, and nothing in the ruled-out list above covers the former. ## Not blocking Not a v1.0 blocker. `dev/` is export-ignored, so this is harness reliability, not shipped behaviour. It is also the reason **#16's `continue-on-error` should stay on the HTML5 CI step** until a run has actually passed there.

yuris referenced this issue

2026-08-20 07:18:14 +00:00

v1.0.0 release checklist #24

yuris referenced this issue

2026-08-20 11:46:16 +00:00

v1.0.0 release checklist #24

yuris referenced this issue

2026-08-20 13:06:40 +00:00

v1.0.0 release checklist #24

yuris referenced this issue

2026-08-20 13:26:59 +00:00

v1.1.0 release checklist #59

yuris commented

2026-08-20 16:28:58 +00:00

Author

Owner

A possible recurrence during the v1.1.0 release gate — but I cannot attribute it

Recording it because this issue exists so the next occurrence is not investigated
from zero, and because leaving it out would be the same mistake as burying it.

dev/tools/html5-conformance.sh returned [html5] FAIL once on the v1.1.0
release branch. Immediately re-run on the same tree it passed, and three further
back-to-back runs passed. So: 1 failure in 5 runs.

I did not capture the raw frames, which this issue explicitly asks for, so I
cannot say whether it is this bug. Stating that plainly rather than claiming a
match. What I have:

The failing run reached at least PHASE4 on both loads.
No verdict line beyond FAIL; I had filtered the output and lost the detail
before realising it mattered.
The three clean runs took 28, 29 and 28 seconds against the harness's 120s
HTML5_TIMEOUT, so roughly 4× headroom.

That last point matters for one hypothesis worth ruling out explicitly: #66 added
PHASE6 (a 10,000-row bulk subscription, ~127ms of apply on the wasm tier) to the
phase sequence, and html5-conformance.mjs notes the budget is per load rather
than per run. It is not a budget problem — 28s against 120s, and the failing
run was not near the limit either, since a timeout emits its own distinct message
rather than a bare FAIL.

So PHASE6 does not appear to have introduced this, and the ruled-out list above
stands untouched.

Not blocking v1.1.0, for the same reason as before: dev/ is export-ignored,
so this is harness reliability rather than shipped behaviour. It remains the
reason #16's continue-on-error should stay on the HTML5 CI step.

For the next person, including me: the harness output must be captured whole, not
tailed or grepped, or the diagnostic this issue asks for is gone by the time you
notice you need it. Same lesson as the unit runner printing a crash before its
ok lines.

## A possible recurrence during the v1.1.0 release gate — but I cannot attribute it Recording it because this issue exists so the next occurrence is not investigated from zero, and because leaving it out would be the same mistake as burying it. `dev/tools/html5-conformance.sh` returned `[html5] FAIL` once on the v1.1.0 release branch. Immediately re-run on the same tree it passed, and three further back-to-back runs passed. So: **1 failure in 5 runs.** **I did not capture the raw frames**, which this issue explicitly asks for, so I cannot say whether it is this bug. Stating that plainly rather than claiming a match. What I have: - The failing run reached at least PHASE4 on both loads. - No verdict line beyond `FAIL`; I had filtered the output and lost the detail before realising it mattered. - The three clean runs took 28, 29 and 28 seconds against the harness's 120s `HTML5_TIMEOUT`, so roughly 4× headroom. That last point matters for one hypothesis worth ruling out explicitly: #66 added PHASE6 (a 10,000-row bulk subscription, ~127ms of apply on the wasm tier) to the phase sequence, and `html5-conformance.mjs` notes the budget is per load rather than per run. **It is not a budget problem** — 28s against 120s, and the failing run was not near the limit either, since a timeout emits its own distinct message rather than a bare `FAIL`. So PHASE6 does not appear to have introduced this, and the ruled-out list above stands untouched. **Not blocking v1.1.0**, for the same reason as before: `dev/` is export-ignored, so this is harness reliability rather than shipped behaviour. It remains the reason #16's `continue-on-error` should stay on the HTML5 CI step. For the next person, including me: the harness output must be captured whole, not tailed or grepped, or the diagnostic this issue asks for is gone by the time you notice you need it. Same lesson as the unit runner printing a crash *before* its `ok` lines.

yuris referenced this issue

2026-08-20 16:29:16 +00:00

release: v1.1.0 #70

yuris referenced this issue

2026-08-20 16:31:55 +00:00

v1.1.0 release checklist #59

yuris referenced this issue

2026-08-20 16:38:41 +00:00

HTML5 conformance in CI: prove Chromium runs in the job container #16

~~yuris referenced this issue 2026-08-21 02:17:41 +00:00~~

Developer experience and documentation #77