Skip to content

fix(acp): re-root custom log targets under buzz_acp - #3309

Open
troyhoffman-oss wants to merge 1 commit into
block:mainfrom
troyhoffman-oss:fix/acp-log-target-reroot-up
Open

fix(acp): re-root custom log targets under buzz_acp#3309
troyhoffman-oss wants to merge 1 commit into
block:mainfrom
troyhoffman-oss:fix/acp-log-target-reroot-up

Conversation

@troyhoffman-oss

Copy link
Copy Markdown

The default filter is buzz_acp=info — set in run() and matched by the desktop's child-process filter in managed_agents/runtime.rs — but 84 log sites across the message-handling path declare their own target: pool::session, pool::prompt, acp::wire, canvas::fetch, and a dozen more.

EnvFilter matches a target by prefix from its root, and none of those roots is buzz_acp, so every one of them is filtered out. Turn dispatch, wire traffic, and session lifecycle never appear in a production journal, and RUST_LOG=buzz_acp=debug — the line TESTING.md hands operators when the default log is too quiet — turns none of them on.

This is the mechanism behind an observation in #2795: that fix's only trace was "a pool::model WARN that never reaches the per-agent log files."

Each target is now prefixed with buzz_acp::, so the crate filter reaches them while the existing suffixes keep working as narrower selectors (RUST_LOG=buzz_acp::acp::wire=trace). Names are otherwise unchanged, and nothing outside these call sites referenced them.

Pure rename — 84 insertions, 84 deletions, every changed line a target: string. No behavior change beyond the logs becoming reachable.

Testing

cargo test -p buzz-acp --lib: 616 passed; 0 failed. cargo fmt --check and cargo clippy -p buzz-acp --all-targets clean.

The default filter is `buzz_acp=info` — set in `run()` and matched by the
desktop's child-process filter — but 84 log sites across the message-handling
path declare their own target: `pool::session`, `pool::prompt`, `acp::wire`,
`canvas::fetch`, and a dozen more. `EnvFilter` matches a target by prefix from
its root, and none of those roots is `buzz_acp`, so every one of them was
filtered out. Turn dispatch, wire traffic, and session lifecycle have never
appeared in a production journal, and `RUST_LOG=buzz_acp=debug` — the line
`TESTING.md` hands operators when the default log is too quiet — turned none of
them on.

Each target is now prefixed with `buzz_acp::`, so the crate filter reaches
them while the existing suffixes keep working as narrower selectors
(`RUST_LOG=buzz_acp::acp::wire=trace`). Names are otherwise unchanged, and
nothing outside these call sites referenced them.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Signed-off-by: Troy Hoffman <troy.hoffman@icloud.com>
@artemtrofymenko

Copy link
Copy Markdown

This is the better fix for the defect, and I am standing down the duplicate I opened without finding this first — #6035 approaches the same problem from the filter side. Two things before it lands, one supporting and one blocking.

Independent confirmation. Same conclusion from a Windows fleet: every tracing statement in crates/buzz-acp/src that declares its own target sits under one of acp::*, pool::*, canvas::*, engram::*, observer — none under the crate path — so the shipped buzz_acp=info matches none of them. A separate report on #6035 measured the consequence over 18 days and 17 log files: 51,472 lines carrying a target, 50,625 from buzz_acp*, zero from the twenty custom roots, and 847 from the child process proving the files can hold a foreign target. Re-rooting also fixes something a filter-side patch cannot fix cleanly: RUST_LOG=buzz_acp=debug, the line TESTING.md hands operators, starts working — and a value saved per-agent in the desktop UI stops silently re-silencing everything, because it is now the same root.

The blocker: this turns verbatim conversation content on by default. The rename carries acp::stream to buzz_acp::acp::stream while leaving it at info:

