mirror of
https://github.com/mauriceboe/TREK.git
synced 2026-10-19 13:36:48 +00:00
Maurice
8632f93c37
A 5xx stack and its access-log line were two unrelated lines, the exception filter printed the stack with console.error and no request context, and the MCP, WebSocket, plugin RPC and cron entry points logged nothing per call. A self-hosted bug report could not be traced from a failure back to the call that caused it. Every HTTP request now runs under an id held in AsyncLocalStorage: a well-formed incoming X-Request-Id is kept, anything else is replaced by a UUID, and the response carries it in X-Request-Id. The logger tags every line written inside a unit of work with `[http <id>]`. The exception filter leaves a server-side failure on res.locals and the access log writes the request line and the stack as one entry under that id; without an access log watching the response it still prints the error itself. MCP tool, resource and prompt calls (through a new `around` seam on the registry), WebSocket messages, plugin RPC dispatches and cron ticks each run through traceEntry(), which gives the call its own id (remembering the outer one as its parent) and logs one line for it: debug on success, like the HTTP access log, and warn or error with the reason on failure. The call's result and timing are unchanged, a failed cron tick is logged once rather than twice, and a WebSocket handler rejection no longer reaches rxjs's asynchronous rethrow.
63 lines
2.3 KiB
TypeScript
63 lines
2.3 KiB
TypeScript
/**
|
|
* The correlation store (nest/common/request-correlation.ts): which incoming
|
|
* ids are adopted, how a unit of work nests inside another, and how the tag
|
|
* reads in a log line.
|
|
*/
|
|
import { describe, it, expect } from 'vitest';
|
|
import {
|
|
acceptRequestId,
|
|
childCorrelation,
|
|
correlationTag,
|
|
currentCorrelation,
|
|
newCorrelationId,
|
|
runWithCorrelation,
|
|
} from '../../../../src/nest/common/request-correlation';
|
|
|
|
describe('acceptRequestId', () => {
|
|
it('CORR-001: adopts the ids proxies and tracers send', () => {
|
|
for (const id of ['abc123', '7f9c2ba4-e88f-11ec-8ea0-0242ac120002', 'Root=1-5759e988-bd862e3fe1be46a994272793', 'a.b_c:d']) {
|
|
expect(acceptRequestId(id)).toBe(id);
|
|
}
|
|
});
|
|
|
|
it('CORR-002: refuses anything that could forge or bloat a log line', () => {
|
|
expect(acceptRequestId('')).toBeNull();
|
|
expect(acceptRequestId('x'.repeat(129))).toBeNull();
|
|
expect(acceptRequestId('has space')).toBeNull();
|
|
expect(acceptRequestId('line\nbreak')).toBeNull();
|
|
expect(acceptRequestId('<script>')).toBeNull();
|
|
expect(acceptRequestId(['a', 'b'])).toBeNull();
|
|
expect(acceptRequestId(undefined)).toBeNull();
|
|
});
|
|
});
|
|
|
|
describe('the correlation store', () => {
|
|
it('CORR-003: nothing is current outside a unit of work', () => {
|
|
expect(currentCorrelation()).toBeUndefined();
|
|
expect(correlationTag(undefined)).toBe('');
|
|
});
|
|
|
|
it('CORR-004: a correlation stays current across awaits inside its run', async () => {
|
|
const id = newCorrelationId();
|
|
const seen = await runWithCorrelation({ id, kind: 'http' }, async () => {
|
|
await new Promise((resolve) => setTimeout(resolve, 1));
|
|
return currentCorrelation();
|
|
});
|
|
expect(seen).toEqual({ id, kind: 'http' });
|
|
expect(currentCorrelation()).toBeUndefined();
|
|
});
|
|
|
|
it('CORR-005: a child gets its own id and remembers the one it started inside', () => {
|
|
const top = childCorrelation('cron');
|
|
expect(top.parentId).toBeUndefined();
|
|
const nested = runWithCorrelation({ id: 'outer', kind: 'http' }, () => childCorrelation('mcp'));
|
|
expect(nested.kind).toBe('mcp');
|
|
expect(nested.parentId).toBe('outer');
|
|
expect(nested.id).not.toBe('outer');
|
|
});
|
|
|
|
it('CORR-006: the tag names the kind and the id', () => {
|
|
expect(correlationTag({ id: 'abc', kind: 'ws' })).toBe('[ws abc] ');
|
|
});
|
|
});
|