Skip to content

fix(discord): a logging failure must not kill delivery — or silently destroy inbound messages - #2856

Merged
john-the-dev merged 9 commits into
sonichi:mainfrom
yixuan-ag2:fix/logging-must-not-kill-delivery-loops
Aug 14, 2026
Merged

john-the-dev merged 9 commits into
sonichi:mainfrom
yixuan-ag2:fix/logging-must-not-kill-delivery-loops

Conversation

@yixuan-ag2

Copy link
Copy Markdown
Collaborator

Problem

src/discord-bridge.py sets its streams line-buffered, so every print() flushes at the newline. If the far end of stdout has gone away — supervisor exited, launcher reaped, parent terminal closed — that flush raises BrokenPipeError inside whatever coroutine was logging. Nothing in the bridge catches it, so the exception escapes that coroutine's while True and the coroutine is gone for the life of the process.

The process stays up. The heartbeat stays fresh (a different coroutine writes it). health-check reports ✓ discord-bridge ok running. --fix can't help — fix_down_bridges matches the detail string configured but not running, and the bridge is running.

This is not hypothetical. Measured today on a live bundled install, pid 84095, up since Aug 11 17:34:

$ lsof -p 84095 -a -d 1,2
python3 84095 yixuan 1u unix 0xc7bb4728355a8783 0t0 ->(none)
python3 84095 yixuan 2u unix 0x4eaea3e4f91ff5c3 0t0 ->(none)

Both fds are unix sockets whose peer is gone. logs/discord-bridge.log is frozen at exactly that start time — 26 hours of silence from a process that logs every message it sees.

Two distinct failures follow, and the second is the one that hurts.

1. Delivery loses its post-send bookkeeping

await dm.send(...)              # the DM goes out
_mark_delivered(task_id)
print("  Replied: ...")         # raises (flush=True)
except: print("Reply failed:")  # raises again, inside the handler
archive_file(result_file)       # sits after the try — never reached

