From 3ba228143dd2480fc791197655ec9cb8f94db844 Mon Sep 17 00:00:00 2001 From: ggfevans Date: Thu, 19 Feb 2026 18:01:37 -0800 Subject: [PATCH 1/3] feat: add structured authentication event logging (#1104) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Add auth-logger module emitting structured JSON lines to stdout for Docker/self-hosted log forwarding with secret redaction. Events logged: - auth.login.success — valid session on /auth/check - auth.login.failure — invalid/missing session on /auth/check - auth.logout — POST /auth/logout with valid session - auth.session.invalid — auth gate rejects anonymous request - auth.denied — authorization middleware blocks non-admin write Each event includes timestamp, event type, request method/path, and optionally the subject (email) and denial reason. Sensitive data (tokens, cookies, session IDs) is never included in log output. - New api/src/auth-logger.ts with emitAuthEvent(), logAuthEvent(), redactHeaders(), and extractRequestContext() - Integrated into auth gate (security.ts), authorization middleware, logout handler, and auth check handler (app.ts) - 11 new tests covering event emission, redaction, and integration Fixes #1104 Co-Authored-By: Claude Opus 4.6 --- api/src/app.ts | 7 + api/src/auth-logger.test.ts | 315 ++++++++++++++++++++++++++++++++++++ api/src/auth-logger.ts | 86 ++++++++++ api/src/authorization.ts | 6 + api/src/security.ts | 5 + 5 files changed, 419 insertions(+) create mode 100644 api/src/auth-logger.test.ts create mode 100644 api/src/auth-logger.ts diff --git a/api/src/app.ts b/api/src/app.ts index 5c543429..bd810c39 100644 --- a/api/src/app.ts +++ b/api/src/app.ts @@ -17,6 +17,7 @@ import { type EnvMap, } from "./security"; import { createRequireAdminMiddleware } from "./authorization"; +import { logAuthEvent } from "./auth-logger"; const DEFAULT_MAX_ASSET_SIZE = 5 * 1024 * 1024; // 5MB const DEFAULT_MAX_LAYOUT_SIZE = 1 * 1024 * 1024; // 1MB @@ -116,6 +117,9 @@ export function createApp(env: EnvMap = process.env): Hono { const claims = resolveAuthenticatedSessionClaims(c.req.raw, authSessionConfig); if (!claims) { + logAuthEvent("auth.login.failure", c.req.raw, { + reason: "invalid or missing session on auth check", + }); return c.json( { error: "Unauthorized", @@ -125,6 +129,8 @@ export function createApp(env: EnvMap = process.env): Hono { ); } + logAuthEvent("auth.login.success", c.req.raw, { subject: claims.sub }); + const refreshedCookie = createRefreshedAuthSessionCookieHeader( claims, authSessionConfig, @@ -140,6 +146,7 @@ export function createApp(env: EnvMap = process.env): Hono { const claims = resolveAuthenticatedSessionClaims(c.req.raw, authSessionConfig); if (claims) { invalidateAuthSession(claims.sid, claims.exp); + logAuthEvent("auth.logout", c.req.raw, { subject: claims.sub }); } c.header( diff --git a/api/src/auth-logger.test.ts b/api/src/auth-logger.test.ts new file mode 100644 index 00000000..7035d8f2 --- /dev/null +++ b/api/src/auth-logger.test.ts @@ -0,0 +1,315 @@ +import { beforeEach, describe, expect, it, mock, spyOn } from "bun:test"; +import { + emitAuthEvent, + extractRequestContext, + logAuthEvent, + redactHeaders, + type AuthEvent, +} from "./auth-logger"; +import { createApp } from "./app"; +import { + clearInvalidatedAuthSessions, + createSignedAuthSessionToken, + type AuthSessionClaimsInput, + type EnvMap, +} from "./security"; + +const TEST_AUTH_SECRET = "rackula-auth-session-secret-for-tests-0123456789"; + +function buildEnv(overrides: EnvMap = {}): EnvMap { + return { NODE_ENV: "test", ...overrides }; +} + +function buildAuthEnabledEnv(overrides: EnvMap = {}): EnvMap { + return buildEnv({ + RACKULA_AUTH_MODE: "oidc", + RACKULA_AUTH_SESSION_SECRET: TEST_AUTH_SECRET, + CORS_ORIGIN: "https://rack.example.com", + RACKULA_AUTH_SESSION_MAX_AGE_SECONDS: "3600", + RACKULA_AUTH_SESSION_IDLE_TIMEOUT_SECONDS: "300", + ...overrides, + }); +} + +// Default cookie carries role: "admin" for passing authorization checks. +function buildAuthCookie( + overrides: Partial = {}, +): string { + const now = Math.floor(Date.now() / 1000); + const token = createSignedAuthSessionToken( + { + sub: "admin@example.com", + sid: "session-default", + role: "admin", + iat: now - 30, + exp: now + 600, + idleExp: now + 120, + generation: 0, + ...overrides, + }, + TEST_AUTH_SECRET, + { + sessionMaxAgeSeconds: 3600, + sessionIdleTimeoutSeconds: 300, + sessionGeneration: 0, + }, + ); + return `rackula_auth_session=${token}`; +} + +beforeEach(() => { + clearInvalidatedAuthSessions(); +}); + +describe("redactHeaders", () => { + it("redacts sensitive headers", () => { + const result = redactHeaders({ + "Content-Type": "application/json", + Authorization: "Bearer secret-token", + Cookie: "session=abc123", + "Set-Cookie": "session=xyz", + "X-Forwarded-For": "192.168.1.1", + "X-Request-Id": "req-123", + }); + + expect(result["Content-Type"]).toBe("application/json"); + expect(result["Authorization"]).toBe("[REDACTED]"); + expect(result["Cookie"]).toBe("[REDACTED]"); + expect(result["Set-Cookie"]).toBe("[REDACTED]"); + expect(result["X-Forwarded-For"]).toBe("[REDACTED]"); + expect(result["X-Request-Id"]).toBe("req-123"); + }); +}); + +describe("extractRequestContext", () => { + it("extracts method, path, and IP from request", () => { + const request = new Request("https://example.com/api/layouts/abc", { + method: "PUT", + headers: { "X-Real-IP": "10.0.0.1" }, + }); + + const ctx = extractRequestContext(request); + expect(ctx.method).toBe("PUT"); + expect(ctx.path).toBe("/api/layouts/abc"); + expect(ctx.ip).toBe("10.0.0.1"); + }); + + it("returns undefined IP when header is missing", () => { + const request = new Request("https://example.com/health"); + const ctx = extractRequestContext(request); + expect(ctx.ip).toBeUndefined(); + }); +}); + +describe("emitAuthEvent", () => { + it("writes JSON line to stdout", () => { + const writeSpy = spyOn(process.stdout, "write").mockImplementation(() => true); + + const event: AuthEvent = { + timestamp: "2026-02-19T10:00:00.000Z", + event: "auth.logout", + subject: "user@example.com", + method: "POST", + path: "/auth/logout", + }; + + emitAuthEvent(event); + + expect(writeSpy).toHaveBeenCalledTimes(1); + const output = writeSpy.mock.calls[0][0] as string; + const parsed = JSON.parse(output.trim()); + expect(parsed.event).toBe("auth.logout"); + expect(parsed.subject).toBe("user@example.com"); + expect(parsed.timestamp).toBe("2026-02-19T10:00:00.000Z"); + + writeSpy.mockRestore(); + }); + + it("never includes raw tokens or session IDs in output", () => { + const writeSpy = spyOn(process.stdout, "write").mockImplementation(() => true); + + emitAuthEvent({ + timestamp: new Date().toISOString(), + event: "auth.session.invalid", + reason: "expired session", + method: "GET", + path: "/api/layouts", + }); + + const output = writeSpy.mock.calls[0][0] as string; + // Verify no common secret patterns leak + expect(output).not.toContain("Bearer"); + expect(output).not.toContain("rackula_auth_session="); + + writeSpy.mockRestore(); + }); +}); + +describe("auth event integration", () => { + it("logs auth.session.invalid when anonymous request hits auth gate", async () => { + const writeSpy = spyOn(process.stdout, "write").mockImplementation(() => true); + const app = createApp(buildAuthEnabledEnv()); + + await app.request("/api/layouts"); + + const authEvents = writeSpy.mock.calls + .map((call) => { + try { + return JSON.parse((call[0] as string).trim()); + } catch { + return null; + } + }) + .filter((e) => e?.event?.startsWith("auth.")); + + expect(authEvents.some((e) => e.event === "auth.session.invalid")).toBe(true); + const event = authEvents.find((e) => e.event === "auth.session.invalid"); + expect(event.reason).toBe("missing or invalid session cookie"); + expect(event.path).toBe("/api/layouts"); + + writeSpy.mockRestore(); + }); + + it("logs auth.logout on successful logout", async () => { + const writeSpy = spyOn(process.stdout, "write").mockImplementation(() => true); + const app = createApp(buildAuthEnabledEnv()); + + await app.request("/auth/logout", { + method: "POST", + headers: { + Cookie: buildAuthCookie({ sid: "logout-log-session" }), + Origin: "https://rack.example.com", + }, + }); + + const authEvents = writeSpy.mock.calls + .map((call) => { + try { + return JSON.parse((call[0] as string).trim()); + } catch { + return null; + } + }) + .filter((e) => e?.event?.startsWith("auth.")); + + expect(authEvents.some((e) => e.event === "auth.logout")).toBe(true); + const event = authEvents.find((e) => e.event === "auth.logout"); + expect(event.subject).toBe("admin@example.com"); + + writeSpy.mockRestore(); + }); + + it("logs auth.denied when non-admin attempts write", async () => { + const writeSpy = spyOn(process.stdout, "write").mockImplementation(() => true); + const app = createApp(buildAuthEnabledEnv()); + + await app.request("/layouts/not-a-uuid", { + method: "PUT", + headers: { + Cookie: buildAuthCookie({ role: "viewer", sid: "viewer-denied" }), + Origin: "https://rack.example.com", + "Content-Type": "text/plain", + }, + body: "version: 1.0.0", + }); + + const authEvents = writeSpy.mock.calls + .map((call) => { + try { + return JSON.parse((call[0] as string).trim()); + } catch { + return null; + } + }) + .filter((e) => e?.event?.startsWith("auth.")); + + expect(authEvents.some((e) => e.event === "auth.denied")).toBe(true); + const event = authEvents.find((e) => e.event === "auth.denied"); + expect(event.subject).toBe("admin@example.com"); + expect(event.reason).toContain("viewer"); + + writeSpy.mockRestore(); + }); + + it("logs auth.login.success on valid auth check", async () => { + const writeSpy = spyOn(process.stdout, "write").mockImplementation(() => true); + const app = createApp(buildAuthEnabledEnv()); + + await app.request("/auth/check", { + headers: { + Cookie: buildAuthCookie({ sid: "check-success" }), + Origin: "https://rack.example.com", + }, + }); + + const authEvents = writeSpy.mock.calls + .map((call) => { + try { + return JSON.parse((call[0] as string).trim()); + } catch { + return null; + } + }) + .filter((e) => e?.event?.startsWith("auth.")); + + expect(authEvents.some((e) => e.event === "auth.login.success")).toBe(true); + + writeSpy.mockRestore(); + }); + + it("logs auth.login.failure on invalid auth check", async () => { + const writeSpy = spyOn(process.stdout, "write").mockImplementation(() => true); + const app = createApp(buildAuthEnabledEnv()); + + await app.request("/auth/check"); + + const authEvents = writeSpy.mock.calls + .map((call) => { + try { + return JSON.parse((call[0] as string).trim()); + } catch { + return null; + } + }) + .filter((e) => e?.event?.startsWith("auth.")); + + expect(authEvents.some((e) => e.event === "auth.login.failure")).toBe(true); + + writeSpy.mockRestore(); + }); + + it("never logs raw session tokens or cookies", async () => { + const writeSpy = spyOn(process.stdout, "write").mockImplementation(() => true); + const app = createApp(buildAuthEnabledEnv()); + + const cookie = buildAuthCookie({ sid: "redaction-test" }); + const tokenValue = cookie.split("=")[1]; + + await app.request("/auth/logout", { + method: "POST", + headers: { + Cookie: cookie, + Origin: "https://rack.example.com", + }, + }); + + const allOutput = writeSpy.mock.calls.map((c) => c[0] as string).join(""); + const authLines = allOutput + .split("\n") + .filter((line) => { + try { + const parsed = JSON.parse(line); + return parsed.event?.startsWith("auth."); + } catch { + return false; + } + }); + + for (const line of authLines) { + expect(line).not.toContain(tokenValue); + expect(line).not.toContain("rackula_auth_session="); + } + + writeSpy.mockRestore(); + }); +}); diff --git a/api/src/auth-logger.ts b/api/src/auth-logger.ts new file mode 100644 index 00000000..94339346 --- /dev/null +++ b/api/src/auth-logger.ts @@ -0,0 +1,86 @@ +/** + * Structured authentication event logger. + * + * Emits JSON lines to stdout for Docker/self-hosted log forwarding. + * All sensitive fields (tokens, passwords, session IDs) are redacted. + */ + +export type AuthEventType = + | "auth.login.success" + | "auth.login.failure" + | "auth.logout" + | "auth.session.invalid" + | "auth.denied"; + +export interface AuthEvent { + timestamp: string; + event: AuthEventType; + subject?: string; + reason?: string; + method?: string; + path?: string; + ip?: string; +} + +// Fields that must never appear in logs. +const REDACTED_FIELDS = new Set([ + "authorization", + "cookie", + "set-cookie", + "x-forwarded-for", +]); + +/** + * Extracts minimal, safe request context for logging. + */ +export function extractRequestContext( + request: Request, +): Pick { + const url = new URL(request.url); + return { + method: request.method, + path: url.pathname, + ip: request.headers.get("x-real-ip") ?? undefined, + }; +} + +/** + * Redacts a header map, replacing sensitive values with "[REDACTED]". + */ +export function redactHeaders( + headers: Record, +): Record { + const redacted: Record = {}; + for (const [key, value] of Object.entries(headers)) { + redacted[key] = REDACTED_FIELDS.has(key.toLowerCase()) + ? "[REDACTED]" + : value; + } + return redacted; +} + +/** + * Emits a structured auth event as a JSON line to stdout. + */ +export function emitAuthEvent(event: AuthEvent): void { + const line = JSON.stringify(event); + // Use process.stdout.write for atomic line output in Docker environments. + process.stdout.write(`${line}\n`); +} + +/** + * Convenience: build and emit an auth event with request context. + */ +export function logAuthEvent( + eventType: AuthEventType, + request: Request, + extra?: { subject?: string; reason?: string }, +): void { + const ctx = extractRequestContext(request); + emitAuthEvent({ + timestamp: new Date().toISOString(), + event: eventType, + ...ctx, + ...extra, + }); +} diff --git a/api/src/authorization.ts b/api/src/authorization.ts index 58001083..8b567888 100644 --- a/api/src/authorization.ts +++ b/api/src/authorization.ts @@ -1,5 +1,6 @@ import type { MiddlewareHandler } from "hono"; import { STATE_CHANGING_METHODS, type AuthSessionClaims } from "./security"; +import { logAuthEvent } from "./auth-logger"; // Role constants — single admin role for MVP. // Future roles (editor, viewer) can be added here without changing middleware shape. @@ -42,6 +43,11 @@ export function createRequireAdminMiddleware(): MiddlewareHandler { } if (!isAdmin(claims)) { + logAuthEvent("auth.denied", c.req.raw, { + subject: claims.sub, + reason: `role "${claims.role ?? "none"}" is not admin`, + }); + return c.json( { error: "Forbidden", diff --git a/api/src/security.ts b/api/src/security.ts index d955b849..8ba4098a 100644 --- a/api/src/security.ts +++ b/api/src/security.ts @@ -1,5 +1,6 @@ import type { MiddlewareHandler } from "hono"; import { createHash, createHmac, randomUUID, timingSafeEqual } from "node:crypto"; +import { logAuthEvent } from "./auth-logger"; export type AuthMode = "none" | "oidc" | "local"; export type AuthSessionSameSite = "Lax" | "Strict" | "None"; @@ -1062,6 +1063,10 @@ export function createAuthGateMiddleware( return; } + logAuthEvent("auth.session.invalid", c.req.raw, { + reason: "missing or invalid session cookie", + }); + if (isApiRequestPath(pathname)) { return c.json( { From bfd9d3612510fc3583dd83d1d7329c8914bff78f Mon Sep 17 00:00:00 2001 From: ggfevans Date: Fri, 20 Feb 2026 14:20:43 -0800 Subject: [PATCH 2/3] fix: harden auth event pseudonymization Follow up on CodeRabbit review for #1104 auth event logging:\n- pseudonymize subject/ip identifiers with keyed, namespaced hashes\n- wire configurable auth log hash key from security config\n- derive log hash key from session secret context or generate ephemeral fallback\n- tighten hash key validation and add config diagnostics\n- refactor stdout spy lifecycle and auth logger tests\n\nFixes #1104 --- api/src/app.ts | 3 +- api/src/auth-logger.test.ts | 73 ++++++++++++++---------- api/src/auth-logger.ts | 110 +++++++++++++++++++++++++++++++++++- api/src/security.test.ts | 37 ++++++++++++ api/src/security.ts | 58 ++++++++++++++++++- 5 files changed, 246 insertions(+), 35 deletions(-) diff --git a/api/src/app.ts b/api/src/app.ts index bd810c39..61ce6134 100644 --- a/api/src/app.ts +++ b/api/src/app.ts @@ -17,7 +17,7 @@ import { type EnvMap, } from "./security"; import { createRequireAdminMiddleware } from "./authorization"; -import { logAuthEvent } from "./auth-logger"; +import { configureAuthLogHashKey, logAuthEvent } from "./auth-logger"; const DEFAULT_MAX_ASSET_SIZE = 5 * 1024 * 1024; // 5MB const DEFAULT_MAX_LAYOUT_SIZE = 1 * 1024 * 1024; // 1MB @@ -38,6 +38,7 @@ type AppEnv = { export function createApp(env: EnvMap = process.env): Hono { const app = new Hono(); const securityConfig = resolveApiSecurityConfig(env); + configureAuthLogHashKey(securityConfig.authLogHashKey); if (securityConfig.isProduction && securityConfig.allowInsecureCors) { console.warn( diff --git a/api/src/auth-logger.test.ts b/api/src/auth-logger.test.ts index 7035d8f2..06aea4aa 100644 --- a/api/src/auth-logger.test.ts +++ b/api/src/auth-logger.test.ts @@ -1,9 +1,11 @@ -import { beforeEach, describe, expect, it, mock, spyOn } from "bun:test"; +import { afterEach, beforeEach, describe, expect, it, spyOn } from "bun:test"; import { + configureAuthLogHashKey, emitAuthEvent, extractRequestContext, - logAuthEvent, + pseudonymizeIdentifier, redactHeaders, + resetAuthLogHashConfigForTests, type AuthEvent, } from "./auth-logger"; import { createApp } from "./app"; @@ -59,6 +61,8 @@ function buildAuthCookie( beforeEach(() => { clearInvalidatedAuthSessions(); + resetAuthLogHashConfigForTests(); + configureAuthLogHashKey("rackula-auth-log-test-key"); }); describe("redactHeaders", () => { @@ -102,13 +106,23 @@ describe("extractRequestContext", () => { }); describe("emitAuthEvent", () => { - it("writes JSON line to stdout", () => { - const writeSpy = spyOn(process.stdout, "write").mockImplementation(() => true); + let writeSpy: ReturnType; + + beforeEach(() => { + writeSpy = spyOn(process.stdout, "write").mockImplementation(() => true); + }); + + afterEach(() => { + writeSpy.mockRestore(); + }); + + it("writes JSON line to stdout with pseudonymized identifiers", () => { const event: AuthEvent = { timestamp: "2026-02-19T10:00:00.000Z", event: "auth.logout", subject: "user@example.com", + ip: "10.0.0.9", method: "POST", path: "/auth/logout", }; @@ -119,15 +133,14 @@ describe("emitAuthEvent", () => { const output = writeSpy.mock.calls[0][0] as string; const parsed = JSON.parse(output.trim()); expect(parsed.event).toBe("auth.logout"); - expect(parsed.subject).toBe("user@example.com"); + expect(parsed.subject).toBe( + pseudonymizeIdentifier("user@example.com", "subject"), + ); + expect(parsed.ip).toBe(pseudonymizeIdentifier("10.0.0.9", "ip")); expect(parsed.timestamp).toBe("2026-02-19T10:00:00.000Z"); - - writeSpy.mockRestore(); }); it("never includes raw tokens or session IDs in output", () => { - const writeSpy = spyOn(process.stdout, "write").mockImplementation(() => true); - emitAuthEvent({ timestamp: new Date().toISOString(), event: "auth.session.invalid", @@ -140,14 +153,21 @@ describe("emitAuthEvent", () => { // Verify no common secret patterns leak expect(output).not.toContain("Bearer"); expect(output).not.toContain("rackula_auth_session="); - - writeSpy.mockRestore(); }); }); describe("auth event integration", () => { + let writeSpy: ReturnType; + + beforeEach(() => { + writeSpy = spyOn(process.stdout, "write").mockImplementation(() => true); + }); + + afterEach(() => { + writeSpy.mockRestore(); + }); + it("logs auth.session.invalid when anonymous request hits auth gate", async () => { - const writeSpy = spyOn(process.stdout, "write").mockImplementation(() => true); const app = createApp(buildAuthEnabledEnv()); await app.request("/api/layouts"); @@ -166,12 +186,9 @@ describe("auth event integration", () => { const event = authEvents.find((e) => e.event === "auth.session.invalid"); expect(event.reason).toBe("missing or invalid session cookie"); expect(event.path).toBe("/api/layouts"); - - writeSpy.mockRestore(); }); it("logs auth.logout on successful logout", async () => { - const writeSpy = spyOn(process.stdout, "write").mockImplementation(() => true); const app = createApp(buildAuthEnabledEnv()); await app.request("/auth/logout", { @@ -194,13 +211,12 @@ describe("auth event integration", () => { expect(authEvents.some((e) => e.event === "auth.logout")).toBe(true); const event = authEvents.find((e) => e.event === "auth.logout"); - expect(event.subject).toBe("admin@example.com"); - - writeSpy.mockRestore(); + expect(event.subject).toBe( + pseudonymizeIdentifier("admin@example.com", "subject"), + ); }); it("logs auth.denied when non-admin attempts write", async () => { - const writeSpy = spyOn(process.stdout, "write").mockImplementation(() => true); const app = createApp(buildAuthEnabledEnv()); await app.request("/layouts/not-a-uuid", { @@ -225,14 +241,13 @@ describe("auth event integration", () => { expect(authEvents.some((e) => e.event === "auth.denied")).toBe(true); const event = authEvents.find((e) => e.event === "auth.denied"); - expect(event.subject).toBe("admin@example.com"); + expect(event.subject).toBe( + pseudonymizeIdentifier("admin@example.com", "subject"), + ); expect(event.reason).toContain("viewer"); - - writeSpy.mockRestore(); }); it("logs auth.login.success on valid auth check", async () => { - const writeSpy = spyOn(process.stdout, "write").mockImplementation(() => true); const app = createApp(buildAuthEnabledEnv()); await app.request("/auth/check", { @@ -253,12 +268,13 @@ describe("auth event integration", () => { .filter((e) => e?.event?.startsWith("auth.")); expect(authEvents.some((e) => e.event === "auth.login.success")).toBe(true); - - writeSpy.mockRestore(); + const event = authEvents.find((e) => e.event === "auth.login.success"); + expect(event.subject).toBe( + pseudonymizeIdentifier("admin@example.com", "subject"), + ); }); it("logs auth.login.failure on invalid auth check", async () => { - const writeSpy = spyOn(process.stdout, "write").mockImplementation(() => true); const app = createApp(buildAuthEnabledEnv()); await app.request("/auth/check"); @@ -274,12 +290,9 @@ describe("auth event integration", () => { .filter((e) => e?.event?.startsWith("auth.")); expect(authEvents.some((e) => e.event === "auth.login.failure")).toBe(true); - - writeSpy.mockRestore(); }); it("never logs raw session tokens or cookies", async () => { - const writeSpy = spyOn(process.stdout, "write").mockImplementation(() => true); const app = createApp(buildAuthEnabledEnv()); const cookie = buildAuthCookie({ sid: "redaction-test" }); @@ -309,7 +322,5 @@ describe("auth event integration", () => { expect(line).not.toContain(tokenValue); expect(line).not.toContain("rackula_auth_session="); } - - writeSpy.mockRestore(); }); }); diff --git a/api/src/auth-logger.ts b/api/src/auth-logger.ts index 94339346..33504780 100644 --- a/api/src/auth-logger.ts +++ b/api/src/auth-logger.ts @@ -4,6 +4,7 @@ * Emits JSON lines to stdout for Docker/self-hosted log forwarding. * All sensitive fields (tokens, passwords, session IDs) are redacted. */ +import { createHmac } from "node:crypto"; export type AuthEventType = | "auth.login.success" @@ -22,6 +23,21 @@ export interface AuthEvent { ip?: string; } +const DEFAULT_AUTH_LOG_HASH_KEY = "rackula:auth-log:v1:default"; +const MIN_AUTH_LOG_HASH_KEY_LENGTH = 16; +type AuthIdentifierType = "subject" | "ip"; +let authLogHashKey: string | undefined; +let hasWarnedDefaultHashKey = false; + +export function resetAuthLogHashConfigForTests(): void { + authLogHashKey = undefined; + hasWarnedDefaultHashKey = false; +} + +export function getAuthLogHashKeyForTests(): string | undefined { + return authLogHashKey; +} + // Fields that must never appear in logs. const REDACTED_FIELDS = new Set([ "authorization", @@ -30,6 +46,93 @@ const REDACTED_FIELDS = new Set([ "x-forwarded-for", ]); +/** + * Configures the keyed hash input used to pseudonymize log identifiers. + */ +export function configureAuthLogHashKey(hashKey: string | undefined): void { + const normalized = hashKey?.trim(); + const normalizedLength = normalized?.length ?? 0; + if ( + normalizedLength > 0 && + normalizedLength < MIN_AUTH_LOG_HASH_KEY_LENGTH + ) { + // Primary validation lives in resolveApiSecurityConfig(security.ts); this is a + // defensive fallback for direct caller usage that bypasses config resolution. + console.warn( + `[auth-logger] Ignoring auth log hash key shorter than ${MIN_AUTH_LOG_HASH_KEY_LENGTH} characters. This fallback applies only when resolveApiSecurityConfig is not used.`, + ); + authLogHashKey = undefined; + } else { + authLogHashKey = normalizedLength > 0 ? normalized : undefined; + if (authLogHashKey) { + console.info( + `[auth-logger] Auth log hash key configured (>=${MIN_AUTH_LOG_HASH_KEY_LENGTH} chars).`, + ); + } + } + hasWarnedDefaultHashKey = false; +} + +function getAuthLogHashKey(): string { + if (authLogHashKey) { + return authLogHashKey; + } + + if (!hasWarnedDefaultHashKey) { + console.warn( + "[auth-logger] No auth log hash key configured. Falling back to default auth log hash key; configure RACKULA_AUTH_LOG_HASH_KEY to avoid predictable cross-instance pseudonyms.", + ); + hasWarnedDefaultHashKey = true; + } + + return DEFAULT_AUTH_LOG_HASH_KEY; +} + +/** + * Pseudonymizes potentially identifying values using a keyed SHA-256 hash. + */ +export function pseudonymizeIdentifier( + value: string, + identifierType: AuthIdentifierType, +): string { + const normalized = normalizeIdentifier(value); + if (!normalized) { + throw new Error("Cannot pseudonymize an empty identifier value."); + } + + return pseudonymizeNormalizedIdentifier(normalized, identifierType); +} + +function normalizeIdentifier(value: string | undefined): string | undefined { + if (value === undefined) { + return undefined; + } + + const normalized = value.trim(); + return normalized.length > 0 ? normalized : undefined; +} + +function pseudonymizeNormalizedIdentifier( + normalizedValue: string, + identifierType: AuthIdentifierType, +): string { + return createHmac("sha256", getAuthLogHashKey()) + .update(`${identifierType}:${normalizedValue}`) + .digest("hex"); +} + +function pseudonymizeOptionalIdentifier( + value: string | undefined, + identifierType: AuthIdentifierType, +): string | undefined { + const normalized = normalizeIdentifier(value); + if (!normalized) { + return undefined; + } + + return pseudonymizeNormalizedIdentifier(normalized, identifierType); +} + /** * Extracts minimal, safe request context for logging. */ @@ -63,7 +166,12 @@ export function redactHeaders( * Emits a structured auth event as a JSON line to stdout. */ export function emitAuthEvent(event: AuthEvent): void { - const line = JSON.stringify(event); + const sanitizedEvent: AuthEvent = { + ...event, + subject: pseudonymizeOptionalIdentifier(event.subject, "subject"), + ip: pseudonymizeOptionalIdentifier(event.ip, "ip"), + }; + const line = JSON.stringify(sanitizedEvent); // Use process.stdout.write for atomic line output in Docker environments. process.stdout.write(`${line}\n`); } diff --git a/api/src/security.test.ts b/api/src/security.test.ts index 653d95d0..44cdac2d 100644 --- a/api/src/security.test.ts +++ b/api/src/security.test.ts @@ -199,6 +199,43 @@ describe("resolveApiSecurityConfig", () => { expect(config.csrfTrustedOrigins).toEqual(["https://rack.example.com"]); }); + it("derives auth log hash key from auth session secret by default", () => { + const first = resolveApiSecurityConfig(buildAuthEnabledEnv()); + const second = resolveApiSecurityConfig(buildAuthEnabledEnv()); + expect(first.authLogHashKey).toBe(second.authLogHashKey); + expect(first.authLogHashKey).toMatch(/^[a-f0-9]{64}$/); + expect(first.authLogHashKey).not.toBe(TEST_AUTH_SECRET); + }); + + it("accepts explicit auth log hash key override", () => { + const config = resolveApiSecurityConfig( + buildAuthEnabledEnv({ + RACKULA_AUTH_LOG_HASH_KEY: "rackula-auth-log-key-override", + }), + ); + + expect(config.authLogHashKey).toBe("rackula-auth-log-key-override"); + }); + + it("rejects short auth log hash key overrides", () => { + expect(() => + resolveApiSecurityConfig( + buildAuthEnabledEnv({ + RACKULA_AUTH_LOG_HASH_KEY: "too-short", + }), + ), + ).toThrow("RACKULA_AUTH_LOG_HASH_KEY must be at least 16 characters."); + }); + + it("generates ephemeral auth log hash keys without configured secrets", () => { + const first = resolveApiSecurityConfig(buildEnv()); + const second = resolveApiSecurityConfig(buildEnv()); + + expect(first.authLogHashKey).toMatch(/^[a-f0-9]{64}$/); + expect(second.authLogHashKey).toMatch(/^[a-f0-9]{64}$/); + expect(first.authLogHashKey).not.toBe(second.authLogHashKey); + }); + it("rejects production startup when CORS_ORIGIN is missing", () => { expect(() => resolveApiSecurityConfig(buildEnv({ NODE_ENV: "production" })), diff --git a/api/src/security.ts b/api/src/security.ts index 8ba4098a..2fcc2874 100644 --- a/api/src/security.ts +++ b/api/src/security.ts @@ -1,5 +1,11 @@ import type { MiddlewareHandler } from "hono"; -import { createHash, createHmac, randomUUID, timingSafeEqual } from "node:crypto"; +import { + createHash, + createHmac, + randomBytes, + randomUUID, + timingSafeEqual, +} from "node:crypto"; import { logAuthEvent } from "./auth-logger"; export type AuthMode = "none" | "oidc" | "local"; @@ -46,6 +52,7 @@ export interface ApiSecurityConfig { authMode: AuthMode; authEnabled: boolean; authSessionSecret?: string; + authLogHashKey: string; authSessionCookieName: string; authSessionCookieSecure: boolean; authSessionCookieSameSite: AuthSessionSameSite; @@ -82,6 +89,9 @@ const CORS_ORIGIN_EMPTY_ERROR = "CORS_ORIGIN is set but empty. Provide at least one origin."; const DEFAULT_AUTH_SESSION_MAX_AGE_SECONDS = 12 * 60 * 60; const DEFAULT_AUTH_SESSION_IDLE_TIMEOUT_SECONDS = 30 * 60; +const AUTH_LOG_HASH_CONTEXT = "rackula:auth-log:v1:"; +const MIN_AUTH_LOG_HASH_KEY_LENGTH = 16; +const GENERATED_AUTH_LOG_HASH_KEY_BYTES = 32; const MIN_AUTH_SESSION_TIMEOUT_SECONDS = 60; const MAX_AUTH_SESSION_MAX_AGE_SECONDS = 7 * 24 * 60 * 60; const AUTH_SESSION_REFRESH_THRESHOLD_SECONDS = 60; @@ -110,6 +120,40 @@ function parseBoolean(value: string | undefined): boolean { return value?.toLowerCase() === "true"; } +function deriveAuthLogHashKey(authSessionSecret: string): string { + return createHmac("sha256", authSessionSecret) + .update(AUTH_LOG_HASH_CONTEXT) + .digest("hex"); +} + +function resolveAuthLogHashKey(options: { + authLogHashKeyRaw: string | undefined; + authSessionSecret: string | undefined; + isProduction: boolean; +}): string { + const normalizedAuthLogHashKey = options.authLogHashKeyRaw?.trim(); + if (normalizedAuthLogHashKey) { + if (normalizedAuthLogHashKey.length < MIN_AUTH_LOG_HASH_KEY_LENGTH) { + throw new Error( + `RACKULA_AUTH_LOG_HASH_KEY must be at least ${MIN_AUTH_LOG_HASH_KEY_LENGTH} characters.`, + ); + } + return normalizedAuthLogHashKey; + } + + if (options.authSessionSecret) { + return deriveAuthLogHashKey(options.authSessionSecret); + } + + if (options.isProduction) { + console.warn( + "⚠ Auth log hash key is not configured and no auth session secret is available. Generating an ephemeral per-process key. Set RACKULA_AUTH_LOG_HASH_KEY in production for stable pseudonymization.", + ); + } + + return randomBytes(GENERATED_AUTH_LOG_HASH_KEY_BYTES).toString("hex"); +} + function parseOptionalBoolean( name: string, value: string | undefined, @@ -282,7 +326,9 @@ function normalizeOrigin(input: string): string { return url.origin; } catch (error) { const reason = error instanceof Error ? error.message : String(error); - throw new Error(`Invalid CORS origin "${input}": ${reason}`); + throw new Error(`Invalid CORS origin "${input}": ${reason}`, { + cause: error, + }); } } @@ -924,6 +970,7 @@ export function resolveApiSecurityConfig( const authSessionSecretRaw = env.RACKULA_AUTH_SESSION_SECRET ?? env.AUTH_SESSION_SECRET; const authSessionSecret = authSessionSecretRaw?.trim() || undefined; + const authLogHashKeyRaw = env.RACKULA_AUTH_LOG_HASH_KEY ?? env.AUTH_LOG_HASH_KEY; if (authEnabled && !authSessionSecret) { throw new Error( @@ -941,6 +988,12 @@ export function resolveApiSecurityConfig( ); } + const authLogHashKey = resolveAuthLogHashKey({ + authLogHashKeyRaw, + authSessionSecret, + isProduction, + }); + const authSessionMaxAgeSeconds = parseBoundedPositiveInteger( "RACKULA_AUTH_SESSION_MAX_AGE_SECONDS", env.RACKULA_AUTH_SESSION_MAX_AGE_SECONDS, @@ -1001,6 +1054,7 @@ export function resolveApiSecurityConfig( authMode, authEnabled, authSessionSecret, + authLogHashKey, authSessionCookieName, authSessionCookieSecure, authSessionCookieSameSite, From a5865f8eaa0369ff88433b712d5eef818433cc4f Mon Sep 17 00:00:00 2001 From: ggfevans Date: Wed, 25 Feb 2026 01:19:52 -0800 Subject: [PATCH 3/3] fix: address CodeRabbit review feedback on auth event logging MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - Deduplicate MIN_AUTH_LOG_HASH_KEY_LENGTH (export from auth-logger, import in security) - Add JSDoc to extractRequestContext explaining x-real-ip choice - Reduce startup log noise (console.info → console.debug) - Extract safeLogAuthEvent helper for fault-tolerant logging at all 5 call sites - Extract extractAuthEvents test helper to deduplicate parse/filter pattern - Add null guards on .find() results in integration tests Co-Authored-By: Claude Opus 4.6 --- api/src/app.ts | 8 ++-- api/src/auth-logger.test.ts | 76 +++++++++++++------------------------ api/src/auth-logger.ts | 26 ++++++++++++- api/src/authorization.ts | 4 +- api/src/security.ts | 5 +-- 5 files changed, 59 insertions(+), 60 deletions(-) diff --git a/api/src/app.ts b/api/src/app.ts index 61ce6134..21665ab1 100644 --- a/api/src/app.ts +++ b/api/src/app.ts @@ -17,7 +17,7 @@ import { type EnvMap, } from "./security"; import { createRequireAdminMiddleware } from "./authorization"; -import { configureAuthLogHashKey, logAuthEvent } from "./auth-logger"; +import { configureAuthLogHashKey, safeLogAuthEvent } from "./auth-logger"; const DEFAULT_MAX_ASSET_SIZE = 5 * 1024 * 1024; // 5MB const DEFAULT_MAX_LAYOUT_SIZE = 1 * 1024 * 1024; // 1MB @@ -118,7 +118,7 @@ export function createApp(env: EnvMap = process.env): Hono { const claims = resolveAuthenticatedSessionClaims(c.req.raw, authSessionConfig); if (!claims) { - logAuthEvent("auth.login.failure", c.req.raw, { + safeLogAuthEvent("auth.login.failure", c.req.raw, { reason: "invalid or missing session on auth check", }); return c.json( @@ -130,7 +130,7 @@ export function createApp(env: EnvMap = process.env): Hono { ); } - logAuthEvent("auth.login.success", c.req.raw, { subject: claims.sub }); + safeLogAuthEvent("auth.login.success", c.req.raw, { subject: claims.sub }); const refreshedCookie = createRefreshedAuthSessionCookieHeader( claims, @@ -147,7 +147,7 @@ export function createApp(env: EnvMap = process.env): Hono { const claims = resolveAuthenticatedSessionClaims(c.req.raw, authSessionConfig); if (claims) { invalidateAuthSession(claims.sid, claims.exp); - logAuthEvent("auth.logout", c.req.raw, { subject: claims.sub }); + safeLogAuthEvent("auth.logout", c.req.raw, { subject: claims.sub }); } c.header( diff --git a/api/src/auth-logger.test.ts b/api/src/auth-logger.test.ts index 06aea4aa..8fe99d01 100644 --- a/api/src/auth-logger.test.ts +++ b/api/src/auth-logger.test.ts @@ -167,12 +167,8 @@ describe("auth event integration", () => { writeSpy.mockRestore(); }); - it("logs auth.session.invalid when anonymous request hits auth gate", async () => { - const app = createApp(buildAuthEnabledEnv()); - - await app.request("/api/layouts"); - - const authEvents = writeSpy.mock.calls + function extractAuthEvents(spy: ReturnType): Array> { + return spy.mock.calls .map((call) => { try { return JSON.parse((call[0] as string).trim()); @@ -180,12 +176,23 @@ describe("auth event integration", () => { return null; } }) - .filter((e) => e?.event?.startsWith("auth.")); + .filter((e): e is Record => + typeof e?.event === "string" && (e.event as string).startsWith("auth."), + ); + } + + it("logs auth.session.invalid when anonymous request hits auth gate", async () => { + const app = createApp(buildAuthEnabledEnv()); + + await app.request("/api/layouts"); + + const authEvents = extractAuthEvents(writeSpy); expect(authEvents.some((e) => e.event === "auth.session.invalid")).toBe(true); const event = authEvents.find((e) => e.event === "auth.session.invalid"); - expect(event.reason).toBe("missing or invalid session cookie"); - expect(event.path).toBe("/api/layouts"); + expect(event).toBeDefined(); + expect(event!.reason).toBe("missing or invalid session cookie"); + expect(event!.path).toBe("/api/layouts"); }); it("logs auth.logout on successful logout", async () => { @@ -199,19 +206,12 @@ describe("auth event integration", () => { }, }); - const authEvents = writeSpy.mock.calls - .map((call) => { - try { - return JSON.parse((call[0] as string).trim()); - } catch { - return null; - } - }) - .filter((e) => e?.event?.startsWith("auth.")); + const authEvents = extractAuthEvents(writeSpy); expect(authEvents.some((e) => e.event === "auth.logout")).toBe(true); const event = authEvents.find((e) => e.event === "auth.logout"); - expect(event.subject).toBe( + expect(event).toBeDefined(); + expect(event!.subject).toBe( pseudonymizeIdentifier("admin@example.com", "subject"), ); }); @@ -229,22 +229,15 @@ describe("auth event integration", () => { body: "version: 1.0.0", }); - const authEvents = writeSpy.mock.calls - .map((call) => { - try { - return JSON.parse((call[0] as string).trim()); - } catch { - return null; - } - }) - .filter((e) => e?.event?.startsWith("auth.")); + const authEvents = extractAuthEvents(writeSpy); expect(authEvents.some((e) => e.event === "auth.denied")).toBe(true); const event = authEvents.find((e) => e.event === "auth.denied"); - expect(event.subject).toBe( + expect(event).toBeDefined(); + expect(event!.subject).toBe( pseudonymizeIdentifier("admin@example.com", "subject"), ); - expect(event.reason).toContain("viewer"); + expect(event!.reason).toContain("viewer"); }); it("logs auth.login.success on valid auth check", async () => { @@ -257,19 +250,12 @@ describe("auth event integration", () => { }, }); - const authEvents = writeSpy.mock.calls - .map((call) => { - try { - return JSON.parse((call[0] as string).trim()); - } catch { - return null; - } - }) - .filter((e) => e?.event?.startsWith("auth.")); + const authEvents = extractAuthEvents(writeSpy); expect(authEvents.some((e) => e.event === "auth.login.success")).toBe(true); const event = authEvents.find((e) => e.event === "auth.login.success"); - expect(event.subject).toBe( + expect(event).toBeDefined(); + expect(event!.subject).toBe( pseudonymizeIdentifier("admin@example.com", "subject"), ); }); @@ -279,15 +265,7 @@ describe("auth event integration", () => { await app.request("/auth/check"); - const authEvents = writeSpy.mock.calls - .map((call) => { - try { - return JSON.parse((call[0] as string).trim()); - } catch { - return null; - } - }) - .filter((e) => e?.event?.startsWith("auth.")); + const authEvents = extractAuthEvents(writeSpy); expect(authEvents.some((e) => e.event === "auth.login.failure")).toBe(true); }); diff --git a/api/src/auth-logger.ts b/api/src/auth-logger.ts index 33504780..b2d00c88 100644 --- a/api/src/auth-logger.ts +++ b/api/src/auth-logger.ts @@ -24,7 +24,7 @@ export interface AuthEvent { } const DEFAULT_AUTH_LOG_HASH_KEY = "rackula:auth-log:v1:default"; -const MIN_AUTH_LOG_HASH_KEY_LENGTH = 16; +export const MIN_AUTH_LOG_HASH_KEY_LENGTH = 16; type AuthIdentifierType = "subject" | "ip"; let authLogHashKey: string | undefined; let hasWarnedDefaultHashKey = false; @@ -65,7 +65,7 @@ export function configureAuthLogHashKey(hashKey: string | undefined): void { } else { authLogHashKey = normalizedLength > 0 ? normalized : undefined; if (authLogHashKey) { - console.info( + console.debug( `[auth-logger] Auth log hash key configured (>=${MIN_AUTH_LOG_HASH_KEY_LENGTH} chars).`, ); } @@ -135,6 +135,10 @@ function pseudonymizeOptionalIdentifier( /** * Extracts minimal, safe request context for logging. + * + * Uses `x-real-ip` exclusively for client IP — this header is set by the trusted + * reverse proxy (nginx). `x-forwarded-for` is intentionally excluded because it + * is client-spoofable and is already listed in {@link REDACTED_FIELDS}. */ export function extractRequestContext( request: Request, @@ -192,3 +196,21 @@ export function logAuthEvent( ...extra, }); } + +/** + * Fault-tolerant wrapper around {@link logAuthEvent}. + * + * Swallows and logs errors so that a logging failure (e.g. HMAC misconfiguration) + * never crashes the request handler that called it. + */ +export function safeLogAuthEvent( + eventType: AuthEventType, + request: Request, + extra?: { subject?: string; reason?: string }, +): void { + try { + logAuthEvent(eventType, request, extra); + } catch (err) { + console.error("[auth-logger] Failed to log auth event:", err); + } +} diff --git a/api/src/authorization.ts b/api/src/authorization.ts index 8b567888..9a4d58d2 100644 --- a/api/src/authorization.ts +++ b/api/src/authorization.ts @@ -1,6 +1,6 @@ import type { MiddlewareHandler } from "hono"; import { STATE_CHANGING_METHODS, type AuthSessionClaims } from "./security"; -import { logAuthEvent } from "./auth-logger"; +import { safeLogAuthEvent } from "./auth-logger"; // Role constants — single admin role for MVP. // Future roles (editor, viewer) can be added here without changing middleware shape. @@ -43,7 +43,7 @@ export function createRequireAdminMiddleware(): MiddlewareHandler { } if (!isAdmin(claims)) { - logAuthEvent("auth.denied", c.req.raw, { + safeLogAuthEvent("auth.denied", c.req.raw, { subject: claims.sub, reason: `role "${claims.role ?? "none"}" is not admin`, }); diff --git a/api/src/security.ts b/api/src/security.ts index 2fcc2874..573d7a37 100644 --- a/api/src/security.ts +++ b/api/src/security.ts @@ -6,7 +6,7 @@ import { randomUUID, timingSafeEqual, } from "node:crypto"; -import { logAuthEvent } from "./auth-logger"; +import { safeLogAuthEvent, MIN_AUTH_LOG_HASH_KEY_LENGTH } from "./auth-logger"; export type AuthMode = "none" | "oidc" | "local"; export type AuthSessionSameSite = "Lax" | "Strict" | "None"; @@ -90,7 +90,6 @@ const CORS_ORIGIN_EMPTY_ERROR = const DEFAULT_AUTH_SESSION_MAX_AGE_SECONDS = 12 * 60 * 60; const DEFAULT_AUTH_SESSION_IDLE_TIMEOUT_SECONDS = 30 * 60; const AUTH_LOG_HASH_CONTEXT = "rackula:auth-log:v1:"; -const MIN_AUTH_LOG_HASH_KEY_LENGTH = 16; const GENERATED_AUTH_LOG_HASH_KEY_BYTES = 32; const MIN_AUTH_SESSION_TIMEOUT_SECONDS = 60; const MAX_AUTH_SESSION_MAX_AGE_SECONDS = 7 * 24 * 60 * 60; @@ -1117,7 +1116,7 @@ export function createAuthGateMiddleware( return; } - logAuthEvent("auth.session.invalid", c.req.raw, { + safeLogAuthEvent("auth.session.invalid", c.req.raw, { reason: "missing or invalid session cookie", });