From e711636384abdebb4f6e9232f895c89bf6e155d2 Mon Sep 17 00:00:00 2001 From: Wuming Gong Date: Fri, 9 Oct 2026 22:06:12 -0700 Subject: [PATCH 1/2] fix(codex): log the empty-completion retries and the final 503 MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit An empty Codex completion is currently invisible in serve-$PORT.log. The retry loop writes nothing on any of its exits, so an operator holding a client-side `503 Codex completed without producing output` and a request id has no server-side record to correlate it with, and no way to tell the ~157 s wait apart from a hang, a proxy timeout or a network fault. Three warn records, no behavior change: - `codex_empty_completion_retry`, buffered path, per retry — reqId, transport, model, failedAttempt, maxAttempts, delayMs, ms. Same shape as the existing `buffered_transport_retry` record. - `codex_empty_completion_retry`, live path, once per empty terminal event, with `stream: true`. - `codex_empty_completion_exhausted` on give-up — reqId, transport, model, attempts, reason, ms. `reason` separates `max_attempts` from `backoff_budget`; both produce the same 503, so the log is the only place the difference shows. Every other upstream failure on this code path is already logged — the transport-error arm twenty lines above emits a full `codex_upstream_request_failed` — so this one was the outlier. Closes #177 Co-Authored-By: Claude Opus 5 (1M context) --- src/providers/codex/mod.rs | 104 +++++++++++++++++++++++++++++++++++++ 1 file changed, 104 insertions(+) diff --git a/src/providers/codex/mod.rs b/src/providers/codex/mod.rs index bfc96115..780266b7 100644 --- a/src/providers/codex/mod.rs +++ b/src/providers/codex/mod.rs @@ -404,16 +404,56 @@ impl CodexProvider { let error = empty_buffered_completion_error(); drop_live_continuation_for_retry(&mut continuation); if attempt >= MAX_EMPTY_COMPLETION_RETRIES { + log.warn( + "codex_empty_completion_exhausted", + Some(empty_completion_exhausted_fields( + &req_id, + transport, + &resolved.model, + attempt + 1, + "max_attempts", + upstream_started_at.elapsed().as_millis(), + )), + ); abort_compaction_attempt(ctx.session_id.as_deref(), compaction_attempt); abort_continuation_for_owner(&request_continuation); return map_codex_error_to_response(&error); } let delay = compute_backoff_delay(attempt, None); if delay.exceeds_budget { + log.warn( + "codex_empty_completion_exhausted", + Some(empty_completion_exhausted_fields( + &req_id, + transport, + &resolved.model, + attempt + 1, + "backoff_budget", + upstream_started_at.elapsed().as_millis(), + )), + ); abort_compaction_attempt(ctx.session_id.as_deref(), compaction_attempt); abort_continuation_for_owner(&request_continuation); return map_codex_error_to_response(&error); } + log.warn( + "codex_empty_completion_retry", + Some(serde_json::Map::from_iter([ + ("reqId".to_string(), serde_json::json!(&req_id)), + ("transport".to_string(), serde_json::json!(transport)), + ("model".to_string(), serde_json::json!(&resolved.model)), + ("failedAttempt".to_string(), serde_json::json!(attempt + 1)), + ( + "maxAttempts".to_string(), + serde_json::json!(MAX_EMPTY_COMPLETION_RETRIES + 1), + ), + ("delayMs".to_string(), serde_json::json!(delay.wait_ms)), + ( + "ms".to_string(), + serde_json::json!(upstream_started_at.elapsed().as_millis()), + ), + ])), + ); attempt += 1; sleep(delay.wait_ms).await; }; @@ -943,6 +983,18 @@ async fn live_stream_response_once( && is_codex_success_terminal_event(&payload) && !translator.has_semantic_output() { + create_logger("codex").warn( + "codex_empty_completion_retry", + Some(serde_json::Map::from_iter([ + ("reqId".to_string(), serde_json::json!(&ctx.req_id)), + ( + "transport".to_string(), + serde_json::json!(config::codex_transport().as_str()), + ), + ("model".to_string(), serde_json::json!(model)), + ("stream".to_string(), serde_json::json!(true)), + ])), + ); return provider_retry(&upstream_events, empty_live_completion_error()); } if translator.has_semantic_output() && !pending_chunk.is_empty() { @@ -1265,6 +1317,30 @@ where (headers, Body::from_stream(stream)).into_response() } +/// Log fields for giving up on an empty completion, on either exit. +/// +/// `reason` separates the two: `"max_attempts"` when the retry budget ran +/// out, `"backoff_budget"` when the next delay would have exceeded the +/// backoff budget. They produce the same 503, so the log is the only place +/// the difference is visible. +fn empty_completion_exhausted_fields( + req_id: &str, + transport: &str, + model: &str, + attempts: u32, + reason: &str, + elapsed_ms: u128, +) -> serde_json::Map { + serde_json::Map::from_iter([ + ("reqId".to_string(), serde_json::json!(req_id)), + ("transport".to_string(), serde_json::json!(transport)), + ("model".to_string(), serde_json::json!(model)), + ("attempts".to_string(), serde_json::json!(attempts)), + ("reason".to_string(), serde_json::json!(reason)), + ("ms".to_string(), serde_json::json!(elapsed_ms)), + ]) +} + fn empty_buffered_completion_error() -> client::CodexError { client::CodexError { status: 503, @@ -2177,6 +2253,34 @@ mod tests { assert_eq!(response.headers()["x-should-retry"], "false"); } + #[test] + fn empty_completion_exhausted_fields_distinguish_the_two_give_up_reasons() { + let max = empty_completion_exhausted_fields( + "req-1", + "websocket", + "gpt-6-sol", + 11, + "max_attempts", + 157_000, + ); + assert_eq!(max["reqId"], "req-1"); + assert_eq!(max["transport"], "websocket"); + assert_eq!(max["model"], "gpt-6-sol"); + assert_eq!(max["attempts"], 11); + assert_eq!(max["reason"], "max_attempts"); + assert_eq!(max["ms"], 157_000); + + let budget = empty_completion_exhausted_fields( + "req-1", + "websocket", + "gpt-6-sol", + 4, + "backoff_budget", + 20_000, + ); + assert_eq!(budget["reason"], "backoff_budget"); + } + #[test] fn live_start_statusless_websocket_handshake_error_is_retryable() { let err = client::CodexError { From befd79cc2b1420080dd7bec9d3f4c3b75f001c1b Mon Sep 17 00:00:00 2001 From: Wuming Gong Date: Sat, 10 Oct 2026 10:21:44 -0700 Subject: [PATCH 2/2] fix(codex): log the give-up on the live path too, not just the retries MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The first commit added `codex_empty_completion_exhausted` only on the buffered path. The live path logs each retry but then gives up in `live_stream_response`'s `LiveStreamStart::Retry` arm, which emitted nothing, so a streamed request that exhausted its budget produced a 503 with no give-up record. Caught by the patch's own output: six hours of real traffic produced four requests with 11 `codex_empty_completion_retry` records each — the ceiling, so all four returned the 503 — and zero `exhausted` records. `is_empty_completion_error` keys off `EMPTY_CODEX_COMPLETION_DETAIL` so the record fires only for the empty-completion case and not for the other retryable errors sharing that loop. `live_stream_response` gains a `started_at` so `ms` is a real elapsed time rather than a placeholder. Co-Authored-By: Claude Opus 5 (1M context) --- src/providers/codex/mod.rs | 33 +++++++++++++++++++++++++++++++++ 1 file changed, 33 insertions(+) diff --git a/src/providers/codex/mod.rs b/src/providers/codex/mod.rs index 780266b7..09623070 100644 --- a/src/providers/codex/mod.rs +++ b/src/providers/codex/mod.rs @@ -766,6 +766,7 @@ async fn live_stream_response( transport: config::CodexTransport, ) -> Response { let model = model.to_string(); + let started_at = Instant::now(); let request_continuation = continuation.clone(); let mut cleanup = LiveRequestStateCleanup::new( request_continuation.clone(), @@ -865,11 +866,37 @@ async fn live_stream_response( continue; } if attempt >= MAX_RETRYABLE_LIVE_STREAM_RETRIES { + if is_empty_completion_error(&error) { + create_logger("codex").warn( + "codex_empty_completion_exhausted", + Some(empty_completion_exhausted_fields( + &ctx.req_id, + transport.as_str(), + &model, + attempt + 1, + "max_attempts", + started_at.elapsed().as_millis(), + )), + ); + } cleanup.abort(); return map_codex_error_to_response(&error); } let delay = compute_backoff_delay(attempt, error.retry_after.as_deref()); if delay.exceeds_budget { + if is_empty_completion_error(&error) { + create_logger("codex").warn( + "codex_empty_completion_exhausted", + Some(empty_completion_exhausted_fields( + &ctx.req_id, + transport.as_str(), + &model, + attempt + 1, + "backoff_budget", + started_at.elapsed().as_millis(), + )), + ); + } cleanup.abort(); return map_codex_error_to_response(&error); } @@ -1317,6 +1344,12 @@ where (headers, Body::from_stream(stream)).into_response() } +/// True when *error* is the empty-completion 503 rather than some other +/// retryable failure sharing the live-stream retry loop. +fn is_empty_completion_error(error: &client::CodexError) -> bool { + error.detail.as_deref() == Some(EMPTY_CODEX_COMPLETION_DETAIL) +} + /// Log fields for giving up on an empty completion, on either exit. /// /// `reason` separates the two: `"max_attempts"` when the retry budget ran