fix(security): internal authorize hop + structured logging

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",

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

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
+  }
 })
 
 /**

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,19 +231,31 @@ export async function verifyToken(
   dbInstance: Knex = defaultDb as unknown as Knex
 ): Promise<VerifyResult> {
   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
 
   const row: ApiTokenDbRow | null = await (dbInstance as any)('api_tokens')
     .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
 }