Commit64d2013eRecorded5 Aug 2026Repositoryapiary

Add the matched-pair experiments and the harness README

Message

Four experiments, each run against a pre-change and a post-change binary. APIARY_BIN is required with no default on purpose: a pair in which both arms silently ran the same binary is worse than no measurement, because it looks like a result.

  exp_confirm_latency   the distribution the confirmation budget is
                        derived from, plus proof that the event-loop
                        goroutine really does run during the wait
  exp_silent_loss       does a post during an outage claim delivery?
                        scored by an independent observer, with a
                        control on each side so neither "everything
                        failed" nor "the observer was broken" can pass
  exp_chatty_vs_silent  does a posting bot still detect a dead link?
                        the silent worker is the internal control
  exp_fd_flatness       do the new failure paths leak descriptors?

README records what will otherwise cost the next person an hour: the exact-PID teardown hazard, the 3-bot quota that the chatty/silent pair sits exactly at, the single-token message bodies the server drops in transit, the extra CAPs lost on every reconnect, and the fact that the proxy still forwards the server's FIN in frozen mode -- so a reconnected line is never evidence that a bot detected anything itself.

Changed
 src/apiary/enclave.sgl               |  31 +++++++++++++++++++++-------
 test/harness/README.md               | 161 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
 test/harness/exp_chatty_vs_silent.py | 152 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
 test/harness/exp_confirm_latency.py  | 115 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
 test/harness/exp_fd_flatness.py      | 124 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
 test/harness/exp_silent_loss.py      | 176 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
 test/harness/mcpdrv.py               |  12 +++++++++++
 7 files changed, 764 insertions(+), 7 deletions(-)
