Skip to content

refactor: unify server-side observability logging #293

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
ben-fornefeld wants to merge 2 commits into
base: main
Choose a base branch
from
Open

refactor: unify server-side observability logging #293

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
c2d901f
Unify server observability logging
ben-fornefeld Apr 11, 2026
fd60dfe
Merge branch 'main' into fix/server-side-observability
ben-fornefeld Apr 11, 2026
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
24 changes: 24 additions & 0 deletions src/__test__/unit/repo-error-from-http.test.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,24 @@
import { describe, expect, it } from 'vitest'
import {
getPublicRepoErrorMessage,
PUBLIC_ERROR_MESSAGE_INTERNAL,
repoErrorFromHttp,
} from '@/core/shared/errors'

describe('repoErrorFromHttp', () => {
it('preserves 400 messages as validation errors', () => {
const error = repoErrorFromHttp(400, 'User is already part of this team.')

expect(error.code).toBe('validation')
expect(getPublicRepoErrorMessage(error)).toBe(
'User is already part of this team.'
)
})

it('still obfuscates unexpected internal errors', () => {
const error = repoErrorFromHttp(500, 'database exploded')

expect(error.code).toBe('unavailable')
expect(getPublicRepoErrorMessage(error)).toBe(PUBLIC_ERROR_MESSAGE_INTERNAL)
})
})
49 changes: 49 additions & 0 deletions src/__test__/unit/request-observability.test.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,49 @@
import { describe, expect, it } from 'vitest'
import {
createRequestObservabilityContext,
createRequestObservabilityContextFromHeaders,
formatRequestLogMessage,
} from '@/core/shared/clients/logger/request-observability'

describe('request observability', () => {
it('extracts request path from an absolute URL', () => {
const requestContext = createRequestObservabilityContext({
requestUrl: 'https://dashboard.test/dashboard/acme/sandboxes?tab=logs',
transport: 'action',
handlerName: 'addTeamMember',
})

expect(requestContext.request_path).toBe('/dashboard/acme/sandboxes')
expect(requestContext.transport).toBe('action')
expect(requestContext.handler_name).toBe('addTeamMember')
})

it('prefers referer when deriving browser-origin request context', () => {
const headers = new Headers({
origin: 'https://dashboard.test',
referer: 'https://dashboard.test/dashboard/acme/sandboxes',
'next-url': '/api/trpc',
})

const requestContext = createRequestObservabilityContextFromHeaders(
headers,
{
fallbackPath: '/server/actions/addTeamMember',
preferReferer: true,
}
)

expect(requestContext.request_url).toBe(
'https://dashboard.test/dashboard/acme/sandboxes'
)
expect(requestContext.request_path).toBe('/dashboard/acme/sandboxes')
})

it('prefixes log messages with the request path', () => {
expect(
formatRequestLogMessage('action addTeamMember failed', {
request_path: '/dashboard/acme/sandboxes',
})
).toBe('/dashboard/acme/sandboxes: action addTeamMember failed')
})
})
174 changes: 100 additions & 74 deletions src/app/api/teams/[teamSlug]/metrics/route.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4,86 +4,112 @@ import { getSessionInsecure } from '@/core/server/functions/auth/get-session'
import { getTeamMetricsCore } from '@/core/server/functions/sandboxes/get-team-metrics-core'
import { getTeamIdFromSlug } from '@/core/server/functions/team/get-team-id-from-slug'
import { l, serializeErrorForLog } from '@/core/shared/clients/logger/logger'
import { withRequestObservabilityFromRequest } from '@/core/shared/clients/logger/request-observability'
import { getPublicErrorMessage } from '@/core/shared/errors'
import { TeamMetricsRequestSchema, type TeamMetricsResponse } from './types'

