mirror of
https://github.com/block/buzz.git
synced 2026-10-27 04:30:52 +00:00
feat(buzz-agent): surface stop reason and silent-turn WARN in telemetry (#7038)
## What Two telemetry additions to make a known silent-death failure mode visible in harness logs. **1. `stop` field on `llm: call completed` INFO** (`crates/buzz-agent/src/llm.rs`) The `ProviderStop` value was already parsed and stored on `LlmResponse` but never emitted in the log line. Without it, "model chose `end_turn`" vs "gateway truncated/refused" is indistinguishable from telemetry alone. **2. WARN on silent-turn signature** (`crates/buzz-agent/src/agent.rs`) Emits a `WARN` when a turn produces no publish, no visible assistant text, and either near-zero or absent output tokens. The WARN logic is extracted into `warn_if_silent_turn` (pure synchronous function) so the seam is testable without the async run loop. Three independent gates before the WARN fires: 1. **`!buzz_reply_call_seen`** — no publish attempt in any round, tracked unconditionally via the existing `is_buzz_reply_call` matcher. Read-only tool calls do NOT suppress the WARN; a turn that ran tools but never published and died at 3 tokens is still a silent death. 2. **`text_is_empty`** — no visible assistant text in the final round. A terse reply like "OK" (≤12 tokens, non-empty) is not a silent death. 3. **Token check** — two distinct WARN messages: - `Some(t) where t <= 12`: near-zero token count, the observed failure signature (2–12 tokens) - `None` usage: provider omitted token counts entirely, separately diagnostic Tests use a scoped `tracing_subscriber` layer (same pattern as the existing stall-warn tests in `llm.rs`) to exercise the WARN seam directly: - Canonical signature (no publish, no text, 4 tokens) → 1 WARN - Non-empty assistant text → 0 WARNs - Publish seen → 0 WARNs - `None` usage (no publish, no text) → 1 WARN ## Why Recurring silent-death incident in a specific agent×channel combination: sessions die with 1 LLM call, 2–12 output tokens, no tool calls, no message, no error — recorded as a "successful" turn. The harness log shows the token count but not the `stop_reason`, leaving the root cause undiagnosable without request-level tracing. The observed shape also includes tool-step-then-3-token-death (one tool call, then silence) — the publish-aware gate catches both shapes. Context thread: buzz://message?channel=91fd9ca1-cf04-4ef7-b18f-aa2aee55692b&id=e3f1693f2e29f26a0c840f8054d592270c1504beacdc1d9c2063d8ab82960a06 ## Scope Logging and telemetry only. No behavior change, no retry-logic change, no stop-reason mapping change. --------- Signed-off-by: Will Pfleger <pfleger.will@gmail.com> Co-authored-by: Duncan <dcfd242e557282d7a1e2cf2e6877522682f1e5c6156dc92ca7d90eaedd3b0f95@buzz.block.builderlab.xyz>
This commit is contained in:
@@ -68,6 +68,12 @@ fn replace_unsupported_images(history: &mut [HistoryItem]) -> usize {
|
||||
/// [`Config::require_reply`](crate::config::Config::require_reply).
|
||||
const MAX_REPLY_NAGS: u32 = 2;
|
||||
|
||||
/// Output-token upper bound (inclusive) for the silent-death signature: the
|
||||
/// observed failure emits 2–12 tokens. Turns with `output_tokens <= 12`
|
||||
/// and no prior tool call are flagged. Legitimate one-sentence replies land
|
||||
/// well above this value even in the most terse case.
|
||||
const SILENT_TURN_TOKEN_THRESHOLD: u64 = 12;
|
||||
|
||||
/// Server label on the synthetic reply-guard objection.
|
||||
///
|
||||
/// Not a real MCP server. It rides the same tool-result path as `_Stop` hook
|
||||
@@ -348,6 +354,11 @@ impl RunCtx<'_> {
|
||||
//
|
||||
// Named for what it proves: a *recognized attempt* to publish, not a
|
||||
// successful publish. See `is_buzz_reply_call`.
|
||||
// Tracks whether a publish-shaped tool call was seen this turn, updated
|
||||
// unconditionally (not gated on `require_reply`) so the silent-turn
|
||||
// diagnostic has a turn-level view regardless of config. A turn that
|
||||
// ran read-only tools and then died at 3 tokens IS a silent death;
|
||||
// only a genuine publish should suppress the WARN.
|
||||
let mut buzz_reply_call_seen = false;
|
||||
let mut reply_nags = 0u32;
|
||||
// Per-`run()` reactive context-recovery budget. Per-turn, not
|
||||
@@ -696,12 +707,33 @@ impl RunCtx<'_> {
|
||||
"provider: stop=tool_use but zero tool_calls".into(),
|
||||
));
|
||||
}
|
||||
// Capture before response.text is moved into history.
|
||||
let text_is_empty = response.text.trim().is_empty();
|
||||
self.history.push(HistoryItem::Assistant {
|
||||
text: response.text,
|
||||
tool_calls: Vec::new(),
|
||||
reasoning_details: response.reasoning_details.clone(),
|
||||
});
|
||||
let stop = map_stop(response.stop);
|
||||
// Diagnostic: warn when no publish was seen across the whole
|
||||
// turn, the final response has no visible text, and the
|
||||
// token count looks silent. Two independent gates:
|
||||
// 1. `!buzz_reply_call_seen` — no publish attempt in any
|
||||
// round (read-only tool calls do NOT suppress: a turn
|
||||
// that ran tools but never published then died at 3
|
||||
// tokens is still a silent death).
|
||||
// 2. `text_is_empty` — model emitted no visible text
|
||||
// (a terse reply like "OK" is not silent).
|
||||
// 3. token count or usage-absent check.
|
||||
// Fires before the `_Stop` hook so the warning appears in
|
||||
// the log even if the hook rejects the stop and the loop
|
||||
// continues. Does not alter control flow.
|
||||
warn_if_silent_turn(
|
||||
buzz_reply_call_seen,
|
||||
text_is_empty,
|
||||
response.output_tokens,
|
||||
response.stop,
|
||||
);
|
||||
// Only gate genuine end_turn — don't override max_tokens/refusal.
|
||||
if stop == StopReason::EndTurn {
|
||||
if stop_rejections >= self.cfg.stop_max_rejections {
|
||||
@@ -746,7 +778,10 @@ impl RunCtx<'_> {
|
||||
}
|
||||
// Deliberately after truncation: a publish-shaped call that was
|
||||
// discarded never runs, so it must not suppress the reminder.
|
||||
if self.cfg.require_reply && !buzz_reply_call_seen {
|
||||
// Updated unconditionally (not gated on `require_reply`) so the
|
||||
// silent-turn diagnostic has a publish-aware turn-level signal
|
||||
// regardless of config.
|
||||
if !buzz_reply_call_seen {
|
||||
buzz_reply_call_seen = calls.iter().any(|c| is_buzz_reply_call(c, self.mcp));
|
||||
}
|
||||
self.history.push(HistoryItem::Assistant {
|
||||
@@ -1286,10 +1321,69 @@ fn map_stop(p: ProviderStop) -> StopReason {
|
||||
}
|
||||
}
|
||||
|
||||
/// Returns `true` when a reported output-token count is at or below the
|
||||
/// silent-death threshold. The observed failure signature is 2–12 tokens.
|
||||
///
|
||||
/// Takes a bare `u64` — the caller handles `None` usage separately (a
|
||||
/// provider that omits token counts is a distinct diagnostic case, not
|
||||
/// automatically "near-zero").
|
||||
///
|
||||
/// Extracted as a pure function so it can be tested without standing up an
|
||||
/// async agent loop.
|
||||
fn is_silent_turn(output_tokens: u64) -> bool {
|
||||
output_tokens <= SILENT_TURN_TOKEN_THRESHOLD
|
||||
}
|
||||
|
||||
/// Emits the silent-turn diagnostic WARN when the turn produced no publish,
|
||||
/// no visible text, and either near-zero or absent output tokens.
|
||||
///
|
||||
/// `buzz_reply_call_seen` is the publish-aware gate (from
|
||||
/// `is_buzz_reply_call`), updated unconditionally regardless of
|
||||
/// `require_reply`. Read-only tool calls do NOT suppress the WARN — a turn
|
||||
/// that ran tools but never published and then died at 3 tokens is a silent
|
||||
/// death.
|
||||
///
|
||||
/// Two distinct WARN shapes:
|
||||
/// - Near-zero token count (`output_tokens <= 12`): canonical silent-death.
|
||||
/// - Unknown usage (`None`) with no publish and no text: separately
|
||||
/// diagnostic; does not assert near-zero since the count is unknown.
|
||||
///
|
||||
/// Extracted as a free function so the WARN seam can be exercised by a
|
||||
/// scoped tracing subscriber without standing up the full async run loop.
|
||||
fn warn_if_silent_turn(
|
||||
buzz_reply_call_seen: bool,
|
||||
text_is_empty: bool,
|
||||
output_tokens: Option<u64>,
|
||||
stop: ProviderStop,
|
||||
) {
|
||||
if buzz_reply_call_seen || !text_is_empty {
|
||||
return;
|
||||
}
|
||||
match output_tokens {
|
||||
Some(t) if is_silent_turn(t) => {
|
||||
tracing::warn!(
|
||||
stop = ?stop,
|
||||
output_tokens = t,
|
||||
"agent: turn ended with no publish attempt and near-zero output tokens — possible silent model/gateway early-stop"
|
||||
);
|
||||
}
|
||||
None => {
|
||||
tracing::warn!(
|
||||
stop = ?stop,
|
||||
"agent: turn ended with no publish attempt and no usage reported — cannot confirm output size"
|
||||
);
|
||||
}
|
||||
_ => {}
|
||||
}
|
||||
}
|
||||
|
||||
#[cfg(test)]
|
||||
mod tests {
|
||||
use super::*;
|
||||
use serde_json::json;
|
||||
use std::sync::atomic::{AtomicUsize, Ordering};
|
||||
use std::sync::Arc;
|
||||
use tracing_subscriber::layer::SubscriberExt;
|
||||
|
||||
/// `truncate_history` cannot serve as the context-window fallback: it is
|
||||
/// measured in BYTES (`max_history_bytes`, default 16 MiB, a request-body
|
||||
@@ -1635,4 +1729,146 @@ mod tests {
|
||||
"three identical rounds must remain consistently proven"
|
||||
);
|
||||
}
|
||||
|
||||
// ── is_silent_turn (pure predicate) ─────────────────────────────────────
|
||||
|
||||
/// Counts WARN events emitted by `warn_if_silent_turn` calls inside `f`.
|
||||
///
|
||||
/// Identifies silent-turn WARNs by target (`buzz_agent::agent`) + WARN
|
||||
/// level + presence of the `stop` field, which is unique to these two
|
||||
/// WARNs in this module. Using the target avoids parsing message strings,
|
||||
/// which are routed through `record_debug` as `Display`-formatted values
|
||||
/// and are not reliably interceptable via `record_str` across tracing
|
||||
/// versions.
|
||||
fn count_silent_turn_warnings(f: impl FnOnce()) -> usize {
|
||||
struct Capture {
|
||||
count: Arc<AtomicUsize>,
|
||||
}
|
||||
struct Visitor {
|
||||
saw_stop: bool,
|
||||
}
|
||||
impl tracing::field::Visit for Visitor {
|
||||
fn record_debug(&mut self, field: &tracing::field::Field, _: &dyn std::fmt::Debug) {
|
||||
if field.name() == "stop" {
|
||||
self.saw_stop = true;
|
||||
}
|
||||
}
|
||||
}
|
||||
impl<S: tracing::Subscriber> tracing_subscriber::Layer<S> for Capture {
|
||||
fn on_event(
|
||||
&self,
|
||||
event: &tracing::Event<'_>,
|
||||
_: tracing_subscriber::layer::Context<'_, S>,
|
||||
) {
|
||||
if *event.metadata().level() != tracing::Level::WARN {
|
||||
return;
|
||||
}
|
||||
if event.metadata().target() != "buzz_agent::agent" {
|
||||
return;
|
||||
}
|
||||
let mut v = Visitor { saw_stop: false };
|
||||
event.record(&mut v);
|
||||
if v.saw_stop {
|
||||
self.count.fetch_add(1, Ordering::SeqCst);
|
||||
}
|
||||
}
|
||||
}
|
||||
let count = Arc::new(AtomicUsize::new(0));
|
||||
let sub = tracing_subscriber::registry().with(Capture {
|
||||
count: count.clone(),
|
||||
});
|
||||
tracing::subscriber::with_default(sub, f);
|
||||
count.load(Ordering::SeqCst)
|
||||
}
|
||||
|
||||
/// Predicate: values within the observed failure range (2–12) fire.
|
||||
/// Pair (0, 12) catches an always-false mutation and an off-by-one at 12.
|
||||
#[test]
|
||||
fn is_silent_turn_fires_at_and_below_threshold() {
|
||||
assert!(
|
||||
is_silent_turn(0),
|
||||
"zero output tokens must be a silent turn"
|
||||
);
|
||||
assert!(
|
||||
is_silent_turn(SILENT_TURN_TOKEN_THRESHOLD),
|
||||
"exactly at threshold (12) must be a silent turn — 12 is in the observed range"
|
||||
);
|
||||
}
|
||||
|
||||
/// One above the threshold must NOT fire, catching `<` vs `<=` and
|
||||
/// always-true mutations.
|
||||
#[test]
|
||||
fn is_silent_turn_silent_above_threshold() {
|
||||
assert!(
|
||||
!is_silent_turn(SILENT_TURN_TOKEN_THRESHOLD + 1),
|
||||
"one above threshold (13) must not be a silent turn"
|
||||
);
|
||||
}
|
||||
|
||||
// ── warn_if_silent_turn (WARN seam) ───────────────────────────────────
|
||||
|
||||
/// The canonical silent-death signature — no publish, no text, ≤12 tokens
|
||||
/// — must emit exactly one WARN. Deleting the WARN call, weakening the
|
||||
/// token check, or hardcoding `buzz_reply_call_seen = true` are all caught.
|
||||
#[test]
|
||||
fn warn_if_silent_turn_fires_for_canonical_signature() {
|
||||
let n = count_silent_turn_warnings(|| {
|
||||
warn_if_silent_turn(
|
||||
false, // no publish seen
|
||||
true, // no text
|
||||
Some(4), // 4 tokens — in the 2–12 range
|
||||
ProviderStop::EndTurn,
|
||||
);
|
||||
});
|
||||
assert_eq!(n, 1, "canonical silent-death must emit exactly one WARN");
|
||||
}
|
||||
|
||||
/// A turn that ends with non-empty assistant text is NOT a silent death
|
||||
/// even if token count is low — a terse reply like "OK" is legitimate.
|
||||
/// Deleting the `text_is_empty` gate would cause this to fail.
|
||||
#[test]
|
||||
fn warn_if_silent_turn_silent_for_nonempty_text() {
|
||||
let n = count_silent_turn_warnings(|| {
|
||||
warn_if_silent_turn(
|
||||
false, // no publish
|
||||
false, // text IS present
|
||||
Some(3), // low tokens — would fire without the text gate
|
||||
ProviderStop::EndTurn,
|
||||
);
|
||||
});
|
||||
assert_eq!(n, 0, "a turn with non-empty assistant text must not WARN");
|
||||
}
|
||||
|
||||
/// A turn that published (buzz_reply_call_seen = true) then ended with a
|
||||
/// short final completion must not trigger the WARN. This is the normal
|
||||
/// publish-then-wrap pattern. Deleting the `buzz_reply_call_seen` gate
|
||||
/// would cause this to fail.
|
||||
#[test]
|
||||
fn warn_if_silent_turn_silent_after_publish() {
|
||||
let n = count_silent_turn_warnings(|| {
|
||||
warn_if_silent_turn(
|
||||
true, // publish seen
|
||||
true, // no text in final round
|
||||
Some(0), // zero tokens — would fire without the publish gate
|
||||
ProviderStop::EndTurn,
|
||||
);
|
||||
});
|
||||
assert_eq!(n, 0, "a turn where a publish ran must not WARN");
|
||||
}
|
||||
|
||||
/// Unknown usage (None) with no publish and no text emits the distinct
|
||||
/// "no usage reported" WARN. Mutating the None arm to fall through to
|
||||
/// `_ => {}` would cause this.
|
||||
#[test]
|
||||
fn warn_if_silent_turn_fires_distinct_warn_for_none_usage() {
|
||||
let n = count_silent_turn_warnings(|| {
|
||||
warn_if_silent_turn(
|
||||
false, // no publish
|
||||
true, // no text
|
||||
None, // provider omitted usage
|
||||
ProviderStop::EndTurn,
|
||||
);
|
||||
});
|
||||
assert_eq!(n, 1, "unknown-usage silent turn must emit exactly one WARN");
|
||||
}
|
||||
}
|
||||
|
||||
@@ -229,6 +229,7 @@ impl Llm {
|
||||
input_tokens = ?response.input_tokens,
|
||||
cached_input_tokens = ?response.cached_input_tokens,
|
||||
output_tokens = ?response.output_tokens,
|
||||
stop = ?response.stop,
|
||||
"llm: call completed"
|
||||
);
|
||||
}
|
||||
|
||||
Reference in New Issue
Block a user