fix: three things that were known and written nowhere
All three have the same shape — the system learns something and only stderr
hears it — and each was flagged in the handoff as a silent-discard defect.
The gate's install outcome. `container_tool_hooks::install` returned Some or
None and both call sites wrote `let _ =`. A mission whose gate never installed
left a record indistinguishable from one whose gate stood there and matched
nothing. `EnsuredContainer` now carries the outcome to the callers that have a
pool, and they record `gate.installed` (with the settings path) or
`gate.absent` on the mission, so "was this mission gated?" is answerable from
the mission.
The inert marker. `vm_tool_gate` writes an `inert` file when it cannot parse
its input and allows everything, precisely so an inert gate does not look like
a permissive one. The only reader was a unit test. `drain_inert` now reads and
clears it at every tap drain, and a `gate.inert` event with the occurrence count
lands beside the calls that ran unchecked.
The judge's spend. `LlmEvent::Usage` arrived on every judge call and was
matched by `Ok(_) => {}`. Two plan exhaustions (2026-08-29, 2026-09-09) with
no row anywhere saying a judge token had been spent; `usage_events` had no
provider or model column. The loop now accumulates requests and tokens onto the
Verdict — counting a request BEFORE the stream opens, so a 429 the provider
refused still counts, because the retry storm was made of those — and
`record` writes a `kind = 'judge'` row with provider, model, mission and
request count. Migration 0085 adds the columns, all nullable, so the two
existing writers are untouched.
Tests: a scripted-provider verdict records one request and nonzero tokens; a
provider that refuses still records the request and zero tokens.
Co-Authored-By: Claude Opus 5 <[email protected]>
Claude-Session: https://claude.ai/code/session_01WZb5A2kfVfjpdwSochkuHz
This commit is contained in:
co-authored by
Claude Opus 5
parent
758760cedb
commit
248948cc84
@@ -175,6 +175,65 @@ pub async fn install_door(docker: &Docker, container: &str, doc: &serde_json::Va
|
||||
}
|
||||
}
|
||||
|
||||
/// Event kinds under which the gate's own state lands in the mission record.
|
||||
///
|
||||
/// Recorded, not only logged, so "was this mission gated?" is answerable from
|
||||
/// the mission afterwards. Stderr is where the answer used to go, which is the
|
||||
/// same place as nowhere once the container that printed it is gone.
|
||||
pub const GATE_INSTALLED: &str = "gate.installed";
|
||||
pub const GATE_ABSENT: &str = "gate.absent";
|
||||
/// The gate ran but could not parse its input and allowed everything. See
|
||||
/// [`crate::vm_tool_gate::INERT_FILE`] — this is the reader that marker was
|
||||
/// missing in production; until now only a unit test looked for it.
|
||||
pub const GATE_INERT: &str = "gate.inert";
|
||||
|
||||
/// Write the install outcome into the mission record.
|
||||
pub async fn record_install(
|
||||
pool: &sqlx::PgPool,
|
||||
mission_id: uuid::Uuid,
|
||||
phase_id: Option<uuid::Uuid>,
|
||||
hooks: Option<&str>,
|
||||
) {
|
||||
let mut e = match hooks {
|
||||
Some(path) => crate::mission_events::MissionEvent::new(mission_id, GATE_INSTALLED)
|
||||
.target(path)
|
||||
.detail(serde_json::json!({ "settings": path, "tap": tap_file() })),
|
||||
None => crate::mission_events::MissionEvent::new(mission_id, GATE_ABSENT).detail(
|
||||
serde_json::json!({
|
||||
"why": "container_tool_hooks::install failed — this mission's tool \
|
||||
calls run unchecked and unrecorded"
|
||||
}),
|
||||
),
|
||||
};
|
||||
if let Some(p) = phase_id {
|
||||
e = e.phase(p);
|
||||
}
|
||||
crate::mission_events::record(pool, e).await;
|
||||
}
|
||||
|
||||
/// The inert marker's path inside the container.
|
||||
pub fn inert_file() -> String {
|
||||
format!("{HOOK_DIR}/{}", crate::vm_tool_gate::INERT_FILE)
|
||||
}
|
||||
|
||||
/// Did the gate go inert since the last drain? Reads the marker and clears
|
||||
/// it, so each occurrence is reported once.
|
||||
///
|
||||
/// `Some(text)` is the marker's contents — every line the gate appended while
|
||||
/// it could not parse. `None` is "the marker is not there", which is the
|
||||
/// normal case and also, by construction, the only case that means the gate
|
||||
/// was actually checking.
|
||||
pub async fn drain_inert(docker: &Docker, container: &str) -> Option<String> {
|
||||
let file = inert_file();
|
||||
let script = format!("cat {file} 2>/dev/null && rm -f {file} 2>/dev/null; true");
|
||||
let argv = vec!["sh".to_string(), "-lc".to_string(), script];
|
||||
match crate::container_exec::exec_as_root(docker, container, None, &argv, INSTALL_TIMEOUT).await
|
||||
{
|
||||
Ok(out) if !out.stdout.trim().is_empty() => Some(out.stdout.trim().to_string()),
|
||||
_ => None,
|
||||
}
|
||||
}
|
||||
|
||||
/// The tap file inside the mission container.
|
||||
pub fn tap_file() -> String {
|
||||
format!("{TAP_DIR}/tools.jsonl")
|
||||
|
||||
@@ -33,6 +33,22 @@ use serde_json::Value;
|
||||
use uuid::Uuid;
|
||||
|
||||
/// The model's verdict on one pass.
|
||||
/// What one verdict cost, in provider calls and tokens.
|
||||
///
|
||||
/// Accumulated across every round of the judge's tool loop, and kept on a
|
||||
/// FAILED attempt too — that is the case that matters. `LlmEvent::Usage` was
|
||||
/// arriving on every call and being dropped on the floor (`Ok(_) => {}`), so
|
||||
/// the z.ai plan emptied twice with nothing anywhere recording a single judge
|
||||
/// token. `usage_events` had no provider or model column; the first signal
|
||||
/// was every mission failing at once.
|
||||
#[derive(Debug, Clone, Copy, Default, PartialEq, Eq, Serialize, Deserialize)]
|
||||
pub struct Usage {
|
||||
/// Model requests made. One verdict is up to `MAX_TOOL_CALLS + 1` of these.
|
||||
pub requests: u32,
|
||||
pub tokens_in: u64,
|
||||
pub tokens_out: u64,
|
||||
}
|
||||
|
||||
#[derive(Debug, Clone, Serialize, Deserialize)]
|
||||
pub struct Verdict {
|
||||
pub met: bool,
|
||||
@@ -66,6 +82,9 @@ pub struct Verdict {
|
||||
/// read back as "not independent", which is what they were.
|
||||
#[serde(default)]
|
||||
pub independent: bool,
|
||||
/// What this attempt cost. Recorded to `usage_events` by [`record`].
|
||||
#[serde(default)]
|
||||
pub usage: Usage,
|
||||
}
|
||||
|
||||
impl Verdict {
|
||||
@@ -92,6 +111,7 @@ impl Verdict {
|
||||
independent: false,
|
||||
error,
|
||||
checks: Vec::new(),
|
||||
usage: Usage::default(),
|
||||
}
|
||||
}
|
||||
}
|
||||
@@ -464,12 +484,23 @@ pub async fn evaluate(
|
||||
model,
|
||||
provider_family(&model)
|
||||
);
|
||||
match judge_with_tools(provider.as_ref(), &system, &user, &model, sandbox.as_ref()).await {
|
||||
let mut usage = Usage::default();
|
||||
match judge_with_tools(
|
||||
provider.as_ref(),
|
||||
&system,
|
||||
&user,
|
||||
&model,
|
||||
sandbox.as_ref(),
|
||||
&mut usage,
|
||||
)
|
||||
.await
|
||||
{
|
||||
Ok((text, checks)) => {
|
||||
let mut v = parse_verdict(&model, &text);
|
||||
v.guidance = sanitize_guidance(condition, evidence, &v.guidance);
|
||||
v.checks = checks;
|
||||
v.independent = true;
|
||||
v.usage = usage;
|
||||
return v;
|
||||
}
|
||||
// Deliberately NOT a silent fall-through to the house judge. An
|
||||
@@ -481,11 +512,13 @@ pub async fn evaluate(
|
||||
eprintln!(
|
||||
"evaluator: the independent judge ({model}) failed — NOT falling back to the agent's own provider: {e}"
|
||||
);
|
||||
return Verdict::not_met(
|
||||
let mut v = Verdict::not_met(
|
||||
&model,
|
||||
"the independent validator could not be reached this pass",
|
||||
Some(e),
|
||||
);
|
||||
v.usage = usage;
|
||||
return v;
|
||||
}
|
||||
}
|
||||
}
|
||||
@@ -498,9 +531,12 @@ pub async fn evaluate(
|
||||
Some(_) => format!("{EVAL_SYSTEM_VERIFYING}\n\n{VERDICT_CONTRACT}"),
|
||||
None => format!("{EVAL_SYSTEM_EVIDENCE_ONLY}\n\n{VERDICT_CONTRACT}"),
|
||||
};
|
||||
let outcome = judge_with_tools(&provider, &system, &user, &model, sandbox.as_ref()).await;
|
||||
let mut usage = Usage::default();
|
||||
let outcome =
|
||||
judge_with_tools(&provider, &system, &user, &model, sandbox.as_ref(), &mut usage)
|
||||
.await;
|
||||
// Same family as the agent; `independent` stays false below.
|
||||
return match outcome {
|
||||
let mut v = match outcome {
|
||||
Err(e) => Verdict::not_met(
|
||||
&model,
|
||||
"could not evaluate the completion condition this pass",
|
||||
@@ -513,6 +549,8 @@ pub async fn evaluate(
|
||||
v
|
||||
}
|
||||
};
|
||||
v.usage = usage;
|
||||
return v;
|
||||
}
|
||||
|
||||
// Fallback paths have no tool loop, so they judge claims only and must say so.
|
||||
@@ -604,6 +642,7 @@ async fn judge_with_tools(
|
||||
user: &str,
|
||||
model: &str,
|
||||
sandbox: Option<&crate::evaluator_tools::Sandbox>,
|
||||
usage: &mut Usage,
|
||||
) -> Result<(String, Vec<crate::evaluator_tools::CheckOutcome>), String> {
|
||||
use cm_llm::{ChatMessage, ChatRequest, ChatRole, ContentPart, LlmEvent};
|
||||
use futures::StreamExt as _;
|
||||
@@ -643,6 +682,10 @@ async fn judge_with_tools(
|
||||
max_tokens: 16384,
|
||||
web_search: false,
|
||||
};
|
||||
// Counted BEFORE the stream is opened: a request the provider refused
|
||||
// with a 429 is still a request we made, and the storm of those is the
|
||||
// thing this accounting exists to make visible.
|
||||
usage.requests += 1;
|
||||
let mut stream = provider.stream(request).await.map_err(|e| e.to_string())?;
|
||||
let mut text = String::new();
|
||||
let mut calls: Vec<(String, String, Value)> = Vec::new();
|
||||
@@ -650,6 +693,10 @@ async fn judge_with_tools(
|
||||
match event {
|
||||
Ok(LlmEvent::TextDelta(t)) => text.push_str(&t),
|
||||
Ok(LlmEvent::ToolUse { id, name, input }) => calls.push((id, name, input)),
|
||||
Ok(LlmEvent::Usage { input_tokens, output_tokens }) => {
|
||||
usage.tokens_in += u64::from(input_tokens);
|
||||
usage.tokens_out += u64::from(output_tokens);
|
||||
}
|
||||
Ok(_) => {}
|
||||
Err(e) => return Err(e.to_string()),
|
||||
}
|
||||
@@ -778,6 +825,7 @@ fn parse_verdict(model: &str, text: &str) -> Verdict {
|
||||
independent: false,
|
||||
error: None,
|
||||
checks: Vec::new(),
|
||||
usage: Usage::default(),
|
||||
}
|
||||
}
|
||||
|
||||
@@ -821,8 +869,30 @@ pub async fn record(
|
||||
.bind(serde_json::json!(v.checks))
|
||||
.bind(v.independent)
|
||||
.execute(pool)
|
||||
.await
|
||||
.map(|_| ())
|
||||
.await?;
|
||||
|
||||
// The judge's spend, beside the verdict it bought. `kind = 'judge'` keeps
|
||||
// it apart from the agents' `llm_tokens`, and `provider` is what makes a
|
||||
// plan-limit question answerable before the plan answers it for you.
|
||||
// Recorded for a failed attempt too: `requests` on those is the number
|
||||
// that emptied the plan.
|
||||
if v.usage.requests > 0 {
|
||||
sqlx::query(
|
||||
"INSERT INTO usage_events
|
||||
(workspace_id, kind, tokens_in, tokens_out, provider, model, mission_id, requests)
|
||||
SELECT workspace_id, 'judge', $2, $3, $4, $5, id, $6
|
||||
FROM missions WHERE id = $1",
|
||||
)
|
||||
.bind(mission_id)
|
||||
.bind(v.usage.tokens_in as i64)
|
||||
.bind(v.usage.tokens_out as i64)
|
||||
.bind(provider_family(&v.model))
|
||||
.bind(&v.model)
|
||||
.bind(v.usage.requests as i32)
|
||||
.execute(pool)
|
||||
.await?;
|
||||
}
|
||||
Ok(())
|
||||
}
|
||||
|
||||
/// The most recent verdict for a phase, used to carry guidance into the next
|
||||
@@ -855,6 +925,41 @@ pub async fn latest(
|
||||
|
||||
#[cfg(test)]
|
||||
mod cross_provider_tests {
|
||||
/// `LlmEvent::Usage` arrives on every provider call. It was matched by
|
||||
/// `Ok(_) => {}` and dropped, which is how two plan exhaustions happened
|
||||
/// with no row anywhere saying a judge token was spent.
|
||||
#[tokio::test]
|
||||
async fn a_verdict_records_what_it_cost() {
|
||||
let provider = cm_llm::ScriptedProvider::from_toml("").expect("empty scenario file");
|
||||
let mut usage = Usage::default();
|
||||
let out = judge_with_tools(&provider, "system", "judge this", "scripted:echo", None, &mut usage)
|
||||
.await
|
||||
.expect("the echo provider answers");
|
||||
assert!(!out.0.is_empty());
|
||||
assert_eq!(usage.requests, 1, "one round, no tool calls, one request");
|
||||
assert!(usage.tokens_in > 0 && usage.tokens_out > 0, "{usage:?}");
|
||||
}
|
||||
|
||||
/// The count is what the plan limit sees, so it must include the request
|
||||
/// that failed — the retry storm was made of those.
|
||||
#[tokio::test]
|
||||
async fn a_refused_request_still_counts() {
|
||||
struct Refuses;
|
||||
#[async_trait::async_trait]
|
||||
impl cm_llm::LlmProvider for Refuses {
|
||||
async fn stream(&self, _: cm_llm::ChatRequest) -> Result<cm_llm::EventStream, cm_llm::LlmError> {
|
||||
Err(cm_llm::LlmError::Scenario("429 Too Many Requests".into()))
|
||||
}
|
||||
}
|
||||
let mut usage = Usage::default();
|
||||
let err = judge_with_tools(&Refuses, "s", "u", "glm:glm-5.3", None, &mut usage)
|
||||
.await
|
||||
.expect_err("refused");
|
||||
assert!(err.contains("429"), "{err}");
|
||||
assert_eq!(usage.requests, 1);
|
||||
assert_eq!((usage.tokens_in, usage.tokens_out), (0, 0));
|
||||
}
|
||||
|
||||
use super::*;
|
||||
|
||||
/// A bare model name must never be accepted as a validator spec.
|
||||
|
||||
@@ -170,6 +170,13 @@ pub async fn on_launch(
|
||||
match prov.ensure_container(mission_id).await {
|
||||
Ok(ec) => {
|
||||
mission_gateway = Some(ec.endpoint.clone());
|
||||
crate::container_tool_hooks::record_install(
|
||||
pool,
|
||||
mission_id,
|
||||
None,
|
||||
ec.hooks.as_deref(),
|
||||
)
|
||||
.await;
|
||||
let container_name = crate::mission_runtime::container_name(mission_id);
|
||||
if let Err(e) = cm_db::repo::missions::set_runtime_binding(
|
||||
pool,
|
||||
|
||||
@@ -558,6 +558,14 @@ pub struct MissionRuntimeProvisioner {
|
||||
#[derive(Debug, Clone)]
|
||||
pub struct EnsuredContainer {
|
||||
pub endpoint: String,
|
||||
/// Where the tool hooks were written, or `None` if installing them failed.
|
||||
///
|
||||
/// Carried out to the caller rather than only logged, because the caller
|
||||
/// has the pool and this struct's producer does not. Before this field
|
||||
/// the outcome went to stderr and nowhere else, so a mission whose gate
|
||||
/// never installed left a record indistinguishable from one whose gate
|
||||
/// stood there all night and matched nothing.
|
||||
pub hooks: Option<String>,
|
||||
/// One-time pairing code minted by the daemon at boot; may be
|
||||
/// None on the reuse-existing path when we couldn't scrape it
|
||||
/// back (log rotation). Callers keep the previously-persisted
|
||||
@@ -628,11 +636,12 @@ impl MissionRuntimeProvisioner {
|
||||
// Re-install on reuse: the container outlives the server
|
||||
// process, and a hook that exists only on first creation is a
|
||||
// hook that quietly disappears after a redeploy.
|
||||
let _ = crate::container_tool_hooks::install(&self.docker, &name).await;
|
||||
let hooks = crate::container_tool_hooks::install(&self.docker, &name).await;
|
||||
let pairing_code = self.mint_pairing_code(&name).await;
|
||||
return Ok(EnsuredContainer {
|
||||
endpoint: endpoint_url(&name),
|
||||
pairing_code,
|
||||
hooks,
|
||||
});
|
||||
}
|
||||
// Exists but not running — remove + recreate below rather
|
||||
@@ -842,11 +851,12 @@ impl MissionRuntimeProvisioner {
|
||||
// Gate and observe the tools claude runs inside its own subprocess.
|
||||
// Best-effort by design: a phase that runs unhooked still delivers, and
|
||||
// failing the launch to protect telemetry would be the wrong trade.
|
||||
let _ = crate::container_tool_hooks::install(&self.docker, &name).await;
|
||||
let hooks = crate::container_tool_hooks::install(&self.docker, &name).await;
|
||||
|
||||
Ok(EnsuredContainer {
|
||||
endpoint: endpoint_url(&name),
|
||||
pairing_code,
|
||||
hooks,
|
||||
})
|
||||
}
|
||||
|
||||
|
||||
@@ -630,6 +630,27 @@ async fn drain_finished_container_phases(pool: &PgPool) -> Result<(), String> {
|
||||
return Ok(());
|
||||
}
|
||||
};
|
||||
// The gate's own confession, before its tool calls: if it could not
|
||||
// parse and allowed everything, every call drained below ran unchecked
|
||||
// — and until this read existed, the marker it left saying so was seen
|
||||
// by exactly one unit test and no production code.
|
||||
if let Some(text) = crate::container_tool_hooks::drain_inert(&docker, &container).await {
|
||||
let lines = text.lines().count();
|
||||
eprintln!(
|
||||
"phase_runner: the tool gate in {container} went INERT {lines} time(s) \
|
||||
during phase {phase_id} — those calls were allowed unchecked"
|
||||
);
|
||||
crate::mission_events::record(
|
||||
pool,
|
||||
crate::mission_events::MissionEvent::new(
|
||||
mission_id,
|
||||
crate::container_tool_hooks::GATE_INERT,
|
||||
)
|
||||
.phase(phase_id)
|
||||
.detail(serde_json::json!({ "occurrences": lines, "marker": text })),
|
||||
)
|
||||
.await;
|
||||
}
|
||||
let tools = crate::container_tool_hooks::drain(&docker, &container).await;
|
||||
if tools.is_empty() {
|
||||
continue;
|
||||
@@ -1053,6 +1074,13 @@ async fn launch_phase(
|
||||
match prov.ensure_container(mission_id).await {
|
||||
Ok(ec) => {
|
||||
let name = crate::mission_runtime::container_name(mission_id);
|
||||
crate::container_tool_hooks::record_install(
|
||||
pool,
|
||||
mission_id,
|
||||
Some(phase_id),
|
||||
ec.hooks.as_deref(),
|
||||
)
|
||||
.await;
|
||||
// Push the checkout into the container. A no-op in bind mode;
|
||||
// in copy mode it is how the agent gets the code at all, so a
|
||||
// failure must fail the launch rather than silently starting a
|
||||
|
||||
@@ -279,6 +279,7 @@ async fn evaluations_are_unique_per_iteration_and_upsert() {
|
||||
error: None,
|
||||
checks: Vec::new(),
|
||||
independent: false,
|
||||
usage: Default::default(),
|
||||
};
|
||||
cm_api::evaluator::record(&pool, mission, phase, 0, &first)
|
||||
.await
|
||||
@@ -298,6 +299,7 @@ async fn evaluations_are_unique_per_iteration_and_upsert() {
|
||||
evidence: "exit status: 0".into(),
|
||||
}],
|
||||
independent: false,
|
||||
usage: Default::default(),
|
||||
};
|
||||
cm_api::evaluator::record(&pool, mission, phase, 0, &second)
|
||||
.await
|
||||
@@ -356,6 +358,7 @@ async fn latest_returns_the_most_recent_iteration() {
|
||||
error: None,
|
||||
checks: Vec::new(),
|
||||
independent: false,
|
||||
usage: Default::default(),
|
||||
},
|
||||
)
|
||||
.await
|
||||
|
||||
Reference in New Issue
Block a user