diff --git a/src/openhuman/agent/harness/mod.rs b/src/openhuman/agent/harness/mod.rs index e26ee9166c..516b8a26cb 100644 --- a/src/openhuman/agent/harness/mod.rs +++ b/src/openhuman/agent/harness/mod.rs @@ -45,6 +45,7 @@ pub mod task_recency_context; pub(crate) mod tool_filter; pub(crate) mod tool_result_artifacts; pub mod turn_attachments_context; +pub mod turn_dispatch_guard; pub mod turn_subagent_usage; pub use agent_graph::{AgentGraph, AgentTurnRequest, AgentTurnResult, AgentTurnUsage}; diff --git a/src/openhuman/agent/harness/session/turn/core.rs b/src/openhuman/agent/harness/session/turn/core.rs index dfdaf99cdf..9d793fa1a8 100644 --- a/src/openhuman/agent/harness/session/turn/core.rs +++ b/src/openhuman/agent/harness/session/turn/core.rs @@ -973,7 +973,18 @@ impl Agent { // `spawn_subagent` runs inline on this task and records into the collector) // so the turn's usage meters + the `chat_done` per-child breakdown include // it — the collector scope the legacy engine installed. - let (outcome, subagent_usage_entries) = + // Install the turn's sub-agent dispatch guard around the same future + // (#5804). It records two facts the turn already produces but never + // wrote down — that a graceful pause has been requested at the + // model-call cap, and how long this turn's sub-agents actually take — + // so `run_subagent` can refuse a dispatch that cannot finish inside the + // remaining wall-clock budget instead of taking the whole turn down + // with it. Boxed at the call site: `with_dispatch_guard` takes its + // future by value, and the collector future wraps the entire turn + // generator, so passing it unboxed would move hundreds of KiB through + // this frame — the same hazard `with_turn_collector`'s own comment + // documents, with the gdb measurements behind it. + let turn_future = Box::pin( crate::openhuman::agent::harness::turn_subagent_usage::with_turn_collector( super::graph::run_chat_turn_graph(super::graph::ChatTurnGraph { turn_models, @@ -1007,6 +1018,13 @@ impl Agent { .map(|definition| definition.sandbox_mode) .unwrap_or(crate::openhuman::agent::harness::definition::SandboxMode::None), }), + ), + ); + let (outcome, subagent_usage_entries) = + crate::openhuman::agent::harness::turn_dispatch_guard::with_dispatch_guard( + crate::openhuman::agent::tinyagents::agent_turn_wall_clock_ms() + .map(std::time::Duration::from_millis), + turn_future, ) .await; let outcome = outcome?; diff --git a/src/openhuman/agent/harness/subagent_runner/ops/mod.rs b/src/openhuman/agent/harness/subagent_runner/ops/mod.rs index 2540d15384..80d5ca7929 100644 --- a/src/openhuman/agent/harness/subagent_runner/ops/mod.rs +++ b/src/openhuman/agent/harness/subagent_runner/ops/mod.rs @@ -62,6 +62,8 @@ pub(super) use crate::openhuman::agent::harness::definition::{AgentDefinition, P #[cfg(test)] pub(super) use crate::openhuman::agent::harness::fork_context::ParentExecutionContext; #[cfg(test)] +pub(super) use crate::openhuman::agent::harness::turn_dispatch_guard; +#[cfg(test)] pub(super) use crate::openhuman::agent::harness::{ current_spawn_depth, with_spawn_depth, MAX_SPAWN_DEPTH, }; diff --git a/src/openhuman/agent/harness/subagent_runner/ops/runner.rs b/src/openhuman/agent/harness/subagent_runner/ops/runner.rs index 92a0280fa9..4a0e626b35 100644 --- a/src/openhuman/agent/harness/subagent_runner/ops/runner.rs +++ b/src/openhuman/agent/harness/subagent_runner/ops/runner.rs @@ -38,6 +38,7 @@ use crate::openhuman::agent::harness::subagent_runner::types::{ SubagentMode, SubagentRunError, SubagentRunOptions, SubagentRunOutcome, SubagentRunStatus, SubagentUsage, }; +use crate::openhuman::agent::harness::turn_dispatch_guard; use crate::openhuman::agent::harness::{ current_spawn_depth, with_current_sandbox_mode, with_spawn_depth, MAX_SPAWN_DEPTH, }; @@ -306,13 +307,18 @@ async fn try_deterministic_memory_retrieval( /// Run a sub-agent based on its definition and a task prompt. /// /// This is the primary entry point for agent delegation. It performs the following: -/// 1. Resolves the [`ParentExecutionContext`] task-local. -/// 2. Generates a unique `task_id` if one wasn't provided. -/// 3. Dispatches to `run_typed_mode`. +/// 1. Generates a unique `task_id` if one wasn't provided. +/// 2. Asks the turn's +/// [dispatch guard](crate::openhuman::agent::harness::turn_dispatch_guard) +/// whether a delegation can still succeed, and refuses before spending +/// anything if it cannot (#5804). +/// 3. Resolves the [`ParentExecutionContext`] task-local. +/// 4. Dispatches to `run_typed_mode`. /// /// On success returns a [`SubagentRunOutcome`] whose `output` is the /// final assistant text. On failure the error is suitable for stringifying -/// into a `tool_result` block. +/// into a `tool_result` block — including the two dispatch refusals, whose +/// messages tell the model to summarise rather than delegate again. pub async fn run_subagent( definition: &AgentDefinition, task_prompt: &str, @@ -333,11 +339,63 @@ pub async fn run_subagent( // child's tinyagents drive future further chunk the child's state so // a single sub-agent run can't blow the stack either. Box::pin(async move { - let parent = current_parent().ok_or(SubagentRunError::NoParentContext)?; let task_id = options .task_id .clone() .unwrap_or_else(|| format!("sub-{}", uuid::Uuid::new_v4())); + + // Turn-scoped dispatch gate (#5804) — deliberately the FIRST gate, for + // the same reason the depth gate is synchronous and pre-dispatch: a + // delegation we already know cannot land should cost nothing, not a + // config load, a hook, or a provider round-trip. + // + // Two refusals, both evidence-based and both derived from what this + // turn has actually observed rather than from any configured constant + // or task shape: a graceful pause has been requested at the model-call + // cap, or less wall-clock remains than this turn's slowest completed + // sub-agent took. Outside a turn scope the guard is absent and this is + // a no-op, so CLI and direct invocations are unaffected. + match turn_dispatch_guard::check() { + turn_dispatch_guard::DispatchDecision::Allow => {} + turn_dispatch_guard::DispatchDecision::RefusePaused { + completed_model_calls, + cap, + } => { + tracing::info!( + agent_id = %definition.id, + task_id = %task_id, + completed_model_calls, + cap, + "[subagent_runner] dispatch refused — turn already requested a graceful pause" + ); + return Err(SubagentRunError::PauseRequested { + completed_model_calls, + cap, + }); + } + turn_dispatch_guard::DispatchDecision::RefuseBudget { + remaining_ms, + observed_max_ms, + observed_samples, + } => { + tracing::info!( + agent_id = %definition.id, + task_id = %task_id, + remaining_ms, + observed_max_ms, + observed_samples, + "[subagent_runner] dispatch refused — remaining budget is shorter than this \ + turn's slowest sub-agent" + ); + return Err(SubagentRunError::DispatchBudgetExhausted { + remaining_ms, + observed_max_ms, + observed_samples, + }); + } + } + + let parent = current_parent().ok_or(SubagentRunError::NoParentContext)?; let started = Instant::now(); let current_depth = current_spawn_depth(); let attempted_depth = current_depth.saturating_add(1); @@ -431,6 +489,19 @@ pub async fn run_subagent( ) .await { + // The fast path completes a real delegation and returns here, + // short-circuiting the recorder below — so record it too, or a + // turn whose only delegations are deterministic memory + // retrievals never accumulates a sample and the budget gate + // stays disarmed for the whole turn (#5804 review). + // + // Including it cannot weaken the gate. `observed_max` is a + // running **maximum**, so a short sample can only leave it + // where it was — an earlier revision of this comment claimed + // the opposite and was wrong about its own statistic. What it + // does buy is a correct `observed_samples` count and a gate + // that arms on a turn shaped entirely from fast-path work. + turn_dispatch_guard::record_subagent_elapsed(started.elapsed()); return Ok(outcome); } } @@ -471,7 +542,7 @@ pub async fn run_subagent( "[subagent_runner] worktree-isolated worker: descriptor will route acting-tool CWD" ); } - let mut outcome = with_spawn_depth(attempted_depth, async { + let run_result = with_spawn_depth(attempted_depth, async { with_file_state_agent_id(task_id.clone(), async { with_current_sandbox_mode(definition.sandbox_mode, async { with_parent_context(parent_for_subagent.clone(), async { @@ -491,7 +562,27 @@ pub async fn run_subagent( }) .await }) - .await?; + .await; + + // Feed this delegation's wall-clock into the turn's running maximum, + // which is the only thing the budget gate above judges a later + // dispatch against (#5804). The deterministic fast path above records + // separately and returns, so it cannot reach here twice. + // + // Recorded on BOTH the success and the failure path, and before the + // `?`: a delegation that ran for three minutes and then errored spent + // exactly as much of the turn's budget as one that succeeded, and is + // exactly as much evidence about what a dispatch costs. Dropping + // failures would bias the estimate downwards, and the gate fails open, + // so the bias would show up as the guard not firing when it should. + // + // Measured from the outer `started` rather than `outcome.elapsed`, so + // the config load and the tier/hook gates are inside the figure — the + // question the gate asks is how long a *dispatch* takes end to end, + // not how long the child's own loop ran. + turn_dispatch_guard::record_subagent_elapsed(started.elapsed()); + + let mut outcome = run_result?; // #3883: offload an oversized worker result to `action_dir/outputs/` // BEFORE the cap below truncates it, so the parent receives a path plus diff --git a/src/openhuman/agent/harness/subagent_runner/ops_tests.rs b/src/openhuman/agent/harness/subagent_runner/ops_tests.rs index e77efd65d9..7133ecf15d 100644 --- a/src/openhuman/agent/harness/subagent_runner/ops_tests.rs +++ b/src/openhuman/agent/harness/subagent_runner/ops_tests.rs @@ -1714,3 +1714,89 @@ fn tier_gate_allows_upward_reasoning_to_chat() { child.agent_tier = AgentTier::Chat; assert!(gate(Some(&parent), &child).is_ok()); } + +// --------------------------------------------------------------------------- +// Turn-scoped dispatch gate (#5804) +// +// These exercise the gate at its real call site rather than only the policy it +// consults. The lever is that no `ParentExecutionContext` is installed here, so +// an ungated `run_subagent` returns `NoParentContext`: each refusal below is +// therefore evidence the gate ran *and* that it ran before anything was spent, +// and removing the gate turns every one of them into `NoParentContext`. +// --------------------------------------------------------------------------- + +#[tokio::test] +async fn dispatch_is_refused_after_the_turn_requests_a_graceful_pause() { + let definition = make_def_named_tools(&[]); + let outcome = turn_dispatch_guard::with_dispatch_guard( + Some(std::time::Duration::from_secs(600)), + async { + // Stands in for `CapPauser`, which writes through a clone of this + // same `Arc` when the model-call cap is reached. + turn_dispatch_guard::current() + .expect("guard installed") + .record_pause_requested(15, 15); + run_subagent(&definition, "task", SubagentRunOptions::default()).await + }, + ) + .await; + + assert!( + matches!( + outcome, + Err(SubagentRunError::PauseRequested { + completed_model_calls: 15, + cap: 15 + }) + ), + "a dispatch after the cap-pause request must be refused, not run: {outcome:?}" + ); +} + +#[tokio::test] +async fn dispatch_is_refused_when_the_remaining_budget_cannot_fit_an_observed_subagent() { + let definition = make_def_named_tools(&[]); + let outcome = turn_dispatch_guard::with_dispatch_guard( + Some(std::time::Duration::from_millis(1)), + async { + // One completed sub-agent took a minute; the turn's whole ceiling + // is a millisecond and it has already elapsed. + turn_dispatch_guard::record_subagent_elapsed(std::time::Duration::from_secs(60)); + tokio::time::sleep(std::time::Duration::from_millis(5)).await; + run_subagent(&definition, "task", SubagentRunOptions::default()).await + }, + ) + .await; + + assert!( + matches!( + outcome, + Err(SubagentRunError::DispatchBudgetExhausted { .. }) + ), + "a dispatch that cannot fit the remaining budget must be refused: {outcome:?}" + ); +} + +#[tokio::test] +async fn dispatch_is_not_refused_while_the_guard_has_no_evidence() { + // The other half of the contract, and the one that keeps this from being a + // throughput regression: with no pause requested and no completed + // sub-agent to learn from, the gate must let the dispatch through. Reaching + // `NoParentContext` is exactly that — the gate declined to interfere and + // the normal path ran. + let definition = make_def_named_tools(&[]); + let outcome = turn_dispatch_guard::with_dispatch_guard( + Some(std::time::Duration::from_millis(1)), + async { + tokio::time::sleep(std::time::Duration::from_millis(5)).await; + run_subagent(&definition, "task", SubagentRunOptions::default()).await + }, + ) + .await; + + assert!( + matches!(outcome, Err(SubagentRunError::NoParentContext)), + "an exhausted budget with no observed sub-agent is not evidence — the \ + dispatch must proceed: {outcome:?}" + ); +} diff --git a/src/openhuman/agent/harness/subagent_runner/types.rs b/src/openhuman/agent/harness/subagent_runner/types.rs index be689b6047..aa0dfc1721 100644 --- a/src/openhuman/agent/harness/subagent_runner/types.rs +++ b/src/openhuman/agent/harness/subagent_runner/types.rs @@ -248,4 +248,41 @@ pub enum SubagentRunError { /// satisfy — so the two must not read the same in a transcript. #[error("delegation blocked by a configured hook: {0}")] HookDenied(String), + + /// The turn asked to pause gracefully at its model-call cap before this + /// dispatch was attempted (#5804). + /// + /// Distinct from the budget refusal below on purpose: this one is a fact + /// about the turn's *intent* — the loop is going to stop at its next + /// boundary no matter how much time is left — while the other is a + /// measured prediction. Reported to the model as a terminal instruction to + /// summarise, because further fan-out cannot reach the answer and can only + /// consume the budget the checkpoint summary needs. + #[error( + "delegation refused: this turn reached its model-call cap ({completed_model_calls}/{cap}) \ + and has already requested a graceful pause. Do not delegate again — summarise the results \ + you already have and finish the turn." + )] + PauseRequested { + completed_model_calls: u64, + cap: u64, + }, + + /// Less wall-clock remained than the slowest sub-agent this turn has + /// actually completed, so the dispatch could not have finished (#5804). + /// + /// The comparison is against this turn's own measured maximum, never a + /// configured constant, so the refusal means the same thing for a turn + /// with three fast children as for one with three hundred slow ones. + #[error( + "delegation refused: {remaining_ms} ms of this turn's wall-clock budget remain, but the \ + slowest of its {observed_samples} completed sub-agent(s) took {observed_max_ms} ms, so a \ + new delegation cannot finish in time. Summarise the results you already have and finish \ + the turn." + )] + DispatchBudgetExhausted { + remaining_ms: u64, + observed_max_ms: u64, + observed_samples: u64, + }, } diff --git a/src/openhuman/agent/harness/turn_dispatch_guard.rs b/src/openhuman/agent/harness/turn_dispatch_guard.rs new file mode 100644 index 0000000000..2c9ca2a52e --- /dev/null +++ b/src/openhuman/agent/harness/turn_dispatch_guard.rs @@ -0,0 +1,290 @@ +//! Turn-scoped guard that decides whether a **new sub-agent dispatch can still +//! succeed** before it is attempted. +//! +//! # The failure this exists to prevent +//! +//! A turn that reaches its model-call cap asks the harness to stop gracefully +//! ([`CapPauser`](crate::openhuman::agent::tinyagents::observability), which +//! sends `SteeringCommand::Pause`) so the caller can summarise a resumable +//! checkpoint instead of erroring. That command is **advisory**: it is honoured +//! at the harness loop boundary, and nothing consulted it before dispatching a +//! new sub-agent. A dispatch issued in the same instant as the pause request +//! then runs as a tool call wrapped by the run's *remaining* wall-clock budget +//! (`run_policy_for`'s `max_wall_clock_ms`). When that remainder is smaller +//! than the child needs, the harness raises `TinyAgentsError::Timeout` for the +//! whole run — and every result the turn had accumulated is discarded rather +//! than checkpointed. The mechanism designed to degrade gracefully became the +//! cause of the hard failure (issue #5804). +//! +//! # What this guard does +//! +//! It records two facts a turn already knows but never wrote down, and turns +//! them into a decision at the one chokepoint every synchronous delegation +//! passes through (`subagent_runner::ops::runner::run_subagent`): +//! +//! 1. **Has a graceful pause been requested?** Once it has, further fan-out +//! cannot help: the loop is going to stop at its next boundary regardless, +//! so a child dispatched now can only burn budget the checkpoint needs. +//! 2. **Is there still enough wall-clock left for a dispatch to finish?** +//! Judged against what *this turn's own* sub-agents have actually taken — +//! never a configured constant. +//! +//! # Scope semantics +//! +//! Installed as a `tokio::task_local` around the parent's turn future, next to +//! [`turn_subagent_usage`](super::turn_subagent_usage) and with deliberately +//! identical visibility rules. The line is **same task or not**, which is not +//! the same line as serial or parallel: +//! +//! * **Serial delegation** (`spawn_subagent` → `run_subagent`) runs inline on +//! the turn's task and is covered. +//! * **Parallel fan-out is also covered.** `spawn_parallel_agents` drives its +//! workers through `tinyagents::graph::parallel::map_reduce`, which bounds +//! concurrency with `futures`' `buffer_unordered` +//! (`vendor/tinyagents/src/graph/parallel/mod.rs:86`) rather than +//! `tokio::spawn`. `buffer_unordered` polls every worker on the **caller's** +//! task, so each one inherits this task-local and passes the same gate. Its +//! serial fallback for shared-workspace writes is covered for the obvious +//! reason. Both call `run_subagent` +//! (`openhuman:src/openhuman/agent/orchestration/spawn_parallel_graph.rs:1386`). +//! * **Detached background sub-agents** (`spawn_async_subagent`) run on tasks +//! that do not inherit the task-local, deliberately — their spend already +//! completes after the parent's `chat_done` and is accounted globally, the +//! same carve-out `turn_subagent_usage` makes. +//! +//! [`current`] returns `None` outside any scope (CLI, direct invocation, +//! tests), and **every read degrades to "allow"** — this guard can only ever +//! refuse a dispatch it has positive evidence against, so a missing scope +//! restores exactly the previous behaviour. + +use std::sync::atomic::{AtomicBool, AtomicU64, Ordering}; +use std::sync::Arc; +use std::time::{Duration, Instant}; + +/// Per-turn dispatch state, shared between the turn scope, the harness's +/// cap-pause listener, and the sub-agent runner. +#[derive(Debug)] +pub struct TurnDispatchState { + /// Set once the harness has been asked to pause gracefully at the + /// model-call cap. Written by the cap-pause listener through a clone of + /// this `Arc` rather than through the task-local, so correctness does not + /// depend on which task the crate dispatches listeners from. + pause_requested: AtomicBool, + /// Model calls completed when the pause was requested, and the cap that + /// triggered it. Carried only so the refusal can explain itself. + pause_completed_calls: AtomicU64, + pause_cap: AtomicU64, + /// When this turn's wall-clock budget started, and how long it is. `None` + /// budget means the ceiling is disabled (`OPENHUMAN_AGENT_TURN_TIMEOUT_SECS=0`), + /// in which case no dispatch can ever be refused for want of time. + started: Instant, + budget: Option, + /// Longest sub-agent this turn has actually completed, in milliseconds. + /// `0` means "no sample yet". A running maximum rather than a stored list: + /// the decision only ever needs the extreme, and a `u64` keeps the whole + /// state lock-free. + observed_max_ms: AtomicU64, + /// How many completed sub-agents fed `observed_max_ms`, for the log line + /// and the refusal text. + observed_samples: AtomicU64, +} + +impl TurnDispatchState { + fn new(budget: Option) -> Self { + Self { + pause_requested: AtomicBool::new(false), + pause_completed_calls: AtomicU64::new(0), + pause_cap: AtomicU64::new(0), + started: Instant::now(), + budget, + observed_max_ms: AtomicU64::new(0), + observed_samples: AtomicU64::new(0), + } + } + + /// Record that a graceful pause has been requested at the model-call cap. + /// + /// Called from the harness's event listener. The crate dispatches listeners + /// synchronously on the emitting task, in insertion order + /// (`vendor/tinyagents/src/harness/events/mod.rs:163-195`), so this write + /// happens-before any later tool dispatch in the same run — which is what + /// makes the gate deterministic rather than a second race against the + /// advisory `SteeringCommand::Pause`. + pub fn record_pause_requested(&self, completed_model_calls: u64, cap: u64) { + self.pause_completed_calls + .store(completed_model_calls, Ordering::SeqCst); + self.pause_cap.store(cap, Ordering::SeqCst); + self.pause_requested.store(true, Ordering::SeqCst); + } + + /// Fold one completed sub-agent's wall-clock duration into the running + /// maximum. + fn record_subagent_elapsed(&self, elapsed: Duration) { + let ms = elapsed.as_millis().min(u128::from(u64::MAX)) as u64; + self.observed_samples.fetch_add(1, Ordering::SeqCst); + self.observed_max_ms.fetch_max(ms, Ordering::SeqCst); + } + + /// Wall-clock still available to this turn, or `None` when no ceiling is + /// configured. + fn remaining(&self) -> Option { + self.budget + .map(|b| b.saturating_sub(self.started.elapsed())) + } + + /// Longest completed sub-agent so far, or `None` when none has completed. + fn observed_max(&self) -> Option { + match self.observed_max_ms.load(Ordering::SeqCst) { + 0 => None, + ms => Some(Duration::from_millis(ms)), + } + } + + fn snapshot(&self) -> DispatchInputs { + DispatchInputs { + pause_requested: self.pause_requested.load(Ordering::SeqCst), + pause_completed_calls: self.pause_completed_calls.load(Ordering::SeqCst), + pause_cap: self.pause_cap.load(Ordering::SeqCst), + remaining: self.remaining(), + observed_max: self.observed_max(), + observed_samples: self.observed_samples.load(Ordering::SeqCst), + } + } +} + +/// Everything [`decide`] is allowed to look at. Extracted as a plain value so +/// the policy is unit-testable without a runtime, a clock, or a turn. +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub struct DispatchInputs { + pub pause_requested: bool, + pub pause_completed_calls: u64, + pub pause_cap: u64, + pub remaining: Option, + pub observed_max: Option, + pub observed_samples: u64, +} + +/// Outcome of the pre-dispatch check. +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub enum DispatchDecision { + /// Nothing known contradicts this dispatch. The default in every uncertain + /// case. + Allow, + /// A graceful pause has already been requested for this turn. + RefusePaused { + completed_model_calls: u64, + cap: u64, + }, + /// Less wall-clock remains than this turn's slowest completed sub-agent + /// took. + RefuseBudget { + remaining_ms: u64, + observed_max_ms: u64, + observed_samples: u64, + }, +} + +/// Decide whether a sub-agent dispatch should be attempted. +/// +/// Two independent refusals, in order of certainty: +/// +/// 1. **A pause was requested.** This is a fact about intent, not an estimate: +/// the loop will stop at its next boundary whatever we do, so a child +/// started now cannot contribute to the answer and can only consume the +/// budget the checkpoint summary needs. +/// +/// 2. **The remaining budget is smaller than the longest sub-agent this turn +/// has actually completed.** The predictor is the turn's own measured +/// maximum — never a configured constant, a model name, a task shape, or +/// the number of children so far — so it is equally meaningful for a turn +/// with three fast children and one with three hundred slow ones, and it +/// means nothing at all until this turn has produced its first sample. +/// +/// The maximum is used rather than a mean or a percentile because the two +/// errors are not symmetric. Refusing a dispatch that would have fit costs one +/// delegation and still returns every result gathered so far; allowing one that +/// does not fit costs **the entire turn**. Under that asymmetry the +/// conservative estimator is the correct one, and it is also the only one that +/// needs no tunable. +/// +/// Both refusals are strictly evidence-based: with no pause requested, no +/// configured ceiling, or no completed sub-agent to learn from, the answer is +/// [`DispatchDecision::Allow`]. +pub fn decide(inputs: DispatchInputs) -> DispatchDecision { + if inputs.pause_requested { + return DispatchDecision::RefusePaused { + completed_model_calls: inputs.pause_completed_calls, + cap: inputs.pause_cap, + }; + } + + // `remaining` is `None` when the wall-clock ceiling is disabled, and + // `observed_max` is `None` until a sub-agent has finished. Either one + // absent means there is nothing to compare, so nothing to refuse. + let (Some(remaining), Some(observed_max)) = (inputs.remaining, inputs.observed_max) else { + return DispatchDecision::Allow; + }; + + if remaining < observed_max { + return DispatchDecision::RefuseBudget { + remaining_ms: remaining.as_millis().min(u128::from(u64::MAX)) as u64, + observed_max_ms: observed_max.as_millis().min(u128::from(u64::MAX)) as u64, + observed_samples: inputs.observed_samples, + }; + } + + DispatchDecision::Allow +} + +tokio::task_local! { + /// Dispatch state for the turn currently executing on this task. Absent + /// outside a turn scope. + static TURN_DISPATCH_STATE: Arc; +} + +/// The dispatch state for the current turn, or `None` outside any scope. +pub fn current() -> Option> { + TURN_DISPATCH_STATE.try_with(|s| s.clone()).ok() +} + +/// Ask the guard whether a sub-agent may be dispatched now. +/// +/// Returns [`DispatchDecision::Allow`] when no guard is installed, so every +/// path that does not run under a turn scope behaves exactly as before. +pub fn check() -> DispatchDecision { + match current() { + Some(state) => decide(state.snapshot()), + None => DispatchDecision::Allow, + } +} + +/// Fold a finished sub-agent's wall-clock duration into the current turn's +/// observed maximum. No-op outside a turn scope. +pub fn record_subagent_elapsed(elapsed: Duration) { + if let Some(state) = current() { + state.record_subagent_elapsed(elapsed); + } +} + +/// Run `future` with a fresh dispatch guard installed for `budget`. +/// +/// `budget` is the turn's wall-clock ceiling — the same value the harness +/// policy receives as `max_wall_clock_ms`. Measuring from here rather than from +/// the harness run means the guard's idea of "elapsed" starts marginally +/// *earlier* than the harness's, so its remaining-budget figure is +/// conservative: it can under-estimate the time left, never over-estimate it. +pub async fn with_dispatch_guard(budget: Option, future: F) -> R +where + F: std::future::Future, +{ + let state = Arc::new(TurnDispatchState::new(budget)); + // `scope` takes the inner future by value; the turn generator is hundreds + // of KiB in a debug build, so pin it to the heap first and move only a + // pointer through this frame. See the same note (and the stack-overflow + // measurements behind it) in `turn_subagent_usage::with_turn_collector`. + TURN_DISPATCH_STATE.scope(state, Box::pin(future)).await +} + +#[cfg(test)] +#[path = "turn_dispatch_guard_tests.rs"] +mod tests; diff --git a/src/openhuman/agent/harness/turn_dispatch_guard_tests.rs b/src/openhuman/agent/harness/turn_dispatch_guard_tests.rs new file mode 100644 index 0000000000..a40beae5f8 --- /dev/null +++ b/src/openhuman/agent/harness/turn_dispatch_guard_tests.rs @@ -0,0 +1,318 @@ +//! Tests for the turn-scoped sub-agent dispatch guard (issue #5804). +//! +//! The policy ([`decide`]) is exercised as a pure function so every branch is +//! reachable without a runtime, a clock, or a model. The scope helpers are +//! exercised under `#[tokio::test]` because a `task_local` needs a task. + +use std::time::Duration; + +use super::{ + check, current, decide, record_subagent_elapsed, with_dispatch_guard, DispatchDecision, + DispatchInputs, +}; + +/// Baseline inputs: nothing known, nothing to refuse. +fn inputs() -> DispatchInputs { + DispatchInputs { + pause_requested: false, + pause_completed_calls: 0, + pause_cap: 0, + remaining: None, + observed_max: None, + observed_samples: 0, + } +} + +#[test] +fn allows_when_nothing_is_known() { + assert_eq!(decide(inputs()), DispatchDecision::Allow); +} + +#[test] +fn refuses_once_a_graceful_pause_has_been_requested() { + let decision = decide(DispatchInputs { + pause_requested: true, + pause_completed_calls: 15, + pause_cap: 15, + ..inputs() + }); + assert_eq!( + decision, + DispatchDecision::RefusePaused { + completed_model_calls: 15, + cap: 15, + }, + "a dispatch issued after the cap-pause request is the #5804 failure" + ); +} + +#[test] +fn pause_refusal_does_not_depend_on_the_remaining_budget() { + // The whole point: at the moment of the observed failure there was budget + // left (26s), it just was not enough. The pause arm must fire on intent + // alone, with an hour to spare. + let decision = decide(DispatchInputs { + pause_requested: true, + pause_completed_calls: 3, + pause_cap: 3, + remaining: Some(Duration::from_secs(3600)), + observed_max: Some(Duration::from_secs(1)), + observed_samples: 9, + }); + assert!( + matches!(decision, DispatchDecision::RefusePaused { .. }), + "pause is a fact about intent, not an estimate — budget must not overrule it" + ); +} + +#[test] +fn refuses_when_less_remains_than_the_slowest_observed_subagent() { + // The observed run: ~26s left, children averaging ~68s. + let decision = decide(DispatchInputs { + remaining: Some(Duration::from_millis(26_375)), + observed_max: Some(Duration::from_secs(68)), + observed_samples: 17, + ..inputs() + }); + assert_eq!( + decision, + DispatchDecision::RefuseBudget { + remaining_ms: 26_375, + observed_max_ms: 68_000, + observed_samples: 17, + }, + "a dispatch that cannot fit in the remaining budget must not be attempted" + ); +} + +#[test] +fn allows_when_the_remaining_budget_still_covers_the_slowest_observed_subagent() { + let decision = decide(DispatchInputs { + remaining: Some(Duration::from_secs(300)), + observed_max: Some(Duration::from_secs(68)), + observed_samples: 17, + ..inputs() + }); + assert_eq!(decision, DispatchDecision::Allow); +} + +#[test] +fn allows_on_the_exact_boundary() { + // `remaining == observed_max` is not evidence the dispatch cannot finish, + // so the guard must not refuse it. Only a strict shortfall refuses. + let decision = decide(DispatchInputs { + remaining: Some(Duration::from_secs(68)), + observed_max: Some(Duration::from_secs(68)), + observed_samples: 2, + ..inputs() + }); + assert_eq!(decision, DispatchDecision::Allow); +} + +#[test] +fn allows_the_first_dispatch_however_little_budget_remains() { + // No sub-agent has completed, so there is no sample to judge against and + // the guard has no evidence. Refusing here would be a guess, and would + // break every short turn that delegates exactly once. + let decision = decide(DispatchInputs { + remaining: Some(Duration::from_millis(1)), + observed_max: None, + observed_samples: 0, + ..inputs() + }); + assert_eq!(decision, DispatchDecision::Allow); +} + +#[test] +fn allows_when_the_wall_clock_ceiling_is_disabled() { + // `OPENHUMAN_AGENT_TURN_TIMEOUT_SECS=0` → no ceiling → nothing can run out. + let decision = decide(DispatchInputs { + remaining: None, + observed_max: Some(Duration::from_secs(600)), + observed_samples: 40, + ..inputs() + }); + assert_eq!(decision, DispatchDecision::Allow); +} + +#[test] +fn the_budget_rule_is_scale_free() { + // Same rule, three orders of magnitude apart and at both fan-out extremes: + // the decision depends only on remaining-vs-observed, never on how many + // children have run or how long they took in absolute terms. + let fast_small = decide(DispatchInputs { + remaining: Some(Duration::from_millis(40)), + observed_max: Some(Duration::from_millis(50)), + observed_samples: 3, + ..inputs() + }); + let slow_large = decide(DispatchInputs { + remaining: Some(Duration::from_secs(40)), + observed_max: Some(Duration::from_secs(50)), + observed_samples: 300, + ..inputs() + }); + assert!(matches!(fast_small, DispatchDecision::RefuseBudget { .. })); + assert!(matches!(slow_large, DispatchDecision::RefuseBudget { .. })); +} + +#[tokio::test] +async fn no_guard_outside_a_turn_scope() { + assert!(current().is_none()); + assert_eq!( + check(), + DispatchDecision::Allow, + "an absent guard must restore the previous behaviour exactly" + ); + // Must not panic when there is nothing to record into. + record_subagent_elapsed(Duration::from_secs(1)); +} + +#[tokio::test] +async fn pause_recorded_through_the_shared_handle_is_visible_to_the_dispatch_check() { + // This is the wiring the fix depends on: the cap-pause listener holds a + // clone of the same `Arc` and writes through it, while the sub-agent + // runner reads the task-local. Both must see one state. + with_dispatch_guard(Some(Duration::from_secs(600)), async { + assert_eq!(check(), DispatchDecision::Allow); + + let state = current().expect("guard installed"); + state.record_pause_requested(15, 15); + + assert_eq!( + check(), + DispatchDecision::RefusePaused { + completed_model_calls: 15, + cap: 15, + }, + "the runner must observe a pause the listener recorded" + ); + }) + .await; +} + +#[tokio::test] +async fn observed_durations_accumulate_as_a_running_maximum() { + with_dispatch_guard(Some(Duration::from_secs(600)), async { + record_subagent_elapsed(Duration::from_secs(5)); + record_subagent_elapsed(Duration::from_secs(90)); + record_subagent_elapsed(Duration::from_secs(30)); + + // Read the real recorded state, not a hand-built copy of it: the claim + // under test is that `record_subagent_elapsed` keeps the maximum + // rather than the mean or the most recent value. + let snapshot = current().expect("guard installed").snapshot(); + assert_eq!( + snapshot.observed_max, + Some(Duration::from_secs(90)), + "the running maximum must survive a later, shorter sub-agent" + ); + assert_eq!(snapshot.observed_samples, 3); + }) + .await; +} + +#[tokio::test] +async fn the_remaining_budget_is_measured_from_the_scope_and_shrinks() { + with_dispatch_guard(Some(Duration::from_millis(400)), async { + let state = current().expect("guard installed"); + let before = state.snapshot().remaining.expect("a ceiling is configured"); + tokio::time::sleep(Duration::from_millis(60)).await; + let after = state.snapshot().remaining.expect("a ceiling is configured"); + assert!( + after < before, + "remaining budget must shrink with elapsed wall-clock ({after:?} !< {before:?})" + ); + + // With a sample longer than the whole ceiling, the guard now has + // positive evidence and must refuse. + record_subagent_elapsed(Duration::from_secs(60)); + assert!( + matches!(check(), DispatchDecision::RefuseBudget { .. }), + "a sub-agent longer than the entire remaining budget must block dispatch" + ); + }) + .await; +} + +#[tokio::test] +async fn the_guard_does_not_leak_into_a_detached_task() { + // Background sub-agents run on tasks that do not inherit the task-local, + // deliberately — same rule as the usage collector. They must degrade to + // "allow", not panic. + with_dispatch_guard(Some(Duration::from_secs(600)), async { + current() + .expect("guard installed") + .record_pause_requested(1, 1); + let detached = tokio::spawn(async { check() }); + assert_eq!( + detached.await.expect("task joined"), + DispatchDecision::Allow, + "a detached task sees no guard and must behave as it did before" + ); + }) + .await; +} + +#[tokio::test] +async fn concurrent_same_task_dispatches_share_one_guard() { + // `spawn_parallel_agents` fans out through `map_reduce`, which bounds + // concurrency with `futures`' `buffer_unordered` rather than + // `tokio::spawn` — so every parallel worker is polled on the caller's task + // and inherits this task-local. `tokio::join!` has the same property, and + // this pins the consequence: concurrency does not bypass the gate, and the + // sample one worker records is visible to the next worker's check. + with_dispatch_guard(Some(Duration::from_millis(50)), async { + // Order matters, and getting it wrong here is what an earlier revision + // of this test did: it recorded the 60s sample *before* its own + // `check()`, so the first worker judged itself against a duration it + // had just written and the `Allow` assertion could never hold. A worker + // checks on the way in and records on the way out — mirror that. + let a = async { + let decision = check(); + record_subagent_elapsed(Duration::from_secs(60)); + decision + }; + let b = async { + tokio::time::sleep(Duration::from_millis(60)).await; + check() + }; + let (first, second) = tokio::join!(a, b); + + // The first worker had no sample of its own to judge against yet. + assert_eq!(first, DispatchDecision::Allow); + // The second sees the first's sample through the shared guard, and the + // budget is gone — exactly the refusal a serial run would produce. + assert!( + matches!(second, DispatchDecision::RefuseBudget { .. }), + "a concurrently-polled dispatch must see the shared guard, not a fresh one: {second:?}" + ); + }) + .await; +} + +#[tokio::test] +async fn a_parallel_batch_with_no_samples_is_never_refused() { + // The other direction, and the one that matters for throughput: the FIRST + // parallel batch has no completed sub-agent to learn from, so however many + // workers it fans out to and however little budget is left, none of them + // may be refused. A guard that blocked the opening fan-out would break + // every parallel task rather than fixing one. + with_dispatch_guard(Some(Duration::from_millis(1)), async { + tokio::time::sleep(Duration::from_millis(5)).await; + let worker = || async { check() }; + let decisions = tokio::join!(worker(), worker(), worker(), worker(), worker()); + let all = [ + decisions.0, + decisions.1, + decisions.2, + decisions.3, + decisions.4, + ]; + assert!( + all.iter().all(|d| *d == DispatchDecision::Allow), + "an opening fan-out has no evidence against it and must proceed: {all:?}" + ); + }) + .await; +} diff --git a/src/openhuman/agent/tinyagents/mod.rs b/src/openhuman/agent/tinyagents/mod.rs index 552c58aebb..ba9f8a12ad 100644 --- a/src/openhuman/agent/tinyagents/mod.rs +++ b/src/openhuman/agent/tinyagents/mod.rs @@ -164,7 +164,7 @@ const DEFAULT_AGENT_TURN_TIMEOUT_SECS: u64 = 600; /// [`DEFAULT_AGENT_TURN_TIMEOUT_SECS`]); `0` means "no ceiling" → `None`, which /// restores the previous unbounded behavior for callers that deliberately opt /// out (e.g. very long autonomous runs). -fn agent_turn_wall_clock_ms() -> Option { +pub(crate) fn agent_turn_wall_clock_ms() -> Option { parse_agent_turn_wall_clock_ms( std::env::var("OPENHUMAN_AGENT_TURN_TIMEOUT_SECS") .ok() @@ -777,9 +777,33 @@ pub(crate) async fn run_turn_via_tinyagents_shared( // Cap pauser: stop gracefully at the model-call budget (returning the partial // transcript) so the caller can summarize a checkpoint instead of erroring. + // + // It is also handed the turn's dispatch guard, so the pause is *recorded* and + // not merely requested. `SteeringCommand::Pause` is advisory — honoured at the + // loop boundary — and nothing consulted it before dispatching a new sub-agent, + // so a dispatch issued in the same instant raced it and took the whole turn + // down with the run's remaining wall-clock budget (#5804). The guard is + // resolved here rather than inside the listener because this future runs on + // the turn's task, where the task-local is in scope; the listener need not. if pause_at_cap { if let (Some(events), Some(handle)) = (&events, &handle) { - events.subscribe(CapPauser::new(handle.clone(), max_iterations)); + // Only the TOP-LEVEL turn's cap pause is binding on dispatch. A + // sub-agent reaching its own model-call cap is a routine outcome — + // it summarises and hands its result back (`hit_cap`) — and the + // parent may legitimately keep delegating afterwards. Recording a + // child's cap here would stop the whole turn's fan-out on a signal + // that says nothing about the parent's budget, so `subagent_scope` + // gates it: `None` is the chat turn, `Some` is a delegated child. + // The child still gets its advisory `Pause` either way. + let dispatch_guard = subagent_scope + .is_none() + .then(crate::openhuman::agent::harness::turn_dispatch_guard::current) + .flatten(); + events.subscribe(CapPauser::new( + handle.clone(), + max_iterations, + dispatch_guard, + )); } } diff --git a/src/openhuman/agent/tinyagents/observability.rs b/src/openhuman/agent/tinyagents/observability.rs index 191a821c30..37313e3573 100644 --- a/src/openhuman/agent/tinyagents/observability.rs +++ b/src/openhuman/agent/tinyagents/observability.rs @@ -19,6 +19,7 @@ use tinyagents::harness::events::{AgentEvent, EventListener, EventRecord}; use tinyagents::harness::steering::{SteeringCommand, SteeringHandle}; use tinyagents::harness::usage::Usage; +use crate::openhuman::agent::harness::turn_dispatch_guard::TurnDispatchState; use crate::openhuman::agent::progress::AgentProgress; use crate::openhuman::inference::provider::UsageInfo; use crate::openhuman::tools::traits::humanize_tool_name; @@ -99,15 +100,26 @@ pub(crate) struct CapPauser { handle: SteeringHandle, cap: u32, completed: AtomicU32, + /// The current turn's dispatch guard, when this run is a turn (rather than + /// a CLI/direct invocation). Recording the pause here is what makes it + /// *binding* on new sub-agent dispatch instead of merely advisory — see + /// [`crate::openhuman::agent::harness::turn_dispatch_guard`] and #5804. + dispatch_guard: Option>, } impl CapPauser { - /// Pause `handle` once `cap` model calls complete. - pub(crate) fn new(handle: SteeringHandle, cap: usize) -> Arc { + /// Pause `handle` once `cap` model calls complete, recording the pause on + /// `dispatch_guard` when the run is executing inside a turn scope. + pub(crate) fn new( + handle: SteeringHandle, + cap: usize, + dispatch_guard: Option>, + ) -> Arc { Arc::new(Self { handle, cap: cap as u32, completed: AtomicU32::new(0), + dispatch_guard, }) } } @@ -122,6 +134,17 @@ impl EventListener for CapPauser { cap = self.cap, "[tinyagents] model-call cap reached — requesting graceful pause" ); + // Record BEFORE sending the advisory command. The crate drains + // its event queue synchronously, notifying listeners in + // insertion order on the emitting task + // (`vendor/tinyagents/src/harness/events/mod.rs:163-195`), so + // this store happens-before any tool call the loop dispatches + // afterwards. That ordering is the whole fix: the pause stops + // being something a dispatch can race and becomes something a + // dispatch must observe. + if let Some(guard) = self.dispatch_guard.as_ref() { + guard.record_pause_requested(u64::from(n), u64::from(self.cap)); + } self.handle.send(SteeringCommand::Pause); } } diff --git a/src/openhuman/web_chat/ops.rs b/src/openhuman/web_chat/ops.rs index 82343baece..ff3ea18e91 100644 --- a/src/openhuman/web_chat/ops.rs +++ b/src/openhuman/web_chat/ops.rs @@ -150,29 +150,69 @@ where /// Reason a terminal `run_chat_task` error should be kept OUT of Sentry, or /// `None` when it is a genuine defect that must page. /// -/// Both suppressed cases are deterministic, user-surfaced, retryable -/// agent-loop outcomes — a terminal `chat_error` already reaches the client, so -/// a Sentry event is pure noise (same tier as `MaxIterationsExceeded` / +/// A suppressed case is a deterministic, user-surfaced, retryable agent-loop +/// outcome — a terminal `chat_error` already reaches the client, so a Sentry +/// event is pure noise (same tier as `MaxIterationsExceeded` / /// `EmptyProviderResponse`, which are demoted the same way): /// /// - the max-iteration cap (`is_max_iterations_error`), and -/// - the turn wall-clock backstop / harness `Timeout` (`is_turn_timeout_error`, -/// issue #4746) — without this arm every wedged turn that trips the ceiling -/// would emit a spurious Sentry event, contradicting the graceful -/// `turn_timeout` framing. +/// - the **outer** web-turn wall-clock backstop (`is_outer_backstop_timeout`, +/// issue #4746) — the turn wedged outside the harness and produced no +/// terminal event, so without this arm every such turn would emit a spurious +/// Sentry event, contradicting the graceful `turn_timeout` framing. +/// +/// **Not suppressed: the harness's own `Timeout` (#5804).** This arm used to +/// cover both, via `is_turn_timeout_error`, because the two are hard to tell +/// apart once stringified. They are not the same event. The outer backstop +/// fires with *nothing in flight*; the harness `Timeout` fires while bounding +/// a real model or tool call, which means the run spent its budget doing work +/// — and every result that work produced is discarded along with the turn. A +/// turn that lost eighteen sub-agents' worth of accumulated work was reported +/// here as `suppressed Sentry emission for turn wall-clock backstop` and +/// reached telemetry as nothing at all, which is why the defect survived. See +/// [`is_outer_backstop_timeout`](super::web_errors::is_outer_backstop_timeout) +/// for the structural argument. +/// +/// The user-facing classification is deliberately untouched: both still render +/// the graceful `turn_timeout` copy via `is_turn_timeout_error`. Only the +/// telemetry decision splits. /// /// Kept as a pure predicate over the already-formatted error string so the /// suppression policy is unit-testable without a Sentry harness. pub(crate) fn sentry_suppression_reason(detailed: &str) -> Option<&'static str> { if crate::openhuman::agent::error::is_max_iterations_error(detailed) { Some("max-iteration cap") - } else if super::web_errors::is_turn_timeout_error(detailed) { - Some("turn wall-clock backstop") + } else if super::web_errors::is_outer_backstop_timeout(detailed) { + Some("turn wall-clock backstop (no terminal event)") } else { None } } +/// Which wall-clock bound a reported timeout hit, as a Sentry tag value. +/// +/// Only meaningful once [`sentry_suppression_reason`] has decided to report — +/// i.e. for a harness `Timeout`, never for the suppressed outer backstop. The +/// crate names the bound in the message (`RUN_BOUND_LABEL` vs +/// `PER_CALL_BOUND_LABEL`), and the two are different triage paths: a run that +/// spent its whole budget doing real work is a capacity/planning problem, while +/// one call that blew a per-call ceiling is a wedged provider. Emitting them +/// under one tag would rebuild, in the dashboard, exactly the conflation this +/// change removed from the code (#5804). +/// +/// Pure over the formatted error string, for the same reason its neighbour is. +pub(crate) fn timeout_bound_tag(detailed: &str) -> &'static str { + if detailed.contains("per-model-call ceiling") { + "per_model_call" + } else if detailed.contains("remaining wall-clock budget") { + "run_remaining" + } else if super::web_errors::is_turn_timeout_error(detailed) { + "unclassified_timeout" + } else { + "none" + } +} + /// What the budget-correlator should do with a terminated turn (#3386). #[derive(Debug, Clone, Copy, PartialEq, Eq)] pub(super) enum BudgetCorrelation { @@ -814,6 +854,10 @@ pub async fn start_chat( ("error_type", classified_type), ("thread_id", thread_id_task.as_str()), ("request_id", request_id_task.as_str()), + // Names which ceiling fired for the harness + // timeouts this arm now reports (#5804); "none" + // for every other error type. + ("timeout_bound", timeout_bound_tag(&detailed)), ], ); } @@ -988,7 +1032,54 @@ async fn spawn_parallel_turn( request_id_task, err ); + let detailed = format!( + "parallel run_chat_task failed client_id={} thread_id={} request_id={} error={}", + client_id_task, thread_id_task, request_id_task, err + ); let classified = classify_inference_error(&err); + let classified_type = classified.error_type; + + // A parallel turn runs under the same deadline wrapper as the + // serial one and dies the same way, but this branch reported + // NOTHING to Sentry — not merely the timeouts this PR + // un-suppresses, but every error type, since the parallel path + // was added. So a discarded turn was invisible here even + // before the suppression arm existed, and fixing only + // `start_chat` would have left `QueueMode::Parallel` exactly + // as blind as it was (#5804 review). + // + // Same policy as the serial site, deliberately sharing + // `sentry_suppression_reason` rather than restating it: the + // outer backstop stays suppressed, a harness `Timeout` reports + // with the ceiling that fired. + if let Some(reason) = sentry_suppression_reason(&detailed) { + log::info!( + target: "web_channel", + "[web_channel.spawn_parallel_turn] suppressed Sentry emission for {} \ + client_id={} thread_id={} request_id={} error_type={} message={}", + reason, + client_id_task, + thread_id_task, + request_id_task, + classified_type, + detailed + ); + } else { + crate::core::observability::report_error_or_expected( + detailed.as_str(), + "web_channel", + "spawn_parallel_turn", + &[ + ("channel", "web"), + ("error_type", classified_type), + ("thread_id", thread_id_task.as_str()), + ("request_id", request_id_task.as_str()), + ("queue_mode", "parallel"), + ("timeout_bound", timeout_bound_tag(&detailed)), + ], + ); + } + publish_web_channel_event(WebChannelEvent { event: "chat_error".to_string(), client_id: client_id_task.clone(), diff --git a/src/openhuman/web_chat/web_errors.rs b/src/openhuman/web_chat/web_errors.rs index 36daf15ebf..12e9640bdf 100644 --- a/src/openhuman/web_chat/web_errors.rs +++ b/src/openhuman/web_chat/web_errors.rs @@ -82,6 +82,34 @@ pub(crate) fn is_turn_timeout_error(err: &str) -> bool { || err.contains("exceeded its wall-clock deadline") } +/// True when `err` is the **outer** web-turn backstop firing — +/// [`TURN_TIMEOUT_MARKER`], raised by [`drive_turn_with_deadline`] — as opposed +/// to the harness's own `Timeout`. +/// +/// The two are structurally different events and only look alike once +/// stringified, which is why they were treated alike and why one of them went +/// unnoticed for as long as it did (#5804): +/// +/// * The marker is raised when the turn future produced **no terminal event at +/// all** inside the channel's ceiling. By construction nothing was completing +/// — the turn wedged outside the harness run (session assembly, persistence +/// plumbing). There is no in-flight work to report and the user already has a +/// graceful `turn_timeout`, so a Sentry event would be noise. +/// +/// * The harness `Timeout` is raised while bounding a **real, in-flight model +/// or tool call** against the run's remaining wall-clock budget. Reaching it +/// means the run consumed its budget doing work, and everything that work +/// produced is discarded with the turn. That is a defect signal, and +/// suppressing it is what made the discarded-turn failure invisible. +/// +/// Used only for the Sentry suppression decision. [`is_turn_timeout_error`] +/// still covers both for the *user-facing* classification, which is unchanged: +/// either way the turn ran out of time and the graceful `turn_timeout` copy is +/// the right thing to show. +pub(crate) fn is_outer_backstop_timeout(err: &str) -> bool { + err.contains(TURN_TIMEOUT_MARKER) +} + /// Pull the structured provider error message out of a raw error string. /// /// Provider error chains from OpenAI/Anthropic/OpenRouter/etc. arrive looking diff --git a/src/openhuman/web_chat/web_tests.rs b/src/openhuman/web_chat/web_tests.rs index 0e43b0e9f1..02ddd3bf88 100644 --- a/src/openhuman/web_chat/web_tests.rs +++ b/src/openhuman/web_chat/web_tests.rs @@ -592,30 +592,22 @@ fn classify_inference_error_harness_wall_clock_timeout_is_turn_timeout() { } #[test] -fn turn_timeout_error_is_suppressed_from_sentry() { - // Issue #4746 (maintainer review): a wedged turn that trips the wall-clock - // ceiling is a deterministic, user-surfaced, retryable outcome — the client - // already gets a graceful `turn_timeout` chat_error, so it must NOT page - // Sentry (same tier as the max-iteration cap). `run_chat_task`'s emit site - // gates on `sentry_suppression_reason`; assert both the synthetic backstop - // marker and the harness `Timeout` renderings are suppressed, while a - // genuine provider defect still reports. +fn outer_backstop_timeout_is_suppressed_from_sentry() { + // Issue #4746 (maintainer review): the OUTER web-turn backstop fires when a + // turn wedges outside the harness and produces no terminal event at all. + // The client already gets a graceful `turn_timeout` chat_error and there is + // no in-flight work to report, so it must NOT page Sentry (same tier as the + // max-iteration cap). `run_chat_task`'s emit site gates on + // `sentry_suppression_reason`. let detailed_marker = format!( "run_chat_task failed client_id=c thread_id=t request_id=r error={}", super::web_errors::turn_timeout_error_message(600) ); assert_eq!( sentry_suppression_reason(&detailed_marker), - Some("turn wall-clock backstop"), + Some("turn wall-clock backstop (no terminal event)"), "the synthetic backstop marker must suppress the Sentry emit" ); - assert_eq!( - sentry_suppression_reason( - "run timed out: model call for run `abc` exceeded its remaining wall-clock budget (600000 ms)" - ), - Some("turn wall-clock backstop"), - "the harness Timeout rendering must suppress the Sentry emit" - ); // A real provider defect is NOT a deterministic agent-loop outcome and must // still page. assert_eq!( @@ -625,6 +617,65 @@ fn turn_timeout_error_is_suppressed_from_sentry() { ); } +#[test] +fn harness_timeout_with_work_in_flight_is_reported_to_sentry() { + // Issue #5804. The harness `Timeout` used to be suppressed by the same arm + // as the outer backstop, so a turn that burned its whole wall-clock budget + // doing real work — and discarded every result when it died — reached + // telemetry as nothing at all. That is what kept the discarded-turn defect + // invisible. The harness only raises this while bounding an in-flight model + // or tool call, so by construction work was in flight and it must page. + assert_eq!( + sentry_suppression_reason( + "run timed out: tool call for run `agent_turn` exceeded its remaining wall-clock budget (26375 ms)" + ), + None, + "a harness timeout with work in flight must reach Sentry" + ); + assert_eq!( + sentry_suppression_reason( + "run timed out: model call for run `abc` exceeded its per-model-call ceiling (120000 ms)" + ), + None, + "a per-model-call ceiling breach must reach Sentry" + ); +} + +#[test] +fn timeout_bound_tag_separates_the_two_harness_ceilings() { + // The two ceilings are different triage paths: a run that spent its whole + // budget on real work vs one call wedged against its own ceiling. Tagging + // them alike would rebuild the conflation in the dashboard (#5804). + assert_eq!( + super::ops::timeout_bound_tag( + "run timed out: tool call for run `agent_turn` exceeded its remaining wall-clock budget (26375 ms)" + ), + "run_remaining" + ); + assert_eq!( + super::ops::timeout_bound_tag( + "run timed out: model call for run `abc` exceeded its per-model-call ceiling (120000 ms)" + ), + "per_model_call" + ); + assert_eq!( + super::ops::timeout_bound_tag("openrouter API error (500 Internal Server Error)"), + "none", + "a non-timeout error must not carry a timeout bound" + ); +} + +#[test] +fn both_timeout_shapes_still_render_the_same_user_facing_copy() { + // The telemetry split must not change what the user sees: either way the + // turn ran out of time and the graceful `turn_timeout` copy is correct. + let marker = super::web_errors::turn_timeout_error_message(600); + let harness = + "run timed out: tool call for run `agent_turn` exceeded its remaining wall-clock budget (26375 ms)"; + assert_eq!(classify_inference_error(&marker).error_type, "turn_timeout"); + assert_eq!(classify_inference_error(harness).error_type, "turn_timeout"); +} + #[test] fn classify_inference_error_rate_limited_surfaces_retry_after_seconds() { let raw = "openrouter API error (429 Too Many Requests): Retry-After: 30";