export async function POST(
request: Request,
{ params }: { params: Promise<{ teamSlug: string }> }
) {
try {
const { teamSlug } = await params

const parsedInput = TeamMetricsRequestSchema.safeParse(await request.json())

if (!parsedInput.success) {
// should not happen
l.warn(
{
key: 'team_metrics_route_handler:invalid_request',
error: serializeErrorForLog(parsedInput.error),
team_slug: teamSlug,
context: {
request: parsedInput.data,
},
},
'team_metrics_route_handler: invalid request'
)

return Response.json({ error: 'Invalid request' }, { status: 400 })
return withRequestObservabilityFromRequest(
request,
{
fallbackPath: '/api/teams/[teamSlug]/metrics',
transport: 'route',
handlerName: 'teamMetricsRoute',
},
async () => {
try {
const { teamSlug } = await params

const parsedInput = TeamMetricsRequestSchema.safeParse(
await request.json()
)

if (!parsedInput.success) {
// should not happen
l.warn(
{
key: 'team_metrics_route_handler:invalid_request',
error: serializeErrorForLog(parsedInput.error),
team_slug: teamSlug,
context: {
request: parsedInput.data,
},
},
'team_metrics_route_handler: invalid request'
)

return Response.json({ error: 'Invalid request' }, { status: 400 })
}

const { start: startMs, end: endMs } = parsedInput.data

const session = await getSessionInsecure()

if (!session) {
l.warn(
{
key: 'team_metrics_route_handler:unauthenticated',
team_slug: teamSlug,
},
'team_metrics_route_handler: unauthenticated'
)

return Response.json({ error: 'Unauthenticated' }, { status: 401 })
}

const teamId = await getTeamIdFromSlug(teamSlug, session.access_token)

if (!teamId) {
l.warn(
{
key: 'team_metrics_route_handler:forbidden_team',
team_slug: teamSlug,
user_id: session.user.id,
},
'team_metrics_route_handler: forbidden team'
)

return Response.json({ error: 'Forbidden' }, { status: 403 })
}

const result = await getTeamMetricsCore({
accessToken: session.access_token,
teamId,
userId: session.user.id,
startMs,
endMs,
})

if (result.error) {
const safeMessage = getPublicErrorMessage({ status: result.status })
return Response.json(
{ error: safeMessage },
{ status: result.status }
)
}

if (!result.data) {
return Response.json(
{ error: 'Internal server error' },
{ status: 500 }
)
}

return Response.json(result.data satisfies TeamMetricsResponse)
} catch (error) {
l.error({
key: 'team_metrics_route_handler:unexpected_error',
error: serializeErrorForLog(error),
})

return Response.json(
{ error: 'Internal server error' },
{ status: 500 }
)
}
}

const { start: startMs, end: endMs } = parsedInput.data

const session = await getSessionInsecure()

if (!session) {
l.warn(
{
key: 'team_metrics_route_handler:unauthenticated',
team_slug: teamSlug,
},
'team_metrics_route_handler: unauthenticated'
)

return Response.json({ error: 'Unauthenticated' }, { status: 401 })
}

const teamId = await getTeamIdFromSlug(teamSlug, session.access_token)

if (!teamId) {
l.warn(
{
key: 'team_metrics_route_handler:forbidden_team',
team_slug: teamSlug,
user_id: session.user.id,
},
'team_metrics_route_handler: forbidden team'
)

return Response.json({ error: 'Forbidden' }, { status: 403 })
}

const result = await getTeamMetricsCore({
accessToken: session.access_token,
teamId,
userId: session.user.id,
startMs,
endMs,
})

if (result.error) {
const safeMessage = getPublicErrorMessage({ status: result.status })
return Response.json({ error: safeMessage }, { status: result.status })
}

return Response.json(result.data! satisfies TeamMetricsResponse)
} catch (error) {
l.error({
key: 'team_metrics_route_handler:unexpected_error',
error: serializeErrorForLog(error),
})

return Response.json({ error: 'Internal server error' }, { status: 500 })
}
)
}
7 changes: 7 additions & 0 deletions src/app/api/trpc/[trpc]/route.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -3,6 +3,7 @@ import type { NextRequest } from 'next/server'

import { trpcAppRouter } from '@/core/server/api/routers'
import { createTRPCContext } from '@/core/server/trpc/init'
import { createRequestObservabilityContext } from '@/core/shared/clients/logger/request-observability'

/**
* This wraps the `createTRPCContext` helper and provides the required context for the tRPC API when
Expand All @@ -11,6 +12,12 @@ import { createTRPCContext } from '@/core/server/trpc/init'
const createContext = async (req: NextRequest) => {
return createTRPCContext({
headers: req.headers,
requestObservability: createRequestObservabilityContext({
requestUrl: req.headers.get('referer') ?? req.url,
fallbackPath: '/api/trpc',
transport: 'trpc',
handlerName: 'http',
}),
})
}

Expand Down
30 changes: 25 additions & 5 deletions src/core/server/actions/client.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,5 +1,6 @@
import { context, SpanStatusCode, trace } from '@opentelemetry/api'
import type { Session, User } from '@supabase/supabase-js'
import { headers } from 'next/headers'
import { unauthorized } from 'next/navigation'
import { createMiddleware, createSafeActionClient } from 'next-safe-action'
import { z } from 'zod'
Expand All @@ -12,6 +13,10 @@ import { getSessionInsecure } from '@/core/server/functions/auth/get-session'
import getUserByToken from '@/core/server/functions/auth/get-user-by-token'
import { getTeamIdFromSlug } from '@/core/server/functions/team/get-team-id-from-slug'
import { l, serializeErrorForLog } from '@/core/shared/clients/logger/logger'
import {
createRequestObservabilityContextFromHeaders,
withRequestObservabilityContext,
} from '@/core/shared/clients/logger/request-observability'
import { createClient } from '@/core/shared/clients/supabase/server'
import { getTracer } from '@/core/shared/clients/tracer'
import { UnauthenticatedError, UnknownError } from '@/core/shared/errors'
Expand Down Expand Up @@ -105,14 +110,23 @@ export const actionClient = createSafeActionClient({
const name = actionOrFunctionName

const s = t.startSpan(`${type}:${name}`)
const headerStore = await headers()
const requestObservabilityContext =
createRequestObservabilityContextFromHeaders(headerStore, {
fallbackPath: `/server/${type}s/${name}`,
transport: type,
handlerName: name,
preferReferer: true,
})

const startTime = performance.now()

const result = await context.with(
trace.setSpan(context.active(), s),
async () => {
return next()
}
const result = await withRequestObservabilityContext(
requestObservabilityContext,
() =>
context.with(trace.setSpan(context.active(), s), async () => {
return next()
})
)

const duration = performance.now() - startTime
Expand All @@ -122,6 +136,9 @@ export const actionClient = createSafeActionClient({
server_function_name: name,
server_function_input: clientInput,
server_function_duration_ms: duration.toFixed(3),
request_url: requestObservabilityContext.request_url,
request_path: requestObservabilityContext.request_path,
team_slug: flattenClientInputValue(clientInput, 'teamSlug'),
team_id: flattenClientInputValue(clientInput, 'teamId'),
template_id: flattenClientInputValue(clientInput, 'templateId'),
sandbox_id: flattenClientInputValue(clientInput, 'sandboxId'),
Expand All @@ -137,6 +154,9 @@ export const actionClient = createSafeActionClient({
if (baseLogPayload.team_id) {
s.setAttribute('team_id', baseLogPayload.team_id)
}
if (baseLogPayload.team_slug) {
s.setAttribute('team_slug', baseLogPayload.team_slug)
}
if (baseLogPayload.template_id) {
s.setAttribute('template_id', baseLogPayload.template_id)
}
Expand Down
7 changes: 3 additions & 4 deletions src/core/server/adapters/errors.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -119,10 +119,6 @@ function logObfuscatedRepoError(
error: RepoError
) {
const publicMessage = getPublicRepoErrorMessage(error)
if (publicMessage === error.message) {
return
}

const observedMessage = getObservedErrorMessage(error)
const span = trace.getActiveSpan()

Comment on lines 119 to 124
Copy link
Copy Markdown

@claude claude bot Apr 11, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🔴 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

  1. Client calls a tRPC mutation that hits a duplicate-entry constraint in the repo layer.
  2. Repo returns RepoError{ code: 'conflict', message: 'Team member already exists', status: 409 }.
  3. throwTRPCErrorFromRepoError(error) is called.
  4. 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.
  5. new TRPCError({ code: 'CONFLICT', message: 'Team member already exists' }) is thrown.
  6. 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.

Expand All @@ -134,9 +130,12 @@ function logObfuscatedRepoError(

const payload = {
key: `transport:${transport}:repo_error`,
transport,
repo_error_code: error.code,
repo_error_status: error.status,
public_message: publicMessage,
observed_message: observedMessage,
was_obfuscated: publicMessage !== error.message,
error: serializeErrorForLog(error),
}

Expand Down
Loading
Loading