feat(api-proxy): add always-on audit trail for token tracking

Add token-tracker-audit.jsonl that unconditionally logs TRACK_START and
TRACK_END events for every tracked request. This provides visibility
into the token tracking lifecycle in CI without requiring
AWF_DEBUG_TOKENS=1.

When token-usage.jsonl is missing, the check-token-usage.js CI script
now prints the audit trail contents to help diagnose why tracking
failed (e.g. whether the tracker was never invoked, or invoked but
failed to extract usage from responses).

The audit trail is minimal (timestamp + event + key metadata) to avoid
significant disk overhead in production.

Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com>

Author: lpcox

containers/api-proxy/token-persistence.js

@@ -16,6 +16,7 @@ const { logRequest } = require('./logging');
 const TOKEN_LOG_DIR = process.env.AWF_TOKEN_LOG_DIR || '/var/log/api-proxy';
 const TOKEN_LOG_FILE = path.join(TOKEN_LOG_DIR, 'token-usage.jsonl');
 const DIAG_LOG_FILE = path.join(TOKEN_LOG_DIR, 'token-diag.jsonl');
+const AUDIT_LOG_FILE = path.join(TOKEN_LOG_DIR, 'token-tracker-audit.jsonl');
 const DIAG_ENABLED = process.env.AWF_DEBUG_TOKENS === '1';
 
 // AWF version used to identify schema version in JSONL records.
@@ -33,6 +34,7 @@ const TOKEN_DIAG_SCHEMA = `token-diag/v${AWF_VERSION || '0.0.0-dev'}`;
 
 let logStream = null;
 let diagStream = null;
+let auditStream = null;
 
 /**
  * Write a diagnostic line to the diagnostics log file.
@@ -72,6 +74,25 @@ function diag(msg, data) {
   } catch { /* best-effort */ }
 }
 
