feat(server): correlate log lines with a request id per entry point

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.

server/CLAUDE.md

@@ -95,6 +95,7 @@ SQLite is the engine today and Postgres is the planned second one. Code under `s
 - **`src/nest/common/`**: the global exception filter (error envelope), the Zod validation pipe, the idempotency interceptor (`X-Idempotency-Key` replay), and `validate-route-guards.ts` (boot-time ratchet refusing any public route not on its allow-list).
 - **Auth is default-deny**: the global auth guard and the MFA policy guard run as `APP_GUARD`s, followed by the managed-install guard (`managed.guard.ts`), which refuses the routes a centrally administered install withholds from its own admin — it runs last so strangers still get a 401, never a route-revealing 403. Routes opt out with `@Public()`/`@OptionalAuth()`. The global guard stands down for routes declaring their own guard chain, so `@UseGuards(JwtAuthGuard, TripAccessGuard)` + `@RequirePermission` stacks work. Session is a cookie (`trek_session`); `@CurrentUser()` reads the user. **Never gate a multipart upload with a guard** — guards run before the parser and the client sees ECONNRESET instead of your 403; check in the handler.
 - **Logging**: `src/nest/audit/audit-log.logger.ts` (`logInfo`/`logWarn`/`logError`/`logDebug`) prints each line to the console and queues it for `data/logs/trek.log`, which `log-file.ts` appends in batches off the event loop and rotates at 10 MB over five files; `index.ts` flushes what is queued on exit. Never write the log file synchronously from a request path.
+- **Request correlation** (`src/nest/common/request-correlation.ts`): every HTTP request runs under an id (a well-formed incoming `X-Request-Id`, else a fresh UUID) that the response carries in `X-Request-Id`, and every log line written inside it is tagged `[http <id>]`. The exception filter leaves a 5xx on `res.locals` so the access log writes the request line and the stack as one entry. The other entry points (MCP tool/resource/prompt calls via the registry's `around` seam, WebSocket messages in `TrekWsAdapter`, plugin RPC dispatches in the supervisor, cron ticks in `CronRegistrarService`) each run under their own id through `traceEntry()` (`nest/audit/entry-trace.logger.ts`), which logs one line per call: debug on success, warn or error with the reason on failure. A new entry point goes through `traceEntry()` too.
 - **`src/middleware/globalMiddleware.ts`** is the only Express middleware left (helmet/CSP, CORS, HSTS, forced-HTTPS, logging, cookies).
 
 ## Tests

server/src/mcp/tools.ts

@@ -18,6 +18,6 @@ import { getPluginMcpToolSource } from '../plugin-mcp-tools';
  * exist and an app built without the plugins runtime resolves it to undefined.
  * Tests pass it explicitly instead of reaching for the global.
  */
-export async function registerTools(registry: McpRegistry | null, server: McpServer, userId: number, scopes: string[] | null, isStaticToken = false, getDeprecationNotice: () => string | null = () => null, onInvoke?: McpAttachOptions['onInvoke'], dynamicTools: McpAttachOptions['dynamicTools'] = getPluginMcpToolSource() ?? undefined): Promise<void> {
-  if (registry) await registry.attach(server, { userId, scopes, isStaticToken, getDeprecationNotice }, { onInvoke, dynamicTools });
+export async function registerTools(registry: McpRegistry | null, server: McpServer, userId: number, scopes: string[] | null, isStaticToken = false, getDeprecationNotice: () => string | null = () => null, onInvoke?: McpAttachOptions['onInvoke'], dynamicTools: McpAttachOptions['dynamicTools'] = getPluginMcpToolSource() ?? undefined, around?: McpAttachOptions['around']): Promise<void> {
+  if (registry) await registry.attach(server, { userId, scopes, isStaticToken, getDeprecationNotice }, { onInvoke, dynamicTools, around });
 }

server/src/middleware/globalMiddleware.ts

@@ -1,4 +1,5 @@
 import express, { Request, Response, NextFunction } from 'express';
+import { AsyncResource } from 'node:async_hooks';
 import compression from 'compression';
 import cors from 'cors';
 import helmet from 'helmet';
@@ -8,6 +9,14 @@ import { readEnv } from '../app-config';
 import { httpConfig } from '../nest/app-config/tokens';
 import { logDebug, logWarn, logError } from '../nest/audit/audit-log.logger';
 import { isSameHostOrigin } from '../nest/common/same-origin';
+import {
+  ACCESS_LOG_ATTACHED,
+  REQUEST_ID_HEADER,
+  UNHANDLED_ERROR,
+  acceptRequestId,
+  newCorrelationId,
+  runWithCorrelation,
+} from '../nest/common/request-correlation';
 
 /**
  * Field names redacted from request-log query/body dumps (case-insensitive —
@@ -146,6 +155,16 @@ export function applyGlobalMiddleware(
   const liveHttp = readEnv().http;
   const { nodeEnv, isProduction } = readEnv().app;
 
+  // Request correlation comes first, so the whole pipeline and every line the
+  // request logs run under its id. An X-Request-Id set by the proxy in front is
+  // kept when it looks like an id, so its logs and ours line up; anything else
+  // is replaced. The response always says which id it got.
+  app.use((req: Request, res: Response, next: NextFunction) => {
+    const id = acceptRequestId(req.headers['x-request-id']) ?? newCorrelationId();
+    res.setHeader(REQUEST_ID_HEADER, id);
+    runWithCorrelation({ id, kind: 'http' }, next);
+  });
+
   // Trust first proxy (nginx/Docker) for correct req.ip
   if (isProduction || http.trustProxyRaw) {
     app.set('trust proxy', http.trustProxy);
@@ -361,14 +380,33 @@ export function applyGlobalMiddleware(
 
   app.use(cookieParser());
 
-  // Request logging with sensitive field redaction (SENSITIVE_KEYS/redact above)
+  // Request logging with sensitive field redaction (SENSITIVE_KEYS/redact above).
+  // The line is written in the request's own correlation context (the 'finish'
+  // listener would otherwise run in whatever context the socket emits from),
+  // and a 5xx carries the stack the exception filter left on res.locals, so
+  // the request line, its id and the failure are one entry.
   app.use((req: Request, res: Response, next: NextFunction) => {
     if (req.path === '/api/health' || req.path === '/api/health/ready') return next();
     const startedAt = Date.now();
-    res.on('finish', () => {
+    res.locals[ACCESS_LOG_ATTACHED] = true;
+    let reported = false;
+    const failureSuffix = (): string => {
+      const failure: unknown = res.locals[UNHANDLED_ERROR];
+      if (failure === undefined) return '';
+      return `\n${failure instanceof Error ? (failure.stack ?? failure.message) : String(failure)}`;
+    };
+    // A response the filter had to cut off after its headers went out never
+    // finishes; it is reported when the socket closes, with its failure.
+    res.on('close', AsyncResource.bind(() => {
+      if (reported || res.locals[UNHANDLED_ERROR] === undefined) return;
+      reported = true;
+      logError(`${req.method} ${req.path} aborted after headers ${Date.now() - startedAt}ms ip=${req.ip}${failureSuffix()}`);
+    }));
+    res.on('finish', AsyncResource.bind(() => {
+      reported = true;
       const ms = Date.now() - startedAt;
       if (res.statusCode >= 500) {
-        logError(`${req.method} ${req.path} ${res.statusCode} ${ms}ms ip=${req.ip}`);
+        logError(`${req.method} ${req.path} ${res.statusCode} ${ms}ms ip=${req.ip}${failureSuffix()}`);
       } else if (res.statusCode === 401 || res.statusCode === 403) {
         logDebug(`${req.method} ${req.path} ${res.statusCode} ${ms}ms ip=${req.ip}`);
       } else if (res.statusCode >= 400) {
@@ -377,7 +415,7 @@ export function applyGlobalMiddleware(
       const q = Object.keys(req.query).length ? ` query=${JSON.stringify(redact(req.query))}` : '';
       const b = req.body && Object.keys(req.body).length ? ` body=${JSON.stringify(redact(req.body))}` : '';
       logDebug(`${req.method} ${req.path} ${res.statusCode} ${ms}ms ip=${req.ip}${q}${b}`);
-    });
+    }));
     next();
   });
 }

server/src/nest-mcp/registry.ts

@@ -7,6 +7,7 @@ import type {
   McpDynamicTool,
   McpDynamicToolSource,
   McpEntry,
+  McpEntryKind,
   McpRegistryListing,
   PromptOptions,
   ResourceOptions,
@@ -40,6 +41,11 @@ export interface McpRegistryOptions {
 
 type AnyHandler = (this: unknown, ...handlerArgs: unknown[]) => unknown;
 
+/** Run one handler call through the host's `around` wrapper when it set one. */
+function invoke(opts: McpAttachOptions | undefined, info: { kind: McpEntryKind; name: string }, call: () => unknown): unknown {
+  return opts?.around ? opts.around(info, call) : call();
+}
+
 /**
  * Structural view of the SDK registration surface. The SDK's real signatures
  * are generic over the Zod shapes; the registry hands schemas over as objects
@@ -327,11 +333,11 @@ export class McpRegistry {
       options.inputSchema !== undefined
         ? (args: unknown, _extra: unknown) => {
             opts?.onInvoke?.({ kind: 'tool', name: options.name });
-            return handler.call(instance, args, ctx);
+            return invoke(opts, { kind: 'tool', name: options.name }, () => handler.call(instance, args, ctx));
           }
         : (_extra: unknown) => {
             opts?.onInvoke?.({ kind: 'tool', name: options.name });
-            return handler.call(instance, {}, ctx);
+            return invoke(opts, { kind: 'tool', name: options.name }, () => handler.call(instance, {}, ctx));
           };
     registrar.registerTool(options.name, config, cb);
   }
@@ -352,7 +358,7 @@ export class McpRegistry {
     };
     registrar.registerResource(options.name, options.uri, metadata, (uri: unknown, _extra: unknown) => {
       opts?.onInvoke?.({ kind: 'resource', name: options.name });
-      return handler.call(instance, uri, ctx);
+      return invoke(opts, { kind: 'resource', name: options.name }, () => handler.call(instance, uri, ctx));
     });
   }
 
@@ -376,7 +382,9 @@ export class McpRegistry {
       metadata,
       (uri: unknown, variables: unknown, _extra: unknown) => {
         opts?.onInvoke?.({ kind: 'resourceTemplate', name: options.name });
-        return handler.call(instance, uri, variables, ctx);
+        return invoke(opts, { kind: 'resourceTemplate', name: options.name }, () =>
+          handler.call(instance, uri, variables, ctx),
+        );
       },
     );
   }
@@ -404,11 +412,11 @@ export class McpRegistry {
       argsSchema !== undefined
         ? (args: unknown, _extra: unknown) => {
             opts?.onInvoke?.({ kind: 'prompt', name: options.name });
-            return handler.call(instance, args, ctx);
+            return invoke(opts, { kind: 'prompt', name: options.name }, () => handler.call(instance, args, ctx));
           }
         : (_extra: unknown) => {
             opts?.onInvoke?.({ kind: 'prompt', name: options.name });
-            return handler.call(instance, {}, ctx);
+            return invoke(opts, { kind: 'prompt', name: options.name }, () => handler.call(instance, {}, ctx));
           };
     registrar.registerPrompt(options.name, config, cb);
   }

server/src/nest-mcp/types.ts

@@ -180,6 +180,15 @@ export interface McpAttachOptions {
    * failure handling.
    */
   onInvoke?: (info: { kind: McpEntryKind; name: string }) => void;
+  /**
+   * Wraps every attached handler call: `call` runs the handler, and what the
+   * wrapper returns is what the SDK receives. This is the host's tracing seam
+   * (a correlation id and one log line per call); nest-mcp attaches no
+   * semantics to it. Unlike `onInvoke` it sees the outcome. Contract: the
+   * wrapper calls `call` exactly once and passes its result or its error on
+   * unchanged.
+   */
+  around?: (info: { kind: McpEntryKind; name: string }, call: () => unknown) => unknown;
   /**
    * Extra tools contributed for THIS session only, on top of the decorated
    * ones. Consulted once per `attach()`, after every registered entry.

server/src/nest/audit/audit-log.logger.ts

@@ -1,6 +1,7 @@
 import { readEnv } from '../../app-config';
 import { resolveDataPaths } from '../../app-config/data-paths';
 import { BufferedLogFile } from './log-file';
+import { correlationTag, currentCorrelation } from '../common/request-correlation';
 
 /**
  * The server's rotating file logger, a plain module and NOT an injectable
@@ -8,8 +9,10 @@ import { BufferedLogFile } from './log-file';
  * to the console at once and to `data/logs/trek.log` through a buffered,
  * asynchronous sink (log-file.ts), so logging never waits for the disk.
  * Nothing touches the disk at import: the directory appears with the first
- * flush. The LOG_LEVEL freeze below is the one deliberate import-time behavior
- * and is load-bearing for tests/setup.ts.
+ * flush. A line written inside a unit of work (an HTTP request, an MCP call,
+ * a WebSocket message, a plugin RPC, a cron tick) carries its correlation tag,
+ * `[http 1b9d...]`, after the timestamp. The LOG_LEVEL freeze below is the
+ * one deliberate import-time behavior and is load-bearing for tests/setup.ts.
  */
 
 // Frozen at import on purpose (legacy timing; tests/setup.ts sets it pre-import).
@@ -54,36 +57,38 @@ export function flushLogFileSync(): void {
 
 // ── Public log helpers ────────────────────────────────────────────────────
 
-function formatTs(): string {
+/** Timestamp, then the correlation tag of the current unit of work when there is one. */
+function prefix(): string {
   const tz = readEnv().app.tz || 'UTC';
-  return new Date().toLocaleString('sv-SE', { timeZone: tz }).replace(' ', 'T');
+  const ts = new Date().toLocaleString('sv-SE', { timeZone: tz }).replace(' ', 'T');
+  return `${ts} ${correlationTag(currentCorrelation())}`;
 }
 
 export function logInfo(msg: string): void {
   if (LOG_THRESHOLD < LEVEL_RANKS.info) return;
-  const ts = formatTs();
-  console.log(`${C.blue}[INFO]${C.reset} ${ts} ${msg}`);
-  logFile.write(`[INFO] ${ts} ${msg}`);
+  const ts = prefix();
+  console.log(`${C.blue}[INFO]${C.reset} ${ts}${msg}`);
+  logFile.write(`[INFO] ${ts}${msg}`);
 }
 
 export function logDebug(msg: string): void {
   if (LOG_THRESHOLD < LEVEL_RANKS.debug) return;
-  const ts = formatTs();
-  console.log(`${C.cyan}[DEBUG]${C.reset} ${ts} ${msg}`);
-  logFile.write(`[DEBUG] ${ts} ${msg}`);
+  const ts = prefix();
+  console.log(`${C.cyan}[DEBUG]${C.reset} ${ts}${msg}`);
+  logFile.write(`[DEBUG] ${ts}${msg}`);
 }
 
 export function logError(msg: string): void {
-  const ts = formatTs();
-  console.error(`${C.red}[ERROR]${C.reset} ${ts} ${msg}`);
-  logFile.write(`[ERROR] ${ts} ${msg}`);
+  const ts = prefix();
+  console.error(`${C.red}[ERROR]${C.reset} ${ts}${msg}`);
+  logFile.write(`[ERROR] ${ts}${msg}`);
 }
 
 export function logWarn(msg: string): void {
   if (LOG_THRESHOLD < LEVEL_RANKS.warn) return;
-  const ts = formatTs();
-  console.warn(`${C.yellow}[WARN]${C.reset} ${ts} ${msg}`);
-  logFile.write(`[WARN] ${ts} ${msg}`);
+  const ts = prefix();
+  console.warn(`${C.yellow}[WARN]${C.reset} ${ts}${msg}`);
+  logFile.write(`[WARN] ${ts}${msg}`);
 }
 
 export { LOG_LEVEL };

server/src/nest/audit/entry-trace.logger.ts

@@ -0,0 +1,94 @@
+import { logDebug, logError, logWarn } from './audit-log.logger';
+import { childCorrelation, runWithCorrelation, type Correlation, type EntryKind } from '../common/request-correlation';
+
+/** Errors a trace has already written to the log, so an outer handler can skip a second line. */
+const reported = new WeakSet<object>();
+
+export interface TraceOptions<T = unknown> {
+  /** How a failure is logged: `warn` (default) for calls a client made, `error` for the server's own work. */
+  failureLevel?: 'warn' | 'error';
+  /** The failure line, when the entry point already has a wording people search for. */
+  failureMessage?: (error: unknown) => string;
+  /**
+   * For entry points that answer failures with a value instead of a throw (a
+   * plugin RPC returns `{ ok: false, error }`): the reason when `result` is a
+   * failure, null when it is not. A failure found this way is logged at warn.
+   */
+  refusal?: (result: Awaited<T>) => string | null;
+}
+
+function messageOf(error: unknown): string {
+  return error instanceof Error ? error.message : String(error);
+}
+
+function parentNote(correlation: Correlation): string {
+  return correlation.parentId ? ` parent=${correlation.parentId}` : '';
+}
+
+function isThenable(value: unknown): value is PromiseLike<unknown> {
+  return (
+    value !== null &&
+    (typeof value === 'object' || typeof value === 'function') &&
+    typeof (value as { then?: unknown }).then === 'function'
+  );
+}
+
+/**
+ * Run one call of a non-HTTP entry point (an MCP tool, a WebSocket message, a
+ * plugin RPC, a cron tick) under its own correlation id, and log one line for
+ * it: at debug when it succeeds, mirroring the HTTP access log, and at warn
+ * (or error) with the reason when it fails. Every line the call writes in
+ * between carries the same id.
+ *
+ * The call's own result comes back untouched, a plain value as a plain value
+ * and a promise as that same promise, and is invoked synchronously, so
+ * wrapping an entry point changes nothing about its timing. For a promise the
+ * line is written when it settles.
+ */
+export function traceEntry<T>(
+  kind: Exclude<EntryKind, 'http'>,
+  label: string,
+  fn: () => T,
+  options: TraceOptions<T> = {},
+): T {
+  const correlation = childCorrelation(kind);
+  const startedAt = Date.now();
+  const elapsed = () => `${Date.now() - startedAt}ms${parentNote(correlation)}`;
+
+  const succeeded = (value: Awaited<T>): void => {
+    const refused = options.refusal?.(value) ?? null;
+    if (refused === null) logDebug(`${kind} ${label} ok ${elapsed()}`);
+    else logWarn(`${kind} ${label} refused ${elapsed()}: ${refused}`);
+  };
+  const failed = (error: unknown): void => {
+    const line = options.failureMessage?.(error) ?? `${kind} ${label} failed ${elapsed()}: ${messageOf(error)}`;
+    if (options.failureLevel === 'error') logError(line);
+    else logWarn(line);
+    if (error !== null && typeof error === 'object') reported.add(error);
+  };
+
+  return runWithCorrelation(correlation, () => {
+    let result: T;
+    try {
+      result = fn();
+    } catch (error) {
+      failed(error);
+      throw error;
+    }
+    if (isThenable(result)) {
+      // Observes the outcome without replacing the promise the caller gets.
+      result.then(
+        (value) => succeeded(value as Awaited<T>),
+        (error: unknown) => failed(error),
+      );
+    } else {
+      succeeded(result as Awaited<T>);
+    }
+    return result;
+  });
+}
+
+/** True when a trace already logged this error (see traceEntry). */
+export function wasTraced(error: unknown): boolean {
+  return error !== null && typeof error === 'object' && reported.has(error);
+}

server/src/nest/common/request-correlation.ts

@@ -0,0 +1,76 @@
+import { AsyncLocalStorage } from 'node:async_hooks';
+import { randomUUID } from 'node:crypto';
+
+/**
+ * Request correlation: one id per unit of work, carried through everything
+ * that unit does by AsyncLocalStorage, so the access log line, the stack of a
+ * 500 and every log line in between can be found together.
+ *
+ * Five entry points start work: an HTTP request (globalMiddleware.ts), an MCP
+ * tool call, a WebSocket message, a plugin RPC dispatch and a cron tick (each
+ * through `traceEntry()` in nest/audit/entry-trace.logger.ts). An MCP call or a
+ * WebSocket message gets its own id even though an HTTP request or a socket is
+ * already open around it, and remembers that outer id as its parent.
+ *
+ * Process-local by nature: the store is per async chain, never shared.
+ */
+
+export type EntryKind = 'http' | 'mcp' | 'ws' | 'rpc' | 'cron';
+
+export interface Correlation {
+  readonly id: string;
+  readonly kind: EntryKind;
+  /** The id of the unit of work this one started inside, if any. */
+  readonly parentId?: string;
+}
+
+/** The header an incoming request may carry its id in, and the one every response carries. */
+export const REQUEST_ID_HEADER = 'X-Request-Id';
+
+/**
+ * What an incoming X-Request-Id may look like to be adopted: the characters
+ * proxies and tracing systems use for their ids, and short. Anything else is
+ * replaced by a fresh id rather than echoed into the logs and the response.
+ */
+const INCOMING_ID = /^[A-Za-z0-9._:=-]{1,128}$/;
+
+/**
+ * Keys on `res.locals` shared by the exception filter and the access log: the
+ * access log marks a response it will report, and the filter leaves the
+ * exception there so the request line and the stack land in one entry.
+ */
+export const ACCESS_LOG_ATTACHED = 'trekAccessLog';
+export const UNHANDLED_ERROR = 'trekUnhandledError';
+
+const storage = new AsyncLocalStorage<Correlation>();
+
+export function newCorrelationId(): string {
+  return randomUUID();
+}
+
+/** The incoming header value when it is a single, well-formed id; null otherwise. */
+export function acceptRequestId(value: unknown): string | null {
+  if (typeof value !== 'string') return null;
+  return INCOMING_ID.test(value) ? value : null;
+}
+
+/** The unit of work the caller is part of, if any. */
+export function currentCorrelation(): Correlation | undefined {
+  return storage.getStore();
+}
+
+/** Run `fn` (and everything it awaits) as part of `correlation`. */
+export function runWithCorrelation<T>(correlation: Correlation, fn: () => T): T {
+  return storage.run(correlation, fn);
+}
+
+/** A fresh correlation for an entry point, nested under whatever is running now. */
+export function childCorrelation(kind: EntryKind): Correlation {
+  const parent = storage.getStore();
+  return parent ? { id: newCorrelationId(), kind, parentId: parent.id } : { id: newCorrelationId(), kind };
+}
+
+/** How a correlation appears in a log line: `[http 1b9d...]`. */
+export function correlationTag(correlation: Correlation | undefined): string {
+  return correlation ? `[${correlation.kind} ${correlation.id}] ` : '';
+}

server/src/nest/common/trek-exception.filter.ts

@@ -1,6 +1,20 @@
 import { ArgumentsHost, Catch, ExceptionFilter, HttpException } from '@nestjs/common';
 import type { Response } from 'express';
 import { MulterError } from 'multer';
+import { ACCESS_LOG_ATTACHED, UNHANDLED_ERROR } from './request-correlation';
+
+/**
+ * Leave a server-side failure for the access log, which writes it together
+ * with the request line under the request's correlation id. False when no
+ * access log watches this response (a probe path, a hand-built test app), so
+ * the caller logs it itself.
+ */
+function handOverToAccessLog(res: Response, exception: unknown): boolean {
+  const locals = (res as Partial<Response>).locals;
+  if (!locals?.[ACCESS_LOG_ATTACHED]) return false;
+  locals[UNHANDLED_ERROR] = exception;
+  return true;
+}
 
 /**
  * Normalises every Nest exception to TREK's legacy error envelope so migrated
@@ -33,7 +47,7 @@ export class TrekExceptionFilter implements ExceptionFilter {
     //    branch's logging (including case 2's `status >= 500` log) — then
     //    destroy the socket so the connection doesn't hang open.
     if (res.headersSent) {
-      console.error('Unhandled error after headers sent:', exception);
+      if (!handOverToAccessLog(res, exception)) console.error('Unhandled error after headers sent:', exception);
       res.destroy();
       return;
     }
@@ -50,6 +64,9 @@ export class TrekExceptionFilter implements ExceptionFilter {
     if (exception instanceof HttpException) {
       const status = exception.getStatus();
       const body = exception.getResponse();
+      // A deliberate 5xx used to leave no trace beyond its status line; its
+      // stack now rides along with that line.
+      if (status >= 500) handOverToAccessLog(res, exception);
 
       if (body && typeof body === 'object') {
         const obj = body as Record<string, unknown>;
@@ -78,7 +95,7 @@ export class TrekExceptionFilter implements ExceptionFilter {
     //    status = err.statusCode || err.status || 500; 4xx exposes err.message.
     const err = exception as { statusCode?: number; status?: number; message?: unknown } | null;
     const status = (err && (err.statusCode || err.status)) || 500;
-    if (status >= 500) console.error('Unhandled error:', exception);
+    if (status >= 500 && !handOverToAccessLog(res, exception)) console.error('Unhandled error:', exception);
     const message = status < 500 ? String(err?.message ?? 'Error') : 'Internal server error';
     res.status(status).json({ error: message });
   }

server/src/nest/mcp-transport/mcp-transport.service.ts

@@ -17,6 +17,7 @@ import { OauthService } from '../oauth/oauth.service';
 import { AddonsService } from '../addons/addons.service';
 import { AuditService } from '../audit/audit.service';
 import { getClientIp } from '../audit/client-ip';
+import { traceEntry } from '../audit/entry-trace.logger';
 
 /**
  * The MCP transport handler behind the container — the former non-Nest
@@ -311,7 +312,12 @@ export class McpTransportService {
       });
     };
 
-    await registerTools(this.registry, server, user.id, scopes, isStaticToken, getDeprecationNotice, onInvoke);
+    // Every tool, resource and prompt call is its own unit of work: a correlation
+    // id under the /mcp request's, and one log line with its outcome.
+    const around = (info: { kind: string; name: string }, call: () => unknown): unknown =>
+      traceEntry('mcp', `${info.kind} ${info.name} user=${user.id}`, call);
+
+    await registerTools(this.registry, server, user.id, scopes, isStaticToken, getDeprecationNotice, onInvoke, undefined, around);
 
     const transport = new StreamableHTTPServerTransport({
       sessionIdGenerator: () => randomUUID(),

server/src/nest/plugins/supervisor/plugin-supervisor.ts

@@ -10,6 +10,7 @@ import { scheduleJobs, stopJobs, type ScheduledJob } from '../host/plugin-jobs';
 import { SNAPSHOT_GRANT, type PluginEventMeta } from '../../../plugin-event-sink';
 import { RpcRateLimiter, DEFAULT_RPC_LIMIT, TokenBucket, DEFAULT_LOG_LIMIT } from '../host/rate-limit';
 import { withRequestContext } from '../../database/request-context';
+import { traceEntry } from '../../audit/entry-trace.logger';
 
 export interface PluginRouteInfo {
   i: number;
@@ -619,7 +620,14 @@ export class PluginSupervisor {
           sup.child?.send({ k: 'res', id: req.id, ok: false, error: { code: 'HOST_ERROR', message: 'no ORM available to build a request context' } } satisfies RpcError);
           throw new Error('PluginSupervisor: no ORM available to build a request context for this RPC dispatch');
         }
-        const res = await withRequestContext(orm, () => sup.rpcHost.dispatch(req, actingUserId));
+        // One unit of work per RPC, with its own correlation id and one log line;
+        // a refusal travels back as `{ ok: false }`, so that is what the line reports.
+        const res = await traceEntry(
+          'rpc',
+          `${sup.id} ${req.method}`,
+          () => withRequestContext(orm, () => sup.rpcHost.dispatch(req, actingUserId)),
+          { refusal: (answer) => ('error' in answer ? `${answer.error.code} ${answer.error.message}` : null) },
+        );
         sup.child?.send(res);
       } finally {
         sup.rpcLimiter.release();

server/src/nest/realtime/trek-ws.adapter.ts

@@ -6,8 +6,9 @@ import { WebSocketServer } from 'ws';
 import type { Observable } from 'rxjs';
 import type { EntityManager } from '@mikro-orm/core';
 import { readEnv } from '../../app-config';
-import { setServer, type TrekWebSocket } from './ws-state';
+import { setServer, userOf, type TrekWebSocket } from './ws-state';
 import { logError } from '../audit/audit-log.logger';
+import { traceEntry } from '../audit/entry-trace.logger';
 import { withRequestContext } from '../database/request-context';
 import { isSameHostOrigin } from '../common/same-origin';
 
@@ -287,13 +288,22 @@ export class TrekWsAdapter extends WsAdapter {
       if (!this.orm) {
         throw new Error('TrekWsAdapter: no MikroORM available to build a request context for this message handler');
       }
-      const result = withRequestContext(this.orm, () => handler.callback(message, socket));
+      const orm = this.orm;
+      // Each message is its own unit of work with its own correlation id, and
+      // one log line (debug when it succeeds, warn with the reason when it
+      // throws). The handler is still invoked synchronously, inside this frame.
+      const user = userOf(socket);
+      const label = `${message.type}${user ? ` user=${user.id}` : ''}`;
+      const result = traceEntry('ws', label, () => withRequestContext(orm, () => handler.callback(message, socket)));
       transform(result).subscribe({
         next: (response) => {
           if (response !== undefined && socket.readyState === 1) {
             socket.send(JSON.stringify(response));
           }
         },
+        // Already logged by the trace; without a handler rxjs rethrows it
+        // asynchronously, which would take the whole process down.
+        error: () => {},
       });
     });
   }

server/src/nest/scheduling/cron-registrar.service.ts

@@ -6,6 +6,7 @@ import { readEnv } from '../../app-config';
 import { RuntimeEnvService } from '../app-config/runtime-env.service';
 import { withRequestContext } from '../database/request-context';
 import { logError } from '../audit/audit-log.logger';
+import { traceEntry, wasTraced } from '../audit/entry-trace.logger';
 
 /**
  * The one way TREK code schedules a cron. Job providers register here from
@@ -84,23 +85,33 @@ export class CronRegistrarService implements OnApplicationShutdown {
     // OUR OWN clear error instead, so a hand-built double that registers a
     // job without an ORM but whose tick reaches a repository fails loudly and
     // distinctly rather than silently degrading.
+    const failed = (error: unknown) =>
+      `Cron job "${name}" failed: ${error instanceof Error ? error.message : String(error)}`;
     const wrappedTick = async () => {
       if (!orm) {
         throw new Error(`CronRegistrarService: no MikroORM available to build a request context for job "${name}"`);
       }
-      return withRequestContext(orm, () => onTick());
+      // Each tick is its own unit of work: one correlation id for every line
+      // the job writes, and one line for the tick itself.
+      return traceEntry('cron', name, () => withRequestContext(orm, () => onTick()), {
+        failureLevel: 'error',
+        failureMessage: failed,
+      });
     };
     // waitForCompletion: a tick still running when the next one is due is not
     // started twice (an hourly backup of a large library can outlast its hour).
     // errorHandler: a rejected tick reaches the app log instead of cron's own
-    // console line.
+    // console line, once: a failure the trace above already logged is not
+    // repeated.
     const job = CronJob.from({
       cronTime: expression,
       onTick: wrappedTick,
       start: true,
       timeZone,
       waitForCompletion: true,
-      errorHandler: (error: unknown) => logError(`Cron job "${name}" failed: ${error instanceof Error ? error.message : String(error)}`),
+      errorHandler: (error: unknown) => {
+        if (!wasTraced(error)) logError(failed(error));
+      },
     });
     this.registry.addCronJob(name, job);
     this.names.add(name);

server/tests/unit/middleware/globalMiddleware.correlation.test.ts

@@ -0,0 +1,100 @@
+/**
+ * Request correlation in the global middleware: every response says which id
+ * its request ran under, a well-formed X-Request-Id from the proxy is kept,
+ * and the access log writes a 5xx with that id and the stack the exception
+ * filter left behind, as one entry. REQID-001 through REQID-006.
+ */
+import { describe, it, expect, vi, beforeEach } from 'vitest';
+
+const log = vi.hoisted(() => ({
+  LOG_LEVEL: 'error',
+  logInfo: vi.fn(),
+  logDebug: vi.fn(),
+  logWarn: vi.fn(),
+  logError: vi.fn(),
+}));
+vi.mock('../../../src/nest/audit/audit-log.logger', () => log);
+
+import express, { type Request, type Response } from 'express';
+import request from 'supertest';
+import { applyGlobalMiddleware } from '../../../src/middleware/globalMiddleware';
+import { httpConfig } from '../../../src/nest/app-config/tokens';
+import {
+  ACCESS_LOG_ATTACHED,
+  UNHANDLED_ERROR,
+  currentCorrelation,
+} from '../../../src/nest/common/request-correlation';
+
+const UUID = /^[0-9a-f]{8}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{12}$/;
+
+/** The correlation each logError call was made in, captured at call time. */
+const loggedUnder: Array<string | undefined> = [];
+
+function app() {
+  const a = express();
+  applyGlobalMiddleware(a, { http: httpConfig() });
+  a.get('/api/echo', (_req: Request, res: Response) => {
+    res.json({ id: currentCorrelation()?.id ?? null, kind: currentCorrelation()?.kind ?? null });
+  });
+  a.get('/api/after-await', async (_req: Request, res: Response) => {
+    await new Promise((resolve) => setTimeout(resolve, 1));
+    res.json({ id: currentCorrelation()?.id ?? null });
+  });
+  a.get('/api/boom', (_req: Request, res: Response) => {
+    // What TrekExceptionFilter does for a 5xx when the access log watches the response.
+    expect(res.locals[ACCESS_LOG_ATTACHED]).toBe(true);
+    res.locals[UNHANDLED_ERROR] = new Error('kaput');
+    res.status(500).json({ error: 'Internal server error' });
+  });
+  return a;
+}
+
+beforeEach(() => {
+  vi.clearAllMocks();
+  loggedUnder.length = 0;
+  log.logError.mockImplementation(() => {
+    loggedUnder.push(currentCorrelation()?.id);
+  });
+});
+
+describe('X-Request-Id', () => {
+  it('REQID-001: a request without one gets a fresh id, on the response and in its context', async () => {
+    const res = await request(app()).get('/api/echo');
+    expect(res.headers['x-request-id']).toMatch(UUID);
+    expect(res.body).toEqual({ id: res.headers['x-request-id'], kind: 'http' });
+  });
+
+  it('REQID-002: a well-formed id from the proxy is kept', async () => {
+    const res = await request(app()).get('/api/echo').set('X-Request-Id', 'proxy-1234.abc');
+    expect(res.headers['x-request-id']).toBe('proxy-1234.abc');
+    expect(res.body.id).toBe('proxy-1234.abc');
+  });
+
+  it('REQID-003: a malformed one is replaced, never echoed', async () => {
+    const res = await request(app()).get('/api/echo').set('X-Request-Id', 'not an id <b>');
+    expect(res.headers['x-request-id']).toMatch(UUID);
+  });
+
+  it('REQID-004: the id survives an await in the handler', async () => {
+    const res = await request(app()).get('/api/after-await');
+    expect(res.body.id).toBe(res.headers['x-request-id']);
+  });
+
+  it('REQID-005: two requests never share an id', async () => {
+    const a = app();
+    const [one, two] = await Promise.all([request(a).get('/api/echo'), request(a).get('/api/echo')]);
+    expect(one.headers['x-request-id']).not.toBe(two.headers['x-request-id']);
+  });
+});
+
+describe('the access log', () => {
+  it('REQID-006: a 5xx is one entry with the request line, the stack and the request id', async () => {
+    const res = await request(app()).get('/api/boom');
+    expect(res.status).toBe(500);
+    await vi.waitFor(() => expect(log.logError).toHaveBeenCalledTimes(1));
+    const line = String(log.logError.mock.calls[0][0]);
+    expect(line).toMatch(/^GET \/api\/boom 500 \d+ms ip=/);
+    expect(line).toContain('\nError: kaput');
+    expect(loggedUnder[0]).toBe(res.headers['x-request-id']);
+  });
+});

server/tests/unit/nest-mcp/attach.test.ts

@@ -373,3 +373,52 @@ describe('McpAttachOptions.onInvoke', () => {
     expect((result as { isError?: boolean }).isError).toBe(true);
   });
 });
+
+describe('McpAttachOptions.around', () => {
+  let harness: AttachHarness | undefined;
+  afterEach(async () => {
+    await harness?.cleanup();
+    harness = undefined;
+  });
+
+  const fullCtx: TestCtx = { userId: 7, canRead: true, canWrite: true, allow: true };
+
+  it('wraps every invocation and passes the handler result through unchanged', async () => {
+    const seen: Array<{ kind: string; name: string }> = [];
+    const plain = await createAttachHarness(buildRegistry(), fullCtx);
+    const expected = await plain.client.callTool({ name: 'open_tool', arguments: {} });
+    await plain.cleanup();
+
+    harness = await createAttachHarness(buildRegistry(), fullCtx, {
+      around: (info, call) => {
+        seen.push(info);
+        return call();
+      },
+    });
+    expect(seen).toEqual([]);
+    expect(await harness.client.callTool({ name: 'open_tool', arguments: {} })).toEqual(expected);
+    await harness.client.readResource({ uri: 'test://doc' });
+    await harness.client.readResource({ uri: 'test://item/5' });
+    await harness.client.getPrompt({ name: 'fixture_prompt', arguments: { topic: 't' } });
+    expect(seen).toEqual([
+      { kind: 'tool', name: 'open_tool' },
+      { kind: 'resource', name: 'fixture_doc' },
+      { kind: 'resourceTemplate', name: 'fixture_item' },
+      { kind: 'prompt', name: 'fixture_prompt' },
+    ]);
+  });
+
+  it('runs the handler inside the wrapper, so the wrapper sees its outcome', async () => {
+    const outcomes: unknown[] = [];
+    harness = await createAttachHarness(buildRegistry(), fullCtx, {
+      around: async (_info, call) => {
+        const result = await call();
+        outcomes.push(result);
+        return result;
+      },
+    });
+    await harness.client.callTool({ name: 'open_tool', arguments: {} });
+    expect(outcomes).toHaveLength(1);
+    expect(outcomes[0]).toBeDefined();
+  });
+});

server/tests/unit/nest/common/request-correlation.test.ts

@@ -0,0 +1,62 @@
+/**
+ * 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] ');
+  });
+});

server/tests/unit/nest/cron-registrar.service.test.ts

@@ -56,6 +56,7 @@ import type { RuntimeEnvService } from '../../../src/nest/app-config/runtime-env
 import { createSnapshotTestDb } from '../../helpers/db-mock';
 import { createTestOrm, type TestOrm } from '../../helpers/test-orm';
 import { Users } from '../../../src/db/entities/Users.entity';
+import { currentCorrelation, type Correlation } from '../../../src/nest/common/request-correlation';
 
 function makeRegistrar(isTest: boolean) {
   const registry = new SchedulerRegistry();
@@ -250,6 +251,31 @@ describe('CronRegistrarService', () => {
       expect(caught).toBeUndefined();
       expect(typeof result).toBe('number');
     });
+
+    it('CRONREG-015: each tick runs under its own cron correlation id', async () => {
+      const registrar = new CronRegistrarService(new SchedulerRegistry(), { isTest: () => false } as RuntimeEnvService, t.orm);
+      const seen: Array<Correlation | undefined> = [];
+      registrar.register('job', '0 2 * * *', () => {
+        seen.push(currentCorrelation());
+      });
+      await h.jobs[0].onTick();
+      await h.jobs[0].onTick();
+      expect(seen.map((c) => c?.kind)).toEqual(['cron', 'cron']);
+      expect(seen[0]!.id).not.toBe(seen[1]!.id);
+    });
+
+    it('CRONREG-016: a failed tick is logged once, by the trace, and the error handler does not repeat it', async () => {
+      logErrorMock.mockClear();
+      const registrar = new CronRegistrarService(new SchedulerRegistry(), { isTest: () => false } as RuntimeEnvService, t.orm);
+      const boom = new Error('kaput');
+      registrar.register('job', '0 2 * * *', () => {
+        throw boom;
+      });
+      await expect(h.jobs[0].onTick()).rejects.toBe(boom);
+      expect(logErrorMock).toHaveBeenCalledWith('Cron job "job" failed: kaput');
+      h.jobs[0].errorHandler!(boom);
+      expect(logErrorMock).toHaveBeenCalledTimes(1);
+    });
   });
 
   describe('runOnBoot (task-6-fix-brief.md item 7 — the boot-sweep choke point)', () => {

server/tests/unit/nest/entry-trace.logger.test.ts

@@ -0,0 +1,105 @@
+/**
+ * traceEntry (nest/audit/entry-trace.logger.ts): one correlation id and one
+ * log line per call of a non-HTTP entry point, without changing what the call
+ * returns or when it runs. TRACE-001 through TRACE-008.
+ */
+import { describe, it, expect, vi, beforeEach } from 'vitest';
+
+const log = vi.hoisted(() => ({
+  LOG_LEVEL: 'error',
+  logInfo: vi.fn(),
+  logDebug: vi.fn(),
+  logWarn: vi.fn(),
+  logError: vi.fn(),
+}));
+vi.mock('../../../src/nest/audit/audit-log.logger', () => log);
+
+import { traceEntry, wasTraced } from '../../../src/nest/audit/entry-trace.logger';
+import { currentCorrelation, runWithCorrelation } from '../../../src/nest/common/request-correlation';
+
+beforeEach(() => {
+  vi.clearAllMocks();
+});
+
+describe('traceEntry', () => {
+  it('TRACE-001: a plain value comes back as it is, synchronously, with one debug line', () => {
+    const result = traceEntry('ws', 'join user=3', () => 42);
+    expect(result).toBe(42);
+    expect(log.logDebug).toHaveBeenCalledTimes(1);
+    expect(log.logDebug.mock.calls[0][0]).toMatch(/^ws join user=3 ok \d+ms$/);
+  });
+
+  it('TRACE-002: the call runs under its own correlation, nested under the current one', () => {
+    let inside: ReturnType<typeof currentCorrelation>;
+    runWithCorrelation({ id: 'req-1', kind: 'http' }, () => {
+      traceEntry('mcp', 'tool list_trips user=1', () => {
+        inside = currentCorrelation();
+      });
+    });
+    expect(inside!.kind).toBe('mcp');
+    expect(inside!.parentId).toBe('req-1');
+    expect(inside!.id).not.toBe('req-1');
+    expect(log.logDebug.mock.calls[0][0]).toContain(' parent=req-1');
+  });
+
+  it('TRACE-003: a promise comes back as that same promise, and the line waits for it to settle', async () => {
+    let resolve!: (value: string) => void;
+    const pending = new Promise<string>((r) => {
+      resolve = r;
+    });
+    const result = traceEntry('rpc', 'p1 trips.get', () => pending);
+    expect(result).toBe(pending);
+    expect(log.logDebug).not.toHaveBeenCalled();
+    resolve('done');
+    await expect(result).resolves.toBe('done');
+    await vi.waitFor(() => expect(log.logDebug).toHaveBeenCalledTimes(1));
+  });
+
+  it('TRACE-004: a synchronous throw is logged at warn and rethrown', () => {
+    expect(() =>
+      traceEntry('ws', 'join', () => {
+        throw new Error('nope');
+      }),
+    ).toThrow('nope');
+    expect(log.logWarn.mock.calls[0][0]).toMatch(/^ws join failed \d+ms: nope$/);
+  });
+
+  it('TRACE-005: a rejection is logged with the configured level and wording, and marked as reported', async () => {
+    const boom = new Error('disk full');
+    const result = traceEntry('cron', 'auto-backup', () => Promise.reject(boom), {
+      failureLevel: 'error',
+      failureMessage: (error) => `Cron job "auto-backup" failed: ${(error as Error).message}`,
+    });
+    await expect(result).rejects.toBe(boom);
+    await vi.waitFor(() => expect(log.logError).toHaveBeenCalledWith('Cron job "auto-backup" failed: disk full'));
+    expect(wasTraced(boom)).toBe(true);
+    expect(wasTraced(new Error('other'))).toBe(false);
+    expect(wasTraced('a string')).toBe(false);
+  });
+
+  it('TRACE-006: a call that answers with a refusal is logged at warn with the reason', async () => {
+    const answer = { ok: false as const, error: 'FORBIDDEN' };
+    await traceEntry('rpc', 'p1 trips.update', () => Promise.resolve(answer), {
+      refusal: (value) => (value.ok ? null : value.error),
+    });
+    await vi.waitFor(() => expect(log.logWarn).toHaveBeenCalledTimes(1));
+    expect(log.logWarn.mock.calls[0][0]).toMatch(/^rpc p1 trips.update refused \d+ms: FORBIDDEN$/);
+    expect(log.logDebug).not.toHaveBeenCalled();
+  });
+
+  it('TRACE-007: every line the call writes carries the same correlation', async () => {
+    const seen: Array<string | undefined> = [];
+    await traceEntry('cron', 'docsync', async () => {
+      seen.push(currentCorrelation()?.id);
+      await new Promise((resolve) => setTimeout(resolve, 1));
+      seen.push(currentCorrelation()?.id);
+    });
+    expect(seen[0]).toBeDefined();
+    expect(seen[1]).toBe(seen[0]);
+  });
+
+  it('TRACE-008: two calls never share an id', () => {
+    const ids = [1, 2].map(() => traceEntry('ws', 'leave', () => currentCorrelation()?.id));
+    expect(ids[0]).not.toBe(ids[1]);
+  });
+});

server/tests/unit/nest/exception-filter.test.ts

@@ -142,3 +142,54 @@ describe('TrekExceptionFilter', () => {
     expect(res.json).toHaveBeenCalledWith({ error: 'Internal server error' });
   });
 });
+
+describe('TrekExceptionFilter and the access log', () => {
+  const filter = new TrekExceptionFilter();
+  /** A response the access log watches: what the global middleware marks on res.locals. */
+  const watched = (extra: Record<string, unknown> = {}) => {
+    const locals: Record<string, unknown> = { trekAccessLog: true };
+    return { locals, ...mockHost({ locals, ...extra }) };
+  };
+
+  it('leaves a 5xx for the access log instead of printing it on its own line', () => {
+    const consoleError = vi.spyOn(console, 'error').mockImplementation(() => {});
+    const { res, host, locals } = watched();
+    const exception = new Error('boom');
+    filter.catch(exception, host);
+    expect(res.status).toHaveBeenCalledWith(500);
+    expect(locals.trekUnhandledError).toBe(exception);
+    expect(consoleError).not.toHaveBeenCalled();
+    consoleError.mockRestore();
+  });
+
+  it('does the same for a failure after the headers went out, and still destroys the socket', () => {
+    const consoleError = vi.spyOn(console, 'error').mockImplementation(() => {});
+    const { res, host, locals } = watched({ headersSent: true });
+    const exception = new Error('mid-stream failure');
+    filter.catch(exception, host);
+    expect(res.destroy).toHaveBeenCalledTimes(1);
+    expect(locals.trekUnhandledError).toBe(exception);
+    expect(consoleError).not.toHaveBeenCalled();
+    consoleError.mockRestore();
+  });
+
+  it('hands over a deliberate 5xx HttpException too, but never a 4xx', () => {
+    const server = watched();
+    const exception = new HttpException('database exploded', 503);
+    filter.catch(exception, server.host);
+    expect(server.locals.trekUnhandledError).toBe(exception);
+
+    const client = watched();
+    filter.catch(new HttpException('Bad thing', 400), client.host);
+    expect(client.locals.trekUnhandledError).toBeUndefined();
+  });
+
+  it('prints the 5xx itself when no access log watches the response', () => {
+    const consoleError = vi.spyOn(console, 'error').mockImplementation(() => {});
+    const { host } = mockHost();
+    const exception = new Error('unwatched');
+    filter.catch(exception, host);
+    expect(consoleError).toHaveBeenCalledWith('Unhandled error:', exception);
+    consoleError.mockRestore();
+  });
+});

server/tests/unit/nest/trek-ws-adapter.test.ts

@@ -37,6 +37,7 @@ import type { Server as HttpServer } from 'node:http';
 import { createSnapshotTestDb } from '../../helpers/db-mock';
 import { createTestOrm, type TestOrm } from '../../helpers/test-orm';
 import { Users } from '../../../src/db/entities/Users.entity';
+import { currentCorrelation, type Correlation } from '../../../src/nest/common/request-correlation';
 
 const testDb = createSnapshotTestDb();
 
@@ -186,6 +187,23 @@ describe('TrekWsAdapter D6 request context (task-2-review.md C3 ruling)', () =>
   });
 });
 
+describe('TrekWsAdapter correlation', () => {
+  it('WSAD-050: every message runs under its own ws correlation, and a plain answer still goes out at once', () => {
+    const socket = fakeSocket();
+    const seen: Array<Correlation | undefined> = [];
+    adapter.bindMessageHandlers(
+      socket as never,
+      [{ message: 'join', callback: () => { seen.push(currentCorrelation()); return { type: 'joined' }; } }] as never,
+      transform,
+    );
+    socket.emit('message', frame({ type: 'join', tripId: 1 }));
+    socket.emit('message', frame({ type: 'join', tripId: 2 }));
+    expect(seen.map((c) => c?.kind)).toEqual(['ws', 'ws']);
+    expect(seen[0]!.id).not.toBe(seen[1]!.id);
+    expect(socket.sent).toHaveLength(2);
+  });
+});
+
 describe('TrekWsAdapter flood guard', () => {
   it('WSAD-010: counts EVERY frame, including the ones no handler wants', () => {
     // The guard sits before parsing on purpose. Counting only the frames that

server/tests/unit/plugins/rpc-trace.test.ts

@@ -0,0 +1,93 @@
+/**
+ * Every plugin RPC dispatch is its own unit of work: a correlation id the
+ * whole dispatch runs under, and one log line per call. A refused call comes
+ * back as `{ ok: false }` rather than a throw, so that is what the line says.
+ */
+import { describe, it, expect, vi, beforeAll, afterAll, beforeEach } from 'vitest';
+
+const log = vi.hoisted(() => ({
+  LOG_LEVEL: 'error',
+  logInfo: vi.fn(),
+  logDebug: vi.fn(),
+  logWarn: vi.fn(),
+  logError: vi.fn(),
+}));
+vi.mock('../../../src/nest/audit/audit-log.logger', () => log);
+
+import { createSnapshotTestDb } from '../../helpers/db-mock';
+import { createTestOrm, type TestOrm } from '../../helpers/test-orm';
+import { PluginSupervisor } from '../../../src/nest/plugins/supervisor/plugin-supervisor';
+import { RpcRateLimiter, DEFAULT_RPC_LIMIT } from '../../../src/nest/plugins/host/rate-limit';
+import { currentCorrelation, type Correlation } from '../../../src/nest/common/request-correlation';
+import type { PluginRpcHost } from '../../../src/nest/plugins/host/rpc-host';
+import type { RpcRequest, RpcResponse, RpcError } from '../../../src/nest/plugins/protocol/envelope';
+
+interface DispatchEntry {
+  id: string;
+  rpcHost: Pick<PluginRpcHost, 'dispatch'>;
+  child: { send: (msg: unknown) => void } | null;
+  rpcLimiter: RpcRateLimiter;
+  invocations: Map<string, number | undefined>;
+}
+interface SupervisorPrivate {
+  onMessage(sup: DispatchEntry, msg: RpcRequest): Promise<void>;
+}
+
+const testDb = createSnapshotTestDb();
+let t: TestOrm;
+
+beforeAll(async () => {
+  t = await createTestOrm(testDb);
+});
+afterAll(async () => {
+  await t.close();
+  testDb.close();
+});
+beforeEach(() => {
+  vi.clearAllMocks();
+});
+
+function makeSupervisor(answer: (req: RpcRequest) => RpcResponse | RpcError) {
+  const seen: Array<Correlation | undefined> = [];
+  const sent: unknown[] = [];
+  const dispatch: PluginRpcHost['dispatch'] = async (req) => {
+    seen.push(currentCorrelation());
+    return answer(req);
+  };
+  const supervisor = new PluginSupervisor(() => ({ dispatch }) as unknown as PluginRpcHost, {}, {}, () => t.orm) as unknown as SupervisorPrivate;
+  const sup: DispatchEntry = {
+    id: 'weather-plugin',
+    rpcHost: { dispatch },
+    child: { send: (msg) => sent.push(msg) },
+    rpcLimiter: new RpcRateLimiter(DEFAULT_RPC_LIMIT, Date.now()),
+    invocations: new Map(),
+  };
+  return { supervisor, sup, seen, sent };
+}
+
+describe('plugin RPC tracing', () => {
+  it('RPC-TRACE-001: a dispatch runs under its own rpc correlation and logs one ok line', async () => {
+    const { supervisor, sup, seen, sent } = makeSupervisor((req) => ({ k: 'res', id: req.id, ok: true, result: 1 }));
+    await supervisor.onMessage(sup, { k: 'req', id: 'r1', method: 'trips.get', params: {} });
+    await supervisor.onMessage(sup, { k: 'req', id: 'r2', method: 'trips.get', params: {} });
+    expect(sent).toHaveLength(2);
+    expect(seen.map((c) => c?.kind)).toEqual(['rpc', 'rpc']);
+    expect(seen[0]!.id).not.toBe(seen[1]!.id);
+    await vi.waitFor(() => expect(log.logDebug).toHaveBeenCalledTimes(2));
+    expect(String(log.logDebug.mock.calls[0][0])).toMatch(/^rpc weather-plugin trips\.get ok \d+ms$/);
+  });
+
+  it('RPC-TRACE-002: a refused dispatch is logged at warn with its code and reason', async () => {
+    const { supervisor, sup } = makeSupervisor((req) => ({
+      k: 'res',
+      id: req.id,
+      ok: false,
+      error: { code: 'PERMISSION_DENIED', message: 'no trip access' },
+    }));
+    await supervisor.onMessage(sup, { k: 'req', id: 'r3', method: 'trips.update', params: {} });
+    await vi.waitFor(() => expect(log.logWarn).toHaveBeenCalledTimes(1));
+    expect(String(log.logWarn.mock.calls[0][0])).toMatch(
+      /^rpc weather-plugin trips\.update refused \d+ms: PERMISSION_DENIED no trip access$/,
+    );
+  });
+});