🔊 fix: Preserve Log Metadata on Console for Warn/Error Levels

api/config/__tests__/parsers.spec.js

@@ -0,0 +1,195 @@
+jest.unmock('winston');
+
+const { formatConsoleMeta, redactMessage, debugTraverse } = jest.requireActual('../parsers');
+const SPLAT_SYMBOL = Symbol.for('splat');
+
+describe('formatConsoleMeta', () => {
+  it('returns empty string when there is no user metadata', () => {
+    expect(
+      formatConsoleMeta({
+        level: 'error',
+        message: 'oops',
+        timestamp: '2026-04-18 02:25:22',
+      }),
+    ).toBe('');
+  });
+
+  it('serializes user-supplied metadata keys', () => {
+    const meta = formatConsoleMeta({
+      level: 'error',
+      message: '[agents:summarize] Summarization LLM call failed',
+      timestamp: '2026-04-18 02:25:22',
+      provider: 'azureOpenAI',
+      model: 'gpt-5.4-mini',
+      messagesToRefineCount: 42,
+    });
+
+    expect(meta).toContain('"provider":"azureOpenAI"');
+    expect(meta).toContain('"model":"gpt-5.4-mini"');
+    expect(meta).toContain('"messagesToRefineCount":42');
+  });
+
+  it('ignores reserved winston keys and underscore-prefixed internals', () => {
+    const meta = formatConsoleMeta({
+      level: 'error',
+      message: 'boom',
+      timestamp: 'ts',
+      splat: [1, 2],
+      _internal: 'skip',
+      userField: 'keep',
+    });
+
+    expect(meta).toBe('{"userField":"keep"}');
+  });
+
+  it('drops empty, null, undefined, function, and symbol values', () => {
+    const meta = formatConsoleMeta({
+      level: 'warn',
+      message: 'noise',
+      timestamp: 'ts',
+      empty: '',
+      nullish: null,
+      undef: undefined,
+      fn: () => 1,
+      sym: Symbol('x'),
+      kept: 'yes',
+    });
+
+    expect(meta).toBe('{"kept":"yes"}');
+  });
+
+  it('truncates very long string values to avoid console spam', () => {
+    const longString = 'x'.repeat(5000);
+    const meta = formatConsoleMeta({
+      level: 'error',
+      message: 'long',
+      timestamp: 'ts',
+      errorStack: longString,
+    });
+
+    expect(meta.length).toBeLessThan(longString.length);
+    expect(meta).toContain('...');
+  });
+
+  it('gracefully handles circular objects', () => {
+    const circular = {};
+    circular.self = circular;
+    const meta = formatConsoleMeta({
+      level: 'error',
+      message: 'circular',
+      timestamp: 'ts',
+      circular,
+    });
+
+    expect(meta).toBe('');
+  });
+
+  it('redacts sensitive patterns inside string metadata values', () => {
+    const meta = formatConsoleMeta({
+      level: 'error',
+      message: 'leak test',
+      timestamp: 'ts',
+      openaiKey: 'sk-abc123def456',
+      auth: 'Bearer eyJhbGciOi...tokenvalue',
+      google: 'https://example.com/?key=AIzaSyXX',
+    });
+
+    expect(meta).not.toContain('sk-abc123def456');
+    expect(meta).not.toContain('eyJhbGciOi...tokenvalue');
+    expect(meta).not.toContain('AIzaSyXX');
+    expect(meta).toContain('sk-[REDACTED]');
+    expect(meta).toContain('Bearer [REDACTED]');
+    expect(meta).toContain('key=[REDACTED]');
+  });
+
+  it('redacts multiple occurrences of the same pattern in one value', () => {
+    const meta = formatConsoleMeta({
+      level: 'error',
+      message: 'two keys',
+      timestamp: 'ts',
+      combined: 'first sk-aaa and then sk-bbb',
+    });
+
+    expect(meta).not.toContain('sk-aaa');
+    expect(meta).not.toContain('sk-bbb');
+    expect(meta.match(/sk-\[REDACTED\]/g)?.length).toBe(2);
+  });
+});
+
+describe('redactMessage', () => {
+  it('redacts sk- keys that are not at line start (inside JSON-like text)', () => {
+    const input = '{"apiKey":"sk-abc123"}';
+    expect(redactMessage(input)).toBe('{"apiKey":"sk-[REDACTED]"}');
+  });
+
+  it('redacts all sk- occurrences in a single pass', () => {
+    const input = 'sk-one sk-two sk-three';
+    expect(redactMessage(input)).toBe('sk-[REDACTED] sk-[REDACTED] sk-[REDACTED]');
+  });
+
+  it('trims redacted output when trimLength is provided', () => {
+    const input = 'Bearer supersecretvalue';
+    expect(redactMessage(input, 10)).toBe('Bearer [RE...');
+  });
+
+  it('returns empty string for falsy input', () => {
+    expect(redactMessage('')).toBe('');
+    expect(redactMessage(undefined)).toBe('');
+  });
+
+  it('does not redact ordinary words that contain "sk-" inside them', () => {
+    expect(redactMessage('task-runner failed')).toBe('task-runner failed');
+    expect(redactMessage('mask-value computed')).toBe('mask-value computed');
+    expect(redactMessage('desk-lamp is on')).toBe('desk-lamp is on');
+  });
+
+  it('does not redact words that contain "key=" inside them', () => {
+    expect(redactMessage('monkey=10 bananas')).toBe('monkey=10 bananas');
+  });
+
+  it('still redacts standalone sk- keys at word boundaries', () => {
+    expect(redactMessage('token: sk-abc123def')).toBe('token: sk-[REDACTED]');
+    expect(redactMessage('"sk-abc123def"')).toBe('"sk-[REDACTED]"');
+  });
+});
+
+describe('debugTraverse', () => {
+  const runFormatter = (info) => {
+    const transformed = debugTraverse.transform(info);
+    const MESSAGE = Symbol.for('message');
+    if (transformed && typeof transformed === 'object') {
+      return transformed[MESSAGE] ?? String(transformed);
+    }
+    return String(transformed);
+  };
+
+  const buildInfo = (level, meta) => {
+    const info = {
+      level,
+      message: 'test',
+      timestamp: 'ts',
+      ...meta,
+    };
+    info[SPLAT_SYMBOL] = [meta];
+    return info;
+  };
+
+  it('redacts sensitive strings in metadata for error level', () => {
+    const out = runFormatter(buildInfo('error', { auth: 'Bearer eyJabc123', openai: 'sk-abc123' }));
+    expect(out).not.toContain('eyJabc123');
+    expect(out).not.toContain('sk-abc123');
+    expect(out).toContain('Bearer [REDACTED]');
+    expect(out).toContain('sk-[REDACTED]');
+  });
+
+  it('redacts sensitive strings in metadata for warn level', () => {
+    const out = runFormatter(buildInfo('warn', { header: 'Bearer supersecrettoken' }));
+    expect(out).not.toContain('supersecrettoken');
+    expect(out).toContain('Bearer [REDACTED]');
+  });
+
+  it('preserves debug-level metadata unmodified (existing behavior)', () => {
+    const out = runFormatter(buildInfo('debug', { someField: 'not-sensitive' }));
+    expect(out).toContain('not-sensitive');
+  });
+});

