fix(observability): name the failure on the access log line

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<u32>,
+    /// 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();
         });

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,

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(&not_found);
+        assert_eq!(kind, "model_not_found");
+        assert!(msg.contains("ghost"), "{msg}");
+        assert!(
+            attempt_error_from_proxy(&not_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,

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();
 }

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<u64>,
     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();
 }

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();
 }