A timing test that stops measuring the machine, and a relay boot that stops adopting a stranger - #394
Merged
Merged
Conversation
login-timing: the [min, max] range overlap is an extreme-value statistic and at eight samples it went falsely red 6.9% to 8.9% per level, which is what a 0.85 ms difference on a pull-request run turned into. Replaced by 24 samples, a median tolerance of max(2 ms, 1% of the designed answer time), an overlap of the central 80% of each group, and one repeat of a level before it may fail. Measured false-red 0.000% per level, and it still catches a real 5 ms offset 94% to 100% of the time where the old assertion caught it 67% to 94%. _relay-server: boot() probed /health on a port from its first iteration and took any 200 as its own child, so a port collision between the parallel route suites handed the caller another suite's relay. That is the 401 "ADMIN_TOKEN required for admin endpoints" that route-billing-entitlements #315 hit after a restart. It now waits for its own child's relay_started on that port and, when a token is set, proves ownership with one authenticated request. restart() awaits the old process instead of sleeping 150 ms at it.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Two tests that block the deploy gate when the machine under them is busy, and neither
of them was measuring what it claimed to measure.
1. admin/test/login-timing.test.js: the range assertion was an extreme-value statistic
Since #379 this suite runs in two jobs. A parallel PR run saw it red at the twelve-failure
level: exists p50 752.29 ms against absent p50 751.44 ms, a difference of 0.85 ms, with the
two
[min, max]ranges missing each other by a hair. Green on the rerun.The medians were never the problem. The range overlap was.
[min, max]is decided by thesingle slowest and single fastest request in each group, and at eight samples those are two
draws from a tail.
How bad. 40 real measurements per case per level on a loaded machine, resampled 20 000
times per cell:
min < maxoverlap (old)min < maxoverlapRoughly one run in five over three levels is what the old assertion cost. The interquartile
band the brief suggested is stricter still, but it is too strict: with a 0.85 ms apparent
offset injected, the difference that turned the run above red, IQR overlap goes red 15.5% of
the time at the bottom level. The central 80% band is the one that holds: 0.000% at a true
offset, at most 0.075% at 0.85 ms, and it still catches 5 ms almost always and 20 ms always.
What the suite asserts now, per level, on both routes:
|p50(exists) - p50(absent)| < max(2 ms, 1% of that floor), so 2.5 ms at a 250 ms floor(four times tighter than the flat 10 ms it replaces) and 22.5 ms at 2250 ms;
p10..p90, notmin..max;busy costs a rerun; a machine that is leaking the answer fails both rounds, and the
discarded round's numbers go into the message.
This is a stricter detector than the one it replaces on every axis measured, not a looser one.
Measurements, on a machine under a parallel CPU hog
/api/user/login, stub relay, 16-way hog/api/user/login-with-backup, real relay and real argon2, 8-way hogTen runs under load, green
node --test admin/test/login-timing.test.jsagainst a real redis, with eight busy-loop workers pinned alongside on a sixteen-core machine. 10 of 10 green, 19 checks each.Sabotage, hard red, twice each
The suite has to keep catching the thing it exists for. Three sabotages of
admin/server.js,each run twice:
admin/server.jsfullthrottled_upstreamdropped so the relay only charges an address that existsoraclethrottled_upstreamdroppedbackupthrottled_upstreamdroppedThe numbers the suite printed, from the failing rounds:
full, level 0: exists p50 8.28[7.24, 8.81], absent p50 3.76[3.30, 4.42]. Floor gone.oracle, level 12: exists p50 510.60[509.32, 513.32], absent p50 251.98[251.25, 253.00].A 258.62 ms gap against a 7.50 ms tolerance, and the two bands are disjoint by 256 ms. Both
the median test and the band test are red on those numbers; the floor test is simply the
first assertion to fire.
backup, level 0: exists p50 2532.65[2511.11, 2547.86], absent p50 3.65[3.32, 4.05].A 2.5 second oracle.
Each sabotage failed on both the first round and the repeat, so the one retry does not soften them.
Cost
The suite goes from about 1.9 minutes to about 6.8 minutes: 24 samples instead of 8 and 6,
and at twenty prior failures every single answer is held for 2.25 s by design. The admin unit
job pays about half of that (its backup case is declared skipped there,
ADMIN_TEST_SKIP=relay);the crypto job pays all of it. That is the price of a timing test that does not have to be
rerun.
2. relay/test/_relay-server.js: boot() adopted whatever answered on the port
Run 33713795533 on main (d3c126d, a screenshot-suite change) went red in the crypto job on
route-billing-entitlements.test.js:57, "#315: a paid period on disk is still bounded after arestart": after the restart the admin endpoint answered
401 {"error":"ADMIN_TOKEN required for admin endpoints"}instead of 200. It reads like arestart bug. It is not.
freePort()asks the OS for a free port, closes the listener and hands the number on. Betweenthat close and the child's own
listen()the port belongs to nobody. The route suites run asnode --test test/route-*.test.js, which runs the files in parallel processes, and every oneof them boots relays through this function.
The old wait loop then made the collision invisible: it probed
GET /healthon the port fromits very first iteration, long before its own child could be listening, and took any 200 as
"we are up". When another suite's relay held that port, that relay answered,
boot()returneda handle pointing at it, and the caller's own child died of EADDRINUSE unnoticed. The test then
talked to a stranger with a different
ADMIN_TOKEN, which is exactly the 401 above.The fix, both halves:
relay_startedfor this port before anything is probed.Only the process that owns the socket logs that line, so it is proof of ownership rather
than a guess about timing;
ADMIN_TOKEN, one authenticated admin request must not come back401 before the handle is returned. Same proof from the other end, and it is the exact
symptom the suite hit.
restart()also stopped sleeping 150 ms at the old process and now awaits its exit. relay.jszeroizes its blobs, flushes the CT/STH queues and writes
users.jsonon SIGTERM, and the nextboot reads that same
users.json; 150 ms was a guess at how long that takes.Deterministic reproduction
A foreign relay with a different
ADMIN_TOKENis put on the portboot()is then handed:mainboot()returned a handle on the foreign relay's port; the admin request answered401 {"error":"ADMIN_TOKEN required for admin endpoints"}. The CI failure, exactly.boot()refused the foreign relay, retried on a fresh port, admin request 200 with the entitlements.relay_startedwaitboot()threw: "the relay answering on port N does not share this suite's ADMIN_TOKEN". Loud, but no recovery.Removing only the wait step from the fixed version leaves the authenticated probe, which still
refuses, so the failure is loud instead of wrong. It is the wait step that lets the boot
recover.
Ten runs of the whole parallel route job, green
node --test relay/test/route-*.test.js relay/test/parasign-signs-quota.test.js, the crypto job'sown command line, ten times with an 8-way CPU hog alongside: 10 of 10 green, 91 tests each,
15.3 s to 21.9 s per run.
route-billing-entitlements.test.json its own: 16 of 16.Gates
scripts/check-test-declarations.shtests/static-sanity.shnpx eslint@9 .ADMIN_TEST_SKIP=relay)admin/test/login-timing.test.jsfull, with the real relayNot fixed here, but measured
Under a hog of twelve or more workers on this sixteen-core machine, ten argon2id verifications
at 64 MiB take longer than the 1500 ms floor on
/api/user/login-with-backup, the admin logsanswer overran its floorand the suite fails on that, with the right diagnostic(
raise PARAMANT_LOGIN_BACKUP_MIN_ANSWER_MS). That is the product's design envelope beingexceeded, not a wobbly statistic, and the suite is right to say so. Measured: at a 12-way hog,
exists p50 2127.41 ms against absent p50 1504.18 ms with 23 overruns logged. The loaded runs
above use an 8-way hog, which keeps the machine inside that envelope. A GitHub runner has four
vCPUs and runs nothing else, so this is not what CI sees, but it is worth writing down.
relay/test/route-redis-outage.test.jsfails the same way under a 16-way hog (its redisdeadline is exceeded, 503
redis_unavailable); untouched here.