api/config/parsers.js

@@ -8,26 +8,15 @@ const CONSOLE_JSON_STRING_LENGTH = parseInt(process.env.CONSOLE_JSON_STRING_LENG
 const DEBUG_MESSAGE_LENGTH = parseInt(process.env.DEBUG_MESSAGE_LENGTH) || 150;
 
 const sensitiveKeys = [
-  /^(sk-)[^\s]+/, // OpenAI API key pattern
-  /(Bearer )[^\s]+/, // Header: Bearer token pattern
-  /(api-key:? )[^\s]+/, // Header: API key pattern
-  /(key=)[^\s]+/, // URL query param: sensitive key pattern (Google)
+  // OpenAI API key: `sk-` at a word boundary, followed by the documented
+  // charset for keys. `\b` keeps `task-runner`, `mask-value`, etc. from
+  // being mis-redacted.
+  /\b(sk-)[a-zA-Z0-9_-]+/g,
+  /\b(Bearer )[^\s"']+/g, // Header: Bearer token pattern
+  /\b(api-key:? )[^\s"']+/g, // Header: API key pattern
+  /\b(key=)[^\s"'&]+/g, // URL query param: sensitive key pattern (Google)
 ];
 
-/**
- * Determines if a given value string is sensitive and returns matching regex patterns.
- *
- * @param {string} valueStr - The value string to check.
- * @returns {Array<RegExp>} An array of regex patterns that match the value string.
- */
-function getMatchingSensitivePatterns(valueStr) {
-  if (valueStr) {
-    // Filter and return all regex patterns that match the value string
-    return sensitiveKeys.filter((regex) => regex.test(valueStr));
-  }
-  return [];
-}
-
 /**
  * Redacts sensitive information from a console message and trims it to a specified length if provided.
  * @param {string} str - The console message to be redacted.
@@ -39,16 +28,16 @@ function redactMessage(str, trimLength) {
     return '';
   }
 
-  const patterns = getMatchingSensitivePatterns(str);
-  patterns.forEach((pattern) => {
-    str = str.replace(pattern, '$1[REDACTED]');
-  });
+  let redacted = str;
+  for (const pattern of sensitiveKeys) {
+    redacted = redacted.replace(pattern, '$1[REDACTED]');
+  }
 
-  if (trimLength !== undefined && str.length > trimLength) {
-    return `${str.substring(0, trimLength)}...`;
+  if (trimLength !== undefined && redacted.length > trimLength) {
+    return `${redacted.substring(0, trimLength)}...`;
   }
 
-  return str;
+  return redacted;
 }
 
 /**
@@ -96,6 +85,64 @@ const condenseArray = (item) => {
   return item;
 };
 
+const RESERVED_LOG_KEYS = new Set(['level', 'message', 'timestamp', 'splat']);
+
+/**
+ * Extracts user-supplied metadata from a winston info object, filtering out
+ * reserved keys, internal underscore-prefixed keys, and non-serializable values.
+ *
+ * @param {Record<string, unknown>} source - The object to extract metadata from.
+ * @returns {Record<string, unknown> | undefined} - The extracted metadata, or undefined if empty.
+ */
+function extractMetaObject(source) {
+  if (source == null || typeof source !== 'object') {
+    return undefined;
+  }
+  const meta = {};
+  for (const key of Object.keys(source)) {
+    if (RESERVED_LOG_KEYS.has(key) || key.startsWith('_')) {
+      continue;
+    }
+    const value = source[key];
+    if (value === undefined || value === null || value === '') {
+      continue;
+    }
+    if (typeof value === 'function' || typeof value === 'symbol') {
+      continue;
+    }
+    meta[key] = value;
+  }
+  return Object.keys(meta).length > 0 ? meta : undefined;
+}
+
+/**
+ * Formats the metadata portion of a winston info object as a compact
+ * single-line JSON trailer, suitable for appending to the console message.
+ * Returns an empty string when there is no meaningful metadata.
+ *
+ * @param {Record<string, unknown>} info - The winston info object.
+ * @returns {string} - The serialized metadata, or an empty string.
+ */
+function formatConsoleMeta(info) {
+  const meta = extractMetaObject(info);
+  if (!meta) {
+    return '';
+  }
+  try {
+    return JSON.stringify(meta, (_key, value) => {
+      if (typeof value !== 'string') {
+        return value;
+      }
+      const safe = redactMessage(value);
+      return safe.length > CONSOLE_JSON_STRING_LENGTH
+        ? `${safe.substring(0, CONSOLE_JSON_STRING_LENGTH)}...`
+        : safe;
+    });
+  } catch {
+    return '';
+  }
+}
+
 /**
  * Formats log messages for debugging purposes.
  * - Truncates long strings within log messages.
@@ -120,28 +167,31 @@ const debugTraverse = winston.format.printf(({ level, message, timestamp, ...met
   }
 
   let msg = `${timestamp} ${level}: ${truncateLongStrings(message?.trim(), DEBUG_MESSAGE_LENGTH)}`;
+  const levelStr = typeof level === 'string' ? level : String(level);
+  const isErrorOrWarn = levelStr.includes('error') || levelStr.includes('warn');
+  const finalize = (text) => (isErrorOrWarn ? redactMessage(text) : text);
   try {
-    if (level !== 'debug') {
-      return msg;
+    if (level !== 'debug' && !isErrorOrWarn) {
+      return finalize(msg);
     }
 
     if (!metadata) {
-      return msg;
+      return finalize(msg);
     }
 
-    const debugValue = metadata[SPLAT_SYMBOL]?.[0];
+    const debugValue = metadata[SPLAT_SYMBOL]?.[0] ?? extractMetaObject(metadata);
 
     if (!debugValue) {
-      return msg;
+      return finalize(msg);
     }
 
     if (debugValue && Array.isArray(debugValue)) {
       msg += `\n${JSON.stringify(debugValue.map(condenseArray))}`;
-      return msg;
+      return finalize(msg);
     }
 
     if (typeof debugValue !== 'object') {
-      return (msg += ` ${debugValue}`);
+      return finalize((msg += ` ${debugValue}`));
     }
 
     msg += '\n{';
@@ -182,9 +232,9 @@ const debugTraverse = winston.format.printf(({ level, message, timestamp, ...met
     });
 
     msg += '\n}';
-    return msg;
+    return finalize(msg);
   } catch (e) {
-    return (msg += `\n[LOGGER PARSING ERROR] ${e.message}`);
+    return finalize((msg += `\n[LOGGER PARSING ERROR] ${e.message}`));
   }
 });
 
@@ -229,4 +279,5 @@ module.exports = {
   redactMessage,
   debugTraverse,
   jsonTruncateFormat,
+  formatConsoleMeta,
 };