diff --git a/config.example.yaml b/config.example.yaml index a5728288..0e9250da 100644 --- a/config.example.yaml +++ b/config.example.yaml @@ -173,6 +173,10 @@ admin: observability: service_name: "aisix" log_level: "info" + # One access-log line ("proxy request completed") per request, written at + # `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 053e2bef..965cd5f6 100644 --- a/config.managed.yaml +++ b/config.managed.yaml @@ -169,6 +169,10 @@ admin: observability: service_name: "aisix" log_level: "info" + # One access-log line ("proxy request completed") per request, written at + # `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/crates/aisix-core/src/config.rs b/crates/aisix-core/src/config.rs index 2a164064..6c07b67a 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 63550189..2eb8000d 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 where every access-log line is written 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 @@ -291,15 +302,17 @@ 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) { self.emit_with(None); } fn emit_with(&self, semantic: Option<&SemanticAccessLog>) { + 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 03d96124..83a64030 100644 --- a/crates/aisix-obs/src/lib.rs +++ b/crates/aisix-obs/src/lib.rs @@ -135,6 +135,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 00000000..98bacbd3 --- /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 561ac0bf..c6c7bc9e 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/cases/listener-tls-e2e.test.ts b/tests/e2e/src/cases/listener-tls-e2e.test.ts index c859d370..02c59bd1 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 460129dd..777b05f2 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 diff --git a/tests/e2e/src/harness/app.ts b/tests/e2e/src/harness/app.ts index 2db91810..3f13dc4b 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,