From c2d901f03769c78b50342817e1830576da6642be Mon Sep 17 00:00:00 2001 From: ben-fornefeld Date: Fri, 10 Apr 2026 19:04:35 -0700 Subject: [PATCH] Unify server observability logging --- .../unit/repo-error-from-http.test.ts | 24 +++ .../unit/request-observability.test.ts | 49 +++++ src/app/api/teams/[teamSlug]/metrics/route.ts | 174 ++++++++++-------- src/app/api/trpc/[trpc]/route.ts | 7 + src/core/server/actions/client.ts | 30 ++- src/core/server/adapters/errors.ts | 7 +- src/core/server/api/middlewares/telemetry.ts | 33 +++- src/core/server/trpc/init.ts | 7 +- src/core/shared/clients/logger/logger.ts | 78 +++++++- .../clients/logger/request-observability.ts | 148 +++++++++++++++ src/core/shared/errors.ts | 7 + src/trpc/server.tsx | 7 + 12 files changed, 478 insertions(+), 93 deletions(-) create mode 100644 src/__test__/unit/repo-error-from-http.test.ts create mode 100644 src/__test__/unit/request-observability.test.ts create mode 100644 src/core/shared/clients/logger/request-observability.ts diff --git a/src/__test__/unit/repo-error-from-http.test.ts b/src/__test__/unit/repo-error-from-http.test.ts new file mode 100644 index 000000000..9f554a930 --- /dev/null +++ b/src/__test__/unit/repo-error-from-http.test.ts @@ -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) + }) +}) diff --git a/src/__test__/unit/request-observability.test.ts b/src/__test__/unit/request-observability.test.ts new file mode 100644 index 000000000..c01aa5663 --- /dev/null +++ b/src/__test__/unit/request-observability.test.ts @@ -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') + }) +}) diff --git a/src/app/api/teams/[teamSlug]/metrics/route.ts b/src/app/api/teams/[teamSlug]/metrics/route.ts index bf1d7915a..4a625f8fa 100644 --- a/src/app/api/teams/[teamSlug]/metrics/route.ts +++ b/src/app/api/teams/[teamSlug]/metrics/route.ts @@ -4,6 +4,7 @@ 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' @@ -11,79 +12,104 @@ 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 }) - } + ) } diff --git a/src/app/api/trpc/[trpc]/route.ts b/src/app/api/trpc/[trpc]/route.ts index ee154b2c6..19c28e61f 100644 --- a/src/app/api/trpc/[trpc]/route.ts +++ b/src/app/api/trpc/[trpc]/route.ts @@ -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 @@ -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', + }), }) } diff --git a/src/core/server/actions/client.ts b/src/core/server/actions/client.ts index c57fe4b92..a13da934a 100644 --- a/src/core/server/actions/client.ts +++ b/src/core/server/actions/client.ts @@ -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' @@ -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' @@ -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 @@ -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'), @@ -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) } diff --git a/src/core/server/adapters/errors.ts b/src/core/server/adapters/errors.ts index 2a367419a..fd399292f 100644 --- a/src/core/server/adapters/errors.ts +++ b/src/core/server/adapters/errors.ts @@ -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() @@ -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), } diff --git a/src/core/server/api/middlewares/telemetry.ts b/src/core/server/api/middlewares/telemetry.ts index 67011e9cd..6b7b32638 100644 --- a/src/core/server/api/middlewares/telemetry.ts +++ b/src/core/server/api/middlewares/telemetry.ts @@ -18,6 +18,7 @@ import { } from '@/core/server/adapters/errors' import { t } from '@/core/server/trpc/init' import { l, serializeErrorForLog } from '@/core/shared/clients/logger/logger' +import { withRequestObservabilityContext } from '@/core/shared/clients/logger/request-observability' import { getMeter } from '@/core/shared/clients/meter' import { getTracer } from '@/core/shared/clients/tracer' @@ -114,14 +115,30 @@ export const startTelemetryMiddleware = t.middleware( } // execute within span context and pass telemetry state through - return context.with(trace.setSpan(context.active(), span), async () => { - return next({ - ctx: { - ...ctx, - telemetry: telemetryState, - }, - }) - }) + const requestObservability = + ctx.requestObservability ?? + ({ + request_path: '/api/trpc', + transport: 'trpc', + handler_name: procedurePath, + } as const) + + return withRequestObservabilityContext( + { + ...requestObservability, + transport: 'trpc', + handler_name: procedurePath, + }, + () => + context.with(trace.setSpan(context.active(), span), async () => { + return next({ + ctx: { + ...ctx, + telemetry: telemetryState, + }, + }) + }) + ) } ) diff --git a/src/core/server/trpc/init.ts b/src/core/server/trpc/init.ts index 016d01b65..5ea86f8ff 100644 --- a/src/core/server/trpc/init.ts +++ b/src/core/server/trpc/init.ts @@ -2,18 +2,23 @@ import type { Session, User } from '@supabase/supabase-js' import { initTRPC } from '@trpc/server' import superjson from 'superjson' import { flattenError, ZodError } from 'zod' +import type { RequestObservabilityContext } from '@/core/shared/clients/logger/request-observability' /** * TRPC Context Factory * * Factory function that creates a TRPC context. If a session exists, we are trying resolve the correct user data. */ -export const createTRPCContext = async (opts: { headers: Headers }) => { +export const createTRPCContext = async (opts: { + headers: Headers + requestObservability?: RequestObservabilityContext +}) => { return { ...opts, session: undefined as Session | undefined, user: undefined as User | undefined, teamId: undefined as string | undefined, + requestObservability: undefined as RequestObservabilityContext | undefined, } } diff --git a/src/core/shared/clients/logger/logger.ts b/src/core/shared/clients/logger/logger.ts index 4ed1f8f0e..82e965645 100644 --- a/src/core/shared/clients/logger/logger.ts +++ b/src/core/shared/clients/logger/logger.ts @@ -1,11 +1,20 @@ import pino, { type Logger } from 'pino' import { type ErrorObject, serializeError } from 'serialize-error' +import { + formatRequestLogMessage, + getRequestObservabilityContext, +} from './request-observability' interface PlatformContextKeys { team_id?: string + team_slug?: string user_id?: string sandbox_id?: string template_id?: string + request_url?: string + request_path?: string + transport?: string + handler_name?: string } interface ILoggerContext extends Record, PlatformContextKeys { @@ -76,6 +85,19 @@ const stripStackFields = ( export const serializeErrorForLog = (error: unknown): ErrorObject | unknown => stripStackFields(serializeError(error)) as ErrorObject +function enrichLogContext(context: ILoggerContext): ILoggerContext { + const requestContext = getRequestObservabilityContext() + + if (!requestContext) { + return context + } + + return { + ...requestContext, + ...context, + } +} + const createLogger = () => { const baseConfig = { redact: { @@ -85,7 +107,61 @@ const createLogger = () => { level: 'debug', } - return pino(baseConfig) + const baseLogger = pino(baseConfig) + + return { + child(bindings: Record) { + return baseLogger.child(bindings) + }, + fatal(context: ILoggerContext, message?: string, ...args: unknown[]) { + const enrichedContext = enrichLogContext(context) + baseLogger.fatal( + enrichedContext, + formatRequestLogMessage(message, enrichedContext), + ...args + ) + }, + error(context: ILoggerContext, message?: string, ...args: unknown[]) { + const enrichedContext = enrichLogContext(context) + baseLogger.error( + enrichedContext, + formatRequestLogMessage(message, enrichedContext), + ...args + ) + }, + warn(context: ILoggerContext, message?: string, ...args: unknown[]) { + const enrichedContext = enrichLogContext(context) + baseLogger.warn( + enrichedContext, + formatRequestLogMessage(message, enrichedContext), + ...args + ) + }, + info(context: ILoggerContext, message?: string, ...args: unknown[]) { + const enrichedContext = enrichLogContext(context) + baseLogger.info( + enrichedContext, + formatRequestLogMessage(message, enrichedContext), + ...args + ) + }, + debug(context: ILoggerContext, message?: string, ...args: unknown[]) { + const enrichedContext = enrichLogContext(context) + baseLogger.debug( + enrichedContext, + formatRequestLogMessage(message, enrichedContext), + ...args + ) + }, + trace(context: ILoggerContext, message?: string, ...args: unknown[]) { + const enrichedContext = enrichLogContext(context) + baseLogger.trace( + enrichedContext, + formatRequestLogMessage(message, enrichedContext), + ...args + ) + }, + } satisfies ILogger } export const logger: ILogger = createLogger() diff --git a/src/core/shared/clients/logger/request-observability.ts b/src/core/shared/clients/logger/request-observability.ts new file mode 100644 index 000000000..ee4cef73a --- /dev/null +++ b/src/core/shared/clients/logger/request-observability.ts @@ -0,0 +1,148 @@ +import { createContextKey, context as otelContext } from '@opentelemetry/api' + +type HeaderStore = Pick + +export type RequestObservabilityContext = { + request_url?: string + request_path?: string + transport?: string + handler_name?: string +} + +const REQUEST_OBSERVABILITY_CONTEXT_KEY = createContextKey( + 'request-observability-context' +) + +function safelyParseUrl(url: string): URL | null { + try { + return new URL(url) + } catch { + return null + } +} + +function deriveOriginFromHeaders(headers: HeaderStore): string | undefined { + const origin = headers.get('origin') + if (origin) { + return origin + } + + const host = headers.get('x-forwarded-host') ?? headers.get('host') + const proto = headers.get('x-forwarded-proto') ?? 'https' + + if (!host) { + return undefined + } + + return `${proto}://${host}` +} + +export function createRequestObservabilityContext(input: { + requestUrl?: string + requestPath?: string + fallbackPath?: string + transport?: string + handlerName?: string +}): RequestObservabilityContext { + const parsedUrl = input.requestUrl ? safelyParseUrl(input.requestUrl) : null + const requestPath = + input.requestPath ?? parsedUrl?.pathname ?? input.fallbackPath + + return { + request_url: parsedUrl?.toString() ?? input.requestUrl, + request_path: requestPath, + transport: input.transport, + handler_name: input.handlerName, + } +} + +export function createRequestObservabilityContextFromHeaders( + headers: HeaderStore, + input: { + requestUrl?: string + fallbackPath?: string + transport?: string + handlerName?: string + preferReferer?: boolean + } = {} +): RequestObservabilityContext { + const referer = headers.get('referer') ?? undefined + const nextUrl = headers.get('next-url') ?? undefined + const origin = deriveOriginFromHeaders(headers) + + const normalizedNextUrl = + nextUrl && !nextUrl.startsWith('http') && origin + ? `${origin}${nextUrl}` + : nextUrl + + const requestUrl = input.preferReferer + ? (referer ?? input.requestUrl ?? normalizedNextUrl) + : (input.requestUrl ?? normalizedNextUrl ?? referer) + const requestPath = + requestUrl === referer && referer + ? undefined + : nextUrl && !nextUrl.startsWith('http') + ? nextUrl + : undefined + + return createRequestObservabilityContext({ + requestUrl, + requestPath, + fallbackPath: input.fallbackPath, + transport: input.transport, + handlerName: input.handlerName, + }) +} + +export function getRequestObservabilityContext(): + | RequestObservabilityContext + | undefined { + const activeContext = otelContext.active() + + return activeContext.getValue(REQUEST_OBSERVABILITY_CONTEXT_KEY) as + | RequestObservabilityContext + | undefined +} + +export function withRequestObservabilityContext( + requestContext: RequestObservabilityContext, + fn: () => T +): T { + return otelContext.with( + otelContext + .active() + .setValue(REQUEST_OBSERVABILITY_CONTEXT_KEY, requestContext), + fn + ) +} + +export function withRequestObservabilityFromRequest( + request: Pick, + input: { + fallbackPath?: string + transport?: string + handlerName?: string + }, + fn: () => T +): T { + return withRequestObservabilityContext( + createRequestObservabilityContext({ + requestUrl: request.url, + fallbackPath: input.fallbackPath, + transport: input.transport, + handlerName: input.handlerName, + }), + fn + ) +} + +export function formatRequestLogMessage( + message: string | undefined, + requestContext: RequestObservabilityContext | undefined +): string | undefined { + if (!message || !requestContext?.request_path) { + return message + } + + return `${requestContext.request_path}: ${message}` +} diff --git a/src/core/shared/errors.ts b/src/core/shared/errors.ts index 23f0566e1..ba8ec2f1a 100644 --- a/src/core/shared/errors.ts +++ b/src/core/shared/errors.ts @@ -96,6 +96,13 @@ export function repoErrorFromHttp( cause?: unknown ): RepoError { switch (status) { + case 400: + return createRepoError({ + code: 'validation', + status, + message, + cause, + }) case 401: return createRepoError({ code: 'unauthorized', diff --git a/src/trpc/server.tsx b/src/trpc/server.tsx index 54ab40f24..43c37aecc 100644 --- a/src/trpc/server.tsx +++ b/src/trpc/server.tsx @@ -9,6 +9,7 @@ import { headers } from 'next/headers' import { cache } from 'react' import { createTRPCCaller, trpcAppRouter } from '@/core/server/api/routers' import { createTRPCContext } from '@/core/server/trpc/init' +import { createRequestObservabilityContextFromHeaders } from '@/core/shared/clients/logger/request-observability' import { createQueryClient } from './query-client' /** @@ -21,6 +22,12 @@ const createContext = cache(async () => { return createTRPCContext({ headers: heads, + requestObservability: createRequestObservabilityContextFromHeaders(heads, { + fallbackPath: '/trpc/rsc', + transport: 'trpc', + handlerName: 'rsc', + preferReferer: true, + }), }) })