From 9d209d5a6b520aa0c5b091e0742d4b053a1e7b26 Mon Sep 17 00:00:00 2001 From: robbond Date: Thu, 11 Jun 2026 09:40:28 +0100 Subject: [PATCH] feat: add safe logging helper --- PROJECT_STATE.md | 5 +- TASKS.md | 32 ++++ src/utils/logging.js | 62 ++++++- test/utils/logging.test.js | 368 +++++++++++++++++++++++++++++++++++++ 4 files changed, 464 insertions(+), 3 deletions(-) create mode 100644 test/utils/logging.test.js diff --git a/PROJECT_STATE.md b/PROJECT_STATE.md index 4bd7a38..f91429a 100644 --- a/PROJECT_STATE.md +++ b/PROJECT_STATE.md @@ -20,7 +20,8 @@ Phase 1 - Core Utilities - Task 1.1 — Configuration loader ✅ - Task 1.2 — Secret redaction utility (`src/utils/redact.js`) ✅ - Task 1.3 — Context budget utility (`src/utils/context-budget.js`) ✅ +- Task 1.4 — Safe logging helper (`src/utils/logging.js`) ✅ -## Next Task +## Next Phase -Task 1.4 — Safe logging helper (`src/utils/logging.js`) +Phase 2 - OpenAI Integration diff --git a/TASKS.md b/TASKS.md index a3a2af3..51050ba 100644 --- a/TASKS.md +++ b/TASKS.md @@ -82,5 +82,37 @@ Requirements: - Log safe metadata (tool name, timestamp, model, input/output size, duration, success/failure, error type). - No stack traces in logs. - No sensitive data in logs. +- Defensive redaction of secret field names and Bearer tokens in metadata values. +- Support levels: info, warn, error, silent (invalid levels throw). + +Status: ✅ Complete + +--- + +## Phase 2 - OpenAI Integration + +### Task 2.1 - OpenAI client wrapper + +Create `src/openai/client.js`. + +Requirements: +- Create a minimal OpenAI API client using the OpenAI SDK. +- Accept API key from configuration (never hardcoded). +- Support configurable model and temperature. +- Implement streaming via the Responses API. + +Status: ⏳ Pending + +### Task 2.2 - Response builder + +Create `src/openai/responses.js`. + +Requirements: +- Build structured OpenAI Responses API payloads from tool inputs. +- Apply character budget checks before sending. +- Redact secrets using `redact()` before constructing the request. +- Never include openaiApiKey in request logs or error messages. +- Handle OpenAI API errors gracefully (authentication, rate limits, timeouts). +- Return safe advisory-formatted text responses. Status: ⏳ Pending diff --git a/src/utils/logging.js b/src/utils/logging.js index b171c82..7d0dbfa 100644 --- a/src/utils/logging.js +++ b/src/utils/logging.js @@ -1 +1,61 @@ -// Safe logging utility (stderr only). +// Safe logging utility (stderr only, JSON Lines). + +import { redact } from './redact.js'; + +const LEVELS = { silent: 0, info: 10, warn: 20, error: 30 }; + +const SECRET_KEY_PATTERN = /(api[_-]?key|token|secret|password)/i; + +function sanitizeMetadata(meta) { + if (!meta) return {}; + + const filtered = {}; + for (const [key, value] of Object.entries(meta)) { + if (typeof value === 'string' && SECRET_KEY_PATTERN.test(key.toLowerCase())) { + filtered[key] = '[REDACTED]'; + } else if (typeof value === 'string' && /^Bearer\s+/i.test(value)) { + // Preserve "Bearer " prefix, redact the token portion + const cleaned = value.replace(/(Bearer\s+).+/, '$1[REDACTED]'); + filtered[key] = cleaned; + } else { + filtered[key] = value; + } + } + + const jsonStr = JSON.stringify(filtered); + const redactedStr = redact(jsonStr); + + try { + return JSON.parse(redactedStr); + } catch { + return filtered; + } +} + +export function createLogger(level) { + if (!(level in LEVELS)) { + throw new Error(`Invalid log level: ${level}`); + } + + const currentLevel = LEVELS[level]; + + function write(eventLevel, message, metadata) { + if (LEVELS[eventLevel] < currentLevel && currentLevel !== LEVELS.silent) return; + if (currentLevel === LEVELS.silent) return; + + const meta = sanitizeMetadata(metadata); + const entry = JSON.stringify({ + level: eventLevel, + ts: new Date().toISOString(), + msg: message, + meta, + }); + process.stderr.write(entry + '\n'); + } + + return { + info: (message, metadata) => write('info', message, metadata), + warn: (message, metadata) => write('warn', message, metadata), + error: (message, metadata) => write('error', message, metadata), + }; +} diff --git a/test/utils/logging.test.js b/test/utils/logging.test.js new file mode 100644 index 0000000..7672760 --- /dev/null +++ b/test/utils/logging.test.js @@ -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({}); + }); +});