🧹 fix: Prefer Structured Metadata Over Consumed Splat Args in Traversal

`debugTraverse` previously read `metadata[Symbol.for('splat')][0]` first
and only fell back to the structured metadata object. When a caller uses
printf interpolation alongside a metadata object — for example
`logger.warn('failed for %s', tenant, { provider })` — winston leaves the
*consumed* positional arg (`tenant`) in `SPLAT[0]` after interpolation.
The formatter would then append the tenant a second time and skip the
real metadata, regressing debug-file and `DEBUG_CONSOLE` output quality
now that warn/error share this path.

Prefer the structured metadata object (via `extractMetaObject`) and only
fall back to `SPLAT[0]` when there's nothing else, so the surviving log
line surfaces the actual key/value pairs regardless of call shape.

Reviewed-by: Codex (P2 finding on PR #12737, commit 1e43d636).
This commit is contained in:
Danny Avila 2026-04-18 11:47:23 -04:00
parent 1e43d63687
commit bccbf117d6
2 changed files with 25 additions and 1 deletions

View file

@ -215,4 +215,18 @@ describe('debugTraverse', () => {
const out = runFormatter(buildInfo('debug', { someField: 'not-sensitive' }));
expect(out).toContain('not-sensitive');
});
it('prefers structured metadata over a consumed printf arg in SPLAT[0]', () => {
const info = {
level: 'warn',
message: 'failed for tenant-7',
timestamp: 'ts',
provider: 'openai',
[SPLAT_SYMBOL]: ['tenant-7', { provider: 'openai' }],
};
const out = runFormatter(info);
expect(out).toContain('openai');
const tenantMatches = out.match(/tenant-7/g) ?? [];
expect(tenantMatches.length).toBeLessThanOrEqual(1);
});
});

View file

@ -186,7 +186,17 @@ const debugTraverse = winston.format.printf(({ level, message, timestamp, ...met
return finalize(msg);
}
const debugValue = metadata[SPLAT_SYMBOL]?.[0] ?? extractMetaObject(metadata);
/*
* Prefer the structured metadata object (which winston merges into info)
* over `SPLAT_SYMBOL[0]`. The first splat entry may be a *consumed*
* printf arg e.g. `logger.warn('failed for %s', tenant, { provider })`
* leaves `tenant` in `SPLAT[0]` after interpolation, which would then
* be appended again to the line instead of surfacing the real metadata
* object `{ provider }`.
*/
const extracted = extractMetaObject(metadata);
const splatFirst = metadata[SPLAT_SYMBOL]?.[0];
const debugValue = extracted ?? splatFirst;
if (!debugValue) {
return finalize(msg);