diff --git a/crates/aisix-proxy/AGENTS.md b/crates/aisix-proxy/AGENTS.md index 702a98e8..0004ebc1 100644 --- a/crates/aisix-proxy/AGENTS.md +++ b/crates/aisix-proxy/AGENTS.md @@ -237,6 +237,19 @@ telemetry, so the two can't drift apart): `Result, JsonRejection>` / `Result` 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. diff --git a/crates/aisix-proxy/src/a2a.rs b/crates/aisix-proxy/src/a2a.rs index 67169476..f1449a1f 100644 --- a/crates/aisix-proxy/src/a2a.rs +++ b/crates/aisix-proxy/src/a2a.rs @@ -673,6 +673,31 @@ pub async fn a2a_agent_card( State(state): State, uri: axum::http::Uri, headers: HeaderMap, + method: axum::http::Method, + request_id: Option>, +) -> 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 @@ -680,11 +705,11 @@ pub async fn a2a_agent_card( // 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, diff --git a/crates/aisix-proxy/src/auth.rs b/crates/aisix-proxy/src/auth.rs index fdc04fa2..e961ed17 100644 --- a/crates/aisix-proxy/src/auth.rs +++ b/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 { - let proxy_state = ProxyState::from_ref(state); - let request_id = parts - .extensions - .get::() - .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::() + .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( + parts: &mut Parts, + state: &S, +) -> Result +where + S: Send + Sync, + ProxyState: FromRef, +{ + let proxy_state = ProxyState::from_ref(state); + let request_id = parts + .extensions + .get::() + .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,11 +325,8 @@ 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 `), so it logs /// at `debug` and an internet-facing DP is not flooded at the default @@ -285,10 +334,8 @@ async fn authenticate_token_inner( /// 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, diff --git a/crates/aisix-proxy/src/lib.rs b/crates/aisix-proxy/src/lib.rs index 25c84681..84120423 100644 --- a/crates/aisix-proxy/src/lib.rs +++ b/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 diff --git a/crates/aisix-proxy/src/mcp.rs b/crates/aisix-proxy/src/mcp.rs index 38313b4d..285c1eb9 100644 --- a/crates/aisix-proxy/src/mcp.rs +++ b/crates/aisix-proxy/src/mcp.rs @@ -186,10 +186,9 @@ async fn serve(state: ProxyState, request: Request, scope: Option) -> 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, diff --git a/crates/aisix-proxy/src/mcp_auth.rs b/crates/aisix-proxy/src/mcp_auth.rs index 136e3656..ec6c6041 100644 --- a/crates/aisix-proxy/src/mcp_auth.rs +++ b/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, + uri: axum::http::Uri, + request_id: Option>, ) -> 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) diff --git a/crates/aisix-proxy/src/models.rs b/crates/aisix-proxy/src/models.rs index 4a29e088..d7656723 100644 --- a/crates/aisix-proxy/src/models.rs +++ b/crates/aisix-proxy/src/models.rs @@ -55,7 +55,26 @@ pub struct ModelList { pub async fn list_models( State(state): State, auth: AuthenticatedKey, -) -> impl IntoResponse { + method: axum::http::Method, + request_id: Option>, +) -> 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 { let now = SystemTime::now() .duration_since(UNIX_EPOCH) .map(|d| d.as_secs() as i64) diff --git a/crates/aisix-proxy/src/passthrough_route.rs b/crates/aisix-proxy/src/passthrough_route.rs index bf2dd6f8..608a5e75 100644 --- a/crates/aisix-proxy/src/passthrough_route.rs +++ b/crates/aisix-proxy/src/passthrough_route.rs @@ -291,6 +291,14 @@ pub async fn entry( // Every unmatched path, `/passthrough/*` included, takes the // router's ordinary miss path: the namespace is entirely the // operator's to claim with explicit `passthrough_route` resources. + crate::reject::emit_unrouted_access_log( + method.as_str(), + &path, + &request_id, + None, + StatusCode::NOT_FOUND.as_u16(), + started, + ); return StatusCode::NOT_FOUND.into_response(); }; diff --git a/crates/aisix-proxy/src/reject.rs b/crates/aisix-proxy/src/reject.rs index 77f5de8e..598cda67 100644 --- a/crates/aisix-proxy/src/reject.rs +++ b/crates/aisix-proxy/src/reject.rs @@ -116,6 +116,67 @@ pub(crate) fn reject_before_dispatch( } } +/// Write the access-log line for a request answered without dispatch and +/// without a typed error: a discovery document, the model list, an +/// unrouted path's 404, the router's 405. Only what is known is written — +/// no upstream, no model, no error class. +pub(crate) fn emit_unrouted_access_log( + method: &str, + path: &str, + request_id: &str, + api_key_id: Option<&str>, + status: u16, + started: Instant, +) { + let elapsed = started.elapsed(); + crate::attribution::emit_access_log(AccessLog { + method, + path, + status, + latency: elapsed, + duration: elapsed, + provider: None, + model: None, + upstream_model: None, + provider_key_id: None, + api_key_id, + 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: None, + error: None, + mcp: None, + cache: None, + request_body_bytes: None, + response_body_bytes: None, + }); +} + +/// The router's answer to a known path with a method it does not serve. +/// axum's own 405 (it still adds `Allow`), plus the request's access-log +/// line, which the built-in fallback never wrote. +pub(crate) async fn method_not_allowed(request: axum::extract::Request) -> Response { + let request_id = request + .extensions() + .get::() + .map(|r| r.0.clone()) + .unwrap_or_default(); + emit_unrouted_access_log( + request.method().as_str(), + request.uri().path(), + &request_id, + None, + axum::http::StatusCode::METHOD_NOT_ALLOWED.as_u16(), + Instant::now(), + ); + axum::http::StatusCode::METHOD_NOT_ALLOWED.into_response() +} + /// `axum::extract::Path` with the rejection routed through /// [`reject_before_dispatch`]. /// diff --git a/tests/e2e/src/cases/access-log-auth-denial-e2e.test.ts b/tests/e2e/src/cases/access-log-auth-denial-e2e.test.ts new file mode 100644 index 00000000..47d94e31 --- /dev/null +++ b/tests/e2e/src/cases/access-log-auth-denial-e2e.test.ts @@ -0,0 +1,205 @@ +import { createHash } from "node:crypto"; +import { afterAll, beforeAll, describe, expect, test } from "vitest"; +import { + agentClaims, + EtcdClient, + ProxyClient, + SeedClient, + spawnApp, + startMockIdp, + waitConfigPropagation, + waitForLogLine, + type MockIdp, + type SpawnedApp, +} from "../harness/index.js"; + +// E2E: a request refused for authentication writes its access-log line. +// +// An operator auditing who hit the gateway with a bad credential reads the +// access log, so every denial shape — no credential, an unknown key, a +// disabled or expired key, a rejected JWT — is one line there, on every +// proxy surface (a JWT short of a required scope is a 403, the rest 401), +// carrying the status the caller saw and never the +// credential itself. `observability.access_log: false` suppresses these +// lines like every other. + +const ACCESS_LINE = "proxy request completed"; +const VALID = "sk-auth-denial-valid"; +const DISABLED = "sk-auth-denial-disabled"; +const EXPIRED = "sk-auth-denial-expired"; +const UNKNOWN = "sk-auth-denial-unknown-0123456789"; + +const sha = (s: string) => createHash("sha256").update(s).digest("hex"); + +// Every proxy surface that authenticates through the gateway key. +const SURFACES: ReadonlyArray<{ method: string; path: string }> = [ + { method: "POST", path: "/v1/chat/completions" }, + { method: "POST", path: "/v1/completions" }, + { method: "POST", path: "/v1/messages" }, + { method: "POST", path: "/v1/messages/count_tokens" }, + { method: "POST", path: "/v1/responses" }, + { method: "POST", path: "/v1/embeddings" }, + { method: "POST", path: "/v1/rerank" }, + { method: "POST", path: "/v1/images/generations" }, + { method: "POST", path: "/v1/audio/speech" }, + { method: "POST", path: "/v1/videos" }, + { method: "GET", path: "/v1/models" }, + { method: "GET", path: "/v1/files" }, + { method: "GET", path: "/v1/batches/batch_x" }, + { method: "POST", path: "/mcp" }, + { method: "POST", path: "/a2a/some-agent" }, +]; + +interface Sent { + method: string; + path: string; + id: string; + status: number; + secret?: string; + label: string; +} + +async function send( + app: SpawnedApp, + method: string, + path: string, + headers: Record, +): Promise<{ status: number; id: string }> { + const res = await fetch(`${app.proxyUrl}${path}`, { + method, + headers: { ...headers, "content-type": "application/json" }, + body: method === "GET" ? undefined : "{}", + }); + await res.text(); + return { status: res.status, id: res.headers.get("x-aisix-request-id") ?? "" }; +} + +async function drive(app: SpawnedApp, idp: MockIdp, scopedIdp: MockIdp): Promise { + const jwtExpired = idp.sign( + agentClaims(idp.url, { exp: Math.floor(Date.now() / 1000) - 3600 }), + ); + const jwtUnmapped = idp.sign(agentClaims(idp.url, { sub: "nobody-bound" })); + const jwtUnscoped = scopedIdp.sign(agentClaims(scopedIdp.url)); + const credentials: ReadonlyArray<{ + label: string; + headers: Record; + secret?: string; + status?: number; + }> = [ + { label: "no credential", headers: {} }, + { label: "unknown key", headers: { authorization: `Bearer ${UNKNOWN}` }, secret: UNKNOWN }, + { label: "unknown x-api-key", headers: { "x-api-key": UNKNOWN }, secret: UNKNOWN }, + { label: "disabled key", headers: { authorization: `Bearer ${DISABLED}` }, secret: DISABLED }, + { label: "expired key", headers: { authorization: `Bearer ${EXPIRED}` }, secret: EXPIRED }, + { label: "expired jwt", headers: { authorization: `Bearer ${jwtExpired}` }, secret: jwtExpired }, + { label: "unmapped jwt", headers: { authorization: `Bearer ${jwtUnmapped}` }, secret: jwtUnmapped }, + { + label: "jwt missing a required scope", + headers: { authorization: `Bearer ${jwtUnscoped}` }, + secret: jwtUnscoped, + status: 403, + }, + ]; + const sent: Sent[] = []; + for (const { method, path } of SURFACES) { + for (const cred of credentials) { + const { status, id } = await send(app, method, path, cred.headers); + const label = `${cred.label} on ${method} ${path}`; + expect(status, label).toBe(cred.status ?? 401); + expect(id, `${label} carries x-aisix-request-id`).toBeTruthy(); + sent.push({ method, path, id, status, secret: cred.secret, label }); + } + } + return sent; +} + +/** Stop the gateway (which drains its log queue) and return its lines. */ +async function drainedLines(app: SpawnedApp): Promise { + await app.stop(); + await waitForLogLine(app, (l) => l.includes("aisix shut down cleanly"), "the shutdown line"); + return app.output().split("\n"); +} + +describe("an authentication denial writes its access-log line", () => { + let idp: MockIdp | undefined; + let scopedIdp: MockIdp | undefined; + let on: SpawnedApp | undefined; + let off: SpawnedApp | undefined; + let etcdReachable = false; + + beforeAll(async () => { + const etcd = new EtcdClient(); + etcdReachable = await etcd.ping(); + if (!etcdReachable) return; + idp = await startMockIdp(); + scopedIdp = await startMockIdp(); + on = await spawnApp({ logLevel: "info" }); + off = await spawnApp({ logLevel: "info", accessLog: false }); + for (const app of [on, off]) { + const seed = new SeedClient(etcd, app.etcdPrefix); + await seed.createOidcProvider({ + name: "auth-denial-idp", + issuer: idp.url, + audiences: ["aisix-gateway"], + jwks_uri: idp.jwksUrl, + }); + await seed.createOidcProvider({ + name: "auth-denial-scoped-idp", + issuer: scopedIdp.url, + audiences: ["aisix-gateway"], + jwks_uri: scopedIdp.jwksUrl, + required_scopes: ["ai.access"], + }); + await seed.createApiKey({ key_hash: sha(DISABLED), allowed_models: ["*"], disabled: true }); + await seed.createApiKey({ + key_hash: sha(EXPIRED), + allowed_models: ["*"], + expires_at: "2020-01-01T00:00:00Z", + }); + // Seeded last: once it authenticates, every row above has loaded. + await seed.createApiKey({ key_hash: sha(VALID), allowed_models: [] }); + const probe = new ProxyClient(app.proxyUrl, VALID); + await waitConfigPropagation(async () => (await probe.listModels()).status === 200); + } + }); + + afterAll(async () => { + await on?.exit(); + await off?.exit(); + await idp?.close(); + await scopedIdp?.close(); + }); + + test("each denial is exactly one line with its status and without the credential", async (ctx) => { + if (!etcdReachable || !on || !idp || !scopedIdp) { + ctx.skip(); + return; + } + const sent = await drive(on, idp, scopedIdp); + const lines = (await drainedLines(on)).filter((l) => l.includes(ACCESS_LINE)); + for (const s of sent) { + const mine = lines.filter((l) => l.includes(`request_id="${s.id}"`)); + expect(mine, `one access-log line for ${s.label}`).toHaveLength(1); + expect(mine[0], s.label).toContain(`status=${s.status}`); + expect(mine[0], s.label).toMatch(new RegExp(`method="?${s.method}"?\\s`)); + expect(mine[0], s.label).toMatch(new RegExp(`path="?${s.path}"?\\s`)); + // Nothing about the caller is established by a refused credential. + expect(mine[0], s.label).not.toContain("api_key_id="); + if (s.secret) { + expect(mine[0].includes(s.secret), `${s.label}: credential not logged`).toBe(false); + } + } + }); + + test("access_log: false suppresses them", async (ctx) => { + if (!etcdReachable || !off || !idp || !scopedIdp) { + ctx.skip(); + return; + } + await drive(off, idp, scopedIdp); + const lines = await drainedLines(off); + expect(lines.filter((l) => l.includes(ACCESS_LINE))).toEqual([]); + // Only the access log is off: the gateway's other `info` lines remain. + expect(lines.some((l) => l.includes("tracing initialised"))).toBe(true); + }); +}); diff --git a/tests/e2e/src/cases/access-log-unrouted-e2e.test.ts b/tests/e2e/src/cases/access-log-unrouted-e2e.test.ts new file mode 100644 index 00000000..fda7372c --- /dev/null +++ b/tests/e2e/src/cases/access-log-unrouted-e2e.test.ts @@ -0,0 +1,158 @@ +import { createHash } from "node:crypto"; +import { afterAll, beforeAll, describe, expect, test } from "vitest"; +import { + EtcdClient, + ProxyClient, + SeedClient, + spawnApp, + waitConfigPropagation, + waitForLogLine, + type SpawnedApp, +} from "../harness/index.js"; + +// E2E: every request answered on the proxy listener writes one access-log +// line, including the ones no dispatching handler answers — the model list, +// the A2A agent card, the OAuth discovery document, a path no route serves, +// and a method a known route does not serve. Health probes are the +// exception: they are the platform's traffic, not a client's. +// `observability.access_log: false` suppresses all of them. + +const ACCESS_LINE = "proxy request completed"; +const CALLER = "sk-access-log-unrouted"; + +interface Probe { + label: string; + method: string; + path: string; + auth: boolean; + status: number; +} + +const LOGGED: readonly Probe[] = [ + { label: "model list", method: "GET", path: "/v1/models", auth: true, status: 200 }, + { + label: "agent card of an unknown agent", + method: "GET", + path: "/a2a/no-such-agent/.well-known/agent-card.json", + auth: true, + status: 404, + }, + { + label: "OAuth discovery, surface dormant", + method: "GET", + path: "/.well-known/oauth-protected-resource", + auth: false, + status: 404, + }, + { + label: "OAuth discovery for /mcp, surface dormant", + method: "GET", + path: "/.well-known/oauth-protected-resource/mcp", + auth: false, + status: 404, + }, + { label: "unrouted path", method: "GET", path: "/v1/no-such-route", auth: true, status: 404 }, + { label: "unrouted path, no credential", method: "POST", path: "/nothing/here", auth: false, status: 404 }, + { label: "wrong method on chat", method: "GET", path: "/v1/chat/completions", auth: true, status: 405 }, + { label: "wrong method on files", method: "PUT", path: "/v1/files", auth: true, status: 405 }, + { label: "wrong method on realtime", method: "POST", path: "/v1/realtime", auth: false, status: 405 }, +]; + +const PROBES: readonly Probe[] = [ + { label: "liveness probe", method: "GET", path: "/livez", auth: false, status: 200 }, + { label: "readiness probe", method: "GET", path: "/readyz", auth: false, status: 200 }, +]; + +interface Sent { + probe: Probe; + id: string; +} + +async function send(app: SpawnedApp, p: Probe): Promise { + const res = await fetch(`${app.proxyUrl}${p.path}`, { + method: p.method, + headers: p.auth ? { authorization: `Bearer ${CALLER}` } : {}, + }); + await res.text(); + expect(res.status, p.label).toBe(p.status); + if (p.status === 405) { + expect(res.headers.get("allow"), `${p.label} still names the allowed methods`).toBeTruthy(); + } + return { probe: p, id: res.headers.get("x-aisix-request-id") ?? "" }; +} + +async function drainedAccessLines(app: SpawnedApp): Promise { + await app.stop(); + await waitForLogLine(app, (l) => l.includes("aisix shut down cleanly"), "the shutdown line"); + return app + .output() + .split("\n") + .filter((l) => l.includes(ACCESS_LINE)); +} + +describe("requests answered outside dispatch write their access-log line", () => { + let on: SpawnedApp | undefined; + let off: SpawnedApp | undefined; + let etcdReachable = false; + + beforeAll(async () => { + const etcd = new EtcdClient(); + etcdReachable = await etcd.ping(); + if (!etcdReachable) return; + on = await spawnApp({ logLevel: "info" }); + off = await spawnApp({ logLevel: "info", accessLog: false }); + for (const app of [on, off]) { + const seed = new SeedClient(etcd, app.etcdPrefix); + await seed.createApiKey({ + key_hash: createHash("sha256").update(CALLER).digest("hex"), + allowed_models: [], + }); + const probe = new ProxyClient(app.proxyUrl, CALLER); + await waitConfigPropagation(async () => (await probe.listModels()).status === 200); + } + }); + + afterAll(async () => { + await on?.exit(); + await off?.exit(); + }); + + test("one line each, with the status the caller got; none for health probes", async (ctx) => { + if (!etcdReachable || !on) { + ctx.skip(); + return; + } + const logged: Sent[] = []; + for (const p of LOGGED) logged.push(await send(on, p)); + const probes: Sent[] = []; + for (const p of PROBES) probes.push(await send(on, p)); + const lines = await drainedAccessLines(on); + for (const { probe, id } of logged) { + expect(id, `${probe.label} carries x-aisix-request-id`).toBeTruthy(); + const mine = lines.filter((l) => l.includes(`request_id="${id}"`)); + expect(mine, `one access-log line for ${probe.label}`).toHaveLength(1); + expect(mine[0], probe.label).toContain(`status=${probe.status}`); + expect(mine[0], probe.label).toMatch(new RegExp(`method="?${probe.method}"?\\s`)); + expect(mine[0], probe.label).toMatch(new RegExp(`path="?${probe.path}"?\\s`)); + } + for (const { probe, id } of probes) { + expect( + lines.filter((l) => id && l.includes(`request_id="${id}"`)), + `${probe.label} writes no line`, + ).toEqual([]); + expect( + lines.filter((l) => new RegExp(`path="?${probe.path}"?\\s`).test(l)), + `${probe.label} writes no line`, + ).toEqual([]); + } + }); + + test("access_log: false suppresses them", async (ctx) => { + if (!etcdReachable || !off) { + ctx.skip(); + return; + } + for (const p of LOGGED) await send(off, p); + expect(await drainedAccessLines(off)).toEqual([]); + }); +});