"agent_message_chunk" => {
    if let Some(text) = update["content"]["text"].as_str() {
        tracing::info!(target: "buzz_acp::acp::stream", "{text}");

That site logs the model's reply verbatim, and the desktop appends the child's output to a persistent plaintext file whose rotation is only checked when the file is opened. Today the target is dark, so the statement is harmless; after this PR the default filter matches it and every assistant message on every machine running an agent is written to disk. pool::prompt carries command arguments on the same terms.

This was raised against my PR by @ravarora2 and it is what reshaped it: the families are worth restoring at warn, where they carry timeouts, ids and failures, but info on these particular targets is a different decision — it is a content-retention change wearing a logging change's clothes. Cheapest fix that keeps this PR's shape: drop the content-bearing sites to debug in the same commit, or leave stream/thought/wire payloads outside the default root. Either keeps the 90-odd diagnostic sites you are rescuing while leaving conversation text off by default.

Also: this is CONFLICTING at head 6fdeba54 and has been open since 28 July with no reviews. Worth a rebase so it is landable the day someone looks at it.

If a maintainer confirms this is the one to take, I will close #6035 rather than keep two open PRs against one defect.

@cristiansotogarciaxatech

Copy link
Copy Markdown

I am the source of the measurement @artemtrofymenko quoted above. Here it is first hand and refreshed this morning, plus two things I checked in source today that change what this PR needs before it lands.

Every source reference below is at c6ca9d94 (main, 3 September).

The field number

One Windows box running managed agents. 18 log files, window 2026-08-15T09:21:40Z to 2026-09-03T11:29:44Z.

target root lines
buzz_acp* 98,082
serve_inner and buzz_agent, the child process under its own filter 1,192
the 20 custom roots this PR renames 0

99,274 target-bearing lines, and those three rows sum to exactly that. The 1,192 foreign lines are the positive control. That file accepts a target that is not buzz_acp without complaint, so the zero is a measurement and not a broken grep. The buzz-acp binary installed on that box carries the literal strings acp::stream, pool::effort, canvas::fetch and buzz_acp=info, with a nonsense control string absent. It is the build that produced everything in the window from 25 August on, so the zero is tied to this mechanism in a binary I can inspect.

1. A straight rebase leaves five sites behind

This branch rewrites 19 distinct targets. Main now has 20. The one that postdates the branch is pool::effort, and it is five sites.

crates/buzz-acp/src/pool.rs:1688  [info]
crates/buzz-acp/src/pool.rs:1705  [info]
crates/buzz-acp/src/pool.rs:1718  [error]
crates/buzz-acp/src/pool.rs:1726  [warn]
crates/buzz-acp/src/pool.rs:1735  [error]

Rebase as it stands and 5 of 93 sites stay dark. I read that as the argument for landing this quickly. Every week it sits, main adds more targets under the old convention, because there is nothing in the tree that stops it.

2. The content blocker is real. It is also narrower than this thread says.

I went through all 93 sites by level. 25 info, 31 warn, 14 error, 23 debug. After the rename, buzz_acp=info turns on 70 of them and leaves 23 dark. Three of the 70 touch content.

Blocking.

  • acp.rs:1758, acp::stream at info, "{text}" from agent_message_chunk. The model's reply, verbatim, every chunk. @artemtrofymenko has this one exactly right.
  • pool.rs:2684, pool::prompt at info, the command = %cmd field. This is worse than command arguments. extract_slash_command returns rest.to_string() at queue.rs:1154, which is the whole message after leading mentions are stripped. Any message starting with a slash goes to disk in full.

Needs a ruling.

  • acp.rs:1771, acp::tool at info, tool_call: {title} ({kind}). title is whatever the agent puts in the ACP field. There is no fixed vocabulary behind it, so it deserves a decision rather than an assumption in either direction.

Already dark, and staying that way.

  • acp::thought is at debug (acp.rs:1789). Verbatim reasoning does not come on under the default filter.
  • Nine of the eleven acp::wire sites are debug, including every one that dumps a full JSON payload. The two at warn (acp.rs:1230 and acp.rs:1553) log a serde parse failure and nothing more.
  • pool.rs:2751 logs prompt_bytes, an integer sum built at pool.rs:2743. That is a size, not a prompt.
  • No warn or error site interpolates conversation content. They carry timeouts, ids, model names, config ids and error strings.

So the content fix here is two sites. It is not a redesign of the level scheme. Drop acp::stream to debug, and either remove cmd from the pool::prompt field set or log its length instead. That leaves the other 68 diagnostic sites doing exactly the job this PR exists to restore.

One note on shape

Worth saying plainly while the two approaches are being compared. This branch is 168 changed lines and every one of them contains target: ". No level changes, no logic changes, pure rename. That is the reason the content question is a two-line addition here rather than a rework.

I am not opening a competing PR. I have said the same on #6035.

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.

3 participants