fix(obs): log the requests refused before dispatch - #863
Conversation
A body-cap rejection is answered either by the `enforce_request_body_limit` middleware (declared Content-Length over the cap — every non-streamed SDK POST) or by a handler's body extractor (chunked / lying Content-Length). Both return before the dispatch tail that emits the access log and `record_request`, so the caller got a 413 the gateway kept no record of: no access-log line, no metric sample. "Client reports 413, gateway shows nothing" is indistinguishable from the request never arriving. Route every pre-dispatch rejection through one helper (`reject.rs`) that renders the caller's envelope AND emits the telemetry, so the two can't drift apart: the middleware's two short-circuits (413 and the conflicting Content-Length 400) plus the extractor rejections in chat, completions, embeddings, responses, rerank, images, audio speech, messages, count_tokens, batches and fine-tuning jobs. The endpoints that already wrap their whole dispatch — /mcp, /a2a, /passthrough, /v1/videos, /v1/files — logged these correctly and are untouched. The middleware runs ahead of authentication, so its lines carry no api_key_id; the handler-side ones do. Latency spans the body drain, which is what an oversize request actually costs the gateway. Nothing on the wire changes: same status, same envelope. Response bodies stay out of the log — only method, path, status, latency, request id and the failure. chat.rs and embeddings.rs also drop their inlined copies of the 413-vs-400 discrimination for the shared `proxy_error_from_json_rejection` the sibling routes already use. The E2E harness gains a `logLevel` override, because the access log is an info-level line and the harness pins RUST_LOG=warn — which silently outranks `observability.log_level`.
The unit assertion moves from the access-log line to the request metric: both are emitted by the same helper, but the log line rides process-global tracing state, so a parallel unit test can lose it to another test's subscriber guard. The line itself is pinned end-to-end in the body-edges E2E instead — now for the chunked path too, whose refusal is recorded by the handler rather than the middleware.
|
Warning Review limit reachedYou’ve reached a temporary PR review limit under our Fair Usage Limits Policy. Next review available in: 34 minutes Enable usage-based reviews in Billing to review now. Otherwise, wait until the next included review is available. How can I continue?After more reviews become available, a review can be triggered using the To avoid repeated limits, reduce automatic review volume by pausing incremental auto-reviews earlier, using label-based review opt-in, excluding WIP or generated PR titles, or requesting reviews manually when the PR is ready. If your team needs uninterrupted high-volume reviews, an organization admin can enable usage-based reviews. How do review limits work?CodeRabbit enforces per-developer PR review limits for each organization. Most developers receive the normal plan review availability. For paid Pro and Pro+ PR reviews, CodeRabbit uses adaptive limits for sustained high-volume activity. When a developer's recent PR review activity reaches the 95th percentile or higher among CodeRabbit users, additional reviews become available more gradually as earlier reviews age out of the rolling window. Please refer docs for additional details. Review details⚙️ Run configurationConfiguration used: Organization UI Review profile: CHILL Plan: Pro Run ID: 📒 Files selected for processing (15)
Comment |
1 participant
Problem
A request whose body exceeds
request_body_limit_bytesgets a correct 413 and leaves no trace in the gateway. The access log andaisix_requests_totalare emitted by the handler at the end of dispatch — that is the only place that knows provider, model and token counts — and a body-cap rejection never gets there:enforce_request_body_limitshort-circuits before any handler runs.So "the client reports a 413 the gateway has no record of" was indistinguishable from the request never arriving. The conflicting-Content-Length 400 had the same hole.
Change
One helper —
reject::reject_before_dispatch— renders the caller's envelope and emits the access log + request metrics, so the two can't drift apart. Every pre-dispatch rejection answers through it:/mcp,/a2a,/passthrough,/v1/videosand/v1/fileswrap their whole dispatch and already recorded these — untouched, and adding a second emit there would double-log.chat.rsandembeddings.rsalso drop their inlined copies of the 413-vs-400 discrimination for the sharedproxy_error_from_json_rejectionthe sibling routes already use.Behaviour
Nothing changes on the wire: same status, same envelope, same body. What is new is one access-log line and one
aisix_requests_total{provider="unknown",model="unresolved",status="413"}sample per refused request.api_key_id; the handler-side ones do./logsand the budget ledger are unchanged.error_kindstays the coarseinvalid_request_errorthe OpenAI envelope pins; the cap hit is named inerror.Tests
status="413"sample. The metric rather than the log line, because the two are emitted by the same helper while the line rides process-global tracing state that a parallel unit test can lose.body-edges): the oversize request's access-log line is joined to the caller'sx-aisix-request-idand checked for status, path and reason, plus the metric; a second case covers the chunked path, whose refusal is recorded by the handler.logLeveloverride: the access log is an info-level line and the harness pinsRUST_LOG=warn, which silently outranksobservability.log_level.Mainstream gateways short-circuit an oversize request the same way and rely on their HTTP server's built-in access log to record it; this gateway has no server-level access log, so it has to emit the line itself.