Diff
src/apiary/enclave.sglmodified
@@ -323,15 +323,32 @@
323
;; How long `enclave-confirm-delivery!` waits for the PONG that
324
;; proves the peer consumed the bytes we just wrote.
325
;;
−326
;; MEASURED, not chosen. Against a local enclave-server the
−327
;; observed confirmation latency is in `test/harness/` (see
−328
;; `exp_confirm_latency.py`, which prints p50/p95/max over N
−329
;; posts). The budget is set far above the measured worst case
−330
;; on purpose: a false UNCONFIRMED on a merely slow link is
−331
;; worse than a slow post, because the first person who sees a
−332
;; spurious one starts ignoring the warning, and then the
+326
;; MEASURED, not chosen. `test/harness/exp_confirm_latency.py`,
+327
;; 40 posts against a local enclave-server, two independent
+328
;; signals that agree:
+329
;;
+330
;; apiary's own log p50 40 ms p95 60 ms max 60 ms
+331
;; tool-call wall p50 42 ms p95 62 ms max 62 ms
+332
;;
+333
;; Note what dominates that: the values quantise to 20 ms, which
+334
;; is `+post-confirm-poll+`, and the floor is the 50 ms event-
+335
;; loop tick. The wire round trip on localhost is smaller than
+336
;; either. So on a real link the latency is roughly one event-
+337
;; loop tick plus one RTT, and 3 s tolerates an RTT of nearly
+338
;; three seconds — far past the point where a link is usable at
+339
;; all. Against the measured local worst case it is ~50x.
+340
;;
+341
;; That margin is deliberate. A false UNCONFIRMED on a merely
+342
;; slow link is worse than a slow post: the first person to see
+343
;; a spurious one starts ignoring the warning, and then the
344
;; signal this whole change exists to create is gone.
345
;;
+346
;; The cost is real and worth stating: a post used to return in
+347
;; well under a millisecond and now takes ~40 ms, because it
+348
;; waits for a round trip it did not previously make. For agent
+349
;; milestones that is not a rate anyone will notice; for a
+350
;; high-throughput producer it would be.
+351
;;
352
;; It also stays well under `+keepalive-pong-timeout+` (30 s),
353
;; so a confirmation wait can never outlive the window in which
354
;; the keepalive would declare the same link dead.
test/harness/README.mdadded
@@ -0,0 +1,161 @@
+1
# Transport failure harness
+2
+3
Constructs network failures that a socket close cannot imitate, and
+4
drives apiary against them.
+5
+6
Everything here talks to a **throwaway local enclave-server**. Nothing
+7
in this directory should ever be pointed at a deployment anyone is
+8
using: the whole point is to break the link on purpose.
+9
+10
## Why it exists
+11
+12
Apiary's unit tests cover the keepalive state machine, and `smoke.sh`
+13
covers a live connect. Neither can produce the failure that matters
+14
most in practice: a **blackholed route**, where bytes simply stop
+15
arriving and no FIN or RST is ever sent. The peer's kernel keeps the
+16
socket `ESTABLISHED` forever and every local write still succeeds. That
+17
is what a laptop changing networks looks like from the other end, and
+18
it is the condition behind both of the defects this harness measured.
+19
+20
## Files
+21
+22
| file | what it does |
+23
|---|---|
+24
| `proxy.py` | freeze-proxy: blackholes live sockets, or drops new SYNs |
+25
| `proxy_control_test.py` | proves the SYN-drop control can go RED |
+26
| `mcpdrv.py` | JSON-RPC driver for apiary's MCP-stdio interface |
+27
| `env-up.sh` / `env-down.sh` | throwaway enclave-server lifecycle |
+28
| `exp_confirm_latency.py` | post-confirmation latency distribution |
+29
| `exp_silent_loss.py` | does a post during an outage claim delivery? |
+30
| `exp_chatty_vs_silent.py` | does a posting bot still detect a dead link? |
+31
| `exp_fd_flatness.py` | do the failure paths leak file descriptors? |
+32
+33
Apiary has no CLI — the binary speaks MCP JSON-RPC on stdin/stdout — so
+34
`mcpdrv.py` is how a test script calls a tool and observes what the bot
+35
received, without needing an MCP client.
+36
+37
## Running
+38
+39
```sh
+40
ENCLAVE_BIN=/path/to/enclave ./test/harness/env-up.sh
+41
APIARY_BIN=$PWD/build/release/bin/apiary \
+42
python3 test/harness/exp_silent_loss.py
+43
./test/harness/env-down.sh
+44
```
+45
+46
`SIGIL_LOG_LEVEL=debug` makes apiary's per-post confirmation lines
+47
visible, which several experiments parse.
+48
+49
### Always run an experiment as a matched PAIR
+50
+51
Point `APIARY_BIN` at the pre-change binary, then at the post-change
+52
one, and compare. A single reading tells you what a binary does; it
+53
cannot tell you what a change did. `APIARY_BIN` is deliberately
+54
required with no default, because a pair in which both arms silently
+55
ran the same binary is worse than no measurement — it looks like a
+56
result.
+57
+58
Watch the **internal control** in each experiment (the arm that should
+59
NOT change) as closely as the headline number. If it moves between
+60
arms, the two runs are not comparable and the delta is not
+61
attributable to the code.
+62
+63
## THE TEARDOWN HAZARD — read this before stopping anything
+64
+65
**Stop servers by the exact PID recorded in `state.env`. Never by
+66
pattern.**
+67
+68
`env-down.sh` does this. Do not replace it with `pkill -f enclave`,
+69
`pkill -f apiary`, or anything similar, for two independent reasons:
+70
+71
1. **Concurrent harnesses on one host are normal, not an accident.**
+72
More than one of these environments has been found running at once,
+73
from the same binary path, belonging to different work. A pattern
+74
kill takes the other one down silently.
+75
2. **A pattern can match the killing process itself.** An agent
+76
session's own command line typically contains its task name, its
+77
worktree path and its launch arguments. `pkill -f <task-keyword>`
+78
has terminated the very session that ran it, mid-measurement, with
+79
no output explaining why.
+80
+81
If you need to stop something whose PID you did not record, kill by
+82
port (`fuser -k <port>/tcp`) rather than by pattern.
+83
+84
## Gotchas that will otherwise cost you an hour
+85
+86
**The bot quota is 3 per owner and the leader bot counts.** So one
+87
leader plus **two** workers is the ceiling, and `exp_chatty_vs_silent`
+88
sits exactly at it. Revoking a bot DISABLES the row rather than
+89
deleting it, so nicks stay burned and quota is only released when the
+90
row expires. Bring the environment up fresh between experiments rather
+91
than debugging `quota-exceeded`.
+92
+93
**A single-token message body is dropped in transit.** apiary writes
+94
`PRIVMSG #chan :SPACELESS`, and the server relays it as
+95
`PRIVMSG #chan SPACELESS` — no colon — so the receiving parser reads
+96
the body as a middle parameter and the text arrives EMPTY. Measured on
+97
the wire on both legs; `two words` relays intact in the same run. Every
+98
payload in this directory is multi-word for that reason. A harness
+99
using single-token tags would see its messages "lost" for a reason
+100
that has nothing to do with what it is testing.
+101
+102
**Extra CAPs are lost on the reconnect path.** After a reconnect,
+103
`acked=sasl` only, with a `CAP REQ timed out — falling back` warning.
+104
So anything you build on `echo-message`, `draft/multiline` or
+105
`message-tags` is unavailable on exactly the path that follows an
+106
outage. Verify against a reconnected connection, not just a fresh one.
+107
+108
**`sever_existing()` and `freeze_existing()` are different failures.**
+109
Severing closes cleanly and the peer sees EOF within milliseconds;
+110
freezing sends nothing at all and detection takes the keepalive's full
+111
window. Use severing only when you want the reconnect path itself,
+112
not the detection that precedes it.
+113
+114
**The proxy still forwards the server's FIN in frozen mode.** So a bot
+115
can be rescued by the server giving up on it, which a real blackhole
+116
would never deliver — that close travels the same dead path. Never cite
+117
a `reconnected` line as evidence that a bot detected anything itself;
+118
only its own `PONG timeout` is that evidence. The experiments here
+119
report the two separately for this reason.
+120
+121
## The SYN-drop positive control — do not remove it
+122
+123
`blackhole_new()` stops new connections by filling the accept queue and
+124
never accepting, so the kernel drops further SYNs and a connect hangs
+125
for its full retransmit budget (~135s).
+126
+127
If the queue does not actually fill, the listening socket **refuses**
+128
instead, and a connect fails in about 5 seconds. Refused and dropped
+129
are **different failures**, not a strong and a weak version of one. An
+130
experiment that believes it is measuring the first while measuring the
+131
second still produces numbers, and the numbers still look like results.
+132
+133
So the mode carries two controls, and they answer different questions:
+134
+135
- `assert_accepting()` — the **negative control**. Proves the probe can
+136
see a HEALTHY port. Without it, a probe that reported "hung"
+137
unconditionally would pass the positive control for free.
+138
- `assert_blackholing()` — the **positive control**. Proves new
+139
connections HANG, and raises loudly and specifically if they are
+140
merely refused.
+141
+142
`python3 test/harness/proxy.py` runs both and prints the
+143
classification either side of the switch:
+144
+145
```
+146
before blackhole_new(): fresh connect -> 'connected'
+147
[PASS] negative control: probe sees a HEALTHY port
+148
after blackhole_new(): fresh connect -> 'hung'
+149
[PASS] positive control: new connections are DROPPED, not refused
+150
```
+151
+152
`python3 test/harness/proxy_control_test.py` then breaks the mode three
+153
ways and asserts the control goes red for each — listener closed
+154
(→ refused), `blackhole_new()` a no-op, and a backlog large enough that
+155
the kernel completes the handshake by itself. A control that has only
+156
ever been seen passing is indistinguishable from one that always
+157
passes.
+158
+159
Both controls score their own single probe. An earlier version probed
+160
separately and compared the answers, which is a race rather than a
+161
check — two connects can land on different port states, and one did.
test/harness/exp_chatty_vs_silent.pyadded
@@ -0,0 +1,152 @@
+1
#!/usr/bin/env python3
+2
"""Does a bot that POSTS still notice its link has died?
+3
+4
The defect: the keepalive idle clock was refreshed by outbound traffic
+5
as well as inbound. A write succeeds into the local kernel send buffer
+6
whatever the peer is doing, so a bot posting more often than the 60s
+7
idle threshold kept resetting its own timer and never PINGed -- and so
+8
never detected the dead link at all. The busier the bot, the blinder.
+9
+10
MATCHED PAIR, which is what makes this a measurement rather than an
+11
anecdote: two workers, the SAME proxy, frozen at the SAME instant,
+12
differing ONLY in whether they post.
+13
+14
chatty -- posts every 20s (below the 60s idle threshold)
+15
silent -- says nothing
+16
+17
`silent` is the internal control. Its detection time should be
+18
unchanged by any of this, and if it ever moves, the run is not
+19
comparable to the one before it and the delta on `chatty` is not
+20
attributable to the code.
+21
+22
A NOTE ON WHAT THE HARNESS ITSELF PROVIDES, so nobody cites it as
+23
safety: the freeze-proxy still forwards the server's eventual FIN even
+24
in frozen mode, so a bot can be rescued by the server closing the
+25
connection. Under a real blackhole that close travels the same dead
+26
path and never arrives. Detection via `Apiary reconnected` alone is
+27
therefore NOT evidence the bot detected anything itself; only its own
+28
`PONG timeout` is. Both are reported below, separately, for that
+29
reason.
+30
+31
Run against BOTH binaries:
+32
+33
APIARY_BIN=/path/to/pre-change python3 test/harness/exp_chatty_vs_silent.py
+34
APIARY_BIN=/path/to/post-change python3 test/harness/exp_chatty_vs_silent.py
+35
"""
+36
import os
+37
import re
+38
import sys
+39
import threading
+40
import time
+41
+42
sys.path.insert(0, os.path.dirname(os.path.abspath(__file__)))
+43
from mcpdrv import (Bot, leader_env, worker_env, load_state, # noqa: E402
+44
say, check, unique_nick)
+45
from proxy import Proxy # noqa: E402
+46
+47
PROXY_PORT = int(os.environ.get("HARNESS_PROXY_PORT", "49783"))
+48
WATCH = float(os.environ.get("HARNESS_WATCH", "200"))
+49
CHAT_EVERY = float(os.environ.get("HARNESS_CHAT_EVERY", "20"))
+50
+51
+52
def main():
+53
st = load_state()
+54
port, token = st["PORT"], st["LEADER_TOKEN"]
+55
proxy = Proxy(PROXY_PORT, int(port))
+56
bots, nicks = [], {}
+57
try:
+58
leader = Bot("cs-leader", leader_env(port, token))
+59
bots.append(leader)
+60
leader.initialize()
+61
if not leader.wait_connected(30):
+62
raise SystemExit("leader never connected")
+63
+64
made = {}
+65
for role in ("chatty", "silent"):
+66
nick = unique_nick(f"{role[:4]}-")
+67
nicks[role] = nick
+68
out = leader.call("spawn-worker", nick=nick,
+69
**{"expires-in": "60m"})
+70
m = re.search(r"[a-f0-9]{64}", out)
+71
if not m:
+72
raise SystemExit(f"spawn {nick} failed: {out!r}")
+73
b = Bot(f"cs-{role}",
+74
worker_env(str(PROXY_PORT), m.group(0), nick))
+75
bots.append(b)
+76
b.initialize()
+77
made[role] = b
+78
for role, b in made.items():
+79
if not b.wait_connected(30):
+80
raise SystemExit(f"{role} never connected through the proxy")
+81
say(f"both workers connected through the proxy "
+82
f"(chatty={nicks['chatty']}, silent={nicks['silent']})")
+83
+84
say("\n== freezing BOTH sockets at the same instant ==")
+85
proxy.freeze_existing()
+86
t0 = time.time()
+87
+88
stop = threading.Event()
+89
posts = {"n": 0}
+90
+91
def chatter():
+92
while not stop.is_set():
+93
posts["n"] += 1
+94
try:
+95
# Multi-word payload: a single-token body is relayed
+96
# without its ':' and arrives empty, so a harness
+97
# using one would be posting nothing.
+98
made["chatty"].call(
+99
"send-channel",
+100
text=f"chatty milestone {posts['n']:02d}",
+101
timeout=25)
+102
except Exception:
+103
pass
+104
stop.wait(CHAT_EVERY)
+105
+106
threading.Thread(target=chatter, daemon=True).start()
+107
+108
say(f" watching {WATCH:.0f}s for each to notice on its OWN keepalive...")
+109
detect = {"chatty": None, "silent": None}
+110
while time.time() - t0 < WATCH:
+111
for role, b in made.items():
+112
if detect[role] is None and b.grep_stderr("PONG timeout"):
+113
detect[role] = round(time.time() - t0, 1)
+114
say(f" {role}: PONG timeout at t+{detect[role]}s")
+115
if all(v is not None for v in detect.values()):
+116
break
+117
time.sleep(1)
+118
stop.set()
+119
time.sleep(1)
+120
+121
say("\n== reconnect status (NOT the same claim as detection) ==")
+122
for role, b in made.items():
+123
rec = b.grep_stderr("Apiary reconnected")
+124
say(f" {role}: reconnected={bool(rec)}")
+125
+126
say("")
+127
ok = True
+128
ok &= check("INTERNAL CONTROL: the silent worker detected on its own "
+129
"keepalive",
+130
detect["silent"] is not None,
+131
f"t+{detect['silent']}s" if detect["silent"]
+132
else f"never in {WATCH:.0f}s -- the run is not comparable")
+133
ok &= check("the CHATTY worker detected on its own keepalive",
+134
detect["chatty"] is not None,
+135
f"t+{detect['chatty']}s ({posts['n']} posts made)"
+136
if detect["chatty"]
+137
else f"NEVER in {WATCH:.0f}s despite {posts['n']} posts "
+138
"-- posting suppressed its own detection")
+139
say(f"\n chatty t+{detect['chatty']}s silent t+{detect['silent']}s"
+140
f" posts={posts['n']}")
+141
return 0 if ok else 1
+142
finally:
+143
if bots and bots[0].alive():
+144
for nick in nicks.values():
+145
bots[0].call("revoke-worker", nick=nick)
+146
for b in bots:
+147
b.close()
+148
proxy.close()
+149
+150
+151
if __name__ == "__main__":
+152
sys.exit(main())
test/harness/exp_confirm_latency.pyadded
@@ -0,0 +1,115 @@
+1
#!/usr/bin/env python3
+2
"""How long does post-time delivery confirmation actually take?
+3
+4
`+post-confirm-timeout+` bounds the wait for the PONG that proves the
+5
peer consumed a post. A budget picked by intuition is a bad budget: set
+6
too tight it produces UNCONFIRMED on a healthy-but-slow link, and the
+7
first person who sees a spurious one starts ignoring the warning --
+8
which destroys the signal the whole mechanism exists to create.
+9
+10
So measure it. This posts N times over a healthy connection and reports
+11
the distribution of the confirmation latency apiary logged, plus the
+12
wall-clock latency of the tool call itself as a second, differently
+13
shaped signal.
+14
+15
It also settles a load-bearing assumption CHEAPLY: that the event-loop
+16
goroutine keeps reading the socket while the confirmation wait sleeps.
+17
If it did not, nothing could ever ack the token, every post would burn
+18
the full budget, and every post would come back UNCONFIRMED. A run in
+19
which posts confirm in milliseconds is that assumption's proof.
+20
+21
APIARY_BIN=$PWD/build/release/bin/apiary \
+22
python3 test/harness/exp_confirm_latency.py [N]
+23
"""
+24
import os
+25
import re
+26
import sys
+27
import time
+28
+29
sys.path.insert(0, os.path.dirname(os.path.abspath(__file__)))
+30
from mcpdrv import (Bot, leader_env, worker_env, load_state, # noqa: E402
+31
say, check, unique_nick)
+32
+33
N = int(sys.argv[1]) if len(sys.argv) > 1 else 40
+34
+35
+36
def pct(xs, p):
+37
if not xs:
+38
return None
+39
xs = sorted(xs)
+40
i = min(len(xs) - 1, int(round((p / 100.0) * (len(xs) - 1))))
+41
return xs[i]
+42
+43
+44
def main():
+45
st = load_state()
+46
port, token = st["PORT"], st["LEADER_TOKEN"]
+47
bots = []
+48
nick = None
+49
try:
+50
leader = Bot("lat-leader", leader_env(port, token))
+51
bots.append(leader)
+52
leader.initialize()
+53
if not leader.wait_connected(30):
+54
raise SystemExit("leader never connected")
+55
+56
nick = unique_nick("lat-")
+57
out = leader.call("spawn-worker", nick=nick,
+58
**{"expires-in": "30m"})
+59
m = re.search(r"[a-f0-9]{64}", out)
+60
if not m:
+61
raise SystemExit(f"spawn failed: {out!r}")
+62
w = Bot("lat-work", worker_env(port, m.group(0), nick))
+63
bots.append(w)
+64
w.initialize()
+65
if not w.wait_connected(30):
+66
raise SystemExit("worker never connected")
+67
time.sleep(1)
+68
+69
say(f"== {N} healthy posts ==")
+70
walls, unconfirmed = [], 0
+71
for i in range(N):
+72
# Multi-word payload on purpose: a single-token body is
+73
# relayed without its leading ':' by the server and arrives
+74
# with an EMPTY text, which would silently weaken any
+75
# delivery check built on top of it.
+76
t0 = time.time()
+77
r = w.call("send-channel", text=f"latency probe {i:03d}")
+78
walls.append((time.time() - t0) * 1000.0)
+79
if "UNCONFIRMED" in r:
+80
unconfirmed += 1
+81
time.sleep(1)
+82
+83
logged = [float(x) for x in re.findall(
+84
r"post-confirm confirmed elapsed-ms=([0-9.]+)", w.stderr_text())]
+85
+86
say("\n apiary's own confirmation latency (ms), from its log:")
+87
say(f" samples={len(logged)} p50={pct(logged, 50)} "
+88
f"p95={pct(logged, 95)} max={max(logged) if logged else None}")
+89
say(" tool-call wall clock (ms), independent signal:")
+90
say(f" samples={len(walls)} p50={pct(walls, 50):.1f} "
+91
f"p95={pct(walls, 95):.1f} max={max(walls):.1f}")
+92
+93
ok = True
+94
ok &= check("every healthy post CONFIRMED", unconfirmed == 0,
+95
f"{unconfirmed}/{N} came back UNCONFIRMED")
+96
# The event-loop assumption. Without a concurrently-running
+97
# event loop the wait could never be satisfied and every post
+98
# would cost the full budget.
+99
ok &= check("the event loop runs during the confirmation wait",
+100
bool(logged) and max(logged) < 1000,
+101
f"max logged confirm {max(logged) if logged else 'n/a'}ms "
+102
"-- a stalled loop would show the full budget")
+103
ok &= check("apiary's log and the wall clock agree",
+104
bool(logged) and pct(walls, 50) < 1000,
+105
f"wall p50 {pct(walls, 50):.1f}ms")
+106
return 0 if ok else 1
+107
finally:
+108
if bots and bots[0].alive() and nick:
+109
bots[0].call("revoke-worker", nick=nick)
+110
for b in bots:
+111
b.close()
+112
+113
+114
if __name__ == "__main__":
+115
sys.exit(main())
test/harness/exp_fd_flatness.pyadded
@@ -0,0 +1,124 @@
+1
#!/usr/bin/env python3
+2
"""Do the failure paths leak file descriptors?
+3
+4
Counts the worker process's open fds before and after exercising the
+5
paths this change touches: many post-time confirmation waits, then a
+6
full freeze -> detect -> reconnect cycle.
+7
+8
Run it against BOTH binaries. A single post-change reading cannot show
+9
"we did not regress this" -- it can only show a number. The value is in
+10
the comparison, so the pair is the measurement.
+11
+12
APIARY_BIN=/path/to/pre-change python3 test/harness/exp_fd_flatness.py
+13
APIARY_BIN=/path/to/post-change python3 test/harness/exp_fd_flatness.py
+14
"""
+15
import os
+16
import re
+17
import sys
+18
import time
+19
+20
sys.path.insert(0, os.path.dirname(os.path.abspath(__file__)))
+21
from mcpdrv import (Bot, leader_env, worker_env, load_state, # noqa: E402
+22
say, check, unique_nick)
+23
from proxy import Proxy # noqa: E402
+24
+25
PROXY_PORT = int(os.environ.get("HARNESS_PROXY_PORT", "49785"))
+26
POSTS = int(os.environ.get("HARNESS_POSTS", "40"))
+27
+28
+29
def fd_count(pid):
+30
try:
+31
return len(os.listdir(f"/proc/{pid}/fd"))
+32
except OSError:
+33
return None
+34
+35
+36
def main():
+37
st = load_state()
+38
port, token = st["PORT"], st["LEADER_TOKEN"]
+39
proxy = Proxy(PROXY_PORT, int(port))
+40
bots, nick = [], None
+41
try:
+42
leader = Bot("fd-leader", leader_env(port, token))
+43
bots.append(leader)
+44
leader.initialize()
+45
if not leader.wait_connected(30):
+46
raise SystemExit("leader never connected")
+47
+48
nick = unique_nick("fd-")
+49
out = leader.call("spawn-worker", nick=nick, **{"expires-in": "60m"})
+50
m = re.search(r"[a-f0-9]{64}", out)
+51
if not m:
+52
raise SystemExit(f"spawn failed: {out!r}")
+53
w = Bot("fd-worker", worker_env(str(PROXY_PORT), m.group(0), nick))
+54
bots.append(w)
+55
w.initialize()
+56
if not w.wait_connected(30):
+57
raise SystemExit("worker never connected")
+58
time.sleep(2)
+59
+60
pid = w.proc.pid
+61
base = fd_count(pid)
+62
say(f" worker pid={pid} fds after connect: {base}")
+63
if base is None:
+64
raise SystemExit("cannot read /proc/<pid>/fd on this host")
+65
+66
say(f"\n== {POSTS} healthy posts (confirmation path) ==")
+67
for i in range(POSTS):
+68
w.call("send-channel", text=f"fd probe healthy {i:03d}")
+69
after_posts = fd_count(pid)
+70
say(f" fds after {POSTS} confirmed posts: {after_posts}")
+71
+72
say("\n== freeze -> detect -> reconnect cycle ==")
+73
proxy.freeze_existing()
+74
t0 = time.time()
+75
i = 0
+76
while time.time() - t0 < 45:
+77
i += 1
+78
try:
+79
w.call("send-channel",
+80
text=f"fd probe outage {i:03d}", timeout=25)
+81
except TimeoutError:
+82
pass
+83
time.sleep(5)
+84
after_outage_posts = fd_count(pid)
+85
say(f" fds after {i} posts into a dead link: {after_outage_posts}")
+86
+87
proxy.frozen_at = {}
+88
deadline = time.time() + 150
+89
while (time.time() < deadline
+90
and not w.grep_stderr("Apiary reconnected")):
+91
time.sleep(1)
+92
reconnected = bool(w.grep_stderr("Apiary reconnected"))
+93
time.sleep(5)
+94
after_reconnect = fd_count(pid)
+95
say(f" reconnected: {reconnected}")
+96
say(f" fds after reconnect: {after_reconnect}")
+97
+98
say("")
+99
ok = True
+100
ok &= check("fd count flat across the confirmation path",
+101
after_posts - base <= 1,
+102
f"{base} -> {after_posts} (delta "
+103
f"{after_posts - base}) over {POSTS} posts")
+104
ok &= check("fd count flat across posts into a dead link",
+105
after_outage_posts - base <= 1,
+106
f"{base} -> {after_outage_posts} (delta "
+107
f"{after_outage_posts - base}) over {i} posts")
+108
ok &= check("fd count flat across detect + reconnect",
+109
abs(after_reconnect - base) <= 1,
+110
f"{base} -> {after_reconnect} (delta "
+111
f"{after_reconnect - base})")
+112
say(f"\n SUMMARY connect={base} posts={after_posts} "
+113
f"outage={after_outage_posts} reconnect={after_reconnect}")
+114
return 0 if ok else 1
+115
finally:
+116
if bots and bots[0].alive() and nick:
+117
bots[0].call("revoke-worker", nick=nick)
+118
for b in bots:
+119
b.close()
+120
proxy.close()
+121
+122
+123
if __name__ == "__main__":
+124
sys.exit(main())
test/harness/exp_silent_loss.pyadded
@@ -0,0 +1,176 @@
+1
#!/usr/bin/env python3
+2
"""Does a post made during an outage claim to have been delivered?
+3
+4
The defect: with a worker's socket frozen, every `send-channel` call
+5
returned `Broadcast to <channel> (1 line)` and NONE of the messages
+6
arrived. A worker riding through a network switch reports milestones it
+7
never sent, and neither it nor its leader can tell. That is worse than
+8
a wedge -- a wedge is visibly stuck; this lies.
+9
+10
METHOD, and the part of it that carries the whole result:
+11
+12
* The LEADER is the observer, and it talks to the server DIRECTLY.
+13
Only the worker's path is broken, so the observer stays reliable
+14
for the whole run. Delivery is scored by what the LEADER RECEIVED,
+15
never by what the sender reported -- the entire defect is that the
+16
sender's report is not evidence, so a harness that trusted it would
+17
be measuring nothing.
+18
+19
* A control post BEFORE the freeze, with the same code path and the
+20
same shape of payload, establishes that the observer can see a
+21
delivered message. Without it, "nothing arrived" is equally
+22
consistent with a broken observer.
+23
+24
* A control post AFTER recovery closes the other direction. A change
+25
that reported failure for everything would pass the first half of
+26
this experiment perfectly.
+27
+28
Payloads are multi-word on purpose. The server relays a single-token
+29
body without its leading ':', so it arrives with an EMPTY text and the
+30
observer cannot match it -- which would look exactly like a loss.
+31
+32
Run against BOTH binaries; the result only means something as a pair:
+33
+34
APIARY_BIN=/path/to/pre-change python3 test/harness/exp_silent_loss.py
+35
APIARY_BIN=/path/to/post-change python3 test/harness/exp_silent_loss.py
+36
"""
+37
import os
+38
import re
+39
import sys
+40
import time
+41
+42
sys.path.insert(0, os.path.dirname(os.path.abspath(__file__)))
+43
from mcpdrv import (Bot, leader_env, worker_env, load_state, # noqa: E402
+44
say, check, unique_nick, CHANNEL)
+45
from proxy import Proxy # noqa: E402
+46
+47
PROXY_PORT = int(os.environ.get("HARNESS_PROXY_PORT", "49781"))
+48
POSTS = int(os.environ.get("HARNESS_POSTS", "14"))
+49
INTERVAL = float(os.environ.get("HARNESS_INTERVAL", "10"))
+50
+51
+52
def claims_delivery(result):
+53
"""Did the tool result assert the message was delivered?
+54
+55
'Broadcast'/'Posted' are delivery claims. A result that also says
+56
UNCONFIRMED is not claiming delivery whatever verb it leads with.
+57
"""
+58
if "UNCONFIRMED" in result:
+59
return False
+60
return ("Broadcast to" in result) or ("Posted to" in result)
+61
+62
+63
def main():
+64
st = load_state()
+65
port, token = st["PORT"], st["LEADER_TOKEN"]
+66
proxy = Proxy(PROXY_PORT, int(port))
+67
bots, nick = [], None
+68
try:
+69
leader = Bot("loss-leader", leader_env(port, token))
+70
bots.append(leader)
+71
leader.initialize()
+72
if not leader.wait_connected(30):
+73
raise SystemExit("leader never connected")
+74
+75
nick = unique_nick("loss-")
+76
out = leader.call("spawn-worker", nick=nick, **{"expires-in": "60m"})
+77
m = re.search(r"[a-f0-9]{64}", out)
+78
if not m:
+79
raise SystemExit(f"spawn failed: {out!r}")
+80
w = Bot("loss-worker",
+81
worker_env(str(PROXY_PORT), m.group(0), nick))
+82
bots.append(w)
+83
w.initialize()
+84
if not w.wait_connected(30):
+85
raise SystemExit("worker never connected through the proxy")
+86
+87
say("== CONTROL A: a post BEFORE the freeze ==")
+88
r0 = w.call("send-channel", text="loss control before freeze")
+89
got0 = leader.wait_notification("loss control before freeze",
+90
timeout=10) is not None
+91
say(f" returned {r0!r}")
+92
say(f" leader received it: {got0}")
+93
+94
say("\n== freezing the worker's socket (no FIN, no RST) ==")
+95
proxy.freeze_existing()
+96
t0 = time.time()
+97
+98
rows = []
+99
for i in range(1, POSTS + 1):
+100
at = time.time() - t0
+101
tag = f"loss probe {i:03d}"
+102
try:
+103
r = w.call("send-channel",
+104
text=f"{tag} at t plus {at:.0f}s", timeout=30)
+105
except TimeoutError:
+106
r = "<TOOL CALL TIMED OUT>"
+107
rows.append((round(at), tag, r))
+108
time.sleep(INTERVAL)
+109
+110
say("\n== waiting 30s for any late delivery, then scoring ==")
+111
time.sleep(30)
+112
delivered = set()
+113
for c in leader.contents():
+114
mm = re.search(r"loss probe (\d{3})", c)
+115
if mm and c.startswith(f"{nick}: "):
+116
delivered.add(f"loss probe {mm.group(1)}")
+117
+118
say("\n t+ message claimed delivery? leader got it?")
+119
say(" " + "-" * 62)
+120
silent_losses = 0
+121
for at, tag, r in rows:
+122
ok = tag in delivered
+123
claimed = claims_delivery(r)
+124
flag = ""
+125
if claimed and not ok:
+126
flag = " <-- SILENT LOSS"
+127
silent_losses += 1
+128
say(f" {at:<4} {tag:<16} {'YES' if claimed else 'no':<18}"
+129
f"{'YES' if ok else 'no':<4}{flag}")
+130
+131
say("\n sample of what the worker was told:")
+132
for at, tag, r in rows[:3]:
+133
say(f" t+{at:<4} {r[:150]!r}")
+134
+135
say("\n== CONTROL B: a post AFTER the outage ==")
+136
say(" (unfreezing so a reconnected socket can carry traffic)")
+137
proxy.frozen_at = {}
+138
deadline = time.time() + 150
+139
while time.time() < deadline and not w.grep_stderr("Apiary reconnected"):
+140
time.sleep(1)
+141
reconnected = bool(w.grep_stderr("Apiary reconnected"))
+142
say(f" worker reconnected: {reconnected}")
+143
time.sleep(3)
+144
r1 = w.call("send-channel", text="loss control after recovery",
+145
timeout=30)
+146
got1 = leader.wait_notification("loss control after recovery",
+147
timeout=15) is not None
+148
say(f" returned {r1!r}")
+149
say(f" leader received it: {got1}")
+150
+151
say("")
+152
ok = True
+153
ok &= check("CONTROL A: the observer can see a delivered post",
+154
got0 and claims_delivery(r0),
+155
"if this fails, nothing below means anything")
+156
ok &= check("no post claimed delivery it did not achieve",
+157
silent_losses == 0,
+158
f"{silent_losses}/{len(rows)} claimed delivery and "
+159
"were never delivered")
+160
ok &= check("CONTROL B: a healthy post still reports success",
+161
got1 and claims_delivery(r1),
+162
"a fix that reports failure for everything would "
+163
"pass the check above")
+164
say(f"\n silent losses: {silent_losses}/{len(rows)} "
+165
f"delivered during outage: {len(delivered)}/{len(rows)}")
+166
return 0 if ok else 1
+167
finally:
+168
if bots and bots[0].alive() and nick:
+169
say(" " + repr(bots[0].call("revoke-worker", nick=nick)))
+170
for b in bots:
+171
b.close()
+172
proxy.close()
+173
+174
+175
if __name__ == "__main__":
+176
sys.exit(main())
test/harness/mcpdrv.pymodified
@@ -258,6 +258,18 @@ def worker_env(port, token, nick, reports_to=None,
258
return e
259
260
+261
def unique_nick(prefix):
+262
"""A nick that has not been used on this server before.
+263
+264
Revoking a bot DISABLES the row rather than deleting it, so the
+265
nick stays burned: re-running an experiment with a fixed nick fails
+266
with `name-taken`. That failure is loud, but in a matched pair it
+267
lands on the SECOND arm, which is the arm you are testing -- so a
+268
careless run reports the pre-change result and nothing else.
+269
"""
+270
return f"{prefix}{int(time.time()) % 100000}"
+271
+272
273
def say(*a):
274
print(*a, flush=True)
275