From bccbf117d662389f282f6fd104d63f86f1b72af2 Mon Sep 17 00:00:00 2001 From: Danny Avila Date: Sat, 18 Apr 2026 11:47:23 -0400 Subject: [PATCH] =?UTF-8?q?=F0=9F=A7=B9=20fix:=20Prefer=20Structured=20Met?= =?UTF-8?q?adata=20Over=20Consumed=20Splat=20Args=20in=20Traversal?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `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). --- api/config/__tests__/parsers.spec.js | 14 ++++++++++++++ api/config/parsers.js | 12 +++++++++++- 2 files changed, 25 insertions(+), 1 deletion(-) diff --git a/api/config/__tests__/parsers.spec.js b/api/config/__tests__/parsers.spec.js index db2a0dea65..678796c9c1 100644 --- a/api/config/__tests__/parsers.spec.js +++ b/api/config/__tests__/parsers.spec.js @@ -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); + }); }); diff --git a/api/config/parsers.js b/api/config/parsers.js index 29caf79bfe..868814fc4e 100644 --- a/api/config/parsers.js +++ b/api/config/parsers.js @@ -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);