dev-server: gate restart on the database serving, not the port answering #50

Merged
yuris merged 1 commit from feat/39-readiness into main 2026-08-20 06:37:08 +00:00
Owner

Addresses #39. Read the falsifiability section before the fix — the flake did not reproduce, and this PR does not claim to have fixed it.

What is proven

wait_ready polled /v1/ping for a 200, which proves the HTTP port answers and nothing else. One restart, one clock:

05:00:26.3229  ping returns 200          <- the old probe returned here
05:00:26.3295  module replica lock
05:00:26.3361  transaction history replayed
05:00:26.3367  host launched
05:00:26.3630  trivial SELECT returns 200 <- the database can actually serve

The old probe returned ~14 ms before the database took its lock and 40 ms before it could serve a query. So the probe asserted strictly less than the harness depends on. That is worth closing on its own merits, independent of whether it was the cause of anything.

Why asking is the mechanism: the module database opens lazily, on the first request that names it. Control run — restart, poll /v1/ping only, deliberately issue no SQL for 3 s — and the entire server log for that window is one line, Starting SpacetimeDB listening. No replica lock, no transaction history, no module launch. So the table above is not a fixed boot sequence: the lock, replay and launch land where they do because a poller is already asking. Read it as "ping 200 is ~30-40 ms ahead of a served query".

And that ~40 ms is a move, not a cost. Measured client-side on one server with one restart procedure, only the gate differing: a client subscribing at the earliest instant the port accepts pays 47-51 ms inside its WebSocket handshake (n=10); behind the gate, 2-3 ms (n=5). Every sample got the correct row, no close frames. restart grows by roughly what the reconnecting client stops paying, and the client is the one on a clock.

What is not proven

I could not reproduce #39's flake, so there is no before/after. 70 unpatched runs, all green: 50 idle, 10 more idle, and 10 with the client's backoff cut to 20 ms so it made 28 reconnect attempts per run instead of 1.

Three candidate mechanisms were actively disproved, not merely unobserved:

  1. A reopening database serving a stale or empty snapshot — 25 raw JSON-protocol subscribes fired at the earliest instant the port accepted, plus 10 harness runs retrying every 20 ms, all got the row. /subscribe waits for the host too.
  2. A gracefully-dying server serving a reconnect — SIGTERM closes the listener immediately; connections are refused from the first attempt.
  3. A lost commit — phase 1's edit survived 8/8 SIGKILLs issued immediately after the reducer returned.

So this narrows the probe to what the test actually needs, and the code comment says exactly that so nobody over-trusts it.

The change

Two gates. wait_port keeps the old ping loop. A new wait_ready polls SELECT * FROM message LIMIT 0 against /v1/database/$DB/sql and returns only on 200 — it cannot answer until the datastore is open and the schema resolvable, and asking is what forces that open to happen inside the restart rather than on the reconnecting client's path.

Only restart asks for it. Cold start deliberately gates on the port alone: there is no database to query yet, and the publish that follows is itself a database operation, so it is the cold path's own gate. The cold start's readiness gate is unchanged — but its behaviour is not byte-identical, because the cold path also picked up the pre-spawn stray-server check below: one extra HTTP request and a new refusal path, measured at 15 ms.

Restart cost went from ~0.52 s to ~0.56 s, against the 47 ms → 2 ms taken off the reconnecting client's handshake above. After the patch, restart returned after the new server's lock, replay and host launch, and the first query issued afterwards was 200 on the first try.

A second bug the new gate exposed

The stray-server refusal was useless where it stood. A stray answers ping on our behalf, and our doomed child spends ~250 ms printing and abandoning the CLI's use port 5242 instead? [y/N] prompt — stdin is not a TTY under the harness, so it reads EOF and dies rather than hanging there — which is long enough to pass kill -0. With a stray answering, wait_port's first curl returns 200 in 5-10 ms, so the liveness check ran ~240 ms before the child died and could never fire. The refusal now runs ahead of the spawn; the post-spawn liveness check is kept for the narrow race.

Measured: with a foreign server holding the port, restart and start now refuse in 17 ms / 14 ms. Before the move, the same scenario took 31 s and ended in a misleading database never served a query message.

Three more fixes, from review

The post-spawn refusal deleted someone else's pidfile. Two invocations racing on a free port both pass the pre-spawn check and both spawn; the loser reaches the post-spawn refusal with the winner's pid in server.pid, and the unconditional rm -f there stripped a live, correctly-published server of its only record. Reproduced on a fresh state dir, port 5350: winner rc 0 with Created new database with name: chat, loser rc 1 with our server died immediately, server.pid absent, listener still up and answering /v1/ping and the SQL probe 200 — after which stop says no server running and leaks it, and restart refuses with no server of ours is running, which is false and needs a manual pkill to escape. Now guarded on the pid matching. The same race on port 5351 after the fix leaves server.pid present holding the winner's pid, and restart (rc 0) and stop both work. The ordinary refusal still removes its own pidfile — checked with a shim server that exits after handing the port to a bare HTTP responder, so the recorded pid is genuinely dead. Pre-existing on main, fixed here because the section above is precisely about racing invocations.

The gate threw away the server's own diagnosis. The probe wrote to /dev/null, so a module whose message table is missing bought 31 s of polling and then last status 400 explained by a sentence about 404, with nothing useful in the log tail — a SQL-layer rejection is never written to the server log. The probe now writes $STATE/probe.out and the failure path prints its first 200 bytes; the 404 hint is printed only on an actual 404. Against a scratch module with the table renamed:

[dev-server] http://127.0.0.1:5355 answers but database 'chat' never served a query (last status 400).
[dev-server] last response: no such table: `message`. If the table exists, it may be marked private.

and a fresh state dir with nothing published still gets last response: `chat` not found plus the 404 hint. The retry loop is deliberately kept: a 4xx arriving during the lazy open cannot be told apart from a permanent one here, and bailing early would trade a legibility bug for a new flake.

A crash during the gate exited 7 in silence. code=$(curl ...) is a bare assignment, so under set -e a server that stopped accepting connections mid-gate — a crash, a stolen port — aborted the whole script with exit 7 and not one line of output, indistinguishable from a harness bug. Reproduced in isolation against a closed port; now || true, so the loop runs to its timeout and prints the diagnosis it was written to print.

