feat(opencode-http): readable run logs + structured event trace#279
Conversation
The opencode-http adapter logged only server INFO stdout; a finished run had no agent transcript. Add an inline readable transcript to <task>.log (role-coloured), a structured JSONL trace to <task>.events.jsonl, and redirect server stdout to its own <task>.server.out. Purely additive; writes off the existing SSE dispatch, no control-loop change.
|
No actionable comments were generated in the recent review. 🎉 ℹ️ Recent review info⚙️ Run configurationConfiguration used: Organization UI Review profile: CHILL Plan: Pro Plus Run ID: 📒 Files selected for processing (5)
🚧 Files skipped from review as they are similar to previous changes (4)
WalkthroughThe opencode HTTP adapter now produces curated transcript logs, separate server stdout logs, and optional structured SSE traces. SSE rendering handles message roles, tool activity, session-less events, malformed payloads, and trace sequencing, with expanded tests and documentation. ChangesOpencode HTTP logging
Estimated code review effort: 4 (Complex) | ~45 minutes Sequence Diagram(s)sequenceDiagram
participant OpencodeSSE
participant OpencodeHttpAdapter
participant TaskTranscript
participant SSETrace
participant ControlQueue
OpencodeSSE->>OpencodeHttpAdapter: deliver /event frame
OpencodeHttpAdapter->>TaskTranscript: render curated transcript line
OpencodeHttpAdapter->>SSETrace: append structured SSE record
OpencodeHttpAdapter->>ControlQueue: queue session.idle or session.error
Possibly related PRs
Suggested reviewers: Poem
🚥 Pre-merge checks | ✅ 4 | ❌ 1❌ Failed checks (1 warning)
✅ Passed checks (4 passed)
✨ Finishing Touches🧪 Generate unit tests (beta)
Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out. Comment |
|
Thanks @jackmcintyre — this is a real gap, and the shape you landed on is the one we want: curate the transcript off the SSE dispatch, keep the server's own stdout out of it, and leave the control loop alone. We're adopting the PR. Since maintainer edits are on, I'll push the revisions directly to your branch rather than asking you to chase them — authorship stays yours. Planned revisions:
We'll take the companion issue too (CONTRIBUTING wants one for a feature) — no need for you to file it; I'll link it here. One more thing coming to this thread: I'm live-probing 1.18.2's |
Live probe evidence — opencode 1.18.2
|
| reply size | part.updated fires |
fires w/ non-empty text | part.delta frames |
|---|---|---|---|
4 chars (done) |
2 | 1 | 1 |
| 711 chars | 2 | 1 | 8 |
| 5689 chars (~700 words) | 2 | 1 | 50 |
At 5689 chars the 50 deltas concatenate byte-exactly to the single part.updated text (asserted equal). So both halves of your reasoning check out: the inline log gets one clean line per statement, and the deltas are pure redundancy in the trace — dropping them loses no information.
Also confirmed: no tool.call / tool.response anywhere — not in the 89-variant union, not live.
⚠️ Three corrections the probe turned up
These are on us for the adoption revisions, not asks for you — but they change the pin list I posted above, so recording the evidence here.
1. command.executed never fires for agent tool use — 0 frames across bash, write, read, and edit calls. Tool execution surfaces as message.part.updated where part.type == "tool":
{"type":"message.part.updated","properties":{"sessionID":"ses_…","part":{
"id":"prt_…","type":"tool","tool":"bash","messageID":"msg_…",
"state":{"status":"completed","input":{"command":"echo hi"},"output":"hi\n"}}}}with state.status stepping pending → running → completed. command.executed does exist in the union (it has name/arguments/messageID), but it's the slash-command surface, not the tool surface.
This one matters beyond a dead branch: _inline_line reads part.get("text"), which is absent on tool parts, so it returns None — meaning the transcript currently renders no tool activity at all, only assistant prose. Rendering off part.type == "tool" (on the completed transition, so each tool logs once) is what actually delivers the "see what the agent did" half of the feature.
2. permission.updated does not exist in 1.18.2 — it's permission.asked, and the field names differ from what the render assumes:
{"type":"permission.asked","properties":{"id":"per_…","sessionID":"ses_…",
"permission":"bash","patterns":["echo permcheck"],
"metadata":{"command":"echo permcheck"},"always":["echo *"],
"tool":{"messageID":"msg_…","callID":"toolu_…"}}}
{"type":"permission.replied","properties":{"sessionID":"ses_…",
"requestID":"per_…","reply":"once"}}So it's permission / patterns (not type / pattern), and permission.replied carries reply, not response — the current line would always print ?. (There are also permission.v2.asked / permission.v2.replied variants in the union we should decide about.)
3. file.edited carries no sessionID, so it's dropped before your render ever sees it. Live payload is exactly {"file": "/abs/path"} — nothing else. Since _dispatch_sse does if props.get("sessionID") != sess.session_id: return above the render call, the file: branch is unreachable. Same for file.watcher.updated. Fix is an explicit allowlist for the session-less types — safe here specifically because bmad-loop runs one server per session, so a server-global frame is still unambiguously this session's.
For reference, every type seen live, with whether it carries sessionID:
sessionID: message.part.updated(67) message.part.delta(64) message.updated(50)
session.status(30) session.updated(22) session.diff(15) session.idle(5)
session.created(2) permission.asked(1) permission.replied(1)
NO sessionID: plugin.added(90) server.heartbeat(27) catalog.updated(4)
server.connected(2) reference.updated(2) integration.updated(2)
file.edited(2) file.watcher.updated(2)
Net
The design is sound and the expensive assumption — complete-once part.updated — is confirmed, so no rework of your rendering approach. The corrections are frame-name and field-name fixes plus the tool-part render, which we'll fold into the revisions on your branch. Thanks again for finding this gap and building it in the right place.
|
Approved the fork CI run (first-time contributor, so it was parked on 8/9 green — full test matrix passes on Linux py3.11–3.14 and both Windows legs, plus trunk lint and version-sync. One failure,
|
Redirecting the server's stdout to <task>.server.out left the give-up
raise citing `log: {log_path}` — the transcript sink, which now holds
only SSE-rendered lines and is EMPTY when the spawn never got far enough
to stream any. So every failed spawn sent the operator to a blank file
while the diagnostics sat unread in the file next to it.
The give-up test asserted only that <task>.log exists, which it does
either way; it now pins the path named in the message and reads the
named file back, asserting all three attempts' stdout landed there.
_render_inline and _emit_event run inside _dispatch_sse, upstream of the idle/error queue puts, and both walk nested .get chains into payloads the server controls (props["part"], ["info"], ["permission"]). A frame that ships a string where a dict is expected raises AttributeError there. Unguarded that unwinds into the reader's connection-level `except` in _sse_loop, which reads it as a dead connection: it tears the stream down, puts a `gap`, sleeps and reconnects, dropping whatever the server had already buffered. A logging bug would degrade completion signaling. Wrap both calls in the reader's own never-die doctrine, with _emit_event ordered first so a render bug still leaves the offending frame recorded in the trace you would read to diagnose it. Also narrow the frame type before the typed helpers: a non-string `type` can match no branch below, and it cleared the two pyright errors CI flagged on the previous commit. Ablation-checked: with the try/except removed, the four malformed-frame cases and the trace-record test fail with AttributeError. The unserializable-payload test is not guard-sensitive (it exercises _emit_event's own json.dumps catch) and the block comment says so.
Three scope decisions on the structured trace: - Rename <task>.events.jsonl to <task>.sse.jsonl. "events" is overloaded in this tree (the copilot token parser reads a different events.jsonl, and tasks/ already carries session-lifecycle.jsonl); the file is one specific thing — the frames off /event — so name it that. - Gate it behind an SSE_TRACE module default plus an `sse_trace` instance attribute, alongside the timing knobs. Deliberately tier-1 and not a policy field in core.toml: it changes nothing about how a run behaves, only whether a debugging artifact is written, so it does not belong in the run contract every settings file has to carry. Off means the sink is never opened, not opened-and-empty. - Exclude message.part.delta records. The live probe showed 50 deltas concatenating byte-exactly to the single message.part.updated text already in the file, so each one re-stores text the trace holds — and they dominate the frame count on any real turn while logs/ is never trimmed by retention, making the cost permanent. Deltas also no longer burn a seq, so the numbering matches the lines in the file.
The transcript had no line for session.error: a failing turn just stopped mid-sentence while the queue put below ended the session. Render one, in the same role-less hue as the other markers (the colour family is "not a speaker", not severity), summarizing whatever the payload carries — the error shape is not pinned on this surface. _emit_event also switches to the existing _now_ms() helper rather than open-coding the same epoch-ms conversion, and the sink-open site now records that seq is per session while the file is per task across retries, so a seq dropping back to 1 mid-file reads as a new session and not a truncation. Extend the module docstring's API pin list — the stated authority, "this list wins over memory" — with every /event type the renderer reads, cited to the 1.18.2 probe posted on PR bmad-code-org#279 (388 frames, cross-checked against the 89-variant Event union at GET /doc). It records the semantics the render path depends on (part.updated is complete-once, NOT cumulative; message.updated re-emits out of order) and, just as importantly, the three types the renderer names but never actually sees on 1.18.2: command.executed does not fire for agent tool use, file.edited carries no sessionID so the filter drops it, and permission.updated does not exist (it is permission.asked, and replied carries `reply`, not `response`). Those are live-fire corrections, not cleanups, and land separately.
The 1.18.2 probe found `command.executed` never fires for agent tool use —
0 frames across live bash/write/read/edit. Tool execution arrives on
`message.part.updated` as a `tool`-typed part (`part.tool`, `state.status`
stepping pending → running → terminal). `_inline_line` reads `part.text`,
which tool parts do not carry, so it returned None for every one of them:
the transcript rendered the assistant's prose and none of its actions.
Add the tool branch ABOVE the empty-text bail-out — below it the branch is
unreachable, which is the whole bug — and render on a TERMINAL status so one
tool call is one line. `ToolState` is a 4-variant union (pending / running /
completed / error), so the terminal pair is exhaustive: `error` is in it
because the probe never saw a tool fail and gating on `completed` alone would
drop failed calls silently, which is the one thing a reader goes to the
transcript for. `state.input` is summarized inline (reusing `_sum_args`);
`state.output` is left to the SSE trace, since on this surface it is a whole
command's stdout or a whole file.
`command.executed` KEEPS its branch: it is the slash-command surface, which
is real, and its payload is pinned. The comment now says so explicitly so the
next reader does not "fix" tool rendering back into it.
Once-per-call is a placement claim, so both ablation directions were run:
(a) delete the tool branch → all five new tests fail, the count one at 0 != 1;
(b) INVERSE: drop the terminal-status gate so it renders on every transition
→ the once-only test fails on its first intermediate assert (pending
rendered a line), proving the pending/running frames really do reach the
branch and the count is not passing vacuously; run to completion it is
3 != 1, with running and completed rendering identical lines.
`permission.updated` does not exist in 1.18.2 — the branch could never fire.
The live ask frame is `permission.asked`, and its payload is not the shape the
render assumed: `permission` is a STRING and `patterns` a list, not a nested
object with `type` / `pattern`. `permission.replied` carries `reply`, not
`response`, so that line printed `?` on every reply it ever rendered.
Both are now keyed to the live names and fields, with tests pinned to the
payloads captured in the probe. `metadata` (the concrete command) and `always`
stay out of the line and live in the SSE trace; `patterns` is what the
permission actually matched on. The ask and reply lines are labelled
distinctly (`perm ask:` / `perm reply:`) so a reader can pair them.
`permission.v2.asked` / `permission.v2.replied`: NOT consumed, deliberately.
Neither was seen in 388 live frames, and the v2 ask is a different payload
(`action` / `resources` / `save` / `metadata` / `source`), so a branch for it
would be written from the OpenAPI schema alone — which is exactly the kind of
guess that made all three of these corrections necessary. The v2 reply IS
shape-identical to the v1 one, but consuming a reply without its ask logs a
decision with no request, so the two go in together or not at all. The
docstring records the v2 payload so adding them later is a small change.
Also swaps the malformed-frame fixture that used the dead `permission.updated`
name: post-correction the permission branches read straight off `props` (always
a dict), so that shape can no longer reach a `.get` on a non-dict. A tool part
with a non-dict `state` is the render path's live landmine now, so it takes the
slot. Re-ran the S2 guard ablation with the new set — unchanged verdict: the
same five render-path tests fail with AttributeError (the new fixture among
them, at `state.get("status")`) and test_unserializable_properties_ still
passes ablated, since it exercises _emit_event's own catch.
`file.edited` carries no `sessionID` — live payload is exactly
`{"file": "/abs/path"}`, and 1.18.2 pins it `additionalProperties: false` over
that one key. `_dispatch_sse` returns early on
`props.get("sessionID") != sess.session_id` ABOVE both sinks, so the `file:`
branch was unreachable no matter what it rendered.
Add an explicit allowlist of session-less types exempt from that filter. This
is sound ONLY because bmad-loop spawns one `opencode serve` per session: the
server is single-tenant, so a server-global frame is unambiguously this
session's. The comment says so, and says what to do if that ever changes.
Two decisions, both recorded at the code:
- The allowlisted frames enter the SSE TRACE as well as the transcript, since
`_emit_event` sits under the same filter. Intended: the trace's contract is
one record per frame the adapter acted on, and it is the file you read to
explain a transcript line — a rendered line with no matching record would
make the two sinks disagree. It is affordable precisely because the
allowlist admits one low-rate type.
- NOT a blanket session-less exemption, and `file.watcher.updated`
specifically stays out. The session-less traffic is mostly noise that says
nothing about the run (`plugin.added` alone was 90 of 388 live frames, plus
heartbeats, `catalog.updated`, `reference.updated`, `integration.updated`).
The watcher fires for any change under the project — our own git
operations, a build, an editor save — so it is not evidence the agent did
anything, and for the changes the agent DID make it just double-reports
`file.edited`.
The membership test sits outside the try/except that guards the two sinks, so
it narrows with isinstance first: `in` on a frozenset raises TypeError for an
unhashable value and `type` is server-controlled. Ablating that narrowing
fails the new unhashable-type test with exactly that TypeError.
ABLATION: reverting the filter to the plain sessionID comparison fails the two
tests that assert a session-less frame REACHES a sink. The negative tests
(non-allowlisted `plugin.added`, control-queue isolation) keep passing under
it — they assert absence, which holds however the frame was dropped — so the
comment marks them as scope documentation, not reachability evidence.
Probe corrections landed on the branch (3 commits)Following up on the live-probe evidence above — the three frame-name findings are now fixed on your branch, on top of your commit and the four adoption commits. Nothing of yours was rewritten; these are follow-ons.
One thing the live probe couldn't see, which the OpenAPI does:
We decided not to consume
Testing+9 tests (2879 passing), trunk clean, pyright 0 errors. "One line per tool" is a placement claim, and it's also what a renderer that emits nothing satisfies — so both ablation directions were run and are recorded in the test file:
Docs and CHANGELOG are next — they describe what the transcript renders, which is exactly what changed here, so they were deliberately held until after this. The PR comes out of draft with that. |
The sink split shipped in this series was documented nowhere outside the adapter module. Cover it at the three altitudes the docs already use: - `adapter-authoring-guide.md` — the opencode worked example gains the sink split as a design lesson worth stealing: a transport with no pane still owes the operator a transcript, and you get one by curating it off the event stream the adapter already consumes for control, rather than by inventing a second channel. Names what each sink is for and the catch that comes with curating — what you render is only as good as the frame names you pinned. - `FEATURES.md` / `setup-guide.md` — one sentence each, at the density those files already run: which three files appear and what lands in each, so an operator watching a run knows where to look. None of them restate the `/event` pin list; that stays in the module docstring as its single copy. CHANGELOG gets one `### Added` entry under `[Unreleased]` crediting @jackmcintyre, referencing bmad-code-org#306.
Full-branch review before un-drafting. The code's altitude is right for the problem — three sinks, one renderer, one allowlist, no new config surface, no new infrastructure — but the COMMENTS outgrew it: 34% of the added lines are pure comment against 14% in the file they were added to, and the excess is duplication, not explanation. The live-probed `/event` facts were restated three and four times over — the `file.edited` payload in the module docstring, at `_SESSIONLESS_TYPES`, and again at the `_dispatch_sse` filter; the permission field names and the tool-part ordering rule in the module docstring and again in `_render_inline`'s. `_render_inline` was the worst of it: it told the reader to go read the module docstring and then recapped its contents anyway. That duplication is a liability rather than redundancy, because these facts are the ones that go stale — this branch already had to correct three guessed frame names, and the next version bump will re-verify them against exactly one place or silently leave a stale copy behind. Cut the restatements at both sites; keep the pointers, and at `_render_inline` keep the REASON the single copy matters. Local comments that explain why THIS code is shaped the way it is — the tool branch sitting above the empty-text bail-out, the isinstance narrowing ahead of the frozenset test, the ablation notes — are consequence rather than contract and stay where they are. Comments only; no behavior change. 79 adapter tests pass unchanged.
…e-logs # Conflicts: # CHANGELOG.md
![coderabbitai[bot]](https://avatars.githubusercontent.com/in/347564?s=60&v=4){kind=small}
There was a problem hiding this comment.
Actionable comments posted: 1
🤖 Prompt for all review comments with AI agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
Inline comments:
In `@src/bmad_loop/adapters/opencode_http.py`:
- Around line 493-507: Guard the sink-opening sequence in `_spawn_server` so any
failure opening `event_fh` or `server_fh` closes every handle already opened,
including `log_fh`, before propagating the original exception. Update
`_close_spawn_sinks` to close each handle independently and ignore `OSError`,
matching `_teardown` so close failures cannot mask the primary error.
🪄 Autofix (Beta)
Fix all unresolved CodeRabbit comments on this PR:
- Push a commit to this branch (recommended)
- Create a new PR with the fixes
ℹ️ Review info
⚙️ Run configuration
Configuration used: Organization UI
Review profile: CHILL
Plan: Pro Plus
Run ID: 168ee193-6dd0-4650-8505-012d8b63e87d
📒 Files selected for processing (6)
CHANGELOG.mddocs/FEATURES.mddocs/adapter-authoring-guide.mddocs/setup-guide.mdsrc/bmad_loop/adapters/opencode_http.pytests/test_opencode_http.py
CodeRabbit review on bmad-code-org#279, both halves confirmed against the code. All three per-task sinks open ABOVE the retry loop's try/except. An `open()` that fails partway — ENOSPC, EMFILE, a permission race — propagates straight out of `_spawn_server` without ever reaching that handler, so the handles already opened are never closed and stay open for as long as the propagating traceback keeps the frame alive. This series introduced the exposure: with one sink there was nothing open at that point to leak, with three there is. Guard the two later opens and route them through the same `_close_spawn_sinks`. `_close_spawn_sinks` also closed each handle unguarded, unlike `_teardown`. Both of its callers are already reporting a failure — one is mid-`raise`, the other is about to raise `OpencodeServerError` — so an OSError from a flush-on-close would replace the failure actually worth reporting, and would strand the sinks after it. Close each one independently, swallowing OSError, and skip None: `event_fh` is None when the sse_trace knob is off, and either of the last two is None when the failure WAS the open that would have created it. CodeRabbit's suggested diff deleted the append-semantics and event_seq comments along the way; the fix keeps them. ABLATIONS, both run: - Drop the try/except around the two later opens and `test_spawn_open_failure_closes_the_sinks_already_open` fails on the leaked `.log` and `.sse.jsonl` handles. It asserts a list of leaks is empty, so it had to be checked — the assertion holds for every reason the handles could be absent, including never having been opened, which is why it also asserts both sinks ARE in the opened set first. - Restore the unguarded closes and `test_close_spawn_sinks_survives_a_failing_close` fails with the OSError escaping. The fixture makes the FIRST sink the one that fails to close, so the test pins both properties at once: the error does not propagate, and the two sinks after it still get closed.
|
@coderabbitai review |
✅ Action performedReview finished.
|
|
Thanks for this, @jackmcintyre — and sorry it took a while to come back to you. This was a real gap, and you found it in the right place. opencode-http was the only adapter whose finished runs were opaque: the claude/tmux adapters get a transcript for free by replaying the pane, and nobody had noticed that the HTTP adapter's We took you up on the "check the shape is welcome before going further" and pushed the rest onto this branch directly ( What we added on top, roughly in order:
CI is 9/9 green and CodeRabbit's one finding (a file-handle leak in the spawn path — genuinely ours, introduced when we went from one sink to three) is fixed and confirmed. Leaving the merge to the maintainer. If you want to keep going on this adapter, the |
|
@CodeRabbit review |
✅ Action performedReview finished.
|
|
Thanks @pbean, happy to have been able to contribute |
2 participants
Closes #306
What
Adds a readable agent transcript and a structured event trace to the opencode-http adapter's run logs. Purely additive; no control-loop change.
Why
The opencode-http adapter's run logs only carry the server's INFO stdout (timestamps, "loading instance", and so on). The claude and tmux adapters get a full replay from the tmux pane, but the HTTP adapter has nothing to scrape, so a finished run is opaque - you can't see what the agent did or said. That makes finished runs hard to debug.
How
<task>.lognow carries a readable, role-coloured inline transcript; a new<task>.events.jsonlholds the complete structured SSE trace for replay; and the server stdout is redirected to its own<task>.server.outso it stops mixing into the transcript.adapters/opencode_http.py. No change to the deterministic control loop.Testing
Unit tests cover the render and emit paths and the role lookup (messageID-keyed, survives out-of-order events). Full suite green (2840 passed). Verified end to end against a real opencode server.
Opening as a draft to check the shape is welcome before going further. Happy to file an issue to go with it.
Summary by CodeRabbit
opencode-http, split into:logs/<task-id>.log,<task-id>.server.out, and optional<task-id>.sse.jsonl(structured SSE trace).