Re-acquire the poller claim periodically, and fix two review findings
Three changes, two of them defects found by adversarial review of the previous commits.
- TOCTOU in the stale-claim break (the serious one). break-stale-claim! unlinked the claim unconditionally. Deciding the owner is dead involves a proc-comm port read, which yields the scheduler inside the supervisor goroutine, so a second instance reaching the same verdict can have broken AND retaken the claim in between -- and the blind delete would then remove a LIVE owner's claim, leaving both instances polling. That is the original 409 bug re-entering through the repair path, with nothing left to notice it. The unlink is now conditional on the claim still naming the pid we judged; a racer that still slips through loses at the settle check.
- Log pruning could delete a LIVE instance's log. It selected purely by mtime, and mtime is whole seconds and goes stale on an idle process. A leader alive since Jul 23 with ten newer generations behind it would have been pruned while running -- destroying exactly the long-lived evidence per-instance logs exist to preserve, from the same long-lived session that caused the original problem. Pruning now consults pid-liveness (reused from the claim module) and only ever removes logs whose owning process is gone. A name carrying no pid, such as a worker's courier-<task>.log, is not ours to judge and is left alone.
- Periodic re-acquire of the claim, approved by the leader after I raised that the brief's "do not retry in a loop" produced a worse failure than the one it fixed. Acquiring once and giving up means that when the HOLDER exits, every other healthy instance has already decided, and nothing polls again until a brand-new process starts: a silent go-dark in place of a visible 409 storm. Non-holders now re-check every 60s. Logging is on state change only, so a long-lived non-polling session writes one line, not one a minute, and the normal case is never a warn.
Harness case 4 now proves the takeover with the ORIGINAL instance rather than a fresh one -- measured: skip logged at 06:11:55, takeover at 06:12:55, exactly one skip line and exactly one takeover line.
Also from review, no behaviour change: courier-state-dir replaces four open-coded copies of (path-dirname (default-relay-dir)); claim-token-hash uses string-pad; prune uses glob; two comments that this branch had made untrue were corrected; the appended test group moved above (run-tests) so it runs under direct invocation too.
Suite 111/0. Harness 44/0 with the pre-fix control still red (4 conflicts, 2 poller children). Storm repro 1 send -> 1 delivery with its window-neutered positive control at 4. Sentinel-zero repro green.
repro/single_poller_harness.py | 101 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++--------------
src/courier/claim.sgl | 30 +++++++++++++++++++++---------
src/courier/dedup.sgl | 2 +-
src/courier/main.sgl | 64 +++++++++++++++++++++++++++++++++++++++++++++-------------------
src/courier/poller.sgl | 52 +++++++++++++++++++++++++++++++++++++++++-----------
src/courier/relay.sgl | 10 ++++++++++
src/courier/telegram.sgl | 16 +++++++++++-----
test/test-telegram.sgl | 4 ++--
8 files changed, 218 insertions(+), 61 deletions(-)repro/single_poller_harness.pymodified
pointed at the local mock, which is the only endpoint the send AND poll pathsuse once that variable is set.What it proves, in the order the cases run:The cases are NUMBERED BY TOPIC, and run in the order 1, 3, 4, 7, 8, 5, 6, 2 --the ordering is dictated by shared state (cases 1, 3, 4 and 7 all operate on thesame pair of live instances, and the pre-fix control in case 2 runs last so its409s can never be confused with the fixed binary's). What each proves: 1 ONE POLLER two leader-mode couriers on one token -> exactly one poller child process, and zero 409s at the mock. is a claim of absence made by an instrument never shown capable of detecting presence. 3 NON-POLLER IS FINE the instance that lost the claim still serves its MCP tools -- create-relay / list-relays / close-relay. 4 SIGKILL RECOVERY SIGKILL (not a graceful stop) the claim holder, start a fresh instance: it detects the dead owner, breaks the stale claim, and polls. MCP tools -- create-relay, a real worker connecting over that relay, send both ways, close-relay. 4 SIGKILL RECOVERY SIGKILL (not a graceful stop) the claim holder, then (a) the OTHER already-running instance re-acquires and starts polling on its own, and (b) a fresh instance can also break a stale claim. (a) is the one that matters: without the periodic re-acquire, a healthy instance would sit there forever and the estate would silently stop receiving Telegram. 5 DRY-RUN IS HONEST with COURIER_DISABLE_TELEGRAM_SEND=1 the tool returns a string that cannot be read as success, does not raise, and delivers nothing at the mock. log files, and grep works on both (the shared-log interleaving produced NUL bytes, which made grep silently report zero matches during an incident). 8 LOG PRUNING instance logs are capped, a LIVE instance's log is never pruned however old it looks, and nothing that is not an instance log is touched.Usage: single_poller_harness.py --bin <courier> [--control-bin <pre-fix courier>]# binary would only mean "we did not watch for long enough".OBSERVE_WINDOW = 20# Must match *claim-recheck-interval* in src/courier/poller.sgl.CLAIM_RECHECK = 60FAILED = []PASSED = [] r == "Relay 'harness-relay' closed.", repr(r))def case_sigkill(binp, run_dir, a, state_dir):def case_sigkill(binp, run_dir, a, b, state_dir): print("=== 4 SIGKILL RECOVERY ===") dead_pid = a.pid a.sigkill() owner == str(dead_pid), f"owner={owner} killed={dead_pid}") # (a) The instance that was ALREADY RUNNING and had been told to skip must # take over by itself. This is the case that would silently not happen if # the supervisor acquired once and gave up: B is healthy, holds the token, # and would never poll again. took_over = wait_for(lambda: len(poller_children(b.pid)) == 1, timeout=CLAIM_RECHECK + 45) check("the already-running non-poller re-acquires and starts polling", took_over, f"B children={poller_children(b.pid)} " f"claim owner={claim_owner(state_dir)}") check("the claim now records the instance that took over", claim_owner(state_dir) == str(b.pid), f"owner={claim_owner(state_dir)} B={b.pid}") log = b.log_text() check("the takeover is logged, once, at INFO", len([l for l in log.splitlines() if "previous holder is gone" in l]) == 1, repr([l for l in log.splitlines() if "claim" in l])) # And the skip line was NOT repeated every recheck interval. check("the periodic re-check does not spam the log", len([l for l in log.splitlines() if "another courier instance holds" in l]) == 1, f"{len([l for l in log.splitlines() if 'another courier instance holds' in l])} skip lines") # (b) A fresh instance can break a stale claim too. Kill the new holder # hard so the claim is stale again. b.sigkill() time.sleep(1) c = Courier(binp, run_dir, "inst-c") c.initialize() got = wait_for(lambda: len(poller_children(c.pid)) == 1, timeout=45) # Staggered mtimes, oldest first, so "keep the newest N" is testable. os.utime(p, (now - (100 - i) * 60, now - (100 - i) * 60)) fakes.append(p) # A log belonging to a LIVE COURIER, made to look ancient. This is the # Jul-23 case: a long-lived session whose log has an old mtime because it # has been quiet, with ten newer generations behind it. Pruning it by age # would destroy exactly the evidence per-instance logs exist to preserve # -- and it is the same long-lived process that caused the original bug. # # It has to be a real courier, not this harness: liveness is "the pid is # running AND its comm matches courier's", so a live PYTHON pid is # correctly judged a recycled pid and pruned. (Measured: the first # version of this fixture used os.getpid() and failed for exactly that # reason -- the code was right and the fixture was wrong.) live = Courier(binp, d, "prune-live") live.initialize() live_old = live.log_path() os.utime(live_old, (now - 90 * 86400, now - 90 * 86400)) # A worker-style name (no pid) must also be left alone. worker_log = os.path.join(d, "courier-some-task-name.log") with open(worker_log, "w") as f: f.write("worker log\n") os.utime(worker_log, (now - 91 * 86400, now - 91 * 86400)) # Files that are NOT instance logs must survive untouched. bystanders = { os.path.join(d, "send-dedup.state"): "1 abc\n", time.sleep(2) remaining = sorted(n for n in os.listdir(d) if n.startswith("courier-") and n.endswith(".log")) check("instance logs are capped at 10", len(remaining) == 10, f"{len(remaining)} remain: {remaining}") dead_remaining = [n for n in remaining if n not in (f"courier-{c.pid}.log", os.path.basename(live_old), os.path.basename(worker_log))] check("dead instance logs are capped at 10", len(dead_remaining) == 10, f"{len(dead_remaining)} dead remain: {dead_remaining}") check("the instance's own log survived pruning", f"courier-{c.pid}.log" in remaining, f"{remaining}") check("the OLDEST fakes are the ones removed", check("the OLDEST dead fakes are the ones removed", os.path.basename(fakes[0]) not in remaining and os.path.basename(fakes[14]) in remaining, f"{remaining}") # The rule that matters: liveness beats age. check("a LIVE instance's log survives even when 90 days old", os.path.basename(live_old) in remaining, f"{remaining}") check("a log whose name carries no pid is left alone", os.path.basename(worker_log) in remaining, f"{remaining}") survived = [os.path.basename(p) for p in bystanders if os.path.exists(p)] check("non-log files (dedup state, offset) are untouched", len(survived) == len(bystanders), f"survived={survived} of {[os.path.basename(p) for p in bystanders]}") c.close_stdin() for inst in (c, live): inst.close_stdin() time.sleep(1) c.kill() for inst in (c, live): inst.kill()EXPECTED_DRY_RUN = ("Message NOT sent: COURIER_DISABLE_TELEGRAM_SEND is set " a, b, state_dir = case_one_poller(args.bin, run_dir) instances += [a, b] case_relay_tools(args.bin, b, run_dir) c = case_sigkill(args.bin, run_dir, a, state_dir) c = case_sigkill(args.bin, run_dir, a, b, state_dir) instances.append(c) pids = [a.pid, b.pid, c.pid] for inst in (b, c): inst.close_stdin() c.close_stdin() time.sleep(1.5) case_log_hygiene(run_dir, pids) for inst in instances:src/courier/claim.sglmodified
;;; little to reconstruct a token from. (define (claim-token-hash token) (: string? -> string?) (let* ((h (fnv1a-hex token)) (n (string-length h)) (padded (if (< n 16) (string-append (make-string (- 16 n) #\0) h) h))) (substring padded 0 12))) (substring (string-pad (fnv1a-hex token) 16 #\0) 0 12)) ;;; Where the claim for `token` lives. Scoped to the token (two bots on ;;; one machine do not collide) AND to the relay dir (so a test courier ;;; with its own COURIER_RELAY_DIR never contends with the live one). (define (poller-claim-path token) (: string? -> string?) (path-join (path-dirname (default-relay-dir)) (path-join (courier-state-dir) (string-append "telegram-poller-" (claim-token-hash token) ".claim"))) ;; Present but unreadable: leave it alone rather than break ;; something we cannot attribute. ((not owner) 'held-by-other) ;; Our own pid already in the link (a re-entry): keep it. ;; Our own pid already in the link. Normally try-claim! ;; has already returned 'acquired for this, since it reads ;; the link back; this is the path where make-symlink ;; RAISED (EACCES, ENOENT on a vanished dir) over a claim ;; we still hold, so it is reachable only via try-claim!'s ;; guard. Keeping it means a transient filesystem error ;; cannot make us abandon a claim we own. ((string=? owner me) (set-car! *held-claim* path) 'acquired) (define (break-stale-claim! path owner me) (log-info "Breaking stale Telegram poller claim (owner gone)" owner-pid: owner) (guard (e (else #f)) (delete-file path)) ;; Unlink ONLY while the claim still names the dead pid we just judged. ;; An unconditional delete here is a TOCTOU big enough to drive two ;; pollers through: deciding `owner` is dead involves a proc-comm port ;; read, which yields the scheduler inside the supervisor goroutine, so ;; a second instance that reached the same verdict can have broken the ;; claim AND taken it in the meantime. Deleting blind would then remove ;; a LIVE owner's claim, and both instances would poll -- the exact 409 ;; storm this module exists to remove, with no path to notice it. ;; Re-reading first narrows the window to the unlink itself, and a ;; racer that slips through still loses at the settle check below. (when (equal? (read-claim-owner path) owner) (guard (e (else #f)) (delete-file path))) (if (not (eq? (try-claim! path me) 'acquired)) 'held-by-other (beginsrc/courier/dedup.sglmodified
override ;; ".state", not ".log": this is a rewritten-in-place state set, ;; not an append log like courier.log. (path-join (path-dirname (default-relay-dir)) "send-dedup.state")))) (path-join (courier-state-dir) "send-dedup.state")))) ;; ---- FNV-1a 64-bit key hashing (no plaintext on disk) ---- (define *fnv-offset* 14695981039346656037)src/courier/main.sglmodified
(sigil mcp channel) (sigil log) (courier config) (courier claim) (courier telegram) (courier poller) (courier notify) ;; How many courier-<pid>.log files to keep in the state dir. (define *log-keep-generations* 10) ;; The pid encoded in a courier-<pid>.log path, or #f if the name does ;; not carry one (a worker's courier-<task>.log, for instance). (define (instance-log-pid path) (let* ((base (path-basename path)) (n (string-length base)) (stem (substring base 8 (- n 4)))) ;; "courier-" ... ".log" (and (string->number stem) stem))) ;; Is this log file being written by a process that is still running? ;; Reuses the claim module's liveness check rather than inferring from ;; mtime. mtime is whole seconds and an idle-but-alive instance can have ;; a very old one -- a leader alive since Jul 23 with ten newer ;; generations behind it would be pruned while running, silently ;; destroying exactly the long-lived evidence per-instance logs exist to ;; preserve. A name with no pid in it is not ours to judge, so it is ;; treated as live and left alone. (define (instance-log-live? path) (let ((pid (instance-log-pid path))) (if (not pid) #t (not (eq? 'dead (pid-liveness pid)))))) ;; Remove all but the newest *log-keep-generations* courier-<pid>.log ;; files. Best-effort and never fatal: a failure here costs disk, not ;; correctness. A live instance's file has a recent mtime and is ;; therefore kept; even if one were removed, Unix keeps the open fd ;; valid, so the writer cannot be broken by this. ;; files whose owning process is GONE. Best-effort and never fatal: a ;; failure here costs disk, not correctness. (define (prune-instance-logs! log-dir) (guard (e (else #f)) (let* ((entries (or (directory-list log-dir) '())) (logs (filter (lambda (n) (and (string-starts-with? n "courier-") (string-ends-with? n ".log"))) entries)) (paths (map (lambda (n) (path-join log-dir n)) logs)) (let* ((dead (filter (lambda (p) (not (instance-log-live? p))) (glob (path-join log-dir "courier-*.log")))) (sorted (list-sort (lambda (a b) (> (or (file-mtime a) 0) (or (file-mtime b) 0))) paths))) dead))) (let loop ((rest sorted) (i 0)) (unless (null? rest) (when (>= i *log-keep-generations*) (guard (e (else #f)) (delete-file (car rest)))) (loop (cdr rest) (+ i 1))))))) ;; Configure persistent logging for leader mode in APPEND mode, so ;; a hung instance's evidence survives across leader restarts. A ;; /mcp reconnect SIGKILLs the leader and spawns a fresh one; the ;; old rotate-current-to-.prev scheme kept only ONE prior ;; generation, so a hang -> /mcp -> still-hung -> /mcp loop lost ;; the original (load-bearing) evidence. Appending into one file ;; keeps the whole history (capped by *log-carryover-max*). ;; Configure persistent logging for leader mode, so a hung instance's ;; evidence survives across leader restarts. A /mcp reconnect SIGKILLs ;; the leader and spawns a fresh one; the old rotate-current-to-.prev ;; scheme kept only ONE prior generation, so a hang -> /mcp -> ;; still-hung -> /mcp loop lost the original (load-bearing) evidence. ;; ;; That history is now kept by KEEPING THE FILES rather than by ;; concatenating into one. Each generation is its own courier-<pid>.log ;; and prune-instance-logs! retains the ten most recent DEAD ones, so a ;; hang/reconnect loop leaves ten separate, individually readable ;; generations. open-log-append!'s carryover no longer fires on this ;; path (a fresh pid means a fresh filename, so there is nothing to ;; carry); it is kept because pids DO get reused, and truncating a ;; predecessor's log because the kernel handed us its number would lose ;; exactly the evidence this function exists to protect. The --log ;; path still uses the carryover for real. ;; ;; PER-INSTANCE FILE (courier-<pid>.log, was the shared courier.log): ;; append here is EMULATED -- read the old contents, reopen (which ;; configures this (main() calls it whenever no explicit --log target ;; was given), so production never logs to an async port. (define (configure-persistent-log!) (let* ((log-dir (path-dirname (default-relay-dir))) (let* ((log-dir (courier-state-dir)) (log-path (path-join log-dir (string-append "courier-" (number->string (process-id))src/courier/poller.sglmodified
;; connect lets a bad IP be abandoned fast (a working one is tried). (define *poll-connect-timeout* 10) ;; seconds; must be < stale threshold ;; How often an instance that did NOT get the single-poller claim looks ;; again. Without this the fix trades a visible failure for a silent one: ;; the claim HOLDER exits, every other live courier has already decided ;; once and returned, and nothing polls until some brand-new process ;; happens to start. Deliberately slow and quiet -- one filesystem check ;; a minute, logged only on a state CHANGE, never a warn for the normal ;; case of another instance holding it. (define *claim-recheck-interval* 60) ;; Supervisor: wedge detection and restart backoff (define *poller-stale-threshold* 30) ;; seconds of child silence (define *watchdog-interval* 10) ;; seconds between checks ;; Where the offset lives: next to courier.log, keyed off the relay ;; dir so a poller child and the leader agree on the location. (define (offset-file-path) (path-join (path-dirname (default-relay-dir)) "telegram-offset")) (path-join (courier-state-dir) "telegram-offset")) ;; Persisted offset, or #f when the file is absent, unreadable, or ;; not a STRICTLY POSITIVE integer. #f means "cold start" -> drain, ;;; ;;; Telegram allows ONE getUpdates consumer per bot token, so this first ;;; takes the single-poller claim (see (courier claim)). Not getting it is ;;; the NORMAL outcome for the 2nd..Nth concurrent session: this returns ;;; quietly and the instance runs on as a full MCP server -- tools, ;;; relays, sends and notifications all unaffected. There is deliberately ;;; no retry loop and no exit. ;;; the NORMAL outcome for the 2nd..Nth concurrent session: the instance ;;; runs on as a full MCP server -- tools, relays, sends and notifications ;;; all unaffected -- and simply looks again every ;;; *claim-recheck-interval* seconds. ;;; ;;; The re-check is what stops this fix from swapping a loud failure for ;;; a quiet one. Acquiring once and giving up means that when the HOLDER ;;; exits, every other healthy instance has already decided and nothing ;;; polls again until a brand-new process starts. A 409 storm is at least ;;; visible in a log; a poller that silently stopped is not. ;;; ;;; Logging is on STATE CHANGE only, so a long-lived non-polling session ;;; does not write a line a minute forever. (define (telegram-poller-supervisor server config) (: mcp-server? courier-config? -> void?) (channel-wait-initialized! server) (case (acquire-poller-claim! (courier-config-telegram-token config)) ((acquired) (poller-supervise-loop server)) ((held-by-other) (log-info "Telegram polling skipped -- another courier instance holds the poller claim (normal; this instance is fully functional)")) (else (log-warn "Telegram polling skipped -- could not establish poller claim ownership")))) (let ((token (courier-config-telegram-token config))) (let loop ((announced #f)) (let ((result (acquire-poller-claim! token))) (case result ((acquired) (when announced (log-info "Telegram poller claim acquired -- the previous holder is gone")) ;; Never returns: supervises and respawns the child forever. (poller-supervise-loop server)) (else (unless (eq? announced result) (if (eq? result 'held-by-other) (log-info "Telegram polling skipped -- another courier instance holds the poller claim (normal; this instance is fully functional)" recheck-seconds: *claim-recheck-interval*) (log-warn "Telegram polling skipped -- could not establish poller claim ownership" recheck-seconds: *claim-recheck-interval*))) (sleep *claim-recheck-interval*) (loop result))))))) (define (poller-supervise-loop server) (log-info "Telegram polling started (isolated poller process)")src/courier/relay.sglmodified
make-media-upload-envelope default-relay-dir courier-state-dir create-relay! close-relay! register-relay-tools! (or (getenv "COURIER_RELAY_DIR") (path-join (or (getenv "HOME") "/tmp") ".courier" "relays"))) ;;; Where courier keeps its per-machine state: the instance logs, the ;;; getUpdates offset, the send-dedup record, and the single-poller ;;; claim. Derived from the relay dir so all of them move together when ;;; COURIER_RELAY_DIR is overridden -- which is what keeps a test ;;; courier from ever contending with the live one. (define (courier-state-dir) (: -> string?) (path-dirname (default-relay-dir))) (define (make-relay-state) (relay-state base-dir: (default-relay-dir)))src/courier/telegram.sglmodified
;; bug it was masking, making production ;; observation of that bug impossible. ;; A dry-run is a DEFINITE non-delivery, so ;; it also releases the dedup key: without ;; that, the very next identical send hits ;; the 'suppress path and reports "Message ;; sent." — reintroducing the same lie one ;; call later. Returning (not raising) is ;; it also releases the dedup key, for the ;; same reason a rejected send does. The ;; key was recorded BEFORE this branch; ;; leaving it would make the next ;; identical send take the 'suppress path ;; and claim the message "was accepted for ;; delivery" when nothing ever accepted ;; it. Measured on the pre-fix binary: ;; gag on, gag off, same text -> zero ;; deliveries while reporting success. ;; Returning (not raising) is ;; deliberate: an MCP error invites a client ;; retry, and retry-against-a-killed-courier ;; is the mechanism behind the send storm.test/test-telegram.sglmodified
;; 2.5 MB exactly = 2621440 bytes; integer truncation gives "2.5 MB" (assert-equal "2.5 MB" (format-size (quotient (* 5 1024 1024) 2)))))(run-tests);; ============================================================;; Send-result strings: a caller must be able to tell delivery;; from non-delivery by reading the return value (test "the two non-delivery strings are distinct from each other" (assert-true (not (string=? *dry-run-not-sent-message* *duplicate-suppressed-message*)))))(run-tests)