Verification

6 passed, 0 failed; stylua clean. 26 consecutive native runs on the patched tree, 0 failures. HTML5 PASS including PHASE5 on both loads. No fixture drift — conformance's re-derive/diff passed in every run.

Re-run after the review fixes: unit suite 6 passed, 0 failed, stylua --check stdb dev/test clean, and 7 more consecutive native conformance runs (own port and state dir), all EXIT 0, each PASS on both loads including PHASE2, PHASE5 and the identity-persistence assertion, git status --porcelain carrying nothing but dev/tools/dev-server.sh after every one.

HTML5 needs no separate treatment: html5-conformance.mjs:150 bounces the server through the same dev-server.sh restart, so the new gate applies unchanged. Confirmed by a PASS run whose log shows the restart followed by PHASE2/PHASE5 OK on both loads.

Known ceiling, tested: restart before anything is published fails after 31 s with database 'chat' never served a query (last status 404), last response: `chat` not found, and the line naming the cause. Left as a self-explaining failure rather than adding a pre-bounce existence probe.

Explicitly not done

#16's continue-on-error should not come off on the strength of this. The causal link is unproven, and saying otherwise would be exactly the over-trust this PR's comment warns against.

The message table name is hardcoded in the probe rather than made configurable — dev/server/index.js declares it byte-frozen, so its absence would be a real failure worth surfacing. No SDK-side jitter or backoff tuning; the client's 1 s backoff is untouched.

Addresses #39. **Read the falsifiability section before the fix — the flake did not reproduce, and this PR does not claim to have fixed it.** ## What is proven `wait_ready` polled `/v1/ping` for a 200, which proves the HTTP port answers and nothing else. One restart, one clock: ``` 05:00:26.3229 ping returns 200 <- the old probe returned here 05:00:26.3295 module replica lock 05:00:26.3361 transaction history replayed 05:00:26.3367 host launched 05:00:26.3630 trivial SELECT returns 200 <- the database can actually serve ``` The old probe returned ~14 ms before the database took its lock and **40 ms before it could serve a query**. So the probe asserted strictly less than the harness depends on. That is worth closing on its own merits, independent of whether it was the cause of anything. **Why *asking* is the mechanism: the module database opens lazily, on the first request that names it.** Control run — restart, poll `/v1/ping` only, deliberately issue no SQL for 3 s — and the entire server log for that window is one line, `Starting SpacetimeDB listening`. No replica lock, no transaction history, no module launch. So the table above is not a fixed boot sequence: the lock, replay and launch land where they do *because a poller is already asking*. Read it as "ping 200 is ~30-40 ms ahead of a served query". **And that ~40 ms is a move, not a cost.** Measured client-side on one server with one restart procedure, only the gate differing: a client subscribing at the earliest instant the port accepts pays **47-51 ms inside its WebSocket handshake** (n=10); behind the gate, **2-3 ms** (n=5). Every sample got the correct row, no close frames. `restart` grows by roughly what the reconnecting client stops paying, and the client is the one on a clock. ## What is not proven **I could not reproduce #39's flake, so there is no before/after.** 70 unpatched runs, all green: 50 idle, 10 more idle, and 10 with the client's backoff cut to 20 ms so it made 28 reconnect attempts per run instead of 1. Three candidate mechanisms were actively **disproved**, not merely unobserved: 1. *A reopening database serving a stale or empty snapshot* — 25 raw JSON-protocol subscribes fired at the earliest instant the port accepted, plus 10 harness runs retrying every 20 ms, all got the row. `/subscribe` waits for the host too. 2. *A gracefully-dying server serving a reconnect* — SIGTERM closes the listener immediately; connections are refused from the first attempt. 3. *A lost commit* — phase 1's edit survived 8/8 SIGKILLs issued immediately after the reducer returned. So this narrows the probe to what the test actually needs, and the code comment says exactly that so nobody over-trusts it. ## The change Two gates. `wait_port` keeps the old ping loop. A new `wait_ready` polls `SELECT * FROM message LIMIT 0` against `/v1/database/$DB/sql` and returns only on 200 — it cannot answer until the datastore is open and the schema resolvable, and *asking* is what forces that open to happen inside the restart rather than on the reconnecting client's path. **Only `restart` asks for it.** Cold start deliberately gates on the port alone: there is no database to query yet, and the publish that follows is itself a database operation, so it is the cold path's own gate. The cold start's **readiness gate** is unchanged — but its behaviour is not byte-identical, because the cold path also picked up the pre-spawn stray-server check below: one extra HTTP request and a new refusal path, measured at 15 ms. Restart cost went from ~0.52 s to ~0.56 s, against the 47 ms → 2 ms taken off the reconnecting client's handshake above. After the patch, `restart` returned *after* the new server's lock, replay and host launch, and the first query issued afterwards was 200 on the first try. ## A second bug the new gate exposed The stray-server refusal was **useless where it stood**. A stray answers ping on our behalf, and our doomed child spends ~250 ms printing and abandoning the CLI's `use port 5242 instead? [y/N]` prompt — stdin is not a TTY under the harness, so it reads EOF and dies rather than hanging there — which is long enough to pass `kill -0`. With a stray answering, `wait_port`'s first curl returns 200 in 5-10 ms, so the liveness check ran ~240 ms before the child died and could never fire. The refusal now runs *ahead* of the spawn; the post-spawn liveness check is kept for the narrow race. Measured: with a foreign server holding the port, `restart` and `start` now refuse in 17 ms / 14 ms. Before the move, the same scenario took 31 s and ended in a misleading *database never served a query* message. ## Three more fixes, from review **The post-spawn refusal deleted someone else's pidfile.** Two invocations racing on a free port both pass the pre-spawn check and both spawn; the loser reaches the post-spawn refusal with the **winner's** pid in `server.pid`, and the unconditional `rm -f` there stripped a live, correctly-published server of its only record. Reproduced on a fresh state dir, port 5350: winner `rc 0` with `Created new database with name: chat`, loser `rc 1` with `our server died immediately`, `server.pid` absent, listener still up and answering `/v1/ping` and the SQL probe 200 — after which `stop` says `no server running` and leaks it, and `restart` refuses with `no server of ours is running`, which is false and needs a manual `pkill` to escape. Now guarded on the pid matching. The same race on port 5351 after the fix leaves `server.pid` present holding the winner's pid, and `restart` (`rc 0`) and `stop` both work. The ordinary refusal still removes its own pidfile — checked with a shim server that exits after handing the port to a bare HTTP responder, so the recorded pid is genuinely dead. Pre-existing on `main`, fixed here because the section above is precisely about racing invocations. **The gate threw away the server's own diagnosis.** The probe wrote to `/dev/null`, so a module whose `message` table is missing bought 31 s of polling and then `last status 400` explained by a sentence about 404, with nothing useful in the log tail — a SQL-layer rejection is never written to the server log. The probe now writes `$STATE/probe.out` and the failure path prints its first 200 bytes; the 404 hint is printed only on an actual 404. Against a scratch module with the table renamed: ``` [dev-server] http://127.0.0.1:5355 answers but database 'chat' never served a query (last status 400). [dev-server] last response: no such table: `message`. If the table exists, it may be marked private. ``` and a fresh state dir with nothing published still gets ``last response: `chat` not found`` plus the 404 hint. The retry loop is deliberately kept: a 4xx arriving during the lazy open cannot be told apart from a permanent one here, and bailing early would trade a legibility bug for a new flake. **A crash during the gate exited 7 in silence.** `code=$(curl ...)` is a bare assignment, so under `set -e` a server that stopped accepting connections mid-gate — a crash, a stolen port — aborted the whole script with exit 7 and not one line of output, indistinguishable from a harness bug. Reproduced in isolation against a closed port; now `|| true`, so the loop runs to its timeout and prints the diagnosis it was written to print. ## Verification `6 passed, 0 failed`; stylua clean. 26 consecutive native runs on the patched tree, 0 failures. HTML5 PASS including PHASE5 on both loads. No fixture drift — conformance's re-derive/diff passed in every run. Re-run after the review fixes: unit suite `6 passed, 0 failed`, `stylua --check stdb dev/test` clean, and 7 more consecutive native conformance runs (own port and state dir), all `EXIT 0`, each PASS on both loads including PHASE2, PHASE5 and the identity-persistence assertion, `git status --porcelain` carrying nothing but `dev/tools/dev-server.sh` after every one. **HTML5 needs no separate treatment**: `html5-conformance.mjs:150` bounces the server through the same `dev-server.sh restart`, so the new gate applies unchanged. Confirmed by a PASS run whose log shows the restart followed by PHASE2/PHASE5 OK on both loads. Known ceiling, tested: `restart` before anything is published fails after 31 s with `database 'chat' never served a query (last status 404)`, ``last response: `chat` not found``, and the line naming the cause. Left as a self-explaining failure rather than adding a pre-bounce existence probe. ## Explicitly not done **#16's `continue-on-error` should not come off on the strength of this.** The causal link is unproven, and saying otherwise would be exactly the over-trust this PR's comment warns against. The `message` table name is hardcoded in the probe rather than made configurable — `dev/server/index.js` declares it byte-frozen, so its absence would be a real failure worth surfacing. No SDK-side jitter or backoff tuning; the client's 1 s backoff is untouched.
dev-server: gate restart on the database serving, not the port answering
All checks were successful
ci / ci (pull_request) Successful in 19s
c393498f64
`wait_ready` polled /v1/ping, which proves only that the HTTP listener is up.
Timed against one restart on one clock that is 40ms early: the port answers at
.3229 while the module database takes its replica lock at .3295, finishes
replaying its transaction history at .3361 and launches its host at .3367, and
a trivial SELECT does not come back until .3630. `dev-server.sh restart`
therefore returned while the database the reconnecting client is about to
subscribe against was still opening - the gap #39 names, under an assertion
(phase 2: the row survived the bounce) that depends on the difference.

