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>
56 lines
2.1 KiB
TypeScript
56 lines
2.1 KiB
TypeScript
import { describe, it, expect } from 'vitest';
|
|
import { Writable } from 'stream';
|
|
import pino from 'pino';
|
|
import { loggerOptions } from '@/infrastructure/observability/logger';
|
|
import { requestContextStore } from '@/infrastructure/observability/request-context.store';
|
|
|
|
function buildCapturingLogger() {
|
|
const lines: Record<string, unknown>[] = [];
|
|
const sink = new Writable({
|
|
write(chunk, _enc, callback) {
|
|
lines.push(JSON.parse(chunk.toString()));
|
|
callback();
|
|
},
|
|
});
|
|
// Same options (same mixin) the real singleton uses — only the destination differs, per
|
|
// logger.ts's own comment on why loggerOptions is exported. `transport` is never set outside
|
|
// NODE_ENV=development (see logger.ts), so it's always undefined under `npm test`.
|
|
const testLogger = pino(loggerOptions, sink);
|
|
return { testLogger, lines };
|
|
}
|
|
|
|
describe('logger mixin (014-full-observability FR-002)', () => {
|
|
it('attaches requestId/correlationId to a log line made inside the request context store', () => {
|
|
const { testLogger, lines } = buildCapturingLogger();
|
|
|
|
requestContextStore.run({ requestId: 'req-1', correlationId: 'corr-1' }, () => {
|
|
testLogger.info('inside request');
|
|
});
|
|
|
|
expect(lines).toHaveLength(1);
|
|
expect(lines[0]).toMatchObject({ requestId: 'req-1', correlationId: 'corr-1' });
|
|
});
|
|
|
|
it('attaches neither field to a log line made outside any request context', () => {
|
|
const { testLogger, lines } = buildCapturingLogger();
|
|
|
|
testLogger.info('outside any request');
|
|
|
|
expect(lines).toHaveLength(1);
|
|
expect(lines[0]?.requestId).toBeUndefined();
|
|
expect(lines[0]?.correlationId).toBeUndefined();
|
|
});
|
|
|
|
it('does not leak one request context into a log line logged after that context ends', () => {
|
|
const { testLogger, lines } = buildCapturingLogger();
|
|
|
|
requestContextStore.run({ requestId: 'req-2', correlationId: 'corr-2' }, () => {
|
|
testLogger.info('inside');
|
|
});
|
|
testLogger.info('after');
|
|
|
|
expect(lines[0]).toMatchObject({ requestId: 'req-2' });
|
|
expect(lines[1]?.requestId).toBeUndefined();
|
|
});
|
|
});
|