fix(desktop): stop dropping 19 of the harness's log targets - #16
Merged
Merged
Conversation
`child_rust_log_filter` handed the spawned harness `buzz_acp=info`, which
looks right and matches almost nothing. EnvFilter matches on a span's TARGET,
which defaults to the module path — but buzz-acp sets an explicit `target:` on
its diagnostic lines, and an explicit target REPLACES the module path rather
than extending it. None of those targets start with `buzz_acp`.
Silenced: 19 targets under five roots — pool:: (prompt, session, model,
permission, metrics), acp:: (wire, update, usage, permission, tool, cancel,
thought, stream, session, plan, init), canvas::fetch, engram::core, observer.
Two of the casualties are lines whose absence cost real debugging time: the
only record that a session was created ("created session … for channel …"),
so session rotation was unobservable, and pool::model's model-override miss,
which is what would say whether a `[1m]` model ref actually reaches the API.
Both questions went unanswered for days against a log that was structurally
incapable of answering them.
info, not debug, and that is measured rather than assumed: across these
targets the call sites are roughly 11 debug, 7 info, 6 warn, 2 error. At info
the debug lines stay off — including acp::wire's frame dumps — so this
surfaces the ~15 lines worth reading without inflating every agent's log.
Split the env read from the rule so the rule is testable without mutating
process state that parallel tests share. The regression test asserts coverage
against a list of the roots buzz-acp actually uses, so adding a sixth root
upstream fails here rather than silently going dark.
Scope worth stating plainly: LOCAL agents only. A provider-backed agent's
harness is launched by its backend from a separate env and never through this
path, and `get_managed_agent_log` refuses remote agents outright. This does
nothing for diagnosing a sprite.
Signed-off-by: Junchao Yan <yjc801@gmail.com>
Round 2 on #16. Three P2s from review, all reproduced against source before fixing. 1. acp::stream is a per-chunk firehose, not a diagnostic line. `acp=info` also enables `acp::stream`, whose agent_message_chunk arm is `tracing::info!` on the chunk text (buzz-acp/src/acp.rs:1734) — every agent response copied verbatim into the runtime log. Nothing bounds that: `maybe_rotate_log` runs only inside `open_log_file` (managed_agents/storage.rs), which is called once at spawn, so the 10 MB ceiling is never re-checked for the life of the process. Default is now `acp::stream=off`. It is the only info-level per-chunk site in the set — acp::thought and all 11 acp::wire sites are already debug, so nothing else needed naming. 2. Appending defaults silently overrode operator directives. `RUST_LOG=pool=off` produced `pool=off,…,pool=info`. That is not a no-op: EnvFilter keeps one directive per (target, span, fields), and `DirectiveSet::add` does `Ok(i) => self.directives[i] = directive` on a binary-search hit while `Ord for Directive` compares target/span/ fields and never the level. The later duplicate wins, so the default re-enabled logs the operator had switched off, and `acp=debug` was clipped back to info. Defaults are now merged per target rather than concatenated: a default is dropped when the operator names its target or an ancestor of it. `acp=debug` therefore suppresses both `acp=info` and `acp::stream=off`; `acp::stream=trace` suppresses only the latter, leaving `acp=info` to cover the sibling targets the operator said nothing about. Directive parsing strips the `[span{field=value}]` section before splitting on `=`, since that section can contain one. 3. The additions broke the desktop file-size ratchet. runtime.rs went 985 -> 1022 against a 1000-line limit, and runtime/tests.rs 1275 -> 1333 while already capped at its merge-base 1275, so `just ci` could not pass. Both files are back at their base contents; the helper and its tests live in a new managed_agents/runtime/log_filter.rs (281 lines). Tests now assert resolved behaviour instead of substrings. The defect this module exists to fix was a filter that read correctly and matched nothing, so `filter.contains("pool=info")` is not evidence. Each case parses the produced filter and asks whether a target is enabled at a level, via `filter::Targets` — a newtype over the same `DirectiveSet<StaticDirective>` that backs EnvFilter's static directives, added as a dev-dependency (already in the desktop lockfile; one line added). Signed-off-by: Junchao Yan <yjc801@gmail.com>
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Summary
child_rust_log_filterhanded the spawned harnessbuzz_acp=info. That looksright and matches almost nothing.
EnvFiltermatches on an event's target, which defaults to the module path —but buzz-acp sets an explicit
target:on its diagnostic lines, and an explicittarget replaces the module path rather than extending it. None of those
targets begin with
buzz_acp, so none of them ever matched.That silenced 19 targets under five roots:
pool::acp::canvas::engram::observerTwo of the casualties are lines whose absence cost real debugging time: the only
record that a session was created (
created session … for channel …), which madesession rotation unobservable, and
pool::model's model-override miss, which iswhat would say whether a
[1m]model ref actually reaches the API. Both questionswent unanswered for days against a log that was structurally incapable of
answering them.
The fix names each root explicitly. With no
RUST_LOGset, the harness gets:buzz_acp=stays in the list — lines that don't overridetarget:still fallback to the module path, which does start with
buzz_acp.Why
infoand notdebug— measured, not assumed. Across these targets thecall sites are roughly 11
debug, 7info, 6warn, 2error. Atinfothedebug lines stay off, including
acp::wire's 11 frame dumps andacp::thought,so this surfaces the lines worth reading without inflating every agent's log.
Why
acp::stream=off— it is the one info-level site that fires per chunk,logging the text of every
agent_message_chunk(
crates/buzz-acp/src/acp.rs), soacp=infoalone would copy every agent response into the runtime log verbatim. Nothing
would bound that:
maybe_rotate_logruns only insideopen_log_file(
managed_agents/storage.rs), which is called once at spawn, so the 10 MBceiling is never re-checked for the life of the process. It stays available on
request —
RUST_LOG=acp::stream=traceoracp=debugboth turn it on.Defaults are merged per target, not appended. Appending is not neutral:
EnvFilterkeeps one directive per (target, span, fields), andDirectiveSet::adddoes
Ok(i) => self.directives[i] = directiveon a binary-search hit whileOrd for Directivecompares target/span/fields and never the level. So a trailingpool=infowins over an operator'sRUST_LOG=pool=off, and clipsacp=debugback to
info. Instead, a default is dropped when the operator names its targetor an ancestor of it:
RUST_LOGpool=offpoolstays off; other roots still coveredacp=debugacp=infoandacp::stream=off— debug means debugacp::stream=traceacp::stream=off;acp=infostill covers the siblingswarnbuzz_acpDirective parsing strips the
[span{field=value}]section before splitting on=, since that section can itself contain one.Scope
Local agents only. A provider-backed agent's harness is launched by its
backend from a separate env and never through this path, and
get_managed_agent_logrefuses remote agents outright. This does nothing fordiagnosing a sprite.
The operator escape hatch is preserved: a
RUST_LOGthat namesbuzz_acpexplicitly is passed through untouched, so someone narrowing the filter to one
target doesn't get it widened back out.
Related issue
Upstream block/buzz#3309 — same bug, other side of the seam. Currently open, not merged.
block#3309 diagnoses the identical mechanism (explicit
target:replaces the modulepath, so
buzz_acp=*matches none of it) and fixes it in buzz-acp byprefixing every custom target with
buzz_acp::, so the crate filter reachesthem. That is the better fix and it strictly dominates this one on coverage:
explicitly does not;
RUST_LOG=buzz_acp=debugbehave asTESTING.mdalready documents,instead of leaving the docs wrong;
This PR is a fork-local workaround that works today without waiting on an
upstream merge, and is worth having on those terms — but a reviewer should know
it is the narrower of the two fixes.
They are compatible. If block#3309 lands and this fork merges upstream, the
re-rooted targets match the
buzz_acp=infoclause that this filter stillcarries; the extra roots become inert rather than conflicting. The redundant
roots should be dropped at that point, and
HARNESS_TARGET_ROOTSinlog_filter.rsis the thing that will flag it — it asserts against the rootsbuzz-acp actually uses, so a re-rooting upstream fails that test loudly instead
of leaving dead config behind.
acp::stream=offwould need re-expressing asbuzz_acp::acp::stream=offat the same time.Layout
The helper and its tests moved out of
runtime.rs/runtime/tests.rsintomanaged_agents/runtime/log_filter.rs(281 lines). Keeping them in placepushed
runtime.rsto 1022 against a 1000-line limit andruntime/tests.rsto 1333 against its merge-base ratchet of 1275, so
just cicould not pass.Both files are back at their base contents.
Testing
test result: ok. 11 passed; 0 failed. Full gate:just cigreen.The tests assert resolved behaviour, not substrings. The defect this module
exists to fix was a filter that read correctly and matched nothing, so
filter.contains("pool=info")is not evidence of anything. Each case parses theproduced filter and asks whether a target is enabled at a level, through
tracing_subscriber::filter::Targets— a newtype over the sameDirectiveSet<StaticDirective>that backsEnvFilter's static directives,parsed and resolved most-specific-first the same way. Added as a
dev-dependency; it was already in
desktop/src-tauri/Cargo.lock, so thelockfile change is one line.
default_filter_enables_every_harness_target_rootHARNESS_TARGET_ROOTSresolves to enabled atinfo; a sixth root added upstream fails here rather than silently going darkharness_targets_are_enabled_at_info_not_debugacp::wire/pool::promptstay off atdebug— guards against "fixing" quiet logs by turning on the frame dumpsresponse_chunks_are_off_by_defaultacp::streamoff at every level, siblings still onan_empty_or_blank_rust_log_is_treated_as_unset""and whitespacean_unrelated_rust_log_is_extended_not_replacedhyper=warnsurvives, defaults appendedan_explicit_buzz_acp_filter_is_passed_through_untouchedan_operator_silenced_root_stays_silencedpool=offis not re-enabled — the regression test for the append bugan_operator_raised_root_is_not_downgradedacp=debugreaches debug, includingacp::streamasking_for_the_stream_gets_the_stream_and_keeps_the_resta_bare_level_names_no_target_and_suppresses_nothingRUST_LOG=warna_span_field_directive_does_not_confuse_target_parsingpool[work{id=7}]=offparses as targetpool, notpool[work{idTwo traps worth naming, because both produce a green result that means nothing:
cargo testat the repo root does not cover this. The
--manifest-pathis required.cargo testexits 0 when a name filter matches nothing. Filtering on afunction name that no test is called leaves you with a passing build that
verified nothing — check the reported test count, not the exit code.
No UI change, so no screenshots.
🤖 Generated with Claude Code