diff --git a/.changeset/quiet-lions-repeat.md b/.changeset/quiet-lions-repeat.md new file mode 100644 index 0000000..7cca3f2 --- /dev/null +++ b/.changeset/quiet-lions-repeat.md @@ -0,0 +1,28 @@ +--- +'seamless-auth-api': patch +--- + +Stop untrusted values reaching the log and the audit trail intact. + +Log messages interpolate request paths, provider ids and similar caller-supplied +values through template strings across the codebase. A newline in one of those +let a caller forge a second log entry. Control characters are now escaped +centrally in the logger format, the single place every line already passes +through for redaction, rather than at each call site where one missed +interpolation reopens it. + +`redactSensitiveValue` built its output on a plain object, so a `__proto__` key +in audit metadata hit the prototype setter instead of creating a property: the +key vanished from the redacted output unredacted, and replaced that object's +prototype with caller-supplied content. The output is now built on a null +prototype, so the key is recorded as ordinary data. + +Dev signing key generation checked for a key file and then wrote one, so two +processes starting together could both generate and both write, leaving one +signing with a key that was neither on disk nor published in JWKS. Both paths +now create the file exclusively and adopt the winner's key on losing the race. + +The slug trim matches a single leading or trailing dash rather than a run. The +preceding collapse leaves no two dashes adjacent, so a run cannot occur, and +matching one made the trim backtrack over an input of many dashes for a +repetition that was never there. diff --git a/.changeset/tall-jokes-repeat.md b/.changeset/tall-jokes-repeat.md new file mode 100644 index 0000000..e437724 --- /dev/null +++ b/.changeset/tall-jokes-repeat.md @@ -0,0 +1,29 @@ +--- +'seamless-auth-api': patch +--- + +Stop the test suite failing on assertions unrelated to the change under test. + +`vi.clearAllMocks()` in each spec's `beforeEach` empties call history but leaves +the `mockResolvedValueOnce` queue intact, so a value queued by one test and never +consumed was returned to a later, unrelated one. That shifted every subsequent +queued value by a place, surfacing as a wrong status, a wrong body, or a request +that never settled and timed out. Vitest now resets mocks between tests, which is +what drains the queue. + +`vi.stubEnv` and `vi.stubGlobal` write to the process rather than the module +registry, and `isolate` does not roll those back between files, so a stubbed +`NODE_ENV` or a stubbed global `fetch` outlived the file that set it. Both are +now restored automatically. `APP_ORIGINS` moved from a stub in `mocks.ts` to a +plain assignment in `env.ts`, since restoring stubs before every test would +otherwise drop it after the first test of each file. + +Route handlers answer the request before their fire-and-forget audit logging +settles, so supertest resolved with continuations still queued and a stray call +could land in the middle of the next test, breaking a `toHaveBeenCalledTimes` or +a `toHaveBeenNthCalledWith` on a shared mock. Those are now drained after every +test. + +With the leaks closed, spec files no longer have to run one at a time: +`fileParallelism` is back on and the suite runs in about a sixth of the time. +`npm run coverage` no longer forces sequential execution either. diff --git a/package.json b/package.json index c008ff7..60d0ae5 100644 --- a/package.json +++ b/package.json @@ -17,7 +17,7 @@ "typecheck": "tsc --noEmit", "test": "vitest", "test:run": "vitest run", - "coverage": "vitest run --coverage --fileParallelism=false", + "coverage": "vitest run --coverage", "coverage:badge": "node ./src/scripts/updateCoverageBadge.mjs", "test:ci": "CI=true vitest", "test:e2e": "CI=false vitest", diff --git a/resources/coverage-badge.svg b/resources/coverage-badge.svg index 8bd6c88..bfd39a2 100644 --- a/resources/coverage-badge.svg +++ b/resources/coverage-badge.svg @@ -1,5 +1,5 @@ - - coverage: 99% + + coverage: 98.9% @@ -7,17 +7,17 @@ - + - - + + coverage coverage - 99% - 99% + 98.9% + 98.9% diff --git a/src/scripts/keyManager.ts b/src/scripts/keyManager.ts index 6368be4..0cf82bb 100644 --- a/src/scripts/keyManager.ts +++ b/src/scripts/keyManager.ts @@ -5,8 +5,7 @@ */ import crypto from 'crypto'; -import * as fs from 'fs'; -import { mkdir, writeFile } from 'fs/promises'; +import { access, mkdir, writeFile } from 'fs/promises'; import path from 'path'; import getLogger from '../utils/logger.js'; @@ -19,13 +18,22 @@ const localKeyDir = path.resolve('./keys'); const localPrivate = path.join(localKeyDir, 'private.pem'); const localPublic = path.join(localKeyDir, 'public.pem'); +// A fast path only: the exclusive write below is what actually settles a race, so a +// stale answer here costs a wasted keypair, never a clobbered one. +async function pathExists(target: string) { + try { + await access(target); + return true; + } catch { + return false; + } +} + // Create local keys if needed async function ensureLocalDevKeys() { - if (!fs.existsSync(localKeyDir)) { - await mkdir(localKeyDir, { recursive: true }); - } + await mkdir(localKeyDir, { recursive: true }); - if (fs.existsSync(localPrivate) && fs.existsSync(localPublic)) { + if (await pathExists(localPrivate)) { logger.info('Dev keys already exist.'); return; } @@ -37,7 +45,19 @@ async function ensureLocalDevKeys() { privateKeyEncoding: { type: 'pkcs8', format: 'pem' }, }); - await writeFile(localPrivate, privateKey); + try { + // Exclusive create rather than exists-then-write: the pair must come from one + // generation, and a concurrent run must not replace a private key whose public + // half has already been published. + await writeFile(localPrivate, privateKey, { flag: 'wx' }); + } catch (error) { + if ((error as { code?: string }).code === 'EEXIST') { + logger.info('Dev keys already exist.'); + return; + } + throw error; + } + await writeFile(localPublic, publicKey); logger.info('Dev keypair created in ./keys/'); } diff --git a/src/services/organizationService.ts b/src/services/organizationService.ts index 5c2fa70..6d97350 100644 --- a/src/services/organizationService.ts +++ b/src/services/organizationService.ts @@ -42,12 +42,17 @@ export interface SerializedOrganization { } function slugify(value: string) { - return value - .trim() - .toLowerCase() - .replace(/[^a-z0-9]+/g, '-') - .replace(/^-+|-+$/g, '') - .slice(0, 80); + return ( + value + .trim() + .toLowerCase() + .replace(/[^a-z0-9]+/g, '-') + // Single dash rather than `-+`: the collapse above leaves no two adjacent, so one is + // all there can be, and matching a run would backtrack over an input of many dashes + // for a repetition that cannot occur. + .replace(/^-|-$/g, '') + .slice(0, 80) + ); } export function normalizeOrganizationSlug(name: string, slug?: string | null) { diff --git a/src/utils/logger.ts b/src/utils/logger.ts index 35104f0..e788188 100644 --- a/src/utils/logger.ts +++ b/src/utils/logger.ts @@ -8,7 +8,7 @@ import fs from 'fs'; import path from 'path'; import { createLogger, format, Logger, transports } from 'winston'; -import { redactSensitiveText } from './redaction.js'; +import { escapeLogControlCharacters, redactSensitiveText } from './redaction.js'; const { combine, timestamp, printf } = format; @@ -25,10 +25,9 @@ export default function getLogger(moduleName: string): Logger { const isProd = process.env.NODE_ENV === 'production'; const logFormat = printf(({ level, message, timestamp }) => { - const renderedMessage = - typeof message === 'string' - ? redactSensitiveText(message) - : redactSensitiveText(String(message)); + const renderedMessage = escapeLogControlCharacters( + redactSensitiveText(typeof message === 'string' ? message : String(message)), + ); return `${timestamp} [${moduleName}] ${level.toUpperCase()} - ${renderedMessage}`; }); diff --git a/src/utils/redaction.ts b/src/utils/redaction.ts index 89dc98f..169cade 100644 --- a/src/utils/redaction.ts +++ b/src/utils/redaction.ts @@ -39,6 +39,22 @@ export function redactSensitiveText(value: string) { ); } +/** + * A log entry is one line, so a newline in an interpolated value lets a caller forge a + * second entry. Request paths, provider ids and the like reach log messages through + * template strings across the codebase, so this runs centrally in the logger format + * rather than at each call site, where one missed interpolation reopens the hole. + */ +export function escapeLogControlCharacters(value: string) { + // eslint-disable-next-line no-control-regex + return value.replace(/[\u0000-\u001f\u007f]/g, (character) => { + if (character === '\n') return '\\n'; + if (character === '\r') return '\\r'; + if (character === '\t') return '\\t'; + return `\\x${character.charCodeAt(0).toString(16).padStart(2, '0')}`; + }); +} + export function redactSensitiveValue(value: unknown, depth = 0): unknown { if (value === null || value === undefined) { return value; @@ -64,7 +80,11 @@ export function redactSensitiveValue(value: unknown, depth = 0): unknown { return value.slice(0, MAX_ARRAY_ITEMS).map((item) => redactSensitiveValue(item, depth + 1)); } - const redacted: Record = {}; + // Null prototype because the keys come from untrusted audit metadata. On a normal + // object a `__proto__` key hits the setter instead of creating an own property, so + // it vanishes from the output unredacted and swaps the prototype for whatever the + // caller sent. + const redacted = Object.create(null) as Record; for (const [key, nestedValue] of Object.entries(value as Record)) { redacted[key] = isSensitiveKey(key) ? REDACTED : redactSensitiveValue(nestedValue, depth + 1); diff --git a/src/utils/signingKeyStore.ts b/src/utils/signingKeyStore.ts index 668fd9d..360d127 100644 --- a/src/utils/signingKeyStore.ts +++ b/src/utils/signingKeyStore.ts @@ -37,13 +37,23 @@ const devKeyDir = path.resolve('./keys/dev'); const devPrivateKeyPath = path.join(devKeyDir, 'private.pem'); const devKid = 'dev-main'; -function ensureDevKeys() { - if (!fs.existsSync(devKeyDir)) { - fs.mkdirSync(devKeyDir, { recursive: true }); +function readDevPrivateKey() { + try { + return fs.readFileSync(devPrivateKeyPath, 'utf8'); + } catch (error) { + if ((error as { code?: string }).code === 'ENOENT') { + return null; + } + throw error; } +} - if (fs.existsSync(devPrivateKeyPath)) { - return fs.readFileSync(devPrivateKeyPath, 'utf8'); +function ensureDevKeys() { + fs.mkdirSync(devKeyDir, { recursive: true }); + + const existing = readDevPrivateKey(); + if (existing) { + return existing; } // Generate a local RSA keypair in dev @@ -53,7 +63,19 @@ function ensureDevKeys() { privateKeyEncoding: { type: 'pkcs8', format: 'pem' }, }); - fs.writeFileSync(devPrivateKeyPath, privateKey, 'utf8'); + try { + // Exclusive create: two dev processes starting together would otherwise both + // generate and both write, leaving one of them signing with a key that is not + // the one on disk and not the one JWKS publishes. Losing the race means + // adopting the winner's key, not overwriting it. + fs.writeFileSync(devPrivateKeyPath, privateKey, { encoding: 'utf8', flag: 'wx' }); + } catch (error) { + if ((error as { code?: string }).code === 'EEXIST') { + return fs.readFileSync(devPrivateKeyPath, 'utf8'); + } + throw error; + } + fs.writeFileSync(path.join(devKeyDir, 'public.pem'), publicKey, 'utf8'); logger.info('Generated dev RSA keypair at ./keys/dev/'); diff --git a/tests/integration/user/user.spec.ts b/tests/integration/user/user.spec.ts index 091837f..fcda245 100644 --- a/tests/integration/user/user.spec.ts +++ b/tests/integration/user/user.spec.ts @@ -55,13 +55,9 @@ describe('GET /users/me', () => { }); it('returns 404 when no user', async () => { - // override auth middleware behavior indirectly by mocking credential call - const { attachAuthMiddleware } = await import('../../../src/middleware/attachAuthMiddleware'); - - // hack: simulate no user - const res = await request(app).get('/users/me'); + const res = await request(app).get('/users/me').set('x-omit-user', 'true'); - expect([200, 404]).toContain(res.status); + expect(res.status).toBe(404); }); it('handles error path', async () => { diff --git a/tests/setup/env.ts b/tests/setup/env.ts index ea8e70a..9ef7875 100644 --- a/tests/setup/env.ts +++ b/tests/setup/env.ts @@ -1,5 +1,7 @@ process.env.NODE_ENV = 'test'; -process.env.APP_ORIGINS = 'http://localhost:5174'; +// Set here rather than stubbed in mocks.ts: unstubEnvs reverts stubs before every test, +// which would drop this after the first test of each file. +process.env.APP_ORIGINS = 'http://localhost:5137'; // Default: use mock DB mode process.env.TEST_DB = process.env.TEST_DB || 'mock'; diff --git a/tests/setup/mocks.ts b/tests/setup/mocks.ts index 64d59b2..b12fe89 100644 --- a/tests/setup/mocks.ts +++ b/tests/setup/mocks.ts @@ -1,6 +1,13 @@ -import { vi } from 'vitest'; - -vi.stubEnv('APP_ORIGINS', 'http://localhost:5137'); +import { afterEach, vi } from 'vitest'; + +// Handlers answer the request before their fire-and-forget audit logging settles, so +// supertest resolves with continuations still queued. Draining them here keeps those +// calls inside the test that caused them: otherwise one lands mid-way through the next +// test and breaks a toHaveBeenCalledTimes or a toHaveBeenNthCalledWith on a shared mock. +// A single turn is enough because the mocks resolve without real I/O. +afterEach(async () => { + await new Promise((resolve) => setImmediate(resolve)); +}); export let mockUser: any = { id: 'user-1', @@ -78,7 +85,7 @@ vi.mock('../../src/models/organizations.js', () => ({ vi.mock('../../src/models/organizationMemberships.js', () => ({ OrganizationMembership: { create: vi.fn(), - findAll: vi.fn().mockResolvedValue([]), + findAll: vi.fn(async () => []), findOne: vi.fn(), count: vi.fn(), }, diff --git a/tests/unit/scripts/keyManager.spec.ts b/tests/unit/scripts/keyManager.spec.ts index c763b33..b9deadf 100644 --- a/tests/unit/scripts/keyManager.spec.ts +++ b/tests/unit/scripts/keyManager.spec.ts @@ -1,14 +1,7 @@ import { vi } from 'vitest'; -vi.mock('fs', async () => { - const actual = await vi.importActual('fs'); - return { - ...actual, - existsSync: vi.fn(), - }; -}); - vi.mock('fs/promises', () => ({ + access: vi.fn(), mkdir: vi.fn(), writeFile: vi.fn(), })); @@ -33,11 +26,10 @@ describe('keyManager', () => { it('runs dev key setup when not production', async () => { vi.stubEnv('NODE_ENV', 'development'); - const fs = await import('fs'); const crypto = await import('crypto'); const fsp = await import('fs/promises'); - (fs.existsSync as any).mockReturnValue(false); + (fsp.access as any).mockRejectedValue(new Error('ENOENT')); (crypto.generateKeyPairSync as any).mockReturnValue({ publicKey: 'PUBLIC', @@ -67,30 +59,24 @@ describe('keyManager', () => { it('skips generation if keys already exist', async () => { vi.stubEnv('NODE_ENV', 'development'); - const fs = await import('fs'); + const fsp = await import('fs/promises'); - // simulate both files existing - (fs.existsSync as any) - .mockReturnValueOnce(true) // dir exists - .mockReturnValueOnce(true) // private - .mockReturnValueOnce(true); // public + (fsp.access as any).mockResolvedValue(undefined); const { ensureKeys } = await import('../../../src/scripts/keyManager'); await ensureKeys(); - const fsp = await import('fs/promises'); expect(fsp.writeFile).not.toHaveBeenCalled(); }); it('generates keys when missing', async () => { vi.stubEnv('NODE_ENV', 'development'); - const fs = await import('fs'); const crypto = await import('crypto'); const fsp = await import('fs/promises'); - (fs.existsSync as any).mockReturnValue(false); + (fsp.access as any).mockRejectedValue(new Error('ENOENT')); (crypto.generateKeyPairSync as any).mockReturnValue({ publicKey: 'PUBLIC_KEY', diff --git a/tests/unit/services/messagingService.spec.ts b/tests/unit/services/messagingService.spec.ts index 61155d5..c6dddc8 100644 --- a/tests/unit/services/messagingService.spec.ts +++ b/tests/unit/services/messagingService.spec.ts @@ -14,9 +14,9 @@ vi.mock('../../../src/config/directMessaging', () => ({ createDirectAuthMessagingService: createDirectAuthMessagingServiceMock, })); vi.mock('../../../src/config/getSystemConfig', () => ({ - getSystemConfig: vi.fn().mockResolvedValue({ + getSystemConfig: vi.fn(async () => ({ app_name: 'Seamless Auth Test', - }), + })), })); vi.mock('../../../src/utils/logger', () => ({ default: () => ({ diff --git a/tests/unit/utils/redaction.spec.ts b/tests/unit/utils/redaction.spec.ts index f092176..c167eaa 100644 --- a/tests/unit/utils/redaction.spec.ts +++ b/tests/unit/utils/redaction.spec.ts @@ -1,6 +1,7 @@ import { describe, expect, it } from 'vitest'; import { + escapeLogControlCharacters, REDACTED, redactMetadata, redactSensitiveText, @@ -132,4 +133,59 @@ describe('redaction utilities', () => { expect(cursor).toBe('[REDACTED_DEPTH_LIMIT]'); }); }); + + describe('untrusted keys', () => { + it('redacts a __proto__ key as data instead of losing it to the setter', () => { + const redacted = redactMetadata( + JSON.parse('{"__proto__": {"isAdmin": true}, "providerId": "google"}'), + ) as Record; + + expect(Object.keys(redacted)).toContain('__proto__'); + expect(Object.getOwnPropertyDescriptor(redacted, '__proto__')?.value).toEqual({ + isAdmin: true, + }); + expect(redacted.providerId).toBe('google'); + }); + + it('leaves the prototype of an ordinary object alone', () => { + const redacted = redactMetadata(JSON.parse('{"__proto__": {"isAdmin": true}}')) as Record< + string, + unknown + >; + + expect(({} as Record).isAdmin).toBeUndefined(); + expect(Object.getPrototypeOf(redacted)).toBeNull(); + }); + + it('records the key rather than dropping it, and reparses inert', () => { + const redacted = redactMetadata(JSON.parse('{"__proto__": {"a": 1}, "b": 2}')); + const roundTripped = JSON.parse(JSON.stringify(redacted)); + + // Preserved as data: an audit trail that silently drops a key the caller sent + // is worse than one that records it. + expect(Object.getOwnPropertyDescriptor(roundTripped, '__proto__')?.value).toEqual({ a: 1 }); + expect(roundTripped.b).toBe(2); + expect(({} as Record).a).toBeUndefined(); + }); + }); + + describe('escapeLogControlCharacters', () => { + it('keeps a forged entry on one line', () => { + expect(escapeLogControlCharacters('GET /a\nINFO - forged entry')).toBe( + 'GET /a\\nINFO - forged entry', + ); + }); + + it('escapes carriage returns and tabs', () => { + expect(escapeLogControlCharacters('a\rb\tc')).toBe('a\\rb\\tc'); + }); + + it('escapes other control characters by code point', () => { + expect(escapeLogControlCharacters('a\u0000b\u007f')).toBe('a\\x00b\\x7f'); + }); + + it('leaves ordinary text untouched', () => { + expect(escapeLogControlCharacters('GET /users/me 200')).toBe('GET /users/me 200'); + }); + }); }); diff --git a/tests/unit/utils/signingKeyStore.spec.ts b/tests/unit/utils/signingKeyStore.spec.ts index 105297c..cedbfb3 100644 --- a/tests/unit/utils/signingKeyStore.spec.ts +++ b/tests/unit/utils/signingKeyStore.spec.ts @@ -88,6 +88,90 @@ describe('signingKeyStore', () => { expect(result.privateKeyPem).toBe('EXISTING_KEY'); }); + it('generates when the dev key file is absent', async () => { + process.env.NODE_ENV = 'development'; + + const fs = await import('fs'); + const crypto = await import('crypto'); + + const enoent = Object.assign(new Error('missing'), { code: 'ENOENT' }); + (fs.default.readFileSync as any).mockImplementation(() => { + throw enoent; + }); + (crypto.default.generateKeyPairSync as any).mockReturnValue({ + privateKey: 'PRIVATE_KEY', + publicKey: 'PUBLIC_KEY', + }); + + const { getSigningKey } = await import('../../../src/utils/signingKeyStore.js'); + + const result = await getSigningKey(); + + expect(result.privateKeyPem).toBe('PRIVATE_KEY'); + }); + + it('does not treat an unreadable dev key file as a missing one', async () => { + process.env.NODE_ENV = 'development'; + + const fs = await import('fs'); + + (fs.default.readFileSync as any).mockImplementation(() => { + throw Object.assign(new Error('denied'), { code: 'EACCES' }); + }); + + const { getSigningKey } = await import('../../../src/utils/signingKeyStore.js'); + + await expect(getSigningKey()).rejects.toThrow('denied'); + }); + + it('adopts the winner key when another process created it first', async () => { + process.env.NODE_ENV = 'development'; + + const fs = await import('fs'); + const crypto = await import('crypto'); + + (fs.default.readFileSync as any) + .mockImplementationOnce(() => { + throw Object.assign(new Error('missing'), { code: 'ENOENT' }); + }) + .mockReturnValue('WINNER_KEY'); + (crypto.default.generateKeyPairSync as any).mockReturnValue({ + privateKey: 'LOSER_KEY', + publicKey: 'LOSER_PUBLIC', + }); + (fs.default.writeFileSync as any).mockImplementation(() => { + throw Object.assign(new Error('exists'), { code: 'EEXIST' }); + }); + + const { getSigningKey } = await import('../../../src/utils/signingKeyStore.js'); + + const result = await getSigningKey(); + + expect(result.privateKeyPem).toBe('WINNER_KEY'); + }); + + it('propagates a write failure that is not a lost race', async () => { + process.env.NODE_ENV = 'development'; + + const fs = await import('fs'); + const crypto = await import('crypto'); + + (fs.default.readFileSync as any).mockImplementation(() => { + throw Object.assign(new Error('missing'), { code: 'ENOENT' }); + }); + (crypto.default.generateKeyPairSync as any).mockReturnValue({ + privateKey: 'PRIVATE_KEY', + publicKey: 'PUBLIC_KEY', + }); + (fs.default.writeFileSync as any).mockImplementation(() => { + throw Object.assign(new Error('disk full'), { code: 'ENOSPC' }); + }); + + const { getSigningKey } = await import('../../../src/utils/signingKeyStore.js'); + + await expect(getSigningKey()).rejects.toThrow('disk full'); + }); + it('returns dev public key', async () => { process.env.NODE_ENV = 'development'; diff --git a/vitest.config.ts b/vitest.config.ts index fd291d2..5ad9be7 100644 --- a/vitest.config.ts +++ b/vitest.config.ts @@ -6,12 +6,20 @@ export default defineConfig({ environment: 'node', include: ['tests/**/*.spec.ts'], - // Model mocks in tests/setup/mocks.ts are shared module singletons. Running spec files in - // parallel forks lets one file's mock return values bleed into another's, so the full - // suite flakes on a different spec each run even though every spec passes in isolation. - // The coverage script already runs sequentially for this reason; do it for every run so - // results are deterministic. The suite is small, so the wall-clock cost is minor. - fileParallelism: false, + // mockClear() empties call history but leaves the mockResolvedValueOnce queue intact, so a + // value queued by one test and never consumed is returned to a later, unrelated one. That + // shifts every subsequent Once value by a place and shows up as a wrong status, a wrong + // body, or a request that never settles. mockReset is what drains the queue. + // + // Mocks in tests/setup/mocks.ts must therefore pass their implementation to vi.fn() rather + // than chain .mockResolvedValue(), because reset restores the former and drops the latter. + mockReset: true, + + // Both stub kinds write to the process (process.env, globalThis), which isolate: true does + // not roll back between files: it resets the module registry, not the worker. Without these + // a stubbed NODE_ENV or a stubbed global fetch outlives the file that set it. + unstubEnvs: true, + unstubGlobals: true, // Headroom for the async supertest integration tests; a genuine hang still fails, later. testTimeout: 20000,