a73x

818302fd

test: convergence on the prediction scenarios; stats reads move to split stderr

a73x   2026-08-09 17:31

Commit message
test: convergence on the prediction scenarios; stats reads move to split stderr
test/e2e.sh
Old New
@@ -203,6 +203,7 @@ cleanup() {
203 "$OUT.m7.err" "$OUT.m7b.err" "$OUT.qc.err" "$OUT.qr.err" "$OUT.qk.err" \ 203 "$OUT.m7.err" "$OUT.m7b.err" "$OUT.qc.err" "$OUT.qr.err" "$OUT.qk.err" \
204 "$SOCK5" "$SOCK6" "$SOCK7" "$PWSH" \ 204 "$SOCK5" "$SOCK6" "$SOCK7" "$PWSH" \
205 "$OUT.p1" "$OUT.p1.early" "$OUT.pb" "$OUT.pw" "$OUT.rw" "$OUT.pr" \ 205 "$OUT.p1" "$OUT.p1.early" "$OUT.pb" "$OUT.pw" "$OUT.rw" "$OUT.pr" \
206 "$OUT.p1.err" "$OUT.pb.err" "$OUT.pw.err" "$OUT.rw.err" "$OUT.pr.err" \
206 "$SOCK" "$SOCK2" "$SOCK3" "$SOCK4" "$SOCK4.second" "$QKEY" "$QKEY.bad" \ 207 "$SOCK" "$SOCK2" "$SOCK3" "$SOCK4" "$SOCK4.second" "$QKEY" "$QKEY.bad" \
207 "$OUT" "$OUT.kill" "$OUT.re" "$OUT.a" \ 208 "$OUT" "$OUT.kill" "$OUT.re" "$OUT.a" \
208 "$OUT.b" "$OUT.via" "$OUT.dead" "$OUT.abort" "$OUT.m7" "$OUT.m7b" \ 209 "$OUT.b" "$OUT.via" "$OUT.dead" "$OUT.abort" "$OUT.m7" "$OUT.m7b" \
@@ -1175,7 +1176,7 @@ set +e
1175 { sleep 2; printf 'z'; sleep 4; printf '\034'; } | \ 1176 { sleep 2; printf 'z'; sleep 4; printf '\034'; } | \
1176 DELAY_MS="$PDELAY" MUX_PREDICT_STATS=1 timeout 40 "$MUX" \ 1177 DELAY_MS="$PDELAY" MUX_PREDICT_STATS=1 timeout 40 "$MUX" \
1177 --via "$DELAYPIPE | $MUXD proxy --sock $SOCK5 | $DELAYPIPE" \ 1178 --via "$DELAYPIPE | $MUXD proxy --sock $SOCK5 | $DELAYPIPE" \
1178 > "$OUT.p1" 2>&1 & 1179 > "$OUT.p1" 2> "$OUT.p1.err" &
1179 P1PID=$! 1180 P1PID=$!
1180 set -e 1181 set -e
1181 # Snapshot the client output 450ms after the keystroke: well 1182 # Snapshot the client output 450ms after the keystroke: well
@@ -1187,7 +1188,9 @@ set +e
1187 wait "$P1PID" 1188 wait "$P1PID"
1188 RC=$? 1189 RC=$?
1189 set -e 1190 set -e
1190 [ "$RC" -eq 0 ] || { echo "e2e FAIL: line-mode prediction client exited $RC"; cat "$OUT.p1"; exit 1; } 1191 [ "$RC" -eq 0 ] || {
1192 echo "e2e FAIL: line-mode prediction client exited $RC"
1193 cat "$OUT.p1" "$OUT.p1.err" 2>/dev/null; exit 1; }
1191 1194
1192 # The underlined glyph, in the snapshot taken before the echo could arrive. 1195 # The underlined glyph, in the snapshot taken before the echo could arrive.
1193 # This is the whole claim of the milestone, as an effect rather than a 1196 # This is the whole claim of the milestone, as an effect rather than a
@@ -1204,15 +1207,16 @@ if grep -q "$(printf '\033\[2K\033\[0mz')" "$OUT.p1.early"; then
1204 echo " either DELAY_MS was ignored (default is 150) or delaypipe is not delaying" 1207 echo " either DELAY_MS was ignored (default is 150) or delaypipe is not delaying"
1205 exit 1 1208 exit 1
1206 fi 1209 fi
1207 want_stat "$OUT.p1" contradicted 0 "line mode" 1210 want_stat "$OUT.p1.err" contradicted 0 "line mode"
1208 CONF=$(predict_stat "$OUT.p1" confirmed) 1211 CONF=$(predict_stat "$OUT.p1.err" confirmed)
1209 [ -n "$CONF" ] && [ "$CONF" -ge 1 ] || { 1212 [ -n "$CONF" ] && [ "$CONF" -ge 1 ] || {
1210 echo "e2e FAIL: line mode: confirmed=$CONF, want >=1"; grep "^predict " "$OUT.p1"; exit 1; 1213 echo "e2e FAIL: line mode: confirmed=$CONF, want >=1"; grep "^predict " "$OUT.p1.err"; exit 1;
1211 } 1214 }
1212 # The session really received the keystroke: cat echoed it into the grid. 1215 # The session really received the keystroke: cat echoed it into the grid.
1213 "$MUXD" dump --sock "$SOCK5" | grep -q "z" || { 1216 "$MUXD" dump --sock "$SOCK5" | grep -q "z" || {
1214 echo "e2e FAIL: line mode: daemon grid never saw the keystroke"; exit 1; 1217 echo "e2e FAIL: line mode: daemon grid never saw the keystroke"; exit 1;
1215 } 1218 }
1219 assert_converged "$OUT.p1" "$SOCK5" "line-mode prediction"
1216 1220
1217 # 2. A burst outrunning the round trip. This is reconcile v2's reason to 1221 # 2. A burst outrunning the round trip. This is reconcile v2's reason to
1218 # exist: under the old rule every character after the first was judged by 1222 # exist: under the old rule every character after the first was judged by
@@ -1224,16 +1228,18 @@ set +e
1224 sleep 4; printf '\034'; } | \ 1228 sleep 4; printf '\034'; } | \
1225 DELAY_MS="$PDELAY" MUX_PREDICT_STATS=1 timeout 40 "$MUX" \ 1229 DELAY_MS="$PDELAY" MUX_PREDICT_STATS=1 timeout 40 "$MUX" \
1226 --via "$DELAYPIPE | $MUXD proxy --sock $SOCK5 | $DELAYPIPE" \ 1230 --via "$DELAYPIPE | $MUXD proxy --sock $SOCK5 | $DELAYPIPE" \
1227 > "$OUT.pb" 2>&1 1231 > "$OUT.pb" 2> "$OUT.pb.err"
1228 RC=$? 1232 RC=$?
1229 set -e 1233 set -e
1230 [ "$RC" -eq 0 ] || { echo "e2e FAIL: burst client exited $RC"; cat "$OUT.pb"; exit 1; } 1234 [ "$RC" -eq 0 ] || {
1235 echo "e2e FAIL: burst client exited $RC"
1236 cat "$OUT.pb" "$OUT.pb.err" 2>/dev/null; exit 1; }
1231 1237
1232 # Five keystrokes typed at 200ms into a 600ms round trip: three are always 1238 # Five keystrokes typed at 200ms into a 600ms round trip: three are always
1233 # outstanding at once. `made` is asserted too, so two keystrokes arriving in 1239 # outstanding at once. `made` is asserted too, so two keystrokes arriving in
1234 # one read (which would be suppressed as a multi-byte chunk, not predicted) 1240 # one read (which would be suppressed as a multi-byte chunk, not predicted)
1235 # fails loudly instead of quietly weakening the test. 1241 # fails loudly instead of quietly weakening the test.
1236 want_stat "$OUT.pb" made 5 "burst" 1242 want_stat "$OUT.pb.err" made 5 "burst"
1237 # `confirmed` is a LIVENESS counter and the only timing-dependent one here: 1243 # `confirmed` is a LIVENESS counter and the only timing-dependent one here:
1238 # the fifth confirmation can still be in flight when the detach byte lands, 1244 # the fifth confirmation can still be in flight when the detach byte lands,
1239 # which is why it is a floor rather than an equality. Observed 1 run in 3 1245 # which is why it is a floor rather than an equality. Observed 1 run in 3
@@ -1244,12 +1250,13 @@ want_stat "$OUT.pb" made 5 "burst"
1244 # `contradicted` and `expired` stay EXACT. They are the correctness claims — 1250 # `contradicted` and `expired` stay EXACT. They are the correctness claims —
1245 # a prediction judged wrong, or one that aged out unjudged, is a defect 1251 # a prediction judged wrong, or one that aged out unjudged, is a defect
1246 # whenever it happens, and nothing about timing makes either acceptable. 1252 # whenever it happens, and nothing about timing makes either acceptable.
1247 want_stat_ge "$OUT.pb" confirmed 4 "burst" 1253 want_stat_ge "$OUT.pb.err" confirmed 4 "burst"
1248 want_stat "$OUT.pb" contradicted 0 "burst" 1254 want_stat "$OUT.pb.err" contradicted 0 "burst"
1249 want_stat "$OUT.pb" expired 0 "burst" 1255 want_stat "$OUT.pb.err" expired 0 "burst"
1250 "$MUXD" dump --sock "$SOCK5" | grep -q "burst" || { 1256 "$MUXD" dump --sock "$SOCK5" | grep -q "burst" || {
1251 echo "e2e FAIL: burst: daemon grid does not hold the typed text"; exit 1; 1257 echo "e2e FAIL: burst: daemon grid does not hold the typed text"; exit 1;
1252 } 1258 }
1259 assert_converged "$OUT.pb" "$SOCK5" "burst"
1253 1260
1254 kill "$D5PID" 2>/dev/null || true 1261 kill "$D5PID" 2>/dev/null || true
1255 D5PID="" 1262 D5PID=""
@@ -1284,19 +1291,23 @@ while [ ! -S "$SOCK6" ] && [ "$i" -lt 50 ]; do sleep 0.1; i=$((i+1)); done
1284 set +e 1291 set +e
1285 { sleep 2; for c in h u n t e r 2; do printf '%s' "$c"; sleep 0.2; done; \ 1292 { sleep 2; for c in h u n t e r 2; do printf '%s' "$c"; sleep 0.2; done; \
1286 printf '\n'; sleep 2; printf '\034'; } | \ 1293 printf '\n'; sleep 2; printf '\034'; } | \
1287 MUX_PREDICT_STATS=1 timeout 40 "$MUX" --sock "$SOCK6" > "$OUT.pw" 2>&1 1294 MUX_PREDICT_STATS=1 timeout 40 "$MUX" --sock "$SOCK6" > "$OUT.pw" 2> "$OUT.pw.err"
1288 RC=$? 1295 RC=$?
1289 set -e 1296 set -e
1290 [ "$RC" -eq 0 ] || { echo "e2e FAIL: password client exited $RC"; cat "$OUT.pw"; exit 1; } 1297 [ "$RC" -eq 0 ] || {
1298 echo "e2e FAIL: password client exited $RC"
1299 cat "$OUT.pw" "$OUT.pw.err" 2>/dev/null; exit 1; }
1291 1300
1292 # Nothing was shown, and nothing was even attempted: echo-off canonical is 1301 # Nothing was shown, and nothing was even attempted: echo-off canonical is
1293 # the tier where a prediction must never be MADE, not merely never painted, 1302 # the tier where a prediction must never be MADE, not merely never painted,
1294 # because a made prediction sits in a buffer the overlay paints from. 1303 # because a made prediction sits in a buffer the overlay paints from.
1295 want_stat "$OUT.pw" made 0 "password" 1304 want_stat "$OUT.pw.err" made 0 "password"
1296 want_stat "$OUT.pw" displayed 0 "password" 1305 want_stat "$OUT.pw.err" displayed 0 "password"
1297 # The effect, not the counter: the secret appears nowhere in the bytes the 1306 # The effect, not the counter: the secret appears nowhere in the bytes the
1298 # client wrote to the terminal. 1307 # client wrote — either stream. The stats line cannot carry a secret, but
1299 if grep -q "hunter2" "$OUT.pw"; then 1308 # checking both costs one word and the claim is about everything the client
1309 # emitted, not about the half of it that happens to be the screen.
1310 if grep -q "hunter2" "$OUT.pw" "$OUT.pw.err"; then
1300 echo "e2e FAIL: the password appears in the client's terminal output"; exit 1 1311 echo "e2e FAIL: the password appears in the client's terminal output"; exit 1
1301 fi 1312 fi
1302 # ...and the run was not vacuous: the shell really received all seven 1313 # ...and the run was not vacuous: the shell really received all seven
@@ -1306,6 +1317,7 @@ fi
1306 echo "e2e FAIL: the password never reached the shell; the absence above proves nothing" 1317 echo "e2e FAIL: the password never reached the shell; the absence above proves nothing"
1307 "$MUXD" dump --sock "$SOCK6"; exit 1; 1318 "$MUXD" dump --sock "$SOCK6"; exit 1;
1308 } 1319 }
1320 assert_converged "$OUT.pw" "$SOCK6" "password"
1309 1321
1310 kill "$D6PID" 2>/dev/null || true 1322 kill "$D6PID" 2>/dev/null || true
1311 D6PID="" 1323 D6PID=""
@@ -1322,35 +1334,41 @@ while [ ! -S "$SOCK7" ] && [ "$i" -lt 50 ]; do sleep 0.1; i=$((i+1)); done
1322 set +e 1334 set +e
1323 { sleep 2; for c in a b c; do printf '%s' "$c"; sleep 0.5; done; \ 1335 { sleep 2; for c in a b c; do printf '%s' "$c"; sleep 0.5; done; \
1324 printf '\000'; sleep 0.5; printf 'j'; sleep 2.5; printf '\034'; } | \ 1336 printf '\000'; sleep 0.5; printf 'j'; sleep 2.5; printf '\034'; } | \
1325 MUX_PREDICT_STATS=1 timeout 40 "$MUX" --sock "$SOCK7" > "$OUT.rw" 2>&1 1337 MUX_PREDICT_STATS=1 timeout 40 "$MUX" --sock "$SOCK7" > "$OUT.rw" 2> "$OUT.rw.err"
1326 RC=$? 1338 RC=$?
1327 set -e 1339 set -e
1328 [ "$RC" -eq 0 ] || { echo "e2e FAIL: rawmode client exited $RC"; cat "$OUT.rw"; exit 1; } 1340 [ "$RC" -eq 0 ] || {
1341 echo "e2e FAIL: rawmode client exited $RC"
1342 cat "$OUT.rw" "$OUT.rw.err" 2>/dev/null; exit 1; }
1329 1343
1330 # Four printable keystrokes made predictions; the 0x00 that switched modes 1344 # Four printable keystrokes made predictions; the 0x00 that switched modes
1331 # is not printable and was refused. 1345 # is not printable and was refused.
1332 want_stat "$OUT.rw" made 4 "raw mode" 1346 want_stat "$OUT.rw.err" made 4 "raw mode"
1333 want_stat "$OUT.rw" suppressed 1 "raw mode" 1347 want_stat "$OUT.rw.err" suppressed 1 "raw mode"
1334 # a and b are invisible while promotion is earned; c is the first painted, 1348 # a and b are invisible while promotion is earned; c is the first painted,
1335 # and j is painted because by then display had been earned. 1349 # and j is painted because by then display had been earned.
1336 want_stat "$OUT.rw" displayed 2 "raw mode" 1350 want_stat "$OUT.rw.err" displayed 2 "raw mode"
1337 want_stat "$OUT.rw" confirmed 3 "raw mode" 1351 want_stat "$OUT.rw.err" confirmed 3 "raw mode"
1338 # j was swallowed: no frame ever answered the cell it was drawn in, so the 1352 # j was swallowed: no frame ever answered the cell it was drawn in, so the
1339 # expiry bound retired it rather than leaving a phantom glyph on screen for 1353 # expiry bound retired it rather than leaving a phantom glyph on screen for
1340 # the rest of the session. 1354 # the rest of the session.
1341 want_stat "$OUT.rw" expired 1 "raw mode" 1355 want_stat "$OUT.rw.err" expired 1 "raw mode"
1342 want_stat "$OUT.rw" contradicted 1 "raw mode" 1356 want_stat "$OUT.rw.err" contradicted 1 "raw mode"
1343 want_stat "$OUT.rw" abandoned 1 "raw mode" 1357 want_stat "$OUT.rw.err" abandoned 1 "raw mode"
1344 1358
1345 # Every prediction accounted for: made = confirmed + abandoned + pending, 1359 # Every prediction accounted for: made = confirmed + abandoned + pending,
1346 # and the queue is empty at exit, so nothing survived unexplained. 1360 # and the queue is empty at exit, so nothing survived unexplained.
1347 RW_MADE=$(predict_stat "$OUT.rw" made) 1361 RW_MADE=$(predict_stat "$OUT.rw.err" made)
1348 RW_CONF=$(predict_stat "$OUT.rw" confirmed) 1362 RW_CONF=$(predict_stat "$OUT.rw.err" confirmed)
1349 RW_ABND=$(predict_stat "$OUT.rw" abandoned) 1363 RW_ABND=$(predict_stat "$OUT.rw.err" abandoned)
1350 [ "$((RW_MADE - RW_CONF - RW_ABND))" -eq 0 ] || { 1364 [ "$((RW_MADE - RW_CONF - RW_ABND))" -eq 0 ] || {
1351 echo "e2e FAIL: raw mode: $((RW_MADE - RW_CONF - RW_ABND)) predictions unaccounted for" 1365 echo "e2e FAIL: raw mode: $((RW_MADE - RW_CONF - RW_ABND)) predictions unaccounted for"
1352 grep "^predict " "$OUT.rw"; exit 1; 1366 grep "^predict " "$OUT.rw.err"; exit 1;
1353 } 1367 }
1368 # The counters say `j` expired; this says the screen agrees. An expiry that
1369 # retired the prediction in the book but left its underlined glyph painted is
1370 # exactly the phantom the styled half of this check exists to catch.
1371 assert_converged "$OUT.rw" "$SOCK7" "raw mode"
1354 1372
1355 kill "$D7PID" 2>/dev/null || true 1373 kill "$D7PID" 2>/dev/null || true
1356 D7PID="" 1374 D7PID=""
@@ -1368,7 +1386,7 @@ set +e
1368 { sleep 2; printf 'p'; sleep 5; printf 'q'; sleep 4; printf '\034'; } | \ 1386 { sleep 2; printf 'p'; sleep 5; printf 'q'; sleep 4; printf '\034'; } | \
1369 DELAY_MS="$PDELAY" MUX_PREDICT_STATS=1 timeout 60 "$MUX" \ 1387 DELAY_MS="$PDELAY" MUX_PREDICT_STATS=1 timeout 60 "$MUX" \
1370 --via "$DELAYPIPE | $MUXD proxy --sock $SOCK5 | $DELAYPIPE" \ 1388 --via "$DELAYPIPE | $MUXD proxy --sock $SOCK5 | $DELAYPIPE" \
1371 > "$OUT.pr" 2>&1 & 1389 > "$OUT.pr" 2> "$OUT.pr.err" &
1372 PRPID=$! 1390 PRPID=$!
1373 set -e 1391 set -e
1374 # Kill the transport a tenth of a second after the keystroke, while its 1392 # Kill the transport a tenth of a second after the keystroke, while its
@@ -1377,36 +1395,42 @@ set -e
1377 # --via string, so a pattern kill would take out the client under test. 1395 # --via string, so a pattern kill would take out the client under test.
1378 sleep 2.1 1396 sleep 2.1
1379 PP=$(proxy_pid "$SOCK5") 1397 PP=$(proxy_pid "$SOCK5")
1380 [ -n "$PP" ] || { echo "e2e FAIL: no proxy to tear down"; cat "$OUT.pr"; exit 1; } 1398 [ -n "$PP" ] || {
1399 echo "e2e FAIL: no proxy to tear down"
1400 cat "$OUT.pr" "$OUT.pr.err" 2>/dev/null; exit 1; }
1381 kill -9 "$PP" 1401 kill -9 "$PP"
1382 1402
1383 set +e 1403 set +e
1384 wait "$PRPID" 1404 wait "$PRPID"
1385 RC=$? 1405 RC=$?
1386 set -e 1406 set -e
1387 [ "$RC" -eq 0 ] || { echo "e2e FAIL: reconnect client exited $RC"; cat "$OUT.pr"; exit 1; } 1407 [ "$RC" -eq 0 ] || {
1408 echo "e2e FAIL: reconnect client exited $RC"
1409 cat "$OUT.pr" "$OUT.pr.err" 2>/dev/null; exit 1; }
1388 1410
1389 # The queue is empty at exit, by attribution rather than by inspection: 1411 # The queue is empty at exit, by attribution rather than by inspection:
1390 # nothing predicted is still outstanding, and the flush that dropped the 1412 # nothing predicted is still outstanding, and the flush that dropped the
1391 # in-flight prediction was not counted as anybody being wrong. 1413 # in-flight prediction was not counted as anybody being wrong.
1392 PR_MADE=$(predict_stat "$OUT.pr" made) 1414 PR_MADE=$(predict_stat "$OUT.pr.err" made)
1393 PR_CONF=$(predict_stat "$OUT.pr" confirmed) 1415 PR_CONF=$(predict_stat "$OUT.pr.err" confirmed)
1394 PR_ABND=$(predict_stat "$OUT.pr" abandoned) 1416 PR_ABND=$(predict_stat "$OUT.pr.err" abandoned)
1395 [ -n "$PR_MADE" ] || { echo "e2e FAIL: reconnect: no predict stats"; cat "$OUT.pr"; exit 1; } 1417 [ -n "$PR_MADE" ] || {
1418 echo "e2e FAIL: reconnect: no predict stats"
1419 cat "$OUT.pr" "$OUT.pr.err" 2>/dev/null; exit 1; }
1396 [ "$((PR_MADE - PR_CONF - PR_ABND))" -eq 0 ] || { 1420 [ "$((PR_MADE - PR_CONF - PR_ABND))" -eq 0 ] || {
1397 echo "e2e FAIL: reconnect: $((PR_MADE - PR_CONF - PR_ABND)) predictions outlived the tear" 1421 echo "e2e FAIL: reconnect: $((PR_MADE - PR_CONF - PR_ABND)) predictions outlived the tear"
1398 grep "^predict " "$OUT.pr"; exit 1; 1422 grep "^predict " "$OUT.pr.err"; exit 1;
1399 } 1423 }
1400 # And it was the reconnect that dropped it, not the expiry bound catching it 1424 # And it was the reconnect that dropped it, not the expiry bound catching it
1401 # a second later. Without this the scenario cannot tell the two apart: the 1425 # a second later. Without this the scenario cannot tell the two apart: the
1402 # resync after a reconnect flushes as well, so the outcome looks identical 1426 # resync after a reconnect flushes as well, so the outcome looks identical
1403 # either way and removing the reconnect's own flush passes unnoticed. It 1427 # either way and removing the reconnect's own flush passes unnoticed. It
1404 # did, until this line. 1428 # did, until this line.
1405 want_stat "$OUT.pr" expired 0 "reconnect" 1429 want_stat "$OUT.pr.err" expired 0 "reconnect"
1406 [ -n "$PR_ABND" ] && [ "$PR_ABND" -ge 1 ] || { 1430 [ -n "$PR_ABND" ] && [ "$PR_ABND" -ge 1 ] || {
1407 echo "e2e FAIL: reconnect: nothing was abandoned ($PR_ABND), so no prediction was" 1431 echo "e2e FAIL: reconnect: nothing was abandoned ($PR_ABND), so no prediction was"
1408 echo " outstanding when the transport died and the tear proves nothing" 1432 echo " outstanding when the transport died and the tear proves nothing"
1409 grep "^predict " "$OUT.pr"; exit 1; 1433 grep "^predict " "$OUT.pr.err"; exit 1;
1410 } 1434 }
1411 # The session survived and the client resumed into it: the keystroke typed 1435 # The session survived and the client resumed into it: the keystroke typed
1412 # after the tear reached the shell. 1436 # after the tear reached the shell.
@@ -1414,6 +1438,7 @@ want_stat "$OUT.pr" expired 0 "reconnect"
1414 echo "e2e FAIL: reconnect: the post-tear keystroke never reached the session" 1438 echo "e2e FAIL: reconnect: the post-tear keystroke never reached the session"
1415 "$MUXD" dump --sock "$SOCK5"; exit 1; 1439 "$MUXD" dump --sock "$SOCK5"; exit 1;
1416 } 1440 }
1441 assert_converged "$OUT.pr" "$SOCK5" "reconnect flush"
1417 1442
1418 kill "$D5PID" 2>/dev/null || true 1443 kill "$D5PID" 2>/dev/null || true
1419 D5PID="" 1444 D5PID=""