🧹 fix: Skip Consumed Splat Primitives in Warn/Error Debug Traversal

When no structured metadata is attached, winston still leaves consumed
`%s` / `%d` arguments in `Symbol.for('splat')`. Previous fix preferred
the structured object but still fell back to whatever sat at `SPLAT[0]`
— so `logger.warn('failed for %s', tenantId)` emitted
`failed for tenant-7 tenant-7` in the traversal path (debug file and
`DEBUG_CONSOLE`), now regressed outside of `debug` level because
warn/error share the path.

Only accept the splat fallback when the value is a plain object or an
array (structural data worth surfacing). Primitives there are almost
certainly consumed printf args and get skipped.

Regression tests cover the single-%s case and the array-as-metadata case
(which still surfaces through splat).

Reviewed-by: Codex (P2 finding on PR #12737, commit bccbf117).
This commit is contained in:
Danny Avila 2026-04-18 11:53:21 -04:00
parent bccbf117d6
commit b34628de85
2 changed files with 33 additions and 5 deletions

View file

@ -229,4 +229,29 @@ describe('debugTraverse', () => {
const tenantMatches = out.match(/tenant-7/g) ?? [];
expect(tenantMatches.length).toBeLessThanOrEqual(1);
});
it('does not duplicate a consumed %s arg when there is no structured metadata', () => {
const info = {
level: 'warn',
message: 'failed for tenant-7',
timestamp: 'ts',
[SPLAT_SYMBOL]: ['tenant-7'],
};
const out = runFormatter(info);
const tenantMatches = out.match(/tenant-7/g) ?? [];
expect(tenantMatches.length).toBe(1);
});
it('still surfaces array metadata in SPLAT[0] when no object is extracted', () => {
const info = {
level: 'debug',
message: 'list',
timestamp: 'ts',
[SPLAT_SYMBOL]: [['alpha', 'beta', 'gamma']],
};
const out = runFormatter(info);
expect(out).toContain('alpha');
expect(out).toContain('beta');
expect(out).toContain('gamma');
});
});

View file

@ -189,14 +189,17 @@ const debugTraverse = winston.format.printf(({ level, message, timestamp, ...met
/*
* 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 }`.
* printf arg e.g. `logger.warn('failed for %s', tenant)` leaves
* `tenant` in `SPLAT[0]` after interpolation, and appending it again
* would emit `failed for tenant tenant`. Only fall back to the splat
* entry when it's a non-primitive (array or plain object); a string
* or number there is almost certainly a consumed %s/%d arg.
*/
const extracted = extractMetaObject(metadata);
const splatFirst = metadata[SPLAT_SYMBOL]?.[0];
const debugValue = extracted ?? splatFirst;
const splatUsable =
Array.isArray(splatFirst) || (splatFirst != null && typeof splatFirst === 'object');
const debugValue = extracted ?? (splatUsable ? splatFirst : undefined);
if (!debugValue) {
return finalize(msg);