refactor: unify server-side observability logging#293
refactor: unify server-side observability logging#293ben-fornefeld wants to merge 2 commits intomainfrom
Conversation
|
The latest updates on your projects. Learn more about Vercel for GitHub.
|
PR SummaryMedium Risk Overview Logs are now automatically enriched with Error handling tweaks: Reviewed by Cursor Bugbot for commit fd60dfe. Bugbot is set up for automated code reviews on this repo. Configure here. |
![chatgpt-codex-connector[bot]](https://avatars.githubusercontent.com/in/1144995?s=60&v=4){kind=small}
There was a problem hiding this comment.
💡 Codex Review
Here are some automated review suggestions for this pull request.
Reviewed commit: c2d901f037
ℹ️ About Codex in GitHub
Codex has been enabled to automatically review pull requests in this repo. Reviews are triggered when you
- Open a pull request for review
- Mark a draft as ready
- Comment "@codex review".
If Codex has suggestions, it will comment; otherwise it will react with 👍.
When you sign up for Codex through ChatGPT, Codex can also answer questions or update the PR, like "@codex address that feedback".
| session: undefined as Session | undefined, | ||
| user: undefined as User | undefined, | ||
| teamId: undefined as string | undefined, | ||
| requestObservability: undefined as RequestObservabilityContext | undefined, |
There was a problem hiding this comment.
createTRPCContext now accepts opts.requestObservability, but this return object immediately overwrites it with undefined, so every tRPC request loses the request-scoped metadata provided by src/app/api/trpc/[trpc]/route.ts and src/trpc/server.tsx. As a result, telemetry/logging in startTelemetryMiddleware always falls back to generic /api/trpc context instead of the actual originating path/handler, which breaks the new observability behavior this change is intended to add.
Useful? React with 👍 / 👎.
ben-fornefeld
changed the title
![cursor[bot]](https://avatars.githubusercontent.com/in/1210556?s=60&v=4){kind=small}
There was a problem hiding this comment.
Cursor Bugbot has reviewed your changes and found 1 potential issue.
❌ Bugbot Autofix is OFF. To automatically fix reported issues with cloud agents, enable autofix in the Cursor dashboard.
Reviewed by Cursor Bugbot for commit c2d901f. Configure here.
| session: undefined as Session | undefined, | ||
| user: undefined as User | undefined, | ||
| teamId: undefined as string | undefined, | ||
| requestObservability: undefined as RequestObservabilityContext | undefined, |
There was a problem hiding this comment.
tRPC context always discards requestObservability input
High Severity
createTRPCContext spreads opts (which includes requestObservability) but then explicitly overrides it with requestObservability: undefined. Since the explicit property comes after ...opts, the caller-provided observability context is always silently discarded. Both the HTTP route handler and the RSC caller compute and pass requestObservability, but it never reaches the telemetry middleware's ctx.requestObservability, which always falls back to a generic default. This defeats the core purpose of this PR for tRPC requests.
Additional Locations (2)
Reviewed by Cursor Bugbot for commit c2d901f. Configure here.
There was a problem hiding this comment.
Pull request overview
This PR unifies request-scoped server logging/observability across server actions, tRPC (RSC + HTTP), and route handlers by introducing a shared request observability context, while also preserving HTTP 400s as validation errors and improving repo error logging payloads.
Changes:
- Add a request observability context helper (derived from request/headers) and use it to prefix log messages with the originating request path.
- Update logger plumbing to enrich log context from the active OpenTelemetry context.
- Treat HTTP 400s as
validationRepoErrors and adjust repo error logging fields; add unit tests for both behaviors.
Reviewed changes
Copilot reviewed 12 out of 12 changed files in this pull request and generated 2 comments.
Show a summary per file
| File | Description |
|---|---|
| src/trpc/server.tsx | Adds request observability context to RSC tRPC context creation. |
| src/core/shared/errors.ts | Preserves HTTP 400 errors as validation repo errors. |
| src/core/shared/clients/logger/request-observability.ts | Introduces request observability context creation/propagation + message prefixing helper. |
| src/core/shared/clients/logger/logger.ts | Enriches log payloads/messages using request observability from OpenTelemetry context. |
| src/core/server/trpc/init.ts | Extends tRPC context shape to include optional request observability. |
| src/core/server/api/middlewares/telemetry.ts | Wraps tRPC middleware execution with request observability context. |
| src/core/server/adapters/errors.ts | Logs unobfuscated repo errors too; adds observed message + obfuscation metadata to payload. |
| src/core/server/actions/client.ts | Wraps action execution with request observability derived from Next headers; logs request path/url + team slug. |
| src/app/api/trpc/[trpc]/route.ts | Adds request observability context to HTTP tRPC route context creation. |
| src/app/api/teams/[teamSlug]/metrics/route.ts | Wraps route handler in request observability context. |
| src/test/unit/request-observability.test.ts | Adds unit tests for request context derivation and message prefix formatting. |
| src/test/unit/repo-error-from-http.test.ts | Adds unit tests for 400 validation handling and 500 obfuscation behavior. |
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
| session: undefined as Session | undefined, | ||
| user: undefined as User | undefined, | ||
| teamId: undefined as string | undefined, | ||
| requestObservability: undefined as RequestObservabilityContext | undefined, |
There was a problem hiding this comment.
createTRPCContext currently overwrites the passed opts.requestObservability by setting requestObservability: undefined after spreading opts. This makes ctx.requestObservability always undefined, so the new request-scoped logging context never propagates into tRPC middlewares. Remove the override or set requestObservability from opts so the value survives into ctx.
| requestObservability: undefined as RequestObservabilityContext | undefined, |
| return { | ||
| child(bindings: Record<string, unknown>) { | ||
| return baseLogger.child(bindings) | ||
| }, | ||
| fatal(context: ILoggerContext, message?: string, ...args: unknown[]) { | ||
| const enrichedContext = enrichLogContext(context) | ||
| baseLogger.fatal( | ||
| enrichedContext, | ||
| formatRequestLogMessage(message, enrichedContext), |
There was a problem hiding this comment.
This logger implementation assumes calls are always l.<level>(contextObj, message?, ...args), but the repo still contains pino-style call sites like l.info('step:...') and l.info('step:...', { ... }) (e.g. src/__test__/development/sandbox-events.test.ts, src/__test__/development/traffic.test.ts). With the current wrapper those will mis-handle arguments (string treated as context; object treated as message, leading to [object Object] and lost fields). Either add runtime argument-shape detection/overloads to keep pino-compatible call signatures, or update the remaining call sites to the { key, ... } + optional message pattern.
![claude[bot]](https://avatars.githubusercontent.com/in/1236702?s=60&v=4){kind=small}
| error: RepoError | ||
| ) { | ||
| const publicMessage = getPublicRepoErrorMessage(error) | ||
| if (publicMessage === error.message) { | ||
| return | ||
| } | ||
|
|
||
| const observedMessage = getObservedErrorMessage(error) | ||
| const span = trace.getActiveSpan() | ||
|
|
There was a problem hiding this comment.
🔴 Removing the early-return guard from logObfuscatedRepoError causes double-logging for all expected repo errors (validation, not_found, conflict): once in logObfuscatedRepoError itself and again in the downstream telemetry handler (endTelemetryMiddleware for tRPC, handleServerError for actions). The action transport produces three log entries per error. Consider keeping the guard and only adding the was_obfuscated/observed_message fields, or suppressing the downstream log when the transport adapter already logged.
Extended reasoning...
What the bug is and how it manifests
Before this PR, logObfuscatedRepoError contained an early-return guard: if (publicMessage === error.message) { return }. For validation, not_found, and conflict errors, getPublicRepoErrorMessage returns error.message unchanged, so the condition was always true and the function returned without logging. The single log entry came exclusively from the downstream telemetry handler. This PR removes the guard so logObfuscatedRepoError now always calls l.warn() for expected errors (via the isExpectedRepoError branch), and the downstream handlers still log as before — producing duplicates.
The specific code paths that trigger it
tRPC path: throwTRPCErrorFromRepoError -> logObfuscatedRepoError('trpc', error) -> l.warn with key 'transport:trpc:repo_error' (NEW). The thrown TRPCError(BAD_REQUEST/NOT_FOUND/CONFLICT) propagates to endTelemetryMiddleware, where isExpectedTRPCError() returns true -> l.warn with key 'trpc:procedure_failure' (pre-existing). Total: 2 entries (was 1).
Action path: toActionErrorFromRepoError -> logObfuscatedRepoError('action', error) -> l.warn key 'transport:action:repo_error' (NEW). ActionError(expected: true) caught by handleServerError -> l.warn key 'action_client:expected_server_error' (pre-existing). Middleware sees result.serverError -> l.warn key 'action_client:failure' (pre-existing). Total: 3 entries (was 2).
Why existing code does not prevent it
The telemetry handlers have no awareness that logObfuscatedRepoError already logged the same event at the transport adapter layer. Before the PR, the guard in logObfuscatedRepoError implicitly coordinated with them by staying silent for non-obfuscated errors. Removing the guard without suppressing the downstream logs breaks this implicit contract.
Addressing the refutations
Two refutations argue this is intentional design: (1) unauthorized/forbidden already double-logged before this PR, and (2) the two entries carry genuinely different context (repo-layer detail vs. procedure timing/input). Both points are fair. However, they describe a pre-existing accepted pattern for obfuscated errors where the transport-layer context adds real value — not necessarily a deliberate extension to unobfuscated errors where both logs emit the same public message. The PR description says 'log unobfuscated repo errors as warnings', which is achievable while keeping the guard — by adding was_obfuscated, observed_message, and transport fields before the early return rather than removing it.
What the impact is
Every validation failure (e.g., duplicate team member, invalid input) and every 404 now emits 2-3 warning log lines instead of 1-2. In production these are among the most common expected errors, so this materially inflates log volume and can obscure signal in dashboards or alerting thresholds that monitor warning rates.
Step-by-step proof
- Client calls a tRPC mutation that hits a duplicate-entry constraint in the repo layer.
- Repo returns RepoError{ code: 'conflict', message: 'Team member already exists', status: 409 }.
- throwTRPCErrorFromRepoError(error) is called.
- Inside: getPublicRepoErrorMessage(error) returns 'Team member already exists' (conflict -> returns error.message). isExpectedRepoError(error) returns true. l.warn({ key: 'transport:trpc:repo_error', was_obfuscated: false, ... }) fires. LOG ENTRY Refactor to Server Components #1.
- new TRPCError({ code: 'CONFLICT', message: 'Team member already exists' }) is thrown.
- endTelemetryMiddleware catches the failure: result.ok === false, isExpectedTRPCError(error) returns true for CONFLICT. l.warn({ key: 'trpc:procedure_failure', ... }) fires. LOG ENTRY Finalize MLP #2.
How to fix it
The minimal fix restores the guard while still capturing the new fields:
function logObfuscatedRepoError(transport, error) {
const publicMessage = getPublicRepoErrorMessage(error)
const observedMessage = getObservedErrorMessage(error)
const wasObfuscated = publicMessage !== error.message
if (!wasObfuscated) {
return // downstream telemetry handler will log; skip double-log
}
// ... log with was_obfuscated/observed_message/transport fields
}
Alternatively, accept the double log but remove the redundant downstream log when was_obfuscated === false.
| return { | ||
| ...opts, | ||
| session: undefined as Session | undefined, | ||
| user: undefined as User | undefined, | ||
| teamId: undefined as string | undefined, | ||
| requestObservability: undefined as RequestObservabilityContext | undefined, | ||
| } | ||
| } |
There was a problem hiding this comment.
🔴 In createTRPCContext (src/core/server/trpc/init.ts), the return object spreads ...opts (which carries the caller-supplied requestObservability) but then unconditionally overrides it with requestObservability: undefined on the last line—so ctx.requestObservability is always undefined. As a result, startTelemetryMiddleware always falls back to the hardcoded {request_path: '/api/trpc'} path instead of the rich referer-derived context that both callers (the HTTP tRPC route and the RSC caller) compute and pass in, defeating the core observability improvement this PR introduces. Fix: remove the explicit requestObservability: undefined line, since the value is already present via ...opts.
Extended reasoning...
What the bug is
In src/core/server/trpc/init.ts, createTRPCContext returns an object literal that first spreads ...opts and then explicitly sets requestObservability: undefined as RequestObservabilityContext | undefined as the last property. In JavaScript object literals, later properties silently win over earlier ones with the same key, so the spread value of opts.requestObservability is always thrown away regardless of what the caller passes.
The specific code path
// src/core/server/trpc/init.ts (lines 16–23)
return {
...opts, // ← opts.requestObservability spread here
session: undefined,
user: undefined,
teamId: undefined,
requestObservability: undefined as RequestObservabilityContext | undefined, // ← always wins
}Both callers compute a rich RequestObservabilityContext and pass it to createTRPCContext:
src/app/api/trpc/[trpc]/route.ts: callscreateRequestObservabilityContext({ requestUrl: req.headers.get('referer') ?? req.url, ... })src/trpc/server.tsx: callscreateRequestObservabilityContextFromHeaders(heads, { preferReferer: true, ... })
Both are silently discarded.
Why existing code doesn't prevent it
TypeScript's type annotation on the requestObservability line (as RequestObservabilityContext | undefined) was presumably added to ensure the return type includes that field for downstream type-checking, but the side-effect is that the runtime value is unconditionally set to undefined. There are no tests that verify the returned context actually carries through the caller's value.
Impact
In startTelemetryMiddleware (src/core/server/api/middlewares/telemetry.ts, lines 118–124):
const requestObservability =
ctx.requestObservability ??
({ request_path: '/api/trpc', transport: 'trpc', handler_name: procedurePath } as const)Because ctx.requestObservability is always undefined, the fallback is always used. Every tRPC log will show request_path: '/api/trpc' regardless of the actual page that triggered the request, making per-route log analysis impossible and defeating the stated goal of this PR.
Step-by-step proof
- A browser on page
/dashboard/acme/sandboxesmakes a tRPC mutation. - The browser attaches a
referer: https://app.example.com/dashboard/acme/sandboxesheader. - The HTTP route handler calls
createRequestObservabilityContext({ requestUrl: req.headers.get('referer') }), producing{ request_path: '/dashboard/acme/sandboxes', transport: 'trpc', handler_name: 'http' }. - It passes this as
requestObservabilitytocreateTRPCContext. - Inside
createTRPCContext, the spread captures it at keyrequestObservability. - The explicit
requestObservability: undefinedon the final line overwrites it. startTelemetryMiddlewarereceivesctx.requestObservability === undefinedand logsrequest_path: '/api/trpc'instead.
How to fix
Remove line 21 (requestObservability: undefined as RequestObservabilityContext | undefined) entirely. The field is already present via ...opts and TypeScript will infer the correct type from the parameter declaration. Alternatively, change it to requestObservability: opts.requestObservability to make the intent explicit.
Note on the duplicate refutation
One verifier argued this is a duplicate of bug_001. That concern is about review-process deduplication, not about whether the bug is real. The bug is clearly real and confirmed by three independent verifiers; the fix and impact are identical, but the bug itself is legitimate and worth flagging.
Summary
Testing
Notes
tsc --noEmitremains noisy because of pre-existing .next and route typing issues unrelated to this change