From 6ccf893443a6a279e9a7bd08404e9a53d2a9566b Mon Sep 17 00:00:00 2001 From: ferhat elmas Date: Fri, 24 Apr 2026 13:39:05 +0200 Subject: [PATCH] fix: drop creating a child logger per req Signed-off-by: ferhat elmas --- src/http/plugins/db.ts | 30 ++++++-- src/http/plugins/log-request.test.ts | 16 ++++ src/http/plugins/log-request.ts | 15 +++- src/http/plugins/tenant-id.test.ts | 74 +++++++++++++++++++ src/http/plugins/tenant-id.ts | 25 +------ src/http/plugins/tracing.ts | 3 + src/http/routes/admin/jwks.ts | 5 +- src/http/routes/admin/objects.ts | 12 ++- src/http/routes/tus/index.ts | 6 +- src/http/routes/tus/lifecycle.test.ts | 10 +++ src/http/routes/tus/lifecycle.ts | 22 ++++-- src/internal/monitoring/logger.ts | 29 ++++---- src/start/server.ts | 2 +- src/storage/events/lifecycle/webhook.ts | 2 +- src/storage/events/objects/backup-object.ts | 4 +- .../objects/object-admin-delete-all-before.ts | 2 +- .../events/objects/object-admin-delete.ts | 2 +- 17 files changed, 192 insertions(+), 67 deletions(-) create mode 100644 src/http/plugins/tenant-id.test.ts diff --git a/src/http/plugins/db.ts b/src/http/plugins/db.ts index 49145388b..5931033a0 100644 --- a/src/http/plugins/db.ts +++ b/src/http/plugins/db.ts @@ -67,8 +67,11 @@ export const db = fastifyPlugin( request.db.dispose().catch((e) => { logSchema.error(request.log, 'Error disposing db connection', { type: 'db-connection', - error: e, + tenantId: request.tenantId, + project: request.tenantId, + reqId: request.id, sbReqId: request.sbReqId, + error: e, }) }) } @@ -80,8 +83,11 @@ export const db = fastifyPlugin( request.db.dispose().catch((e) => { logSchema.error(request.log, 'Error disposing db connection', { type: 'db-connection', - error: e, + tenantId: request.tenantId, + project: request.tenantId, + reqId: request.id, sbReqId: request.sbReqId, + error: e, }) }) } @@ -92,8 +98,11 @@ export const db = fastifyPlugin( request.db.dispose().catch((e) => { logSchema.error(request.log, 'Error disposing db connection', { type: 'db-connection', - error: e, + tenantId: request.tenantId, + project: request.tenantId, + reqId: request.id, sbReqId: request.sbReqId, + error: e, }) }) } @@ -139,8 +148,11 @@ export const dbSuperUser = fastifyPlugin( request.db.dispose().catch((e) => { logSchema.error(request.log, 'Error disposing db connection', { type: 'db-connection', - error: e, + tenantId: request.tenantId, + project: request.tenantId, + reqId: request.id, sbReqId: request.sbReqId, + error: e, }) }) } @@ -153,8 +165,11 @@ export const dbSuperUser = fastifyPlugin( request.db.dispose().catch((e) => { logSchema.error(request.log, 'Error disposing db connection', { type: 'db-connection', - error: e, + tenantId: request.tenantId, + project: request.tenantId, + reqId: request.id, sbReqId: request.sbReqId, + error: e, }) }) } @@ -165,8 +180,11 @@ export const dbSuperUser = fastifyPlugin( request.db.dispose().catch((e) => { logSchema.error(request.log, 'Error disposing db connection', { type: 'db-connection', - error: e, + tenantId: request.tenantId, + project: request.tenantId, + reqId: request.id, sbReqId: request.sbReqId, + error: e, }) }) } diff --git a/src/http/plugins/log-request.test.ts b/src/http/plugins/log-request.test.ts index 662d41d39..07c6f90a0 100644 --- a/src/http/plugins/log-request.test.ts +++ b/src/http/plugins/log-request.test.ts @@ -27,6 +27,7 @@ describe('log-request plugin', () => { lines = [] app = createApp(lines) + app.decorateRequest('tenantId', 'tenant-a') await app.register(requestContext) await app.register(logRequest({})) @@ -100,4 +101,19 @@ describe('log-request plugin', () => { expect(requestLogLine).toContain('"sbReqId":"sb-req-123"') expect(requestLogLine).not.toContain('"request_id"') }) + + it('threads tenant context into the request log data', async () => { + const response = await app.inject({ + method: 'GET', + url: '/request-log', + }) + + expect(response.statusCode).toBe(200) + + const requestLogLine = lines.find((line) => line.includes('"type":"request"')) + + expect(requestLogLine).toBeDefined() + expect(requestLogLine).toContain('"tenantId":"tenant-a"') + expect(requestLogLine).toContain('"project":"tenant-a"') + }) }) diff --git a/src/http/plugins/log-request.ts b/src/http/plugins/log-request.ts index 7f77445d5..0eab99f4f 100644 --- a/src/http/plugins/log-request.ts +++ b/src/http/plugins/log-request.ts @@ -178,16 +178,22 @@ function doRequestLog(req: FastifyRequest, options: LogRequestOptions) { // do nothing logSchema.warning(req.log, 'Failed to serialize log metadata', { type: 'otel', - error: e, + tenantId, + project: tenantId, + reqId: rId, sbReqId: req.sbReqId, + error: e, }) } } } catch (e) { logSchema.error(req.log, 'Failed to get log metadata', { type: 'request', - error: e, + tenantId, + project: tenantId, + reqId: rId, sbReqId: req.sbReqId, + error: e, }) } } @@ -196,6 +202,10 @@ function doRequestLog(req: FastifyRequest, options: LogRequestOptions) { logSchema.request(req.log, buildLogMessage, { type: 'request', + tenantId, + project: tenantId, + reqId: rId, + sbReqId: req.sbReqId, req, reqMetadata, res: options.reply, @@ -207,6 +217,5 @@ function doRequestLog(req: FastifyRequest, options: LogRequestOptions) { resources: req.resources, operation: req.operation?.type ?? req.routeOptions.config.operation?.type, serverTimes: req.serverTimings, - sbReqId: req.sbReqId, }) } diff --git a/src/http/plugins/tenant-id.test.ts b/src/http/plugins/tenant-id.test.ts new file mode 100644 index 000000000..3bc41ae7e --- /dev/null +++ b/src/http/plugins/tenant-id.test.ts @@ -0,0 +1,74 @@ +import Fastify, { type FastifyInstance, type FastifyRequest } from 'fastify' +import { getConfig } from '../../config' +import { adminTenantId, tenantId } from './tenant-id' + +const { tenantId: defaultTenantId } = getConfig() + +function failOnRequestChildLogger(app: FastifyInstance) { + app.addHook('onRequest', async (request: FastifyRequest) => { + request.log.child = (() => { + throw new Error('request.log.child should not be called by the tenant id plugin') + }) as typeof request.log.child + }) +} + +describe('tenant id plugins', () => { + it('does not create an extra request child logger for API requests', async () => { + const app = Fastify() + + failOnRequestChildLogger(app) + await app.register(tenantId) + app.get('/status', async () => ({ ok: true })) + + try { + const response = await app.inject({ + method: 'GET', + url: '/status', + }) + + expect(response.statusCode).toBe(200) + } finally { + await app.close() + } + }) + + it('does not create an extra request child logger for admin requests', async () => { + const app = Fastify() + + failOnRequestChildLogger(app) + await app.register(adminTenantId) + app.get('/tenants/:tenantId', async (request) => ({ tenantId: request.tenantId })) + + try { + const response = await app.inject({ + method: 'GET', + url: '/tenants/tenant-a', + }) + + expect(response.statusCode).toBe(200) + expect(response.json()).toEqual({ tenantId: 'tenant-a' }) + } finally { + await app.close() + } + }) + + it('sets the default tenant id for admin requests without tenant params', async () => { + const app = Fastify() + + failOnRequestChildLogger(app) + await app.register(adminTenantId) + app.get('/status', async (request) => ({ tenantId: request.tenantId })) + + try { + const response = await app.inject({ + method: 'GET', + url: '/status', + }) + + expect(response.statusCode).toBe(200) + expect(response.json()).toEqual({ tenantId: defaultTenantId }) + } finally { + await app.close() + } + }) +}) diff --git a/src/http/plugins/tenant-id.ts b/src/http/plugins/tenant-id.ts index bba564914..36c26ade3 100644 --- a/src/http/plugins/tenant-id.ts +++ b/src/http/plugins/tenant-id.ts @@ -7,12 +7,7 @@ declare module 'fastify' { } } -const { - version, - isMultitenant, - tenantId: defaultTenantId, - requestXForwardedHostRegExp, -} = getConfig() +const { isMultitenant, tenantId: defaultTenantId, requestXForwardedHostRegExp } = getConfig() export const tenantId = fastifyPlugin( async (fastify) => { @@ -26,35 +21,19 @@ export const tenantId = fastifyPlugin( request.tenantId = result[1] }) - - fastify.addHook('onRequest', async (request, reply) => { - reply.log = request.log = request.log.child({ - tenantId: request.tenantId, - project: request.tenantId, - reqId: request.id, - appVersion: version, - }) - }) }, { name: 'tenant-id' } ) export const adminTenantId = fastifyPlugin( async (fastify) => { + fastify.decorateRequest('tenantId', defaultTenantId) fastify.addHook('onRequest', async (request) => { const tenantId = (request.params as Record).tenantId if (!tenantId) return request.tenantId = tenantId }) - - fastify.addHook('onRequest', async (request, reply) => { - reply.log = request.log = request.log.child({ - tenantId: request.tenantId, - project: request.tenantId, - reqId: request.id, - }) - }) }, { name: 'admin-tenant-id' } ) diff --git a/src/http/plugins/tracing.ts b/src/http/plugins/tracing.ts index fd291fa3f..5ffcdf5b1 100644 --- a/src/http/plugins/tracing.ts +++ b/src/http/plugins/tracing.ts @@ -43,6 +43,9 @@ export const tracing = fastifyPlugin( logSchema.error(request.log, 'failed setting tracing mode', { error: e, type: 'tracing', + tenantId: request.tenantId, + project: request.tenantId, + reqId: request.id, sbReqId: request.sbReqId, }) } diff --git a/src/http/routes/admin/jwks.ts b/src/http/routes/admin/jwks.ts index 8ccdefabd..657e1df77 100644 --- a/src/http/routes/admin/jwks.ts +++ b/src/http/routes/admin/jwks.ts @@ -170,8 +170,11 @@ export default async function routes(fastify: FastifyInstance) { }).catch((e) => { logSchema.error(request.log, 'Error generating url signing jwks for all tenants', { type: 'jwk-generator', - error: e, + tenantId: request.tenantId, + project: request.tenantId, + reqId: request.id, sbReqId: request.sbReqId, + error: e, }) }) return reply.send({ started: true }) diff --git a/src/http/routes/admin/objects.ts b/src/http/routes/admin/objects.ts index 310629e16..e7bf48c32 100644 --- a/src/http/routes/admin/objects.ts +++ b/src/http/routes/admin/objects.ts @@ -124,10 +124,12 @@ export default async function routes(fastify: FastifyInstance) { } catch (e) { logSchema.error(req.log, 'list orphaned objects stream failed', { type: 'orphan', + tenantId: req.tenantId, + project: req.tenantId, + reqId: req.id, + sbReqId: req.sbReqId, error: e, - project: req.params.tenantId, metadata: JSON.stringify({ bucket }), - sbReqId: req.sbReqId, }) writeNdjson(reply, { event: 'error', @@ -190,10 +192,12 @@ export default async function routes(fastify: FastifyInstance) { } catch (e) { logSchema.error(req.log, 'delete orphaned objects stream failed', { type: 'orphan', + tenantId: req.tenantId, + project: req.tenantId, + reqId: req.id, + sbReqId: req.sbReqId, error: e, - project: req.params.tenantId, metadata: JSON.stringify({ bucket }), - sbReqId: req.sbReqId, }) writeNdjson(reply, { event: 'error', diff --git a/src/http/routes/tus/index.ts b/src/http/routes/tus/index.ts index 3024692e5..4e8921952 100644 --- a/src/http/routes/tus/index.ts +++ b/src/http/routes/tus/index.ts @@ -246,11 +246,12 @@ const authenticatedRoutes = fastifyPlugin( fastify.addHook('preHandler', async (req) => { ;(req.raw as MultiPartRequest).log = req.log ;(req.raw as MultiPartRequest).upload = { + tenantId: req.tenantId, storage: req.storage, owner: req.owner, - tenantId: req.tenantId, db: req.db, isUpsert: req.headers['x-upsert'] === 'true', + reqId: req.id, sbReqId: req.sbReqId, } }) @@ -349,11 +350,12 @@ export const publicRoutes = fastifyPlugin( fastify.addHook('preHandler', async (req) => { ;(req.raw as MultiPartRequest).log = req.log ;(req.raw as MultiPartRequest).upload = { + tenantId: req.tenantId, storage: req.storage, owner: req.owner, - tenantId: req.tenantId, db: req.db, isUpsert: req.headers['x-upsert'] === 'true', + reqId: req.id, sbReqId: req.sbReqId, } }) diff --git a/src/http/routes/tus/lifecycle.test.ts b/src/http/routes/tus/lifecycle.test.ts index d1fd78f9d..0cf37f518 100644 --- a/src/http/routes/tus/lifecycle.test.ts +++ b/src/http/routes/tus/lifecycle.test.ts @@ -39,6 +39,7 @@ function createRawTusRequest({ location: {}, }, tenantId: 'tenant-123', + reqId: 'req-123', sbReqId, }, url: '/upload/resumable', @@ -79,6 +80,9 @@ describe('tus lifecycle logging', () => { expect(errorSpy).toHaveBeenCalledWith(reqLog, 'Error disposing db connection', { type: 'db-connection', + tenantId: 'tenant-123', + project: 'tenant-123', + reqId: 'req-123', error, sbReqId: 'sb-req-123', }) @@ -97,6 +101,9 @@ describe('tus lifecycle logging', () => { expect(warningSpy).toHaveBeenCalledWith(reqLog, 'Failed to parse upload metadata', { type: 'tus', + tenantId: 'tenant-123', + project: 'tenant-123', + reqId: 'req-123', error: expect.any(Error), sbReqId: 'sb-req-123', }) @@ -117,6 +124,9 @@ describe('tus lifecycle logging', () => { expect(canUploadSpy).toHaveBeenCalledOnce() expect(warningSpy).toHaveBeenCalledWith(reqLog, 'Failed to parse user metadata', { type: 'tus', + tenantId: 'tenant-123', + project: 'tenant-123', + reqId: 'req-123', error: expect.any(Error), sbReqId: 'sb-req-123', }) diff --git a/src/http/routes/tus/lifecycle.ts b/src/http/routes/tus/lifecycle.ts index 1a995af23..843fa0756 100644 --- a/src/http/routes/tus/lifecycle.ts +++ b/src/http/routes/tus/lifecycle.ts @@ -1,6 +1,6 @@ import { TenantConnection } from '@internal/database' import { ERRORS, isRenderableError } from '@internal/errors' -import { logSchema } from '@internal/monitoring' +import { logSchema, RequestLogContext } from '@internal/monitoring' import { UploadId } from '@storage/protocols/tus' import { Storage } from '@storage/storage' import { Uploader, validateMimeType } from '@storage/uploader' @@ -34,14 +34,13 @@ function getNodeRequest(rawReq: Request): MultiPartRequest { export type MultiPartRequest = http.IncomingMessage & { executionError?: Error log: FastifyBaseLogger - upload: { + upload: RequestLogContext & { + tenantId: string storage: Storage db: TenantConnection owner?: string - tenantId: string isUpsert: boolean resources?: string[] - sbReqId?: string } } @@ -70,8 +69,11 @@ export async function onIncomingRequest(rawReq: Request, id: string, datastore: req.upload.db.dispose().catch((e) => { logSchema.error(req.log, 'Error disposing db connection', { type: 'db-connection', - error: e, + tenantId: req.upload.tenantId, + project: req.upload.tenantId, + reqId: req.upload.reqId, sbReqId: req.upload.sbReqId, + error: e, }) }) }) @@ -123,8 +125,11 @@ export async function onIncomingRequest(rawReq: Request, id: string, datastore: } catch (e) { logSchema.warning(req.log, 'Failed to parse upload metadata', { type: 'tus', - error: e, + tenantId: req.upload.tenantId, + project: req.upload.tenantId, + reqId: req.upload.reqId, sbReqId: req.upload.sbReqId, + error: e, }) throw ERRORS.InvalidParameter('upload-metadata', { error: e as Error, @@ -148,8 +153,11 @@ export async function onIncomingRequest(rawReq: Request, id: string, datastore: } catch (e) { logSchema.warning(req.log, 'Failed to parse user metadata', { type: 'tus', - error: e, + tenantId: req.upload.tenantId, + project: req.upload.tenantId, + reqId: req.upload.reqId, sbReqId: req.upload.sbReqId, + error: e, }) } } diff --git a/src/internal/monitoring/logger.ts b/src/internal/monitoring/logger.ts index 3655146e0..116e1671a 100644 --- a/src/internal/monitoring/logger.ts +++ b/src/internal/monitoring/logger.ts @@ -12,6 +12,7 @@ const { logflareEnabled, logflareBatchSize, region, + version: appVersion, } = getConfig() export const baseLogger = pino({ @@ -61,13 +62,20 @@ export const baseLogger = pino({ timestamp: pino.stdTimeFunctions.isoTime, }) -export let logger = baseLogger.child({ region }) +export let logger = baseLogger.child({ region, appVersion }) export function setLogger(newLogger: Logger) { logger = newLogger } -export interface RequestLog { +export interface RequestLogContext { + tenantId?: string + project?: string + reqId?: string + sbReqId?: string +} + +export interface RequestLog extends RequestLogContext { type: 'request' req: FastifyRequest res?: FastifyReply @@ -80,35 +88,26 @@ export interface RequestLog { operation?: string resources?: string[] serverTimes?: { spanName: string; duration: number }[] - sbReqId?: string } -export interface EventLog { - jodId: string +export interface EventLog extends RequestLogContext { + jobId: string type: 'event' event: string payload: string objectPath: string - tenantId: string - project: string resources?: string[] - reqId?: string - sbReqId?: string } -interface ErrorLog { +interface ErrorLog extends RequestLogContext { type: string error?: Error | unknown - project?: string metadata?: string - sbReqId?: string } -interface InfoLog { +interface InfoLog extends RequestLogContext { type: string - project?: string metadata?: string - sbReqId?: string } export const logSchema = { diff --git a/src/start/server.ts b/src/start/server.ts index b0e23f7e9..e2c27ed52 100644 --- a/src/start/server.ts +++ b/src/start/server.ts @@ -236,7 +236,7 @@ async function httpAdminServer( try { await adminApp.listen({ port: adminPort, host, signal }) } catch (err) { - logSchema.error(adminApp.log, 'Failed to start admin app', { + logSchema.error(logger, 'Failed to start admin app', { type: 'adminAppStartError', error: err, }) diff --git a/src/storage/events/lifecycle/webhook.ts b/src/storage/events/lifecycle/webhook.ts index 5fe6d2ad8..a82352e63 100644 --- a/src/storage/events/lifecycle/webhook.ts +++ b/src/storage/events/lifecycle/webhook.ts @@ -147,7 +147,7 @@ export class Webhook extends BaseEvent { const path = `${job.data.tenant.ref}/${payload.bucketId}/${payload.name}` logSchema.event(logger, `[Lifecycle]: ${job.data.event.type} ${path}`, { - jodId: job.id, + jobId: job.id, type: 'event', event: job.data.event.type, payload: JSON.stringify(job.data.event.payload), diff --git a/src/storage/events/objects/backup-object.ts b/src/storage/events/objects/backup-object.ts index 184021d8b..884b83169 100644 --- a/src/storage/events/objects/backup-object.ts +++ b/src/storage/events/objects/backup-object.ts @@ -56,7 +56,7 @@ export class BackupObjectEvent extends BaseEvent { try { logSchema.event(logger, `[Admin]: BackupObject ${s3Key}`, { - jodId: job.id, + jobId: job.id, type: 'event', event: 'BackupObject', payload: JSON.stringify(job.data), @@ -78,7 +78,7 @@ export class BackupObjectEvent extends BaseEvent { if (job.data.deleteOriginal) { logSchema.event(logger, `[Admin]: DeleteOriginalObject ${s3Key}`, { - jodId: job.id, + jobId: job.id, type: 'event', event: 'BackupObject', payload: JSON.stringify(job.data), diff --git a/src/storage/events/objects/object-admin-delete-all-before.ts b/src/storage/events/objects/object-admin-delete-all-before.ts index fd178bee3..c8c941cd8 100644 --- a/src/storage/events/objects/object-admin-delete-all-before.ts +++ b/src/storage/events/objects/object-admin-delete-all-before.ts @@ -45,7 +45,7 @@ export class ObjectAdminDeleteAllBefore extends BaseEvent { }) logSchema.event(logger, `[Admin]: ObjectAdminDelete ${s3Key}`, { - jodId: job.id, + jobId: job.id, type: 'event', event: 'ObjectAdminDelete', payload: JSON.stringify(job.data),