From 85c4653774adbafd9428ff5340fc93074393ea8f Mon Sep 17 00:00:00 2001 From: Volodymyr Vreshch Date: Thu, 13 Aug 2026 14:41:29 +0200 Subject: [PATCH] feat: shared Express request-log middleware --- README.md | 15 ++++++ src/index.ts | 14 +++++- src/request-log.ts | 95 +++++++++++++++++++++++++++++++++++ test/request-log.test.ts | 106 +++++++++++++++++++++++++++++++++++++++ 4 files changed, 229 insertions(+), 1 deletion(-) create mode 100644 src/request-log.ts create mode 100644 test/request-log.test.ts diff --git a/README.md b/README.md index 36b7a69..34c423e 100644 --- a/README.md +++ b/README.md @@ -88,6 +88,20 @@ mark it failed - there is no separate capture call to learn. Pass context alongs error as `log.error({ err, userId })`; the message defaults to the error's. Stdio MCP servers must pass `stream: 'stderr'` - on stdio, stdout is the JSON-RPC channel. +### Request logs + +```ts +import { createRequestLog, logger } from '@agentage/observability'; + +app.use(createRequestLog(logger())); // before the routers, so 404s are counted too +``` + +One line per finished request: `kind: 'http'`, `method`, `path`, `route` (templated), +`status`, `duration_ms`, `user_id`, plus `trace_id`/`span_id` from the logger mixin. The +route falls back to a low-cardinality template derived from the URL when Express has no +matched route (404s) or matched by RegExp (a whole app mounted behind one pattern). Pass +`classify` to add `user_type`, and `userId` when the user does not live at `req.user.id`. + ### Error events One error line, one shape, whatever the runtime: `err`, `route` (templated), `method`, @@ -253,6 +267,7 @@ without parsing the body. | `@agentage/observability` | `logger(options?)` | pino preset: trace-linked lines, `log.error` capture | | | `withSpan(name, fn, attrs?)` | Add depth deliberately; no-op without an SDK | | | `setMcpTool`, `markSpanError`, `setSpanAttributes` | MCP tool-call span semantics | +| | `createRequestLog(log, options?)` | Express middleware: one wide event per request | | | `errorMiddleware(log, options?)` | Express error handler emitting the `ErrorEvent` | | | `onRequestError(log)` | Next `instrumentation.ts` error hook | | | `wrapToolHandler(log, tool, handler)` | MCP tool errors, including `isError` results | diff --git a/src/index.ts b/src/index.ts index d5c5c03..888674d 100644 --- a/src/index.ts +++ b/src/index.ts @@ -43,7 +43,19 @@ export { type CollectorRequest, type CollectorResponse, } from './collector.js'; -export { routeFromUrl, normalizeFetchSpanName, FetchSpanNameProcessor } from './span-names.js'; +export { + createRequestLog, + type RequestLogMiddleware, + type RequestLogOptions, + type RequestLogRequest, + type RequestLogResponse, +} from './request-log.js'; +export { + routeFromUrl, + readableRoute, + normalizeFetchSpanName, + FetchSpanNameProcessor, +} from './span-names.js'; export { NextNoiseSampler, samplerFromEnv } from './noise-sampler.js'; export { withSpan } from './with-span.js'; export { diff --git a/src/request-log.ts b/src/request-log.ts new file mode 100644 index 0000000..0bb4f48 --- /dev/null +++ b/src/request-log.ts @@ -0,0 +1,95 @@ +import type { Logger } from 'pino'; +import { readableRoute, routeFromUrl } from './span-names.js'; + +/** Structurally typed so the kit stays dependency-light - no express import. */ +export interface RequestLogRequest { + method: string; + path: string; + baseUrl?: string; + route?: { path?: unknown } | null; +} + +export interface RequestLogResponse { + statusCode: number; + on(event: 'finish', listener: () => void): unknown; +} + +export interface RequestLogOptions { + /** + * Traffic classifier behind `user_type`. An injection point rather than a + * built-in: a shared classifier would drag a product dependency into the kit. + * The field is omitted when no classifier is given. + */ + classify?: (req: RequestLogRequest) => string | undefined; + /** Where the user id lives on your request; defaults to `req.user.id`. */ + userId?: (req: RequestLogRequest) => string | undefined; + /** Log message; defaults to `'request'`. */ + message?: string; +} + +export type RequestLogMiddleware = ( + req: RequestLogRequest, + res: RequestLogResponse, + next: () => void +) => void; + +const defaultUserId = (req: RequestLogRequest): string | undefined => { + const id = (req as { user?: { id?: unknown } }).user?.id; + return typeof id === 'string' ? id : undefined; +}; + +// A router index route ('/') mounted at /api/x yields baseUrl+'/' = '/api/x/'; +// drop the trailing slash so it groups with the inventory's '/api/x'. +const dropTrailingSlash = (route: string): string => + route.length > 1 && route.endsWith('/') ? route.slice(0, -1) : route; + +/** + * Matched pattern (`/api/memories/:id`), so records group instead of fragmenting + * on ids. Two fallbacks to `routeFromUrl(req.path)`: no `req.route` (404s, + * rate-limited requests), and a route Express matched by RegExp - there + * `route.path` is the regex SOURCE, not a template (agentage-auth mounts Better + * Auth behind one regex). `readableRoute` rewrites regex sources and only those, + * so a rewrite is the detector. + */ +const routeOf = (req: RequestLogRequest): string => { + const template = req.route?.path; + if (template === undefined || template === null) return dropTrailingSlash(routeFromUrl(req.path)); + const joined = `${req.baseUrl ?? ''}${String(template)}`; + const readable = readableRoute(joined); + return dropTrailingSlash(readable === joined ? joined : routeFromUrl(req.path)); +}; + +/** + * One structured line per finished request (method/path/route/status/duration) - + * the estate log agent tails container stdout, so no in-process shipping. + * Register BEFORE the routers so 404s and rate-limited requests are counted too. + * `trace_id`/`span_id` are injected by the `createLogger` mixin. + */ +export function createRequestLog( + log: Logger, + options: RequestLogOptions = {} +): RequestLogMiddleware { + const userId = options.userId ?? defaultUserId; + const message = options.message ?? 'request'; + return (req, res, next) => { + const start = process.hrtime.bigint(); + res.on('finish', () => { + const durationMs = Number(process.hrtime.bigint() - start) / 1e6; + const userType = options.classify?.(req); + log.info( + { + kind: 'http', + method: req.method, + path: req.path, + route: routeOf(req), + status: res.statusCode, + duration_ms: Math.round(durationMs), + user_id: userId(req), + ...(userType === undefined ? {} : { user_type: userType }), + }, + message + ); + }); + next(); + }; +} diff --git a/test/request-log.test.ts b/test/request-log.test.ts new file mode 100644 index 0000000..fbaccc2 --- /dev/null +++ b/test/request-log.test.ts @@ -0,0 +1,106 @@ +import { describe, it, expect, vi } from 'vitest'; +import { createRequestLog, type RequestLogRequest } from '../src/request-log.js'; +import type { Logger } from 'pino'; + +type LogRecord = Record; + +const run = ( + req: Partial & LogRecord, + options?: Parameters[1], + statusCode = 200 +): LogRecord => { + const info = vi.fn(); + let finish: () => void = () => {}; + const res = { + statusCode, + on: (_event: 'finish', listener: () => void) => { + finish = listener; + }, + }; + const next = vi.fn(); + createRequestLog({ info } as unknown as Logger, options)( + { method: 'GET', path: '/', ...req } as RequestLogRequest, + res, + next + ); + expect(next).toHaveBeenCalledOnce(); + finish(); + expect(info).toHaveBeenCalledOnce(); + return info.mock.calls[0][0] as LogRecord; +}; + +describe('createRequestLog', () => { + it('logs the wide event with the matched route template', () => { + const record = run( + { + method: 'GET', + path: '/api/memories/abc123def456', + baseUrl: '/api/memories', + route: { path: '/:id' }, + user: { id: 'user_1' }, + }, + undefined, + 201 + ); + expect(record).toMatchObject({ + kind: 'http', + method: 'GET', + path: '/api/memories/abc123def456', + route: '/api/memories/:id', + status: 201, + user_id: 'user_1', + }); + expect(typeof record.duration_ms).toBe('number'); + expect(record).not.toHaveProperty('user_type'); + }); + + it('falls back to the url-derived route on a 404 (no req.route)', () => { + const record = run({ method: 'POST', path: '/api/memories/42/notes' }, undefined, 404); + expect(record.route).toBe('/api/memories/:id/notes'); + expect(record.status).toBe(404); + expect(record.user_id).toBeUndefined(); + }); + + it('falls back to the url-derived route for a RegExp-mounted route', () => { + const record = run({ + path: '/api/auth/get-session', + baseUrl: '', + route: { path: '/^\\/api\\/auth\\//' }, + }); + expect(record.route).toBe('/api/auth/get-session'); + }); + + it('trims the trailing slash of a router index route', () => { + const record = run({ path: '/api/memories/', baseUrl: '/api/memories', route: { path: '/' } }); + expect(record.route).toBe('/api/memories'); + }); + + it('trims the trailing slash on the fallback path too', () => { + const record = run({ path: '/api/memories/' }); + expect(record.route).toBe('/api/memories'); + }); + + it('adds user_type from the injected classifier and honors a custom message', () => { + const info = vi.fn(); + let finish: () => void = () => {}; + const classify = vi.fn(() => 'bot'); + createRequestLog({ info } as unknown as Logger, { + classify, + userId: () => 'from-opt', + message: 'http', + })( + { method: 'GET', path: '/health' } as RequestLogRequest, + { + statusCode: 200, + on: (_e: 'finish', l: () => void) => { + finish = l; + }, + }, + () => {} + ); + finish(); + expect(classify).toHaveBeenCalledOnce(); + expect(info.mock.calls[0][0]).toMatchObject({ user_type: 'bot', user_id: 'from-opt' }); + expect(info.mock.calls[0][1]).toBe('http'); + }); +});