diff --git a/Cargo.lock b/Cargo.lock index 1101c01c..8d8320a1 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -170,6 +170,7 @@ dependencies = [ "thiserror 1.0.69", "tokio", "tracing", + "tracing-subscriber", "uuid", "wiremock", ] diff --git a/crates/aisix-guardrails/Cargo.toml b/crates/aisix-guardrails/Cargo.toml index 2fad7adb..1ea44621 100644 --- a/crates/aisix-guardrails/Cargo.toml +++ b/crates/aisix-guardrails/Cargo.toml @@ -78,3 +78,4 @@ presidio = ["dep:reqwest"] [dev-dependencies] tokio = { workspace = true, features = ["macros", "rt"] } wiremock.workspace = true +tracing-subscriber.workspace = true diff --git a/crates/aisix-guardrails/src/aliyun.rs b/crates/aisix-guardrails/src/aliyun.rs index d5cf3cdd..e66427c2 100644 --- a/crates/aisix-guardrails/src/aliyun.rs +++ b/crates/aisix-guardrails/src/aliyun.rs @@ -233,9 +233,14 @@ impl AliyunTextModerationGuardrail { return Err(AliyunFailure::ServerError); } if !status.is_success() { + // Echo the provider's actual reason (e.g. `InvalidAccessKeyId.NotFound` + // or a 404 HTML page) — a bare status code can't tell a wrong access + // key from a wrong region/endpoint. + let response_body = crate::read_error_body_capped(resp).await; tracing::error!( row = %self.row_name, http_status = status.as_u16(), + response_body = %response_body, "aliyun TextModerationPlus returned 4xx — check region/access keys configuration", ); return Err(AliyunFailure::ConfigError); @@ -255,6 +260,8 @@ impl AliyunTextModerationGuardrail { tracing::error!( row = %self.row_name, aliyun_code = body.code, + aliyun_message = + %crate::truncate_error_body_for_log(body.message.as_deref().unwrap_or("")), "aliyun TextModerationPlus auth/permission error — check access keys", ); Err(AliyunFailure::ConfigError) @@ -380,6 +387,8 @@ impl AliyunFailure { struct AliyunResponse { #[serde(rename = "Code", default)] code: i32, + #[serde(rename = "Message", default)] + message: Option, #[serde(rename = "Data", default)] data: Option, } @@ -684,6 +693,129 @@ mod tests { assert!(g.check_input(&req("x")).await.is_block()); } + /// A tracing writer that appends every emitted byte into a shared buffer so + /// a test can assert what a log line carried. + #[derive(Clone)] + struct BufWriter(std::sync::Arc>>); + impl std::io::Write for BufWriter { + fn write(&mut self, buf: &[u8]) -> std::io::Result { + self.0.lock().unwrap().extend_from_slice(buf); + Ok(buf.len()) + } + fn flush(&mut self) -> std::io::Result<()> { + Ok(()) + } + } + impl tracing_subscriber::fmt::MakeWriter<'_> for BufWriter { + type Writer = BufWriter; + fn make_writer(&self) -> Self::Writer { + self.clone() + } + } + + /// Run `f` with a log-capturing subscriber installed and return everything + /// it emitted. + async fn capture_logs(f: F) -> String + where + F: FnOnce() -> Fut, + Fut: std::future::Future, + { + let buf = std::sync::Arc::new(std::sync::Mutex::new(Vec::new())); + let subscriber = tracing_subscriber::fmt() + .with_ansi(false) + .with_writer(BufWriter(buf.clone())) + .finish(); + { + let _guard = tracing::subscriber::set_default(subscriber); + f().await; + } + let bytes = buf.lock().unwrap().clone(); + String::from_utf8(bytes).unwrap() + } + + // The three error-body log scenarios live in ONE test on purpose: the + // capture uses a thread-local default subscriber (`set_default`), so two + // capture tests running in parallel would race over it. Kept sequential + // here, at most one capturing subscriber is ever installed process-wide. + #[tokio::test] + async fn error_paths_log_provider_diagnostics() { + // 1. A wrong access key: green-cip answers 4xx (the customer saw 404) + // with a body naming the cause. Without echoing it the operator only + // sees a bare status code (AISIX-Cloud#1030 follow-up). + { + let server = MockServer::start().await; + Mock::given(method("POST")) + .respond_with(ResponseTemplate::new(404).set_body_json(json!({ + "Code": "InvalidAccessKeyId.NotFound", + "Message": "Specified access key is not found.", + "RequestId": "ABC-123", + }))) + .mount(&server) + .await; + let uri = server.uri(); + let logged = capture_logs(|| async { + let g = build(&uri, "high", false); + assert!(g.check_input(&req("x")).await.is_block()); + }) + .await; + assert!( + logged.contains("response_body") && logged.contains("InvalidAccessKeyId.NotFound"), + "4xx log must echo the provider's actual reason; got: {logged}" + ); + } + + // 2. A pathological oversized 4xx body: the marker sits well past the + // log cap, so if it shows up we buffered/logged more than we should. + { + let server = MockServer::start().await; + let filler = "X".repeat(crate::MAX_ERROR_BODY_LOG_BYTES + 4_000); + Mock::given(method("POST")) + .respond_with( + ResponseTemplate::new(400).set_body_string(format!("{filler}__TAIL_MARKER__")), + ) + .mount(&server) + .await; + let uri = server.uri(); + let logged = capture_logs(|| async { + let g = build(&uri, "high", false); + assert!(g.check_input(&req("x")).await.is_block()); + }) + .await; + assert!( + logged.contains("XXXX"), + "the head of the body must be logged" + ); + assert!( + !logged.contains("__TAIL_MARKER__"), + "the logged body must be capped, not echoed in full", + ); + } + + // 3. HTTP 200 but an app-level error Code — the Message carries the + // reason (e.g. an access key lacking llm_response_moderation). + { + let server = MockServer::start().await; + Mock::given(method("POST")) + .respond_with(ResponseTemplate::new(200).set_body_json(json!({ + "Code": 403, + "Message": "AccessKey has no permission for llm_response_moderation", + }))) + .mount(&server) + .await; + let uri = server.uri(); + let logged = capture_logs(|| async { + let g = build(&uri, "high", false); + assert!(g.check_input(&req("x")).await.is_block()); + }) + .await; + assert!( + logged.contains("aliyun_message") + && logged.contains("no permission for llm_response_moderation"), + "app-level error log must echo the Aliyun Message; got: {logged}" + ); + } + } + #[test] fn stream_policy_reflects_config() { let g = build("http://unused", "high", true); diff --git a/crates/aisix-guardrails/src/lakera.rs b/crates/aisix-guardrails/src/lakera.rs index 8407bbee..21ab40c7 100644 --- a/crates/aisix-guardrails/src/lakera.rs +++ b/crates/aisix-guardrails/src/lakera.rs @@ -167,9 +167,11 @@ impl LakeraGuardrail { // (bad api_key / project_id / endpoint). Error level: with // fail_open=true this silently bypasses the guardrail on every // request until the operator notices. + let response_body = crate::read_error_body_capped(resp).await; tracing::error!( row = %self.row_name, http_status = status.as_u16(), + response_body = %response_body, "lakera guard returned 4xx — check endpoint, api_key, and project_id configuration", ); return Err(LakeraFailure::ConfigError); diff --git a/crates/aisix-guardrails/src/lib.rs b/crates/aisix-guardrails/src/lib.rs index bafeaa87..454481e1 100644 --- a/crates/aisix-guardrails/src/lib.rs +++ b/crates/aisix-guardrails/src/lib.rs @@ -42,6 +42,50 @@ use aisix_core::models::GuardrailMonitorHit; use aisix_gateway::{ChatFormat, ChatMessage, ChatResponse}; use async_trait::async_trait; +/// Max bytes of an upstream guardrail-provider error body to echo into a log +/// line. Mirrors nginx's single-error-line cap (`NGX_MAX_ERROR_STR` = 2048) so +/// a verbose HTML error page or stack trace can't blow up the log. +pub(crate) const MAX_ERROR_BODY_LOG_BYTES: usize = 2048; + +/// Truncate a guardrail-provider error body for logging: at most +/// [`MAX_ERROR_BODY_LOG_BYTES`] bytes, cut on a UTF-8 char boundary so a +/// multi-byte character is never split. Returned verbatim otherwise — the +/// whole point is to surface the provider's actual reason (e.g. Aliyun's +/// `InvalidAccessKeyId.NotFound`) that a bare status code hides. +pub(crate) fn truncate_error_body_for_log(body: &str) -> &str { + if body.len() <= MAX_ERROR_BODY_LOG_BYTES { + return body; + } + let mut end = MAX_ERROR_BODY_LOG_BYTES; + while end > 0 && !body.is_char_boundary(end) { + end -= 1; + } + &body[..end] +} + +/// Read a guardrail provider's error-response body for logging, stopping once +/// [`MAX_ERROR_BODY_LOG_BYTES`] have arrived. We only ever log a snippet, so a +/// broken provider returning a huge 4xx body can't make us buffer the whole +/// thing. Reads chunk-by-chunk and gives up on the first read error — this is +/// best-effort diagnostics on a path that's already returning an error. +#[cfg(any( + feature = "azure-content-safety", + feature = "aliyun-text-moderation", + feature = "lakera", + feature = "openai-moderation", + feature = "presidio", +))] +pub(crate) async fn read_error_body_capped(mut resp: reqwest::Response) -> String { + let mut buf: Vec = Vec::new(); + while buf.len() < MAX_ERROR_BODY_LOG_BYTES { + match resp.chunk().await { + Ok(Some(chunk)) => buf.extend_from_slice(&chunk), + Ok(None) | Err(_) => break, + } + } + truncate_error_body_for_log(&String::from_utf8_lossy(&buf)).to_owned() +} + /// The text a guardrail should scan for one message. /// /// Prefers the flat `content` string; when it's empty, falls back to @@ -550,6 +594,39 @@ pub trait Guardrail: Send + Sync + 'static { mod tests { use super::*; + #[test] + fn truncate_error_body_short_passes_through() { + assert_eq!(truncate_error_body_for_log("boom"), "boom"); + // Exactly at the cap is not truncated. + let at_cap = "a".repeat(MAX_ERROR_BODY_LOG_BYTES); + assert_eq!(truncate_error_body_for_log(&at_cap), at_cap); + } + + #[test] + fn truncate_error_body_caps_length() { + let big = "a".repeat(MAX_ERROR_BODY_LOG_BYTES + 500); + let out = truncate_error_body_for_log(&big); + assert_eq!(out.len(), MAX_ERROR_BODY_LOG_BYTES); + } + + #[test] + fn truncate_error_body_never_splits_a_char() { + // '€' is 3 bytes; place a run of them so the byte cap lands mid-char. + // The result must stay ≤ cap AND be valid UTF-8 (no split), i.e. end + // on a char boundary just below the cap. + let s = "€".repeat(MAX_ERROR_BODY_LOG_BYTES); // 3 * cap bytes + let out = truncate_error_body_for_log(&s); + assert!(out.len() <= MAX_ERROR_BODY_LOG_BYTES); + assert!( + out.len() > MAX_ERROR_BODY_LOG_BYTES - 3, + "should fill the budget to within one char" + ); + assert!( + out.chars().all(|c| c == '€'), + "must not emit a partial char" + ); + } + #[test] fn message_scan_text_falls_back_to_content_blocks() { // Flat content present → used verbatim. diff --git a/crates/aisix-guardrails/src/openai_moderation.rs b/crates/aisix-guardrails/src/openai_moderation.rs index 21c4668e..0637a1e2 100644 --- a/crates/aisix-guardrails/src/openai_moderation.rs +++ b/crates/aisix-guardrails/src/openai_moderation.rs @@ -161,9 +161,11 @@ impl OpenaiModerationGuardrail { // (bad api_key / endpoint / model). Error level: with // fail_open=true this silently bypasses the guardrail on every // request until the operator notices. + let response_body = crate::read_error_body_capped(resp).await; tracing::error!( row = %self.row_name, http_status = status.as_u16(), + response_body = %response_body, "openai moderation returned 4xx — check endpoint, api_key, and model configuration", ); return Err(ModerationFailure::ConfigError); diff --git a/crates/aisix-guardrails/src/presidio.rs b/crates/aisix-guardrails/src/presidio.rs index 953da1c0..8be565bb 100644 --- a/crates/aisix-guardrails/src/presidio.rs +++ b/crates/aisix-guardrails/src/presidio.rs @@ -216,10 +216,12 @@ impl PresidioGuardrail { if !status.is_success() { // 4xx other than 429 — almost always a misconfiguration // (bad URL path, unsupported language, malformed entity list). + let response_body = crate::read_error_body_capped(resp).await; tracing::error!( row = %self.row_name, http_status = status.as_u16(), url = %url, + response_body = %response_body, "presidio returned 4xx — check analyzer_url/anonymizer_url, language, and entities configuration", ); return Err(PresidioFailure::ConfigError); diff --git a/crates/aisix-guardrails/src/prompt_shield.rs b/crates/aisix-guardrails/src/prompt_shield.rs index 432a3b97..2d306e92 100644 --- a/crates/aisix-guardrails/src/prompt_shield.rs +++ b/crates/aisix-guardrails/src/prompt_shield.rs @@ -174,9 +174,11 @@ impl PromptShieldGuardrail { // silently bypasses the guardrail on every request until // the operator notices. A persistent error-level log is // the only signal they get. + let response_body = crate::read_error_body_capped(resp).await; tracing::error!( row = %self.row_name, http_status = status.as_u16(), + response_body = %response_body, "azure content safety returned 4xx — check endpoint and api_key configuration", ); return Err(AcsFailure::ConfigError); diff --git a/crates/aisix-guardrails/src/text_moderation.rs b/crates/aisix-guardrails/src/text_moderation.rs index 180e2ea6..80864f0c 100644 --- a/crates/aisix-guardrails/src/text_moderation.rs +++ b/crates/aisix-guardrails/src/text_moderation.rs @@ -173,9 +173,11 @@ impl TextModerationGuardrail { return Err(AcsFailure::ServerError); } if !status.is_success() { + let response_body = crate::read_error_body_capped(resp).await; tracing::error!( row = %self.row_name, http_status = status.as_u16(), + response_body = %response_body, "azure content safety text:analyze returned 4xx — check endpoint and api_key configuration", ); return Err(AcsFailure::ConfigError);