fix(proxy): write an access-log line for every request the proxy surface answers

crates/aisix-proxy/AGENTS.md

@@ -237,6 +237,19 @@ telemetry, so the two can't drift apart):
   `Result<Json<T>, JsonRejection>` / `Result<Bytes, BytesRejection>` parameters.
   Auth already ran here, so pass the key id.
 
+Authentication denials are the one early exit that writes its own line: the
+`AuthenticatedKey` extractor emits it on every `Err` it returns, so a handler
+must not emit again for an auth failure (`/v1/messages` re-renders the error,
+it does not log it). A surface that authenticates without the extractor
+(`/v1/realtime`, passthrough routes) writes its line in its own error arm.
+
+A route that answers without dispatching at all — `/v1/models`, the A2A
+agent card, the OAuth discovery documents, the unrouted-path 404, the router's
+405 (`method_not_allowed_fallback`, which must stay the LAST call before the
+layers or later routes miss it) — writes its line through
+`reject::emit_unrouted_access_log`. `/livez` and `/readyz` deliberately write
+none: they are platform probes, not client traffic.
+
 A handler that instead wraps its whole dispatch and logs the wrapper's status
 (`/mcp`, `/a2a`, `/passthrough`, `/v1/videos`, `/v1/files`) is already covered —
 don't add a second emit to those, or the request logs twice.

crates/aisix-proxy/src/a2a.rs

