mirror of
https://github.com/danny-avila/LibreChat.git
synced 2026-10-21 01:22:54 +00:00
🧹 refactor: Split Warn/Error From Debug-Level Traversal in Parsers
Retrofitting `debugTraverse`'s multi-line object walker to cover
warn/error created a minefield of splat-interaction edge cases
(numeric artifacts, consumed %s args, bogus `_`-prefix filtering,
over-eager suppression of unconsumed primitives). Each fix kept
introducing new corner cases.
Split the two concerns instead:
- Warn/error now emit a compact single-line JSON metadata trailer via
`formatConsoleMeta`, then pass the full line through `redactMessage`.
This mirrors what the console formatter already does, so behavior
between the console and debug-file outputs stays consistent for
warn/error — and none of the splat/traversal edge cases apply.
- Debug level keeps its original code path verbatim (including the
raw `metadata` traversal and SPLAT\[0\] fallback). No regressions from
my earlier iterations.
- `extractMetaObject` no longer filters underscore-prefixed keys, so
legitimate fields like MongoDB `_id` still appear. Reserved winston
keys and numeric splat artifacts remain filtered.
Updated tests reflect the simpler contract (underscore preservation,
single-line trailer expectations already covered).
Reviewed-by: Codex (two P2 findings on PR #12737, commit 9ea11529:
`_id` regression and over-eager primitive suppression).
This commit is contained in:
parent
9ea11529f0
commit
d63742a5cb
2 changed files with 35 additions and 51 deletions
|
|
@ -30,17 +30,19 @@ describe('formatConsoleMeta', () => {
|
||||||
expect(meta).toContain('"messagesToRefineCount":42');
|
expect(meta).toContain('"messagesToRefineCount":42');
|
||||||
});
|
});
|
||||||
|
|
||||||
it('ignores reserved winston keys and underscore-prefixed internals', () => {
|
it('ignores reserved winston keys but preserves legitimate fields like _id', () => {
|
||||||
const meta = formatConsoleMeta({
|
const meta = formatConsoleMeta({
|
||||||
level: 'error',
|
level: 'error',
|
||||||
message: 'boom',
|
message: 'boom',
|
||||||
timestamp: 'ts',
|
timestamp: 'ts',
|
||||||
splat: [1, 2],
|
splat: [1, 2],
|
||||||
_internal: 'skip',
|
_id: '507f191e810c19729de860ea',
|
||||||
userField: 'keep',
|
userField: 'keep',
|
||||||
});
|
});
|
||||||
|
|
||||||
expect(meta).toBe('{"userField":"keep"}');
|
expect(meta).toContain('"_id":"507f191e810c19729de860ea"');
|
||||||
|
expect(meta).toContain('"userField":"keep"');
|
||||||
|
expect(meta).not.toContain('"splat"');
|
||||||
});
|
});
|
||||||
|
|
||||||
it('drops numeric-index-like keys (splat artifacts from primitive args)', () => {
|
it('drops numeric-index-like keys (splat artifacts from primitive args)', () => {
|
||||||
|
|
|
||||||
|
|
@ -107,15 +107,17 @@ function extractMetaObject(source) {
|
||||||
}
|
}
|
||||||
const meta = {};
|
const meta = {};
|
||||||
for (const key of Object.keys(source)) {
|
for (const key of Object.keys(source)) {
|
||||||
if (RESERVED_LOG_KEYS.has(key) || key.startsWith('_')) {
|
if (RESERVED_LOG_KEYS.has(key)) {
|
||||||
continue;
|
continue;
|
||||||
}
|
}
|
||||||
/*
|
/*
|
||||||
* Skip numeric-index-like keys. When a caller passes a primitive as
|
* Skip numeric-index-like keys. When a caller passes a primitive as
|
||||||
* the second argument to `logger.warn/error`, `format.splat()` can
|
* the second argument to `logger.warn/error`, `format.splat()` can
|
||||||
* leave character-index keys ("0", "1", ...) on `info`. Those are
|
* leave character-index keys ("0", "1", ...) on `info`. Those are
|
||||||
* synthetic splat artifacts, not real metadata, and would otherwise
|
* synthetic splat artifacts, not real metadata.
|
||||||
* produce noisy output now that warn/error share this path.
|
*
|
||||||
|
* Note: we intentionally do NOT filter keys starting with `_`, since
|
||||||
|
* legitimate fields like MongoDB `_id` use that prefix.
|
||||||
*/
|
*/
|
||||||
if (/^\d+$/.test(key)) {
|
if (/^\d+$/.test(key)) {
|
||||||
continue;
|
continue;
|
||||||
|
|
@ -186,68 +188,48 @@ const debugTraverse = winston.format.printf(({ level, message, timestamp, ...met
|
||||||
let msg = `${timestamp} ${level}: ${truncateLongStrings(message?.trim(), DEBUG_MESSAGE_LENGTH)}`;
|
let msg = `${timestamp} ${level}: ${truncateLongStrings(message?.trim(), DEBUG_MESSAGE_LENGTH)}`;
|
||||||
const levelStr = typeof level === 'string' ? level : String(level);
|
const levelStr = typeof level === 'string' ? level : String(level);
|
||||||
const isErrorOrWarn = levelStr.includes('error') || levelStr.includes('warn');
|
const isErrorOrWarn = levelStr.includes('error') || levelStr.includes('warn');
|
||||||
const finalize = (text) => (isErrorOrWarn ? redactMessage(text) : text);
|
|
||||||
|
/*
|
||||||
|
* Warn/error follow a simpler code path: append a single-line JSON
|
||||||
|
* metadata trailer (same shape as the console formatter) and pass the
|
||||||
|
* result through `redactMessage`. The complex object-traversal below is
|
||||||
|
* kept for debug level only, where detailed multi-line output is the
|
||||||
|
* intended behavior and its splat/interpolation interactions were
|
||||||
|
* already tolerated.
|
||||||
|
*/
|
||||||
|
if (isErrorOrWarn) {
|
||||||
|
const trailer = formatConsoleMeta(metadata);
|
||||||
|
const line = trailer ? `${msg} ${trailer}` : msg;
|
||||||
|
return redactMessage(line);
|
||||||
|
}
|
||||||
|
|
||||||
try {
|
try {
|
||||||
if (level !== 'debug' && !isErrorOrWarn) {
|
if (level !== 'debug') {
|
||||||
return finalize(msg);
|
return msg;
|
||||||
}
|
}
|
||||||
|
|
||||||
if (!metadata) {
|
if (!metadata) {
|
||||||
return finalize(msg);
|
return msg;
|
||||||
}
|
}
|
||||||
|
|
||||||
/*
|
const debugValue = metadata[SPLAT_SYMBOL]?.[0];
|
||||||
* Prefer the structured metadata object (which winston merges into info)
|
|
||||||
* over `SPLAT_SYMBOL[0]`. For primitive splat values, skip only if the
|
|
||||||
* value already appears in the interpolated message (i.e. `%s`/`%d`
|
|
||||||
* consumed it) — `logger.warn('failed for %s', tenant)` leaves `tenant`
|
|
||||||
* in `SPLAT[0]` after interpolation and would otherwise be appended a
|
|
||||||
* second time. Unconsumed primitives like
|
|
||||||
* `logger.debug('prefix:', detail)` still surface.
|
|
||||||
*/
|
|
||||||
const extracted = extractMetaObject(metadata);
|
|
||||||
const splatFirst = metadata[SPLAT_SYMBOL]?.[0];
|
|
||||||
const splatUsable = (() => {
|
|
||||||
if (splatFirst == null) {
|
|
||||||
return false;
|
|
||||||
}
|
|
||||||
if (Array.isArray(splatFirst) || typeof splatFirst === 'object') {
|
|
||||||
return true;
|
|
||||||
}
|
|
||||||
if (
|
|
||||||
typeof splatFirst === 'string' ||
|
|
||||||
typeof splatFirst === 'number' ||
|
|
||||||
typeof splatFirst === 'boolean'
|
|
||||||
) {
|
|
||||||
const splatStr = String(splatFirst);
|
|
||||||
return splatStr !== '' && !message.includes(splatStr);
|
|
||||||
}
|
|
||||||
return false;
|
|
||||||
})();
|
|
||||||
const debugValue = extracted ?? (splatUsable ? splatFirst : undefined);
|
|
||||||
|
|
||||||
if (!debugValue) {
|
if (!debugValue) {
|
||||||
return finalize(msg);
|
return msg;
|
||||||
}
|
}
|
||||||
|
|
||||||
if (debugValue && Array.isArray(debugValue)) {
|
if (debugValue && Array.isArray(debugValue)) {
|
||||||
msg += `\n${JSON.stringify(debugValue.map(condenseArray))}`;
|
msg += `\n${JSON.stringify(debugValue.map(condenseArray))}`;
|
||||||
return finalize(msg);
|
return msg;
|
||||||
}
|
}
|
||||||
|
|
||||||
if (typeof debugValue !== 'object') {
|
if (typeof debugValue !== 'object') {
|
||||||
return finalize((msg += ` ${debugValue}`));
|
return (msg += ` ${debugValue}`);
|
||||||
}
|
}
|
||||||
|
|
||||||
msg += '\n{';
|
msg += '\n{';
|
||||||
|
|
||||||
/*
|
const copy = klona(metadata);
|
||||||
* Traverse the filtered metadata (`debugValue`), not the raw `metadata`
|
|
||||||
* object. `extractMetaObject` strips reserved keys, underscore-prefixed
|
|
||||||
* internals, and numeric-string splat artifacts — re-reading from raw
|
|
||||||
* `metadata` here would put those artifacts back into the output.
|
|
||||||
*/
|
|
||||||
const copy = klona(debugValue);
|
|
||||||
traverse(copy).forEach(function (value) {
|
traverse(copy).forEach(function (value) {
|
||||||
if (typeof this?.key === 'symbol') {
|
if (typeof this?.key === 'symbol') {
|
||||||
return;
|
return;
|
||||||
|
|
@ -283,9 +265,9 @@ const debugTraverse = winston.format.printf(({ level, message, timestamp, ...met
|
||||||
});
|
});
|
||||||
|
|
||||||
msg += '\n}';
|
msg += '\n}';
|
||||||
return finalize(msg);
|
return msg;
|
||||||
} catch (e) {
|
} catch (e) {
|
||||||
return finalize((msg += `\n[LOGGER PARSING ERROR] ${e.message}`));
|
return (msg += `\n[LOGGER PARSING ERROR] ${e.message}`);
|
||||||
}
|
}
|
||||||
});
|
});
|
||||||
|
|
||||||
|
|
|
||||||
Loading…
Add table
Add a link
Reference in a new issue