So readiness is two gates now. `wait_port` keeps the old ping loop, and
`wait_ready` polls `SELECT * FROM message LIMIT 0` against the module: it cannot
answer 200 until the datastore is open and the schema resolvable, and asking is
also what forces that open to happen inside the restart rather than on the
reconnecting client's critical path. Only `restart` asks for it. A cold start has
no database to query yet, and the publish that follows is itself a database
operation - it cannot succeed against a server that is not serving - so the cold
path keeps its own gate and behaves exactly as before.

Both harnesses bounce the server through this same `restart`, so the native and
the HTML5 runs are covered by the one change; neither harness needed touching.

The stray-server refusal moved ahead of the spawn, because the new gate made its
old placement useless: a stray answers /v1/ping on our behalf, and our doomed
child can sit at the CLI's "use port 5242 instead? [y/N]" prompt long enough to
pass the liveness check under it. Measured, a `restart` against a held port then
spent 31s arriving at a misleading "the database never served a query"; it now
refuses in 17ms with the message that names the cause. The liveness check stays
for the narrow race where the stray appears after the pre-check.

Honest about the flake itself: 70 unpatched runs here, ten of them with the
client retrying every 20ms instead of every second, produced zero failures, and
no experiment could make a reopening server serve a bad snapshot - /subscribe
evidently waits for the host as well, and a commit survives even SIGKILL. This
closes a readiness gap that is real and measured, and 26 patched runs plus an
HTML5 run pass, but it is not proof that #39's 1-in-8 failure had this cause.
#16's continue-on-error should not come off on the strength of it.
Author
Owner

Review — automated reviewer, posted for the record

Verdict: APPROVE — merge. The change is justified independently of #39. No blockers. 3 should-fix (all wording/legibility), 2 nits. Do NOT close #39 on merge.

Is a change justified at all?

