From dc0284db2e87a20d839adc01be1190f044b3e692 Mon Sep 17 00:00:00 2001 From: Postil Maintainer Date: Fri, 11 Sep 2026 01:09:33 +0000 Subject: [PATCH] Log routed responses before identity rejection --- src/llm.rs | 56 +++++++++++++++++------------------ tests/e2e.rs | 84 ++++++++++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 112 insertions(+), 28 deletions(-) diff --git a/src/llm.rs b/src/llm.rs index 3d5473d..97f6da5 100644 --- a/src/llm.rs +++ b/src/llm.rs @@ -4457,6 +4457,34 @@ impl LlmClient { return Err(error); } if response.status.is_success() { + eprintln!( + "postil: llm response phase={} model={} attempt={} status={} elapsed={} bytes={} request_id={} response_id={} returned_model={} provider={} choices={} finish={} usage={} prompt_tokens={} completion_tokens={} reasoning_tokens={} category={}", + phase.as_str(), + log_text(model), + retries + 1, + response.status.as_u16(), + elapsed, + response.text.len(), + response.request_id.as_deref().unwrap_or("none"), + summary.response_id.as_deref().unwrap_or("none"), + summary.returned_model.as_deref().unwrap_or("none"), + summary.provider.as_deref().unwrap_or("none"), + summary + .choices + .map_or_else(|| "unknown".to_string(), |count| count.to_string()), + summary.finish_reason.as_deref().unwrap_or("none"), + if summary.usage.is_some() { + "present" + } else { + "missing" + }, + summary.usage.map_or(0, |value| value.prompt_tokens), + summary.usage.map_or(0, |value| value.completion_tokens), + summary + .reasoning_tokens + .map_or_else(|| "unknown".to_string(), |value| value.to_string()), + summary.error_type.as_deref().unwrap_or("none"), + ); let actual_identity = route_provider.map(|_| actual_response_identity(&response.text)); // A pinned route that answers without echoing its @@ -4503,34 +4531,6 @@ impl LlmClient { } return Err(error); } - eprintln!( - "postil: llm response phase={} model={} attempt={} status={} elapsed={} bytes={} request_id={} response_id={} returned_model={} provider={} choices={} finish={} usage={} prompt_tokens={} completion_tokens={} reasoning_tokens={} category={}", - phase.as_str(), - log_text(model), - retries + 1, - response.status.as_u16(), - elapsed, - response.text.len(), - response.request_id.as_deref().unwrap_or("none"), - summary.response_id.as_deref().unwrap_or("none"), - summary.returned_model.as_deref().unwrap_or("none"), - summary.provider.as_deref().unwrap_or("none"), - summary - .choices - .map_or_else(|| "unknown".to_string(), |count| count.to_string()), - summary.finish_reason.as_deref().unwrap_or("none"), - if summary.usage.is_some() { - "present" - } else { - "missing" - }, - summary.usage.map_or(0, |value| value.prompt_tokens), - summary.usage.map_or(0, |value| value.completion_tokens), - summary - .reasoning_tokens - .map_or_else(|| "unknown".to_string(), |value| value.to_string()), - summary.error_type.as_deref().unwrap_or("none"), - ); let usage_before_parse = *usage; match self.parse_response(&response.text, usage) { Ok(content) => { diff --git a/tests/e2e.rs b/tests/e2e.rs index 98ea776..7e13a00 100644 --- a/tests/e2e.rs +++ b/tests/e2e.rs @@ -2492,6 +2492,90 @@ async fn provider_403_redacts_key_management_url_from_cli_and_finding() { ); } +#[cfg(feature = "qualification-candidate")] +#[tokio::test] +async fn routed_http_200_errors_log_each_attempt_without_exposing_response_content() { + for recover in [false, true] { + let server = MockServer::start().await; + let secret = "fixture-private-provider-error-content"; + let failures = if recover { 2 } else { 3 }; + Mock::given(method("POST")) + .and(path("/chat/completions")) + .respond_with(ResponseTemplate::new(200).set_body_json(json!({ + "error": { + "message": secret, + "metadata": { + "error_type": "provider_error", + "provider_code": secret + } + } + }))) + .up_to_n_times(failures) + .with_priority(1) + .expect(failures) + .mount(&server) + .await; + if recover { + let mut response = llm_content(json!([])); + response["model"] = json!("openai/gpt-5.6-luna"); + response["provider"] = json!("Azure"); + Mock::given(method("POST")) + .and(path("/chat/completions")) + .respond_with(ResponseTemplate::new(200).set_body_json(response)) + .with_priority(2) + .expect(1) + .mount(&server) + .await; + } + let directory = tempfile::tempdir().unwrap(); + let profile = directory.path().join("profile.json"); + std::fs::write(&profile, include_str!("../provisional-models.json")).unwrap(); + let diff = write_diff(directory.path()); + let output = postil() + .current_dir(directory.path()) + .env("CI", "true") + .env("GITHUB_API_URL", "http://127.0.0.1:9") + .env("POSTIL_BENCH_REQUIRE_HOSTED_PROVIDER_PRIVACY", "1") + .env("POSTIL_QUALIFICATION_CANDIDATE_PROFILE", &profile) + .env("POSTIL_QUALIFICATION_CAPTURE_API_BASE", server.uri()) + .args(["review", "--diff-file"]) + .arg(&diff) + .args(["--output", "json"]) + .assert() + .code(if recover { 0 } else { 1 }); + let stderr = String::from_utf8_lossy(&output.get_output().stderr); + let stdout = String::from_utf8_lossy(&output.get_output().stdout); + assert!(!stderr.contains(secret)); + assert!(!stdout.contains(secret)); + let responses = stderr + .lines() + .filter(|line| line.starts_with("postil: llm response ")) + .collect::>(); + assert_eq!(responses.len(), 3, "{stderr}"); + assert_eq!(server.received_requests().await.unwrap().len(), 3); + for (index, line) in responses.iter().enumerate() { + assert!(line.contains(&format!("attempt={} ", index + 1))); + assert!(line.contains("status=200 ")); + if index < failures as usize { + assert!(line.contains("category=provider_error")); + assert!(line.contains("returned_model=none provider=none ")); + assert!(line.contains("usage=missing ")); + } else { + assert!(line.contains("category=none")); + assert!(line.contains("usage=present ")); + } + } + assert_eq!(stderr.matches("identity echo is missing").count(), 2); + let envelope: Value = serde_json::from_str(&stdout).unwrap(); + assert_eq!(envelope["usageAccountingComplete"], false); + if recover { + assert!(envelope["findings"].as_array().unwrap().is_empty()); + } else { + assert!(!envelope["findings"].as_array().unwrap().is_empty()); + } + } +} + #[tokio::test] async fn byok_reported_spend_is_not_subject_to_the_hosted_operation_cap() { let server = MockServer::start().await;