fix(observability): name the failure on the access log line#819
Merged
Conversation
A failed request left `status=… latency_ms=…` as its entire trace. That
line is identical whether the upstream returned 502, DNS failed, a pooled
connection was reaped, or the kernel gave up on an unanswered SYN — and
on the `/v1/messages` native path it is the ONLY record, because that
handler emits no WARN either. Diagnosing AISIX-Cloud#1093 from a customer
log capture meant reading hyper's connection-layer TRACE output to
recover what the gateway already knew at the point it logged the line.
`AccessLog` gains `error_kind` + `error`, filled from the `ProxyError`
every handler already holds on its failure branch:
status=502 latency_ms=6747 … error_kind="upstream_status"
error="upstream returned HTTP 502: upstream exploded"
`error_kind` is `ProxyError::kind` — a stable token to filter or alert
on; `error` is the reason. Success lines carry neither, so `error_kind=`
means "something failed" and nothing else.
Wired through all 15 handlers rather than just the reported one: the gap
was in the shared struct, so every endpoint had it. `/mcp` and `/a2a`
are the two that stay `None` — their dispatch returns an already-rendered
`Response`, so no typed error reaches the log point; noted inline.
`attempt::access_log_error` is deliberately not `attempt_error_from_proxy`:
that one leaves the message empty for non-bridge variants, which is right
for a per-attempt record but would put a failed request straight back to
naming no cause. It reuses the existing control-char strip + 2048 cap so
the line stays one-line-greppable and #1065's double-clipping doesn't
come back.
Tests: access-log rendering (failure fields present, absent on success),
and the class/reason extraction incl. control-char stripping, the cap,
and the `Timeout.cause` added for this issue surviving into the line.
No handler-level log-capture test: a scoped subscriber cannot observe
events emitted through the axum router under the full suite — the
callsite interest for `AccessLog::emit` is cached process-wide by
whichever test reaches it first, so the capture comes back empty (each
test passes alone). Handler wiring is enforced by the type system
instead: every call site must pass `Option<&ProxyError>` explicitly.
Fixes api7/AISIX-Cloud#1093
📝 WalkthroughWalkthroughAccess logs gain optional ChangesStructured access-log error metadata
Estimated code review effort: 3 (Moderate) | ~30 minutes Possibly related PRs
Suggested reviewers: 🚥 Pre-merge checks | ✅ 5 | ❌ 1❌ Failed checks (1 warning)
✅ Passed checks (5 passed)
✨ Finishing Touches🧪 Generate unit tests (beta)
Comment |
![coderabbitai[bot]](https://avatars.githubusercontent.com/in/347564?s=60&v=4){kind=small}
There was a problem hiding this comment.
Actionable comments posted: 2
Caution
Some comments are outside the diff and can’t be posted inline due to platform limitations.
⚠️ Outside diff range comments (2)
crates/aisix-proxy/src/chat.rs (1)
415-428: 🗄️ Data Integrity & Integration | 🟠 Major | ⚡ Quick winLog typed pre-dispatch failures as well.
These calls cover only
dispatchfailures.chat_completionsreturns typed JSON-rejection errors before this branch, whilecount_tokensreturns typed auth/body-rejection errors before its dispatch call; those common 400/401/403/413 responses still produce no handler access record or failure metadata.
crates/aisix-proxy/src/chat.rs#L415-L428: emit an access record before the JSON-rejection return, usingclient.request_idand unknown routing/provider metadata.crates/aisix-proxy/src/count_tokens.rs#L115-L125: emit an access record before auth and body-rejection returns, using unknown metadata when authentication did not resolve.🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the rest with a brief reason, keep changes minimal, and validate. In `@crates/aisix-proxy/src/chat.rs` around lines 415 - 428, Emit access records for typed pre-dispatch failures before their JSON-rejection returns: in crates/aisix-proxy/src/chat.rs at lines 415-428, update chat_completions to use client.request_id with unknown routing/provider metadata; in crates/aisix-proxy/src/count_tokens.rs at lines 115-125, add equivalent logging before auth and body-rejection returns, using unknown metadata when authentication has not resolved.crates/aisix-proxy/src/audio.rs (1)
1186-1211: 📐 Maintainability & Code Quality | 🟠 Major | 🏗️ Heavy liftAdd source-blind endpoint tests for the propagated fields.
The helper tests validate rendering and sanitization, but not that each handler emits
Some(&err)on failure and omits both fields on success. Add observable access-log tests for all changed routes, including both streaming and non-streaming chat paths.
crates/aisix-proxy/src/audio.rs#L1186-L1211: cover transcription, translation, and speech success/failure logs.crates/aisix-proxy/src/chat.rs#L3854-L3889: cover chat success and typed failures in streaming and non-streaming modes.crates/aisix-proxy/src/completions.rs#L659-L688: cover completion success/failure logs.crates/aisix-proxy/src/count_tokens.rs#L436-L461: cover count-token success/failure logs.crates/aisix-proxy/src/images.rs#L465-L490: cover image-generation success/failure logs.As per coding guidelines, “test every wired endpoint,” including streaming and non-streaming branches.
🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the rest with a brief reason, keep changes minimal, and validate. In `@crates/aisix-proxy/src/audio.rs` around lines 1186 - 1211, Add source-blind endpoint tests verifying access logs emit Some(&err) for failures and omit both error fields on success. Cover transcription, translation, and speech in crates/aisix-proxy/src/audio.rs:1186-1211; streaming and non-streaming chat success and typed failures in crates/aisix-proxy/src/chat.rs:3854-3889; completion success/failure in crates/aisix-proxy/src/completions.rs:659-688; count-token success/failure in crates/aisix-proxy/src/count_tokens.rs:436-461; and image-generation success/failure in crates/aisix-proxy/src/images.rs:465-490, exercising each handler’s wired endpoint branches.Source: Coding guidelines
🤖 Prompt for all review comments with AI agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
Inline comments:
In `@crates/aisix-proxy/src/attempt.rs`:
- Around line 161-165: Update sanitize_error_message so its character filter
excludes Unicode line separators U+2028 and U+2029 in addition to control
characters, then apply the existing MAX_ATTEMPT_ERROR_MESSAGE_CHARS cap and
collection behavior unchanged.
In `@crates/aisix-proxy/src/realtime.rs`:
- Line 591: Update run_session’s shared completion path to retain an
Option<ProxyError> for post-upgrade failures: create sanitized errors in the
idle-timeout and upstream-stream-error branches, while leaving successful
completion as None, then pass that option instead of the unconditional None so
the access log includes error_kind and error.
---
Outside diff comments:
In `@crates/aisix-proxy/src/audio.rs`:
- Around line 1186-1211: Add source-blind endpoint tests verifying access logs
emit Some(&err) for failures and omit both error fields on success. Cover
transcription, translation, and speech in
crates/aisix-proxy/src/audio.rs:1186-1211; streaming and non-streaming chat
success and typed failures in crates/aisix-proxy/src/chat.rs:3854-3889;
completion success/failure in crates/aisix-proxy/src/completions.rs:659-688;
count-token success/failure in crates/aisix-proxy/src/count_tokens.rs:436-461;
and image-generation success/failure in
crates/aisix-proxy/src/images.rs:465-490, exercising each handler’s wired
endpoint branches.
In `@crates/aisix-proxy/src/chat.rs`:
- Around line 415-428: Emit access records for typed pre-dispatch failures
before their JSON-rejection returns: in crates/aisix-proxy/src/chat.rs at lines
415-428, update chat_completions to use client.request_id with unknown
routing/provider metadata; in crates/aisix-proxy/src/count_tokens.rs at lines
115-125, add equivalent logging before auth and body-rejection returns, using
unknown metadata when authentication has not resolved.
🪄 Autofix (Beta)
Fix all unresolved CodeRabbit comments on this PR:
- Push a commit to this branch (recommended)
- Create a new PR with the fixes
ℹ️ Review info
⚙️ Run configuration
Configuration used: Organization UI
Review profile: CHILL
Plan: Pro
Run ID: 72167c1e-bcce-42ef-8c78-5d52c24b3304
📒 Files selected for processing (17)
crates/aisix-obs/src/access_log.rscrates/aisix-proxy/src/a2a.rscrates/aisix-proxy/src/attempt.rscrates/aisix-proxy/src/audio.rscrates/aisix-proxy/src/chat.rscrates/aisix-proxy/src/completions.rscrates/aisix-proxy/src/count_tokens.rscrates/aisix-proxy/src/embeddings.rscrates/aisix-proxy/src/images.rscrates/aisix-proxy/src/jobs.rscrates/aisix-proxy/src/mcp.rscrates/aisix-proxy/src/messages.rscrates/aisix-proxy/src/passthrough.rscrates/aisix-proxy/src/realtime.rscrates/aisix-proxy/src/rerank.rscrates/aisix-proxy/src/responses.rscrates/aisix-proxy/src/videos.rs
Review catch on the previous commit: `run_session` sets `close_status` to 504 (idle timeout), 502 (upstream stream error), or 400 (guardrail block), but the shared completion path passed `None` — so exactly the failures this PR exists to explain stayed nameless on the realtime endpoint. A `session_error` now travels beside `close_status`, set in all four failing branches, `None` only for a clean close. CodeRabbit flagged the 504/502 pair; the two 400 guardrail blocks are the same class and are wired here too. Also strip U+2028/U+2029 in `sanitize_error_message`. They are `Zl`/`Zp`, not `Cc`, so `is_control()` forwards them and a viewer that breaks lines on them would split a record — the exact property the sanitizer exists to guarantee.
There was a problem hiding this comment.
Actionable comments posted: 1
🤖 Prompt for all review comments with AI agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
Inline comments:
In `@crates/aisix-proxy/src/realtime.rs`:
- Around line 448-451: The realtime client receive error path must not leave
session_error as None while reporting a successful close status. Update the
client receive branch handling Some(Err(_)) to record a dedicated client-side
ProxyError and corresponding failing close status, or explicitly preserve and
document the exclusion if intentional; add an E2E assertion covering the chosen
behavior.
🪄 Autofix (Beta)
Fix all unresolved CodeRabbit comments on this PR:
- Push a commit to this branch (recommended)
- Create a new PR with the fixes
ℹ️ Review info
⚙️ Run configuration
Configuration used: Organization UI
Review profile: CHILL
Plan: Pro
Run ID: 3317d628-44d1-4ad3-8716-4681583bee11
📒 Files selected for processing (2)
crates/aisix-proxy/src/attempt.rscrates/aisix-proxy/src/realtime.rs
🚧 Files skipped from review as they are similar to previous changes (1)
- crates/aisix-proxy/src/attempt.rs
Review follow-up: the comment claimed `session_error` is `None` only for a clean close, which is not true — a client-side transport error (`Some(Err(_))` on the receive half) also leaves it `None`, keeping `close_status` 200. Documented rather than reclassified. Turning that into a failure is a behaviour change, not a logging one: `RequestOutcome::from_status` would flip those sessions from `success` to `client_error` and move every operator's realtime success rate. It belongs with the termination-reason taxonomy (`downstream_remote_disconnect` and friends) AISIX-Cloud#1093 asks for separately, which needs its own status decision.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Problem
A failed request left
status=… latency_ms=…as its entire trace. That line is identical whether the upstream returned 502, DNS failed, a pooled connection was reaped, or the kernel gave up on an unanswered SYN.On the
/v1/messagesnative path it is also the only record — that handler emits no WARN either. Diagnosing AISIX-Cloud#1093 from a customer log capture meant turning on hyper's connection-layer TRACE and readingconnect error for …: ConnectError("tcp connect error", Os { code: 110, kind: TimedOut })to recover a cause the gateway already held in hand at the moment it wrote the access log.Change
AccessLoggainserror_kind+error, filled from theProxyErrorevery handler already has on its failure branch:error_kind—ProxyError::kind, a stable token to filter or alert on without parsing prose.error— the reason.error_kind=means "something failed" and nothing else.Wired through all 15 handlers, not just the reported one: the gap was in the shared struct, so every endpoint had it.
/mcpand/a2aare the two that stayNone— theirdispatchreturns an already-renderedResponse, so no typed error reaches the log point (noted inline). On/v1/realtime,session_errortravels besideclose_statusand is set in all four failing branches (504 idle timeout, 502 upstream stream error, both 400 guardrail blocks).attempt::access_log_erroris deliberately notattempt_error_from_proxy: that one leaves the message empty for every non-bridge variant, which is right for a per-attempt record (the class is the point) but would put a failed request straight back to naming no cause. It reuses the existing control-char strip + 2048 cap, so the line stays one-line-greppable and #1065's double-clipping does not return. U+2028/U+2029 are stripped explicitly — they areZl/Zp, sois_control()forwards them.Behaviour
Additive only — a new pair of optional fields on an existing log line. No status, envelope, or telemetry change. The reason text is the same
Displayalready sent to the client and toUsageEvent.error_message, so no new information is exposed.Scope boundary
The issue also asks for a termination-reason taxonomy (
downstream_remote_disconnect,upstream_disconnect,gateway_timeout) so a client cancellation stops showing up as a plain 200. That is not in this PR. It is a behaviour change rather than a logging one: a client-side transport error on/v1/realtimecurrently keepsclose_status200, andRequestOutcome::from_statusmaps that tosuccess, so giving it a failing status would move every operator's realtime success rate and the alerts on it. Each reason needs its own status decision, and it reaches past realtime. Called out explicitly in-code at the one place it bites.Tests
ProxyErrorvariant contributes a message, control chars and U+2028/U+2029 stripped, cap enforced, and theTimeout.causeadded for this issue survives into the lineTest exception: no handler-level log-capture test. A scoped subscriber cannot observe events emitted through the axum router under the full suite —
AccessLog::emit's callsite interest is cached process-wide by whichever test reaches it first, so the capture comes back empty (verified: same thread, global max-levelINFO,emit_access_logprovably invoked with the right status; each test passes when run alone, and a direct synchronousemit()captures fine). Handler wiring is enforced by the type system instead: every call site must passOption<&ProxyError>explicitly, and the compiler enumerated all 36 of them.Fixes api7/AISIX-Cloud#1093