saqib mirandClaude Sonnet 5
acd3843aaf
User Stories 1-2: every completed request (including 404s and early replies from other hooks) now emits exactly one structured access-log line, and every log line produced during that request's handling shares its requestId/correlationId via a new AsyncLocalStorage-backed Pino mixin — with zero changes to any existing log call site. The previously-dead supporthub_http_request_duration_seconds histogram now actually receives observations, so error rate and latency per route are computable from /metrics alone. Also bumps @opentelemetry/sdk-trace-base 1.x -> 2.x to align with the two new tracing dependencies added in this same branch (exporter-trace-otlp-http, resources) onto one consistent major version — npm had otherwise installed two incompatible OTel core/resources majors side by side, which also happened to resolve a moderate DoS advisory in @opentelemetry/core <2.8.0. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
76 lines
2.5 KiB
TypeScript
76 lines
2.5 KiB
TypeScript
import { describe, it, expect, beforeAll, afterAll, vi, MockInstance } from 'vitest';
|
|
import { buildApp } from '@/app';
|
|
import { FastifyInstance } from 'fastify';
|
|
import { logger } from '@/infrastructure/observability';
|
|
|
|
/** Covers specs/014-full-observability/quickstart.md Scenario 1 against a real running app. */
|
|
describe('Per-request access log (User Story 1)', () => {
|
|
let app: FastifyInstance;
|
|
|
|
beforeAll(async () => {
|
|
app = await buildApp();
|
|
});
|
|
|
|
afterAll(async () => {
|
|
await app.close();
|
|
});
|
|
|
|
function callsData(spy: MockInstance): Record<string, unknown>[] {
|
|
return spy.mock.calls.map(([data]: unknown[]) => data as Record<string, unknown>);
|
|
}
|
|
|
|
function accessLogCalls(spy: MockInstance): Record<string, unknown>[] {
|
|
return callsData(spy).filter((data) => data?.event === 'http_request_completed');
|
|
}
|
|
|
|
it('emits exactly one access-log line for a successful request, carrying a requestId', async () => {
|
|
const infoSpy = vi.spyOn(logger, 'info');
|
|
|
|
const res = await app.inject({ method: 'GET', url: '/health/live' });
|
|
expect(res.statusCode).toBe(200);
|
|
|
|
const lines = accessLogCalls(infoSpy);
|
|
expect(lines).toHaveLength(1);
|
|
expect(lines[0]).toMatchObject({ method: 'GET', route: '/health/live', statusCode: 200 });
|
|
expect(lines[0]?.requestId).toBeTruthy();
|
|
expect(lines[0]?.requestId).toBe(res.headers['x-request-id']);
|
|
|
|
infoSpy.mockRestore();
|
|
});
|
|
|
|
it('correlates the access-log line with other log lines produced for the same request', async () => {
|
|
const warnSpy = vi.spyOn(logger, 'warn');
|
|
|
|
const res = await app.inject({
|
|
method: 'POST',
|
|
url: '/auth/login',
|
|
payload: { email: `nobody-${Date.now()}@supporthub.test`, password: 'wrong' },
|
|
});
|
|
expect(res.statusCode).toBe(401);
|
|
|
|
const accessLine = accessLogCalls(warnSpy)[0];
|
|
expect(accessLine).toBeDefined();
|
|
|
|
const authFailureLine = callsData(warnSpy).find((data) => data?.code === 'UNAUTHORIZED');
|
|
expect(authFailureLine).toBeDefined();
|
|
|
|
expect(authFailureLine?.requestId).toBe(accessLine?.requestId);
|
|
expect(accessLine?.requestId).toBe(res.headers['x-request-id']);
|
|
|
|
warnSpy.mockRestore();
|
|
});
|
|
|
|
it('still emits an access-log line for a 404', async () => {
|
|
const warnSpy = vi.spyOn(logger, 'warn');
|
|
|
|
const res = await app.inject({ method: 'GET', url: '/this-route-does-not-exist' });
|
|
expect(res.statusCode).toBe(404);
|
|
|
|
const lines = accessLogCalls(warnSpy);
|
|
expect(lines).toHaveLength(1);
|
|
expect(lines[0]).toMatchObject({ statusCode: 404 });
|
|
|
|
warnSpy.mockRestore();
|
|
});
|
|
});
|