test/harness/exp_silent_loss.py

1#!/usr/bin/env python3

2"""Does a post made during an outage claim to have been delivered?

4The defect: with a worker's socket frozen, every `send-channel` call

5returned `Broadcast to <channel> (1 line)` and NONE of the messages

6arrived. A worker riding through a network switch reports milestones it

7never sent, and neither it nor its leader can tell. That is worse than

8a wedge -- a wedge is visibly stuck; this lies.

10METHOD, and the part of it that carries the whole result:

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.

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.

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.

28Payloads are multi-word on purpose. The server relays a single-token

29body without its leading ':', so it arrives with an EMPTY text and the

30observer cannot match it -- which would look exactly like a loss.

32Run against BOTH binaries; the result only means something as a pair:

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

37import os

38import re

39import sys

40import time

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

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

44 say, check, unique_nick, CHANNEL)

45from proxy import Proxy # noqa: E402

47PROXY_PORT = int(os.environ.get("HARNESS_PROXY_PORT", "49781"))

48POSTS = int(os.environ.get("HARNESS_POSTS", "14"))

49INTERVAL = float(os.environ.get("HARNESS_INTERVAL", "10"))

52def claims_delivery(result):

53 """Did the tool result assert the message was delivered?

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)

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

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

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

94 say("\n== freezing the worker's socket (no FIN, no RST) ==")

95 proxy.freeze_existing()

96 t0 = time.time()

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

175if __name__ == "__main__":

176 sys.exit(main())