Yes, on three independent grounds, none of which depend on #39

  • MEASUREMENT (15 samples, my clock): the WS handshake is where a reconnecting client pays for the datastore open. No gate (subscribe at earliest TCP accept, n=10): open()->onopen = 47-51 ms. Gate first (SQL 200 then subscribe, n=5): 2-3 ms. The ~48 ms does not vanish, it moves from the client into restart. 15/15 got the correct row, 0 close frames, 0 SubscriptionError.
  • THE DATABASE OPEN IS LAZY — the load-bearing fact nobody wrote down. Control run: restart, poll /v1/ping only, issue NO SQL for 3 s. The entire server log for that window is one line, Starting SpacetimeDB listening. No replica lock, no applying transaction history, no launching module. The module database does not open at boot; it opens on the first request that names it. So the code comment's 'asking is also what FORCES that open to happen here' (:70-73) is literally true and is the real justification.
  • GUARD MOVE: bare stray holding :5303. Pre-move variant (patched minus the pre-spawn block) restart = rc 1 after 31.69 s with database 'chat' never served a query (last status 404). Patched: restart rc 1 in 16 ms, start rc 1 in 15 ms, correct message. Author reported 31 s / 17 ms / 14 ms — reproduced within noise.

Re-derived measurement

ordering — CONFIRMED. Own run: spawn 05:55:47.9322 | log 'listening' .9926 | log 'Acquired lock on data/replicas/1/db.lock' .9945 | ping 200 .9959 | log 'applied transaction history' 06:...48.0003 | log 'launching module' .0015 | SQL 200 (11th attempt) .0243. ping-200 -> SQL-200 gap = 28.4 ms (author: ~40 ms; same order, same sign).

caveat_on_the_authors_table — lock/replay/launch land where they do relative to ping only because a poller is already asking. In my run the lock PRECEDED ping-200 by 1.4 ms for exactly that reason. The table should be read as 'ping 200 is ~30-40 ms ahead of a served query', not as a fixed boot sequence.

restart_waits_for_the_host — CONFIRMED on the patched script: restart returned 06:03:28.4454, i.e. 23 ms AFTER launching module at .4223. The first query afterwards was 200 on attempt 1, no retry.

disproof_spotcheck_SIGTERM — VERIFIED. Tight ping loop with SIGTERM delivered mid-loop: signal at 06:08:03.0423, attempt 24 was the last 200, attempt 25 the first 000 at .0502 (7.9 ms = one curl iteration), process gone .0539, five further pings all 000. The listener closes at signal delivery; there is no half-open window. Author's disproof #2 stands as written.

disproof_spotcheck_stale_snapshot — Independently reproduced at a TIGHTER instant than the author's. 10 restarts, each subscribing at the earliest instant TCP accepts (~800 connect refusals deep), NO SQL probe at all: 10/10 InitialSubscription with num_rows=1 carrying the correct row, 1-2 ms after onopen. No 1001, no SubscriptionError, no close. Also ruled out my own added hypothesis (server closing the socket with 1001 during the open window).

Two-gate split

cold_start_identical — Gate identical, BEHAVIOUR NOT. main: keygen -> spawn -> wait_ready(ping) -> kill -0. Patched no-arg: keygen -> NEW pre-spawn ping guard -> spawn -> wait_port(same loop) -> kill -0 -> skip wait_ready. Cold path gained one HTTP request and a whole new refusal path. Measured cold-path refusal myself at 15 ms. Fresh-state cold start: rc 0, 407 ms, guard does not misfire, stdout exactly 2 lines (BASE+TOKEN) = conformance.sh's contract. Second start adopts in 129 ms. Owned restart 577 ms (author: ~0.56 s).

timeout_path — Sane. 120 x 0.25 s ~= 31 s, same shape and budget as the pre-existing wait_port. Engine TIMEOUT is 90 s (smoke.script:35), so a gate stall is reported by dev-server before the engine gives up. set -e correctly suppressed the misleading server back up at $BASE line on failure.

restart_before_publish_message — ACCURATE TO THE SECOND AND THE STATUS CODE. Fresh state dir, restart: rc 1 at 31.35 s, database 'chat' never served a query (last status 404) + A permanent 404 means nothing is published into ... : start without 'restart'. The advice is correct for this case. Side effect (nit, pre-existing shape): the failed restart leaves the spawned server running with a valid pidfile; self-healing because the next plain start adopts it, which is what the message tells you to do, but undocumented.

empty_database — PASSES. message was empty for every §1 run ("rows":[]). SELECT * FROM message LIMIT 0 returns 200 with a schema envelope and zero rows. No hang, no false negative.

renamed_or_dropped_message_table — SHOULD-FIX, legibility. Measured: missing table -> 400 with body no such table: `msg`. If the table exists, it may be marked private.; missing database -> 404 `nosuchdb` not found; during the lazy-open window -> 000 (curl cannot connect), never a 4xx. The probe uses -o /dev/null (:89), so the server's own one-line diagnosis is DISCARDED. On a renamed message the operator waits 31 s and gets last status 400 explained by a sentence about 404, with no mention of the table; the tail -20 $LOGFILE does not help because a SQL-layer rejection is never written to the server log (verified). Fix: -o "$STATE/probe.out" and log its first 200 bytes on the failure path. Do NOT bail early on 4xx — I could not establish that a 404 is never transient on this path, and an early bail would trade a legibility bug for a new flake.

sql_200_vs_subscribe_THE_SUBSTANTIVE_RISK — RESOLVED: neither implies the other; both simply force and await the same lazy open, so /subscribe is SELF-GATING. Proof: subscribe at the earliest instant TCP accepts with no SQL anywhere returned the correct row 1 ms after handshake, 53 ms after spawn, with the datastore never opened by anything else — and the intermediate SQL statuses in the same window are 000, never 4xx, i.e. the first request naming the database BLOCKS through the open and then answers correctly. So the gate is a BETTER PROXY, NOT A PROOF, and subscribe never needed it. That is consistent with and explains the author's inability to reproduce #39. The gate's real, defensible value is the 48 ms it moves off the client's handshake — which is what the code comment claims and nothing more.

Stray-guard move

old_failure_mode_reproduced — YES, twice over. (a) Post-spawn liveness check was mechanically incapable of firing: with port 5301 held, the doomed child lived 254 ms (spawn 06:05:38.664, gone .918) while wait_port's FIRST curl returns 200 in ~5-10 ms against the stray, so kill -0 runs ~240 ms early and ALWAYS passes. (b) Pre-move variant against a bare stray: rc 1 after 31.69 s with the misleading never served a query message.

