diff --git a/containers/api-proxy/Dockerfile b/containers/api-proxy/Dockerfile index dd2882a13..04afcfb55 100644 --- a/containers/api-proxy/Dockerfile +++ b/containers/api-proxy/Dockerfile @@ -27,7 +27,7 @@ COPY server.js logging.js metrics.js rate-limiter.js \ ai-credits-pricing.js models-dev-catalog.js models.dev.catalog.json \ oidc-refresh-utils.js body-transform.js body-utils.js rate-limit.js websocket-proxy.js \ deprecated-header-tracker.js billing-headers.js upstream-response.js \ - anthropic-cache.js otel.js token-budget-log.js ./ + anthropic-cache.js otel.js token-budget-log.js blocked-request-diagnostics.js ./ COPY guards/ ./guards/ COPY providers/ ./providers/ COPY transforms/ ./transforms/ diff --git a/containers/api-proxy/blocked-request-diagnostics.js b/containers/api-proxy/blocked-request-diagnostics.js new file mode 100644 index 000000000..aa6aaa4ba --- /dev/null +++ b/containers/api-proxy/blocked-request-diagnostics.js @@ -0,0 +1,392 @@ +'use strict'; + +/** + * Opt-in diagnostics for blocked LLM requests. + * + * When AWF_CAPTURE_BLOCKED_LLM_REQUESTS is set, writes a JSONL record to + * blocked-request-diag.jsonl for every request that is rejected by a guard + * (effective_tokens_limit_exceeded, ai_credits_limit_exceeded, etc.). + * + * Capture modes: + * false / not set : disabled (default) + * summary : body-shape metadata only — counts, sizes, hashes. No content. + * redacted : summary + first 200 chars of each message (may still contain secrets) + * full : full body capture up to AWF_MAX_BLOCKED_CAPTURE_BYTES + * + * The resulting file is written to the same directory as token-usage.jsonl + * (AWF_TOKEN_LOG_DIR, default /var/log/api-proxy) so it is picked up by the + * same log-collection infrastructure. + */ + +const fs = require('fs'); +const path = require('path'); +const crypto = require('crypto'); + +// ── Config (read at module load; tests override via jest.isolateModules) ─────── +const TOKEN_LOG_DIR = process.env.AWF_TOKEN_LOG_DIR || '/var/log/api-proxy'; +const DIAG_FILE = path.join(TOKEN_LOG_DIR, 'blocked-request-diag.jsonl'); + +const AWF_VERSION = process.env.AWF_VERSION || '0.0.0-dev'; +const SCHEMA = `blocked-request-diag/v${AWF_VERSION}`; + +/** Maximum bytes to capture in 'full' mode (per-record total). */ +const DEFAULT_MAX_CAPTURED_BYTES = 250_000; + +let diagStream = null; + +// ── Capture-mode helpers ────────────────────────────────────────────────────── + +/** + * Returns the configured capture mode for blocked LLM requests. + * Read at call time so it can be changed between requests in tests. + * + * @returns {'summary'|'redacted'|'full'|false} + */ +function getCaptureMode() { + const raw = process.env.AWF_CAPTURE_BLOCKED_LLM_REQUESTS; + if (!raw || raw === 'false' || raw === '0') return false; + if (raw === 'true' || raw === '1' || raw === 'summary') return 'summary'; + if (raw === 'redacted') return 'redacted'; + if (raw === 'full') return 'full'; + return false; +} + +// ── Body analysis ───────────────────────────────────────────────────────────── + +/** + * Compute a short (16-hex-char) SHA-256 prefix of a buffer for correlation. + * @param {Buffer} buf + * @returns {string} + */ +function sha256Short(buf) { + return crypto.createHash('sha256').update(buf).digest('hex').slice(0, 16); +} + +/** + * Rough token estimate — 4 characters per token, consistent with many + * provider pricing calculators for English text. + * @param {string} str + * @returns {number} + */ +function estimateTokens(str) { + if (!str || typeof str !== 'string') return 0; + return Math.ceil(str.length / 4); +} + +/** + * Analyse the text content of a single message content value. + * Handles both plain-string content and Anthropic/OpenAI structured + * content-block arrays. + * + * @param {unknown} content + * @returns {{ type: string, chars: number, bytes: number, estimated_tokens: number }} + */ +function analyzeContent(content) { + if (typeof content === 'string') { + const bytes = Buffer.byteLength(content, 'utf8'); + return { + type: 'text', + chars: content.length, + bytes, + estimated_tokens: estimateTokens(content), + }; + } + + if (Array.isArray(content)) { + let totalChars = 0; + let totalBytes = 0; + let totalTokens = 0; + const types = new Set(); + + for (const block of content) { + if (!block || typeof block !== 'object') continue; + const blockType = typeof block.type === 'string' ? block.type : 'unknown'; + types.add(blockType); + + // Text block + if (typeof block.text === 'string') { + totalChars += block.text.length; + totalBytes += Buffer.byteLength(block.text, 'utf8'); + totalTokens += estimateTokens(block.text); + } + // Tool result content (nested string) + if (typeof block.content === 'string') { + totalChars += block.content.length; + totalBytes += Buffer.byteLength(block.content, 'utf8'); + totalTokens += estimateTokens(block.content); + } + // Tool result content (nested array — recurse one level) + if (Array.isArray(block.content)) { + for (const inner of block.content) { + if (inner && typeof inner.text === 'string') { + totalChars += inner.text.length; + totalBytes += Buffer.byteLength(inner.text, 'utf8'); + totalTokens += estimateTokens(inner.text); + } + } + } + // Base64-encoded image data — estimate decoded size + if (block.source && typeof block.source === 'object' && + typeof block.source.data === 'string') { + const decodedBytes = Math.ceil(block.source.data.length * 3 / 4); + totalBytes += decodedBytes; + } + } + + return { + type: [...types].sort().join(',') || 'mixed', + chars: totalChars, + bytes: totalBytes, + estimated_tokens: totalTokens, + }; + } + + return { type: 'unknown', chars: 0, bytes: 0, estimated_tokens: 0 }; +} + +/** + * Extract a short content preview (first 200 chars of concatenated text). + * Used in 'redacted' and 'full' modes. + * + * @param {unknown} content + * @returns {string|undefined} + */ +function extractContentPreview(content) { + if (typeof content === 'string') { + return content.slice(0, 200) || undefined; + } + if (Array.isArray(content)) { + const parts = []; + for (const block of content) { + if (!block || typeof block !== 'object') continue; + if (typeof block.text === 'string') parts.push(block.text.slice(0, 100)); + else if (typeof block.content === 'string') parts.push(block.content.slice(0, 100)); + } + const joined = parts.join(' ').slice(0, 200); + return joined || undefined; + } + return undefined; +} + +/** + * Analyse a messages array (OpenAI or Anthropic format). + * + * @param {unknown[]} messages + * @param {'summary'|'redacted'|'full'} captureMode + * @returns {{ messageCount: number, toolResultCount: number, messageSizes: object[] } | null} + */ +function analyzeMessages(messages, captureMode) { + if (!Array.isArray(messages)) return null; + + let messageCount = 0; + let toolResultCount = 0; + const messageSizes = []; + + for (const msg of messages) { + if (!msg || typeof msg !== 'object') continue; + messageCount++; + + const role = typeof msg.role === 'string' ? msg.role : 'unknown'; + const contentAnalysis = analyzeContent(msg.content); + + // Count tool-result blocks (Anthropic: type='tool_result'; OpenAI: role='tool') + let toolBlocksInMsg = 0; + if (Array.isArray(msg.content)) { + for (const block of msg.content) { + if (block && block.type === 'tool_result') { + toolBlocksInMsg++; + toolResultCount++; + } + } + } + if (role === 'tool') { + toolResultCount++; + } + + const entry = { + role, + content_type: contentAnalysis.type, + chars: contentAnalysis.chars, + bytes: contentAnalysis.bytes, + estimated_tokens: contentAnalysis.estimated_tokens, + }; + if (toolBlocksInMsg > 0) entry.tool_blocks = toolBlocksInMsg; + + if (captureMode === 'redacted' || captureMode === 'full') { + const preview = extractContentPreview(msg.content); + if (preview !== undefined) entry.content_preview = preview; + } + + messageSizes.push(entry); + } + + return { messageCount, toolResultCount, messageSizes }; +} + +/** + * Analyse a request body buffer and return diagnostic shape information. + * + * @param {Buffer} body - Final (possibly transformed) request body + * @param {'summary'|'redacted'|'full'} captureMode + * @returns {object} + */ +function analyzeRequestBody(body, captureMode) { + const bodyBytes = body ? body.length : 0; + const result = { + body_bytes: bodyBytes, + body_sha256: body && bodyBytes > 0 ? sha256Short(body) : null, + }; + + if (!body || bodyBytes === 0) return result; + + let parsed; + try { + parsed = JSON.parse(body.toString('utf8')); + } catch { + result.parse_error = true; + return result; + } + + if (!parsed || typeof parsed !== 'object' || Array.isArray(parsed)) return result; + + if (typeof parsed.model === 'string') result.model = parsed.model; + if (parsed.stream === true) result.streaming = true; + + if (captureMode === 'full') { + // Full mode: include the entire body, truncated to the configured byte cap. + const maxBytes = parseInt(process.env.AWF_MAX_BLOCKED_CAPTURE_BYTES, 10) || DEFAULT_MAX_CAPTURED_BYTES; + const raw = body.slice(0, maxBytes).toString('utf8'); + result.body_full = raw; + } + + if (Array.isArray(parsed.messages)) { + const analysis = analyzeMessages(parsed.messages, captureMode); + if (analysis) { + result.message_count = analysis.messageCount; + result.tool_result_count = analysis.toolResultCount; + result.message_sizes = analysis.messageSizes; + } + } + + return result; +} + +// ── Stream management ───────────────────────────────────────────────────────── + +/** + * Lazy singleton write stream for the diagnostics log. + * Reads TOKEN_LOG_DIR at call time to support test overrides via + * jest.isolateModules (TOKEN_LOG_DIR is constant per module instance). + * + * @returns {fs.WriteStream|null} + */ +function getDiagStream() { + if (diagStream) return diagStream; + try { + fs.mkdirSync(TOKEN_LOG_DIR, { recursive: true }); + diagStream = fs.createWriteStream(DIAG_FILE, { flags: 'a' }); + diagStream.on('error', () => { diagStream = null; }); + return diagStream; + } catch { + return null; + } +} + +// ── Public API ──────────────────────────────────────────────────────────────── + +/** + * Write a blocked-request diagnostic record. + * + * Silently does nothing when: + * - AWF_CAPTURE_BLOCKED_LLM_REQUESTS is not set or is 'false' + * - the log directory cannot be created + * - any other error occurs (best-effort, never throws) + * + * @param {object} opts + * @param {string} opts.requestId - Unique request identifier + * @param {string} opts.provider - Provider name (openai, anthropic, …) + * @param {string} opts.path - Sanitized request path + * @param {string} opts.guardType - Guard event name + * @param {object} opts.guardLogFields - Guard-specific totals / limits + * @param {Buffer} opts.body - Final request body (after transforms) + * @param {number} opts.inboundBytes - Raw body bytes before transforms + */ +function writeBlockedRequestDiag(opts) { + const captureMode = getCaptureMode(); + if (!captureMode) return; + + const { requestId, provider, path: reqPath, guardType, guardLogFields, body, inboundBytes } = opts; + + let bodyAnalysis; + try { + bodyAnalysis = analyzeRequestBody(body, captureMode); + } catch { + bodyAnalysis = { body_bytes: body ? body.length : 0, analysis_error: true }; + } + + const bodyTransformed = (body ? body.length : 0) !== inboundBytes; + + const record = { + _schema: SCHEMA, + timestamp: new Date().toISOString(), + event: 'blocked_request_diag', + capture_mode: captureMode, + request_id: requestId, + provider, + path: reqPath, + guard_type: guardType, + guard_totals: guardLogFields || {}, + body_transformed: bodyTransformed, + inbound_bytes: inboundBytes, + ...bodyAnalysis, + }; + + try { + const stream = getDiagStream(); + if (stream && !stream.writableEnded) { + stream.write(JSON.stringify(record) + '\n'); + } + } catch { /* best-effort */ } +} + +/** + * Close the diagnostics write stream (called during graceful shutdown). + * Returns a Promise that resolves once the stream has been flushed. + * + * @returns {Promise} + */ +function closeBlockedRequestDiagStream() { + return new Promise((resolve) => { + if (diagStream) { + diagStream.end(() => { diagStream = null; resolve(); }); + } else { + resolve(); + } + }); +} + +// ── Internal test helpers ───────────────────────────────────────────────────── + +/** @internal Test-only: reset singleton stream so tests start clean. */ +// ts-prune-ignore-next +const testHelpers = { + resetDiagStream() { + if (diagStream) { + try { diagStream.destroy(); } catch { /* ignore */ } + diagStream = null; + } + }, + DIAG_FILE, + SCHEMA, +}; + +module.exports = { + getCaptureMode, + analyzeRequestBody, + analyzeMessages, + writeBlockedRequestDiag, + closeBlockedRequestDiagStream, + DIAG_FILE, + SCHEMA, + testHelpers, +}; diff --git a/containers/api-proxy/blocked-request-diagnostics.test.js b/containers/api-proxy/blocked-request-diagnostics.test.js new file mode 100644 index 000000000..d24e2c00b --- /dev/null +++ b/containers/api-proxy/blocked-request-diagnostics.test.js @@ -0,0 +1,542 @@ +'use strict'; + +/** + * Tests for blocked-request-diagnostics.js + * + * Covers: + * - getCaptureMode() env-var parsing + * - analyzeRequestBody() shape extraction in all capture modes + * - analyzeMessages() message/tool-result counting + * - writeBlockedRequestDiag() JSONL persistence + * - graceful handling of malformed bodies and disabled mode + */ + +const fs = require('fs'); +const os = require('os'); +const path = require('path'); + +// ── Helpers ─────────────────────────────────────────────────────────────────── + +function withIsolatedModule(envOverrides, fn) { + // Save and apply env + const saved = {}; + for (const [k, v] of Object.entries(envOverrides)) { + saved[k] = process.env[k]; + if (v === undefined) { + delete process.env[k]; + } else { + process.env[k] = v; + } + } + + let mod; + jest.isolateModules(() => { + mod = require('./blocked-request-diagnostics'); + }); + + try { + return fn(mod); + } finally { + // Restore env + for (const [k, v] of Object.entries(saved)) { + if (v === undefined) { + delete process.env[k]; + } else { + process.env[k] = v; + } + } + } +} + +function readDiagLines(file) { + if (!fs.existsSync(file)) return []; + return fs.readFileSync(file, 'utf8') + .split('\n') + .filter(Boolean) + .map(l => JSON.parse(l)); +} + +// ── getCaptureMode() ────────────────────────────────────────────────────────── + +describe('getCaptureMode()', () => { + afterEach(() => { + delete process.env.AWF_CAPTURE_BLOCKED_LLM_REQUESTS; + }); + + it('returns false when env var is not set', () => { + jest.isolateModules(() => { + const { getCaptureMode } = require('./blocked-request-diagnostics'); + expect(getCaptureMode()).toBe(false); + }); + }); + + it('returns false for explicit "false"', () => { + process.env.AWF_CAPTURE_BLOCKED_LLM_REQUESTS = 'false'; + jest.isolateModules(() => { + const { getCaptureMode } = require('./blocked-request-diagnostics'); + expect(getCaptureMode()).toBe(false); + }); + }); + + it('returns false for "0"', () => { + process.env.AWF_CAPTURE_BLOCKED_LLM_REQUESTS = '0'; + jest.isolateModules(() => { + const { getCaptureMode } = require('./blocked-request-diagnostics'); + expect(getCaptureMode()).toBe(false); + }); + }); + + it('returns "summary" for "summary"', () => { + process.env.AWF_CAPTURE_BLOCKED_LLM_REQUESTS = 'summary'; + jest.isolateModules(() => { + const { getCaptureMode } = require('./blocked-request-diagnostics'); + expect(getCaptureMode()).toBe('summary'); + }); + }); + + it('returns "summary" for "true"', () => { + process.env.AWF_CAPTURE_BLOCKED_LLM_REQUESTS = 'true'; + jest.isolateModules(() => { + const { getCaptureMode } = require('./blocked-request-diagnostics'); + expect(getCaptureMode()).toBe('summary'); + }); + }); + + it('returns "summary" for "1"', () => { + process.env.AWF_CAPTURE_BLOCKED_LLM_REQUESTS = '1'; + jest.isolateModules(() => { + const { getCaptureMode } = require('./blocked-request-diagnostics'); + expect(getCaptureMode()).toBe('summary'); + }); + }); + + it('returns "redacted" for "redacted"', () => { + process.env.AWF_CAPTURE_BLOCKED_LLM_REQUESTS = 'redacted'; + jest.isolateModules(() => { + const { getCaptureMode } = require('./blocked-request-diagnostics'); + expect(getCaptureMode()).toBe('redacted'); + }); + }); + + it('returns "full" for "full"', () => { + process.env.AWF_CAPTURE_BLOCKED_LLM_REQUESTS = 'full'; + jest.isolateModules(() => { + const { getCaptureMode } = require('./blocked-request-diagnostics'); + expect(getCaptureMode()).toBe('full'); + }); + }); + + it('returns false for unrecognised value', () => { + process.env.AWF_CAPTURE_BLOCKED_LLM_REQUESTS = 'verbose'; + jest.isolateModules(() => { + const { getCaptureMode } = require('./blocked-request-diagnostics'); + expect(getCaptureMode()).toBe(false); + }); + }); +}); + +// ── analyzeRequestBody() ────────────────────────────────────────────────────── + +describe('analyzeRequestBody()', () => { + let analyzeRequestBody; + + beforeAll(() => { + jest.isolateModules(() => { + ({ analyzeRequestBody } = require('./blocked-request-diagnostics')); + }); + }); + + it('returns body_bytes=0 and null sha256 for empty buffer', () => { + const result = analyzeRequestBody(Buffer.alloc(0), 'summary'); + expect(result).toEqual({ body_bytes: 0, body_sha256: null }); + }); + + it('returns body_bytes and sha256 for non-JSON body', () => { + const body = Buffer.from('not json'); + const result = analyzeRequestBody(body, 'summary'); + expect(result.body_bytes).toBe(8); + expect(result.body_sha256).toMatch(/^[0-9a-f]{16}$/); + expect(result.parse_error).toBe(true); + }); + + it('extracts model and message_count in summary mode', () => { + const payload = { + model: 'gpt-4o', + messages: [ + { role: 'user', content: 'Hello' }, + { role: 'assistant', content: 'Hi there' }, + ], + }; + const body = Buffer.from(JSON.stringify(payload)); + const result = analyzeRequestBody(body, 'summary'); + + expect(result.model).toBe('gpt-4o'); + expect(result.message_count).toBe(2); + expect(result.tool_result_count).toBe(0); + expect(result.message_sizes).toHaveLength(2); + expect(result.message_sizes[0]).toMatchObject({ + role: 'user', + content_type: 'text', + chars: 5, + bytes: 5, + }); + expect(result.body_sha256).toMatch(/^[0-9a-f]{16}$/); + // Summary mode: no content_preview + expect(result.message_sizes[0].content_preview).toBeUndefined(); + }); + + it('includes content_preview in redacted mode', () => { + const payload = { + model: 'claude-opus-4.7', + messages: [{ role: 'user', content: 'Secret prompt' }], + }; + const body = Buffer.from(JSON.stringify(payload)); + const result = analyzeRequestBody(body, 'redacted'); + + expect(result.message_sizes[0].content_preview).toBe('Secret prompt'); + }); + + it('includes content_preview in full mode', () => { + const payload = { + model: 'gpt-4o', + messages: [{ role: 'user', content: 'Full content' }], + }; + const body = Buffer.from(JSON.stringify(payload)); + const result = analyzeRequestBody(body, 'full'); + + expect(result.message_sizes[0].content_preview).toBe('Full content'); + expect(result.body_full).toBeDefined(); + }); + + it('counts tool_result blocks (Anthropic format)', () => { + const payload = { + model: 'claude-opus-4.7', + messages: [ + { + role: 'user', + content: [ + { type: 'tool_result', tool_use_id: 'tu_1', content: 'result text' }, + { type: 'text', text: 'Check the above' }, + ], + }, + ], + }; + const body = Buffer.from(JSON.stringify(payload)); + const result = analyzeRequestBody(body, 'summary'); + + expect(result.tool_result_count).toBe(1); + expect(result.message_sizes[0].tool_blocks).toBe(1); + }); + + it('counts tool role messages (OpenAI format)', () => { + const payload = { + model: 'gpt-4o', + messages: [ + { role: 'user', content: 'Use the tool' }, + { role: 'tool', content: 'tool result here' }, + ], + }; + const body = Buffer.from(JSON.stringify(payload)); + const result = analyzeRequestBody(body, 'summary'); + + expect(result.tool_result_count).toBe(1); + }); + + it('sets streaming=true when stream:true in body', () => { + const payload = { model: 'gpt-4o', stream: true, messages: [] }; + const body = Buffer.from(JSON.stringify(payload)); + const result = analyzeRequestBody(body, 'summary'); + + expect(result.streaming).toBe(true); + }); + + it('truncates body_full to AWF_MAX_BLOCKED_CAPTURE_BYTES', () => { + const original = process.env.AWF_MAX_BLOCKED_CAPTURE_BYTES; + process.env.AWF_MAX_BLOCKED_CAPTURE_BYTES = '10'; + try { + const payload = { model: 'gpt-4o', messages: [{ role: 'user', content: 'abcdefghij1234567890' }] }; + const body = Buffer.from(JSON.stringify(payload)); + jest.isolateModules(() => { + const { analyzeRequestBody: analyze } = require('./blocked-request-diagnostics'); + const result = analyze(body, 'full'); + expect(result.body_full.length).toBeLessThanOrEqual(10); + }); + } finally { + if (original === undefined) { + delete process.env.AWF_MAX_BLOCKED_CAPTURE_BYTES; + } else { + process.env.AWF_MAX_BLOCKED_CAPTURE_BYTES = original; + } + } + }); + + it('handles structured content blocks (Anthropic array content)', () => { + const payload = { + model: 'claude-opus-4.7', + messages: [ + { + role: 'user', + content: [ + { type: 'text', text: 'Here is the image' }, + { type: 'image', source: { type: 'base64', data: 'aGVsbG8=' } }, + ], + }, + ], + }; + const body = Buffer.from(JSON.stringify(payload)); + const result = analyzeRequestBody(body, 'summary'); + + expect(result.message_sizes[0].content_type).toContain('text'); + expect(result.message_sizes[0].chars).toBeGreaterThan(0); + expect(result.message_sizes[0].bytes).toBeGreaterThan(0); + }); +}); + +// ── writeBlockedRequestDiag() ───────────────────────────────────────────────── + +describe('writeBlockedRequestDiag()', () => { + let tmpDir; + + beforeEach(() => { + tmpDir = fs.mkdtempSync(path.join(os.tmpdir(), 'awf-blocked-diag-')); + }); + + afterEach(() => { + fs.rmSync(tmpDir, { recursive: true, force: true }); + delete process.env.AWF_CAPTURE_BLOCKED_LLM_REQUESTS; + delete process.env.AWF_TOKEN_LOG_DIR; + }); + + it('does not write anything when capture mode is disabled', () => { + delete process.env.AWF_CAPTURE_BLOCKED_LLM_REQUESTS; + + withIsolatedModule({ AWF_TOKEN_LOG_DIR: tmpDir }, (mod) => { + mod.writeBlockedRequestDiag({ + requestId: 'req-1', + provider: 'openai', + path: '/v1/chat/completions', + guardType: 'effective_tokens_limit_exceeded', + guardLogFields: { total_effective_tokens: 100, max_effective_tokens: 50 }, + body: Buffer.from(JSON.stringify({ model: 'gpt-4o', messages: [] })), + inboundBytes: 40, + }); + mod.testHelpers.resetDiagStream(); + }); + + const diagFile = path.join(tmpDir, 'blocked-request-diag.jsonl'); + expect(fs.existsSync(diagFile)).toBe(false); + }); + + it('writes a JSONL record in summary mode', (done) => { + withIsolatedModule( + { AWF_TOKEN_LOG_DIR: tmpDir, AWF_CAPTURE_BLOCKED_LLM_REQUESTS: 'summary' }, + (mod) => { + const body = Buffer.from(JSON.stringify({ + model: 'gpt-4o', + messages: [{ role: 'user', content: 'Hello' }], + })); + + mod.writeBlockedRequestDiag({ + requestId: 'req-abc', + provider: 'openai', + path: '/v1/chat/completions', + guardType: 'effective_tokens_limit_exceeded', + guardLogFields: { total_effective_tokens: 1500, max_effective_tokens: 1000 }, + body, + inboundBytes: body.length, + }); + + // Flush stream before reading + setImmediate(() => { + mod.closeBlockedRequestDiagStream().then(() => { + const diagFile = path.join(tmpDir, 'blocked-request-diag.jsonl'); + const lines = readDiagLines(diagFile); + + expect(lines).toHaveLength(1); + const rec = lines[0]; + expect(rec._schema).toMatch(/^blocked-request-diag\/v/); + expect(rec.event).toBe('blocked_request_diag'); + expect(rec.capture_mode).toBe('summary'); + expect(rec.request_id).toBe('req-abc'); + expect(rec.provider).toBe('openai'); + expect(rec.path).toBe('/v1/chat/completions'); + expect(rec.guard_type).toBe('effective_tokens_limit_exceeded'); + expect(rec.guard_totals).toEqual({ + total_effective_tokens: 1500, + max_effective_tokens: 1000, + }); + expect(rec.model).toBe('gpt-4o'); + expect(rec.message_count).toBe(1); + expect(rec.tool_result_count).toBe(0); + expect(rec.body_bytes).toBe(body.length); + expect(rec.body_sha256).toMatch(/^[0-9a-f]{16}$/); + expect(rec.body_transformed).toBe(false); + expect(rec.inbound_bytes).toBe(body.length); + // Summary mode: no content_preview + expect(rec.message_sizes[0].content_preview).toBeUndefined(); + done(); + }); + }); + }, + ); + }); + + it('writes content_preview in redacted mode', (done) => { + withIsolatedModule( + { AWF_TOKEN_LOG_DIR: tmpDir, AWF_CAPTURE_BLOCKED_LLM_REQUESTS: 'redacted' }, + (mod) => { + const body = Buffer.from(JSON.stringify({ + model: 'claude-opus-4.7', + messages: [{ role: 'user', content: 'This is the user prompt' }], + })); + + mod.writeBlockedRequestDiag({ + requestId: 'req-redacted', + provider: 'anthropic', + path: '/v1/messages', + guardType: 'ai_credits_limit_exceeded', + guardLogFields: { total_ai_credits: 10.5, max_ai_credits: 10.0 }, + body, + inboundBytes: body.length, + }); + + mod.closeBlockedRequestDiagStream().then(() => { + const lines = readDiagLines(path.join(tmpDir, 'blocked-request-diag.jsonl')); + expect(lines).toHaveLength(1); + const rec = lines[0]; + expect(rec.capture_mode).toBe('redacted'); + expect(rec.message_sizes[0].content_preview).toBe('This is the user prompt'); + done(); + }); + }, + ); + }); + + it('records body_transformed=true when body was changed by a transform', (done) => { + withIsolatedModule( + { AWF_TOKEN_LOG_DIR: tmpDir, AWF_CAPTURE_BLOCKED_LLM_REQUESTS: 'summary' }, + (mod) => { + const originalBody = Buffer.from('{"model":"gpt-4o","messages":[]}'); + const transformedBody = Buffer.from('{"model":"gpt-4o","messages":[],"stream_options":{"include_usage":true}}'); + + mod.writeBlockedRequestDiag({ + requestId: 'req-transform', + provider: 'openai', + path: '/v1/chat/completions', + guardType: 'max_runs_exceeded', + guardLogFields: { invocation_count: 5, max_runs: 5 }, + body: transformedBody, + inboundBytes: originalBody.length, + }); + + mod.closeBlockedRequestDiagStream().then(() => { + const lines = readDiagLines(path.join(tmpDir, 'blocked-request-diag.jsonl')); + expect(lines[0].body_transformed).toBe(true); + expect(lines[0].inbound_bytes).toBe(originalBody.length); + done(); + }); + }, + ); + }); + + it('writes multiple records to the same file', (done) => { + withIsolatedModule( + { AWF_TOKEN_LOG_DIR: tmpDir, AWF_CAPTURE_BLOCKED_LLM_REQUESTS: 'summary' }, + (mod) => { + const body = Buffer.from(JSON.stringify({ model: 'gpt-4o', messages: [] })); + const writeOpts = { + provider: 'openai', + path: '/v1/chat/completions', + guardType: 'effective_tokens_limit_exceeded', + guardLogFields: {}, + body, + inboundBytes: body.length, + }; + + mod.writeBlockedRequestDiag({ ...writeOpts, requestId: 'req-1' }); + mod.writeBlockedRequestDiag({ ...writeOpts, requestId: 'req-2' }); + mod.writeBlockedRequestDiag({ ...writeOpts, requestId: 'req-3' }); + + mod.closeBlockedRequestDiagStream().then(() => { + const lines = readDiagLines(path.join(tmpDir, 'blocked-request-diag.jsonl')); + expect(lines).toHaveLength(3); + expect(lines.map(l => l.request_id)).toEqual(['req-1', 'req-2', 'req-3']); + done(); + }); + }, + ); + }); + + it('does not include content_preview in summary mode', (done) => { + withIsolatedModule( + { AWF_TOKEN_LOG_DIR: tmpDir, AWF_CAPTURE_BLOCKED_LLM_REQUESTS: 'summary' }, + (mod) => { + const body = Buffer.from(JSON.stringify({ + model: 'gpt-4o', + messages: [{ role: 'user', content: 'Top secret system prompt' }], + })); + + mod.writeBlockedRequestDiag({ + requestId: 'req-safe', + provider: 'openai', + path: '/v1/chat/completions', + guardType: 'effective_tokens_limit_exceeded', + guardLogFields: {}, + body, + inboundBytes: body.length, + }); + + mod.closeBlockedRequestDiagStream().then(() => { + const lines = readDiagLines(path.join(tmpDir, 'blocked-request-diag.jsonl')); + const rec = lines[0]; + // No content should appear in summary mode + for (const msg of rec.message_sizes) { + expect(msg.content_preview).toBeUndefined(); + } + // Body full should not appear in summary mode + expect(rec.body_full).toBeUndefined(); + done(); + }); + }, + ); + }); + + it('handles malformed JSON body gracefully', (done) => { + withIsolatedModule( + { AWF_TOKEN_LOG_DIR: tmpDir, AWF_CAPTURE_BLOCKED_LLM_REQUESTS: 'summary' }, + (mod) => { + const body = Buffer.from('not valid json {{{'); + + mod.writeBlockedRequestDiag({ + requestId: 'req-bad-body', + provider: 'openai', + path: '/v1/chat/completions', + guardType: 'effective_tokens_limit_exceeded', + guardLogFields: {}, + body, + inboundBytes: body.length, + }); + + mod.closeBlockedRequestDiagStream().then(() => { + const lines = readDiagLines(path.join(tmpDir, 'blocked-request-diag.jsonl')); + expect(lines).toHaveLength(1); + expect(lines[0].parse_error).toBe(true); + expect(lines[0].body_bytes).toBe(body.length); + done(); + }); + }, + ); + }); +}); + +// ── closeBlockedRequestDiagStream() ────────────────────────────────────────── + +describe('closeBlockedRequestDiagStream()', () => { + it('resolves even when no stream has been opened', async () => { + let mod; + jest.isolateModules(() => { + mod = require('./blocked-request-diagnostics'); + }); + await expect(mod.closeBlockedRequestDiagStream()).resolves.toBeUndefined(); + }); +}); diff --git a/containers/api-proxy/proxy-request.js b/containers/api-proxy/proxy-request.js index 94ab547b8..59411176d 100644 --- a/containers/api-proxy/proxy-request.js +++ b/containers/api-proxy/proxy-request.js @@ -65,6 +65,7 @@ const { getRetiredModelBlockState, buildRetiredModelError, } = require('./guards/retired-model-guard'); +const { writeBlockedRequestDiag } = require('./blocked-request-diagnostics'); // ── Optional token tracker (graceful degradation when not bundled) ──────────── let trackTokenUsage; @@ -371,22 +372,35 @@ function sendGuardBlockedResponse(block, { eventName, buildError, buildLogFields, + body, + inboundBytes, }) { const duration = Date.now() - startTime; + const guardLogFields = buildLogFields(block); metrics.gaugeDec('active_requests', { provider }); metrics.increment('requests_total', { provider, method: req.method, status_class: '4xx' }); metrics.observe('request_duration_ms', duration, { provider }); logRequest('warn', eventName, { request_id: requestId, provider, - ...buildLogFields(block), + ...guardLogFields, }); otel.endSpan(span, statusCode); res.writeHead(statusCode, { 'Content-Type': 'application/json', 'X-Request-ID': requestId }); res.end(JSON.stringify(buildError(block))); + + writeBlockedRequestDiag({ + requestId, + provider, + path: sanitizeForLog(req.url), + guardType: eventName, + guardLogFields, + body: body || Buffer.alloc(0), + inboundBytes: inboundBytes || 0, + }); } -function enforceGuards({ body, provider, req, res, requestId, startTime, span }) { +function enforceGuards({ body, provider, req, res, requestId, startTime, span, inboundBytes }) { const checkModelMultiplier = req.method === 'POST' || req.method === 'PUT' || req.method === 'PATCH'; const guardChecks = [ { @@ -488,6 +502,8 @@ function enforceGuards({ body, provider, req, res, requestId, startTime, span }) eventName: guard.eventName, buildError: guard.buildError, buildLogFields: guard.buildLogFields, + body, + inboundBytes, }); return true; } @@ -709,7 +725,7 @@ function proxyRequest(req, res, targetHost, injectHeaders, provider, basePath = const headers = buildRequestHeaders(body, inboundBytes, req, { injectHeaders, provider, targetHost, requestId }); - if (enforceGuards({ body, provider, req, res, requestId, startTime, span })) return; + if (enforceGuards({ body, provider, req, res, requestId, startTime, span, inboundBytes })) return; sendUpstreamRequest(headers, { body, targetHost, upstreamPath, req, res, provider, requestId, startTime, span, requestBytes, diff --git a/containers/api-proxy/token-persistence.js b/containers/api-proxy/token-persistence.js index 078d464ba..608408ab2 100644 --- a/containers/api-proxy/token-persistence.js +++ b/containers/api-proxy/token-persistence.js @@ -240,19 +240,28 @@ function writeTokenUsage(record) { * Returns a Promise that resolves once the stream has flushed. */ function closeLogStream() { - return new Promise((resolve) => { - let pending = 0; - const check = () => { if (pending === 0) resolve(); }; - if (logStream) { - pending++; - logStream.end(() => { logStream = null; pending--; check(); }); - } - if (diagStream) { - pending++; - diagStream.end(() => { diagStream = null; pending--; check(); }); - } - if (pending === 0) resolve(); - }); + // Also close the blocked-request diagnostics stream if the module is loaded. + let closeBlockedRequestDiagStream = () => Promise.resolve(); + try { + ({ closeBlockedRequestDiagStream } = require('./blocked-request-diagnostics')); + } catch { /* optional module — no-op when absent */ } + + return Promise.all([ + new Promise((resolve) => { + let pending = 0; + const check = () => { if (pending === 0) resolve(); }; + if (logStream) { + pending++; + logStream.end(() => { logStream = null; pending--; check(); }); + } + if (diagStream) { + pending++; + diagStream.end(() => { diagStream = null; pending--; check(); }); + } + if (pending === 0) resolve(); + }), + closeBlockedRequestDiagStream(), + ]).then(() => {}); } module.exports = { diff --git a/docs/awf-config-spec.md b/docs/awf-config-spec.md index 982ae10a8..d44ddd284 100644 --- a/docs/awf-config-spec.md +++ b/docs/awf-config-spec.md @@ -118,6 +118,8 @@ AWF settings MAY be supplied via config files, including stdin (`--config -`). - `apiProxy.models` → *(config-only; model alias rewriting)* - `apiProxy.logging.debugTokens` → *(config-only; maps to `AWF_DEBUG_TOKENS`)* - `apiProxy.logging.tokenLogDir` → *(config-only; maps to `AWF_TOKEN_LOG_DIR`)* +- `apiProxy.diagnostics.captureBlockedRequests` → *(config-only; maps to `AWF_CAPTURE_BLOCKED_LLM_REQUESTS`)* +- `apiProxy.diagnostics.maxCapturedBytes` → *(config-only; maps to `AWF_MAX_BLOCKED_CAPTURE_BYTES`)* - `apiProxy.auth.type` → *(config-only; maps to `AWF_AUTH_TYPE`)* - `apiProxy.auth.provider` → *(config-only; maps to `AWF_AUTH_PROVIDER`)* - `apiProxy.auth.oidcAudience` → *(config-only; maps to `AWF_AUTH_OIDC_AUDIENCE`)* @@ -1232,12 +1234,17 @@ apiProxy: logging: debugTokens: true tokenLogDir: "/var/log/api-proxy" + diagnostics: + captureBlockedRequests: summary # false | summary | redacted | full + maxCapturedBytes: 250000 ``` | Property | Type | Default | Env var | Description | |----------|------|---------|---------|-------------| | `apiProxy.logging.debugTokens` | boolean | `false` | `AWF_DEBUG_TOKENS` | Enable diagnostic token/model-alias logging to file | | `apiProxy.logging.tokenLogDir` | string | `/var/log/api-proxy` | `AWF_TOKEN_LOG_DIR` | Directory for `token-usage.jsonl` and `token-diag.jsonl` | +| `apiProxy.diagnostics.captureBlockedRequests` | string \| boolean | `false` | `AWF_CAPTURE_BLOCKED_LLM_REQUESTS` | Capture body-shape info for guard-blocked requests (`false`/`true`/`summary`/`redacted`/`full`; `true` is an alias for `summary`) | +| `apiProxy.diagnostics.maxCapturedBytes` | integer | `250000` | `AWF_MAX_BLOCKED_CAPTURE_BYTES` | Max bytes per record in `full` capture mode | ### 13.4 Log File Inventory @@ -1268,6 +1275,7 @@ Directory: configured by `apiProxy.logging.tokenLogDir` / `AWF_TOKEN_LOG_DIR` |------|--------|-------------|----------------| | `token-usage.jsonl` | JSONL (`token-usage/v` schema) | Per-API-call token usage and cost records | Yes (when API proxy is active) | | `token-diag.jsonl` | JSONL (`token-diag/v` schema) | Diagnostic events: model resolution steps, alias rewrites, token budget decisions | Only when `apiProxy.logging.debugTokens: true` | +| `blocked-request-diag.jsonl` | JSONL (`blocked-request-diag/v` schema) | Body-shape diagnostics for guard-blocked requests (effective tokens, AI credits, etc.) | Only when `apiProxy.diagnostics.captureBlockedRequests` is set | | `otel.jsonl` | JSONL (OpenTelemetry spans) | Distributed tracing spans; written as local fallback when no OTLP collector is configured | Only when OTEL is active and no collector endpoint set | #### CLI Proxy Logs @@ -1292,6 +1300,92 @@ file mechanism (`token-persistence.js`) was refactored into a dedicated module in v0.25.50 but the logging events and their format have been stable since initial release. +### 13.6 Blocked Request Diagnostics (blocked-request-diag.jsonl) + +When a guard hard-rails a request (e.g. `effective_tokens_limit_exceeded`, +`ai_credits_limit_exceeded`, `max_runs_exceeded`), the api-proxy can write a +structured diagnostic record to `blocked-request-diag.jsonl`. This is +**opt-in and disabled by default**. + +#### Enabling + +Set the environment variable or config key before starting the container: + +```sh +# Minimal (body-shape only, no content): +AWF_CAPTURE_BLOCKED_LLM_REQUESTS=summary + +# Include first 200 chars of each message (for debugging over-large tool results): +AWF_CAPTURE_BLOCKED_LLM_REQUESTS=redacted + +# Full body up to AWF_MAX_BLOCKED_CAPTURE_BYTES (default 250 000 bytes): +AWF_CAPTURE_BLOCKED_LLM_REQUESTS=full +AWF_MAX_BLOCKED_CAPTURE_BYTES=250000 +``` + +Or via config YAML: + +```yaml +apiProxy: + diagnostics: + captureBlockedRequests: summary # false | summary | redacted | full + maxCapturedBytes: 250000 +``` + +#### Capture modes + +| Mode | Content | Use case | +|------|---------|----------| +| `false` (default) | Nothing written | Production default | +| `summary` | Counts, sizes, hashes — **no content** | Safe for normal debugging; identify which message/tool-result was large | +| `redacted` | Summary + first 200 chars per message | Debug prompt growth without full disclosure | +| `full` | Full body up to `maxCapturedBytes` | Local/private runs only; explicitly document and review | + +#### Record format + +Each record follows the `blocked-request-diag/v` schema: + +```json +{ + "_schema": "blocked-request-diag/v0.26.0", + "timestamp": "2025-01-15T10:30:00.000Z", + "event": "blocked_request_diag", + "capture_mode": "summary", + "request_id": "bc446626-a67b-4a78-a8c3-7293a2bc7306", + "provider": "anthropic", + "path": "/v1/messages", + "guard_type": "effective_tokens_limit_exceeded", + "guard_totals": { + "total_effective_tokens": 27198679, + "max_effective_tokens": 25000000 + }, + "body_transformed": true, + "inbound_bytes": 184320, + "body_bytes": 185040, + "body_sha256": "a3f2b1c8d9e0f1a2", + "model": "claude-opus-4.7", + "streaming": true, + "message_count": 52, + "tool_result_count": 14, + "message_sizes": [ + { "role": "user", "content_type": "text", "chars": 312, "bytes": 312, "estimated_tokens": 78 }, + { "role": "assistant", "content_type": "text", "chars": 1840, "bytes": 1840, "estimated_tokens": 460 }, + { "role": "user", "content_type": "tool_result", "chars": 94321, "bytes": 94321, "estimated_tokens": 23580, "tool_blocks": 3 } + ] +} +``` + +#### Security considerations + +- `summary` mode captures **no message content** and is safe for shared/public + workflow runs. +- `redacted` mode includes short previews; review before attaching to public + issues. +- `full` mode captures potentially sensitive prompt and tool-result content. + Use only for private runs and rotate or delete the artifact promptly. +- The file is written to `AWF_TOKEN_LOG_DIR` alongside `token-usage.jsonl` + and is governed by the same artifact-retention policy. + ## Normative References - [RFC 2119](https://www.rfc-editor.org/rfc/rfc2119) — Key words for use in diff --git a/docs/awf-config.schema.json b/docs/awf-config.schema.json index 324548216..cea03d461 100644 --- a/docs/awf-config.schema.json +++ b/docs/awf-config.schema.json @@ -380,6 +380,27 @@ "default": "/var/log/api-proxy" } } + }, + "diagnostics": { + "type": "object", + "description": "Opt-in diagnostics for blocked LLM requests. Writes body-shape records to blocked-request-diag.jsonl when a guard hard-rails a request.", + "additionalProperties": false, + "properties": { + "captureBlockedRequests": { + "description": "Enable capture of body-shape diagnostics for guard-blocked requests. 'summary' captures counts/sizes/hashes only (no content). 'redacted' adds first 200 chars per message. 'full' captures the entire body up to maxCapturedBytes. Maps to AWF_CAPTURE_BLOCKED_LLM_REQUESTS.", + "oneOf": [ + { "type": "boolean" }, + { "type": "string", "enum": ["summary", "redacted", "full"] } + ], + "default": false + }, + "maxCapturedBytes": { + "type": "integer", + "description": "Maximum body bytes to include in a single 'full'-mode blocked-request-diag record. Maps to AWF_MAX_BLOCKED_CAPTURE_BYTES.", + "minimum": 1, + "default": 250000 + } + } } } }, diff --git a/src/awf-config-schema.json b/src/awf-config-schema.json index 324548216..cea03d461 100644 --- a/src/awf-config-schema.json +++ b/src/awf-config-schema.json @@ -380,6 +380,27 @@ "default": "/var/log/api-proxy" } } + }, + "diagnostics": { + "type": "object", + "description": "Opt-in diagnostics for blocked LLM requests. Writes body-shape records to blocked-request-diag.jsonl when a guard hard-rails a request.", + "additionalProperties": false, + "properties": { + "captureBlockedRequests": { + "description": "Enable capture of body-shape diagnostics for guard-blocked requests. 'summary' captures counts/sizes/hashes only (no content). 'redacted' adds first 200 chars per message. 'full' captures the entire body up to maxCapturedBytes. Maps to AWF_CAPTURE_BLOCKED_LLM_REQUESTS.", + "oneOf": [ + { "type": "boolean" }, + { "type": "string", "enum": ["summary", "redacted", "full"] } + ], + "default": false + }, + "maxCapturedBytes": { + "type": "integer", + "description": "Maximum body bytes to include in a single 'full'-mode blocked-request-diag record. Maps to AWF_MAX_BLOCKED_CAPTURE_BYTES.", + "minimum": 1, + "default": 250000 + } + } } } },