diff --git a/crates/aisix-obs/src/access_log.rs b/crates/aisix-obs/src/access_log.rs index 50ee8606..01973ed2 100644 --- a/crates/aisix-obs/src/access_log.rs +++ b/crates/aisix-obs/src/access_log.rs @@ -29,6 +29,15 @@ pub struct AccessLog<'a> { /// per-attempt detail lives in telemetry (per-attempt UsageEvents), /// not in this one-line-per-request access log. pub routing_fallback_count: Option, + /// Stable failure class (`ProxyError::kind`) — `None` on success. + /// Machine-readable so an operator can filter or alert on a class + /// without parsing the free-text message below. + pub error_kind: Option<&'a str>, + /// Why the request failed — `None` on success. Without it a 5xx line + /// carries only `status` + `latency_ms`, which is the same shape for a + /// kernel-level connect timeout, an upstream 500, and a blocked + /// guardrail (AISIX-Cloud#1093). + pub error: Option<&'a str>, } impl AccessLog<'_> { @@ -52,6 +61,8 @@ impl AccessLog<'_> { served_by_model = self.served_by_model, routing_attempt_count = self.routing_attempt_count, routing_fallback_count = self.routing_fallback_count, + error_kind = self.error_kind, + error = self.error, "proxy request completed", ); } @@ -116,6 +127,8 @@ mod tests { served_by_model: Some("fallback-target"), routing_attempt_count: Some(2), routing_fallback_count: Some(1), + error_kind: None, + error: None, } .emit(); }); @@ -134,6 +147,56 @@ mod tests { ); assert!(out.contains("routing_attempt_count=2")); assert!(out.contains("routing_fallback_count=1")); + // A success line must not carry failure fields at all — an + // always-present `error=""` would defeat filtering on it. + assert!(!out.contains("error_kind"), "{out}"); + assert!(!out.contains("error="), "{out}"); + } + + /// The gap this field closes: without it a failed request's only trace + /// is `status=502 latency_ms=…`, identical for every cause. + #[test] + fn emit_carries_the_failure_class_and_reason() { + let writer = VecWriter::default(); + let subscriber = fmt() + .with_writer(writer.clone()) + .with_ansi(false) + .with_target(false) + .with_env_filter(EnvFilter::new("info")) + .finish(); + + with_default(subscriber, || { + AccessLog { + method: "POST", + path: "/v1/messages", + status: 504, + latency: Duration::from_millis(7167), + provider: None, + model: Some("claude-sonnet-4"), + api_key_id: Some("key-id-1"), + prompt_tokens: None, + completion_tokens: None, + total_tokens: None, + request_id: "req-fail", + served_by_model: None, + routing_attempt_count: Some(1), + routing_fallback_count: None, + error_kind: Some("timeout"), + error: Some("upstream request timed out after 7167ms"), + } + .emit(); + }); + + let out = writer.contents(); + assert!(out.contains("status=504")); + assert!( + out.contains("error_kind=\"timeout\"") || out.contains("error_kind=timeout"), + "{out}" + ); + assert!( + out.contains("upstream request timed out after 7167ms"), + "{out}" + ); } #[test] @@ -162,6 +225,8 @@ mod tests { served_by_model: None, routing_attempt_count: None, routing_fallback_count: None, + error_kind: None, + error: None, } .emit(); }); diff --git a/crates/aisix-proxy/src/a2a.rs b/crates/aisix-proxy/src/a2a.rs index 53c1cccf..3ced0d00 100644 --- a/crates/aisix-proxy/src/a2a.rs +++ b/crates/aisix-proxy/src/a2a.rs @@ -81,6 +81,10 @@ pub async fn a2a_endpoint( completion_tokens: None, total_tokens: None, request_id: &request_id, + // Same as `/mcp`: `dispatch` returns an already-rendered `Response`, + // so no typed error reaches this point. + error_kind: None, + error: None, served_by_model: None, routing_attempt_count: None, routing_fallback_count: None, diff --git a/crates/aisix-proxy/src/attempt.rs b/crates/aisix-proxy/src/attempt.rs index 9c14440f..da145b30 100644 --- a/crates/aisix-proxy/src/attempt.rs +++ b/crates/aisix-proxy/src/attempt.rs @@ -155,15 +155,38 @@ pub(crate) fn routing_error_class(err: &BridgeError) -> &'static str { /// a second time (AISIX-Cloud#1065). const MAX_ATTEMPT_ERROR_MESSAGE_CHARS: usize = 2048; +/// Control-char-stripped, capped rendering of an error's `Display`. +/// +/// Anything that a log reader would treat as a line break is dropped, so a +/// multi-line upstream body can't split the one-line-per-record shape of +/// the telemetry field and the access log. U+2028/U+2029 are listed +/// explicitly: they are `Zl`/`Zp`, not `Cc`, so `is_control()` lets them +/// through even though plenty of viewers break lines on them. +fn sanitize_error_message(s: &str) -> String { + s.chars() + .filter(|c| !c.is_control() && !matches!(c, '\u{2028}' | '\u{2029}')) + .take(MAX_ATTEMPT_ERROR_MESSAGE_CHARS) + .collect() +} + /// Control-char-stripped error string for the per-attempt /// `error_message` telemetry field (#655), capped at /// [`MAX_ATTEMPT_ERROR_MESSAGE_CHARS`]. pub(crate) fn attempt_error_message(err: &BridgeError) -> String { - err.to_string() - .chars() - .filter(|c| !c.is_control()) - .take(MAX_ATTEMPT_ERROR_MESSAGE_CHARS) - .collect() + sanitize_error_message(&err.to_string()) +} + +/// Failure class + reason for the access log's `error_kind` / `error` +/// fields. +/// +/// Deliberately NOT [`attempt_error_from_proxy`]: that one leaves the +/// message empty for every non-bridge variant, which is fine for a +/// per-attempt record (the class is the point) but would put a failed +/// request back to carrying no reason at all — the gap this exists to +/// close. Here every variant contributes its `Display`, because the access +/// log is the one line an operator gets per request. +pub(crate) fn access_log_error(err: &ProxyError) -> (&'static str, String) { + (err.kind(), sanitize_error_message(&err.to_string())) } /// Bounded error class + short message for a per-attempt record, derived @@ -190,6 +213,59 @@ mod tests { use super::*; use aisix_gateway::{UpstreamWire, MAX_UPSTREAM_ERROR_MESSAGE_BYTES}; + /// AISIX-Cloud#1093: the access log is the one line an operator gets + /// per request, so EVERY failure has to name itself there — including + /// the variants `attempt_error_from_proxy` deliberately leaves + /// message-less because a per-attempt record only needs the class. + #[test] + fn access_log_error_names_every_variant_not_just_bridge_ones() { + // The cause added for #1093 has to survive into the access log — + // it is what separates "the upstream is slow" from "we never + // reached it", which render identically without it. + let (kind, msg) = access_log_error(&ProxyError::Bridge(BridgeError::Timeout { + elapsed_ms: 7167, + cause: "tcp connect error: Connection timed out (os error 110)".into(), + })); + assert_eq!(kind, "timeout"); + assert_eq!( + msg, + "upstream request timed out after 7167ms: \ + tcp connect error: Connection timed out (os error 110)" + ); + + // A non-bridge variant: `attempt_error_from_proxy` yields "" here, + // which would put the access log right back to naming no cause. + let not_found = ProxyError::ModelNotFound("model \"ghost\" not found".into()); + let (kind, msg) = access_log_error(¬_found); + assert_eq!(kind, "model_not_found"); + assert!(msg.contains("ghost"), "{msg}"); + assert!( + attempt_error_from_proxy(¬_found).1.is_empty(), + "per-attempt records intentionally carry no message here — \ + that is why the access log needs its own helper" + ); + } + + /// Control chars would break the one-line-per-request shape that makes + /// the access log greppable. + #[test] + fn access_log_error_strips_control_chars_and_caps_length() { + // U+2028/U+2029 are Zl/Zp rather than Cc, so `is_control()` alone + // would forward them and a log viewer would break the record. + let (_, msg) = access_log_error(&ProxyError::InvalidRequest( + "bad\nrequest\tbody\u{2028}split\u{2029}again\r\n".into(), + )); + assert!( + !msg.contains(['\n', '\r', '\t', '\u{2028}', '\u{2029}']), + "{msg:?}" + ); + assert!(msg.ends_with("badrequestbodysplitagain"), "{msg}"); + + let long = ProxyError::InvalidRequest("x".repeat(MAX_ATTEMPT_ERROR_MESSAGE_CHARS * 2)); + let (_, msg) = access_log_error(&long); + assert_eq!(msg.chars().count(), MAX_ATTEMPT_ERROR_MESSAGE_CHARS); + } + fn upstream_status(message: &str) -> BridgeError { BridgeError::UpstreamStatus { status: 400, diff --git a/crates/aisix-proxy/src/audio.rs b/crates/aisix-proxy/src/audio.rs index 822dec40..aee000bc 100644 --- a/crates/aisix-proxy/src/audio.rs +++ b/crates/aisix-proxy/src/audio.rs @@ -115,6 +115,7 @@ pub async fn transcriptions( status, elapsed, &request_id, + None, ); state.metrics.record_request( &success.provider, @@ -146,6 +147,7 @@ pub async fn transcriptions( status, elapsed, &request_id, + Some(&err), ); state.metrics.record_request( "unknown", @@ -213,6 +215,7 @@ pub async fn translations( status, elapsed, &request_id, + None, ); state.metrics.record_request( &success.provider, @@ -244,6 +247,7 @@ pub async fn translations( status, elapsed, &request_id, + Some(&err), ); state.metrics.record_request( "unknown", @@ -310,6 +314,7 @@ pub async fn speech( 200, elapsed, &request_id, + None, ); state.metrics.record_request( &provider, @@ -355,6 +360,7 @@ pub async fn speech( status, elapsed, &request_id, + Some(&err), ); let snap = state.snapshot.load(); let metric_model = crate::usage_attr::metric_model_label(&snap, &model_name); @@ -1177,7 +1183,15 @@ fn emit_access_log( status: u16, latency: Duration, request_id: &str, + error: Option<&ProxyError>, ) { + let (error_kind, error) = match error { + Some(e) => { + let (kind, msg) = crate::attempt::access_log_error(e); + (Some(kind), Some(msg)) + } + None => (None, None), + }; AccessLog { method, path, @@ -1193,6 +1207,8 @@ fn emit_access_log( served_by_model: None, routing_attempt_count: None, routing_fallback_count: None, + error_kind, + error: error.as_deref(), } .emit(); } diff --git a/crates/aisix-proxy/src/chat.rs b/crates/aisix-proxy/src/chat.rs index 0afef84a..7c9fd054 100644 --- a/crates/aisix-proxy/src/chat.rs +++ b/crates/aisix-proxy/src/chat.rs @@ -187,6 +187,7 @@ pub async fn chat_completions( success.total_tokens, &request_id, &success.routing, + None, ); // Per #655: emit a zero-token event for each failed attempt // that preceded the winner (non-streaming fallover). No-op for @@ -424,6 +425,7 @@ pub async fn chat_completions( al_total, &request_id, &routing, + Some(&err), ); // `resolved_model_id` is populated by `dispatch` once // `req.model` resolves against the snapshot, so a guardrail / @@ -3849,7 +3851,15 @@ fn emit_access_log( total_tokens: Option, request_id: &str, routing: &RoutingTelemetry, + error: Option<&ProxyError>, ) { + let (error_kind, error) = match error { + Some(e) => { + let (kind, msg) = crate::attempt::access_log_error(e); + (Some(kind), Some(msg)) + } + None => (None, None), + }; // Per #655 the access log stays ONE line per request (the transport // plane), carrying user-perceived `latency` + the final status plus a // routing summary. The per-attempt detail lives in telemetry only. @@ -3875,6 +3885,8 @@ fn emit_access_log( 0 => None, n => Some(n), }, + error_kind, + error: error.as_deref(), } .emit(); } diff --git a/crates/aisix-proxy/src/completions.rs b/crates/aisix-proxy/src/completions.rs index 818708f8..fe777490 100644 --- a/crates/aisix-proxy/src/completions.rs +++ b/crates/aisix-proxy/src/completions.rs @@ -117,6 +117,7 @@ pub async fn completions( status, elapsed, &request_id, + None, ); state.metrics.record_request( &success.provider, @@ -161,6 +162,7 @@ pub async fn completions( status, elapsed, &request_id, + Some(&err), ); let snap = state.snapshot.load(); let metric_model = crate::usage_attr::metric_model_label(&snap, &model_name); @@ -654,7 +656,15 @@ fn emit_access_log( status: u16, latency: Duration, request_id: &str, + error: Option<&ProxyError>, ) { + let (error_kind, error) = match error { + Some(e) => { + let (kind, msg) = crate::attempt::access_log_error(e); + (Some(kind), Some(msg)) + } + None => (None, None), + }; let _now_ts = SystemTime::now() .duration_since(UNIX_EPOCH) .map(|d| d.as_secs() as i64) @@ -674,6 +684,8 @@ fn emit_access_log( served_by_model: None, routing_attempt_count: None, routing_fallback_count: None, + error_kind, + error: error.as_deref(), } .emit(); } diff --git a/crates/aisix-proxy/src/count_tokens.rs b/crates/aisix-proxy/src/count_tokens.rs index 1c6151c7..013f1007 100644 --- a/crates/aisix-proxy/src/count_tokens.rs +++ b/crates/aisix-proxy/src/count_tokens.rs @@ -101,6 +101,7 @@ pub async fn count_tokens( status, elapsed, &request_id, + None, ); state.metrics.record_request( &provider, @@ -121,6 +122,7 @@ pub async fn count_tokens( status, elapsed, &request_id, + Some(&err), ); let snap = state.snapshot.load(); let metric_model = crate::usage_attr::metric_model_label(&snap, &model_name); @@ -431,7 +433,15 @@ fn emit_access_log( status: u16, elapsed: Duration, request_id: &str, + error: Option<&ProxyError>, ) { + let (error_kind, error) = match error { + Some(e) => { + let (kind, msg) = crate::attempt::access_log_error(e); + (Some(kind), Some(msg)) + } + None => (None, None), + }; AccessLog { method: "POST", path: "/v1/messages/count_tokens", @@ -447,6 +457,8 @@ fn emit_access_log( served_by_model: None, routing_attempt_count: None, routing_fallback_count: None, + error_kind, + error: error.as_deref(), } .emit(); } diff --git a/crates/aisix-proxy/src/embeddings.rs b/crates/aisix-proxy/src/embeddings.rs index 569d2d2c..5dcc2b8c 100644 --- a/crates/aisix-proxy/src/embeddings.rs +++ b/crates/aisix-proxy/src/embeddings.rs @@ -136,6 +136,7 @@ pub async fn embeddings( status, elapsed, &request_id, + None, ); state.metrics.record_request( &success.provider, @@ -189,6 +190,7 @@ pub async fn embeddings( status, elapsed, &request_id, + Some(&err), ); let snap = state.snapshot.load(); let metric_model = crate::usage_attr::metric_model_label(&snap, &model_name); @@ -512,7 +514,15 @@ fn emit_access_log( status: u16, latency: Duration, request_id: &str, + error: Option<&ProxyError>, ) { + let (error_kind, error) = match error { + Some(e) => { + let (kind, msg) = crate::attempt::access_log_error(e); + (Some(kind), Some(msg)) + } + None => (None, None), + }; let now_ts = SystemTime::now() .duration_since(UNIX_EPOCH) .map(|d| d.as_secs() as i64) @@ -533,6 +543,8 @@ fn emit_access_log( served_by_model: None, routing_attempt_count: None, routing_fallback_count: None, + error_kind, + error: error.as_deref(), } .emit(); } diff --git a/crates/aisix-proxy/src/images.rs b/crates/aisix-proxy/src/images.rs index a98244f5..dc7eb5d5 100644 --- a/crates/aisix-proxy/src/images.rs +++ b/crates/aisix-proxy/src/images.rs @@ -87,6 +87,7 @@ pub async fn image_generations( 200, elapsed, &request_id, + None, ); state.metrics.record_request( &success.provider, @@ -136,6 +137,7 @@ pub async fn image_generations( status, elapsed, &request_id, + Some(&err), ); let snap = state.snapshot.load(); let metric_model = crate::usage_attr::metric_model_label(&snap, &model_name); @@ -460,7 +462,15 @@ fn emit_access_log( status: u16, latency: Duration, request_id: &str, + error: Option<&ProxyError>, ) { + let (error_kind, error) = match error { + Some(e) => { + let (kind, msg) = crate::attempt::access_log_error(e); + (Some(kind), Some(msg)) + } + None => (None, None), + }; AccessLog { method: "POST", path: "/v1/images/generations", @@ -476,6 +486,8 @@ fn emit_access_log( served_by_model: None, routing_attempt_count: None, routing_fallback_count: None, + error_kind, + error: error.as_deref(), } .emit(); } diff --git a/crates/aisix-proxy/src/jobs.rs b/crates/aisix-proxy/src/jobs.rs index ff8030da..ff9a6c4c 100644 --- a/crates/aisix-proxy/src/jobs.rs +++ b/crates/aisix-proxy/src/jobs.rs @@ -562,6 +562,7 @@ fn emit_job_usage_event( .fan_out(&event, None, exporters.iter().map(|e| &e.value)); } +#[allow(clippy::too_many_arguments)] fn emit_access_log( method: &Method, path: &str, @@ -570,7 +571,15 @@ fn emit_access_log( status: u16, elapsed: Duration, request_id: &str, + error: Option<&ProxyError>, ) { + let (error_kind, error) = match error { + Some(e) => { + let (kind, msg) = crate::attempt::access_log_error(e); + (Some(kind), Some(msg)) + } + None => (None, None), + }; AccessLog { method: method.as_str(), path, @@ -586,6 +595,8 @@ fn emit_access_log( served_by_model: None, routing_attempt_count: None, routing_fallback_count: None, + error_kind, + error: error.as_deref(), } .emit(); } @@ -617,6 +628,7 @@ fn finish( status, elapsed, &request_id, + None, ); state.metrics.record_request( target.provider_label(), @@ -651,6 +663,7 @@ fn finish( status, elapsed, &request_id, + Some(&err), ); state.metrics.record_request( "", diff --git a/crates/aisix-proxy/src/mcp.rs b/crates/aisix-proxy/src/mcp.rs index 2aabe1a5..951d2e85 100644 --- a/crates/aisix-proxy/src/mcp.rs +++ b/crates/aisix-proxy/src/mcp.rs @@ -93,6 +93,11 @@ pub async fn mcp_endpoint( completion_tokens: None, total_tokens: None, request_id: &request_id, + // `dispatch` renders its own `Response` rather than surfacing a + // `ProxyError`, so there is no typed error to name here. The status + // code is all this endpoint can attribute a failure to. + error_kind: None, + error: None, served_by_model: None, routing_attempt_count: None, routing_fallback_count: None, diff --git a/crates/aisix-proxy/src/messages.rs b/crates/aisix-proxy/src/messages.rs index e47d8bf7..afc9d0dc 100644 --- a/crates/aisix-proxy/src/messages.rs +++ b/crates/aisix-proxy/src/messages.rs @@ -171,6 +171,7 @@ pub async fn messages( elapsed, &request_id, &routing, + None, ); state.metrics.record_request( &provider_label, @@ -286,6 +287,7 @@ pub async fn messages( elapsed, &request_id, &routing, + Some(&err), ); let snap = state.snapshot.load(); let metric_model = crate::usage_attr::metric_model_label(&snap, &model_name); @@ -3340,6 +3342,7 @@ where } } +#[allow(clippy::too_many_arguments)] fn emit_access_log( model: &str, provider: &str, @@ -3348,7 +3351,15 @@ fn emit_access_log( latency: Duration, request_id: &str, routing: &RoutingTelemetry, + error: Option<&ProxyError>, ) { + let (error_kind, error) = match error { + Some(e) => { + let (kind, msg) = crate::attempt::access_log_error(e); + (Some(kind), Some(msg)) + } + None => (None, None), + }; // Per #655 the access log stays ONE line per request, carrying the // user-perceived `latency` + final status plus a routing summary; the // per-attempt detail lives in telemetry. @@ -3377,6 +3388,8 @@ fn emit_access_log( 0 => None, n => Some(n), }, + error_kind, + error: error.as_deref(), } .emit(); } diff --git a/crates/aisix-proxy/src/passthrough.rs b/crates/aisix-proxy/src/passthrough.rs index b1381b45..d217d883 100644 --- a/crates/aisix-proxy/src/passthrough.rs +++ b/crates/aisix-proxy/src/passthrough.rs @@ -164,6 +164,7 @@ pub async fn passthrough( status, elapsed, &request_id, + None, ); state.metrics.record_request( &provider_label, @@ -203,6 +204,7 @@ pub async fn passthrough( status, elapsed, &request_id, + Some(&err), ); state.metrics.record_request( &provider, @@ -698,6 +700,7 @@ fn copy_safe_headers(src: &HeaderMap, dst: &mut HeaderMap) { } } +#[allow(clippy::too_many_arguments)] fn emit_access_log( method: &Method, path: &str, @@ -706,7 +709,15 @@ fn emit_access_log( status: u16, elapsed: Duration, request_id: &str, + error: Option<&ProxyError>, ) { + let (error_kind, error) = match error { + Some(e) => { + let (kind, msg) = crate::attempt::access_log_error(e); + (Some(kind), Some(msg)) + } + None => (None, None), + }; AccessLog { method: method.as_str(), path, @@ -722,6 +733,8 @@ fn emit_access_log( served_by_model: None, routing_attempt_count: None, routing_fallback_count: None, + error_kind, + error: error.as_deref(), } .emit(); } diff --git a/crates/aisix-proxy/src/realtime.rs b/crates/aisix-proxy/src/realtime.rs index b0b4a7d1..2c8283a0 100644 --- a/crates/aisix-proxy/src/realtime.rs +++ b/crates/aisix-proxy/src/realtime.rs @@ -57,6 +57,7 @@ use crate::auth::AuthenticatedKey; use crate::client_ip::ClientContext; use crate::error::ProxyError; use crate::state::ProxyState; +use aisix_gateway::BridgeError; /// Azure Realtime GA api-version (see the jobs surface twin constant). const AZURE_REALTIME_API_VERSION: &str = "2024-10-01-preview"; @@ -93,7 +94,14 @@ pub(crate) async fn realtime( } Err(err) => { let status = err.status().as_u16(); - emit_access_log(&Method::GET, status, started.elapsed(), &request_id, None); + emit_access_log( + &Method::GET, + status, + started.elapsed(), + &request_id, + None, + Some(&err), + ); crate::usage_attr::emit_error_usage_event( &state, "realtime", @@ -401,18 +409,22 @@ async fn run_session( reason: "upstream connect failed".into(), }))) .await; - crate::cooldown::note_failure( + // `note_failure` hands the error back, so the same value that + // drove the cooldown decision also names the failure in the + // access log instead of being rebuilt. + let connect_err = ProxyError::Bridge(crate::cooldown::note_failure( &state.runtime_status, &model_entry.id, model_entry.value.cooldown.as_ref(), aisix_gateway::BridgeError::Transport(aisix_gateway::error_with_causes(&e)), - ); + )); emit_access_log( &Method::GET, 502, started.elapsed(), &request_id, Some((&provider_label, &requested_model)), + Some(&connect_err), ); crate::usage_attr::emit_error_usage_event( &state, @@ -433,6 +445,19 @@ async fn run_session( let mut usage = SessionUsage::default(); let mut monitor_hits: Vec = Vec::new(); let mut close_status: u16 = 200; + // Paired with `close_status`: every branch that sets a FAILING status + // also names the failure, so the access log can say why a session + // ended (AISIX-Cloud#1093). + // + // A client-side transport error (`Some(Err(_))` on the receive half) + // is deliberately not one of them: it keeps `close_status` 200 and + // stays `None`. Reclassifying it is a behaviour change, not a logging + // one — `RequestOutcome::from_status` would flip that session from + // `success` to `client_error` and move every operator's realtime + // success rate. That belongs with the termination-reason taxonomy + // (`downstream_remote_disconnect` and friends) the issue asks for + // separately, which needs its own status decision. + let mut session_error: Option = None; // Operator-configured stream idle deadline (stream_timeout on the // Model). Absent → no idle cap; realtime sessions are long-lived by // design. @@ -456,6 +481,10 @@ async fn run_session( }))) .await; close_status = 504; + session_error = Some(ProxyError::Bridge(BridgeError::Timeout { + elapsed_ms: cap.as_millis() as u64, + cause: "no realtime frame within the stream idle budget".into(), + })); break; } }, @@ -483,6 +512,9 @@ async fn run_session( }))) .await; close_status = 400; + session_error = Some(ProxyError::ContentFiltered( + "realtime frame blocked by a guardrail".into(), + )); break; } } @@ -526,6 +558,9 @@ async fn run_session( }))) .await; close_status = 400; + session_error = Some(ProxyError::ContentFiltered( + "realtime frame blocked by a guardrail".into(), + )); break; } } @@ -557,6 +592,9 @@ async fn run_session( }))) .await; close_status = 502; + session_error = Some(ProxyError::Bridge(BridgeError::Transport( + aisix_gateway::error_with_causes(&e), + ))); break; } None => { @@ -577,6 +615,7 @@ async fn run_session( elapsed, &request_id, Some((&provider_label, &requested_model)), + session_error.as_ref(), ); state.metrics.record_request( &provider_label, @@ -681,7 +720,15 @@ fn emit_access_log( elapsed: Duration, request_id: &str, target: Option<(&str, &str)>, + error: Option<&ProxyError>, ) { + let (error_kind, error) = match error { + Some(e) => { + let (kind, msg) = crate::attempt::access_log_error(e); + (Some(kind), Some(msg)) + } + None => (None, None), + }; AccessLog { method: method.as_str(), path: "/v1/realtime", @@ -697,6 +744,8 @@ fn emit_access_log( served_by_model: None, routing_attempt_count: None, routing_fallback_count: None, + error_kind, + error: error.as_deref(), } .emit(); } diff --git a/crates/aisix-proxy/src/rerank.rs b/crates/aisix-proxy/src/rerank.rs index 90262fab..d8e1e4ff 100644 --- a/crates/aisix-proxy/src/rerank.rs +++ b/crates/aisix-proxy/src/rerank.rs @@ -95,6 +95,7 @@ pub async fn rerank( status, elapsed, &request_id, + None, ); state.metrics.record_request( &success.provider, @@ -139,6 +140,7 @@ pub async fn rerank( status, elapsed, &request_id, + Some(&err), ); let snap = state.snapshot.load(); let metric_model = crate::usage_attr::metric_model_label(&snap, &model_name); @@ -644,7 +646,15 @@ fn emit_access_log( status: u16, elapsed: Duration, request_id: &str, + error: Option<&ProxyError>, ) { + let (error_kind, error) = match error { + Some(e) => { + let (kind, msg) = crate::attempt::access_log_error(e); + (Some(kind), Some(msg)) + } + None => (None, None), + }; AccessLog { method: "POST", path: "/v1/rerank", @@ -660,6 +670,8 @@ fn emit_access_log( served_by_model: None, routing_attempt_count: None, routing_fallback_count: None, + error_kind, + error: error.as_deref(), } .emit(); } diff --git a/crates/aisix-proxy/src/responses.rs b/crates/aisix-proxy/src/responses.rs index 8452665c..310cacf3 100644 --- a/crates/aisix-proxy/src/responses.rs +++ b/crates/aisix-proxy/src/responses.rs @@ -187,6 +187,7 @@ pub async fn responses( elapsed, &request_id, &success.routing, + None, ); state.metrics.record_request( &success.provider, @@ -278,6 +279,7 @@ pub async fn responses( elapsed, &request_id, &routing, + Some(&err), ); let snap = state.snapshot.load(); let metric_model = crate::usage_attr::metric_model_label(&snap, &model_name); @@ -2799,6 +2801,7 @@ fn emit_failed_attempts( } } +#[allow(clippy::too_many_arguments)] fn emit_access_log( model: &str, provider: &str, @@ -2807,7 +2810,15 @@ fn emit_access_log( elapsed: Duration, request_id: &str, routing: &RoutingTelemetry, + error: Option<&ProxyError>, ) { + let (error_kind, error) = match error { + Some(e) => { + let (kind, msg) = crate::attempt::access_log_error(e); + (Some(kind), Some(msg)) + } + None => (None, None), + }; // Per #655 the access log stays ONE line per request, carrying the // user-perceived `latency` + final status plus a routing summary. let served_by = routing @@ -2835,6 +2846,8 @@ fn emit_access_log( 0 => None, n => Some(n), }, + error_kind, + error: error.as_deref(), } .emit(); } diff --git a/crates/aisix-proxy/src/videos.rs b/crates/aisix-proxy/src/videos.rs index bc20091f..aff2637b 100644 --- a/crates/aisix-proxy/src/videos.rs +++ b/crates/aisix-proxy/src/videos.rs @@ -1011,8 +1011,15 @@ struct Telemetry<'a> { } impl Telemetry<'_> { - fn finish(&self, status: u16, provider: &str, model_label: &str) { + fn finish(&self, status: u16, provider: &str, model_label: &str, error: Option<&ProxyError>) { let elapsed = self.started.elapsed(); + let (error_kind, error) = match error { + Some(e) => { + let (kind, msg) = crate::attempt::access_log_error(e); + (Some(kind), Some(msg)) + } + None => (None, None), + }; AccessLog { method: self.method, path: &self.path, @@ -1028,6 +1035,8 @@ impl Telemetry<'_> { served_by_model: None, routing_attempt_count: None, routing_fallback_count: None, + error_kind, + error: error.as_deref(), } .emit(); self.state.metrics.record_request( @@ -1069,6 +1078,7 @@ pub async fn create_video( err.status().as_u16(), "unknown", crate::usage_attr::UNRESOLVED_MODEL_LABEL, + Some(&err), ); return err.into_response(); } @@ -1090,7 +1100,7 @@ pub async fn create_video( .get_by_id(&success.model_id) .map(|e| e.value.display_name.clone()) .unwrap_or_else(|| crate::usage_attr::UNRESOLVED_MODEL_LABEL.to_string()); - telemetry.finish(status, &success.provider, &model_label); + telemetry.finish(status, &success.provider, &model_label, None); // One zero-token UsageEvent per accepted submit — visible in // /logs and the budget ledger like every other endpoint. // Per-second cost is computed control-plane-side once the @@ -1117,7 +1127,7 @@ pub async fn create_video( let status = err.status().as_u16(); let snap = state.snapshot.load(); let metric_model = crate::usage_attr::metric_model_label(&snap, &model_name); - telemetry.finish(status, "unknown", metric_model); + telemetry.finish(status, "unknown", metric_model, Some(&err)); // #655 parity: failed submits surface in Logs as zero-token // events instead of vanishing. crate::usage_attr::emit_error_usage_event( @@ -1367,7 +1377,7 @@ pub async fn get_video( match result { Ok((resp, provider, model_label)) => { - telemetry.finish(resp.status().as_u16(), &provider, &model_label); + telemetry.finish(resp.status().as_u16(), &provider, &model_label, None); resp } Err(err) => { @@ -1375,6 +1385,7 @@ pub async fn get_video( err.status().as_u16(), "unknown", crate::usage_attr::UNRESOLVED_MODEL_LABEL, + Some(&err), ); err.into_response() } @@ -1469,7 +1480,7 @@ pub async fn video_content( match result { Ok((resp, provider, model_label)) => { - telemetry.finish(resp.status().as_u16(), &provider, &model_label); + telemetry.finish(resp.status().as_u16(), &provider, &model_label, None); resp } Err(err) => { @@ -1477,6 +1488,7 @@ pub async fn video_content( err.status().as_u16(), "unknown", crate::usage_attr::UNRESOLVED_MODEL_LABEL, + Some(&err), ); err.into_response() }