framing_correction_nit — With stdin not a TTY — which is how conformance.sh runs it — the child does not sit at the [y/N] prompt; it gets EOF and exits in ~250 ms. The prompt is still what buys those 250 ms, so ':116' "long enough to pass the liveness check" is accurate, but "can sit at the CLI's prompt" suggests an interactive hang that does not occur in the harness. Also, in the pre-move failure the truth WAS on screen: tail -20 $LOGFILE printed the child's Port 5303 is already in use., buried under the CLI's ASCII-art banner. "Misleading" is fair for the two headline log lines; "baffling" overstates it slightly.

legitimate_cases_not_broken —

  • our_own_server_already_running: OK. server_pid succeeds at :200, start_server is never called, guard never runs. Adopts + republishes in 3.8 s (orphan from the failed restart) and 129 ms (fresh).
  • restart_of_a_server_we_own: OK. rc 0 in 577 ms, server back up, host launched before return, first query 200 on attempt 1.
  • two_racing_invocations: Safe but exposes a latent bug — see should_fix_2. inv1 won and published (rc 0); inv2's post-spawn refusal fired (rc 1) rather than publishing into inv1's database, so the property that matters held. This is exactly the case the new comment at :136-139 claims the post-spawn check is kept for — confirmed: the post-spawn check earns its keep here and the pre-spawn guard could not have helped.