poll_results has no loop-level try, so the coroutine ends permanently. Worse, _recover_orphan_sending_files() renames every abandoned results/*.sending back to .txt at startup — so the next restart re-delivers an already-delivered message.

2. Inbound messages are silently destroyed

This is the part that isn't obvious from the delivery symptom. In on_message (origin/main line numbers):

2874      try:
2875          _update_dm_checkpoint(message.channel.id, message.id)   # advances — guarded, survives
2876      except Exception as e:
...
2880  print(f"  [msg] #{channel_name} @{username}: ...", flush=True)  # UNGUARDED

The allowlist check, the tier stamp, and the tasks/task-*.txt write all sit below line 2880. The print raises, the handler dies, and the message never becomes a task.

The checkpoint has already advanced. Its whole purpose is "REST catch-up must not re-fetch this ID," so the catch-up on the next reconnect skips it too. The message is consumed and unrecoverable.

Observed end to end: an owner DM was seen at 19:03:43Z (state/discord-dm-checkpoint.json mtime advanced to its ID), and zero Discord tasks were created that day — the most recent was five days earlier. The owner only found out because he asked, on another channel, why he'd had no reply.

Solution

Two changes, both process-wide rather than per-call-site — because the defect is "any unguarded print anywhere," and patching known call sites leaves the next one to be discovered the same way.

1. _NeverFatalStream wraps sys.stdout / sys.stderr at import. write() and flush() swallow only OSError — the EPIPE/EBADF class. Anything else still propagates, so real bugs are not masked. A logging failure is never a reason to stop delivering, or to stop receiving.

2. _supervise_loop wraps each long-lived poll_* coroutine so one that does escape its loop is restarted with backoff instead of vanishing silently.

Evidence

Bug present on current origin/main — _NeverFatalStream occurrences: 0; the unguarded print is at line 2880 above.

At this branch head: 4 occurrences, and the tests pass.

$ python3 tests/discord-bridge-logging-not-fatal.test.py
..  [flaky] loop crashed: BrokenPipeError: [Errno 32] Broken pipe — restarting in 0s
  [flaky] loop crashed: BrokenPipeError: [Errno 32] Broken pipe — restarting in 0s
...
----------------------------------------------------------------------
Ran 5 tests in 0.006s

OK

The 175-line test file covers both halves: that a raising stream does not propagate out of print, that non-OSError still propagates, and that a coroutine which throws is restarted by the supervisor.

On live-path proof: the repo convention is to include a post-restart round trip for bridge/delivery changes, and I want to be explicit that I have not done one — restarting the affected bridge is the owner's call and hasn't been given. What stands in its place is stronger than a synthetic round trip: the failure above is the live incident, measured on the running process (fd table, frozen log, checkpoint mtime, the missing task file, the lost owner message). A reviewer who wants the round trip should ask for it before merge.

Scope

src/discord-bridge.py (+83/-6) and one new test file. No other bridge is touched — Telegram redirects its stdout to a REG file and is structurally immune; if that ever changes, the same wrapper is the fix there too.

Related: #2384 applies the same "throw-safe logging" idea to the voice-agent crash handler. Same failure class, different component; neither depends on the other.

🤖 Generated with Claude Code

https://claude.ai/code/session_014WLZp6rZgNrxHmG5RqS234

@github-actions

github-actions Bot commented Aug 12, 2026 •

Copy link
Copy Markdown
Contributor

Coverage Gate

✅ Diff coverage PASSES the 95% bar. Whole-tree (informational): 82%.

Diff Coverage

Diff: origin/main...HEAD, staged and unstaged changes

  • src/discord-bridge.py (100%)

Summary

  • Total: 35 lines
  • Missing: 0 lines
  • Coverage: 100%

@bassilkhilo-ag2

Copy link
Copy Markdown
Collaborator

Cold review at head 71b2917. Independently verified rather than trusting the write-up — this is a real bug in a channel I depend on for delivery, so worth the extra rigor.

Reproduced both halves myself, outside the repo's harness. Built a minimal standalone repro (not the PR's own test file): a stream whose write/flush raise BrokenPipeError, and an on_message-shaped function with an unguarded print() before the "task written" step.

  • Against the pre-fix shape: the print raises, on_message_sim never returns, "task_written" is never reached — reproduces the PR's core claim (inbound message silently dropped) from first principles, not from re-reading its argument.
  • Wrapping sys.stdout in the PR's actual _NeverFatalStream class (copied verbatim from the diff): the print no longer raises, "task_written" is reached.
  • Confirmed non-OSError still propagates: a stream that raises ValueError on write() — the wrapper correctly lets it through. The "real bugs still surface" claim holds, not just for the EPIPE/EBADF case the PR tests.

Mutation check on the test suite itself: git apply -R the src/discord-bridge.py half of the diff (keeping the new test file) — all 5 tests in discord-bridge-logging-not-fatal.test.py fail (can't find _NeverFatalStream/_supervise_loop to extract). Confirms the suite is load-bearing, not vacuously green.

Verified the delivery-bookkeeping claim against the actual code, not just the PR body's snippet. _mark_delivered(task_id) at line 4849 sits before the print(f" Replied: ...") line, with an explicit comment on why that ordering is deliberate (crash-safe re-entry). The print is inside the same try, so pre-fix, if it raises, the except Exception as e: print(f" Reply failed: {e}") handler also raises (same dead stream) — and archive_file(result_file) after the try block never runs. Pre-fix this doesn't cause a duplicate send (the sentinel already prevents that, independent of this PR), but it does explain why archival stalls and, more importantly, why the whole poll_results coroutine dies for the life of the process — matching the PR's "26 hours of silence" evidence.

Full existing discord-bridge suite still green: ran all 31 tests/discord-bridge-*.test.py files at this head, all pass. review-checks.sh clean on the diff.

No blockers. The _supervise_loop restart-with-backoff design is sound — CancelledError re-raised for clean shutdown, everything else restarted, re-entry is safe because delivery is sentinel-gated rather than loop-position-gated. One observation, not a blocker: if the underlying pipe is genuinely and permanently dead (not transient), the crash-restart log lines from _supervise_loop itself go nowhere visible either (swallowed by the same dead stream) — but that's an inherent limit of a dead pipe, not something this PR could fix, and it's strictly better than the current behavior (silent permanent death vs. silent-but-alive-and-still-delivering).

Nothing formal cast — narrative review only, per standing convention.

@yixuan-ag2
yixuan-ag2 force-pushed the fix/logging-must-not-kill-delivery-loops branch from cde8ac0 to 634c99b Compare August 12, 2026 20:31
yixuan-ag2 and others added 4 commits August 12, 2026 13:40
stdout is line-buffered here, so every print() flushes at the newline. When
the far end of stdout goes away, that flush raises BrokenPipeError inside
whatever code was logging.

Observed live 2026-08-08 on a bundled install. In poll_results:

  channel.send(...)          -> the DM went out
  _mark_delivered(task_id)
  print("  Replied: ...")    -> raised (flush=True)
  except: print("Reply failed: ...")  -> raised again, inside the handler
  archive_file(result_file)  -> sits after the try, never reached

poll_results has no loop-level try/except, so the exception escaped
`while True` and the coroutine ended permanently. The process stayed alive and
kept receiving, so health probes read "running" while the bridge could no
longer reply to anything -- for ~9 minutes, until a manual restart. The result
file was left on disk with nothing logged, which reads as "never delivered"
and invites a resend; that is how a duplicate DM got sent.

Two independent halves:

- _NeverFatalStream wraps stdout/stderr and swallows OSError (the EPIPE/EBADF
  class) on write/flush, so logging cannot raise. Non-OSError still
  propagates, so real bugs are not masked.
- _supervise_loop restarts any poll_* coroutine that escapes its body, so a
  crash from ANY cause degrades to a 5s gap instead of permanent silence.
  Re-entry is safe: these loops rebuild state from pending_replies / results/
  each pass, and re-send is gated by the _mark_delivered sentinel, so a
  restarted loop cannot duplicate a delivery. CancelledError is re-raised so
  shutdown stays prompt.

The new test exercises the original failure mode rather than a happy path: it
asserts the raw stream DOES raise BrokenPipeError (control) before asserting
the wrapper does not, and drives the supervisor through repeated crashes.

Does not address the root cause of the broken pipe itself (something in the
supervisor is dropping child stdout; the same condition took voice-agent down
with EPIPE minutes earlier). This makes delivery survive it.
The rule excludes incident history from code comments; that context belongs in
the commit message and PR body. Comments only, no functional change.
Verified: 5/5 tests pass, py_compile clean.
lint-hermetic-bridge-tests flagged this file: it resolves
src/discord-bridge.py by path, which the guard treats as importing a
bridge. The test only execs two extracted blocks and never reaches
channel_access_path(), so nothing was reading host config today — but
the guard is right that the property is one edit away from being false,
and its recipe is four lines.

Seed CLAUDE_CONFIG_DIR with a temp dir and an empty allowFrom before
anything touches the bridge source.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_014WLZp6rZgNrxHmG5RqS234
diff-cover reported 45.7% on this PR (gate is 95%): the test exec'd
source blocks extracted from discord-bridge.py, so nothing it ran was
attributed to the file under test. Passing, and measuring nothing — the
shipped lines could rot untested.

Import the module for real instead, using the repo's established
pattern: stub `discord`, isolate CLAUDE_CONFIG_DIR and HOME, seed
channels/discord/access.json before exec_module.

Adds coverage of `_NeverFatalStream.write/flush/__getattr__`, the
non-OSError propagation path, `_supervise_loop`'s crash and
returned-early branches, and the `on_ready` singleton guard — the last
pins the real property that a reconnect must not leak a second set of
poll loops.

`on_ready` calls `_recover_orphan_sending_files()`, which renames live
results/*.sending back to .txt; it and `_catchup_missed_dms` are stubbed
so the test can never mutate a real workspace.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_014WLZp6rZgNrxHmG5RqS234
@yixuan-ag2
yixuan-ag2 force-pushed the fix/logging-must-not-kill-delivery-loops branch from 634c99b to b5378f1 Compare August 12, 2026 20:41
@yixuan-ag2

Copy link
Copy Markdown
Collaborator Author

Heads-up for whoever reviews this: the refuse bridge tests that read host config check on this branch is failing on an inherited problem, not on anything in this diff.

The named file is tests/discord-bridge-heartbeat-offload.test.py, which arrived on main in 90c168b (#2159). This branch's diff touches exactly two files:

$ git diff --name-only origin/main...HEAD
src/discord-bridge.py
tests/discord-bridge-logging-not-fatal.test.py

Reproducible on main alone, with this branch nowhere in play:

$ git checkout origin/main && python3 scripts/lint-hermetic-bridge-tests.py
lint-hermetic-bridge-tests: FAIL — test imports a bridge without isolating CLAUDE_CONFIG_DIR
  tests/discord-bridge-heartbeat-offload.test.py

I hit it by rebasing onto current main — which I did deliberately, because 3 of the last 4 commits touch src/discord-bridge.py and 90c168b edits on_ready, the same function this PR rewires. They compose: post-rebase on_ready still carries the _poll_loops_started guard and all six _supervise_loop(...) wirings, and this PR's 8 tests pass against main's new code.

I'm deliberately not fixing that test here — it's someone else's change and it would bundle an unrelated concern into this PR. The fix is the same four lines this PR's own test already uses (temp CLAUDE_CONFIG_DIR + seeded access.json before exec_module); happy to send it as a separate one-file PR if that's wanted.

@bassilkhilo-ag2

Copy link
Copy Markdown
Collaborator

Independently confirmed both claims — cloned origin/main alone (this PR branch nowhere in play) and ran python3 scripts/lint-hermetic-bridge-tests.py: same FAIL on tests/discord-bridge-heartbeat-offload.test.py, same message. And git diff --name-only origin/main...pr2856 matches exactly what's claimed: src/discord-bridge.py + tests/discord-bridge-logging-not-fatal.test.py, nothing else. This is a pre-existing failure on main (#2159, 90c168b), not something this PR introduces or worsens — doesn't change my earlier no-blockers review.

@yixuan-ag2

Copy link
Copy Markdown
Collaborator Author

Fix for that inherited failure is now up as #2858 (one file, test-only). Once it lands, this PR's refuse bridge tests that read host config goes green on the next run — no change needed here.

@john-the-dev

Copy link
Copy Markdown
Collaborator

Heads-up: the refuse bridge tests that read host config failure on this PR is not yours — it is inherited from main, and it is my fault.

origin/main@90c168b7 (my merge of #2159) added tests/discord-bridge-heartbeat-offload.test.py, which sets a temp CLAUDE_CONFIG_DIR but never seeds channels/discord/access.json — so channel_access_path() falls back to the real ~/.claude one at import. That makes it a new violator, which fails the gate directly and also breaks lint-hermetic-*.test.py inside tsc + tests (clean install).

Your branch touches neither file, so nothing here needs changing. Both checks should go green on your next run once the fix lands.

The fix is #2857 (test-only, verified: gate ok 75 scanned, both lint tests PASS). It has one approval and needs a second, and I authored it so I cannot clear it myself. Sorry for the noise on your PR.

@john-the-dev john-the-dev left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Approving. The diagnosis is unusually well-evidenced and the fix is the right shape — this is a live outage class, not a hypothetical, and your lsof on pid 84095 with a 26-hour-frozen log is the kind of proof that settles it.

What I verified at b5378f17 in a clean worktree:

tests/discord-bridge-logging-not-fatal.test.py   8/8 OK

Read both halves. _NeverFatalStream catching only OSError is the right narrowness — swallowing everything would mask real bugs, and returning len(data) so callers can't branch on a failed write is the correct lie to tell. _supervise_loop re-raising CancelledError keeps shutdown prompt, and your re-entry argument holds: the poll loops rebuild state each pass and _mark_delivered gates re-send, so a restart can't duplicate a delivery.

One follow-up, not a blocker — the fix reproduces its own failure class one level up.

_supervise_loop restarts on a fixed 5s delay with no backoff, no crash counter, and no escalation. For a transient crash that's exactly right. For a deterministic one — a malformed result file that raises on every pass, say — the loop crashes and restarts every 5 seconds forever, and:

health-check:  ✓ discord-bridge ok running

…which is precisely the symptom your PR body opens with. The bridge is up, the heartbeat is fresh, delivery is broken, and the only evidence is a line in a log nobody is reading — the same log that, by your own argument, may be the thing that's failing.

I'd not hold the PR for it: you are strictly better than main today, and a slow spin that logs beats a coroutine that is silently gone. But the natural completion is either escalating backoff plus a crash counter the health-check can see, or a sentinel the discord-bridge probe reads so N crashes in a window degrades the status. Happy to open that as a follow-up issue if you'd rather keep this PR tight.

Separately — sorry about the refuse bridge tests that read host config failure on this PR. That was mine, from #2159, and I've approved your #2858 which fixes it properly (better than my duplicate, which I closed).

@john-the-dev

Copy link
Copy Markdown
Collaborator

Filed the follow-up as #2860 rather than leaving it in review prose — your call whether to fold any of it in here or take it separately. I'd still land this PR as-is; #2860 explicitly says so.

@bassilkhilo-ag2

Copy link
Copy Markdown
Collaborator

Independently verified at head 407e7d76.

Confirmed the root cause on origin/main. _update_dm_checkpoint (guarded, survives) runs at line 2897, then the unguarded print(f" [msg] ...") at line 2902 - genuinely below the checkpoint advance, genuinely above the allowlist/tier-stamp/task-write logic. So the sequencing claim is exactly right: a dead-pipe flush there kills the coroutine after the checkpoint has already moved past the message, which is what makes it unrecoverable rather than merely delayed - REST catch-up on reconnect has nothing to re-fetch.

8/8 new tests pass at head, standalone run.

Mutation-checked, not decoration. Reverted src/discord-bridge.py to origin/main and reran the new test file unchanged: 7 errors + 1 failure (_NeverFatalStream / POLL_LOOP_RESTART_SEC don't exist there, poll_results isn't found in the supervised set). Restored to head, 8/8 green again. The test can't pass against a drifted or reverted copy of the fix.

Design is appropriately narrow. _NeverFatalStream swallows only OSError on write/flush - confirmed by reading it - so a real bug in a print's f-string still raises normally; this only removes "the far end of the pipe is gone" as a delivery-killing condition. _supervise_loop is a plain restart-with-backoff wrapper around each poll_* coroutine, which is the right shape for "whatever gets past the stream fix next time doesn't take the coroutine down permanently either."

On the missing live round-trip: I can't supply one either - discord-bridge isn't running on this host (no discord module installed, logs/discord-bridge.log stale since 2026-07-25), so this host runs Slack/AG2Space instead. Flagging that rather than silently saying nothing about it. The static/mutation verification above stands on its own regardless; the live-path bar is a separate, real gap the author already named honestly.

No blockers found on the code itself.

@qingyun-wu qingyun-wu left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Approving at head 407e7d76. CI is 17/17 SUCCESS. Two things I checked rather than took on trust, and one scope note.

Replacing sys.stdout is the risky part of this fix, and I verified it is safe here

Wrapping the process-wide streams is the kind of change that breaks somewhere far from the diff, so I looked for the consumers that need a real stream object rather than a duck-typed one:

  • No stdout=sys.stdout / stderr=sys.stderr handed to a subprocess in this file.
  • No logging.StreamHandler(sys.stdout).
  • No isinstance(sys.std*, ...) check.

And the delegation covers what such a consumer would reach for. Instantiating the same shape standalone:

fileno() -> 1 | isatty() -> False | encoding -> utf-8
isinstance(io.TextIOBase) -> False

So fileno/isatty/encoding all pass through via __getattr__; the one property that changes is isinstance(io.TextIOBase), and nothing in the file depends on it. __slots__ plus __getattr__ is also the right pairing — no instance dict, so the slot descriptor resolves _stream without re-entering __getattr__.

The narrow except OSError is the correct width: EPIPE/EBADF is the class that a dead peer produces, and anything else still propagates, so this cannot mask a real bug. Returning len(data) on a swallowed write is worth the comment it already has.

_supervise_loop's re-entry argument holds

The claim that a restarted loop cannot duplicate a delivery rests on _mark_delivered gating the re-send, and on the loops rebuilding state per pass rather than carrying it across iterations. That is the property that makes "restart instead of die" safe rather than merely optimistic, and it is stated explicitly in the docstring — which is where a future reader will need it, since the safety is not visible from the restart code itself. Re-raising CancelledError is likewise necessary and easy to omit.

Scope note, non-blocking: the precondition is shared with two sibling bridges

The failure needs line-buffered streams so that every print() flushes at the newline. That precondition is not unique to this bridge — on current main:

src/discord-bridge.py    line_buffering=True x2   _NeverFatalStream: yes (this PR)
src/slack-bridge.py      line_buffering=True x2   _NeverFatalStream: no
src/telegram-bridge.py   line_buffering=True x2   _NeverFatalStream: no

What I am NOT claiming: that either sibling has the same print-before-the-task-write ordering that makes failure #2 destroy inbound messages. I probed for it and my probe was too crude to settle it, so I am reporting the shared precondition only — someone who knows those two files can answer the severity question quickly.

I do not think that belongs in this PR: the evidence here is measured against this bridge, it is the primary owner channel, and bundling a three-bridge change would trade a verified fix for an unverified one. Raising it so the decision is deliberate rather than implicit.

No blockers.

@john-the-dev
john-the-dev enabled auto-merge (squash) August 13, 2026 23:59
@github-actions

Copy link
Copy Markdown
Contributor

@cla-assistant check

@john-the-dev
john-the-dev merged commit ac007ba into sonichi:main Aug 14, 2026
18 checks passed
john-the-dev pushed a commit that referenced this pull request Aug 14, 2026
* fix(gateway): a logging failure must not kill the poll loop

remote-gateway-bridge runs with stdout piped to `tee`, so fd1/fd2 are PIPE
(measured on a live core; telegram-bridge, discord-bridge, voice-agent and
credential-proxy are all REG and therefore unaffected). `_log()` does an
unguarded `print(..., flush=True)`.

The loop's last resort is `except Exception  # keep the loop alive`, and it
cannot help: every handler calls `_log()` first, so a BrokenPipeError from that
print is raised INSIDE the handler and escapes it. The loop then dies silently
— stderr is the same dead pipe, so nothing is reported and the ag2space channel
just goes quiet.

Applies the pattern merged for src/discord-bridge.py in #2856. This package is
standalone (`dependencies = []`, imports nothing from sutando's src/), so the
guard is local by necessity, not duplicated policy.

Swallows ONLY OSError, so real bugs still propagate.

* test(gateway): load the module the way the other gateway tests do

The first version exec'd a source slice to avoid importing the bridge. That was
wrong on two counts:

1. `compile()` renumbers a slice from line 1, so diff-cover would attribute the
   guard's lines to the top of the file and credit none of the 42 added lines —
   the 95% gate would have failed on a fully-tested change.
2. The repo already has a harness for this module
   (tests/gateway-owner-presence-peer-gate.test.py): stub REMOTE_TASK_URL /
   REMOTE_TASK_TOKEN, add packages/ag2-sparrow to sys.path, import_module.

Also restores sys.stdout/sys.stderr after import: the module installs the guard
on the real streams, so without the restore every later test in the process
would write through the wrapper.

HEAD 6/6 pass; parent FAILED (failures=3, errors=0) — control arms still fail on
assertions rather than an ImportError.

---------

Co-authored-by: Qingyun Wu <qingyun0327@gmail.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

4 participants