feat: add safe logging helper
This commit is contained in:
@@ -0,0 +1,368 @@
|
||||
import { describe, it, expect } from 'vitest';
|
||||
import { createLogger } from '../../src/utils/logging.js';
|
||||
|
||||
function captureStderr(fn) {
|
||||
let output = '';
|
||||
const originalWrite = process.stderr.write.bind(process.stderr);
|
||||
process.stderr.write = (chunk) => {
|
||||
output += String(chunk);
|
||||
return true;
|
||||
};
|
||||
|
||||
fn();
|
||||
|
||||
process.stderr.write = originalWrite;
|
||||
return output;
|
||||
}
|
||||
|
||||
function parseLastLine(output) {
|
||||
const lines = output.trim().split('\n').filter(Boolean);
|
||||
return lines.length > 0 ? JSON.parse(lines[lines.length - 1]) : null;
|
||||
}
|
||||
|
||||
describe('createLogger', () => {
|
||||
it('creates logger with info level', () => {
|
||||
const log = createLogger('info');
|
||||
expect(typeof log.info).toBe('function');
|
||||
expect(typeof log.warn).toBe('function');
|
||||
expect(typeof log.error).toBe('function');
|
||||
});
|
||||
|
||||
it('creates logger with warn level', () => {
|
||||
const log = createLogger('warn');
|
||||
expect(typeof log.info).toBe('function');
|
||||
expect(typeof log.warn).toBe('function');
|
||||
expect(typeof log.error).toBe('function');
|
||||
});
|
||||
|
||||
it('creates logger with error level', () => {
|
||||
const log = createLogger('error');
|
||||
expect(typeof log.info).toBe('function');
|
||||
expect(typeof log.warn).toBe('function');
|
||||
expect(typeof log.error).toBe('function');
|
||||
});
|
||||
|
||||
it('creates logger with silent level', () => {
|
||||
const log = createLogger('silent');
|
||||
expect(typeof log.info).toBe('function');
|
||||
expect(typeof log.warn).toBe('function');
|
||||
expect(typeof log.error).toBe('function');
|
||||
});
|
||||
|
||||
it('throws for invalid level "debug"', () => {
|
||||
expect(() => createLogger('debug')).toThrow('Invalid log level: debug');
|
||||
});
|
||||
|
||||
it('throws for invalid level "foobar"', () => {
|
||||
expect(() => createLogger('foobar')).toThrow('Invalid log level: foobar');
|
||||
});
|
||||
|
||||
it('throws for invalid level "trace"', () => {
|
||||
expect(() => createLogger('trace')).toThrow('Invalid log level: trace');
|
||||
});
|
||||
});
|
||||
|
||||
describe('log levels', () => {
|
||||
it('error level only emits error', () => {
|
||||
const log = createLogger('error');
|
||||
const output = captureStderr(() => {
|
||||
log.info('should not appear');
|
||||
log.warn('should not appear');
|
||||
log.error('only this appears');
|
||||
});
|
||||
expect(output).toContain('only this appears');
|
||||
expect(output).not.toContain('should not appear');
|
||||
});
|
||||
|
||||
it('warn level emits warn and error but not info', () => {
|
||||
const log = createLogger('warn');
|
||||
const output = captureStderr(() => {
|
||||
log.info('info should not appear');
|
||||
log.warn('warning message');
|
||||
log.error('error message');
|
||||
});
|
||||
expect(output).toContain('warning message');
|
||||
expect(output).toContain('error message');
|
||||
expect(output).not.toContain('info should not appear');
|
||||
});
|
||||
|
||||
it('info level emits info, warn, and error', () => {
|
||||
const log = createLogger('info');
|
||||
const output = captureStderr(() => {
|
||||
log.info('info message');
|
||||
log.warn('warning message');
|
||||
log.error('error message');
|
||||
});
|
||||
expect(output).toContain('info message');
|
||||
expect(output).toContain('warning message');
|
||||
expect(output).toContain('error message');
|
||||
});
|
||||
|
||||
it('silent level suppresses all output', () => {
|
||||
const log = createLogger('silent');
|
||||
const output = captureStderr(() => {
|
||||
log.info('info');
|
||||
log.warn('warn');
|
||||
log.error('error');
|
||||
});
|
||||
expect(output).toBe('');
|
||||
});
|
||||
});
|
||||
|
||||
describe('log entry structure', () => {
|
||||
it('output is valid JSON with required fields', () => {
|
||||
const log = createLogger('info');
|
||||
const output = captureStderr(() => {
|
||||
log.info('test message');
|
||||
});
|
||||
const parsed = parseLastLine(output);
|
||||
expect(parsed.level).toBe('info');
|
||||
expect(typeof parsed.ts).toBe('string');
|
||||
expect(parsed.msg).toBe('test message');
|
||||
});
|
||||
|
||||
it('timestamp is valid ISO 8601', () => {
|
||||
const log = createLogger('info');
|
||||
let ts;
|
||||
captureStderr(() => {
|
||||
log.info('ts test');
|
||||
});
|
||||
// re-read to get the ts value
|
||||
const output = captureStderr(() => {
|
||||
log.info('another message');
|
||||
});
|
||||
const parsed = parseLastLine(output);
|
||||
expect(() => new Date(parsed.ts).toISOString()).not.toThrow();
|
||||
expect(parsed.ts.length).toBeGreaterThan(15);
|
||||
});
|
||||
|
||||
it('warn entry has level "warn"', () => {
|
||||
const log = createLogger('warn');
|
||||
const output = captureStderr(() => {
|
||||
log.warn('warning test');
|
||||
});
|
||||
const parsed = parseLastLine(output);
|
||||
expect(parsed.level).toBe('warn');
|
||||
});
|
||||
|
||||
it('error entry has level "error"', () => {
|
||||
const log = createLogger('error');
|
||||
const output = captureStderr(() => {
|
||||
log.error('error test');
|
||||
});
|
||||
const parsed = parseLastLine(output);
|
||||
expect(parsed.level).toBe('error');
|
||||
});
|
||||
|
||||
it('metadata is included when provided', () => {
|
||||
const log = createLogger('info');
|
||||
const output = captureStderr(() => {
|
||||
log.info('with meta', { tool: 'review_code', model: 'gpt-5.1' });
|
||||
});
|
||||
const parsed = parseLastLine(output);
|
||||
expect(parsed.meta.tool).toBe('review_code');
|
||||
expect(parsed.meta.model).toBe('gpt-5.1');
|
||||
});
|
||||
|
||||
it('metadata defaults to empty object when omitted', () => {
|
||||
const log = createLogger('info');
|
||||
const output = captureStderr(() => {
|
||||
log.info('no metadata');
|
||||
});
|
||||
const parsed = parseLastLine(output);
|
||||
expect(parsed.meta).toEqual({});
|
||||
});
|
||||
|
||||
it('numeric values stay as numbers not strings', () => {
|
||||
const log = createLogger('info');
|
||||
const output = captureStderr(() => {
|
||||
log.info('sizes', { durationMs: 523, inputChars: 10420, outputChars: 842 });
|
||||
});
|
||||
const parsed = parseLastLine(output);
|
||||
expect(typeof parsed.meta.durationMs).toBe('number');
|
||||
expect(typeof parsed.meta.inputChars).toBe('number');
|
||||
expect(typeof parsed.meta.outputChars).toBe('number');
|
||||
});
|
||||
|
||||
it('null values are preserved as null in JSON', () => {
|
||||
const log = createLogger('info');
|
||||
const output = captureStderr(() => {
|
||||
log.info('with null', { result: null });
|
||||
});
|
||||
const parsed = parseLastLine(output);
|
||||
expect(parsed.meta.result).toBeNull();
|
||||
});
|
||||
|
||||
it('boolean values are preserved', () => {
|
||||
const log = createLogger('info');
|
||||
const output = captureStderr(() => {
|
||||
log.info('with booleans', { success: true, retry: false });
|
||||
});
|
||||
const parsed = parseLastLine(output);
|
||||
expect(parsed.meta.success).toBe(true);
|
||||
expect(parsed.meta.retry).toBe(false);
|
||||
});
|
||||
|
||||
it('strings with special characters are JSON-escaped', () => {
|
||||
const log = createLogger('info');
|
||||
const output = captureStderr(() => {
|
||||
log.info('special chars', { note: 'line1\nline2\ttab "quote"' });
|
||||
});
|
||||
const parsed = parseLastLine(output);
|
||||
expect(typeof parsed.meta.note).toBe('string');
|
||||
});
|
||||
});
|
||||
|
||||
describe('redaction', () => {
|
||||
it('redacts OPENAI_API_KEY field value', () => {
|
||||
const log = createLogger('info');
|
||||
const output = captureStderr(() => {
|
||||
log.info('test', { OPENAI_API_KEY: 'sk-123' });
|
||||
});
|
||||
const parsed = parseLastLine(output);
|
||||
expect(parsed.meta.OPENAI_API_KEY).toBe('[REDACTED]');
|
||||
});
|
||||
|
||||
it('redacts API_KEY field value', () => {
|
||||
const log = createLogger('info');
|
||||
const output = captureStderr(() => {
|
||||
log.info('test', { API_KEY: 'ak-456' });
|
||||
});
|
||||
const parsed = parseLastLine(output);
|
||||
expect(parsed.meta.API_KEY).toBe('[REDACTED]');
|
||||
});
|
||||
|
||||
it('redacts AUTH_TOKEN field value', () => {
|
||||
const log = createLogger('info');
|
||||
const output = captureStderr(() => {
|
||||
log.info('test', { AUTH_TOKEN: 'tok-789' });
|
||||
});
|
||||
const parsed = parseLastLine(output);
|
||||
expect(parsed.meta.AUTH_TOKEN).toBe('[REDACTED]');
|
||||
});
|
||||
|
||||
it('redacts DB_PASSWORD field value', () => {
|
||||
const log = createLogger('info');
|
||||
const output = captureStderr(() => {
|
||||
log.info('test', { DB_PASSWORD: 'p4ssw0rd' });
|
||||
});
|
||||
const parsed = parseLastLine(output);
|
||||
expect(parsed.meta.DB_PASSWORD).toBe('[REDACTED]');
|
||||
});
|
||||
|
||||
it('redacts GITHUB_SECRET field value', () => {
|
||||
const log = createLogger('info');
|
||||
const output = captureStderr(() => {
|
||||
log.info('test', { GITHUB_SECRET: 'ghs_abc123' });
|
||||
});
|
||||
const parsed = parseLastLine(output);
|
||||
expect(parsed.meta.GITHUB_SECRET).toBe('[REDACTED]');
|
||||
});
|
||||
|
||||
it('redacts token with mixed casing', () => {
|
||||
const log = createLogger('info');
|
||||
const output = captureStderr(() => {
|
||||
log.info('test', { Token: 'mix-case-123' });
|
||||
});
|
||||
const parsed = parseLastLine(output);
|
||||
expect(parsed.meta.Token).toBe('[REDACTED]');
|
||||
});
|
||||
|
||||
it('redacts bearer token in value via defense-in-depth', () => {
|
||||
const log = createLogger('info');
|
||||
const output = captureStderr(() => {
|
||||
log.info('test', { auth: 'Bearer sk-abc123' });
|
||||
});
|
||||
const parsed = parseLastLine(output);
|
||||
expect(parsed.meta.auth).toContain('[REDACTED]');
|
||||
expect(parsed.meta.auth).not.toContain('sk-abc123');
|
||||
});
|
||||
|
||||
it('preserves safe metadata fields unchanged', () => {
|
||||
const log = createLogger('info');
|
||||
const output = captureStderr(() => {
|
||||
log.info('test', { tool: 'review_code', model: 'gpt-5.1', durationMs: 523, inputChars: 10420 });
|
||||
});
|
||||
const parsed = parseLastLine(output);
|
||||
expect(parsed.meta.tool).toBe('review_code');
|
||||
expect(parsed.meta.model).toBe('gpt-5.1');
|
||||
expect(parsed.meta.durationMs).toBe(523);
|
||||
expect(parsed.meta.inputChars).toBe(10420);
|
||||
});
|
||||
|
||||
it('belt-and-braces: mixed secret and safe fields all handled correctly', () => {
|
||||
const log = createLogger('info');
|
||||
const output = captureStderr(() => {
|
||||
log.info('test', { OPENAI_API_KEY: 'sk-123', tool: 'review_code', token: 'abc456', durationMs: 523 });
|
||||
});
|
||||
const parsed = parseLastLine(output);
|
||||
expect(parsed.meta.OPENAI_API_KEY).toBe('[REDACTED]');
|
||||
expect(parsed.meta.tool).toBe('review_code');
|
||||
expect(parsed.meta.token).toBe('[REDACTED]');
|
||||
expect(parsed.meta.durationMs).toBe(523);
|
||||
});
|
||||
|
||||
it('redacts password field', () => {
|
||||
const log = createLogger('info');
|
||||
const output = captureStderr(() => {
|
||||
log.info('test', { password: 'plaintext123' });
|
||||
});
|
||||
const parsed = parseLastLine(output);
|
||||
expect(parsed.meta.password).toBe('[REDACTED]');
|
||||
});
|
||||
|
||||
it('redacts secret field', () => {
|
||||
const log = createLogger('info');
|
||||
const output = captureStderr(() => {
|
||||
log.info('test', { SECRET: 'my-secret' });
|
||||
});
|
||||
const parsed = parseLastLine(output);
|
||||
expect(parsed.meta.SECRET).toBe('[REDACTED]');
|
||||
});
|
||||
|
||||
it('does not redact safe words that contain token as substring in value only', () => {
|
||||
// The key "message" does not match the pattern, so values are preserved
|
||||
const log = createLogger('info');
|
||||
const output = captureStderr(() => {
|
||||
log.info('test', { message: 'authentication was successful' });
|
||||
});
|
||||
const parsed = parseLastLine(output);
|
||||
expect(parsed.meta.message).toBe('authentication was successful');
|
||||
});
|
||||
|
||||
it('redacts api_key with hyphen separator', () => {
|
||||
const log = createLogger('info');
|
||||
const output = captureStderr(() => {
|
||||
log.info('test', { 'api-key': 'hyphenated-key' });
|
||||
});
|
||||
const parsed = parseLastLine(output);
|
||||
expect(parsed.meta['api-key']).toBe('[REDACTED]');
|
||||
});
|
||||
|
||||
it('redacts api_key with underscore separator', () => {
|
||||
const log = createLogger('info');
|
||||
const output = captureStderr(() => {
|
||||
log.info('test', { 'api_key': 'underscored-key' });
|
||||
});
|
||||
const parsed = parseLastLine(output);
|
||||
expect(parsed.meta.api_key).toBe('[REDACTED]');
|
||||
});
|
||||
|
||||
it('handles empty object metadata gracefully', () => {
|
||||
const log = createLogger('info');
|
||||
const output = captureStderr(() => {
|
||||
log.info('test', {});
|
||||
});
|
||||
const parsed = parseLastLine(output);
|
||||
expect(parsed.meta).toEqual({});
|
||||
});
|
||||
|
||||
it('handles undefined metadata gracefully (defaults to empty object)', () => {
|
||||
const log = createLogger('info');
|
||||
const output = captureStderr(() => {
|
||||
log.info('test', undefined);
|
||||
});
|
||||
const parsed = parseLastLine(output);
|
||||
expect(parsed.meta).toEqual({});
|
||||
});
|
||||
});
|
||||
Reference in New Issue
Block a user