+/**
+ * Always-on audit trail for token tracking lifecycle.
+ *
+ * Writes minimal structured events to token-tracker-audit.jsonl so that CI
+ * failures can be diagnosed without AWF_DEBUG_TOKENS=1.  Each tracked
+ * request emits exactly two lines: TRACK_START and TRACK_END (with result).
+ */
+function auditTrack(event, data) {
+  try {
+    if (!auditStream) {
+      fs.mkdirSync(TOKEN_LOG_DIR, { recursive: true });
+      auditStream = fs.createWriteStream(AUDIT_LOG_FILE, { flags: 'a', mode: 0o644 });
+      auditStream.on('error', () => { auditStream = null; });
+    }
+    const line = { ts: Date.now(), event, ...data };
+    auditStream.write(JSON.stringify(line) + '\n');
+  } catch { /* best-effort */ }
+}
+
 /**
  * Get or create the JSONL append stream for token usage logs.
  * Uses a lazy singleton — created on first write.
@@ -258,6 +279,10 @@ function closeLogStream() {
         pending++;
         diagStream.end(() => { diagStream = null; pending--; check(); });
       }
+      if (auditStream) {
+        pending++;
+        auditStream.end(() => { auditStream = null; pending--; check(); });
+      }
       if (pending === 0) resolve();
     }),
     closeBlockedRequestDiagStream(),
@@ -269,6 +294,7 @@ module.exports = {
   TOKEN_USAGE_SCHEMA,
   TOKEN_DIAG_SCHEMA,
   diag,
+  auditTrack,
   buildTokenDiagRecord,
   buildTokenUsageRecord,
   incrementTokenMetrics,

containers/api-proxy/token-tracker-http.js

@@ -34,6 +34,7 @@ const {
   buildTokenUsageRecord,
   incrementTokenMetrics,
   diag,
+  auditTrack,
 } = require('./token-persistence');
 const { warnCacheReadRollupMismatch, mergeBudgetFields } = require('./token-tracker-shared');
 
@@ -286,6 +287,7 @@ function finalizeHttpTracking(state, proxyRes, opts) {
 
   // Only process successful responses (2xx)
   if (proxyRes.statusCode < 200 || proxyRes.statusCode >= 300) {
+    auditTrack('TRACK_END', { rid: requestId, result: 'skip_status', status: proxyRes.statusCode });
     logRequest('debug', 'token_track_skip_status', {
       request_id: requestId,
       provider,
@@ -314,6 +316,7 @@ function finalizeHttpTracking(state, proxyRes, opts) {
 
   const normalized = normalizeUsage(usage);
   if (!normalized) {
+    auditTrack('TRACK_END', { rid: requestId, result: 'no_usage', streaming, bytes: state.totalBytes, overflow: state.overflow, ct: state.contentType, ce: contentEncoding });
     // Log at info level so failed extraction is visible in CI without debug mode
     logRequest('info', 'token_track_no_usage', {
       request_id: requestId,
@@ -329,6 +332,9 @@ function finalizeHttpTracking(state, proxyRes, opts) {
     if (typeof onSpanEnd === 'function') onSpanEnd(proxyRes.statusCode);
     return;
   }
+
+  auditTrack('TRACK_END', { rid: requestId, result: 'ok', streaming, model: model || requestModel, input: normalized.input_tokens, output: normalized.output_tokens, cache_read: normalized.cache_read_tokens });
+
   if (state.observedCacheReadTokens > 0 && normalized.cache_read_tokens === 0) {
     warnCacheReadRollupMismatch({ logRequest, diag, requestId, provider, model, observedCacheReadTokens: state.observedCacheReadTokens, normalizedCacheReadTokens: normalized.cache_read_tokens, streaming });
   }
@@ -394,6 +400,8 @@ function trackTokenUsage(proxyRes, opts) {
   const contentEncoding = proxyRes.headers['content-encoding'] || '(none)';
   const compressed = isCompressedResponse(proxyRes.headers);
 
+  auditTrack('TRACK_START', { rid: requestId, provider, path: reqPath, streaming, ct: contentType, ce: contentEncoding, status: proxyRes.statusCode });
+
   logRequest('debug', 'token_track_start', {
     request_id: requestId,
     provider,
@@ -410,6 +418,7 @@ function trackTokenUsage(proxyRes, opts) {
   // If the response uses an encoding we cannot decompress (e.g. zstd), skip
   // token tracking entirely and log a warning so the issue is visible in CI.
   if (compressed && isUnsupportedEncoding(proxyRes.headers)) {
+    auditTrack('TRACK_SKIP_ENCODING', { rid: requestId, ce: contentEncoding });
     logRequest('warn', 'token_track_unsupported_encoding', {
       request_id: requestId,
       provider,

containers/api-proxy/token-tracker-ws.js

@@ -16,6 +16,7 @@ const {
   buildTokenUsageRecord,
   incrementTokenMetrics,
   diag,
+  auditTrack,
 } = require('./token-persistence');
 const { warnCacheReadRollupMismatch, mergeBudgetFields } = require('./token-tracker-shared');
 
@@ -135,6 +136,7 @@ function parseWebSocketFrames(buf, fragments) {
 function trackWebSocketTokenUsage(upstreamSocket, opts) {
   const { requestId, provider, path: reqPath, startTime, metrics: metricsRef, onUsage } = opts;
 
+  auditTrack('WS_TRACK_START', { rid: requestId, provider, path: reqPath });
   logRequest('debug', 'ws_token_track_start', {
     request_id: requestId,
     provider,
@@ -213,19 +215,22 @@ function trackWebSocketTokenUsage(upstreamSocket, opts) {
     if (finalized) return;
     finalized = true;
 
+    const hasUsage = Object.keys(streamingUsage).length > 0;
+    auditTrack('WS_TRACK_END', { rid: requestId, result: hasUsage ? 'ok' : 'no_usage', frames: frameCount, msgs: textMessageCount, bytes: totalBytes });
+
     logRequest('debug', 'ws_token_track_end', {
       request_id: requestId,
       provider,
       total_bytes: totalBytes,
       frame_count: frameCount,
       text_message_count: textMessageCount,
-      has_usage: Object.keys(streamingUsage).length > 0,
+      has_usage: hasUsage,
       usage_keys: Object.keys(streamingUsage),
       model: streamingModel,
     });
-    diag('WS_TRACK_END', { request_id: requestId, provider, total_bytes: totalBytes, frame_count: frameCount, text_message_count: textMessageCount, has_usage: Object.keys(streamingUsage).length > 0, usage_keys: Object.keys(streamingUsage), model: streamingModel });
+    diag('WS_TRACK_END', { request_id: requestId, provider, total_bytes: totalBytes, frame_count: frameCount, text_message_count: textMessageCount, has_usage: hasUsage, usage_keys: Object.keys(streamingUsage), model: streamingModel });
 
-    if (Object.keys(streamingUsage).length === 0) return;
+    if (!hasUsage) return;
 
     const duration = Date.now() - startTime;
     const normalized = normalizeUsage(streamingUsage);

containers/api-proxy/token-tracker.schema.test.js

@@ -266,8 +266,9 @@ describe('token-usage JSONL record schema field', () => {
     proxyRes.emit('end');
 
     setTimeout(() => {
-      expect(mockStream.write).toHaveBeenCalledTimes(1);
-      const parsed = mockStream.writtenRecords[0];
+      const usageRecords = mockStream.writtenRecords.filter(r => r._schema);
+      expect(usageRecords).toHaveLength(1);
+      const parsed = usageRecords[0];
       expect(parsed._schema).toMatch(/^token-usage\/v\d+\.\d+\.\d+(-\w+)?$/);
       expect(parsed.request_id).toBe('schema-field-http');
       done();
@@ -289,8 +290,9 @@ describe('token-usage JSONL record schema field', () => {
     socket.emit('close');
 
     setTimeout(() => {
-      expect(mockStream.write).toHaveBeenCalledTimes(1);
-      const parsed = mockStream.writtenRecords[0];
+      const usageRecords = mockStream.writtenRecords.filter(r => r._schema);
+      expect(usageRecords).toHaveLength(1);
+      const parsed = usageRecords[0];
       expect(parsed._schema).toMatch(/^token-usage\/v\d+\.\d+\.\d+(-\w+)?$/);
       expect(parsed.request_id).toBe('schema-field-ws');
       done();
@@ -324,8 +326,9 @@ describe('token-usage JSONL record schema field', () => {
     proxyRes.emit('end');
 
     setTimeout(() => {
-      expect(mockStream.write).toHaveBeenCalledTimes(1);
-      const parsed = mockStream.writtenRecords[0];
+      const usageRecords = mockStream.writtenRecords.filter(r => r._schema);
+      expect(usageRecords).toHaveLength(1);
+      const parsed = usageRecords[0];
       expect(parsed).toMatchObject({
         request_id: 'budget-fields-http',
         effective_tokens_this_response: 40,
@@ -359,8 +362,9 @@ describe('token-usage JSONL record schema field', () => {
     proxyRes.emit('end');
 
     setTimeout(() => {
-      expect(mockStream.write).toHaveBeenCalledTimes(1);
-      const parsed = mockStream.writtenRecords[0];
+      const usageRecords = mockStream.writtenRecords.filter(r => r._schema);
+      expect(usageRecords).toHaveLength(1);
+      const parsed = usageRecords[0];
       expect(parsed.effective_tokens_this_response).toBeUndefined();
       expect(parsed.effective_tokens_total).toBeUndefined();
       expect(parsed.model_multiplier).toBeUndefined();
@@ -392,8 +396,9 @@ describe('token-usage JSONL record schema field', () => {
     socket.emit('close');
 
     setTimeout(() => {
-      expect(mockStream.write).toHaveBeenCalledTimes(1);
-      const parsed = mockStream.writtenRecords[0];
+      const usageRecords = mockStream.writtenRecords.filter(r => r._schema);
+      expect(usageRecords).toHaveLength(1);
+      const parsed = usageRecords[0];
       expect(parsed).toMatchObject({
         request_id: 'budget-fields-ws',
         effective_tokens_this_response: 112,
@@ -422,8 +427,9 @@ describe('token-usage JSONL record schema field', () => {
     socket.emit('close');
 
     setTimeout(() => {
-      expect(mockStream.write).toHaveBeenCalledTimes(1);
-      const parsed = mockStream.writtenRecords[0];
+      const usageRecords = mockStream.writtenRecords.filter(r => r._schema);
+      expect(usageRecords).toHaveLength(1);
+      const parsed = usageRecords[0];
       expect(parsed.effective_tokens_this_response).toBeUndefined();
       expect(parsed.effective_tokens_total).toBeUndefined();
       expect(parsed.model_multiplier).toBeUndefined();
@@ -481,8 +487,9 @@ describe('token-usage _schema exact version from AWF_VERSION', () => {
       writeStreamSpy.mockRestore();
       await isolated.closeLogStream();
 
-      expect(mockStream.write).toHaveBeenCalledTimes(1);
-      const parsed = mockStream.writtenRecords[0];
+      const usageRecords = mockStream.writtenRecords.filter(r => r._schema);
+      expect(usageRecords).toHaveLength(1);
+      const parsed = usageRecords[0];
       expect(parsed._schema).toBe('token-usage/v9.8.7');
       expect(parsed.request_id).toBe('exact-version-test');
       done();

scripts/ci/check-token-usage.js

@@ -282,6 +282,22 @@ function main(argv) {
       '::error::Could not locate token-usage.jsonl in the agent artifact. ' +
         'The api-proxy did not record token usage.',
     );
+    // Print audit trail if available to diagnose why tracking failed
+    const auditFile = findFileRecursive(options.artifactRoot, 'token-tracker-audit.jsonl');
+    if (auditFile) {
+      try {
+        const auditContent = fs.readFileSync(auditFile, 'utf8').trim();
+        const lines = auditContent.split('\n').filter(Boolean);
+        console.error(`\n--- Token tracker audit trail (${lines.length} events) ---`);
+        for (const line of lines.slice(0, 100)) {
+          console.error(`  ${line}`);
+        }
+        if (lines.length > 100) console.error(`  ... (${lines.length - 100} more lines)`);
+        console.error('--- End audit trail ---\n');
+      } catch { /* ignore read errors */ }
+    } else {
+      console.error('  (no token-tracker-audit.jsonl found — tracker may not have been invoked)');
+    }
     return 1;
   }