diff --git a/backend/security/package.json b/backend/security/package.json index 53215eaf..26e4ad43 100644 --- a/backend/security/package.json +++ b/backend/security/package.json @@ -28,7 +28,8 @@ "permitio": "^2.7.4", "pg": "^8.11.5", "uuid": "^9.0.1", - "zod": "3.22.4" + "zod": "3.22.4", + "pino": "^9.5.0" }, "devDependencies": { "@types/bcrypt": "^5.0.2", diff --git a/backend/security/src/lib/logger.ts b/backend/security/src/lib/logger.ts new file mode 100644 index 00000000..ed556e4d --- /dev/null +++ b/backend/security/src/lib/logger.ts @@ -0,0 +1,73 @@ +/** + * Shared structured logger for the security-service. + * + * Auth-critical code (password login, OIDC brokering, broker codes, API + * tokens, org provisioning, authz) previously logged via raw `console.*` with + * no level control and no redaction — a credential or auth code could end up + * in plaintext logs, and there was no way to turn on per-hop DEBUG detail in + * prod without a redeploy. This wraps `pino`: + * - level from `LOG_LEVEL` (default `info`); set `LOG_LEVEL=debug` to get + * per-hop detail without a rebuild. + * - JSON output, ISO timestamps. + * - mandatory redaction of common credential/secret shapes. + * + * Use `logger.child({ reqId })` (see `withReqId`) to correlate every log line + * within a request with the `[security-service:xxxx]` id already assigned by + * `@fuzefront/core`'s `createExpressApp` (req.requestId). + */ +import pino from 'pino' + +const REDACT_PATHS = [ + 'password', + 'req.body.password', + 'req.body.currentPassword', + 'req.body.newPassword', + '*.password', + '*.currentPassword', + '*.newPassword', + 'token', + 'access_token', + 'refresh_token', + 'id_token', + 'code', + 'client_secret', + 'clientSecret', + 'codeVerifier', + 'code_verifier', + 'authorization', + 'req.headers.authorization', + 'req.headers.cookie', + 'headers.cookie', + 'headers.Cookie', + 'cookie', + 'Cookie', + 'set-cookie', + '*.token', + '*.access_token', + '*.refresh_token', + '*.id_token', + '*.code', + '*.client_secret', + '*.clientSecret', + '*.codeVerifier', + '*.code_verifier', + '*.authorization', + '*.cookie', +] + +export const logger = pino({ + level: process.env.LOG_LEVEL || 'info', + timestamp: pino.stdTimeFunctions.isoTime, + redact: { + paths: REDACT_PATHS, + censor: '[REDACTED]', + }, + base: { service: 'security-service' }, +}) + +/** Bind a per-request child logger to the `[security-service:xxxx]` request id. */ +export function withReqId(reqId?: string) { + return logger.child({ reqId: reqId || 'unknown' }) +} + +export default logger diff --git a/backend/security/src/routes/authz.ts b/backend/security/src/routes/authz.ts index 12255805..b64fe463 100644 --- a/backend/security/src/routes/authz.ts +++ b/backend/security/src/routes/authz.ts @@ -13,6 +13,7 @@ import express, { Request, Response } from 'express' import { getIdentityProvider } from '../providers/factory' import { getAuthorizationProvider } from '../providers/authzFactory' import type { AuthzQuery } from '../providers/AuthorizationProvider' +import { withReqId } from '../lib/logger' const router = express.Router() @@ -25,12 +26,21 @@ function bearer(req: Request): string | null { /** Resolve the caller from the bearer token, or null (→ 401). */ async function caller(req: Request): Promise<{ id: string } | null> { + const log = withReqId((req as any).requestId) const token = bearer(req) - if (!token) return null + if (!token) { + log.debug('authz: caller resolution failed — no bearer token') + return null + } try { const { user } = await getIdentityProvider().getUserInfo(token) - return user?.id ? { id: user.id } : null - } catch { + if (!user?.id) { + log.warn('authz: caller resolution failed — token valid but no user id') + return null + } + return { id: user.id } + } catch (err) { + log.warn({ err: (err as Error).message }, 'authz: caller resolution failed — token validation error') return null } } @@ -56,12 +66,27 @@ function toQuery(body: any, callerId: string): AuthzQuery | null { // ── Decisions ───────────────────────────────────────────────────────────── router.post('/authz/check', async (req: Request, res: Response) => { + const log = withReqId((req as any).requestId) const c = await caller(req) if (!c) return unauthorized(res) const q = toQuery(req.body, c.id) if (!q) return res.status(400).json({ error: 'Malformed query', code: 'MALFORMED' }) - const allow = await getAuthorizationProvider().check(q) - res.status(200).json({ allow }) + const start = Date.now() + try { + const allow = await getAuthorizationProvider().check(q) + log.info( + { subject: q.subject, tenant: q.tenant, resourceType: q.resource.type, action: q.action, allow, elapsedMs: Date.now() - start }, + 'authz: check decided' + ) + res.status(200).json({ allow }) + } catch (err) { + // Fail-closed: provider errors never grant. Logged with context for triage. + log.error( + { subject: q.subject, tenant: q.tenant, action: q.action, err: (err as Error).message }, + 'authz: check errored — denying' + ) + throw err + } }) /** diff --git a/backend/security/src/services/api-token.ts b/backend/security/src/services/api-token.ts index 7412ee1d..7908a341 100644 --- a/backend/security/src/services/api-token.ts +++ b/backend/security/src/services/api-token.ts @@ -19,6 +19,7 @@ import crypto from 'crypto' import { db as defaultDb } from '../config/database' import { permitSchema } from '../permit/schema' +import { logger } from '../lib/logger' import type { Knex } from 'knex' // --------------------------------------------------------------------------- @@ -194,6 +195,18 @@ export async function createToken( .insert(row) .returning(['id', 'token_prefix', 'name', 'scopes', 'expires_at', 'created_at']) + // token_prefix is explicitly SAFE to log (see file header); raw/hash never are. + logger.info( + { + tokenId: inserted.id, + tokenPrefix: inserted.token_prefix, + ownerType: params.ownerType, + ownerId: params.ownerId, + scopes: params.scopes, + }, + 'api-token: token created' + ) + return { id: inserted.id, token: raw, // raw returned ONCE; never stored @@ -218,7 +231,10 @@ export async function verifyToken( dbInstance: Knex = defaultDb as unknown as Knex ): Promise { const parts = extractParts(rawToken) - if (!parts) return { status: 'invalid' } + if (!parts) { + logger.debug('api-token: verify invalid — unparseable token shape') + return { status: 'invalid' } + } const { prefix, body } = parts @@ -226,11 +242,20 @@ export async function verifyToken( .where({ token_prefix: prefix }) .first() - if (!row) return { status: 'invalid' } + if (!row) { + logger.debug({ tokenPrefix: prefix }, 'api-token: verify invalid — unknown prefix') + return { status: 'invalid' } + } - if (row.revoked_at != null) return { status: 'revoked' } + if (row.revoked_at != null) { + logger.info({ tokenPrefix: prefix, tokenId: row.id }, 'api-token: verify rejected — revoked') + return { status: 'revoked' } + } - if (row.expires_at != null && row.expires_at <= new Date()) return { status: 'expired' } + if (row.expires_at != null && row.expires_at <= new Date()) { + logger.info({ tokenPrefix: prefix, tokenId: row.id }, 'api-token: verify rejected — expired') + return { status: 'expired' } + } // Constant-time hash comparison. // Both hashes are always 64-hex chars (256-bit SHA-256), so lengths are equal. @@ -239,6 +264,7 @@ export async function verifyToken( const computedHash = hashToken(`${prefix}.${body}`) if (storedHash.length !== computedHash.length) { + logger.error({ tokenPrefix: prefix }, 'api-token: verify invalid — hash length mismatch') return { status: 'invalid' } } @@ -247,7 +273,12 @@ export async function verifyToken( Buffer.from(computedHash, 'hex') ) - if (!match) return { status: 'invalid' } + if (!match) { + logger.info({ tokenPrefix: prefix }, 'api-token: verify invalid — hash mismatch') + return { status: 'invalid' } + } + + logger.debug({ tokenPrefix: prefix, tokenId: row.id }, 'api-token: verify valid') // Return the row without token_hash exposed; parse scopes from jsonb string const { token_hash: _omit, ...safeRow } = row as any @@ -269,6 +300,7 @@ export async function revokeToken( .whereNull('revoked_at') .update({ revoked_at: new Date() }) + logger.info({ tokenId, revoked: count > 0 }, 'api-token: revoke') return count > 0 } diff --git a/backend/security/src/services/authentikPassword.ts b/backend/security/src/services/authentikPassword.ts index 0e374ea8..c28ac335 100644 --- a/backend/security/src/services/authentikPassword.ts +++ b/backend/security/src/services/authentikPassword.ts @@ -24,6 +24,7 @@ import { generators } from 'openid-client' import { oidcService } from './oidc' import { User } from '../types/shared' +import { logger } from '../lib/logger' /** * Hard per-fetch timeout (ms) for EVERY server-side Authentik HTTP hop driven in @@ -62,8 +63,9 @@ async function fetchWithTimeout( } catch (err) { const e = err as Error if (e.name === 'AbortError') { - console.error( - `[authentikPassword] ${label} TIMEOUT after ${since(started)}ms (limit ${timeoutMs}ms) url=${url}` + logger.error( + { label, elapsedMs: since(started), timeoutMs, url }, + 'authentikPassword: hop timed out' ) throw new AuthentikUnavailableError( `${label} timed out after ${timeoutMs}ms` @@ -207,8 +209,9 @@ export async function flowRequest( `Authentik unreachable at ${base}: ${(err as Error).message}` ) } - console.log( - `[authentikPassword] flow.step slug=${slug} hop=${hop} ${method} -> ${res.status} in ${since(stepStart)}ms` + logger.debug( + { slug, hop, method, status: res.status, elapsedMs: since(stepStart) }, + 'authentikPassword: flow.step' ) jar.absorb(res) @@ -271,6 +274,33 @@ function challengeHasCredentialErrors(challenge: FlowChallenge): boolean { export async function authentikPasswordLogin( email: string, password: string +): Promise { + const loginStart = Date.now() + logger.info({ email }, 'authentikPassword: login start') + try { + const user = await authentikPasswordLoginInner(email, password) + logger.info( + { email, elapsedMs: since(loginStart) }, + 'authentikPassword: login succeeded' + ) + return user + } catch (err) { + logger.error( + { + email, + elapsedMs: since(loginStart), + errName: (err as Error).name, + err: (err as Error).message, + }, + 'authentikPassword: login failed' + ) + throw err + } +} + +async function authentikPasswordLoginInner( + email: string, + password: string ): Promise { if (!oidcService.isConfigured() || !oidcService.isInitialized()) { throw new AuthentikUnavailableError('OIDC is not configured/initialized') @@ -333,6 +363,31 @@ export async function authentikPasswordLogin( * same session). Token exchange + user sync is identical to the redirect * callback path — Authentik stays the SOLE identity authority. */ +/** + * Rewrite the (browser-facing, EXTERNAL) authorize URL onto the internal + * Authentik base — protocol+host only, path/query untouched — so this + * server-side hop stays in-cluster instead of hairpinning out through + * Cloudflare/ingress. Safe because: + * - `redirect_uri`/`state`/PKCE params are unchanged, so token validation + * (handleCallback) still matches. + * - Authentik's issuer_mode is `per_provider`, so `iss` is fixed to the + * external issuer regardless of request host (see oidc.ts). + * Measured impact: authorize.hop ~6.5s (external, via Cloudflare) -> ~0.2s + * (internal service DNS). `base` already resolves to AUTHENTIK_BASE_URL when + * set (see authentikBaseUrl()); this is a no-op when it is not. + */ +function toInternalAuthorizeUrl(externalUrl: string, base: string): string { + try { + const u = new URL(externalUrl) + const b = new URL(base) + u.protocol = b.protocol + u.host = b.host + return u.toString() + } catch { + return externalUrl + } +} + export async function completeOidcWithSession( base: string, jar: CookieJar @@ -341,7 +396,7 @@ export async function completeOidcWithSession( const { url: authorizeUrl, codeVerifier } = oidcService.generateAuthUrl(state) const target = redirectUri() - let location = authorizeUrl + let location = toInternalAuthorizeUrl(authorizeUrl, base) let code: string | null = null let returnedState: string | null = null const oidcStart = Date.now() @@ -365,8 +420,9 @@ export async function completeOidcWithSession( `Authorize request failed: ${(err as Error).message}` ) } - console.log( - `[authentikPassword] authorize.hop hop=${hop} -> ${res.status} in ${since(hopStart)}ms` + logger.debug( + { hop, status: res.status, elapsedMs: since(hopStart) }, + 'authentikPassword: authorize.hop' ) jar.absorb(res) @@ -406,8 +462,9 @@ export async function completeOidcWithSession( ) } - console.log( - `[authentikPassword] authorize chain resolved to code in ${since(oidcStart)}ms; entering token exchange` + logger.info( + { elapsedMs: since(oidcStart) }, + 'authentikPassword: authorize chain resolved to code; entering token exchange' ) // Token exchange + user sync — identical to the redirect callback path. return oidcService.handleCallback(code, returnedState || state, codeVerifier) @@ -443,6 +500,30 @@ export interface AuthentikSignupInput { * (e.g. an email-verification stage) fails closed as unsupported server-side. */ export async function authentikSignup(input: AuthentikSignupInput): Promise { + const signupStart = Date.now() + logger.info({ email: input.email }, 'authentikPassword: signup start') + try { + const user = await authentikSignupInner(input) + logger.info( + { email: input.email, elapsedMs: since(signupStart) }, + 'authentikPassword: signup succeeded' + ) + return user + } catch (err) { + logger.error( + { + email: input.email, + elapsedMs: since(signupStart), + errName: (err as Error).name, + err: (err as Error).message, + }, + 'authentikPassword: signup failed' + ) + throw err + } +} + +async function authentikSignupInner(input: AuthentikSignupInput): Promise { if (!oidcService.isConfigured() || !oidcService.isInitialized()) { throw new AuthentikUnavailableError('OIDC is not configured/initialized') } diff --git a/backend/security/src/services/brokerCodes.ts b/backend/security/src/services/brokerCodes.ts index 59e74fd2..62515b38 100644 --- a/backend/security/src/services/brokerCodes.ts +++ b/backend/security/src/services/brokerCodes.ts @@ -17,6 +17,7 @@ * In-memory + single-use + short TTL; a code is redeemed at most once. */ import type { BrokeredUser } from '../providers/IdentityProvider' +import { logger } from '../lib/logger' export interface BrokerCodeEntry { token: string @@ -30,20 +31,40 @@ const store = new Map() export function putBrokerCode(code: string, entry: BrokerCodeEntry): void { store.set(code, entry) + // Never log the code/token themselves (pino redaction also strips these + // keys if it ever changes shape) — only correlation metadata. + logger.debug( + { sessionId: entry.sessionId, expiresAt: entry.expiresAt }, + 'brokerCodes: code issued' + ) } /** Redeem a code exactly once; returns null when unknown/expired. */ export function takeBrokerCode(code: string, now = Date.now()): BrokerCodeEntry | null { const entry = store.get(code) - if (!entry) return null + if (!entry) { + logger.debug('brokerCodes: redeem miss — unknown code') + return null + } store.delete(code) // single-use - if (entry.expiresAt < now) return null + if (entry.expiresAt < now) { + logger.info({ sessionId: entry.sessionId }, 'brokerCodes: redeem miss — expired code') + return null + } + logger.debug({ sessionId: entry.sessionId }, 'brokerCodes: redeemed') return entry } /** Sweep never-redeemed expired codes. */ export function sweepBrokerCodes(now = Date.now()): void { + let swept = 0 for (const [code, entry] of store) { - if (entry.expiresAt < now) store.delete(code) + if (entry.expiresAt < now) { + store.delete(code) + swept++ + } + } + if (swept > 0) { + logger.debug({ swept }, 'brokerCodes: swept expired codes') } } diff --git a/backend/security/src/services/googleOidc.ts b/backend/security/src/services/googleOidc.ts index c366335e..618ce07e 100644 --- a/backend/security/src/services/googleOidc.ts +++ b/backend/security/src/services/googleOidc.ts @@ -14,6 +14,7 @@ * Nothing above the `IdentityProvider` boundary sees a vendor name. */ import { Issuer, Client, generators, custom } from 'openid-client' +import { logger } from '../lib/logger' /** * HTTP timeout for every server-side Google call (discovery, token grant, @@ -73,21 +74,33 @@ export class GoogleOidcService { } async initialize(): Promise { + const start = Date.now() if (!this.isConfigured()) { // Fail-closed: without client credentials there is no Google broker. + logger.info('googleOidc: not configured — Google sign-in disabled') throw new Error('GOOGLE_CLIENT_ID / GOOGLE_CLIENT_SECRET are not configured') } - custom.setHttpOptionsDefaults({ timeout: HTTP_TIMEOUT_MS }) - const issuer = await Issuer.discover(GOOGLE_ISSUER) - this.client = new issuer.Client({ - client_id: this.config.clientId, - client_secret: this.config.clientSecret, - redirect_uris: [this.config.redirectUri], - response_types: ['code'], - grant_types: ['authorization_code'], - // Google signs id_tokens with RS256; openid-client validates the signature - // against Google's JWKS automatically on callback. - }) + logger.info('googleOidc: initialize start') + try { + custom.setHttpOptionsDefaults({ timeout: HTTP_TIMEOUT_MS }) + const issuer = await Issuer.discover(GOOGLE_ISSUER) + this.client = new issuer.Client({ + client_id: this.config.clientId, + client_secret: this.config.clientSecret, + redirect_uris: [this.config.redirectUri], + response_types: ['code'], + grant_types: ['authorization_code'], + // Google signs id_tokens with RS256; openid-client validates the signature + // against Google's JWKS automatically on callback. + }) + logger.info({ elapsedMs: Date.now() - start }, 'googleOidc: initialize succeeded') + } catch (err) { + logger.error( + { elapsedMs: Date.now() - start, err: (err as Error).message }, + 'googleOidc: initialize failed' + ) + throw err + } } /** Build the absolute `accounts.google.com` authorize URL + this flow's PKCE verifier. */ @@ -112,24 +125,39 @@ export class GoogleOidcService { * Never logs tokens. Throws on any protocol/validation failure (fail-closed). */ async handleCallback(code: string, state: string, codeVerifier: string): Promise { - if (!this.client) throw new Error('Google OIDC client not initialized') - if (!codeVerifier) throw new Error('code_verifier missing for Google callback') - const tokenSet = await this.client.callback( - this.config.redirectUri, - { code, state }, - { code_verifier: codeVerifier, state } - ) - const claims = tokenSet.claims() - const email = claims.email - if (!email || typeof email !== 'string') { - throw new Error('Google id_token did not include an email claim') - } - return { - email, - emailVerified: claims.email_verified === true || (claims as any).email_verified === 'true', - firstName: (claims.given_name as string | undefined) ?? undefined, - lastName: (claims.family_name as string | undefined) ?? undefined, - sub: claims.sub, + const start = Date.now() + logger.info('googleOidc: callback start') + try { + if (!this.client) throw new Error('Google OIDC client not initialized') + if (!codeVerifier) throw new Error('code_verifier missing for Google callback') + const tokenSet = await this.client.callback( + this.config.redirectUri, + { code, state }, + { code_verifier: codeVerifier, state } + ) + const claims = tokenSet.claims() + const email = claims.email + if (!email || typeof email !== 'string') { + throw new Error('Google id_token did not include an email claim') + } + logger.info( + { elapsedMs: Date.now() - start }, + 'googleOidc: callback succeeded' + ) + return { + email, + emailVerified: claims.email_verified === true || (claims as any).email_verified === 'true', + firstName: (claims.given_name as string | undefined) ?? undefined, + lastName: (claims.family_name as string | undefined) ?? undefined, + sub: claims.sub, + } + } catch (err) { + // Never log `code`/tokens — only the error message, which never carries them. + logger.error( + { elapsedMs: Date.now() - start, err: (err as Error).message }, + 'googleOidc: callback failed' + ) + throw err } } } diff --git a/backend/security/src/services/oidc.ts b/backend/security/src/services/oidc.ts index 9fc528fe..1701dc04 100644 --- a/backend/security/src/services/oidc.ts +++ b/backend/security/src/services/oidc.ts @@ -2,6 +2,7 @@ import { Issuer, Client, generators, custom } from 'openid-client'; import { db } from '../config/database'; import { User } from '../types/shared'; import { defaultEventPublisher } from './eventPublisher'; +import { logger } from '../lib/logger'; /** * HTTP timeout for every server-side OIDC call (discovery, token grant, userinfo, @@ -33,7 +34,7 @@ class OIDCService { async initialize(): Promise { try { - console.log('🔧 Initializing OIDC client...'); + logger.info('oidc: initializing client'); // Raise openid-client's HTTP timeout. Its default is 3500ms, which is too // short for Authentik's token endpoint and silently broke Google sign-in: @@ -49,7 +50,7 @@ class OIDCService { // Discover the issuer const issuer = await Issuer.discover(this.config.issuerUrl); - console.log('✅ Discovered issuer:', issuer.metadata.issuer); + logger.info({ issuer: issuer.metadata.issuer }, 'oidc: discovered issuer'); // Route the SERVER-SIDE OIDC calls (token / userinfo / jwks) over in-cluster // DNS instead of hairpinning out to app.fuzefront.com via Cloudflare (which @@ -86,7 +87,7 @@ class OIDCService { introspection_endpoint: toInternal(issuer.metadata.introspection_endpoint as string | undefined), revocation_endpoint: toInternal(issuer.metadata.revocation_endpoint as string | undefined), }); - console.log('✅ OIDC server-side endpoints routed in-cluster via', internalBase); + logger.info({ internalBase }, 'oidc: server-side endpoints routed in-cluster'); } // Create the client @@ -101,9 +102,9 @@ class OIDCService { id_token_signed_response_alg: 'HS256', }); - console.log('✅ OIDC client initialized successfully'); + logger.info('oidc: client initialized successfully'); } catch (error) { - console.error('❌ Failed to initialize OIDC client:', error); + logger.error({ err: (error as Error).message }, 'oidc: failed to initialize client'); throw error; } } @@ -156,27 +157,30 @@ class OIDCService { { code, state }, { code_verifier: codeVerifier, state } ); - console.log( - `✅ oidc.token exchange completed in ${Math.round(Date.now() - tokenStart)}ms` + logger.info( + { elapsedMs: Math.round(Date.now() - tokenStart) }, + 'oidc: token exchange completed' ); // Get user info const userinfoStart = Date.now(); const userinfo = await this.client.userinfo(tokenSet.access_token!); - console.log( - `✅ oidc.userinfo retrieved in ${Math.round(Date.now() - userinfoStart)}ms for ${userinfo.email}` + logger.info( + { elapsedMs: Math.round(Date.now() - userinfoStart), email: userinfo.email }, + 'oidc: userinfo retrieved' ); // Sync user to local database const syncStart = Date.now(); const user = await this.syncUserToDatabase(userinfo); - console.log( - `✅ user.sync completed in ${Math.round(Date.now() - syncStart)}ms` + logger.info( + { elapsedMs: Math.round(Date.now() - syncStart) }, + 'oidc: user sync completed' ); return user; } catch (error) { - console.error('❌ OIDC callback error:', error); + logger.error({ err: (error as Error).message }, 'oidc: callback error'); throw error; } } @@ -240,7 +244,7 @@ export async function syncUserToDatabase(userinfo: any): Promise { updated_at: new Date(), }); - console.log(`✅ Updated existing user: ${email}`); + logger.debug({ email }, 'oidc: updated existing user'); } else { // Create new user. The local `id` is ALWAYS a generated uuid — never the // OIDC `sub`, which Authentik sets to the email/username (not a uuid) and @@ -280,7 +284,7 @@ export async function syncUserToDatabase(userinfo: any): Promise { }); userRow = newUser; - console.log(`✅ Created new user: ${email}`); + logger.info({ email, userId: newUser.id }, 'oidc: created new user'); // Best-effort publish; failure leaves the outbox row 'pending' for replay. try { @@ -298,7 +302,10 @@ export async function syncUserToDatabase(userinfo: any): Promise { .where({ correlation_id: correlationId }) .update({ status: 'sent', attempts: 1, sent_at: new Date() }); } catch (pubErr) { - console.error('⚠️ identity.user.created publish failed (outbox retains it):', pubErr); + logger.error( + { email, userId: newUser.id, correlationId, err: (pubErr as Error).message }, + 'oidc: identity.user.created publish failed (outbox retains it)' + ); } } @@ -319,7 +326,7 @@ export async function syncUserToDatabase(userinfo: any): Promise { return user; } catch (error) { - console.error('❌ Error syncing user to database:', error); + logger.error({ err: (error as Error).message }, 'oidc: error syncing user to database'); throw error; } } diff --git a/backend/security/src/services/organizationProvisioning.ts b/backend/security/src/services/organizationProvisioning.ts index cb1d2f9e..3d1720ce 100644 --- a/backend/security/src/services/organizationProvisioning.ts +++ b/backend/security/src/services/organizationProvisioning.ts @@ -9,6 +9,7 @@ import { defaultEventPublisher, } from './eventPublisher' import type { Knex } from 'knex' +import { logger } from '../lib/logger' /** * Plan B — tenant provisioning that is correct, idempotent, and self-healing. @@ -107,7 +108,11 @@ export async function ensurePersonalOrg( const existing = await db('organizations') .where({ owner_id: userId, type: 'personal' }) .first() - if (existing) return rowToOrganization(existing) + if (existing) { + logger.debug({ userId, orgId: existing.id }, 'organizationProvisioning: personal org already exists') + return rowToOrganization(existing) + } + logger.info({ userId }, 'organizationProvisioning: creating personal org') const user = await db('users').where({ id: userId }).first() if (!user) throw new Error(`Cannot create personal org: user ${userId} not found`) @@ -148,10 +153,15 @@ export async function ensurePersonalOrg( const raced = await db('organizations') .where({ owner_id: userId, type: 'personal' }) .first() - if (raced) return rowToOrganization(raced) + if (raced) { + logger.info({ userId, orgId: raced.id }, 'organizationProvisioning: personal org create raced — using winner') + return rowToOrganization(raced) + } + logger.error({ userId, err: error?.message }, 'organizationProvisioning: personal org create failed') throw error } + logger.info({ userId, orgId }, 'organizationProvisioning: personal org created') const created = await db('organizations').where({ id: orgId }).first() return rowToOrganization(created) } @@ -244,6 +254,8 @@ export async function reconcileOrganizationProvisioning( ): Promise<'active' | 'pending' | 'failed'> { const deps = getDeps(overrides) const { db } = deps + const reconcileStart = Date.now() + logger.info({ orgId }, 'organizationProvisioning: reconcile start') // I2 — serialize concurrent reconciles of the same org with a Postgres // advisory transaction lock so two concurrent callers never both execute the @@ -280,8 +292,13 @@ export async function reconcileOrganizationProvisioning( last_error: null, updated_at: new Date(), }) + logger.debug({ orgId, step }, 'organizationProvisioning: step done') } catch (error: any) { anyFailed = true + logger.error( + { orgId, step, attempts: (row?.attempts || 0) + 1, err: String(error?.message ?? error) }, + 'organizationProvisioning: step failed' + ) await trx('organization_provisioning') .where({ organization_id: orgId, step }) .update({ @@ -312,6 +329,10 @@ export async function reconcileOrganizationProvisioning( .where({ id: orgId }) .update({ provisioning_state: newState, updated_at: new Date() }) + logger.info( + { orgId, newState, elapsedMs: Date.now() - reconcileStart }, + 'organizationProvisioning: reconcile end' + ) return newState }) } diff --git a/package-lock.json b/package-lock.json index 66d2a84c..0dfa4e0c 100644 --- a/package-lock.json +++ b/package-lock.json @@ -423,6 +423,86 @@ "express": "4 || 5 || ^5.0.0-beta.1" } }, + "backend/node_modules/pino": { + "version": "9.14.0", + "resolved": "https://registry.npmjs.org/pino/-/pino-9.14.0.tgz", + "integrity": "sha512-8OEwKp5juEvb/MjpIc4hjqfgCNysrS94RIOMXYvpYCdm/jglrKEiAYmiumbmGhCvs+IcInsphYDFwqrjr7398w==", + "license": "MIT", + "dependencies": { + "@pinojs/redact": "^0.4.0", + "atomic-sleep": "^1.0.0", + "on-exit-leak-free": "^2.1.0", + "pino-abstract-transport": "^2.0.0", + "pino-std-serializers": "^7.0.0", + "process-warning": "^5.0.0", + "quick-format-unescaped": "^4.0.3", + "real-require": "^0.2.0", + "safe-stable-stringify": "^2.3.1", + "sonic-boom": "^4.0.1", + "thread-stream": "^3.0.0" + }, + "bin": { + "pino": "bin.js" + } + }, + "backend/node_modules/pino-abstract-transport": { + "version": "2.0.0", + "resolved": "https://registry.npmjs.org/pino-abstract-transport/-/pino-abstract-transport-2.0.0.tgz", + "integrity": "sha512-F63x5tizV6WCh4R6RHyi2Ml+M70DNRXt/+HANowMflpgGFMAym/VKm6G7ZOQRjqN7XbGxK1Lg9t6ZrtzOaivMw==", + "license": "MIT", + "dependencies": { + "split2": "^4.0.0" + } + }, + "backend/node_modules/pino-std-serializers": { + "version": "7.1.0", + "resolved": "https://registry.npmjs.org/pino-std-serializers/-/pino-std-serializers-7.1.0.tgz", + "integrity": "sha512-BndPH67/JxGExRgiX1dX0w1FvZck5Wa4aal9198SrRhZjH3GxKQUKIBnYJTdj2HDN3UQAS06HlfcSbQj2OHmaw==", + "license": "MIT" + }, + "backend/node_modules/process-warning": { + "version": "5.0.0", + "resolved": "https://registry.npmjs.org/process-warning/-/process-warning-5.0.0.tgz", + "integrity": "sha512-a39t9ApHNx2L4+HBnQKqxxHNs1r7KF+Intd8Q/g1bUh6q0WIp9voPXJ/x0j+ZL45KF1pJd9+q2jLIRMfvEshkA==", + "funding": [ + { + "type": "github", + "url": "https://github.com/sponsors/fastify" + }, + { + "type": "opencollective", + "url": "https://opencollective.com/fastify" + } + ], + "license": "MIT" + }, + "backend/node_modules/safe-stable-stringify": { + "version": "2.5.0", + "resolved": "https://registry.npmjs.org/safe-stable-stringify/-/safe-stable-stringify-2.5.0.tgz", + "integrity": "sha512-b3rppTKm9T+PsVCBEOUR46GWI7fdOs00VKZ1+9c1EWDaDMvjQc6tUwuFyIprgGgTcWoVHSKrU8H31ZHA2e0RHA==", + "license": "MIT", + "engines": { + "node": ">=10" + } + }, + "backend/node_modules/sonic-boom": { + "version": "4.2.1", + "resolved": "https://registry.npmjs.org/sonic-boom/-/sonic-boom-4.2.1.tgz", + "integrity": "sha512-w6AxtubXa2wTXAUsZMMWERrsIRAdrK0Sc+FUytWvYAhBJLyuI4llrMIC1DtlNSdI99EI86KZum2MMq3EAZlF9Q==", + "license": "MIT", + "dependencies": { + "atomic-sleep": "^1.0.0" + } + }, + "backend/node_modules/thread-stream": { + "version": "3.2.0", + "resolved": "https://registry.npmjs.org/thread-stream/-/thread-stream-3.2.0.tgz", + "integrity": "sha512-zLBvqpwr4Esa0kRjcrzGU6zL25lePWaCLMx0RQFrmteozIfeNdaMLpG5U7PeHzvlFkAWaRKA9/KVW4F60iB+qw==", + "license": "MIT", + "dependencies": { + "real-require": "^0.2.0" + } + }, "backend/security": { "name": "@fuzefront/security-service", "version": "1.0.0", @@ -442,6 +522,7 @@ "openid-client": "^5.6.5", "permitio": "^2.7.4", "pg": "^8.11.5", + "pino": "^9.5.0", "uuid": "^9.0.1", "zod": "3.22.4" }, @@ -3772,6 +3853,12 @@ "@noble/hashes": "^1.1.5" } }, + "node_modules/@pinojs/redact": { + "version": "0.4.0", + "resolved": "https://registry.npmjs.org/@pinojs/redact/-/redact-0.4.0.tgz", + "integrity": "sha512-k2ENnmBugE/rzQfEcdWHcCY+/FM3VLzH9cYEsbdsoqrvzAKRhUZeRNhAZvB8OitQJ1TBed3yqWtdjzS6wJKBwg==", + "license": "MIT" + }, "node_modules/@pkgjs/parseargs": { "version": "0.11.0", "resolved": "https://registry.npmjs.org/@pkgjs/parseargs/-/parseargs-0.11.0.tgz",