# Logging Improvements — TRD ## Status Draft — 2026-03-22 ## Overview Replace ad-hoc string-interpolation logging with structured JSON logs enriched by an AsyncLocalStorage-based request context that flows through all components automatically. Every log line emitted during a request will carry `requestId`, `identityHash`, and `conversationId` without any function signature changes. This enables Datadog faceting, alerting, and end-to-end request tracing across the full conversation lifecycle — from SSE connection through multi-round tool execution to response completion. ### Why this matters for an AI agent ows-coda is not a typical request/response API. A single user message can trigger a multi-round conversation loop: the LLM responds, requests tool calls, the orchestrator dispatches those tools (each making downstream HTTP requests), feeds results back to the LLM, and repeats — sometimes for 10+ rounds. A single SSE stream might produce 30 tool calls across 6 rounds, touching Redis, Snowflake, and 5 downstream services. When something goes wrong today — a conversation hangs, a tool returns unexpected data, a downstream service is slow — the debugging story is painful: - **"Which request caused this?"** Log lines say `tool execution completed` with no request or conversation ID. If two users are chatting simultaneously, their logs interleave and there is no way to separate them. - **"What happened in round 4?"** The orchestrator only logs once at conversation end. If a tool failed in round 4 of 8, the only evidence is the final summary. There is no visibility into per-round timing, tool selection, or error counts. - **"Why is this conversation slow?"** Downstream HTTP logs use string interpolation (`[HTTP] GET /api/accounts -> 200`). Datadog cannot facet on URL, status code, or duration because they are buried in an unstructured message string. Finding which downstream call caused a 15-second conversation requires manually reading raw log text. - **"Is Redis healthy?"** Cache hits and misses are not logged. If Redis latency spikes or hit rates drop, there is no signal until users report degraded performance. - **"Who is getting rate-limited?"** Rate limit events produce zero log output. Abusive clients or misconfigured integrations are invisible. After this change, a single Datadog query like `@conversationId:conv-456` returns every log line from that conversation in order — middleware entry, auth, each orchestrator round, every tool call with duration, every downstream HTTP request, cache operations, and the final summary. Facets on `@tool`, `@durationMs`, `@status`, and `@method` enable dashboards for tool latency percentiles, downstream error rates, and cache hit ratios without custom log-based metric queries. ## Goals 1. **Request traceability.** Every log line within a request carries `requestId`, `identityHash` (SHA-256 truncated, not raw PII), and `conversationId`. A single Datadog query reconstructs the full request timeline. 2. **Operational visibility.** New structured log lines for: per-round orchestrator state (tool dispatch, round timing, error counts), cache hit/miss rates, rate limit events, and slow downstream requests. 3. **Datadog-native faceting.** All log fields are top-level JSON keys — `tool`, `durationMs`, `status`, `method`, `url`, `round`, `hit`. No regex parsing required. 4. **Zero function signature changes.** AsyncLocalStorage + pino mixin means existing code keeps calling `logger.info(...)` and gets context fields automatically. No `ctx` parameter threading. 5. **No new dependencies.** AsyncLocalStorage is built into Node. pino mixin is a configuration option. No additional npm packages. ## Architecture ### Three-Phase Context Enrichment Request context is populated progressively as information becomes available in the middleware chain: ``` Phase 1 Phase 2 Phase 3 requestId identityHash conversationId | | | Request ──> [contextMiddleware] ──> [requireAuth] ──> [enrichCtx] ──> [chatRouter.param("id")] ──> [handler] | | | | reads res.locals.identityId | | hashes it (SHA-256, 12 chars) | | sets conversationId v on mutable store AsyncLocalStorage.run() creates mutable store { requestId } ``` ### Middleware Chain (updated) ``` requestContextMiddleware ← Phase 1: creates AsyncLocalStorage store with requestId | requestLogger (pino-http) ← runs inside ALS context; mixin picks up fields | requireAuth ← populates res.locals.identityId | enrichRequestContext ← Phase 2: hashes identityId, mutates store | apiRateLimit ← rate limiting (now with warn logging) | snowflakeIdentity ← existing | [route handlers] ← Phase 3: chatsRouter.param("id") sets conversationId ``` ### Pino Mixin Integration ``` logger.info({ tool: "search_accounts", durationMs: 142 }, "tool execution completed") | pino mixin() called ──> requestContext.getStore() | merges store fields into log object | v { "level": 30, "requestId": "a1b2c3d4-...", ← from Phase 1 "identityHash": "a3f8c1b2e9d4", ← from Phase 2 "conversationId": "conv-456", ← from Phase 3 "tool": "search_accounts", ← from call site "durationMs": 142, ← from call site "msg": "tool execution completed" } ``` ## Detailed Design ### 1. AsyncLocalStorage Module **New file:** `server/src/utils/request-context.ts` Exports: - `RequestContext` interface: `{ requestId: string; conversationId?: string; identityHash?: string }` - `requestContext`: `AsyncLocalStorage` singleton - `hashIdentity(identityId: string): string`: SHA-256, truncated to 12 hex characters The identity hash is a one-way transform. To debug a user-reported issue, an engineer hashes the user's known `identityId` and searches Datadog for that hash. The hash cannot be reversed to recover the original identifier. ### 2. Two-Middleware Approach Two separate middlewares are required because of the existing middleware ordering constraint: ``` requestLogger → requireAuth → ... ``` `identityId` is only available after `requireAuth` runs, but the AsyncLocalStorage context must be established before `requestLogger` so that pino-http log lines include `requestId`. The solution: - **`requestContextMiddleware`** runs first, calls `requestContext.run()` to establish the ALS store with `requestId` (from `X-Request-Id` header or generated UUID). All downstream middleware and handlers execute inside this `run()` callback. - **`enrichRequestContext`** runs after `requireAuth`, reads `res.locals.identityId`, hashes it, and mutates the existing store object. Because the store is a mutable object reference, the pino mixin sees the updated fields immediately — no new `run()` call needed. A single middleware could not accomplish this because `requestContext.run()` must wrap all downstream execution (including `requestLogger`), but `identityId` is not yet available at that point. ### 3. Pino Mixin Integration The existing `logger.ts` gains a `mixin()` option that reads from `requestContext.getStore()`. When the store is `undefined` (e.g., during server startup, background tasks), the mixin returns `{}` — no fields added, no errors thrown. Optional fields (`conversationId`, `identityHash`) that are `undefined` are spread into the object but omitted from JSON output by pino automatically. No changes to `request-logger.ts` (pino-http) are needed. It already uses the shared logger instance, so the mixin applies to its output automatically. ### 4. Per-Component Logging Specifications **Orchestrator** (`server/src/ai/orchestrator.ts`): - `debug`: round started (round number, max rounds) - `info`: executing tools (round, tool names, count) - `info`: tool round completed (round, tool names, durationMs, error count) - `info`: conversation complete (rounds, durationMs, input/output/total tokens, maxRoundsReached, model) - `error`: LLM stream error (structured error object, replaces string interpolation) **Cache** (`server/src/cache/conversation-cache.ts`): - `debug`: cache hit (conversationId, messageCount) - `debug`: cache miss (conversationId) - `debug`: cache write (conversationId, messageCount) - `warn`: corrupt JSON, malformed meta (structured, replaces string interpolation) **HTTP Client** (`server/src/services/http-client.ts`): - `info`: downstream request success (method, url, status, durationMs) - `warn`: downstream request failed (method, url, status, durationMs) - `warn`: slow downstream request (method, url, status, durationMs) — threshold: 3000ms - `error`: downstream 500 (method, url, responseBody truncated to 200 chars) **Tool Registry** (`server/src/ai/tools/registry.ts`): - `info`: tool execution completed (tool name, durationMs, optional toolError) - `error`: tool execution failed (tool name, durationMs, error object) **Rate Limit** (`server/src/middleware/rate-limit.ts`): - `warn`: rate limit exceeded (tier, ip, method, path, limit, windowMs) **Stream Handler, Route Handlers, Redis Store, Vector Index:** - Mechanical upgrade of all remaining string-interpolation logs to structured format. Same log levels, same semantics, structured fields instead of template strings. ### 5. Log Level Discipline | Level | Usage | Examples | | ------- | ---------------------------- | ----------------------------------------------------- | | `debug` | High-frequency ops, opt-in | Cache hit/miss, round starts | | `info` | Operational milestones | Tool execution, downstream requests, conversation end | | `warn` | Degraded but recoverable | Slow requests, rate limits, corrupt cached data | | `error` | Failures requiring attention | 500s, stream errors, uncaught exceptions | Production runs at `info` level by default. `debug` is available via `LOG_LEVEL=debug` on a single pod for targeted investigation. Cache hit/miss and round-start logs are `debug` because they fire on every request and would significantly increase log volume at `info`. ## Alternatives Explored ### AsyncLocalStorage vs. manual context threading Manual threading would require adding a `ctx` parameter to every function in the call chain — from middleware through orchestrator, tool executor, HTTP client, and cache. This touches dozens of function signatures, breaks existing interfaces, and requires every new function to remember to pass context. AsyncLocalStorage is invisible to application code: set once in middleware, read automatically by the pino mixin. Node.js has supported it since v16 and it is stable. ### Pino mixin vs. child loggers Child loggers (`logger.child({ requestId })`) require creating a new logger instance per request and passing it through the call chain — the same threading problem as manual context. The mixin approach uses a single global logger instance. Every `logger.info(...)` call anywhere in the codebase automatically includes context fields. No code changes at call sites. ### Two middlewares vs. delayed single middleware A single middleware that runs after `requireAuth` would miss the window to wrap `requestLogger` in the ALS context. pino-http logs (request start/end) would lack `requestId`. The two-middleware approach ensures every log line — including pino-http's own request/response logs — carries correlation fields. ### Hashed identity vs. raw identityId in logs Raw `identityId` is a pseudonymous identifier that can be linked back to a person. Logging it in plaintext creates a PII surface in log storage. SHA-256 truncated to 12 hex characters preserves cross-request correlation (deterministic) without storing a reversible identifier. 12 hex characters (48 bits) provide sufficient uniqueness for log correlation while keeping log lines compact. ## Cost Analysis ### Infrastructure cost Zero. No new services, no new dependencies, no additional storage backends. Log volume stays the same — existing log lines are reformatted, not duplicated. New `debug`-level lines are suppressed in production by default. ### Engineering effort 18 files modified across 11 tasks. Estimated 2-3 days of implementation: | Category | Files | Effort | | -------------------------------------------- | ---------------- | ------- | | New modules (request-context, 2 middlewares) | 3 new | 0.5 day | | Logger mixin + route wiring | 3 modified | 0.5 day | | Per-component structured logging | 10 modified | 1 day | | Tests + verification | 2 new test files | 0.5 day | ### Return on investment The primary benefit is reduced debugging time. Current mean-time-to-diagnose for conversation-level issues requires manual log correlation across interleaved request output. With structured context fields, the same investigation is a single Datadog facet query. For a team supporting a production AI agent, this translates to meaningful time savings on every incident. ## Performance Analysis ### AsyncLocalStorage overhead Node.js AsyncLocalStorage uses the native async hooks mechanism. Benchmarks consistently show overhead in the low-microsecond range per async operation — negligible compared to the millisecond-scale I/O operations (Bedrock API calls, Redis reads, HTTP requests) that dominate ows-coda's request lifecycle. The Node.js documentation marks AsyncLocalStorage as stable and recommends it for request context propagation. ### Pino mixin overhead The mixin function runs once per log call. It performs a `getStore()` lookup (pointer dereference, effectively free) and a shallow object spread. At ~30-50 log calls per conversation lifecycle, this adds microseconds total. ### Log volume impact - **Production (`info` level):** No increase. Existing `info` and above log lines are reformatted (same count, richer fields). New orchestrator round logs are `info` but replace the gap where no per-round visibility existed — net new lines are ~2-4 per conversation. - **Debug mode (`debug` level):** Cache hit/miss and round-start logs add ~5-15 lines per conversation. Debug mode is opt-in and typically used on a single pod for investigation. ### Serialization overhead Structured pino objects with 3-5 additional fields (`requestId`, `identityHash`, `conversationId`, `tool`, `durationMs`) add roughly 100-150 bytes per log line. At current request volume this is negligible for log transport and storage. ## Scaling Characteristics Structured logs with top-level JSON fields enable Datadog faceting at any scale. As request volume grows: - **Faceted queries** (`@tool:search_accounts @durationMs:>1000`) remain O(1) lookup in Datadog's indexed fields, regardless of log volume. String-interpolation logs require full-text regex scans that degrade with scale. - **Dashboards and monitors** built on structured fields (p95 tool latency, downstream error rate by service, cache hit ratio) work identically whether the service handles 100 or 100,000 requests per day. - **Log storage** does not increase meaningfully. The same number of log lines are emitted with richer fields. The additional bytes per line (context fields) are a rounding error compared to message content and stack traces. - **Horizontal scaling** (additional Fargate tasks) benefits directly: `requestId` correlates logs across load-balanced instances without relying on pod-level log grouping. ## Breakdown Points & Mitigations ### AsyncLocalStorage context loss **Risk:** If a middleware is registered outside the `requestContext.run()` callback, or if a background task (setTimeout, event emitter) breaks the async context chain, log lines will silently lose correlation fields. **Mitigation:** The mixin gracefully returns `{}` when the store is undefined — no crashes, just missing fields. The unit test for mixin integration verifies both the "context present" and "context absent" paths. Code review should flag any `setTimeout` or manual `Promise` construction in request handlers that might break the chain. ### Log level misconfiguration **Risk:** Setting `LOG_LEVEL=debug` in production would emit high-frequency cache and round-start logs, significantly increasing log volume and Datadog ingestion cost. **Mitigation:** The default level is `info` in production, enforced by the existing `isTest ? "silent" : isDev ? "debug" : "info"` logic. `LOG_LEVEL` override requires an explicit environment variable change — it cannot happen accidentally. Document that debug mode should only be used temporarily on individual pods. ### PII in logs **Risk:** A developer adds `identityId` directly to a structured log call, bypassing the hash. **Mitigation:** The `identityId` is only available on `res.locals` — it is never exposed as a global or passed to downstream components. The `enrichRequestContext` middleware is the single point where identity enters the log context, and it always hashes. Code review guidelines should flag any direct use of `res.locals.identityId` in logger calls. The `requestContext` interface does not include an `identityId` field — only `identityHash`. ### Downstream response body in logs **Risk:** The `responseBody` field logged for 500 errors could contain sensitive data from downstream services. **Mitigation:** Response bodies are truncated to 200 characters (existing behavior, now explicit via `substring(0, 200)`). Downstream services are internal APIs that do not return user PII in error responses. This is the same content that was previously logged via string interpolation — the structured format does not change what is captured. ## Decision Log | Decision | Rationale | | ----------------------------------------------- | --------------------------------------------------------------------------------------------------------- | | AsyncLocalStorage over manual context threading | Zero function signature changes; invisible to call sites; stable Node.js API | | Pino mixin over child loggers | Single global logger; no instance passing; mixin reads from ALS automatically | | Two middlewares over one | `requestId` must be available before pino-http; `identityId` is only available after auth | | Mutable store object | Enables progressive enrichment (Phase 1/2/3) without nested `run()` calls | | SHA-256 truncated to 12 hex chars for identity | One-way (no PII in logs), deterministic (enables cross-request correlation), compact | | Cache logs at `debug` level | High frequency; would increase production log volume at `info`; available when needed | | 3000ms slow-request threshold | Balances signal-to-noise; most downstream calls complete in < 500ms; 3s indicates degradation | | `chatsRouter.param("id")` for conversationId | Runs only for conversation routes; no-op for non-conversation endpoints; already used for UUID validation | ## Dependencies ### Internal - **pino** (existing) — logger library; mixin is a built-in configuration option - **pino-http** (existing) — request logger middleware; no changes needed - **Express middleware chain** (existing) — new middlewares insert into existing `router.use()` call ### External - **Node.js `node:async_hooks`** — built-in module, no npm dependency; stable since Node 16 - **Node.js `node:crypto`** — built-in module; used for `createHash` (identity hashing) and `randomUUID` (request ID generation) ### No new npm dependencies This change introduces zero new packages. AsyncLocalStorage and crypto are Node.js built-ins. All logging uses the existing pino instance. ## Testing Strategy ### Unit tests (new) 1. **`request-context.test.ts`** — Tests for the request context module: - `hashIdentity` returns 12-character hex string - `hashIdentity` is deterministic (same input produces same output) - `hashIdentity` produces different hashes for different inputs - `requestContext.getStore()` returns `undefined` outside a `run()` - `requestContext.getStore()` returns the context inside a `run()` - Store supports mutation for phase 2/3 enrichment 2. **Mixin integration test** — Verifies the pino mixin pattern: - Logger output includes context fields when ALS store is active - Logger output omits context fields when store is not active - `undefined` optional fields (e.g., `conversationId`) are omitted from JSON output ### Existing test suite All existing tests continue to pass without modification. The logger is mocked in test files, so structured format changes do not affect assertions. The `LOG_LEVEL=silent` environment variable (set in test configuration) suppresses all log output during tests. ### Manual verification After deployment, verify in Datadog: - Log lines include `requestId`, `identityHash`, `conversationId` fields - Fields are facetable (appear in Datadog's facet panel) - A query like `@conversationId:` returns all log lines for a conversation in chronological order ## Rollout Plan ### Phase 1: Request context and middleware (Tasks 1-2) - Create `request-context.ts` module with AsyncLocalStorage and `hashIdentity` - Add `mixin` to `logger.ts` - Create and wire `requestContextMiddleware` and `enrichRequestContext` into route chain - Add `conversationId` enrichment in `chatsRouter.param("id")` - **Verification:** Deploy to staging. Confirm Datadog log lines include `requestId`. Confirm `identityHash` appears on authenticated requests. Confirm `conversationId` appears on conversation routes. ### Phase 2: Per-component structured logging (Tasks 3-10) - Orchestrator: per-round logging (round start, tool dispatch, round complete, conversation summary) - Cache: hit/miss/write debug logs, structured warn logs - HTTP client: structured request logs, slow-request warnings, 500-body logging parity - Tool registry: structured execution logs - Rate limit: event logging - Stream handler, route handlers, redis-store, vector-index: mechanical string-to-structured upgrades - **Verification:** Deploy to staging. Confirm new structured fields appear in Datadog. Verify no regressions in existing functionality via test suite. ### Phase 3: Dashboards and monitors (post-implementation) - Create Datadog dashboard: tool latency percentiles (p50/p95/p99 by tool name), downstream service error rates (by URL), cache hit ratio, rate limit events over time - Create Datadog monitors: alert on p95 tool latency > threshold, alert on downstream 500 rate spike, alert on rate limit event volume - **This phase is out of scope for the current implementation plan** but is the intended consumer of the structured log data. ## Open Questions 1. **Log-based metrics vs. StatsD.** Datadog can derive metrics from structured log fields (log-based metrics) or the application can emit StatsD counters/histograms directly via `dd-trace`. Structured logs are sufficient for initial dashboards. Should we also emit StatsD metrics for high-cardinality dimensions (per-tool latency histograms) where log-based metrics may be expensive? 2. **Request ID propagation to downstream services.** The `requestContextMiddleware` generates or reads `X-Request-Id`. Should `http-client.ts` forward this header to downstream services to enable cross-service tracing? This would complement Datadog APM traces but requires downstream services to log the header. 3. **Debug log shipping.** Production defaults to `info` level. If `debug` logs are not shipped to Datadog at all, cache hit/miss data is invisible even when `LOG_LEVEL=debug` is set on a pod. Should the Datadog log pipeline be configured to ingest debug-level logs (with a filter or sampling policy)? 4. **Slow-request threshold tuning.** The 3000ms threshold for slow downstream request warnings is an initial value. Should this be configurable via environment variable, or is a hardcoded constant sufficient given that it can be changed with a code deployment?