From 723f0d6e6ecfd89b3b2afa22cab5d7203d703dd8 Mon Sep 17 00:00:00 2001 From: Hampus Date: Sun, 30 Aug 2026 22:15:40 +0200 Subject: [PATCH] perf(logger): stop building a throwaway pino root per child (#2132) --- .../src/api/auth/services/SsoService.ts | 33 +++++++++------- packages/logger/package.json | 6 ++- packages/logger/src/Logger.ts | 13 ++++--- packages/logger/src/__tests__/Logger.test.ts | 39 +++++++++++++++++++ packages/logger/vitest.config.ts | 27 +++++++++++++ pnpm-lock.yaml | 6 +++ 6 files changed, 105 insertions(+), 19 deletions(-) create mode 100644 packages/logger/src/__tests__/Logger.test.ts create mode 100644 packages/logger/vitest.config.ts diff --git a/fluxer_api/src/api/auth/services/SsoService.ts b/fluxer_api/src/api/auth/services/SsoService.ts index 5e519b086..6305ce86d 100644 --- a/fluxer_api/src/api/auth/services/SsoService.ts +++ b/fluxer_api/src/api/auth/services/SsoService.ts @@ -24,6 +24,7 @@ import { } from 'jose'; import type {ApiContext} from '../../ApiContext'; import type {UserID} from '../../BrandedTypes'; +import type {ILogger} from '../../ILogger'; import type {IDiscriminatorService} from '../../infrastructure/DiscriminatorService'; import type {KVActivityTracker} from '../../infrastructure/KVActivityTracker'; import { @@ -100,6 +101,13 @@ const STATE_BYTE_LENGTH = 16; const NONCE_BYTE_LENGTH = 16; const MOBILE_SSO_REDIRECT_URI = 'fluxer://auth/sso/callback'; +let ssoLogger: ILogger | undefined; + +function getLogger(): ILogger { + ssoLogger ??= Logger.child({logger: 'SsoService'}); + return ssoLogger; +} + function randomBase64UrlToken(byteLength: number): string { return randomBytes(byteLength).toString('base64url'); } @@ -235,7 +243,6 @@ function isJsonWebKeySet(value: unknown): value is JSONWebKeySet { } export class SsoService { - private readonly logger = Logger.child({logger: 'SsoService'}); private static readonly STATE_TTL_SECONDS = seconds('10 minutes'); private static readonly DISCOVERY_TTL_SECONDS = seconds('1 hour'); private static readonly JWKS_CACHE_TTL_MS = ms('1 hour'); @@ -344,12 +351,12 @@ export class SsoService { throw InputValidationError.fromCode('email_verified', ValidationErrorCodes.INVALID_SSO_TOKEN); } const emailLower = claims.email.toLowerCase(); - this.logger.info({email: emailLower, has_sub: true}, 'SSO login with sub claim'); + getLogger().info({email: emailLower, has_sub: true}, 'SSO login with sub claim'); const identityUserId = await this.ssoIdentityRepository.findUserId(config.providerId, claims.sub); if (identityUserId) { const user = await this.apiContext.services.users.findUnique(identityUserId); if (!user) { - this.logger.error( + getLogger().error( {user_id: identityUserId.toString()}, 'SSO identity mapping points at a missing user; refusing reassignment', ); @@ -401,7 +408,7 @@ export class SsoService { if (ownerId?.toString() === userId.toString()) { return; } - this.logger.error( + getLogger().error( {user_id: userId.toString(), owner_user_id: ownerId?.toString() ?? null}, 'SSO identity is already linked to another account', ); @@ -413,7 +420,7 @@ export class SsoService { const traits = user.traits; const existingIdentities = Array.from(traits).filter((trait) => trait.startsWith('sso_identity:')); if (existingIdentities.length > 0 && !traits.has(identityTrait)) { - this.logger.error({user_id: user.id.toString()}, 'SSO identity claim did not match linked account'); + getLogger().error({user_id: user.id.toString()}, 'SSO identity claim did not match linked account'); throw InputValidationError.fromCode('sub', ValidationErrorCodes.SSO_IDENTITY_MISMATCH); } await this.claimSsoIdentity(user.id, sub, config); @@ -534,13 +541,13 @@ export class SsoService { }), ); void this.kvActivityTracker.updateActivity(user.id, now).catch((error: unknown) => { - this.logger.warn({error, userId: user.id}, 'Failed to update real-time user activity'); + getLogger().warn({error, userId: user.id}, 'Failed to update real-time user activity'); }); return user; } catch (error) { if (!userCreated) { await this.ssoIdentityRepository.releaseIdentity(config.providerId, claims.sub).catch((releaseError) => { - this.logger.error({releaseError}, 'Failed to release SSO identity after user provisioning failed'); + getLogger().error({releaseError}, 'Failed to release SSO identity after user provisioning failed'); }); } throw error; @@ -567,7 +574,7 @@ export class SsoService { let claims: JWTPayload | null = null; if (tokenResponse.id_token) { if (!config.jwksUrl) { - this.logger.warn('SSO id_token returned but no JWKS URL is configured; ignoring id_token claims'); + getLogger().warn('SSO id_token returned but no JWKS URL is configured; ignoring id_token claims'); } else { claims = await this.verifyIdToken(tokenResponse.id_token, config, expectedNonce); } @@ -580,7 +587,7 @@ export class SsoService { const userInfoSub = userInfo ? readStringClaim(userInfo, 'sub') : undefined; if (claims && userInfo) { if (!idTokenSub || !userInfoSub || idTokenSub !== userInfoSub) { - this.logger.error('SSO sub mismatch between id_token and userinfo'); + getLogger().error('SSO sub mismatch between id_token and userinfo'); throw InputValidationError.fromCode('sub', ValidationErrorCodes.SSO_IDENTITY_MISMATCH); } } @@ -597,7 +604,7 @@ export class SsoService { const normalizedIdTokenEmail = idTokenEmail ? normalizeSsoEmail(idTokenEmail) : undefined; const normalizedUserInfoEmail = userInfoEmail ? normalizeSsoEmail(userInfoEmail) : undefined; if (normalizedIdTokenEmail && normalizedUserInfoEmail && normalizedIdTokenEmail !== normalizedUserInfoEmail) { - this.logger.error('SSO email mismatch between id_token and userinfo'); + getLogger().error('SSO email mismatch between id_token and userinfo'); throw InputValidationError.fromCode('email', ValidationErrorCodes.SSO_IDENTITY_MISMATCH); } const email = @@ -634,7 +641,7 @@ export class SsoService { }); const nonce = payload['nonce']; if (nonce === undefined) { - this.logger.warn('SSO id_token missing required nonce claim'); + getLogger().warn('SSO id_token missing required nonce claim'); throw new Error('nonce missing'); } if (typeof nonce !== 'string' || nonce.length === 0 || nonce !== expectedNonce) { @@ -644,7 +651,7 @@ export class SsoService { } return decodeJwt(idToken); } catch (error) { - this.logger.error({error}, 'Failed to verify SSO id_token'); + getLogger().error({error}, 'Failed to verify SSO id_token'); throw InputValidationError.fromCode('id_token', ValidationErrorCodes.INVALID_SSO_TOKEN); } } @@ -919,7 +926,7 @@ export class SsoService { try { return await this.assertPublicOutboundUrl(rawUrl, fieldName); } catch (error) { - this.logger.warn({fieldName, rawUrl, error}, 'Ignoring SSO URL that failed outbound policy validation'); + getLogger().warn({fieldName, rawUrl, error}, 'Ignoring SSO URL that failed outbound policy validation'); return null; } } diff --git a/packages/logger/package.json b/packages/logger/package.json index 638828646..2d64fefbd 100644 --- a/packages/logger/package.json +++ b/packages/logger/package.json @@ -4,6 +4,8 @@ "private": true, "type": "module", "scripts": { + "test": "vitest run", + "test:watch": "vitest", "typecheck": "tsgo --noEmit" }, "dependencies": { @@ -12,6 +14,8 @@ }, "devDependencies": { "@types/node": "catalog:", - "@typescript/native-preview": "catalog:" + "@typescript/native-preview": "catalog:", + "vite-tsconfig-paths": "catalog:", + "vitest": "catalog:" } } diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 21184cc86..8f6f4f694 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -111,8 +111,13 @@ function createPinoLogger(serviceName: string, options: LoggerOptions = {}): Pin export class Logger { private logger: PinoLogger; - constructor(serviceName: string, options: LoggerOptions = {}) { - this.logger = createPinoLogger(serviceName, options); + constructor(serviceName: string, options?: LoggerOptions); + constructor(pinoLogger: PinoLogger); + constructor(serviceNameOrPinoLogger: string | PinoLogger, options: LoggerOptions = {}) { + this.logger = + typeof serviceNameOrPinoLogger === 'string' + ? createPinoLogger(serviceNameOrPinoLogger, options) + : serviceNameOrPinoLogger; } getPinoLogger(): PinoLogger { @@ -124,9 +129,7 @@ export class Logger { } static createWithLogger(logger: PinoLogger): Logger { - const childLogger = new Logger('', {}); - childLogger.setPinoLogger(logger); - return childLogger; + return new Logger(logger); } trace(obj: Record, msg?: string): void; diff --git a/packages/logger/src/__tests__/Logger.test.ts b/packages/logger/src/__tests__/Logger.test.ts new file mode 100644 index 000000000..2e3ae9d6b --- /dev/null +++ b/packages/logger/src/__tests__/Logger.test.ts @@ -0,0 +1,39 @@ +// SPDX-License-Identifier: AGPL-3.0-or-later + +import {createLogger, Logger} from '@fluxer/logger/src/Logger'; +import pino, {type Logger as PinoLogger} from 'pino'; +import {afterEach, describe, expect, it, vi} from 'vitest'; + +function readDestination(logger: PinoLogger): unknown { + return (logger as unknown as Record)[pino.symbols.streamSym]; +} + +describe('Logger.child', () => { + afterEach(() => { + vi.restoreAllMocks(); + vi.unstubAllEnvs(); + }); + + it('shares the parent destination instead of opening a new one', () => { + const parent = createLogger('logger-test', {environment: 'production'}); + const child = parent.child({logger: 'ChildService'}); + expect(child).toBeInstanceOf(Logger); + expect(readDestination(child.pino)).toBe(readDestination(parent.pino)); + }); + + it('does not construct a throwaway pino root logger', () => { + vi.stubEnv('FLUXER_ENV', 'production'); + const parent = createLogger('logger-test', {environment: 'production'}); + const destinationSpy = vi.spyOn(pino, 'destination'); + const child = parent.child({logger: 'ChildService'}); + expect(destinationSpy).not.toHaveBeenCalled(); + expect(child.pino.bindings()['logger']).toBe('ChildService'); + }); + + it('keeps the parent bindings on the child', () => { + const parent = createLogger('logger-test', {environment: 'production'}); + const child = parent.child({logger: 'ChildService'}); + expect(child.pino.bindings()['service']).toBe('logger-test'); + expect(child.pino.level).toBe(parent.pino.level); + }); +}); diff --git a/packages/logger/vitest.config.ts b/packages/logger/vitest.config.ts new file mode 100644 index 000000000..08796abc6 --- /dev/null +++ b/packages/logger/vitest.config.ts @@ -0,0 +1,27 @@ +// SPDX-License-Identifier: AGPL-3.0-or-later + +import path from 'node:path'; +import {fileURLToPath} from 'node:url'; +import tsconfigPaths from 'vite-tsconfig-paths'; +import {defineConfig} from 'vitest/config'; + +const __dirname = path.dirname(fileURLToPath(import.meta.url)); + +export default defineConfig({ + plugins: [ + tsconfigPaths({ + root: path.resolve(__dirname, '../..'), + }), + ], + test: { + globals: true, + environment: 'node', + include: ['**/*.{test,spec}.{ts,tsx}'], + exclude: ['node_modules', 'dist'], + coverage: { + provider: 'v8', + reporter: ['text', 'json', 'html'], + exclude: ['**/*.test.tsx', '**/*.spec.tsx', 'node_modules/'], + }, + }, +}); diff --git a/pnpm-lock.yaml b/pnpm-lock.yaml index 792f2871a..d1e89db1d 100644 --- a/pnpm-lock.yaml +++ b/pnpm-lock.yaml @@ -1991,6 +1991,12 @@ importers: '@typescript/native-preview': specifier: 'catalog:' version: 7.0.0-dev.20260224.1 + vite-tsconfig-paths: + specifier: 'catalog:' + version: 6.1.1(typescript@5.9.3)(vite@7.3.1(@types/node@25.3.0)(jiti@2.6.1)(lightningcss@1.31.1)(tsx@4.21.0)(yaml@2.8.2)) + vitest: + specifier: 'catalog:' + version: 4.0.18(@opentelemetry/api@1.9.0)(@types/node@25.3.0)(@vitest/browser-playwright@4.0.18)(happy-dom@20.7.0)(jiti@2.6.1)(jsdom@28.1.0)(lightningcss@1.31.1)(msw@2.12.10(@types/node@25.3.0)(typescript@5.9.3))(tsx@4.21.0)(yaml@2.8.2) packages/openapi: dependencies: