diff --git a/docs/p1-continuation-diagnostics.md b/docs/p1-continuation-diagnostics.md new file mode 100644 index 0000000..eeac1f5 --- /dev/null +++ b/docs/p1-continuation-diagnostics.md @@ -0,0 +1,37 @@ +# P1 continuation diagnostics + +## Scope + +This document records the diagnostic events added around Codex tool-result continuation and state replay. + +The change is logging-only. It does not change protocol conversion, state lookup rules, fallback behavior, or Responses output shape. + +## Events + +| Event | Level | Location | Meaning | +|---|---:|---|---| +| `stored_response_not_found` | warn | `StateStore::get` | A requested `previous_response_id` was not found in non-expired state. The log includes `response_id` and TTL cutoff. | +| `tool_history_unique_fallback_hit` | debug | `StateStore::find_by_call_ids` | No `previous_response_id` was available, but the adapter restored continuation via a unique pending `call_id` match. The log includes the restored `response_id`, requested call IDs, and stored pending call IDs. | +| `tool_history_call_id_ambiguous` | warn | `StateStore::find_by_call_ids` | The same requested `call_id` matched multiple stored responses. The log includes both candidate response IDs and `candidate_count = 2`. | +| `tool_history_response_ambiguous` | warn | `StateStore::find_by_call_ids` | The requested call-id set matched multiple stored responses. The log includes both candidate response IDs and `candidate_count = 2`. | +| `tool_history_call_id_not_found` | warn | `StateStore::find_by_call_ids` | The adapter could not restore continuation via pending `call_id` fallback. The log includes requested and matched call-id counts. | +| `stateless_tool_history_bypass_state_lookup` | debug | `conversion::function_output_call_ids` | Responses input already contains matching tool calls for every tool output, so the server bypasses stored-state lookup and allows stateless history repair. | + +## Operational use + +When a real Codex subagent continuation fails, check logs in this order: + +1. `stored_response_not_found` means Codex supplied a `previous_response_id`, but the adapter no longer has the stored response, commonly because the state TTL expired or a different state DB is being used. +2. `tool_history_unique_fallback_hit` means Codex omitted or rewrote `previous_response_id`, but the adapter recovered through unique `call_id` fallback. +3. `tool_history_call_id_ambiguous` or `tool_history_response_ambiguous` means the adapter refused recovery because multiple stored responses could match the requested tool output. +4. `stateless_tool_history_bypass_state_lookup` means Codex sent a self-contained stateless history; recovery should continue through `build_chat_payload()` and `repair_stateless_history()`. + +## Validation + +Run locally: + +```bash +cargo fmt --check +cargo test --lib +cargo test +``` diff --git a/src/conversion/mod.rs b/src/conversion/mod.rs index f79b66e..c5e3546 100644 --- a/src/conversion/mod.rs +++ b/src/conversion/mod.rs @@ -25,6 +25,11 @@ pub fn function_output_call_ids(body: &Value) -> Result, HistoryErro } if input_contains_all_tool_calls(body, &ids) { + tracing::debug!( + event = "stateless_tool_history_bypass_state_lookup", + call_ids = ?ids, + "Responses input contains matching tool calls for every tool output; using stateless history repair instead of stored-state lookup" + ); Ok(Vec::new()) } else { Ok(ids) diff --git a/src/state.rs b/src/state.rs index d32fb3d..afafaab 100644 --- a/src/state.rs +++ b/src/state.rs @@ -79,6 +79,12 @@ impl StateStore { let payload: String = row.get(0)?; Ok(Some(serde_json::from_str(&payload)?)) } else { + tracing::warn!( + event = "stored_response_not_found", + response_id, + cutoff, + "requested previous_response_id was not found in non-expired state" + ); Ok(None) } } @@ -113,6 +119,15 @@ impl StateStore { intersects_wanted = true; match matched_by_call_id.get(call_id) { Some(existing_response_id) if existing_response_id != &item.response_id => { + tracing::warn!( + event = "tool_history_call_id_ambiguous", + call_id, + candidate_count = 2, + existing_response_id, + candidate_response_id = %item.response_id, + requested_call_ids = ?call_ids, + "call_id matched multiple stored responses; unique fallback disabled" + ); return Ok(None); } Some(_) => {} @@ -125,6 +140,14 @@ impl StateStore { if intersects_wanted && wanted.is_subset(&pending) { match &unique_response_id { Some(existing_response_id) if existing_response_id != &item.response_id => { + tracing::warn!( + event = "tool_history_response_ambiguous", + candidate_count = 2, + existing_response_id, + candidate_response_id = %item.response_id, + requested_call_ids = ?call_ids, + "requested call ids matched multiple stored responses; unique fallback disabled" + ); return Ok(None); } Some(_) => {} @@ -137,8 +160,24 @@ impl StateStore { } if matched_by_call_id.len() == wanted.len() { + if let Some(response) = unique_response.as_ref() { + tracing::debug!( + event = "tool_history_unique_fallback_hit", + response_id = %response.response_id, + requested_call_ids = ?call_ids, + pending_call_ids = ?response.pending_call_ids, + "restored tool continuation by unique pending call_id fallback" + ); + } Ok(unique_response) } else { + tracing::warn!( + event = "tool_history_call_id_not_found", + requested_call_ids = ?call_ids, + matched_call_id_count = matched_by_call_id.len(), + requested_call_id_count = wanted.len(), + "could not restore tool continuation by pending call_id fallback" + ); Ok(None) } }