288 lines
11 KiB
JavaScript
288 lines
11 KiB
JavaScript
/**
|
|
* DC-095: central email (PII) masking in the unified logger.
|
|
*
|
|
* Every log sink must mask email addresses regardless of what a call site
|
|
* interpolates — msg strings, data payloads, error messages/stacks, audit
|
|
* details, and error.log lines. Shape matches AuthProvider.maskEmail
|
|
* ("sa****@example.com"). Non-email `@` shapes (root@hostname, pkg@1.2.3)
|
|
* must pass through untouched.
|
|
*
|
|
* Regression provenance: DC-089 judge note #3 — invite/auth call sites were
|
|
* fixed individually, but new call sites kept reintroducing raw PII. This is
|
|
* the central choke-point defense.
|
|
*/
|
|
|
|
const path = require('path');
|
|
const fs = require('fs');
|
|
const fsp = require('fs').promises;
|
|
const os = require('os');
|
|
|
|
const TMP_DIR = fs.mkdtempSync(path.join(os.tmpdir(), 'dc-logging-emailmask-'));
|
|
process.env.AUDIT_LOG_FILE = path.join(TMP_DIR, 'audit-log.json');
|
|
process.env.ERROR_LOG_FILE = path.join(TMP_DIR, 'error.log');
|
|
process.env.NODE_ENV = 'production'; // JSON output mode
|
|
|
|
const {
|
|
log,
|
|
setLevel,
|
|
AUDIT_LOG_FILE,
|
|
ERROR_LOG_FILE,
|
|
} = require('../src/utils/logging');
|
|
|
|
const RAW = 'sami.admin@example.com';
|
|
|
|
afterAll(async () => {
|
|
try { await fsp.rm(TMP_DIR, { recursive: true, force: true }); } catch (_) {}
|
|
});
|
|
|
|
beforeEach(async () => {
|
|
try { await fsp.writeFile(AUDIT_LOG_FILE, '[]'); } catch (_) {}
|
|
try { await fsp.writeFile(ERROR_LOG_FILE, ''); } catch (_) {}
|
|
setLevel('debug');
|
|
});
|
|
|
|
describe('DC-095: logger-level email masking', () => {
|
|
let infoSpy, errorSpy, warnSpy;
|
|
|
|
beforeEach(() => {
|
|
infoSpy = jest.spyOn(console, 'info').mockImplementation(() => {});
|
|
warnSpy = jest.spyOn(console, 'warn').mockImplementation(() => {});
|
|
errorSpy = jest.spyOn(console, 'error').mockImplementation(() => {});
|
|
});
|
|
|
|
afterEach(() => {
|
|
infoSpy.mockRestore();
|
|
warnSpy.mockRestore();
|
|
errorSpy.mockRestore();
|
|
});
|
|
|
|
const consoleOut = () =>
|
|
[...infoSpy.mock.calls, ...warnSpy.mock.calls, ...errorSpy.mock.calls]
|
|
.map(c => String(c[0]))
|
|
.join('\n');
|
|
|
|
test('msg string with interpolated email is masked on console', () => {
|
|
log.warn('auth-magic-send', `SMTP delivery failed for ${RAW}`);
|
|
const out = consoleOut();
|
|
expect(out).not.toContain(RAW);
|
|
expect(out).toContain('sa****@example.com');
|
|
});
|
|
|
|
test('data payload object: email field masked on console', () => {
|
|
log.info('auth', 'email magic link issued', { email: RAW, ip: '1.2.3.4' });
|
|
const out = consoleOut();
|
|
expect(out).not.toContain(RAW);
|
|
expect(JSON.parse(out)).toMatchObject({ data: { email: 'sa****@example.com', ip: '1.2.3.4' } });
|
|
});
|
|
|
|
test('nested payload strings masked (link URLs, arrays, depth)', () => {
|
|
log.info('auth', 'magic link', {
|
|
url: `https://x.example/verify?to=${RAW}`,
|
|
to: [RAW, 'other.person@sub.domain.org'],
|
|
meta: { owner: RAW, note: 'no email here' },
|
|
});
|
|
const out = consoleOut();
|
|
expect(out).not.toContain(RAW);
|
|
expect(out).not.toContain('other.person@sub.domain.org');
|
|
const parsed = JSON.parse(out);
|
|
expect(parsed.data.url).toBe('https://x.example/verify?to=sa****@example.com');
|
|
expect(parsed.data.to).toEqual(['sa****@example.com', 'ot****@sub.domain.org']);
|
|
expect(parsed.data.meta.owner).toBe('sa****@example.com');
|
|
expect(parsed.data.meta.note).toBe('no email here');
|
|
});
|
|
|
|
test('error messages and stacks are masked on console', () => {
|
|
const err = new Error(`SMTP delivery to ${RAW} rejected by relay`);
|
|
log.error('auth-magic-send', err);
|
|
const out = consoleOut();
|
|
expect(out).not.toContain(RAW);
|
|
expect(out).toContain('sa****@example.com');
|
|
});
|
|
|
|
test('log.error writes masked lines to error.log (head, stack, context)', async () => {
|
|
const err = new Error(`RCPT ${RAW} bounced`);
|
|
await log.error('smtp', err, null, { recipient: RAW, note: 'retry' });
|
|
const raw = await fsp.readFile(ERROR_LOG_FILE, 'utf8');
|
|
expect(raw).not.toContain(RAW);
|
|
expect(raw).toContain('sa****@example.com');
|
|
expect(raw).toContain('***'); // SENSITIVE_KEYS not triggered here; recipient is plain key
|
|
});
|
|
|
|
test('logError wrapper: error.log context line masked', async () => {
|
|
const { logError } = require('../src/utils/logging');
|
|
await logError('smtp', new Error(`delivery failed for ${RAW}`), { to: RAW });
|
|
const raw = await fsp.readFile(ERROR_LOG_FILE, 'utf8');
|
|
expect(raw).not.toContain(RAW);
|
|
expect(raw).toContain('sa****@example.com');
|
|
});
|
|
|
|
test('audit details: email in body masked in audit-log.json', async () => {
|
|
await log.audit({
|
|
action: 'test.invite',
|
|
resource: 'invites',
|
|
outcome: 'success',
|
|
details: { body: { email: RAW, role: 'viewer' } },
|
|
});
|
|
const entries = await log.queryAudit({ limit: 5 });
|
|
const entry = entries.find(e => e.action === 'test.invite');
|
|
expect(entry).toBeDefined();
|
|
expect(entry.details.body.email).toBe('sa****@example.com');
|
|
expect(entry.details.body.role).toBe('viewer');
|
|
const onDisk = await fsp.readFile(AUDIT_LOG_FILE, 'utf8');
|
|
expect(onDisk).not.toContain(RAW);
|
|
});
|
|
|
|
test('log entry event: emitted entry carries masked msg and masked payload', () => {
|
|
const captured = [];
|
|
const handler = (e) => captured.push(e);
|
|
log.on('entry', handler);
|
|
// info-path: msg masked (data object is console-only by design — entry
|
|
// only carries error/payload fields, matching pre-DC-095 behavior).
|
|
log.info('auth', `magic link issued for ${RAW}`);
|
|
// error-path: payload DOES land on the entry and must be masked there.
|
|
log.error('smtp', new Error('relay down'), null, { recipient: RAW });
|
|
log.off('entry', handler);
|
|
const info = captured.find(e => e.msg.includes('magic link'));
|
|
expect(info).toBeDefined();
|
|
expect(info.msg).toBe('magic link issued for sa****@example.com');
|
|
const errEntry = captured.find(e => e.level === 'error');
|
|
expect(errEntry).toBeDefined();
|
|
expect(errEntry.data.recipient).toBe('sa****@example.com');
|
|
});
|
|
|
|
test('non-email @ shapes untouched (hostnames, versions, shas)', () => {
|
|
log.info('docker', 'image built', {
|
|
ref: 'registry.local/app@sha256:abcdef',
|
|
user: 'root@web-1',
|
|
ver: 'pkg@1.2.3',
|
|
tag: 'dashcaddy@2x',
|
|
});
|
|
const out = consoleOut();
|
|
expect(out).toContain('registry.local/app@sha256:abcdef');
|
|
expect(out).toContain('root@web-1');
|
|
expect(out).toContain('pkg@1.2.3');
|
|
expect(out).toContain('dashcaddy@2x');
|
|
expect(out).not.toContain('****');
|
|
});
|
|
|
|
test('masking is idempotent (double-masked output stable)', () => {
|
|
log.info('auth', 'already masked', { email: 'sa****@example.com' });
|
|
const out = consoleOut();
|
|
expect(out).toContain('sa****@example.com');
|
|
expect(out.match(/\*/g).length).toBe(4); // exactly one mask, not doubled
|
|
});
|
|
|
|
test('short local-parts mask to 1 char + stars', () => {
|
|
log.info('auth', 'short', { email: 'ab@example.com' });
|
|
const out = consoleOut();
|
|
expect(out).toContain('a****@example.com');
|
|
});
|
|
|
|
test('payload object identity preserved for non-plain objects', () => {
|
|
const d = new Date(0);
|
|
log.info('test', 'date passthrough', { when: d });
|
|
const out = consoleOut();
|
|
const parsed = JSON.parse(out);
|
|
expect(parsed.data.when).toBe('1970-01-01T00:00:00.000Z');
|
|
});
|
|
});
|
|
|
|
describe('DC-095 round 2: adversarial judge findings', () => {
|
|
let infoSpy, errorSpy, warnSpy;
|
|
|
|
beforeEach(() => {
|
|
infoSpy = jest.spyOn(console, 'info').mockImplementation(() => {});
|
|
warnSpy = jest.spyOn(console, 'warn').mockImplementation(() => {});
|
|
errorSpy = jest.spyOn(console, 'error').mockImplementation(() => {});
|
|
});
|
|
|
|
afterEach(() => {
|
|
infoSpy.mockRestore();
|
|
warnSpy.mockRestore();
|
|
errorSpy.mockRestore();
|
|
});
|
|
|
|
const consoleOut = () =>
|
|
[...infoSpy.mock.calls, ...warnSpy.mock.calls, ...errorSpy.mock.calls]
|
|
.map(c => String(c[0]))
|
|
.join('\n');
|
|
|
|
test('ReDoS: 40KB adversarial "a@"+"1."*20000 string processes in <250ms', () => {
|
|
const evil = 'a@' + '1.'.repeat(20000);
|
|
const t0 = Date.now();
|
|
log.info('test', 'evil', { body: evil });
|
|
const elapsed = Date.now() - t0;
|
|
// The payload contains no real email (all digits/dots, no alpha TLD), so
|
|
// nothing to mask — this test pins the TIMING bound only: the unbounded
|
|
// quantifier version stalled 3.3s on this exact input.
|
|
expect(elapsed).toBeLessThan(250);
|
|
// And a real email embedded in a huge adversarial string still masks fast:
|
|
const evil2 = 'x'.repeat(20000) + ' real@user.example.com ' + 'y'.repeat(20000);
|
|
const t1 = Date.now();
|
|
log.info('test', 'evil2', { body: evil2 });
|
|
expect(Date.now() - t1).toBeLessThan(250);
|
|
const out = consoleOut();
|
|
expect(out).not.toContain('real@user.example.com');
|
|
expect(out).toContain('re****@user.example.com');
|
|
});
|
|
|
|
test('DAG shared reference: BOTH paths masked, no raw leak', () => {
|
|
const shared = { email: 'leak.me@example.com' };
|
|
log.info('auth', 'dag', { a: shared, b: shared });
|
|
const out = consoleOut();
|
|
expect(out).not.toContain('leak.me@example.com');
|
|
// both a and b carry the masked form
|
|
const parsed = JSON.parse(out);
|
|
expect(parsed.data.a.email).toBe('le****@example.com');
|
|
expect(parsed.data.b.email).toBe('le****@example.com');
|
|
});
|
|
|
|
test('quoted local-part ("john doe"@example.com) masked', () => {
|
|
log.info('auth', 'quoted', { email: '"john doe"@example.com' });
|
|
const out = consoleOut();
|
|
expect(out).not.toContain('john doe');
|
|
expect(out).not.toContain('"john doe"@example.com');
|
|
// DC-109: delimiter quotes are syntax, not PII — strip, never re-emit.
|
|
expect(out).toContain('jo****@example.com'); // 2 REAL local chars, canonical shape
|
|
expect(out).not.toMatch(/["']j\*{4}/); // old bug: stray quote among the 2 chars
|
|
});
|
|
|
|
test('class instance enumerable email prop masked, prototype preserved', () => {
|
|
class UserRecord { constructor() { this.email = 'inst@example.com'; } }
|
|
log.info('auth', 'instance', { user: new UserRecord() });
|
|
const out = consoleOut();
|
|
expect(out).not.toContain('inst@example.com');
|
|
expect(out).toContain('in****@example.com');
|
|
});
|
|
|
|
test('cyclic payload terminates and masks (no crash, no hang)', () => {
|
|
const cyc = { note: 'cycle@example.com' };
|
|
cyc.self = cyc;
|
|
// JSON.stringify of the masked clone contains the cycle; jest spy just
|
|
// captures the thrown-free path — assert the log call returns and the
|
|
// raw email never appears in captured console args.
|
|
let threw = null;
|
|
try { log.info('test', 'cycle', cyc); } catch (e) { threw = e; }
|
|
// Either it serializes (clone breaks the cycle via memo) or throws a
|
|
// TypeError cyclic — both acceptable; PII must not leak either way.
|
|
const out = threw ? '' : consoleOut();
|
|
expect(out).not.toContain('cycle@example.com');
|
|
});
|
|
|
|
test('request line: email-bearing req.path and user-agent masked in error.log', async () => {
|
|
const fakeReq = {
|
|
method: 'POST',
|
|
path: '/api/v1/auth/invites/sami.admin@example.com/accept',
|
|
ip: '10.0.0.9',
|
|
id: 'req-1',
|
|
get: (h) => (h === 'user-agent' ? 'ContactTool (admin@example.com)' : ''),
|
|
};
|
|
await log.error('auth', new Error('invite accept failed'), fakeReq);
|
|
const raw = await fsp.readFile(ERROR_LOG_FILE, 'utf8');
|
|
expect(raw).not.toContain('sami.admin@example.com');
|
|
expect(raw).not.toContain('admin@example.com');
|
|
expect(raw).toContain('/api/v1/auth/invites/sa****@example.com/accept');
|
|
expect(raw).toContain('ContactTool (ad****@example.com)');
|
|
});
|
|
});
|