test/harness/exp_confirm_latency.py

1#!/usr/bin/env python3

2"""How long does post-time delivery confirmation actually take?

4`+post-confirm-timeout+` bounds the wait for the PONG that proves the

5peer consumed a post. A budget picked by intuition is a bad budget: set

6too tight it produces UNCONFIRMED on a healthy-but-slow link, and the

7first person who sees a spurious one starts ignoring the warning --

8which destroys the signal the whole mechanism exists to create.

10So measure it. This posts N times over a healthy connection and reports

11the distribution of the confirmation latency apiary logged, plus the

12wall-clock latency of the tool call itself as a second, differently

13shaped signal.

15It also settles a load-bearing assumption CHEAPLY: that the event-loop

16goroutine keeps reading the socket while the confirmation wait sleeps.

17If it did not, nothing could ever ack the token, every post would burn

18the full budget, and every post would come back UNCONFIRMED. A run in

19which posts confirm in milliseconds is that assumption's proof.

21 APIARY_BIN=$PWD/build/release/bin/apiary \

22 python3 test/harness/exp_confirm_latency.py [N]

23"""

24import os

25import re

26import sys

27import time

29sys.path.insert(0, os.path.dirname(os.path.abspath(__file__)))

30from mcpdrv import (Bot, leader_env, worker_env, load_state, # noqa: E402

31 say, check, unique_nick)

33N = int(sys.argv[1]) if len(sys.argv) > 1 else 40

36def 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]

44def 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")

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)

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)

83 logged = [float(x) for x in re.findall(

84 r"post-confirm confirmed elapsed-ms=([0-9.]+)", w.stderr_text())]

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}")

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

114if __name__ == "__main__":

115 sys.exit(main())