From 36ab8eb5c53537e97ed40e2f428cd85215282003 Mon Sep 17 00:00:00 2001 From: Jarvis Date: Tue, 29 Sep 2026 09:08:01 +0000 Subject: [PATCH 1/3] feat(obs): observability.access_log turns the access log off The key was parsed with a default of true but nothing read it, so the only way to silence access-log lines was the log level, which silences every other info line with them. access_log: false now suppresses every access-log line whatever the level or RUST_LOG; the default keeps today's behaviour. The e2e harness wrote access_log: false into every spawned gateway while the key was inert; it now writes the binary's default unless a spec opts out. --- config.example.yaml | 3 + config.managed.yaml | 3 + crates/aisix-core/src/config.rs | 2 + crates/aisix-obs/src/access_log.rs | 21 ++- crates/aisix-obs/src/lib.rs | 1 + .../src/cases/access-log-switch-e2e.test.ts | 176 ++++++++++++++++++ tests/e2e/src/cases/body-edges-e2e.test.ts | 4 - tests/e2e/src/harness/app.ts | 7 +- 8 files changed, 208 insertions(+), 9 deletions(-) create mode 100644 tests/e2e/src/cases/access-log-switch-e2e.test.ts diff --git a/config.example.yaml b/config.example.yaml index a5728288c..dcbf25560 100644 --- a/config.example.yaml +++ b/config.example.yaml @@ -173,6 +173,9 @@ admin: observability: service_name: "aisix" log_level: "info" + # One access-log line ("proxy request completed") per request, written at + # `info`, so `log_level` must allow `info` for it to appear. false turns the + # access log off whatever the level; every other log line is unaffected. access_log: true metrics: # Complete label lists per metric. Omitted metrics retain their defaults. diff --git a/config.managed.yaml b/config.managed.yaml index 053e2bef6..eeddaab80 100644 --- a/config.managed.yaml +++ b/config.managed.yaml @@ -169,6 +169,9 @@ admin: observability: service_name: "aisix" log_level: "info" + # One access-log line ("proxy request completed") per request, written at + # `info`, so `log_level` must allow `info` for it to appear. false turns the + # access log off whatever the level; every other log line is unaffected. access_log: true metrics: # Complete label lists per metric. Omitted metrics retain their defaults. diff --git a/crates/aisix-core/src/config.rs b/crates/aisix-core/src/config.rs index 2a164064a..6c07b67a4 100644 --- a/crates/aisix-core/src/config.rs +++ b/crates/aisix-core/src/config.rs @@ -1188,6 +1188,8 @@ pub struct ObservabilityConfig { pub service_name: String, #[serde(default = "ObservabilityConfig::default_log_level")] pub log_level: String, + /// Write one access-log line per request. Off, no access-log line is + /// written whatever the log level; every other log line is unaffected. #[serde(default = "ObservabilityConfig::default_access_log")] pub access_log: bool, pub metrics: MetricsConfig, diff --git a/crates/aisix-obs/src/access_log.rs b/crates/aisix-obs/src/access_log.rs index 976dbac9e..af4266b33 100644 --- a/crates/aisix-obs/src/access_log.rs +++ b/crates/aisix-obs/src/access_log.rs @@ -87,8 +87,19 @@ //! last byte out. On a non-streamed request the two coincide; on a //! streamed one they differ by the whole length of the stream. +use std::sync::atomic::{AtomicBool, Ordering}; use std::time::Duration; +/// `observability.access_log`, installed once by [`crate::init_tracing`]. +/// Checked in [`AccessLog::emit`] rather than expressed as a filter +/// directive, so no `RUST_LOG` spelling can bring the lines back and no +/// other event is affected. +static ENABLED: AtomicBool = AtomicBool::new(true); + +pub(crate) fn set_enabled(enabled: bool) { + ENABLED.store(enabled, Ordering::Relaxed); +} + /// Canonical access-log fields, passed to [`log_access`]. /// /// Constructed at the point a request's outcome becomes known — which is not @@ -235,11 +246,13 @@ pub struct McpAccessLog<'a> { } impl AccessLog<'_> { - /// Emit a single `tracing::info!` event carrying every field. The - /// subscriber's configured format (text or JSON) determines the - /// wire shape — operators choose via `cfg.observability.log_level` - /// and (later) a JSON/text knob. + /// Emit a single `tracing::info!` event carrying every field, unless + /// `observability.access_log` is off. When on, the line is filtered by + /// the log level like any other `info` event. pub fn emit(&self) { + if !ENABLED.load(Ordering::Relaxed) { + return; + } let mcp = self.mcp.as_ref(); tracing::info!( method = self.method, diff --git a/crates/aisix-obs/src/lib.rs b/crates/aisix-obs/src/lib.rs index 097ed969d..4f2a34f5b 100644 --- a/crates/aisix-obs/src/lib.rs +++ b/crates/aisix-obs/src/lib.rs @@ -133,6 +133,7 @@ pub fn init_tracing(cfg: &ObservabilityConfig) -> Result<(), ObsError> { return Err(ObsError::AlreadyInitialised); } let _ = LOG_WRITER.set(writer); + access_log::set_enabled(cfg.access_log); tracing::info!( service = %cfg.service_name, diff --git a/tests/e2e/src/cases/access-log-switch-e2e.test.ts b/tests/e2e/src/cases/access-log-switch-e2e.test.ts new file mode 100644 index 000000000..98bacbd3f --- /dev/null +++ b/tests/e2e/src/cases/access-log-switch-e2e.test.ts @@ -0,0 +1,176 @@ +import { createHash } from "node:crypto"; +import { afterAll, beforeAll, describe, expect, test } from "vitest"; +import { + EtcdClient, + ProxyClient, + SeedClient, + spawnApp, + startOpenAiUpstream, + waitConfigPropagation, + waitForLogLine, + type OpenAiUpstream, + type SpawnedApp, +} from "../harness/index.js"; + +// E2E: `observability.access_log` is the switch for the access log. +// Off, a gateway logging at `info` writes no access-log line for any +// request — buffered, streamed, or refused before a handler — while its +// other `info` lines, including the ones those same requests produce, +// still appear. Left at its default, the same requests each write one. + +const ACCESS_LINE = "proxy request completed"; +const CALLER_PLAINTEXT = "sk-access-log-switch-caller"; +const CALLER_KEY_HASH = createHash("sha256").update(CALLER_PLAINTEXT).digest("hex"); +const MODEL = "access-log-switch-e2e"; +const STREAM_MODEL = "access-log-switch-stream-e2e"; + +const CHAT_COMPLETION = { + id: "chatcmpl-access-log-switch", + object: "chat.completion", + model: "gpt-4o-mini", + choices: [{ index: 0, message: { role: "assistant", content: "hi" }, finish_reason: "stop" }], + usage: { prompt_tokens: 3, completion_tokens: 1, total_tokens: 4 }, +}; +const STREAM_EVENTS = [ + JSON.stringify({ + id: "chatcmpl-access-log-switch", + object: "chat.completion.chunk", + model: "gpt-4o-mini", + choices: [{ index: 0, delta: { content: "hi" }, finish_reason: null }], + }), + JSON.stringify({ + id: "chatcmpl-access-log-switch", + object: "chat.completion.chunk", + model: "gpt-4o-mini", + choices: [{ index: 0, delta: {}, finish_reason: "stop" }], + usage: { prompt_tokens: 3, completion_tokens: 1, total_tokens: 4 }, + }), + "[DONE]", +]; + +interface Sent { + buffered: string; + streamed: string; + refused: string; +} + +async function chat(app: SpawnedApp, body: string): Promise<{ status: number; requestId: string }> { + const res = await fetch(`${app.proxyUrl}/v1/chat/completions`, { + method: "POST", + headers: { authorization: `Bearer ${CALLER_PLAINTEXT}`, "content-type": "application/json" }, + body, + }); + await res.text(); + return { status: res.status, requestId: res.headers.get("x-aisix-request-id") ?? "" }; +} + +/** Drive one request of each kind and return their request ids. */ +async function drive(app: SpawnedApp): Promise { + const messages = [{ role: "user", content: "hello" }]; + const buffered = await chat(app, JSON.stringify({ model: MODEL, messages })); + expect(buffered.status).toBe(200); + const streamed = await chat(app, JSON.stringify({ model: STREAM_MODEL, stream: true, messages })); + expect(streamed.status).toBe(200); + // Refused before dispatch: its line is written by a different path. + const refused = await chat(app, "{not json"); + expect(refused.status).toBe(400); + for (const id of [buffered.requestId, streamed.requestId, refused.requestId]) { + expect(id, "every response carries x-aisix-request-id").toBeTruthy(); + } + return { buffered: buffered.requestId, streamed: streamed.requestId, refused: refused.requestId }; +} + +describe("observability.access_log switches the access log", () => { + const upstreams: OpenAiUpstream[] = []; + let off: SpawnedApp | undefined; + let on: SpawnedApp | undefined; + let etcdReachable = false; + + beforeAll(async () => { + const etcd = new EtcdClient(); + etcdReachable = await etcd.ping(); + if (!etcdReachable) return; + + const buffered = await startOpenAiUpstream({ nonStreamBody: CHAT_COMPLETION }); + const streamed = await startOpenAiUpstream({ streamEvents: STREAM_EVENTS }); + upstreams.push(buffered, streamed); + off = await spawnApp({ logLevel: "info", accessLog: false }); + on = await spawnApp({ logLevel: "info" }); + + for (const app of [off, on]) { + const seed = new SeedClient(etcd, app.etcdPrefix); + for (const [name, upstream] of [ + [MODEL, buffered], + [STREAM_MODEL, streamed], + ] as const) { + const pk = await seed.createProviderKey({ + display_name: `${name}-pk`, + secret: "sk-mock", + api_base: `${upstream.baseUrl}/v1`, + }); + await seed.createModel({ + display_name: name, + provider: "openai", + model_name: "gpt-4o-mini", + provider_key_id: pk.id, + }); + } + await seed.createApiKey({ key_hash: CALLER_KEY_HASH, allowed_models: [MODEL, STREAM_MODEL] }); + const probe = new ProxyClient(app.proxyUrl, CALLER_PLAINTEXT); + await waitConfigPropagation(async () => (await probe.listModels()).status === 200); + } + }); + + afterAll(async () => { + await off?.exit(); + await on?.exit(); + for (const u of upstreams) await u.close(); + }); + + test("access_log: false writes no access-log line, and every other line still appears", async (ctx) => { + if (!etcdReachable || !off) { + ctx.skip(); + return; + } + const sent = await drive(off); + + // Stopping the gateway is the barrier: it drains its log queue before + // exiting, so every line these requests could have written is ahead of + // the shutdown line. + await off.stop(); + await waitForLogLine(off, (l) => l.includes("aisix shut down cleanly"), "the shutdown line"); + const lines = off.output().split("\n"); + + expect(lines.filter((l) => l.includes(ACCESS_LINE))).toEqual([]); + // Application `info` lines are unaffected — the boot line, and the + // per-attempt lines the same requests wrote. + expect(lines.some((l) => l.includes("tracing initialised"))).toBe(true); + for (const id of [sent.buffered, sent.streamed]) { + expect( + lines.some((l) => l.includes("provider call completed") && l.includes(`request_id="${id}"`)), + `the provider-call line for ${id}`, + ).toBe(true); + } + }); + + test("by default each request writes its access-log line", async (ctx) => { + if (!etcdReachable || !on) { + ctx.skip(); + return; + } + const sent = await drive(on); + const app = on; + for (const [id, status] of [ + [sent.buffered, 200], + [sent.streamed, 200], + [sent.refused, 400], + ] as const) { + const line = await waitForLogLine( + app, + (l) => l.includes(ACCESS_LINE) && l.includes(`request_id="${id}"`), + `the access-log line for ${id}`, + ); + expect(line).toContain(`status=${status}`); + } + }); +}); diff --git a/tests/e2e/src/cases/body-edges-e2e.test.ts b/tests/e2e/src/cases/body-edges-e2e.test.ts index 561ac0bf5..c6c7bc9ee 100644 --- a/tests/e2e/src/cases/body-edges-e2e.test.ts +++ b/tests/e2e/src/cases/body-edges-e2e.test.ts @@ -242,10 +242,6 @@ describe("body edges e2e: multi-turn, oversize body, empty messages", () => { // emitted BY the handlers. That left an operator with nothing to // look at: a caller reporting a 413 the gateway had no record of is // indistinguishable from the request never arriving. - // - // (`observability.access_log` in the harness config is the reserved - // field nothing reads today — the access log is gated by the log - // level alone, which is why this suite raises it to `info`.) const filler = "x".repeat(10 * 1024 * 1024 + 512 * 1024); const res = await fetch(`${app.proxyUrl}/v1/chat/completions`, { method: "POST", diff --git a/tests/e2e/src/harness/app.ts b/tests/e2e/src/harness/app.ts index 2db918108..3f13dc4bd 100644 --- a/tests/e2e/src/harness/app.ts +++ b/tests/e2e/src/harness/app.ts @@ -115,6 +115,11 @@ export interface AppOverrides { * debugging with `RUST_LOG=error` can't turn a test's subject off. */ logLevel?: string; + /** + * `observability.access_log`. Defaults to `true`, the binary's own + * default; only a spec whose subject is the switch turns it off. + */ + accessLog?: boolean; /** * `observability.metrics.client_type_rules` (AISIX-Cloud#1045): operator * UA→client_type regex rules, tried before the built-in allowlist. @@ -434,7 +439,7 @@ async function spawnAppOnce(overrides: AppOverrides = {}): Promise { observability: { service_name: "aisix-e2e", log_level: overrides.logLevel ?? "warn", - access_log: false, + access_log: overrides.accessLog ?? true, metrics: { prometheus: { enabled: prometheusEnabled, From 8107b63fa90c4bde93b690383df60663000afd71 Mon Sep 17 00:00:00 2001 From: Jarvis Date: Tue, 29 Sep 2026 09:14:20 +0000 Subject: [PATCH 2/3] test(e2e): stop the self-spawning specs writing access_log: false The key used to be inert; now it would silently turn off the access log for anyone raising these specs' log level. --- tests/e2e/src/cases/listener-tls-e2e.test.ts | 1 - tests/e2e/src/cases/status-config-e2e.test.ts | 1 - 2 files changed, 2 deletions(-) diff --git a/tests/e2e/src/cases/listener-tls-e2e.test.ts b/tests/e2e/src/cases/listener-tls-e2e.test.ts index c859d3708..02c59bd1b 100644 --- a/tests/e2e/src/cases/listener-tls-e2e.test.ts +++ b/tests/e2e/src/cases/listener-tls-e2e.test.ts @@ -91,7 +91,6 @@ describe("listener TLS (#473)", () => { observability: { service_name: "aisix-e2e-tls", log_level: "warn", - access_log: false, // Explicit free port so concurrent test files never collide on // the default 0.0.0.0:9090 metrics listener. metrics: { diff --git a/tests/e2e/src/cases/status-config-e2e.test.ts b/tests/e2e/src/cases/status-config-e2e.test.ts index 460129dde..777b05f20 100644 --- a/tests/e2e/src/cases/status-config-e2e.test.ts +++ b/tests/e2e/src/cases/status-config-e2e.test.ts @@ -567,7 +567,6 @@ async function spawnPointedAtDeadEtcd(): Promise { observability: { service_name: "aisix-status-nl", log_level: "warn", - access_log: false, metrics: { prometheus: { enabled: true, path: "/metrics", addr: `127.0.0.1:${metricsPort}` }, // Retired blocks, kept here on purpose: they were placeholders no From 7c6111a9a8aa1cf959161ae91e98a68c3441fe72 Mon Sep 17 00:00:00 2001 From: Jarvis Date: Tue, 29 Sep 2026 09:53:47 +0000 Subject: [PATCH 3/3] docs(config): the access_log annotation names RUST_LOG as the effective filter --- config.example.yaml | 5 +++-- config.managed.yaml | 5 +++-- 2 files changed, 6 insertions(+), 4 deletions(-) diff --git a/config.example.yaml b/config.example.yaml index dcbf25560..0e9250da7 100644 --- a/config.example.yaml +++ b/config.example.yaml @@ -174,8 +174,9 @@ observability: service_name: "aisix" log_level: "info" # One access-log line ("proxy request completed") per request, written at - # `info`, so `log_level` must allow `info` for it to appear. false turns the - # access log off whatever the level; every other log line is unaffected. + # `info`, so the effective log filter (`RUST_LOG` when set, else `log_level`) + # must allow `info` for it to appear. false turns the access log off whatever + # the filter; every other log line is unaffected. access_log: true metrics: # Complete label lists per metric. Omitted metrics retain their defaults. diff --git a/config.managed.yaml b/config.managed.yaml index eeddaab80..965cd5f63 100644 --- a/config.managed.yaml +++ b/config.managed.yaml @@ -170,8 +170,9 @@ observability: service_name: "aisix" log_level: "info" # One access-log line ("proxy request completed") per request, written at - # `info`, so `log_level` must allow `info` for it to appear. false turns the - # access log off whatever the level; every other log line is unaffected. + # `info`, so the effective log filter (`RUST_LOG` when set, else `log_level`) + # must allow `info` for it to appear. false turns the access log off whatever + # the filter; every other log line is unaffected. access_log: true metrics: # Complete label lists per metric. Omitted metrics retain their defaults.