Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
15 changes: 15 additions & 0 deletions README.md
Original file line number Diff line number Diff line change
Expand Up @@ -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`,
Expand Down Expand Up @@ -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 |
Expand Down
14 changes: 13 additions & 1 deletion src/index.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand Down
95 changes: 95 additions & 0 deletions src/request-log.ts
Original file line number Diff line number Diff line change
@@ -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();
};
}
106 changes: 106 additions & 0 deletions test/request-log.test.ts
Original file line number Diff line number Diff line change
@@ -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<string, unknown>;

const run = (
req: Partial<RequestLogRequest> & LogRecord,
options?: Parameters<typeof createRequestLog>[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');
});
});