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

The default console formatter discarded every structured metadata key on the
winston info object — only `CONSOLE_JSON=true` preserved it. That meant
failures emitted by the agents SDK (e.g. "Summarization LLM call failed")
reached stdout without the provider, model, or underlying error attached,
leaving users unable to diagnose the root cause.

- Add `formatConsoleMeta` helper to serialize non-reserved metadata as a
  compact JSON trailer, with per-value string truncation and safe handling
  of circular references.
- Append the metadata trailer to warn/error console lines; info/debug
  behavior is unchanged.
- Relax `debugTraverse`'s debug-only gate so warn/error messages routed
  through the debug formatter also surface their metadata.
- Add a `formatConsoleMeta` stub to the shared logger mock so existing
  tests keep working.
This commit is contained in:
Danny Avila 2026-04-18 10:44:22 -04:00
parent b579390287
commit 59371be035
4 changed files with 166 additions and 7 deletions

View file

@ -0,0 +1,83 @@
const { formatConsoleMeta } = jest.requireActual('../parsers');
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('');
});
});

View file

@ -96,6 +96,61 @@ 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' && value.length > CONSOLE_JSON_STRING_LENGTH) {
return `${value.substring(0, CONSOLE_JSON_STRING_LENGTH)}...`;
}
return value;
});
} catch {
return '';
}
}
/**
* Formats log messages for debugging purposes.
* - Truncates long strings within log messages.
@ -121,7 +176,9 @@ const debugTraverse = winston.format.printf(({ level, message, timestamp, ...met
let msg = `${timestamp} ${level}: ${truncateLongStrings(message?.trim(), DEBUG_MESSAGE_LENGTH)}`;
try {
if (level !== 'debug') {
const levelStr = typeof level === 'string' ? level : String(level);
const isErrorOrWarn = levelStr.includes('error') || levelStr.includes('warn');
if (level !== 'debug' && !isErrorOrWarn) {
return msg;
}
@ -129,7 +186,7 @@ const debugTraverse = winston.format.printf(({ level, message, timestamp, ...met
return msg;
}
const debugValue = metadata[SPLAT_SYMBOL]?.[0];
const debugValue = metadata[SPLAT_SYMBOL]?.[0] ?? extractMetaObject(metadata);
if (!debugValue) {
return msg;
@ -229,4 +286,5 @@ module.exports = {
redactMessage,
debugTraverse,
jsonTruncateFormat,
formatConsoleMeta,
};

View file

@ -2,7 +2,13 @@ const path = require('path');
const fs = require('fs');
const winston = require('winston');
require('winston-daily-rotate-file');
const { redactFormat, redactMessage, debugTraverse, jsonTruncateFormat } = require('./parsers');
const {
redactFormat,
redactMessage,
debugTraverse,
jsonTruncateFormat,
formatConsoleMeta,
} = require('./parsers');
/**
* Determine the log directory.
@ -110,12 +116,23 @@ const consoleFormat = winston.format.combine(
winston.format.timestamp({ format: 'YYYY-MM-DD HH:mm:ss' }),
// redactErrors(),
winston.format.printf((info) => {
const message = `${info.timestamp} ${info.level}: ${info.message}`;
if (info.level.includes('error')) {
return redactMessage(message);
const base = `${info.timestamp} ${info.level}: ${info.message}`;
const isError = info.level.includes('error');
const isWarn = info.level.includes('warn');
let line = base;
if (isError || isWarn) {
const metaTrailer = formatConsoleMeta(info);
if (metaTrailer) {
line = `${base} ${metaTrailer}`;
}
}
return message;
if (isError) {
return redactMessage(line);
}
return line;
}),
);

View file

@ -56,5 +56,6 @@ jest.mock('~/config/parsers', () => {
redactMessage: jest.fn(),
redactFormat: jest.fn(),
debugTraverse: jest.fn(),
formatConsoleMeta: jest.fn(() => ''),
};
});