185f900a
feat: WAN measurement harness
a73x 2026-08-08 14:08
Commit message
test/wan.sh
| Old | New | ||
|---|---|---|---|
| @@ -0,0 +1,703 @@ | |||
| 1 | #!/usr/bin/env bash | ||
| 2 | # M6 WAN deployment + measurement harness. | ||
| 3 | # | ||
| 4 | # Deploys a static musl muxd to a remote box, runs a session over it via | ||
| 5 | # `mux --via "<ssh> muxd proxy"`, and measures the numbers the M6 kill | ||
| 6 | # criterion is decided on: | ||
| 7 | # | ||
| 8 | # baseline raw byte round-trip through `<ssh> cat` — the floor mux is | ||
| 9 | # judged against, measured on the same warm channel | ||
| 10 | # attach client launch -> first painted byte | ||
| 11 | # echo keystroke -> that character painted back, through the WHOLE | ||
| 12 | # stack (ssh -> proxy -> daemon -> pty -> bash echo -> engine -> | ||
| 13 | # delta -> proxy -> ssh -> client paint) | ||
| 14 | # reattach kill -9 the client, relaunch, time to first painted byte, and | ||
| 15 | # check pre-kill session state is in that first paint | ||
| 16 | # hol echo latency while the session floods output (probes the | ||
| 17 | # proxy's known head-of-line blocking; recorded, not gated) | ||
| 18 | # | ||
| 19 | # Kill criterion (docs/superpowers/plans/2026-08-07-m6-transport.md): | ||
| 20 | # median echo <= baseline median + 120ms, and reattach to first byte | ||
| 21 | # <= ~2x the link round-trip. Exits non-zero when either fails. Do not | ||
| 22 | # tune the thresholds here; a failure is the milestone's answer. | ||
| 23 | # | ||
| 24 | # Ctrl-C does not work inside a session whose daemon was backgrounded by a | ||
| 25 | # non-interactive shell — which is how this script, e2e.sh and any deploy | ||
| 26 | # script start it. POSIX has such a shell set SIGINT/SIGQUIT to SIG_IGN for | ||
| 27 | # an async child; SIG_IGN survives exec, so muxd passes it to the pty child, | ||
| 28 | # and a shell keeps signals ignored-on-entry ignored for the jobs it spawns. | ||
| 29 | # The pty's isig is on and ^C is echoed; the signal is simply never raised. | ||
| 30 | # Verified on the box: with SIGINT reset to SIG_DFL before muxd exec's, the | ||
| 31 | # same ^C kills the same `sleep 300`. Nothing here may rely on interrupting | ||
| 32 | # the remote shell (see the flood probe). Not this script's to fix — the | ||
| 33 | # reset belongs next to the execveZ in src/pty.zig. | ||
| 34 | # | ||
| 35 | # NOT wired into build.zig: it needs a real remote box. The box is | ||
| 36 | # ephemeral and passed in by environment, never recorded in this file. | ||
| 37 | # | ||
| 38 | # MUX_WAN_SSH full ssh command string, incl. jump/control flags | ||
| 39 | # MUX_WAN_SCP matching scp command string (same ControlPath) | ||
| 40 | # MUX_WAN_HOST scp target prefix, e.g. user@host | ||
| 41 | # MUX_WAN_NETEM 1 to also measure under `netem delay 75ms loss 1%` | ||
| 42 | # ZIG cross-compiling zig 0.15.2 (the Makefile's default) | ||
| 43 | set -euo pipefail | ||
| 44 | |||
| 45 | usage() { | ||
| 46 | cat >&2 <<'USAGE' | ||
| 47 | usage: MUX_WAN_SSH=... MUX_WAN_SCP=... MUX_WAN_HOST=... test/wan.sh | ||
| 48 | |||
| 49 | MUX_WAN_SSH ssh command string, e.g. | ||
| 50 | "ssh -o ControlMaster=auto -o ControlPath=/tmp/mux-cm \ | ||
| 51 | -o ControlPersist=300 -J user@gate:2222 user@box" | ||
| 52 | (keep ControlPath short: long paths exceed sun_path) | ||
| 53 | MUX_WAN_SCP matching scp, e.g. "scp -o ControlPath=/tmp/mux-cm" | ||
| 54 | MUX_WAN_HOST scp target prefix, e.g. "user@box" | ||
| 55 | MUX_WAN_NETEM optional; 1 adds `delay 75ms loss 1%` on the box's | ||
| 56 | default interface and repeats the echo/reattach runs | ||
| 57 | USAGE | ||
| 58 | exit 2 | ||
| 59 | } | ||
| 60 | |||
| 61 | [ -n "${MUX_WAN_SSH:-}" ] || usage | ||
| 62 | [ -n "${MUX_WAN_SCP:-}" ] || usage | ||
| 63 | [ -n "${MUX_WAN_HOST:-}" ] || usage | ||
| 64 | |||
| 65 | ROOT="$(cd "$(dirname "$0")/.." && pwd)" | ||
| 66 | ZIG="${ZIG:-$HOME/Downloads/zig-x86_64-linux-0.15.2/zig}" | ||
| 67 | MUX="$ROOT/zig-out/bin/mux" | ||
| 68 | REPS_ECHO="${MUX_WAN_REPS_ECHO:-20}" | ||
| 69 | REPS_BASE="${MUX_WAN_REPS_BASE:-20}" | ||
| 70 | REPS_ATTACH="${MUX_WAN_REPS_ATTACH:-3}" | ||
| 71 | REPS_REATTACH="${MUX_WAN_REPS_REATTACH:-3}" | ||
| 72 | REPS_HOL="${MUX_WAN_REPS_HOL:-5}" | ||
| 73 | |||
| 74 | # Unique remote names: the box may be shared, and a crashed run must never | ||
| 75 | # leave a socket another run mistakes for its own. | ||
| 76 | TAG="wan-$$-$(date +%s)" | ||
| 77 | RBIN="/tmp/muxd-$TAG" | ||
| 78 | RSOCK="/tmp/mux-$TAG.sock" | ||
| 79 | RLOG="/tmp/muxd-$TAG.log" | ||
| 80 | |||
| 81 | WORK="$(mktemp -d "${TMPDIR:-/tmp}/mux-wan-XXXXXX")" | ||
| 82 | PY="$WORK/wan.py" | ||
| 83 | RESULTS="$WORK/results" | ||
| 84 | ERRLOG="$WORK/client.err" | ||
| 85 | : > "$RESULTS" | ||
| 86 | NETEM_IFACE="" | ||
| 87 | |||
| 88 | # Every remote pattern below is bracketed ('[m]uxd-') so it matches the | ||
| 89 | # processes we started but not the ssh-spawned shell running the pkill, | ||
| 90 | # whose own command line necessarily contains the pattern's text. | ||
| 91 | DEADMAN_SECS=900 | ||
| 92 | NETEM_LEFT=0 | ||
| 93 | DEADMAN_PGID="" | ||
| 94 | |||
| 95 | # Undo the netem qdisc and cancel its deadman. Degrading someone else's box | ||
| 96 | # is the one thing here that outlives the run, so this verifies against the | ||
| 97 | # box instead of believing an exit status. | ||
| 98 | netem_off() { | ||
| 99 | [ -n "$NETEM_IFACE" ] || return 0 | ||
| 100 | local iface="$NETEM_IFACE" | ||
| 101 | NETEM_IFACE="" | ||
| 102 | # By process group, not by name: the deadman is a shell plus the `sleep` | ||
| 103 | # it is waiting on, and killing only the shell orphans a bare `sleep 900` | ||
| 104 | # that no safe pattern can pick out of someone else's processes. setsid | ||
| 105 | # made the pair its own group precisely so this one signal ends both. | ||
| 106 | if [ -n "$DEADMAN_PGID" ]; then | ||
| 107 | timeout 60 $MUX_WAN_SSH "sudo -n kill -TERM -$DEADMAN_PGID" >/dev/null 2>&1 || true | ||
| 108 | DEADMAN_PGID="" | ||
| 109 | fi | ||
| 110 | # Separate invocation, deliberately: a pkill sharing its remote shell | ||
| 111 | # with the tc command matches that shell's own command line and kills it | ||
| 112 | # before the qdisc is ever removed. That is not hypothetical — it left | ||
| 113 | # netem running on the box during development. | ||
| 114 | timeout 60 $MUX_WAN_SSH \ | ||
| 115 | "sudo -n pkill -f '[s]leep $DEADMAN_SECS; tc qdisc del dev $iface'" \ | ||
| 116 | >/dev/null 2>&1 || true | ||
| 117 | timeout 60 $MUX_WAN_SSH "sudo -n tc qdisc del dev $iface root" >/dev/null 2>&1 || true | ||
| 118 | if timeout 60 $MUX_WAN_SSH "tc qdisc show dev $iface" 2>/dev/null | grep -q netem; then | ||
| 119 | NETEM_LEFT=1 | ||
| 120 | echo " WARNING: netem is STILL on $iface. Remove it by hand:" | ||
| 121 | echo " \$MUX_WAN_SSH 'sudo tc qdisc del dev $iface root'" | ||
| 122 | else | ||
| 123 | echo " netem removed from $iface (verified against the box)" | ||
| 124 | fi | ||
| 125 | } | ||
| 126 | |||
| 127 | cleanup() { | ||
| 128 | local rc=$? | ||
| 129 | echo | ||
| 130 | echo "-- cleanup" | ||
| 131 | netem_off | ||
| 132 | # The pkills travel alone: any command sharing their remote shell would | ||
| 133 | # put the tag in that shell's own command line, and -f would kill the | ||
| 134 | # shell before the rest of the line ran. | ||
| 135 | timeout 60 $MUX_WAN_SSH "pkill -f '[m]uxd-$TAG'" >/dev/null 2>&1 || true | ||
| 136 | sleep 0.5 | ||
| 137 | timeout 60 $MUX_WAN_SSH "pkill -9 -f '[m]uxd-$TAG'" >/dev/null 2>&1 || true | ||
| 138 | timeout 60 $MUX_WAN_SSH "rm -f $RBIN $RSOCK $RLOG" \ | ||
| 139 | >/dev/null 2>&1 || echo " WARNING: remote file cleanup failed; check for $TAG" | ||
| 140 | local left | ||
| 141 | left="$(timeout 60 $MUX_WAN_SSH "pgrep -af '[m]uxd-$TAG' || true" 2>/dev/null || true)" | ||
| 142 | if [ -n "$left" ]; then | ||
| 143 | echo " WARNING: remote processes survived: $left" | ||
| 144 | else | ||
| 145 | echo " remote clean (no muxd-$TAG processes, files removed)" | ||
| 146 | fi | ||
| 147 | rm -rf "$WORK" | ||
| 148 | # A box left degraded is a failure of this script whatever the | ||
| 149 | # measurements said. | ||
| 150 | [ "$NETEM_LEFT" -eq 0 ] || rc=3 | ||
| 151 | exit $rc | ||
| 152 | } | ||
| 153 | trap cleanup EXIT INT TERM | ||
| 154 | |||
| 155 | say() { echo; echo "== $*"; } | ||
| 156 | |||
| 157 | # Run one python measurement; echo its human output, bank its #RESULT lines | ||
| 158 | # under a phase name so the summary can find them. | ||
| 159 | measure() { | ||
| 160 | local phase="$1"; shift | ||
| 161 | local out | ||
| 162 | if ! out="$(python3 "$PY" "$@" 2>&1)"; then | ||
| 163 | echo "$out" | ||
| 164 | echo "wan FAIL: measurement '$*' failed" >&2 | ||
| 165 | [ -s "$ERRLOG" ] && { echo "-- client stderr:"; tail -30 "$ERRLOG"; } | ||
| 166 | exit 1 | ||
| 167 | fi | ||
| 168 | echo "$out" | grep -v '^#RESULT' || true | ||
| 169 | echo "$out" | sed -n "s/^#RESULT /$phase /p" >> "$RESULTS" | ||
| 170 | } | ||
| 171 | |||
| 172 | # val <phase> <name> <key> — pull one number out of the banked results. | ||
| 173 | val() { | ||
| 174 | awk -v p="$1" -v n="$2" -v k="$3" \ | ||
| 175 | '$1==p && $2==n { for (i=3;i<=NF;i++) { split($i,kv,"="); if (kv[1]==k) { print kv[2]; exit } } }' \ | ||
| 176 | "$RESULTS" | ||
| 177 | } | ||
| 178 | |||
| 179 | cat > "$PY" <<'PYEOF' | ||
| 180 | """Timing helpers for wan.sh. Shell byte-timing is too crude for this: the | ||
| 181 | numbers are tens of milliseconds and must be taken around a single write(). | ||
| 182 | |||
| 183 | Each subcommand prints human-readable lines plus one '#RESULT <name> k=v...' | ||
| 184 | line that wan.sh banks for the summary.""" | ||
| 185 | import os | ||
| 186 | import select | ||
| 187 | import shlex | ||
| 188 | import signal | ||
| 189 | import statistics | ||
| 190 | import subprocess | ||
| 191 | import sys | ||
| 192 | import time | ||
| 193 | |||
| 194 | TIMEOUT = 25.0 | ||
| 195 | # The flood probe can deliver output faster than any test needs to remember, | ||
| 196 | # so the capture is a sliding window. Every needle waited for below is either | ||
| 197 | # unique to its rep or is matched within a paint or two of being typed, so | ||
| 198 | # dropping the oldest bytes cannot lose a match. | ||
| 199 | MAXBUF = 4 << 20 | ||
| 200 | # Flood length in ticks of ~10ms each: long enough to cover every rep of the | ||
| 201 | # probe with margin, short enough that the session frees itself afterwards. | ||
| 202 | FLOOD_TICKS = 900 | ||
| 203 | # The typed run that the echo measurement grows one character at a time. It | ||
| 204 | # starts with '#' so the line is a bash comment: nothing this harness types | ||
| 205 | # can ever execute on the remote box, whatever arrives at the shell. | ||
| 206 | ECHO_RUN = b"#abcdefghijklmnopqrstuvwxyz" | ||
| 207 | |||
| 208 | |||
| 209 | def now(): | ||
| 210 | return time.monotonic() | ||
| 211 | |||
| 212 | |||
| 213 | def fail(msg): | ||
| 214 | sys.stderr.write("wan.py: %s\n" % msg) | ||
| 215 | sys.exit(1) | ||
| 216 | |||
| 217 | |||
| 218 | def report(name, samples, **extra): | ||
| 219 | s = sorted(samples) | ||
| 220 | kv = "".join(" %s=%s" % (k, v) for k, v in extra.items()) | ||
| 221 | print("#RESULT %s min=%.1f med=%.1f max=%.1f n=%d%s" | ||
| 222 | % (name, s[0], statistics.median(s), s[-1], len(s), kv)) | ||
| 223 | print(" %-26s min=%7.1fms med=%7.1fms max=%7.1fms (n=%d)" | ||
| 224 | % (name, s[0], statistics.median(s), s[-1], len(s))) | ||
| 225 | |||
| 226 | |||
| 227 | class Client: | ||
| 228 | """An attached mux client held open on pipes. | ||
| 229 | |||
| 230 | Its own session (start_new_session) so the kill test can take down the | ||
| 231 | whole transport — client and the ssh it spawned — the way closing a | ||
| 232 | terminal window does, instead of orphaning ssh on the far side. | ||
| 233 | """ | ||
| 234 | |||
| 235 | def __init__(self, mux, via, errlog): | ||
| 236 | env = dict(os.environ) | ||
| 237 | # Nothing may fall back to a local default socket: over-the-wire is | ||
| 238 | # the only path being measured. | ||
| 239 | env["XDG_RUNTIME_DIR"] = "/nonexistent-mux-wan" | ||
| 240 | self.errf = open(errlog, "ab") | ||
| 241 | self.p = subprocess.Popen( | ||
| 242 | [mux, "--via", via], | ||
| 243 | stdin=subprocess.PIPE, stdout=subprocess.PIPE, stderr=self.errf, | ||
| 244 | bufsize=0, start_new_session=True, env=env) | ||
| 245 | self.buf = bytearray() | ||
| 246 | self.total = 0 | ||
| 247 | |||
| 248 | def send(self, data): | ||
| 249 | self.p.stdin.write(data) | ||
| 250 | self.p.stdin.flush() | ||
| 251 | |||
| 252 | def _absorb(self, chunk): | ||
| 253 | self.buf += chunk | ||
| 254 | # Counts every byte ever seen, including trimmed ones: quiescence has | ||
| 255 | # to be judged on arrivals, and len(buf) can shrink. | ||
| 256 | self.total += len(chunk) | ||
| 257 | if len(self.buf) > MAXBUF: | ||
| 258 | del self.buf[:len(self.buf) - MAXBUF // 2] | ||
| 259 | |||
| 260 | def wait_for(self, pred, timeout=TIMEOUT): | ||
| 261 | """Read until pred(self.buf); return elapsed seconds, or None if the | ||
| 262 | deadline passed or the transport died.""" | ||
| 263 | start = now() | ||
| 264 | deadline = start + timeout | ||
| 265 | while not pred(self.buf): | ||
| 266 | remain = deadline - now() | ||
| 267 | if remain <= 0: | ||
| 268 | return None | ||
| 269 | r, _, _ = select.select([self.p.stdout], [], [], remain) | ||
| 270 | if not r: | ||
| 271 | continue | ||
| 272 | chunk = os.read(self.p.stdout.fileno(), 65536) | ||
| 273 | if not chunk: | ||
| 274 | return None | ||
| 275 | self._absorb(chunk) | ||
| 276 | return now() - start | ||
| 277 | |||
| 278 | def drain(self, seconds): | ||
| 279 | """Collect whatever arrives for a fixed window.""" | ||
| 280 | deadline = now() + seconds | ||
| 281 | while True: | ||
| 282 | remain = deadline - now() | ||
| 283 | if remain <= 0: | ||
| 284 | return | ||
| 285 | r, _, _ = select.select([self.p.stdout], [], [], remain) | ||
| 286 | if not r: | ||
| 287 | return | ||
| 288 | chunk = os.read(self.p.stdout.fileno(), 65536) | ||
| 289 | if not chunk: | ||
| 290 | return | ||
| 291 | self._absorb(chunk) | ||
| 292 | |||
| 293 | def alive(self): | ||
| 294 | return self.p.poll() is None | ||
| 295 | |||
| 296 | def kill(self): | ||
| 297 | try: | ||
| 298 | os.killpg(self.p.pid, signal.SIGKILL) | ||
| 299 | except (ProcessLookupError, PermissionError): | ||
| 300 | pass | ||
| 301 | self._close() | ||
| 302 | |||
| 303 | def detach(self): | ||
| 304 | try: | ||
| 305 | self.send(b"\x1c") | ||
| 306 | self.p.wait(timeout=8) | ||
| 307 | except Exception: | ||
| 308 | self.kill() | ||
| 309 | return | ||
| 310 | self._close() | ||
| 311 | |||
| 312 | def _close(self): | ||
| 313 | for f in (self.p.stdin, self.p.stdout): | ||
| 314 | try: | ||
| 315 | f.close() | ||
| 316 | except Exception: | ||
| 317 | pass | ||
| 318 | try: | ||
| 319 | self.p.wait(timeout=5) | ||
| 320 | except Exception: | ||
| 321 | pass | ||
| 322 | self.errf.close() | ||
| 323 | |||
| 324 | |||
| 325 | def settle(c, what): | ||
| 326 | """Wait for the first paint, then prove the remote bash is at a prompt | ||
| 327 | and echoing by typing ECHO_RUN's first character ('#') and waiting for | ||
| 328 | it to come back. Everything downstream then measures against a shell | ||
| 329 | known to be answering — and cmd_echo continues the run from there. | ||
| 330 | |||
| 331 | The wait is anchored past whatever the first paint already contained, | ||
| 332 | so a prompt that itself ends in '#' cannot satisfy it vacuously. | ||
| 333 | """ | ||
| 334 | if c.wait_for(lambda b: len(b) > 0) is None: | ||
| 335 | fail("%s: no first paint (transport never came up)" % what) | ||
| 336 | start = len(c.buf) | ||
| 337 | c.send(ECHO_RUN[:1]) | ||
| 338 | if c.wait_for(lambda b, s=start: ECHO_RUN[:1] in b[s:]) is None: | ||
| 339 | fail("%s: remote shell never echoed (no prompt?)" % what) | ||
| 340 | |||
| 341 | |||
| 342 | def wait_idle(c, what, timeout=60.0): | ||
| 343 | """Wait until the session stops producing output.""" | ||
| 344 | deadline = now() + timeout | ||
| 345 | while now() < deadline: | ||
| 346 | before = c.total | ||
| 347 | c.drain(0.8) | ||
| 348 | if c.total == before: | ||
| 349 | return | ||
| 350 | fail("%s: session never went idle" % what) | ||
| 351 | |||
| 352 | |||
| 353 | def prove_alive(c, what): | ||
| 354 | """Prove the remote shell is back at a prompt and running commands. The | ||
| 355 | flood probe is the only step that leaves work running on the far side, | ||
| 356 | and Ctrl-C cannot be used to stop it (see the SIGINT finding in wan.sh's | ||
| 357 | header), so the session's return to health is checked, never assumed.""" | ||
| 358 | wait_idle(c, what) | ||
| 359 | c.send(b"\x15printf 'holdone-%s\\n' ok\n") | ||
| 360 | if c.wait_for(lambda b: b"holdone-ok" in b) is None: | ||
| 361 | fail("%s: shell never came back to a prompt after the flood" % what) | ||
| 362 | |||
| 363 | |||
| 364 | def cmd_baseline(argv): | ||
| 365 | """Raw byte round-trip through `<ssh> cat`: the link's own number, taken | ||
| 366 | on a warm channel so it measures the link and not session setup.""" | ||
| 367 | ssh_cmd, reps = argv[0], int(argv[1]) | ||
| 368 | p = subprocess.Popen(shlex.split(ssh_cmd) + ["cat"], | ||
| 369 | stdin=subprocess.PIPE, stdout=subprocess.PIPE, bufsize=0) | ||
| 370 | samples = [] | ||
| 371 | try: | ||
| 372 | for i in range(reps + 3): # first three are warmup | ||
| 373 | t0 = now() | ||
| 374 | p.stdin.write(b"x") | ||
| 375 | p.stdin.flush() | ||
| 376 | r, _, _ = select.select([p.stdout], [], [], TIMEOUT) | ||
| 377 | if not r: | ||
| 378 | fail("baseline: no echo from `ssh cat` within %gs" % TIMEOUT) | ||
| 379 | if not os.read(p.stdout.fileno(), 4096): | ||
| 380 | fail("baseline: `ssh cat` closed the pipe") | ||
| 381 | if i >= 3: | ||
| 382 | samples.append((now() - t0) * 1000.0) | ||
| 383 | finally: | ||
| 384 | p.stdin.close() | ||
| 385 | p.stdout.close() | ||
| 386 | p.wait(timeout=10) | ||
| 387 | report("baseline", samples) | ||
| 388 | |||
| 389 | |||
| 390 | def cmd_viafloor(argv): | ||
| 391 | """The floor under any `--via` launch: spawn the transport exactly the | ||
| 392 | way mux does — /bin/sh -c "<ssh> <remote program>" — and time until the | ||
| 393 | remote program's first byte reaches our stdout. | ||
| 394 | |||
| 395 | Attach and reattach both pay this before one protocol byte can move, so | ||
| 396 | it is what separates 'the session is slow to restore' from 'ssh takes | ||
| 397 | this long to open a channel'. Measured on the warm master, so it is | ||
| 398 | channel setup and remote exec, not authentication. | ||
| 399 | """ | ||
| 400 | ssh_cmd, reps = argv[0], int(argv[1]) | ||
| 401 | samples = [] | ||
| 402 | for i in range(reps + 1): # first is warmup | ||
| 403 | t0 = now() | ||
| 404 | p = subprocess.Popen(["/bin/sh", "-c", ssh_cmd + " printf x"], | ||
| 405 | stdout=subprocess.PIPE, bufsize=0) | ||
| 406 | r, _, _ = select.select([p.stdout], [], [], TIMEOUT) | ||
| 407 | if not r or not os.read(p.stdout.fileno(), 16): | ||
| 408 | fail("viafloor: the transport produced no byte") | ||
| 409 | if i > 0: | ||
| 410 | samples.append((now() - t0) * 1000.0) | ||
| 411 | p.stdout.close() | ||
| 412 | p.wait(timeout=10) | ||
| 413 | report("viafloor", samples) | ||
| 414 | |||
| 415 | |||
| 416 | def cmd_attach(argv): | ||
| 417 | """Client launch to first painted byte.""" | ||
| 418 | mux, via, reps, errlog = argv[0], argv[1], int(argv[2]), argv[3] | ||
| 419 | samples = [] | ||
| 420 | for _ in range(reps): | ||
| 421 | t0 = now() | ||
| 422 | c = Client(mux, via, errlog) | ||
| 423 | if c.wait_for(lambda b: len(b) > 0) is None: | ||
| 424 | c.kill() | ||
| 425 | fail("attach: no first paint") | ||
| 426 | samples.append((now() - t0) * 1000.0) | ||
| 427 | c.detach() | ||
| 428 | report("attach", samples) | ||
| 429 | |||
| 430 | |||
| 431 | def cmd_echo(argv): | ||
| 432 | """Keystroke to painted echo, through the whole stack. | ||
| 433 | |||
| 434 | Each rep types the next character of ECHO_RUN and waits for the run so | ||
| 435 | far to appear. A delta paints the changed row whole, so the grown run | ||
| 436 | lands in one piece; and because the run only ever grows, the string | ||
| 437 | being waited for cannot have been on screen before the keystroke that | ||
| 438 | completes it. That is what makes a plain substring search a valid clock. | ||
| 439 | """ | ||
| 440 | mux, via, reps, errlog = argv[0], argv[1], int(argv[2]), argv[3] | ||
| 441 | if reps > len(ECHO_RUN) - 1: | ||
| 442 | fail("echo: at most %d reps" % (len(ECHO_RUN) - 1)) | ||
| 443 | c = Client(mux, via, errlog) | ||
| 444 | samples = [] | ||
| 445 | try: | ||
| 446 | settle(c, "echo") | ||
| 447 | for i in range(1, reps + 1): | ||
| 448 | want = ECHO_RUN[:i + 1] | ||
| 449 | t0 = now() | ||
| 450 | c.send(ECHO_RUN[i:i + 1]) | ||
| 451 | if c.wait_for(lambda b, w=want: w in b) is None: | ||
| 452 | fail("echo: rep %d never echoed %r" % (i, want)) | ||
| 453 | samples.append((now() - t0) * 1000.0) | ||
| 454 | c.send(b"\n") # the run is a comment; this just clears the line | ||
| 455 | finally: | ||
| 456 | c.detach() | ||
| 457 | report("echo", samples) | ||
| 458 | |||
| 459 | |||
| 460 | def cmd_reattach(argv): | ||
| 461 | """kill -9 the client, relaunch, time to first painted byte — and prove | ||
| 462 | the paint carries session state from before the kill.""" | ||
| 463 | mux, via, reps, errlog = argv[0], argv[1], int(argv[2]), argv[3] | ||
| 464 | samples = [] | ||
| 465 | marker_ok = 1 | ||
| 466 | for i in range(reps): | ||
| 467 | nonce = "%d-%d" % (os.getpid(), i) | ||
| 468 | marker = ("wanmark-" + nonce).encode() | ||
| 469 | c = Client(mux, via, errlog) | ||
| 470 | settle(c, "reattach") | ||
| 471 | # The typed line holds "wanmark-%s" and the nonce as separate words, | ||
| 472 | # so the joined marker exists only if the remote shell ran printf. | ||
| 473 | c.send(b'\x15printf "wanmark-%s\\n" ' + nonce.encode() + b"\n") | ||
| 474 | if c.wait_for(lambda b, m=marker: m in b) is None: | ||
| 475 | c.kill() | ||
| 476 | fail("reattach: pre-kill marker never appeared") | ||
| 477 | c.kill() | ||
| 478 | t0 = now() | ||
| 479 | c2 = Client(mux, via, errlog) | ||
| 480 | first = c2.wait_for(lambda b: len(b) > 0) | ||
| 481 | if first is None: | ||
| 482 | c2.kill() | ||
| 483 | fail("reattach: relaunched client never painted") | ||
| 484 | samples.append((now() - t0) * 1000.0) | ||
| 485 | c2.drain(0.4) # the rest of that first paint | ||
| 486 | if marker not in c2.buf: | ||
| 487 | marker_ok = 0 | ||
| 488 | print(" reattach rep %d: FIRST PAINT MISSING PRE-KILL MARKER %s" | ||
| 489 | % (i, marker.decode())) | ||
| 490 | c2.detach() | ||
| 491 | report("reattach", samples, marker_ok=marker_ok) | ||
| 492 | |||
| 493 | |||
| 494 | def cmd_hol(argv): | ||
| 495 | """Echo latency while the session floods output. The proxy is a byte | ||
| 496 | pump with no notion of priority, so a flood shares the pipe with the | ||
| 497 | keystroke's echo; this number is the size of that effect. Recorded for | ||
| 498 | the record, not gated. | ||
| 499 | |||
| 500 | The flood is bounded and self-terminating, which is not tidiness: a mux | ||
| 501 | session started the ordinary way cannot be interrupted at all (the daemon | ||
| 502 | inherits SIGINT=SIG_IGN from the shell that backgrounded it, and passes | ||
| 503 | it to the pty child — see this script's header), so an infinite loop here | ||
| 504 | would run until the daemon died and would silently add itself to every | ||
| 505 | measurement taken afterwards. | ||
| 506 | |||
| 507 | The flood is one line every 10ms, not `yes` at full tilt, and the rate | ||
| 508 | is the measurement, not a courtesy. A scrolling line rewrites every row, | ||
| 509 | so each tick costs a near-full-screen delta: ~100 of them a second is | ||
| 510 | already far more than an interactive link carries. Going faster does not | ||
| 511 | load the wire any further (the daemon sends grid states, not pty bytes) | ||
| 512 | and it destroys the measurement — under `yes` the echoed character is | ||
| 513 | scrolled off screen between two deltas and is never transmitted at all, | ||
| 514 | so there is nothing left to time. | ||
| 515 | """ | ||
| 516 | mux, via, reps, errlog = argv[0], argv[1], int(argv[2]), argv[3] | ||
| 517 | c = Client(mux, via, errlog) | ||
| 518 | samples = [] | ||
| 519 | try: | ||
| 520 | settle(c, "hol") | ||
| 521 | c.send(b"\x15for ((i=0;i<%d;i++)); do echo wanflood; sleep 0.01; done\n" | ||
| 522 | % FLOOD_TICKS) | ||
| 523 | c.drain(1.5) # let the flood reach steady state | ||
| 524 | for i in range(reps): | ||
| 525 | # Unique per rep, and absent from the flood's own text, so a | ||
| 526 | # plain search cannot match an earlier rep or the flood itself. | ||
| 527 | tok = b"ZQXJ" + bytes([ord("A") + i]) | ||
| 528 | t0 = now() | ||
| 529 | c.send(tok) | ||
| 530 | if c.wait_for(lambda b, t=tok: t in b, timeout=20) is None: | ||
| 531 | if not c.alive(): | ||
| 532 | print(" hol: client died under the flood after %d reps" % i) | ||
| 533 | break | ||
| 534 | print(" hol: rep %d never echoed within 20s" % i) | ||
| 535 | break | ||
| 536 | samples.append((now() - t0) * 1000.0) | ||
| 537 | if c.alive(): | ||
| 538 | prove_alive(c, "hol") | ||
| 539 | finally: | ||
| 540 | c.kill() | ||
| 541 | if not samples: | ||
| 542 | print("#RESULT hol min=0.0 med=0.0 max=0.0 n=0") | ||
| 543 | print(" hol: not measurable (no echo observed under flood)") | ||
| 544 | return | ||
| 545 | report("hol", samples) | ||
| 546 | |||
| 547 | |||
| 548 | COMMANDS = { | ||
| 549 | "baseline": cmd_baseline, | ||
| 550 | "viafloor": cmd_viafloor, | ||
| 551 | "attach": cmd_attach, | ||
| 552 | "echo": cmd_echo, | ||
| 553 | "reattach": cmd_reattach, | ||
| 554 | "hol": cmd_hol, | ||
| 555 | } | ||
| 556 | |||
| 557 | if len(sys.argv) < 2 or sys.argv[1] not in COMMANDS: | ||
| 558 | fail("usage: wan.py {%s} ..." % "|".join(COMMANDS)) | ||
| 559 | COMMANDS[sys.argv[1]](sys.argv[2:]) | ||
| 560 | PYEOF | ||
| 561 | |||
| 562 | say "warming the ssh control master" | ||
| 563 | $MUX_WAN_SSH true || { echo "wan FAIL: cannot reach the box with MUX_WAN_SSH" >&2; exit 1; } | ||
| 564 | |||
| 565 | say "deploying a static musl muxd to $MUX_WAN_HOST:$RBIN" | ||
| 566 | (cd "$ROOT" && "$ZIG" build -Dtarget=x86_64-linux-musl) | ||
| 567 | $MUX_WAN_SCP "$ROOT/zig-out/bin/muxd" "$MUX_WAN_HOST:$RBIN" | ||
| 568 | $MUX_WAN_SSH "chmod +x $RBIN && file $RBIN 2>/dev/null | head -1" || true | ||
| 569 | # The local mux must be native again before anything measures it. | ||
| 570 | make -C "$ROOT" build >/dev/null | ||
| 571 | [ -x "$MUX" ] || { echo "wan FAIL: no native mux at $MUX" >&2; exit 1; } | ||
| 572 | |||
| 573 | VIA="$MUX_WAN_SSH $RBIN proxy --sock $RSOCK" | ||
| 574 | |||
| 575 | say "baseline: raw byte round-trip through \`ssh cat\` ($REPS_BASE reps)" | ||
| 576 | measure clean baseline "$MUX_WAN_SSH" "$REPS_BASE" | ||
| 577 | measure clean viafloor "$MUX_WAN_SSH" 5 | ||
| 578 | |||
| 579 | say "starting the remote daemon" | ||
| 580 | $MUX_WAN_SSH "rm -f $RSOCK; nohup $RBIN run --sock $RSOCK --shell /bin/bash \ | ||
| 581 | >$RLOG 2>&1 </dev/null & sleep 0.2" | ||
| 582 | i=0 | ||
| 583 | until $MUX_WAN_SSH "test -S $RSOCK" 2>/dev/null; do | ||
| 584 | i=$((i + 1)) | ||
| 585 | [ "$i" -lt 20 ] || { echo "wan FAIL: remote socket never appeared" >&2 | ||
| 586 | $MUX_WAN_SSH "cat $RLOG" || true; exit 1; } | ||
| 587 | sleep 0.5 | ||
| 588 | done | ||
| 589 | sleep 1.5 # let bash reach a prompt on its pty | ||
| 590 | echo " daemon up on $RSOCK" | ||
| 591 | |||
| 592 | say "attach latency (launch -> first painted byte, $REPS_ATTACH reps)" | ||
| 593 | measure clean attach "$MUX" "$VIA" "$REPS_ATTACH" "$ERRLOG" | ||
| 594 | |||
| 595 | say "keystroke echo through the full stack ($REPS_ECHO reps)" | ||
| 596 | measure clean echo "$MUX" "$VIA" "$REPS_ECHO" "$ERRLOG" | ||
| 597 | |||
| 598 | say "reattach after kill -9 ($REPS_REATTACH reps)" | ||
| 599 | measure clean reattach "$MUX" "$VIA" "$REPS_REATTACH" "$ERRLOG" | ||
| 600 | |||
| 601 | # Every clean-link figure is taken before the box is degraded, so a netem | ||
| 602 | # that failed to clear can never quietly relabel itself as the clean link. | ||
| 603 | say "head-of-line probe: echo while the session floods output ($REPS_HOL reps)" | ||
| 604 | measure clean hol "$MUX" "$VIA" "$REPS_HOL" "$ERRLOG" | ||
| 605 | |||
| 606 | if [ "${MUX_WAN_NETEM:-}" = "1" ]; then | ||
| 607 | IFACE="$($MUX_WAN_SSH "ip route show default | cut -d' ' -f5" | tr -d '\r\n')" | ||
| 608 | [ -n "$IFACE" ] || { echo "wan FAIL: no default interface on the box" >&2; exit 1; } | ||
| 609 | # A root netem qdisc shapes egress only, so this adds ~75ms to the round | ||
| 610 | # trip, not ~150ms — measured, not assumed. | ||
| 611 | say "netem: delay 75ms loss 1% on $IFACE (~75ms added round-trip)" | ||
| 612 | $MUX_WAN_SSH "sudo -n tc qdisc add dev $IFACE root netem delay 75ms loss 1%" | ||
| 613 | NETEM_IFACE="$IFACE" | ||
| 614 | # Deadman switch. The trap is the normal path; this covers the one case | ||
| 615 | # the trap cannot — a hard kill of this script — because the qdisc we | ||
| 616 | # just installed degrades the box for everyone, not only for us. It is | ||
| 617 | # matched and cancelled by command line in netem_off. | ||
| 618 | DEADMAN_PGID="$($MUX_WAN_SSH "setsid sudo -n sh -c \ | ||
| 619 | 'sleep $DEADMAN_SECS; tc qdisc del dev $IFACE root' \ | ||
| 620 | >/dev/null 2>&1 </dev/null & echo \$!" | tr -cd '0-9')" || true | ||
| 621 | |||
| 622 | measure netem baseline "$MUX_WAN_SSH" "$REPS_BASE" | ||
| 623 | measure netem viafloor "$MUX_WAN_SSH" 5 | ||
| 624 | measure netem attach "$MUX" "$VIA" "$REPS_ATTACH" "$ERRLOG" | ||
| 625 | measure netem echo "$MUX" "$VIA" "$REPS_ECHO" "$ERRLOG" | ||
| 626 | measure netem reattach "$MUX" "$VIA" "$REPS_REATTACH" "$ERRLOG" | ||
| 627 | |||
| 628 | measure netem hol "$MUX" "$VIA" "$REPS_HOL" "$ERRLOG" | ||
| 629 | |||
| 630 | netem_off | ||
| 631 | fi | ||
| 632 | |||
| 633 | # ---- summary + the kill criterion ----------------------------------------- | ||
| 634 | FAILED=0 | ||
| 635 | |||
| 636 | phase_block() { | ||
| 637 | local phase="$1" label="$2" | ||
| 638 | local base echo_med reatt_med attach_med marker_ok | ||
| 639 | base="$(val "$phase" baseline med)" | ||
| 640 | echo_med="$(val "$phase" echo med)" | ||
| 641 | reatt_med="$(val "$phase" reattach med)" | ||
| 642 | attach_med="$(val "$phase" attach med)" | ||
| 643 | marker_ok="$(val "$phase" reattach marker_ok)" | ||
| 644 | [ -n "$base" ] || return 0 | ||
| 645 | |||
| 646 | echo | ||
| 647 | echo "$label" | ||
| 648 | printf ' %-34s %8s %8s %8s %5s\n' "" min med max n | ||
| 649 | local name | ||
| 650 | for name in baseline viafloor attach echo reattach hol; do | ||
| 651 | [ -n "$(val "$phase" "$name" med)" ] || continue | ||
| 652 | printf ' %-34s %8s %8s %8s %5s\n' "$name" \ | ||
| 653 | "$(val "$phase" "$name" min)" "$(val "$phase" "$name" med)" \ | ||
| 654 | "$(val "$phase" "$name" max)" "$(val "$phase" "$name" n)" | ||
| 655 | done | ||
| 656 | echo " (all figures milliseconds)" | ||
| 657 | |||
| 658 | local budget verdict | ||
| 659 | budget="$(awk -v b="$base" 'BEGIN{printf "%.1f", b+120}')" | ||
| 660 | verdict="$(awk -v e="$echo_med" -v t="$budget" 'BEGIN{print (e<=t)?"PASS":"FAIL"}')" | ||
| 661 | printf ' echo criterion: med %s <= baseline med %s + 120 = %s -> %s (margin %s)\n' \ | ||
| 662 | "$echo_med" "$base" "$budget" "$verdict" \ | ||
| 663 | "$(awk -v e="$echo_med" -v t="$budget" 'BEGIN{printf "%+.1f", t-e}')" | ||
| 664 | [ "$verdict" = PASS ] || FAILED=1 | ||
| 665 | |||
| 666 | # Gated on the whole wall-clock relaunch, the strict reading. Reported | ||
| 667 | # underneath it, never in place of it: the same number with the measured | ||
| 668 | # transport-setup floor taken out, which is the part the protocol | ||
| 669 | # actually governs. A reattach cannot start before ssh has opened a | ||
| 670 | # channel, and no protocol change can make that term smaller. | ||
| 671 | local floor protocol | ||
| 672 | floor="$(val "$phase" viafloor med)" | ||
| 673 | budget="$(awk -v b="$base" 'BEGIN{printf "%.1f", 2*b}')" | ||
| 674 | verdict="$(awk -v r="$reatt_med" -v t="$budget" 'BEGIN{print (r<=t)?"PASS":"FAIL"}')" | ||
| 675 | printf ' reattach criterion: med %s <= 2 x round-trip %s = %s -> %s (margin %s)\n' \ | ||
| 676 | "$reatt_med" "$base" "$budget" "$verdict" \ | ||
| 677 | "$(awk -v r="$reatt_med" -v t="$budget" 'BEGIN{printf "%+.1f", t-r}')" | ||
| 678 | [ "$verdict" = PASS ] || FAILED=1 | ||
| 679 | protocol="$(awk -v r="$reatt_med" -v f="$floor" 'BEGIN{printf "%.1f", r-f}')" | ||
| 680 | printf ' decomposition: %s = %s transport setup (ssh channel open + exec)\n' \ | ||
| 681 | "$reatt_med" "$floor" | ||
| 682 | printf ' + %s protocol (attach -> first painted byte), vs the same %s budget -> %s\n' \ | ||
| 683 | "$protocol" "$budget" \ | ||
| 684 | "$(awk -v p="$protocol" -v t="$budget" 'BEGIN{print (p<=t)?"within":"over"}')" | ||
| 685 | printf ' reattach first paint carried pre-kill state: %s\n' \ | ||
| 686 | "$([ "$marker_ok" = 1 ] && echo yes || echo NO)" | ||
| 687 | [ "$marker_ok" = 1 ] || FAILED=1 | ||
| 688 | printf ' attach (fresh client, same path): med %s\n' "$attach_med" | ||
| 689 | } | ||
| 690 | |||
| 691 | echo | ||
| 692 | echo "=================== M6 WAN measurement summary ===================" | ||
| 693 | echo "date: $(date -u +%Y-%m-%dT%H:%M:%SZ) host: (ephemeral, from MUX_WAN_SSH)" | ||
| 694 | phase_block clean "link as-is:" | ||
| 695 | phase_block netem "with netem delay 75ms loss 1%:" | ||
| 696 | echo | ||
| 697 | if [ "$FAILED" -eq 0 ]; then | ||
| 698 | echo "M6 kill criterion: PASS" | ||
| 699 | else | ||
| 700 | echo "M6 kill criterion: FAIL — report the numbers; do not tune the thresholds." | ||
| 701 | fi | ||
| 702 | echo "==================================================================" | ||
| 703 | exit "$FAILED" | ||