@@ -673,18 +673,43 @@ pub async fn a2a_agent_card(
     State(state): State<ProxyState>,
     uri: axum::http::Uri,
     headers: HeaderMap,
+    method: axum::http::Method,
+    request_id: Option<axum::Extension<crate::request_id::RequestId>>,
+) -> Response {
+    let started = Instant::now();
+    let response = agent_card(&auth, &agent, &state, &uri, &headers).await;
+    crate::reject::emit_unrouted_access_log(
+        method.as_str(),
+        uri.path(),
+        request_id
+            .as_ref()
+            .map(|r| r.0 .0.as_str())
+            .unwrap_or_default(),
+        Some(&auth.entry.id),
+        response.status().as_u16(),
+        started,
+    );
+    response
+}
+
+async fn agent_card(
+    auth: &AuthenticatedKey,
+    agent: &str,
+    state: &ProxyState,
+    uri: &axum::http::Uri,
+    headers: &HeaderMap,
 ) -> Response {
     // Discovery files no usage row on any outcome, and it normalizes to the
     // same `/a2a` label the calls do — so it has to say so, or a caller that
     // hangs up during the card fetch below (a real upstream round trip) is
     // filed as an abandoned agent call (AISIX-Cloud#1571).
     crate::attribution::note_unmetered_route();
     let snapshot = state.snapshot.load();
-    let entry = match snapshot.a2a_agents.get_by_name(&agent) {
+    let entry = match snapshot.a2a_agents.get_by_name(agent) {
         Some(entry) if entry.value.enabled => entry,
         _ => return (StatusCode::NOT_FOUND, format!("unknown A2A agent: {agent}")).into_response(),
     };
-    if !auth.key().can_access_agent(&agent) {
+    if !auth.key().can_access_agent(agent) {
         return (
             StatusCode::FORBIDDEN,
             format!("this key may not reach A2A agent: {agent}"),
@@ -694,7 +719,7 @@ pub async fn a2a_agent_card(
     // Resolved BEFORE the upstream is contacted: without a public base there is
     // no card this gateway can serve, and finding that out after the fetch only
     // wastes an upstream round trip.
-    let Some(base) = gateway_base(&uri, &headers) else {
+    let Some(base) = gateway_base(uri, headers) else {
         tracing::warn!(
             agent = %agent,
             "cannot derive the gateway's public base for an A2A agent card; refusing to serve one"
@@ -709,7 +734,7 @@ pub async fn a2a_agent_card(
     let upstream = upstream_from_a2a_agent(&entry.value);
 
     let bridge = HttpBridge::new(upstream).with_forwarded_client_headers(
-        aisix_a2a::forwarded_client_headers(&entry.value, Some(&headers)),
+        aisix_a2a::forwarded_client_headers(&entry.value, Some(headers)),
     );
     let mut card = match bridge.fetch_agent_card().await {
         Ok(card) => card,

crates/aisix-proxy/src/auth.rs

@@ -73,15 +73,9 @@ impl std::fmt::Debug for JwtIdentity {
     }
 }
 
-/// Per-request context carried onto an authentication denial.
-///
-/// A 401 short-circuits ahead of every handler, so the request never
-/// reaches an access-log emit; AISIX-Cloud#1081 deliberately kept these out
-/// of the access log because an internet-facing DP would drown in scanner
-/// probes, leaving `aisix_auth_decisions_total` as the only record. That
-/// metric answers "how many" but not "who, when, against what" — so the
-/// denial log line, which an operator turns on precisely when investigating,
-/// carries the identifying detail instead.
+/// Per-request context carried onto an authentication denial's
+/// `aisix::auth` log line, beside the access-log line the extractor writes
+/// for the same request (see [`emit_denial_access_log`]).
 #[derive(Clone, Copy)]
 pub(crate) struct DenialContext<'a> {
     pub method: &'a str,
@@ -132,57 +126,115 @@ where
     type Rejection = ProxyError;
 
     async fn from_request_parts(parts: &mut Parts, state: &S) -> Result<Self, Self::Rejection> {
-        let proxy_state = ProxyState::from_ref(state);
-        let request_id = parts
-            .extensions
-            .get::<crate::request_id::RequestId>()
-            .map(|r| r.0.as_str())
-            .unwrap_or_default();
-        let ctx = DenialContext {
-            method: parts.method.as_str(),
-            path: parts.uri.path(),
-            request_id,
-            // Deferred: only a denial resolves the source IP.
-            source_ip: LazySourceIp::Deferred(&*parts, proxy_state.real_ip.as_ref()),
-        };
-        let token = match extract_bearer(parts) {
-            Ok(t) => t,
-            Err(e) => {
-                // No credential at all: metric + a debug line, never the
-                // access log — logging every scanner probe at the default
-                // level would be noise (AISIX-Cloud#1081).
-                proxy_state
-                    .metrics
-                    .record_auth_decision("none", false, "missing_credentials");
-                tracing::debug!(
-                    target: "aisix::auth",
-                    method = "none",
-                    reason = "missing_credentials",
-                    http_method = %ctx.method,
-                    path = %ctx.path,
-                    request_id = %ctx.request_id,
-                    source_ip = %ctx.source_ip.resolve(),
-                    "rejected inbound request without a credential",
-                );
-                return Err(e);
-            }
-        };
-        let authed = authenticate_token(&proxy_state, &token, ctx).await?;
-        // Publish the resolved key so extractors that run after this one can
-        // see who is calling without re-authenticating. `ClientContext` reads
-        // it for the `${request.api_key.*}` header templates
-        // (AISIX-Cloud#1112) — which is why every handler declares
-        // `auth: AuthenticatedKey` before `client: ClientContext`.
-        parts.extensions.insert(authed.entry.clone());
-        // Same for the JWT identity: `ClientContext` carries it to each
-        // handler's usage-event emitter for attribution.
-        if let Some(jwt) = &authed.jwt {
-            parts.extensions.insert(jwt.clone());
+        let started = std::time::Instant::now();
+        let result = extract_authenticated_key(parts, state).await;
+        if let Err(err) = &result {
+            emit_denial_access_log(parts, started, err);
         }
-        Ok(authed)
+        result
     }
 }
 
+/// Write the access-log line for a request the extractor refused.
+///
+/// The refusal short-circuits ahead of the handler, which is where every
+/// other line is written, so without this an authentication denial left no
+/// access-log record at all. Nothing about the caller is resolved yet: the
+/// line carries no key id (a disabled or expired key's id is on the
+/// `aisix::auth` warn line), and never any part of the presented credential.
+fn emit_denial_access_log(parts: &Parts, started: std::time::Instant, err: &ProxyError) {
+    let request_id = parts
+        .extensions
+        .get::<crate::request_id::RequestId>()
+        .map(|r| r.0.as_str())
+        .unwrap_or_default();
+    let elapsed = started.elapsed();
+    let (error_kind, error) = crate::attempt::access_log_error(err);
+    crate::attribution::emit_access_log(aisix_obs::AccessLog {
+        method: parts.method.as_str(),
+        path: parts.uri.path(),
+        status: err.status().as_u16(),
+        latency: elapsed,
+        duration: elapsed,
+        provider: None,
+        model: None,
+        upstream_model: None,
+        provider_key_id: None,
+        api_key_id: None,
+        prompt_tokens: None,
+        completion_tokens: None,
+        total_tokens: None,
+        request_id,
+        provider_request_id: None,
+        served_by_model: None,
+        routing_attempt_count: None,
+        routing_fallback_count: None,
+        error_kind: Some(error_kind),
+        error: Some(&error),
+        mcp: None,
+        cache: None,
+        request_body_bytes: None,
+        response_body_bytes: None,
+    });
+}
+
+async fn extract_authenticated_key<S>(
+    parts: &mut Parts,
+    state: &S,
+) -> Result<AuthenticatedKey, ProxyError>
+where
+    S: Send + Sync,
+    ProxyState: FromRef<S>,
+{
+    let proxy_state = ProxyState::from_ref(state);
+    let request_id = parts
+        .extensions
+        .get::<crate::request_id::RequestId>()
+        .map(|r| r.0.as_str())
+        .unwrap_or_default();
+    let ctx = DenialContext {
+        method: parts.method.as_str(),
+        path: parts.uri.path(),
+        request_id,
+        // Deferred: only a denial resolves the source IP.
+        source_ip: LazySourceIp::Deferred(&*parts, proxy_state.real_ip.as_ref()),
+    };
+    let token = match extract_bearer(parts) {
+        Ok(t) => t,
+        Err(e) => {
+            // No credential at all: the scanner-probe shape, so the
+            // `aisix::auth` line stays at debug.
+            proxy_state
+                .metrics
+                .record_auth_decision("none", false, "missing_credentials");
+            tracing::debug!(
+                target: "aisix::auth",
+                method = "none",
+                reason = "missing_credentials",
+                http_method = %ctx.method,
+                path = %ctx.path,
+                request_id = %ctx.request_id,
+                source_ip = %ctx.source_ip.resolve(),
+                "rejected inbound request without a credential",
+            );
+            return Err(e);
+        }
+    };
+    let authed = authenticate_token(&proxy_state, &token, ctx).await?;
+    // Publish the resolved key so extractors that run after this one can
+    // see who is calling without re-authenticating. `ClientContext` reads
+    // it for the `${request.api_key.*}` header templates
+    // (AISIX-Cloud#1112) — which is why every handler declares
+    // `auth: AuthenticatedKey` before `client: ClientContext`.
+    parts.extensions.insert(authed.entry.clone());
+    // Same for the JWT identity: `ClientContext` carries it to each
+    // handler's usage-event emitter for attribution.
+    if let Some(jwt) = &authed.jwt {
+        parts.extensions.insert(jwt.clone());
+    }
+    Ok(authed)
+}
+
 /// Authenticate a plaintext bearer and enforce key lifecycle. The single
 /// auth choke point behind the [`AuthenticatedKey`] extractor; also
 /// called directly by surfaces whose credentials arrive outside the
@@ -273,22 +325,17 @@ async fn authenticate_token_inner(
     })
 }
 
-/// Record an API-key denial on the decision metric + log
-/// (AISIX-Cloud#1081 — before this, a 401 was invisible: the extractor
-/// short-circuits ahead of every handler, so neither the request
-/// counter nor the access log ever fired). The token itself is never
-/// logged.
+/// Record an API-key denial on the decision metric + log. The token itself
+/// is never logged.
 ///
 /// `unknown_key` is the scanner-probe shape (`Bearer <junk>`), so it logs
 /// at `debug` and an internet-facing DP is not flooded at the default
 /// level. `key_disabled` / `key_expired` name a real key an operator
 /// provisioned, so they stay at `warn` and carry `api_key_id`.
 ///
 /// Every line carries the [`DenialContext`] — the caller's address, the
-/// route it hit, and the request id. Without it the record was
-/// unactionable: the metric has no such dimensions, and the 401 never
-/// reaches the access log, so "who is hammering us with a bad key" had no
-/// answer anywhere.
+/// route it hit, and the request id — which the metric has no dimensions
+/// for and the access-log line does not carry (it has no source address).
 fn deny_key(
     state: &ProxyState,
     reason: &'static str,

crates/aisix-proxy/src/lib.rs

@@ -237,7 +237,10 @@ pub fn build_router(state: ProxyState) -> Router {
         // the handler.
         // Registered before the layers so fallback traffic gets the same
         // body-limit / telemetry / Server-header treatment as the routes.
-        .fallback(passthrough_route::entry);
+        .fallback(passthrough_route::entry)
+        // After every route is added: it applies only to the routes that
+        // exist when it is called.
+        .method_not_allowed_fallback(reject::method_not_allowed);
     let router = apply_shared_proxy_layers(router, &state, body_limit).with_state(state.clone());
 
     // The host-dispatch target: the same fallback handler behind the SAME

crates/aisix-proxy/src/mcp.rs

@@ -186,10 +186,9 @@ async fn serve(state: ProxyState, request: Request, scope: Option<String>) -> Re
     // Authentication runs here rather than as an extractor because the
     // decision depends on which entry was addressed: a no-credential
     // request may be served anonymously on an entry configured for it
-    // (AISIX-Cloud#1313). A rejection short-circuits WITHOUT an access
-    // log or request metric, exactly as the extractor's 401 did before
-    // — an internet-facing DP would otherwise drown in scanner probes
-    // (AISIX-Cloud#1081); `aisix_auth_decisions_total` records it.
+    // (AISIX-Cloud#1313). Every rejection comes from the extractor call in
+    // `resolve_caller`, which writes its access-log line; no request
+    // metric is recorded for it, as on every other extractor-denied route.
     let (mut parts, body) = request.into_parts();
     let caller = match resolve_caller(&state, &mut parts, scope.as_deref()).await {
         Ok(caller) => caller,

crates/aisix-proxy/src/mcp_auth.rs

@@ -318,7 +318,26 @@ fn prm_document(snapshot: &AisixSnapshot, identity: &DiscoveryIdentity) -> serde
 pub(crate) async fn protected_resource_metadata(
     method: axum::http::Method,
     State(state): State<ProxyState>,
+    uri: axum::http::Uri,
+    request_id: Option<axum::Extension<crate::request_id::RequestId>>,
 ) -> Response {
+    let started = std::time::Instant::now();
+    let response = protected_resource_response(&method, &state);
+    crate::reject::emit_unrouted_access_log(
+        method.as_str(),
+        uri.path(),
+        request_id
+            .as_ref()
+            .map(|r| r.0 .0.as_str())
+            .unwrap_or_default(),
+        None,
+        response.status().as_u16(),
+        started,
+    );
+    response
+}
+
+fn protected_resource_response(method: &axum::http::Method, state: &ProxyState) -> Response {
     // Discovery files no usage row on any outcome, and an unrecognised path
     // normalizes to the passthrough family's own label — so it says so,
     // rather than resting on being unauthenticated today
@@ -328,7 +347,7 @@ pub(crate) async fn protected_resource_metadata(
     let Some(identity) = discovery_identity(&snapshot) else {
         return StatusCode::NOT_FOUND.into_response();
     };
-    if method != axum::http::Method::GET && method != axum::http::Method::HEAD {
+    if *method != axum::http::Method::GET && *method != axum::http::Method::HEAD {
         let mut response = StatusCode::METHOD_NOT_ALLOWED.into_response();
         response
             .headers_mut()
@@ -348,7 +367,7 @@ pub(crate) async fn protected_resource_metadata(
     Response::builder()
         .header(header::CONTENT_TYPE, "application/json")
         .header(header::CONTENT_LENGTH, length)
-        .body(if method == axum::http::Method::HEAD {
+        .body(if *method == axum::http::Method::HEAD {
             axum::body::Body::empty()
         } else {
             axum::body::Body::from(body)

crates/aisix-proxy/src/models.rs

@@ -55,7 +55,26 @@ pub struct ModelList {
 pub async fn list_models(
     State(state): State<ProxyState>,
     auth: AuthenticatedKey,
-) -> impl IntoResponse {
+    method: axum::http::Method,
+    request_id: Option<axum::Extension<crate::request_id::RequestId>>,
+) -> axum::response::Response {
+    let started = std::time::Instant::now();
+    let response = model_list(&state, &auth).into_response();
+    crate::reject::emit_unrouted_access_log(
+        method.as_str(),
+        "/v1/models",
+        request_id
+            .as_ref()
+            .map(|r| r.0 .0.as_str())
+            .unwrap_or_default(),
+        Some(&auth.entry.id),
+        response.status().as_u16(),
+        started,
+    );
+    response
+}
+
+fn model_list(state: &ProxyState, auth: &AuthenticatedKey) -> Json<ModelList> {
     let now = SystemTime::now()
         .duration_since(UNIX_EPOCH)
         .map(|d| d.as_secs() as i64)