a73x

9a3c7535

fix(wan): the authoritative clock was timing the wrong thing

a73x   2026-08-08 17:49

Commit message
fix(wan): the authoritative clock was timing the wrong thing

predictauth searched the whole capture buffer, so rep 0's one-character
needle matched the shell's echo of the `cat` typed during setup and stopped
the clock at once. That is where the record's 0.3ms minimum came from: not a
fast round trip, a needle that was already on screen.

Two faults, both fixed. The search starts from the keystroke now, like the
other two clocks. And rep 0 contributes no authoritative sample at all,
because a one-character needle is a substring of the prediction's own
ESC[4mX paint — searching from the right place would still have timed the
prediction instead of the echo. Nineteen samples for twenty keystrokes, and
the reason is written where the sample is dropped.

Re-run on the box confirms it: predictauth min goes 0.3 -> 154.0, agreeing
with predictoff, which measures the same physical quantity by an
independent route. That agreement is the check that the new number is right
and the old one never was.

Also: an absent control now FAILS leg 1 rather than being skipped. The gate
existed for a control that comes back too fast; a control that is not there
at all is the same hole and was not covered. Both controls are required to
be present and slow before leg 1 can pass, and the leg prints its own PASS
line rather than implying it.

Record corrected from the new run throughout, including the burst counters
(made=55, one abandoned by the mode-transition flush as `cat` starts), and
the reps this run actually used, so every n in the table follows from
something written down. "One keystroke, two clocks" moves to the pair it
describes — the predicted and authoritative times share a keypress; the
unpredicted control does not and never claimed to.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>

docs/decisions.md
Old New
@@ -958,17 +958,40 @@ printed beside the result).
958 958
959 | | min | med | max | n | 959 | | min | med | max | n |
960 |---|---|---|---|---| 960 |---|---|---|---|---|
961 | baseline (the path) | 150.4 | 150.5 | 150.5 | 10 | 961 | baseline (the path) | 150.4 | 150.5 | 150.7 | 10 |
962 | predicted paint | 0.1 | **0.1** | 0.3 | 20 | 962 | predicted paint | 0.1 | **0.1** | 0.2 | 20 |
963 | unpredicted input | 153.8 | **154.2** | 154.8 | 10 | 963 | unpredicted input | 154.0 | **154.3** | 154.7 | 10 |
964 | same keystroke's authoritative echo | 0.3 | 154.2 | 154.6 | 20 | 964 | same keystroke's authoritative echo | 154.0 | 154.2 | 154.6 | 19 |
965 | burst convergence | 233.4 | 233.8 | 234.2 | 10 | 965 | burst convergence | 233.3 | 233.8 | 234.7 | 10 |
966
967 Reps are not all defaults: this run set `MUX_WAN_REPS_BASE=10` (default 20)
968 and cut the M6/M7 phases to 1 rep each, since it was measuring M9 and not
969 re-certifying them. That is where the baseline's n=10 comes from, and it is
970 recorded because an `n` that follows from neither the defaults nor the text
971 is an invitation to distrust the rest of the table. `predictauth`'s n=19 for
972 20 keystrokes is explained below.
973
974 **An artefact was found in review and is gone from these numbers.** The
975 first published table gave `predictauth` a min of 0.3ms, which is not a
976 measurement of anything: that clock searched the whole capture buffer, so
977 rep 0's one-character needle matched the shell's echo of the `cat` command
978 typed during setup and stopped the clock at once. Two things were wrong and
979 both are fixed — the search now starts from the keystroke, and rep 0
980 contributes no authoritative sample at all, because a one-character needle
981 is a substring of the prediction's own `ESC[4mX` paint and would time the
982 prediction instead of the echo. Hence 19 samples for 20 keystrokes. The
983 corrected min is 154.0ms, which agrees with the independent `predictoff`
984 control measuring the same physical quantity — the agreement is the check
985 that the fix is right and the old number was not.
966 986
967 - **Leg 1 (latency) — cleared.** 0.1ms median against a 30ms threshold, at a 987 - **Leg 1 (latency) — cleared.** 0.1ms median against a 30ms threshold, at a
968 round trip three orders of magnitude larger. 988 round trip three orders of magnitude larger.
969 - **Leg 2 (convergence) — cleared, in the narrowed form below.** Ten 989 - **Leg 2 (convergence) — cleared, in the narrowed form below.** Ten
970 adversarial bursts: `made=54 confirmed=54 contradicted=0 expired=0 990 adversarial bursts: `made=55 confirmed=54 contradicted=0 expired=0
971 abandoned=0 pending=0`, last burst present in the daemon's grid. 991 abandoned=1 pending=0`, last burst present in the daemon's grid. The one
992 abandoned prediction is a flush, not a wrong guess — the mode transition
993 as `cat` starts takes the queue with it, which is the churn policy doing
994 exactly what it is for.
972 - **Leg 3 (safety) — cleared by the e2e suite**, not by the WAN harness. A 995 - **Leg 3 (safety) — cleared by the e2e suite**, not by the WAN harness. A
973 session that is canonical with echo off from its first instruction makes 996 session that is canonical with echo off from its first instruction makes
974 **nothing**: `made=0 displayed=0`, the typed secret appears nowhere in the 997 **nothing**: `made=0 displayed=0`, the typed secret appears nowhere in the
@@ -982,13 +1005,20 @@ printed beside the result).
982 ### The control is the measurement 1005 ### The control is the measurement
983 1006
984 Leg 1's number means nothing on its own — a fast local paint is what a 1007 Leg 1's number means nothing on its own — a fast local paint is what a
985 terminal does anyway. What makes it evidence is that the **unpredicted** 1008 terminal does anyway. It takes **two** controls to make it evidence, and
986 control was taken on the same connection in the same run, from the same 1009 they answer different objections:
987 kind of keystroke, and came back at 154.2ms. One keystroke, two clocks: no 1010
988 argument about warm caches, differing conditions or hardware can be made 1011 - **The unpredicted control** (`predictoff`, 154.3ms). Input prediction
989 about the gap between them. 1012 refuses, typed on the same connection in the same run. This is what rules
990 1013 out the fast number being an artefact of the machine or the harness: if
991 Two things about that control are worth keeping. 1014 prediction were not doing the work, this would be fast too.
1015 - **The authoritative echo** (`predictauth`, 154.2ms). *One keystroke, two
1016 clocks* — this number and the predicted one are taken from the same
1017 keypress, so no argument about warm caches, differing conditions or
1018 scheduling can be made about the gap between them. That property belongs
1019 here and nowhere else: it is the only pair that shares a keystroke.
1020
1021 Two things about the unpredicted control are worth keeping.
992 1022
993 - **The criterion's wording was unmeasurable as written.** It asked for an 1023 - **The criterion's wording was unmeasurable as written.** It asked for an
994 "echo-off context" as the control. With echo off *nothing is painted*, so 1024 "echo-off context" as the control. With echo off *nothing is painted*, so
test/wan.sh
Old New
@@ -945,12 +945,26 @@ def cmd_predict(argv):
945 timeout=10.0) is None: 945 timeout=10.0) is None:
946 fail("predict: rep %d was never predicted" % i) 946 fail("predict: rep %d was never predicted" % i)
947 pred.append((now() - t0) * 1000.0) 947 pred.append((now() - t0) * 1000.0)
948 # The authoritative echo of the same keystroke. The run only 948 # The authoritative echo of the same keystroke. Two conditions
949 # grows and predictions paint one cell at a time, so the run as 949 # make a plain substring search a valid clock here, and BOTH
950 # a contiguous string appears only in a daemon row paint. 950 # were got wrong first time round:
951 if c.wait_for(lambda b, w=run: w in b, timeout=20.0) is None: 951 #
952 # - Search from `start`, not the whole buffer. Searching
953 # everything let rep 0's needle match the shell's echo of
954 # the `cat` command typed during setup, stopping the clock
955 # at ~0 and putting an artifact in the record.
956 # - Needle of at least two characters. Predictions paint one
957 # cell at a time with a cursor move between them, so a run
958 # of two or more appears contiguously ONLY in a daemon row
959 # paint — but a one-character needle is a substring of the
960 # prediction's own `ESC[4mX` and would time that instead.
961 # So rep 0 contributes no authoritative sample; it cannot,
962 # and inventing one is how the first artifact got in.
963 if c.wait_for(lambda b, w=run, s=start: w in b[s:],
964 timeout=20.0) is None:
952 fail("predict: rep %d never echoed authoritatively" % i) 965 fail("predict: rep %d never echoed authoritatively" % i)
953 auth.append((now() - t0) * 1000.0) 966 if len(run) >= 2:
967 auth.append((now() - t0) * 1000.0)
954 # The control the criterion asks for: input prediction does NOT 968 # The control the criterion asks for: input prediction does NOT
955 # apply to, timed on the same connection in the same run. 969 # apply to, timed on the same connection in the same run.
956 # 970 #
@@ -1462,18 +1476,29 @@ if [ -n "$(val predict predict med)" ]; then
1462 echo " leg 1: NOT EXERCISED — round trip $P_RTT ms is below the 50ms floor" 1476 echo " leg 1: NOT EXERCISED — round trip $P_RTT ms is below the 50ms floor"
1463 elif awk -v m="$P_MED" 'BEGIN{exit !(m <= 30)}'; then 1477 elif awk -v m="$P_MED" 'BEGIN{exit !(m <= 30)}'; then
1464 P_OFF="$(val predict predictoff med)" 1478 P_OFF="$(val predict predictoff med)"
1465 echo " leg 1: predicted paint med $P_MED <= 30ms -> PASS (round trip $P_RTT ms)" 1479 echo " leg 1: predicted paint med $P_MED <= 30ms (round trip $P_RTT ms)"
1466 echo " control, unpredicted input (refused as multi-byte): med $P_OFF ms" 1480 echo " control, unpredicted input (refused as multi-byte): med ${P_OFF:-ABSENT} ms"
1467 echo " control, same keystroke's authoritative echo: med $P_AUTH ms" 1481 echo " control, same keystroke's authoritative echo: med ${P_AUTH:-ABSENT} ms"
1468 echo " Both track the measured round trip while the predicted number does" 1482 echo " Both track the measured round trip while the predicted number does"
1469 echo " not, which is what rules out the harness having timed the hardware." 1483 echo " not, which is what rules out the harness having timed the hardware."
1470 # A control that came back fast would mean the "unpredicted" input was 1484 # A missing control is a FAILED leg, not a quiet one. Skipping the
1485 # check when the number is absent is the same mistake as accepting a
1486 # control that cannot fail: leg 1 would pass on the strength of a
1487 # comparison nothing had made.
1488 if [ -z "$P_OFF" ] || [ -z "$P_AUTH" ]; then
1489 echo " leg 1 CONTROL MISSING: predictoff='${P_OFF:-}' predictauth='${P_AUTH:-}'."
1490 echo " Leg 1 cannot pass without both — the predicted number alone says"
1491 echo " nothing about the path it was measured over."
1492 FAILED=1
1493 # A control that came back fast means the "unpredicted" input was
1471 # being predicted after all, and leg 1's number would be meaningless. 1494 # being predicted after all, and leg 1's number would be meaningless.
1472 if [ -n "$P_OFF" ] && awk -v o="$P_OFF" -v r="$P_RTT" 'BEGIN{exit !(o < r/2)}'; then 1495 elif awk -v o="$P_OFF" -v r="$P_RTT" 'BEGIN{exit !(o < r/2)}'; then
1473 echo " leg 1 CONTROL FAILED: unpredicted input came back in $P_OFF ms, well" 1496 echo " leg 1 CONTROL FAILED: unpredicted input came back in $P_OFF ms, well"
1474 echo " under the $P_RTT ms path — it cannot have waited for the daemon," 1497 echo " under the $P_RTT ms path — it cannot have waited for the daemon,"
1475 echo " so the comparison above proves nothing." 1498 echo " so the comparison above proves nothing."
1476 FAILED=1 1499 FAILED=1
1500 else
1501 echo " leg 1: PASS (threshold met, both controls present and slow)"
1477 fi 1502 fi
1478 else 1503 else
1479 echo " leg 1: predicted paint med $P_MED > 30ms -> FAIL (round trip $P_RTT ms)" 1504 echo " leg 1: predicted paint med $P_MED > 30ms -> FAIL (round trip $P_RTT ms)"