d9b17d58
test: e2e — delete the unfalsifiable check; (c) measures the time it claims; honest bounds
a73x 2026-08-12 05:05
Commit message
test/e2e.sh
| Old | New | ||
|---|---|---|---|
| @@ -144,6 +144,7 @@ HDPID="" | |||
| 144 | # the launch and the wait, leaving a client the shell would otherwise | 144 | # the launch and the wait, leaving a client the shell would otherwise |
| 145 | # orphan. Declared here so the trap can read them under `set -u`. | 145 | # orphan. Declared here so the trap can read them under `set -u`. |
| 146 | H1PID="" | 146 | H1PID="" |
| 147 | H3PID="" | ||
| 147 | H4PID="" | 148 | H4PID="" |
| 148 | H5PID="" | 149 | H5PID="" |
| 149 | 150 | ||
| @@ -369,6 +370,7 @@ cleanup() { | |||
| 369 | # anyway; this only shortens the wait on a run that failed between a | 370 | # anyway; this only shortens the wait on a run that failed between a |
| 370 | # launch and its wait. | 371 | # launch and its wait. |
| 371 | [ -n "$H1PID" ] && kill "$H1PID" 2>/dev/null || true | 372 | [ -n "$H1PID" ] && kill "$H1PID" 2>/dev/null || true |
| 373 | [ -n "$H3PID" ] && kill "$H3PID" 2>/dev/null || true | ||
| 372 | [ -n "$H4PID" ] && kill "$H4PID" 2>/dev/null || true | 374 | [ -n "$H4PID" ] && kill "$H4PID" 2>/dev/null || true |
| 373 | [ -n "$H5PID" ] && kill "$H5PID" 2>/dev/null || true | 375 | [ -n "$H5PID" ] && kill "$H5PID" 2>/dev/null || true |
| 374 | [ -n "${MUXD:-}" ] && "$MUXD" stop --sock "$SOCK16" >/dev/null 2>&1 || true | 376 | [ -n "${MUXD:-}" ] && "$MUXD" stop --sock "$SOCK16" >/dev/null 2>&1 || true |
| @@ -2287,11 +2289,16 @@ ok "local mux auto-start under the pty fixture" | |||
| 2287 | # The contract it depends on: the client spawns `ssh HOST CMD...` as | 2289 | # The contract it depends on: the client spawns `ssh HOST CMD...` as |
| 2288 | # separate shell words, so dropping HOST is a `shift` and the rest is a | 2290 | # separate shell words, so dropping HOST is a `shift` and the rest is a |
| 2289 | # command. A future client that quoted the remote command instead would | 2291 | # command. A future client that quoted the remote command instead would |
| 2290 | # arrive here as two arguments whose second is one word, and `exec` would | 2292 | # arrive as two arguments whose second is one word, and `exec` would fail |
| 2291 | # fail to find a program by that name — loudly, at 127, rather than by | 2293 | # to find a program by that name — loudly, at 127. |
| 2292 | # quietly not being ssh. The arity guard below is the cheaper half of the | 2294 | # |
| 2293 | # same insurance: a fixture whose silence cannot be told from success is | 2295 | # The arity guard covers the case that would NOT be loud: `ssh HOST` with |
| 2294 | # worth two shell words to rule out. | 2296 | # no command at all. There, `shift` empties "$@" and a bare `exec` is a |
| 2297 | # no-op, so the shim would exit 0 having run nothing — silence that looks | ||
| 2298 | # exactly like success. Note what the guard's 97 does and does not buy: | ||
| 2299 | # nothing prints it, and the client experiences it only as an ssh that | ||
| 2300 | # closed without an announce. It converts "quietly wrong" into "visibly | ||
| 2301 | # no announce", which is a diagnosis this suite can act on. | ||
| 2295 | mkdir -p "$SSHIM_DIR" "$HRUN" "$HRUN2" | 2302 | mkdir -p "$SSHIM_DIR" "$HRUN" "$HRUN2" |
| 2296 | : > "$SSHIM_PIDLOG" | 2303 | : > "$SSHIM_PIDLOG" |
| 2297 | cat > "$SSHIM_DIR/ssh" <<'SHIM' | 2304 | cat > "$SSHIM_DIR/ssh" <<'SHIM' |
| @@ -2320,13 +2327,11 @@ HCACHE="$XDG_CACHE_HOME/mux/hosts/$HHOST" | |||
| 2320 | # inference: the ssh the announce arrived on is killed by the client on | 2327 | # inference: the ssh the announce arrived on is killed by the client on |
| 2321 | # QUIC success, so once its pid is OBSERVED gone, a second marker still | 2328 | # QUIC success, so once its pid is OBSERVED gone, a second marker still |
| 2322 | # making the round trip can only be riding QUIC. The pipe's owner is dead. | 2329 | # making the round trip can only be riding QUIC. The pipe's owner is dead. |
| 2323 | set +e | ||
| 2324 | { printf 'printf "cold-%%s\\n" one\n'; sleep 6; \ | 2330 | { printf 'printf "cold-%%s\\n" one\n'; sleep 6; \ |
| 2325 | printf 'printf "cold-%%s\\n" two\n'; sleep 2.5; printf '\034'; } | \ | 2331 | printf 'printf "cold-%%s\\n" two\n'; sleep 2.5; printf '\034'; } | \ |
| 2326 | SHELL=/bin/sh XDG_RUNTIME_DIR="$HRUN" PATH="$HPATH" timeout 60 \ | 2332 | SHELL=/bin/sh XDG_RUNTIME_DIR="$HRUN" PATH="$HPATH" timeout 60 \ |
| 2327 | "$MUX" "$HHOST" > "$OUT.h1" 2> "$OUT.h1.err" & | 2333 | "$MUX" "$HHOST" > "$OUT.h1" 2> "$OUT.h1.err" & |
| 2328 | H1PID=$! | 2334 | H1PID=$! |
| 2329 | set -e | ||
| 2330 | # The bounded wait, with a message of its own, because of what it is FOR: | 2335 | # The bounded wait, with a message of its own, because of what it is FOR: |
| 2331 | # a client blocked on an announce that is never coming has no other | 2336 | # a client blocked on an announce that is never coming has no other |
| 2332 | # symptom. It cannot be left to the suite's timeout or the trap — those | 2337 | # symptom. It cannot be left to the suite's timeout or the trap — those |
| @@ -2342,29 +2347,30 @@ HSHIMS=$(wc -l < "$SSHIM_PIDLOG") | |||
| 2342 | echo "e2e FAIL: cold handoff ran $HSHIMS ssh invocations, want exactly 1" | 2347 | echo "e2e FAIL: cold handoff ran $HSHIMS ssh invocations, want exactly 1" |
| 2343 | cat "$SSHIM_PIDLOG"; exit 1; } | 2348 | cat "$SSHIM_PIDLOG"; exit 1; } |
| 2344 | HSHIMPID=$(head -1 "$SSHIM_PIDLOG") | 2349 | HSHIMPID=$(head -1 "$SSHIM_PIDLOG") |
| 2345 | # The BASELINE, and it is what makes the pair below an ordering proof | 2350 | wait_pid_gone "$HSHIMPID" "cold handoff: QUIC took over, so ssh must be gone" |
| 2346 | # rather than two independent facts: the second marker must not have | 2351 | # The BASELINE, and it comes AFTER the death rather than before it so that |
| 2347 | # arrived YET. | 2352 | # what it establishes is exactly what the next check needs: at the instant |
| 2353 | # ssh was observed gone, the second marker had not arrived. Its later | ||
| 2354 | # arrival is therefore traffic that moved after the pipe's owner died. | ||
| 2355 | # Taken before the death instead, it would pin absence at some earlier | ||
| 2356 | # moment and lean on wait_pid_gone's 2s budget staying small against the | ||
| 2357 | # script's 6s — a coupling nothing states and nobody would maintain. | ||
| 2348 | # | 2358 | # |
| 2349 | # What actually guarantees the ordering is the PRODUCT, and saying so is | 2359 | # What guarantees the ordering in the first place is the PRODUCT, and |
| 2350 | # the point of this comment. openHandoff kills the ssh child the moment | 2360 | # saying so is the other half of this comment's job: openHandoff kills the |
| 2351 | # QUIC is ready, before Transport.open returns — so before the session can | 2361 | # ssh child the moment QUIC is ready, before Transport.open returns, so |
| 2352 | # emit a single byte, and therefore before cold-one, never mind cold-two. | 2362 | # before the session can emit a single byte — before cold-one, never mind |
| 2353 | # The baseline pins the weaker, checkable half of that: cold-two had not | 2363 | # cold-two. Anyone who moves that kill (to after the first frame, into a |
| 2354 | # arrived at the instant we observed the death. Anyone who moves WHEN the | 2364 | # deferred teardown) takes this scenario's premise with them and should |
| 2355 | # client kills ssh — to after the first frame, say, or into a deferred | 2365 | # expect to rewrite the block rather than nudge a sleep. |
| 2356 | # teardown — takes this scenario's premise with it, and should expect to | ||
| 2357 | # rewrite the block rather than to nudge a sleep. | ||
| 2358 | # | 2366 | # |
| 2359 | # The hole it closes is real rather than theoretical. Both markers are | 2367 | # The case it catches is real rather than theoretical. Both markers are |
| 2360 | # typed by a script on its own clock: if an attach ever outran the 6s | 2368 | # typed by a script on its own clock: if an attach ever outran the 6s |
| 2361 | # between them, both would be buffered before the session existed and | 2369 | # between them, both would be buffered before the session existed and |
| 2362 | # delivered together, and cold-two could already be on screen here. The | 2370 | # delivered together, and cold-two would already be on screen here. The |
| 2363 | # scenario could then no longer WITNESS post-death traffic — not because | 2371 | # scenario could then no longer WITNESS post-death traffic — not because |
| 2364 | # the product misbehaved (the kill still preceded both) but because the | 2372 | # the product misbehaved (the kill still preceded both) but because the |
| 2365 | # two events stopped being separable. That is what this reports, and the | 2373 | # two events stopped being separable. That is what this reports. |
| 2366 | # message says so rather than accusing the product of an ordering it did | ||
| 2367 | # not get wrong. | ||
| 2368 | grep -q "cold-two" "$OUT.h1" && { | 2374 | grep -q "cold-two" "$OUT.h1" && { |
| 2369 | echo "e2e FAIL: cold handoff: the second marker is already on screen at the" | 2375 | echo "e2e FAIL: cold handoff: the second marker is already on screen at the" |
| 2370 | echo " baseline, so it cannot witness bytes moving after ssh died —" | 2376 | echo " baseline, so it cannot witness bytes moving after ssh died —" |
| @@ -2372,28 +2378,16 @@ grep -q "cold-two" "$OUT.h1" && { | |||
| 2372 | echo " when the attach outruns this scenario's 6s script (~300ms" | 2378 | echo " when the attach outruns this scenario's 6s script (~300ms" |
| 2373 | echo " observed). A timing premise broke, not necessarily the product." | 2379 | echo " observed). A timing premise broke, not necessarily the product." |
| 2374 | exit 1; } | 2380 | exit 1; } |
| 2375 | wait_pid_gone "$HSHIMPID" "cold handoff: QUIC took over, so ssh must be gone" | ||
| 2376 | # ...and the session did not go with it. | 2381 | # ...and the session did not go with it. |
| 2377 | wait_for "$OUT.h1" "cold-two" 20 || { | 2382 | wait_for "$OUT.h1" "cold-two" 20 || { |
| 2378 | echo "e2e FAIL: cold handoff: the session stopped converging once ssh was gone," | 2383 | echo "e2e FAIL: cold handoff: the session stopped converging once ssh was gone," |
| 2379 | echo " so the bytes were riding the pipe rather than QUIC" | 2384 | echo " so the bytes were riding the pipe rather than QUIC" |
| 2380 | cat "$OUT.h1" "$OUT.h1.err" 2>/dev/null; exit 1; } | 2385 | cat "$OUT.h1" "$OUT.h1.err" 2>/dev/null; exit 1; } |
| 2381 | # The other half, and it pins a different property from the baseline | ||
| 2382 | # above. That one fixes the ORDER — the marker had not arrived when ssh | ||
| 2383 | # died, so its later arrival is post-death traffic. This one fixes the | ||
| 2384 | # DURATION: dead at one instant is not the claim, dead across the whole | ||
| 2385 | # window is, so the pid is re-observed now that the round trip is complete. | ||
| 2386 | # It also rules out the pid having been reused by an unrelated process | ||
| 2387 | # mid-window, which the single observation could not distinguish from a | ||
| 2388 | # corpse. | ||
| 2389 | kill -0 "$HSHIMPID" 2>/dev/null && { | ||
| 2390 | echo "e2e FAIL: cold handoff: ssh pid $HSHIMPID is alive again after the second" | ||
| 2391 | echo " marker; the death observed earlier was not the whole window" | ||
| 2392 | exit 1; } | ||
| 2393 | set +e | 2386 | set +e |
| 2394 | wait "$H1PID" | 2387 | wait "$H1PID" |
| 2395 | RC=$? | 2388 | RC=$? |
| 2396 | set -e | 2389 | set -e |
| 2390 | H1PID="" | ||
| 2397 | [ "$RC" -eq 0 ] || { | 2391 | [ "$RC" -eq 0 ] || { |
| 2398 | echo "e2e FAIL: cold handoff client exited $RC (want 0; 124 means it hung)" | 2392 | echo "e2e FAIL: cold handoff client exited $RC (want 0; 124 means it hung)" |
| 2399 | cat "$OUT.h1" "$OUT.h1.err" 2>/dev/null; exit 1; } | 2393 | cat "$OUT.h1" "$OUT.h1.err" 2>/dev/null; exit 1; } |
| @@ -2408,7 +2402,8 @@ grep -q '^muxd endpoint: starting' "$OUT.h1.err" || { | |||
| 2408 | HAPID=$(sed -n 's/.* pid=\([0-9]*\).*/\1/p' "$OUT.h1.err" | head -1) | 2402 | HAPID=$(sed -n 's/.* pid=\([0-9]*\).*/\1/p' "$OUT.h1.err" | head -1) |
| 2409 | [ -n "$HAPID" ] || { | 2403 | [ -n "$HAPID" ] || { |
| 2410 | echo "e2e FAIL: endpoint up-line carries no pid"; cat "$OUT.h1.err"; exit 1; } | 2404 | echo "e2e FAIL: endpoint up-line carries no pid"; cat "$OUT.h1.err"; exit 1; } |
| 2411 | kill -0 "$HAPID" || { echo "e2e FAIL: the handoff daemon is not alive"; exit 1; } | 2405 | kill -0 "$HAPID" 2>/dev/null || { |
| 2406 | echo "e2e FAIL: the handoff daemon (pid $HAPID) is not alive"; exit 1; } | ||
| 2412 | 2407 | ||
| 2413 | # The cache: present, private (it holds the key), and naming a port that is | 2408 | # The cache: present, private (it holds the key), and naming a port that is |
| 2414 | # really being listened on. The last one is the assertion that matters — | 2409 | # really being listened on. The last one is the assertion that matters — |
| @@ -2455,12 +2450,15 @@ grep -q "warm-ok" "$OUT.h2" || { | |||
| 2455 | echo "e2e FAIL: warm handoff served no session" | 2450 | echo "e2e FAIL: warm handoff served no session" |
| 2456 | cat "$OUT.h2" "$OUT.h2.err" 2>/dev/null; exit 1; } | 2451 | cat "$OUT.h2" "$OUT.h2.err" 2>/dev/null; exit 1; } |
| 2457 | HSHIMS_B2=$(wc -l < "$SSHIM_PIDLOG") | 2452 | HSHIMS_B2=$(wc -l < "$SSHIM_PIDLOG") |
| 2453 | # This also carries M13's warm-attach silence contract, which is why there | ||
| 2454 | # is no separate grep for spawn progress here: `muxd endpoint` is the only | ||
| 2455 | # thing that prints a starting line, it only runs under ssh, and ssh | ||
| 2456 | # provably did not run. A progress grep could therefore never fail on its | ||
| 2457 | # own — it would be a check the line above has already made. | ||
| 2458 | [ "$HSHIMS_B2" -eq "$HSHIMS_B" ] || { | 2458 | [ "$HSHIMS_B2" -eq "$HSHIMS_B" ] || { |
| 2459 | echo "e2e FAIL: warm handoff spawned ssh: pidlog went $HSHIMS_B -> $HSHIMS_B2" | 2459 | echo "e2e FAIL: warm handoff spawned ssh: pidlog went $HSHIMS_B -> $HSHIMS_B2" |
| 2460 | echo " (want unchanged — a cache hit dials QUIC and never shells out)" | 2460 | echo " (want unchanged — a cache hit dials QUIC and never shells out)" |
| 2461 | exit 1; } | 2461 | exit 1; } |
| 2462 | grep -q 'starting' "$OUT.h2.err" && { | ||
| 2463 | echo "e2e FAIL: warm handoff printed spawn progress"; cat "$OUT.h2.err"; exit 1; } | ||
| 2464 | grep -q 'unreachable, attaching over ssh' "$OUT.h2.err" && { | 2462 | grep -q 'unreachable, attaching over ssh' "$OUT.h2.err" && { |
| 2465 | echo "e2e FAIL: warm handoff printed the fallback line"; cat "$OUT.h2.err"; exit 1; } | 2463 | echo "e2e FAIL: warm handoff printed the fallback line"; cat "$OUT.h2.err"; exit 1; } |
| 2466 | assert_converged "$OUT.h2" "$SOCK16" "warm handoff" | 2464 | assert_converged "$OUT.h2" "$SOCK16" "warm handoff" |
| @@ -2494,12 +2492,21 @@ HHEXKEY=$(sed -n 's/^endpoint [0-9][0-9]* \([0-9a-f]*\)$/\1/p' "$HCACHE") | |||
| 2494 | printf 'endpoint %s %s\n' "$HDEADPORT" "$HHEXKEY" > "$HCACHE" | 2492 | printf 'endpoint %s %s\n' "$HDEADPORT" "$HHEXKEY" > "$HCACHE" |
| 2495 | chmod 600 "$HCACHE" | 2493 | chmod 600 "$HCACHE" |
| 2496 | HSHIMS_C=$(wc -l < "$SSHIM_PIDLOG") | 2494 | HSHIMS_C=$(wc -l < "$SSHIM_PIDLOG") |
| 2497 | set +e | 2495 | HT4=$(date +%s%N) |
| 2498 | { printf 'printf "heal-%%s\\n" ok\n'; sleep 6; printf '\034'; } | \ | 2496 | { printf 'printf "heal-%%s\\n" ok\n'; sleep 6; printf '\034'; } | \ |
| 2499 | SHELL=/bin/sh XDG_RUNTIME_DIR="$HRUN" PATH="$HPATH" timeout 40 \ | 2497 | SHELL=/bin/sh XDG_RUNTIME_DIR="$HRUN" PATH="$HPATH" timeout 40 \ |
| 2500 | "$MUX" "$HHOST" > "$OUT.h3" 2> "$OUT.h3.err" | 2498 | "$MUX" "$HHOST" > "$OUT.h3" 2> "$OUT.h3.err" & |
| 2499 | H3PID=$! | ||
| 2500 | wait_for "$OUT.h3" "heal-ok" 30 || { | ||
| 2501 | echo "e2e FAIL: stale-cache handoff never served a session" | ||
| 2502 | cat "$OUT.h3" "$OUT.h3.err" 2>/dev/null; exit 1; } | ||
| 2503 | HT5=$(date +%s%N) | ||
| 2504 | HMS_C=$(( (HT5 - HT4) / 1000000 )) | ||
| 2505 | set +e | ||
| 2506 | wait "$H3PID" | ||
| 2501 | RC=$? | 2507 | RC=$? |
| 2502 | set -e | 2508 | set -e |
| 2509 | H3PID="" | ||
| 2503 | [ "$RC" -eq 0 ] || { | 2510 | [ "$RC" -eq 0 ] || { |
| 2504 | echo "e2e FAIL: stale-cache handoff client exited $RC (want 0)" | 2511 | echo "e2e FAIL: stale-cache handoff client exited $RC (want 0)" |
| 2505 | cat "$OUT.h3" "$OUT.h3.err" 2>/dev/null; exit 1; } | 2512 | cat "$OUT.h3" "$OUT.h3.err" 2>/dev/null; exit 1; } |
| @@ -2520,8 +2527,21 @@ HSHIMS_C2=$(wc -l < "$SSHIM_PIDLOG") | |||
| 2520 | [ "$((HSHIMS_C2 - HSHIMS_C))" -eq 1 ] || { | 2527 | [ "$((HSHIMS_C2 - HSHIMS_C))" -eq 1 ] || { |
| 2521 | echo "e2e FAIL: the healing attach ran $((HSHIMS_C2 - HSHIMS_C)) ssh invocations, want 1" | 2528 | echo "e2e FAIL: the healing attach ran $((HSHIMS_C2 - HSHIMS_C)) ssh invocations, want 1" |
| 2522 | exit 1; } | 2529 | exit 1; } |
| 2530 | # The invariant this scenario is named for is "a stale cache costs TIME, | ||
| 2531 | # never correctness", and every check above measures only the correctness | ||
| 2532 | # half. The time is asserted here or the claim is unbacked: a build that | ||
| 2533 | # read no cache at all would take the cold path, heal, print nothing, and | ||
| 2534 | # spawn exactly one ssh — passing all six checks above while never paying | ||
| 2535 | # the cost the sentence is about. (Scenario (b) is what actually catches | ||
| 2536 | # that build; this floor is what keeps THIS scenario standing alone, since | ||
| 2537 | # the spec names it as the invariant's pin.) | ||
| 2538 | [ "$HMS_C" -ge 1500 ] || { | ||
| 2539 | echo "e2e FAIL: the stale-cache attach converged in ${HMS_C}ms, too fast to have" | ||
| 2540 | echo " dialled the poisoned port at all — the cache was not read, so" | ||
| 2541 | echo " nothing here witnessed a stale cache costing time" | ||
| 2542 | exit 1; } | ||
| 2523 | assert_converged "$OUT.h3" "$SOCK16" "stale-cache self-heal" | 2543 | assert_converged "$OUT.h3" "$SOCK16" "stale-cache self-heal" |
| 2524 | ok "a stale cache self-heals: one refetch, no fallback line, the real port cached" | 2544 | ok "a stale cache self-heals: one refetch (${HMS_C}ms), no fallback line, real port cached" |
| 2525 | 2545 | ||
| 2526 | # (d) FALLBACK LINE, by key mismatch. A second daemon holding a key nothing | 2546 | # (d) FALLBACK LINE, by key mismatch. A second daemon holding a key nothing |
| 2527 | # else on this box has; `muxd endpoint` announces the DEFAULT key (that is | 2547 | # else on this box has; `muxd endpoint` announces the DEFAULT key (that is |
| @@ -2545,20 +2565,22 @@ ok "a stale cache self-heals: one refetch, no fallback line, the real port cache | |||
| 2545 | # correct build never got as far as printing. | 2565 | # correct build never got as far as printing. |
| 2546 | head -c 32 /dev/urandom > "$HKEY" | 2566 | head -c 32 /dev/urandom > "$HKEY" |
| 2547 | chmod 600 "$HKEY" | 2567 | chmod 600 "$HKEY" |
| 2568 | # No --quic-idle-ms: the daemon's default is already 15000, and spelling | ||
| 2569 | # it here would suggest the ceiling's reasoning below depends on this | ||
| 2570 | # flag. It does not — the 15000 that bounds an overrunning dial is the | ||
| 2571 | # CLIENT's `quic_idle_ms_default`, which this daemon cannot influence. | ||
| 2548 | "$MUXD" run --sock "$SOCK17" --shell /bin/sh \ | 2572 | "$MUXD" run --sock "$SOCK17" --shell /bin/sh \ |
| 2549 | --quic "127.0.0.1:$HQPORT" --key "$HKEY" --quic-idle-ms 15000 & | 2573 | --quic "127.0.0.1:$HQPORT" --key "$HKEY" & |
| 2550 | HDPID=$! | 2574 | HDPID=$! |
| 2551 | i=0 | 2575 | i=0 |
| 2552 | while [ ! -S "$SOCK17" ] && [ "$i" -lt 50 ]; do sleep 0.1; i=$((i+1)); done | 2576 | while [ ! -S "$SOCK17" ] && [ "$i" -lt 50 ]; do sleep 0.1; i=$((i+1)); done |
| 2553 | [ -S "$SOCK17" ] || { echo "e2e FAIL: key-mismatch daemon never bound"; exit 1; } | 2577 | [ -S "$SOCK17" ] || { echo "e2e FAIL: key-mismatch daemon never bound"; exit 1; } |
| 2554 | HSHIMS_D=$(wc -l < "$SSHIM_PIDLOG") | 2578 | HSHIMS_D=$(wc -l < "$SSHIM_PIDLOG") |
| 2555 | HT0=$(date +%s%N) | 2579 | HT0=$(date +%s%N) |
| 2556 | set +e | ||
| 2557 | { printf 'printf "fallback-%%s\\n" ok\n'; sleep 6; printf '\034'; } | \ | 2580 | { printf 'printf "fallback-%%s\\n" ok\n'; sleep 6; printf '\034'; } | \ |
| 2558 | SHELL=/bin/sh XDG_RUNTIME_DIR="$HRUN2" PATH="$HPATH" timeout 40 \ | 2581 | SHELL=/bin/sh XDG_RUNTIME_DIR="$HRUN2" PATH="$HPATH" timeout 40 \ |
| 2559 | "$MUX" "127.0.0.1" > "$OUT.h4" 2> "$OUT.h4.err" & | 2582 | "$MUX" "127.0.0.1" > "$OUT.h4" 2> "$OUT.h4.err" & |
| 2560 | H4PID=$! | 2583 | H4PID=$! |
| 2561 | set -e | ||
| 2562 | # Timed to the LINE rather than to the client's exit: the line is printed | 2584 | # Timed to the LINE rather than to the client's exit: the line is printed |
| 2563 | # the moment the budget runs out, so the elapsed time here IS the deadline | 2585 | # the moment the budget runs out, so the elapsed time here IS the deadline |
| 2564 | # the dial spent, with no session sleeps folded into it. | 2586 | # the dial spent, with no session sleeps folded into it. |
| @@ -2610,6 +2632,7 @@ set +e | |||
| 2610 | wait "$H4PID" | 2632 | wait "$H4PID" |
| 2611 | RC=$? | 2633 | RC=$? |
| 2612 | set -e | 2634 | set -e |
| 2635 | H4PID="" | ||
| 2613 | [ "$RC" -eq 0 ] || { | 2636 | [ "$RC" -eq 0 ] || { |
| 2614 | echo "e2e FAIL: key-mismatch client exited $RC (want 0)" | 2637 | echo "e2e FAIL: key-mismatch client exited $RC (want 0)" |
| 2615 | cat "$OUT.h4" "$OUT.h4.err" 2>/dev/null; exit 1; } | 2638 | cat "$OUT.h4" "$OUT.h4.err" 2>/dev/null; exit 1; } |
| @@ -2637,13 +2660,11 @@ ok "a key mismatch falls back to the ssh pipe: one deadline (${HMS}ms), one line | |||
| 2637 | : > "$HCFGBAD" | 2660 | : > "$HCFGBAD" |
| 2638 | HSHIMS_E=$(wc -l < "$SSHIM_PIDLOG") | 2661 | HSHIMS_E=$(wc -l < "$SSHIM_PIDLOG") |
| 2639 | HT2=$(date +%s%N) | 2662 | HT2=$(date +%s%N) |
| 2640 | set +e | ||
| 2641 | { printf 'printf "none-%%s\\n" ok\n'; sleep 2.5; printf '\034'; } | \ | 2663 | { printf 'printf "none-%%s\\n" ok\n'; sleep 2.5; printf '\034'; } | \ |
| 2642 | SHELL=/bin/sh XDG_RUNTIME_DIR="$HRUN" XDG_CONFIG_HOME="$HCFGBAD" \ | 2664 | SHELL=/bin/sh XDG_RUNTIME_DIR="$HRUN" XDG_CONFIG_HOME="$HCFGBAD" \ |
| 2643 | PATH="$HPATH" timeout 40 \ | 2665 | PATH="$HPATH" timeout 40 \ |
| 2644 | "$MUX" "mux-e2e-none@127.0.0.1" > "$OUT.h5" 2> "$OUT.h5.err" & | 2666 | "$MUX" "mux-e2e-none@127.0.0.1" > "$OUT.h5" 2> "$OUT.h5.err" & |
| 2645 | H5PID=$! | 2667 | H5PID=$! |
| 2646 | set -e | ||
| 2647 | wait_for "$OUT.h5" "none-ok" 20 || { | 2668 | wait_for "$OUT.h5" "none-ok" 20 || { |
| 2648 | echo "e2e FAIL: announce-none handoff never served a session" | 2669 | echo "e2e FAIL: announce-none handoff never served a session" |
| 2649 | cat "$OUT.h5" "$OUT.h5.err" 2>/dev/null; exit 1; } | 2670 | cat "$OUT.h5" "$OUT.h5.err" 2>/dev/null; exit 1; } |
| @@ -2653,6 +2674,7 @@ set +e | |||
| 2653 | wait "$H5PID" | 2674 | wait "$H5PID" |
| 2654 | RC=$? | 2675 | RC=$? |
| 2655 | set -e | 2676 | set -e |
| 2677 | H5PID="" | ||
| 2656 | [ "$RC" -eq 0 ] || { | 2678 | [ "$RC" -eq 0 ] || { |
| 2657 | echo "e2e FAIL: announce-none client exited $RC (want 0)" | 2679 | echo "e2e FAIL: announce-none client exited $RC (want 0)" |
| 2658 | cat "$OUT.h5" "$OUT.h5.err" 2>/dev/null; exit 1; } | 2680 | cat "$OUT.h5" "$OUT.h5.err" 2>/dev/null; exit 1; } |
| @@ -2664,14 +2686,20 @@ grep -q '^muxd endpoint: .*staying on ssh' "$OUT.h5.err" || { | |||
| 2664 | # client never held coordinates to fail with. | 2686 | # client never held coordinates to fail with. |
| 2665 | # | 2687 | # |
| 2666 | # EVIDENCE NOTE, and it is written down precisely because a comment that | 2688 | # EVIDENCE NOTE, and it is written down precisely because a comment that |
| 2667 | # implied otherwise would be worse than the gap. Of this scenario's three | 2689 | # implied otherwise would be worse than the gap. This scenario makes seven |
| 2668 | # assertions only the staying-on-ssh grep above has been SHOWN able to | 2690 | # assertions in all; three of them are specific to what it claims — the |
| 2669 | # fail: deleting announceKey's create_failed message kills it, at 19 | 2691 | # staying-on-ssh line above, this absent fallback line, and the budget |
| 2670 | # checkpoints. This absent-grep and the budget bound below have never been | 2692 | # bound below — and only the FIRST has been shown able to fail (deleting |
| 2671 | # exercised by any mutation — the suite stops at its first failure and | 2693 | # announceKey's create_failed message kills it, at 19 checkpoints). The |
| 2672 | # every mutation tried so far dies in an earlier scenario. Neither is | 2694 | # other four are the shared shape every scenario here uses: exit status, |
| 2673 | # unfalsifiable: this grep is the same shape as (c)'s, which the | 2695 | # marker, pidlog delta, convergence, each exercised by mutations |
| 2674 | # deleted-fallback-line mutation did kill. They are untested, which is a | 2696 | # elsewhere. |
| 2697 | # | ||
| 2698 | # So these two have never been exercised by any mutation — the suite stops | ||
| 2699 | # at its first failure and every mutation tried so far dies in an earlier | ||
| 2700 | # scenario. Neither is unfalsifiable: this grep is the same shape as (c)'s, | ||
| 2701 | # which the deleted-fallback-line mutation did kill, and the bound below | ||
| 2702 | # fires on any number at or above it. They are untested, which is a | ||
| 2675 | # different thing, and Task 8's regrade can take one if it comes cheap. | 2703 | # different thing, and Task 8's regrade can take one if it comes cheap. |
| 2676 | grep -q 'unreachable, attaching over ssh' "$OUT.h5.err" && { | 2704 | grep -q 'unreachable, attaching over ssh' "$OUT.h5.err" && { |
| 2677 | echo "e2e FAIL: announce-none printed the fallback line; no dial was ever possible" | 2705 | echo "e2e FAIL: announce-none printed the fallback line; no dial was ever possible" |
| @@ -2681,12 +2709,20 @@ HSHIMS_E2=$(wc -l < "$SSHIM_PIDLOG") | |||
| 2681 | echo "e2e FAIL: announce-none ran $((HSHIMS_E2 - HSHIMS_E)) ssh invocations, want 1" | 2709 | echo "e2e FAIL: announce-none ran $((HSHIMS_E2 - HSHIMS_E)) ssh invocations, want 1" |
| 2682 | exit 1; } | 2710 | exit 1; } |
| 2683 | # No budget spent, measured to the first marker rather than to exit. The | 2711 | # No budget spent, measured to the first marker rather than to exit. The |
| 2684 | # bound is the 2000ms deadline with room to spare for an attach that has | 2712 | # bound sits at 1500 rather than at the 2000ms budget itself so that a |
| 2685 | # to spawn a shell through two processes: anything at or above the budget | 2713 | # slow-but-honest attach still passes; what it cannot do is name a cause |
| 2686 | # means a dial happened that the announce said was impossible. | 2714 | # it has not proved. A dial that ran its full budget lands at 2000+ |
| 2715 | # (measured 2026-2129 in scenario (d)); anything between 1500 and 2000 is | ||
| 2716 | # an attach that was merely slow, or one that started a dial it should | ||
| 2717 | # never have begun. The message therefore reports the number and says | ||
| 2718 | # which readings are which, rather than asserting a spent budget on | ||
| 2719 | # evidence that cannot distinguish one. | ||
| 2687 | [ "$HMS_E" -lt 1500 ] || { | 2720 | [ "$HMS_E" -lt 1500 ] || { |
| 2688 | echo "e2e FAIL: announce-none took ${HMS_E}ms to converge; a QUIC budget was" | 2721 | echo "e2e FAIL: announce-none took ${HMS_E}ms to converge, over the 1500ms bound." |
| 2689 | echo " spent on coordinates the remote said it did not have" | 2722 | echo " At or above ~2000ms a full QUIC budget was spent, on coordinates" |
| 2723 | echo " the remote said it did not have. Below that it is either load or" | ||
| 2724 | echo " a dial that began and was cut short — check which before blaming" | ||
| 2725 | echo " the machine." | ||
| 2690 | exit 1; } | 2726 | exit 1; } |
| 2691 | assert_converged "$OUT.h5" "$SOCK16" "announce-none stays on ssh" | 2727 | assert_converged "$OUT.h5" "$SOCK16" "announce-none stays on ssh" |
| 2692 | ok "announce-none stays on ssh: no deadline paid (${HMS_E}ms), no fallback line" | 2728 | ok "announce-none stays on ssh: no deadline paid (${HMS_E}ms), no fallback line" |