dev-server: gate restart on the database serving, not the port answering #50
No reviewers
Labels
No labels
area:defold
area:docs
area:infra
area:protocol
area:testing
kind:bug
kind:chore
phase:breadth
phase:core
phase:hardening
phase:slice
No milestone
No project
No assignees
1 participant
Notifications
Due date
No due date set.
Dependencies
No dependencies set.
Reference
yuris/spacetimedb-defold!50
Loading…
Add table
Add a link
Reference in a new issue
No description provided.
Delete branch "feat/39-readiness"
Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?
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_readypolled/v1/pingfor a 200, which proves the HTTP port answers and nothing else. One restart, one clock: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/pingonly, 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.
restartgrows 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:
/subscribewaits for the host too.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_portkeeps the old ping loop. A newwait_readypollsSELECT * FROM message LIMIT 0against/v1/database/$DB/sqland 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
restartasks 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,
restartreturned 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 passkill -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,
restartandstartnow 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 unconditionalrm -fthere stripped a live, correctly-published server of its only record. Reproduced on a fresh state dir, port 5350: winnerrc 0withCreated new database with name: chat, loserrc 1withour server died immediately,server.pidabsent, listener still up and answering/v1/pingand the SQL probe 200 — after whichstopsaysno server runningand leaks it, andrestartrefuses withno server of ours is running, which is false and needs a manualpkillto escape. Now guarded on the pid matching. The same race on port 5351 after the fix leavesserver.pidpresent holding the winner's pid, andrestart(rc 0) andstopboth 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 onmain, 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 whosemessagetable is missing bought 31 s of polling and thenlast status 400explained 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.outand 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:and a fresh state dir with nothing published still gets
last response: `chat` not foundplus 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 underset -ea 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/testclean, and 7 more consecutive native conformance runs (own port and state dir), allEXIT 0, each PASS on both loads including PHASE2, PHASE5 and the identity-persistence assertion,git status --porcelaincarrying nothing butdev/tools/dev-server.shafter every one.HTML5 needs no separate treatment:
html5-conformance.mjs:150bounces the server through the samedev-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:
restartbefore anything is published fails after 31 s withdatabase '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-errorshould 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
messagetable name is hardcoded in the probe rather than made configurable —dev/server/index.jsdeclares 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.restarton the database serving, not the port answeringReview — 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
restart. 15/15 got the correct row, 0 close frames, 0 SubscriptionError.Starting SpacetimeDB listening. No replica lock, noapplying transaction history, nolaunching 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.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 moduleat .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 -ecorrectly suppressed the misleadingserver back up at $BASEline 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 plainstartadopts it, which is what the message tells you to do, but undocumented.empty_database — PASSES.
messagewas empty for every §1 run ("rows":[]).SELECT * FROM message LIMIT 0returns 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 renamedmessagethe operator waits 31 s and getslast status 400explained by a sentence about 404, with no mention of the table; thetail -20 $LOGFILEdoes 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 -0runs ~240 ms early and ALWAYS passes. (b) Pre-move variant against a bare stray: rc 1 after 31.69 s with the misleadingnever served a querymessage.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 $LOGFILEprinted the child'sPort 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 —
server_pidsucceeds 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).server back up, host launched before return, first query 200 on attempt 1.Findings
PR body, 'The change' sectionrestartandstartnow refuse in 17 ms / 14 ms') and I measured the cold-path refusal at 15 ms.dev/tools/dev-server.sh:89 (wait_ready curl)-o /dev/nulldiscards the server's own one-line explanation. A renamed/droppedmessagegives 400no such table: `msg`...but the operator waits 31 s and is toldlast status 400followed by a sentence about 404, with no mention of the table; the log tail carries nothing because SQL rejections are not logged.-o "$STATE/probe.out"pluslog "last response: $(tr -d '\n' < "$STATE/probe.out" | head -c 200)"in the failure path. Keep the retry loop — do not bail on 4xx.dev/tools/dev-server.sh:141 (rm -f "$PIDFILE" in the post-spawn refusal)server.pidabsent;stopthen says "no server running" and leaks it;restartsees 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.[ "$(cat "$PIDFILE" 2>/dev/null)" = "$pid" ] && rm -f "$PIDFILE"PR body + comment at :70-85 (omission)dev/tools/dev-server.sh:55restartused to return while the database was still opening" — it returned while the database had NOT BEGUN opening. Understates the author's own finding.dev/tools/dev-server.sh:116Should #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.
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).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 == 2and 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 asubscribedpayload 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 (legacysubscribeat :105; phase 3'ssubscribe_queryat :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:
restartreturned 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.subscribedpayload 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-errorAGREE with the author's refusal to let it come off.
continue-on-errorshould 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 --porcelainempty 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/testclean.frozen_api — stdb/ untouched — the diff is dev/tools/dev-server.sh only.
messagein dev/server/index.js untouched. Hardcodingmessagein 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_readyreferences anywhere outside dev-server.sh (grepped *.sh *.mjs *.md *.yml) — the rename is complete.c393498f641cb1f36249