Findings

  • should-fix — PR body, 'The change' section
    • "Cold-start behaviour is byte-identical to before." It is not — the cold path gained the pre-spawn ping guard, one extra HTTP request and a new refusal path. The body contradicts itself two paragraphs later ('restart and start now refuse in 17 ms / 14 ms') and I measured the cold-path refusal at 15 ms.
    • Fix: Say "cold start's readiness GATE is unchanged". This matters because 'byte-identical' is exactly the sentence a reviewer trusts instead of re-deriving.
  • should-fix — dev/tools/dev-server.sh:89 (wait_ready curl)
    • -o /dev/null discards the server's own one-line explanation. A renamed/dropped message gives 400 no such table: `msg`... but the operator waits 31 s and is told last status 400 followed by a sentence about 404, with no mention of the table; the log tail carries nothing because SQL rejections are not logged.
    • Fix: -o "$STATE/probe.out" plus log "last response: $(tr -d '\n' < "$STATE/probe.out" | head -c 200)" in the failure path. Keep the retry loop — do not bail on 4xx.
  • should-fix — dev/tools/dev-server.sh:141 (rm -f "$PIDFILE" in the post-spawn refusal)
    • Latent, pre-existing, but the PR's whole §3 narrative is about racing invocations, so this is the right place to fix it. Two racing invocations on :5304: the LOSER deletes the WINNER's pidfile. Verified end state — live correctly-published server on 5304, server.pid absent; stop then says "no server running" and leaks it; restart sees a 200 with no pidfile and refuses with "no server of ours is running", which is false, and is a dead end until the operator pkills by hand.
    • Fix: [ "$(cat "$PIDFILE" 2>/dev/null)" = "$pid" ] && rm -f "$PIDFILE"
  • should-fix — PR body + comment at :70-85 (omission)
    • Neither says the module database opens LAZILY, on first request. That is the entire reason 'asking is what FORCES the open' is a mechanism rather than hand-waving, and a reader cannot verify the change without it. Second omission: the body reports the cost (restart 0.52 -> 0.56 s) but not the offsetting ~48 ms taken off the client's handshake — it states the debit and omits the credit, making the change look like pure overhead.
    • Fix: One sentence for the lazy open plus the 3-second no-SQL control run, and one line for the client-side saving.
  • nit — dev/tools/dev-server.sh:55
    • "So restart used to return while the database was still opening" — it returned while the database had NOT BEGUN opening. Understates the author's own finding.
    • Fix: "...returned before the database had begun opening at all."
  • nit — dev/tools/dev-server.sh:116
    • "can sit at the CLI's 'use port 5242 instead? [y/N]' prompt" implies an interactive hang; under the harness stdin is not a TTY, so the child gets EOF and dies in ~250 ms. The conclusion is unaffected (250 ms still beats wait_port's 5-10 ms).
    • Fix: "...spends ~250 ms printing and abandoning the CLI's port prompt, which is long enough to pass the liveness check."

Should #39 be closed?

NO — partially addresses it; leave it open with much better information. Merge the PR on the strength of the measurement; closing #39 would assert the flake is fixed, which nobody has shown.

  • 'Make wait_ready prove the DATABASE is ready' — done, as the issue literally specified (SELECT * FROM message LIMIT 0), via curl rather than the CLI. The deviation is an improvement: no CLI login/identity dependency, and it can run before the identity is minted (:84-85).
  • 'Confirm the flake disappears by running conformance repeatedly (aim for 20)' — STRUCTURALLY UNMEETABLE. 70 unpatched runs were green, so there is no 'disappears' to confirm. 26 (author) + 6 (mine) green post-patch is consistent with the fix and equally consistent with the flake never having been in this code path.
  • 'Consider whether the HTML5 harness needs the same treatment' — done; it inherits via dev-server.sh restart (html5-conformance.mjs:150, rc checked loudly).

#39's mechanism is factually wrong: The most important thing to rewrite. #39 says '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. The reported failure therefore requires a subscribed payload that lacked the edited row — not a slow one. I also ruled out a partial-replay race: at the bounce exactly one subscription set exists (legacy subscribe at :105; phase 3's subscribe_query at :251 comes after PHASE2 OK). And the measured window is ~48 ms against a 1 s client backoff, so a timing explanation fails on magnitude alone.

Recommended rewrite:

    1. Retitle and close the current issue on what was proven: 'dev-server restart returned before the module database had begun opening' — the database opens lazily on first request; the ping probe returned ~48 ms of open-work early and the reconnecting client paid it inside its WebSocket handshake.
    1. Open a NEW issue named from the symptom, not the theory: 'conformance phase 2 once saw a subscribed payload without the edited row, preceded by a second 1001 disconnect'. It MUST record what is ruled out so the next occurrence is not re-investigated from zero: (a) #39's stated mechanism is wrong, phase 2 has no time budget; (b) no partial-replay race, one subscription set at the bounce; (c) a dying server never serves, listener closes within one round trip of SIGTERM; (d) no stale/empty snapshot at the earliest instant, 25 (author) + 10 (mine) earliest-accept subscribes all returned the row with 0 close frames; (e) no lost commit, 8/8 SIGKILL survivals. Keep the original failing log. Without (a) written down the next reader will chase a budget that does not exist.

#16's continue-on-error

AGREE with the author's refusal to let it come off.

  • Decisive on magnitude: the window this PR closes is ~48 ms; the SDK's reconnect backoff is 1 s base / 30 s cap (stdb/init.lua:140). Three orders of magnitude apart — and a slower runner widens the client's tolerance rather than narrowing it, so 'runner is slower than local' cannot be explained by a 48 ms server-side window.
  • #16 is not blocked on readiness. Its acceptance criterion is 'one manual run whose comment shows either a PASS verdict or a specific environment reason', and its open question is whether Chromium starts in the job container at all. It is also still blocked on #15. This PR touches none of that.
  • #39's own sentence is hedged ('partly because reconnect timing on the runner is slower than local'). The runner-slowness half is untouched here.
  • continue-on-error should come off when a CI run has actually passed, not on a local latency improvement. The body's stated reason — 'saying otherwise would be exactly the over-trust this PR's comment warns against' — is the right reason, not just the right answer.

Sanity

native_conformance — 6/6 EXIT 0 on the patched tree (STDB_PORT=5310, STDB_STATE_DIR=/tmp/r50-conf), 06:08:32 -> 06:09:58. Each run PASS on both loads including PHASE5 and the identity-persistence assertion. Run 1 52 s (cold bob build), runs 2-6 ~6-7 s. Every 'fail' string in the log is the PHASE4 OK line ('failure surfaced as an error').

fixture_drift — None. git status --porcelain empty after all six runs, and conformance.sh's own re-derive/diff gate exited 0 six times.

unit_suite — 6 passed, 0 failed.

stylua — stylua --check stdb dev/test clean.

frozen_api — stdb/ untouched — the diff is dev/tools/dev-server.sh only. message in dev/server/index.js untouched. Hardcoding message in the probe is the right call for harness code given the byte-frozen declaration; the legibility fix above covers its absence.

housekeeping — No stale wait_ready references anywhere outside dev-server.sh (grepped *.sh *.mjs *.md *.yml) — the rename is complete.

## Review — automated reviewer, posted for the record **Verdict:** APPROVE — merge. The change is justified independently of #39. No blockers. 3 should-fix (all wording/legibility), 2 nits. Do NOT close #39 on merge. ### Is a change justified at all? Yes, on three independent grounds, none of which depend on #39 - MEASUREMENT (15 samples, my clock): the WS handshake is where a reconnecting client pays for the datastore open. No gate (subscribe at earliest TCP accept, n=10): open()->onopen = 47-51 ms. Gate first (SQL 200 then subscribe, n=5): 2-3 ms. The ~48 ms does not vanish, it moves from the client into `restart`. 15/15 got the correct row, 0 close frames, 0 SubscriptionError. - THE DATABASE OPEN IS LAZY — the load-bearing fact nobody wrote down. Control run: restart, poll /v1/ping only, issue NO SQL for 3 s. The entire server log for that window is one line, `Starting SpacetimeDB listening`. No replica lock, no `applying transaction history`, no `launching module`. The module database does not open at boot; it opens on the first request that names it. So the code comment's 'asking is also what FORCES that open to happen here' (:70-73) is literally true and is the real justification. - GUARD MOVE: bare stray holding :5303. Pre-move variant (patched minus the pre-spawn block) restart = rc 1 after 31.69 s with `database 'chat' never served a query (last status 404)`. Patched: restart rc 1 in 16 ms, start rc 1 in 15 ms, correct message. Author reported 31 s / 17 ms / 14 ms — reproduced within noise. ### Re-derived measurement **ordering** — CONFIRMED. Own run: spawn 05:55:47.9322 | log 'listening' .9926 | log 'Acquired lock on data/replicas/1/db.lock' .9945 | ping 200 .9959 | log 'applied transaction history' 06:...48.0003 | log 'launching module' .0015 | SQL 200 (11th attempt) .0243. ping-200 -> SQL-200 gap = 28.4 ms (author: ~40 ms; same order, same sign). **caveat_on_the_authors_table** — lock/replay/launch land where they do relative to ping only because a poller is already asking. In my run the lock PRECEDED ping-200 by 1.4 ms for exactly that reason. The table should be read as 'ping 200 is ~30-40 ms ahead of a served query', not as a fixed boot sequence. **restart_waits_for_the_host** — CONFIRMED on the patched script: restart returned 06:03:28.4454, i.e. 23 ms AFTER `launching module` at .4223. The first query afterwards was 200 on attempt 1, no retry. **disproof_spotcheck_SIGTERM** — VERIFIED. Tight ping loop with SIGTERM delivered mid-loop: signal at 06:08:03.0423, attempt 24 was the last 200, attempt 25 the first 000 at .0502 (7.9 ms = one curl iteration), process gone .0539, five further pings all 000. The listener closes at signal delivery; there is no half-open window. Author's disproof #2 stands as written. **disproof_spotcheck_stale_snapshot** — Independently reproduced at a TIGHTER instant than the author's. 10 restarts, each subscribing at the earliest instant TCP accepts (~800 connect refusals deep), NO SQL probe at all: 10/10 InitialSubscription with num_rows=1 carrying the correct row, 1-2 ms after onopen. No 1001, no SubscriptionError, no close. Also ruled out my own added hypothesis (server closing the socket with 1001 during the open window). ### Two-gate split **cold_start_identical** — Gate identical, BEHAVIOUR NOT. main: keygen -> spawn -> wait_ready(ping) -> kill -0. Patched no-arg: keygen -> NEW pre-spawn ping guard -> spawn -> wait_port(same loop) -> kill -0 -> skip wait_ready. Cold path gained one HTTP request and a whole new refusal path. Measured cold-path refusal myself at 15 ms. Fresh-state cold start: rc 0, 407 ms, guard does not misfire, stdout exactly 2 lines (BASE+TOKEN) = conformance.sh's contract. Second start adopts in 129 ms. Owned restart 577 ms (author: ~0.56 s). **timeout_path** — Sane. 120 x 0.25 s ~= 31 s, same shape and budget as the pre-existing wait_port. Engine TIMEOUT is 90 s (smoke.script:35), so a gate stall is reported by dev-server before the engine gives up. `set -e` correctly suppressed the misleading `server back up at $BASE` line on failure. **restart_before_publish_message** — ACCURATE TO THE SECOND AND THE STATUS CODE. Fresh state dir, restart: rc 1 at 31.35 s, `database 'chat' never served a query (last status 404)` + `A permanent 404 means nothing is published into ... : start without 'restart'`. The advice is correct for this case. Side effect (nit, pre-existing shape): the failed restart leaves the spawned server running with a valid pidfile; self-healing because the next plain `start` adopts it, which is what the message tells you to do, but undocumented. **empty_database** — PASSES. `message` was empty for every §1 run (`"rows":[]`). `SELECT * FROM message LIMIT 0` returns 200 with a schema envelope and zero rows. No hang, no false negative. **renamed_or_dropped_message_table** — SHOULD-FIX, legibility. Measured: missing table -> 400 with body ``no such table: `msg`. If the table exists, it may be marked private.``; missing database -> 404 `` `nosuchdb` not found ``; during the lazy-open window -> 000 (curl cannot connect), never a 4xx. The probe uses `-o /dev/null` (:89), so the server's own one-line diagnosis is DISCARDED. On a renamed `message` the operator waits 31 s and gets `last status 400` explained by a sentence about 404, with no mention of the table; the `tail -20 $LOGFILE` does not help because a SQL-layer rejection is never written to the server log (verified). Fix: `-o "$STATE/probe.out"` and log its first 200 bytes on the failure path. Do NOT bail early on 4xx — I could not establish that a 404 is never transient on this path, and an early bail would trade a legibility bug for a new flake. **sql_200_vs_subscribe_THE_SUBSTANTIVE_RISK** — RESOLVED: neither implies the other; both simply force and await the same lazy open, so /subscribe is SELF-GATING. Proof: subscribe at the earliest instant TCP accepts with no SQL anywhere returned the correct row 1 ms after handshake, 53 ms after spawn, with the datastore never opened by anything else — and the intermediate SQL statuses in the same window are 000, never 4xx, i.e. the first request naming the database BLOCKS through the open and then answers correctly. So the gate is a BETTER PROXY, NOT A PROOF, and subscribe never needed it. That is consistent with and explains the author's inability to reproduce #39. The gate's real, defensible value is the 48 ms it moves off the client's handshake — which is what the code comment claims and nothing more. ### Stray-guard move **old_failure_mode_reproduced** — YES, twice over. (a) Post-spawn liveness check was mechanically incapable of firing: with port 5301 held, the doomed child lived 254 ms (spawn 06:05:38.664, gone .918) while wait_port's FIRST curl returns 200 in ~5-10 ms against the stray, so `kill -0` runs ~240 ms early and ALWAYS passes. (b) Pre-move variant against a bare stray: rc 1 after 31.69 s with the misleading `never served a query` message. **framing_correction_nit** — With stdin not a TTY — which is how conformance.sh runs it — the child does not *sit* at the `[y/N]` prompt; it gets EOF and exits in ~250 ms. The prompt is still what buys those 250 ms, so ':116' "long enough to pass the liveness check" is accurate, but "can sit at the CLI's prompt" suggests an interactive hang that does not occur in the harness. Also, in the pre-move failure the truth WAS on screen: `tail -20 $LOGFILE` printed the child's `Port 5303 is already in use.`, buried under the CLI's ASCII-art banner. "Misleading" is fair for the two headline log lines; "baffling" overstates it slightly. **legitimate_cases_not_broken** — - *our_own_server_already_running*: OK. `server_pid` succeeds at :200, start_server is never called, guard never runs. Adopts + republishes in 3.8 s (orphan from the failed restart) and 129 ms (fresh). - *restart_of_a_server_we_own*: OK. rc 0 in 577 ms, `server back up`, host launched before return, first query 200 on attempt 1. - *two_racing_invocations*: Safe but exposes a latent bug — see should_fix_2. inv1 won and published (rc 0); inv2's post-spawn refusal fired (rc 1) rather than publishing into inv1's database, so the property that matters held. This is exactly the case the new comment at :136-139 claims the post-spawn check is kept for — confirmed: the post-spawn check earns its keep here and the pre-spawn guard could not have helped. ### Findings - **should-fix** — `PR body, 'The change' section` - "Cold-start behaviour is byte-identical to before." It is not — the cold path gained the pre-spawn ping guard, one extra HTTP request and a new refusal path. The body contradicts itself two paragraphs later ('`restart` and `start` now refuse in 17 ms / 14 ms') and I measured the cold-path refusal at 15 ms. - *Fix:* Say "cold start's readiness GATE is unchanged". This matters because 'byte-identical' is exactly the sentence a reviewer trusts instead of re-deriving. - **should-fix** — `dev/tools/dev-server.sh:89 (wait_ready curl)` - `-o /dev/null` discards the server's own one-line explanation. A renamed/dropped `message` gives 400 ``no such table: `msg`...`` but the operator waits 31 s and is told `last status 400` followed by a sentence about 404, with no mention of the table; the log tail carries nothing because SQL rejections are not logged. - *Fix:* `-o "$STATE/probe.out"` plus `log "last response: $(tr -d '\n' < "$STATE/probe.out" | head -c 200)"` in the failure path. Keep the retry loop — do not bail on 4xx. - **should-fix** — `dev/tools/dev-server.sh:141 (rm -f "$PIDFILE" in the post-spawn refusal)` - Latent, pre-existing, but the PR's whole §3 narrative is about racing invocations, so this is the right place to fix it. Two racing invocations on :5304: the LOSER deletes the WINNER's pidfile. Verified end state — live correctly-published server on 5304, `server.pid` absent; `stop` then says "no server running" and leaks it; `restart` sees a 200 with no pidfile and refuses with "no server of ours is running", which is false, and is a dead end until the operator pkills by hand. - *Fix:* `[ "$(cat "$PIDFILE" 2>/dev/null)" = "$pid" ] && rm -f "$PIDFILE"` - **should-fix** — `PR body + comment at :70-85 (omission)` - Neither says the module database opens LAZILY, on first request. That is the entire reason 'asking is what FORCES the open' is a mechanism rather than hand-waving, and a reader cannot verify the change without it. Second omission: the body reports the cost (restart 0.52 -> 0.56 s) but not the offsetting ~48 ms taken off the client's handshake — it states the debit and omits the credit, making the change look like pure overhead. - *Fix:* One sentence for the lazy open plus the 3-second no-SQL control run, and one line for the client-side saving. - **nit** — `dev/tools/dev-server.sh:55` - "So `restart` used to return while the database was still opening" — it returned while the database had NOT BEGUN opening. Understates the author's own finding. - *Fix:* "...returned before the database had begun opening at all." - **nit** — `dev/tools/dev-server.sh:116` - "can sit at the CLI's 'use port 5242 instead? [y/N]' prompt" implies an interactive hang; under the harness stdin is not a TTY, so the child gets EOF and dies in ~250 ms. The conclusion is unaffected (250 ms still beats wait_port's 5-10 ms). - *Fix:* "...spends ~250 ms printing and abandoning the CLI's port prompt, which is long enough to pass the liveness check." ### Should #39 be closed? NO — partially addresses it; leave it open with much better information. Merge the PR on the strength of the measurement; closing #39 would assert the flake is fixed, which nobody has shown. - [x] 'Make wait_ready prove the DATABASE is ready' — done, as the issue literally specified (`SELECT * FROM message LIMIT 0`), via curl rather than the CLI. The deviation is an improvement: no CLI login/identity dependency, and it can run before the identity is minted (:84-85). - [ ] 'Confirm the flake disappears by running conformance repeatedly (aim for 20)' — STRUCTURALLY UNMEETABLE. 70 unpatched runs were green, so there is no 'disappears' to confirm. 26 (author) + 6 (mine) green post-patch is consistent with the fix and equally consistent with the flake never having been in this code path. - [x] 'Consider whether the HTML5 harness needs the same treatment' — done; it inherits via `dev-server.sh restart` (html5-conformance.mjs:150, rc checked loudly). **#39's mechanism is factually wrong:** The most important thing to rewrite. #39 says '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. The reported failure therefore requires a `subscribed` payload that lacked the edited row — not a slow one. I also ruled out a partial-replay race: at the bounce exactly one subscription set exists (legacy `subscribe` at :105; phase 3's `subscribe_query` at :251 comes after PHASE2 OK). And the measured window is ~48 ms against a 1 s client backoff, so a timing explanation fails on magnitude alone. **Recommended rewrite:** - 1. Retitle and close the current issue on what was proven: 'dev-server `restart` returned before the module database had begun opening' — the database opens lazily on first request; the ping probe returned ~48 ms of open-work early and the reconnecting client paid it inside its WebSocket handshake. - 2. Open a NEW issue named from the symptom, not the theory: 'conformance phase 2 once saw a `subscribed` payload without the edited row, preceded by a second 1001 disconnect'. It MUST record what is ruled out so the next occurrence is not re-investigated from zero: (a) #39's stated mechanism is wrong, phase 2 has no time budget; (b) no partial-replay race, one subscription set at the bounce; (c) a dying server never serves, listener closes within one round trip of SIGTERM; (d) no stale/empty snapshot at the earliest instant, 25 (author) + 10 (mine) earliest-accept subscribes all returned the row with 0 close frames; (e) no lost commit, 8/8 SIGKILL survivals. Keep the original failing log. Without (a) written down the next reader will chase a budget that does not exist. ### #16's `continue-on-error` AGREE with the author's refusal to let it come off. - Decisive on magnitude: the window this PR closes is ~48 ms; the SDK's reconnect backoff is 1 s base / 30 s cap (stdb/init.lua:140). Three orders of magnitude apart — and a slower runner widens the client's tolerance rather than narrowing it, so 'runner is slower than local' cannot be explained by a 48 ms server-side window. - #16 is not blocked on readiness. Its acceptance criterion is 'one manual run whose comment shows either a PASS verdict or a specific environment reason', and its open question is whether Chromium starts in the job container at all. It is also still blocked on #15. This PR touches none of that. - #39's own sentence is hedged ('partly because reconnect timing on the runner is slower than local'). The runner-slowness half is untouched here. - `continue-on-error` should come off when a CI run has actually passed, not on a local latency improvement. The body's stated reason — 'saying otherwise would be exactly the over-trust this PR's comment warns against' — is the right reason, not just the right answer. ### Sanity **native_conformance** — 6/6 EXIT 0 on the patched tree (STDB_PORT=5310, STDB_STATE_DIR=/tmp/r50-conf), 06:08:32 -> 06:09:58. Each run PASS on both loads including PHASE5 and the identity-persistence assertion. Run 1 52 s (cold bob build), runs 2-6 ~6-7 s. Every 'fail' string in the log is the PHASE4 OK line ('failure surfaced as an error'). **fixture_drift** — None. `git status --porcelain` empty after all six runs, and conformance.sh's own re-derive/diff gate exited 0 six times. **unit_suite** — 6 passed, 0 failed. **stylua** — `stylua --check stdb dev/test` clean. **frozen_api** — stdb/ untouched — the diff is dev/tools/dev-server.sh only. `message` in dev/server/index.js untouched. Hardcoding `message` in the probe is the right call for harness code given the byte-frozen declaration; the legibility fix above covers its absence. **housekeeping** — No stale `wait_ready` references anywhere outside dev-server.sh (grepped *.sh *.mjs *.md *.yml) — the rename is complete.
yuris force-pushed feat/39-readiness from c393498f64
All checks were successful
ci / ci (pull_request) Successful in 19s
to 1cb1f36249
All checks were successful
ci / ci (pull_request) Successful in 20s
2026-08-20 06:32:43 +00:00
Compare
yuris merged commit 97686c4557 into main 2026-08-20 06:37:08 +00:00
Sign in to join this conversation.
No description provided.