feat(observability): add gateway structured request logs

apps/gateway/src/observability.test.ts

@@ -1,9 +1,14 @@
-import { PrometheusHttpMetrics } from '@life-os/observability';
+import {
+  CredentialFreeJsonLogger,
+  PrometheusHttpMetrics,
+  getRequestContext,
+} from '@life-os/observability';
 import { describe, expect, it, vi } from 'vitest';
 import { createGatewayObservabilityMiddleware } from './observability';
 
 const VALID_CORRELATION_ID = '018f47b2-c1d2-4a30-8c17-221fb579c042';
 const GENERATED_CORRELATION_ID = 'd1191b96-b7f4-4d8f-b1f7-9e2838686d5f';
+const FIXED_TIMESTAMP = '2026-08-03T19:30:00.000Z';
 
 type ResponseEvent = 'finish' | 'close';
 
@@ -40,34 +45,73 @@ function request(path: string, correlationId?: string) {
   };
 }
 
+function createLogger(lines: string[]): CredentialFreeJsonLogger {
+  return new CredentialFreeJsonLogger({
+    serviceName: 'life-os-gateway',
+    write: (line) => lines.push(line),
+    wallClock: () => FIXED_TIMESTAMP,
+  });
+}
+
+function parsedLines(lines: string[]): Array<Record<string, unknown>> {
+  return lines.map((line) => JSON.parse(line) as Record<string, unknown>);
+}
+
 describe('gateway observability middleware', () => {
-  it('preserves a valid correlation ID and records the bounded route once', () => {
+  it('propagates context and records one bounded completion', () => {
+    const lines: string[] = [];
     const metrics = new PrometheusHttpMetrics({
       serviceName: 'life-os-gateway',
     });
-    const middleware = createGatewayObservabilityMiddleware(metrics);
+    const clock = [1000, 1250];
+    const middleware = createGatewayObservabilityMiddleware(
+      metrics,
+      undefined,
+      createLogger(lines),
+      () => clock.shift() ?? 1250,
+    );
     const response = new FakeResponse();
-    const next = vi.fn();
+    const next = vi.fn(() => {
+      expect(getRequestContext()?.correlationId).toBe(VALID_CORRELATION_ID);
+    });
 
     middleware(request('/v1/today', VALID_CORRELATION_ID), response, next);
     response.finish(503);
     response.close();
 
     expect(next).toHaveBeenCalledOnce();
+    expect(getRequestContext()).toBeUndefined();
     expect(response.headers.get('x-correlation-id')).toBe(VALID_CORRELATION_ID);
     expect(metrics.renderPrometheus()).toContain(
       'route="/v1/today",status_class="5xx"} 1',
     );
     expect(metrics.renderPrometheus()).not.toContain('status_class="4xx"} 1');
+    expect(parsedLines(lines)).toEqual([
+      {
+        timestamp: FIXED_TIMESTAMP,
+        level: 'error',
+        event: 'http.request.completed',
+        service: 'life-os-gateway',
+        correlation_id: VALID_CORRELATION_ID,
+        method: 'GET',
+        route: '/v1/today',
+        status_code: 503,
+        status_class: '5xx',
+        duration_seconds: 0.25,
+      },
+    ]);
   });
 
   it('replaces invalid input and collapses unknown concrete paths', () => {
+    const lines: string[] = [];
     const metrics = new PrometheusHttpMetrics({
       serviceName: 'life-os-gateway',
     });
     const middleware = createGatewayObservabilityMiddleware(
       metrics,
       () => GENERATED_CORRELATION_ID,
+      createLogger(lines),
+      () => 1000,
     );
     const response = new FakeResponse();
     const concretePath = '/v1/tasks/018f47b2-c1d2-4a30-8c17-221fb579c042';
@@ -80,19 +124,28 @@ describe('gateway observability middleware', () => {
     response.finish(404);
 
     const output = metrics.renderPrometheus();
+    const serializedLogs = lines.join('\n');
     expect(response.headers.get('x-correlation-id')).toBe(
       GENERATED_CORRELATION_ID,
     );
     expect(output).toContain('route="/unmatched",status_class="4xx"} 1');
+    expect(serializedLogs).toContain('"route":"/unmatched"');
     expect(output).not.toContain(concretePath);
-    expect(output).not.toContain('secret');
+    expect(serializedLogs).not.toContain(concretePath);
+    expect(serializedLogs).not.toContain('token=secret');
   });
 
   it('finalizes an aborted response as a client-closed request', () => {
+    const lines: string[] = [];
     const metrics = new PrometheusHttpMetrics({
       serviceName: 'life-os-gateway',
     });
-    const middleware = createGatewayObservabilityMiddleware(metrics);
+    const middleware = createGatewayObservabilityMiddleware(
+      metrics,
+      undefined,
+      createLogger(lines),
+      () => 1000,
+    );
     const response = new FakeResponse();
 
     middleware(request('/v1/today'), response, () => undefined);
@@ -103,9 +156,16 @@ describe('gateway observability middleware', () => {
     expect(output).toContain(
       'life_os_http_in_flight_requests{service="life-os-gateway"} 0',
     );
+    expect(parsedLines(lines)[0]).toMatchObject({
+      level: 'warn',
+      event: 'http.request.completed',
+      status_code: 499,
+      status_class: '4xx',
+    });
   });
 
-  it('isolates metric failures from response finalization', () => {
+  it('emits a sanitized record and completes when metrics fail', () => {
+    const lines: string[] = [];
     const metrics = new PrometheusHttpMetrics({
       serviceName: 'life-os-gateway',
       maxSeries: 1,
@@ -116,28 +176,82 @@ describe('gateway observability middleware', () => {
       statusCode: 200,
       durationSeconds: 0.1,
     });
-    const reportMetricFailure = vi.fn();
     const middleware = createGatewayObservabilityMiddleware(
       metrics,
       undefined,
-      reportMetricFailure,
+      createLogger(lines),
+      () => 1000,
     );
     const response = new FakeResponse();
 
     middleware(request('/v1/today'), response, () => undefined);
     expect(() => response.finish(200)).not.toThrow();
 
-    expect(reportMetricFailure).toHaveBeenCalledOnce();
+    expect(parsedLines(lines)).toEqual([
+      {
+        timestamp: FIXED_TIMESTAMP,
+        level: 'error',
+        event: 'observability.failure',
+        service: 'life-os-gateway',
+        correlation_id: response.headers.get('x-correlation-id'),
+        operation: 'metrics.record',
+      },
+      {
+        timestamp: FIXED_TIMESTAMP,
+        level: 'info',
+        event: 'http.request.completed',
+        service: 'life-os-gateway',
+        correlation_id: response.headers.get('x-correlation-id'),
+        method: 'GET',
+        route: '/v1/today',
+        status_code: 200,
+        status_class: '2xx',
+        duration_seconds: 0,
+      },
+    ]);
+    expect(lines.join('\n')).not.toMatch(/series limit|stack|message|secret/i);
     expect(metrics.renderPrometheus()).toContain(
       'life_os_http_in_flight_requests{service="life-os-gateway"} 0',
     );
   });
 
+  it('isolates structured-log writer failures from response finalization', () => {
+    const metrics = new PrometheusHttpMetrics({
+      serviceName: 'life-os-gateway',
+    });
+    const logger = new CredentialFreeJsonLogger({
+      serviceName: 'life-os-gateway',
+      write: () => {
+        throw new Error('writer unavailable');
+      },
+      wallClock: () => FIXED_TIMESTAMP,
+    });
+    const middleware = createGatewayObservabilityMiddleware(
+      metrics,
+      undefined,
+      logger,
+      () => 1000,
+    );
+    const response = new FakeResponse();
+
+    middleware(request('/v1/health'), response, () => undefined);
+    expect(() => response.finish(200)).not.toThrow();
+    expect(metrics.renderPrometheus()).toContain(
+      'route="/v1/health",status_class="2xx"} 1',
+    );
+  });
+
   it('records synchronous middleware failures once and rethrows', () => {
+    const lines: string[] = [];
     const metrics = new PrometheusHttpMetrics({
       serviceName: 'life-os-gateway',
     });
-    const middleware = createGatewayObservabilityMiddleware(metrics);
+    const middleware = createGatewayObservabilityMiddleware(
+      metrics,
+      undefined,
+      createLogger(lines),
+      () => 1000,
+    );
     const response = new FakeResponse();
 
     expect(() =>
@@ -150,5 +264,12 @@ describe('gateway observability middleware', () => {
     const output = metrics.renderPrometheus();
     expect(output).toContain('route="/v1/health",status_class="5xx"} 1');
     expect(output).not.toContain('status_class="2xx"} 1');
+    expect(parsedLines(lines)).toHaveLength(1);
+    expect(parsedLines(lines)[0]).toMatchObject({
+      event: 'http.request.completed',
+      status_code: 500,
+      status_class: '5xx',
+    });
+    expect(lines.join('\n')).not.toContain('synthetic failure');
   });
 });