Skip to content

Commit 4dfa369

Browse files
os-zhuangclaude
andauthored
fix(objectql): drop the caller value MySQL inlines in its duplicate-entry diagnostic (#8823) (#9162)
The #8682 statement cut keeps the database's own diagnostic because it names the failing identifier. MySQL's ER_DUP_ENTRY prints the conflicting VALUE in that diagnostic instead, so it survived the cut into the server log. The tail is still kept, index name included; only the value slot is replaced. Also closes the fragment a value containing " - " used to leave behind. Co-authored-by: Claude <noreply@anthropic.com>
1 parent bc03179 commit 4dfa369

3 files changed

Lines changed: 327 additions & 8 deletions

File tree

Lines changed: 25 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,25 @@
1+
---
2+
"@objectstack/objectql": patch
3+
---
4+
5+
Keep a caller's value out of the server log when MySQL reports a duplicate entry
6+
7+
The driver-fault redaction added for #8682 replaces the bound statement in a logged
8+
write fault and keeps the database's own diagnostic, because that diagnostic names the
9+
failing identifier an operator needs. On MySQL's `ER_DUP_ENTRY` (1062) that premise does
10+
not hold: the template is `Duplicate entry '<value>' for key '<index>'`, so the
11+
conflicting value is in the diagnostic rather than in the statement and survived the cut.
12+
13+
The tail is still kept — including `for key '<index>'`, which is the answer to "which
14+
constraint?" — and only the value slot is replaced:
15+
16+
```
17+
before Duplicate entry 'acme@example.com' for key 'crm_account.email' [statement and bound values redacted]
18+
after Duplicate entry [value redacted] for key 'crm_account.email' [statement and bound values redacted]
19+
```
20+
21+
Also closed: a value spelled with `" - "` in it used to leave a fragment behind, because
22+
the statement cut takes the last separator and that separator was inside the value.
23+
24+
Identifier-bearing diagnostics on every dialect are unchanged, the rethrown error is
25+
untouched, and no HTTP response moves — this narrows one log slot only.

packages/objectql/src/driver-fault-redaction.test.ts

Lines changed: 162 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -100,6 +100,107 @@ describe('redactStatementFromMessage', () => {
100100
});
101101
});
102102

103+
// #8823 — the tail is kept because it names IDENTIFIERS, and on MySQL's
104+
// duplicate-entry family it does not: `ER_DUP_ENTRY` prints the conflicting
105+
// VALUE in the diagnostic itself. These cases pin both halves of the remedy —
106+
// the value goes, the index name stays — because a fix that blanked the tail
107+
// would trade away exactly the debuggability #8682 paid for.
108+
//
109+
// ⛔ Not a demonstrated deployment leak: no live MySQL server was measured.
110+
// The inputs are this repo's own recorded mysql2 phrasings
111+
// (`packages/types/src/unique-violation.ts`) in knex's documented shape.
112+
describe('#8823 — a caller value inlined in the diagnostic itself', () => {
113+
const EMAIL = 'acme@example.com';
114+
const BOUND_DUP_ENTRY =
115+
'insert into `crm_account` (`email`, `name`) values '
116+
+ `('${EMAIL}', 'Acme')`
117+
+ ` - Duplicate entry '${EMAIL}' for key 'crm_account.email'`;
118+
119+
it('drops the conflicting value and keeps the index the operator needs', () => {
120+
const out = redactStatementFromMessage(BOUND_DUP_ENTRY);
121+
122+
expect(out).not.toContain(EMAIL);
123+
// The index name is the answer to "which constraint?" and survives whole.
124+
expect(out).toContain("for key 'crm_account.email'");
125+
// Still legibly MySQL's own diagnostic, not a blanked tail.
126+
expect(out).toContain('Duplicate entry');
127+
expect(out).toBe(
128+
"Duplicate entry [value redacted] for key 'crm_account.email' [statement and bound values redacted]",
129+
);
130+
});
131+
132+
it('redacts a BARE diagnostic too — the shape that reaches us without a statement', () => {
133+
// Before #9030 the shared leak predicate did not recognise this phrasing,
134+
// so a bare `Duplicate entry …` was turned away at the door and kept its
135+
// value. That limb landed for a different reason; the two compose here.
136+
const out = redactStatementFromMessage(`Duplicate entry '${EMAIL}' for key 'crm_account.email'`);
137+
138+
expect(out).not.toContain(EMAIL);
139+
expect(out).toBe("Duplicate entry [value redacted] for key 'crm_account.email'");
140+
// No statement was present, so the entry must not claim one was removed.
141+
expect(out).not.toContain('[statement and bound values redacted]');
142+
});
143+
144+
it('leaves no fragment when the value itself contained " - "', () => {
145+
// The statement cut takes the LAST separator, which lands INSIDE a value
146+
// spelled like this — measured on the shipped function, it logged
147+
// `Q3 plan' for key 't.label'`. The words are not reconstructed: an anchor
148+
// is evidence about the value, not licence to assert the template.
149+
const out = redactStatementFromMessage(
150+
"insert into `t` (`label`) values ('2026 - Q3 plan')"
151+
+ " - Duplicate entry '2026 - Q3 plan' for key 't.label'",
152+
);
153+
154+
expect(out).not.toContain('Q3 plan');
155+
expect(out).not.toContain('2026');
156+
expect(out).toContain("for key 't.label'");
157+
});
158+
159+
it.each([
160+
["an unescaped quote in the value", "Duplicate entry 'O'Brien' for key 't.name'", 'Brien', "for key 't.name'"],
161+
['a composite key value', "Duplicate entry 'acme-x' for key 't.idx_a_b'", 'acme-x', "for key 't.idx_a_b'"],
162+
['the PRIMARY key', "Duplicate entry 'r1' for key 'PRIMARY'", "'r1'", "for key 'PRIMARY'"],
163+
// Ambiguous: the value may itself contain the anchor. Resolving to the LAST
164+
// anchor discards more, which is the only direction that cannot leak.
165+
['a value that mimics the anchor', "Duplicate entry 'a' for key 'b' for key 't.n'", "for key 'b'", "for key 't.n'"],
166+
])('%s', (_shape, diagnostic, gone, kept) => {
167+
const out = redactStatementFromMessage(`insert into \`t\` (\`c\`) values ('v') - ${diagnostic}`);
168+
169+
expect(out).not.toContain(gone);
170+
expect(out).toContain(kept);
171+
expect(out).toContain('[value redacted]');
172+
});
173+
174+
it('leaves every IDENTIFIER-bearing tail exactly as it was', () => {
175+
// The other three dialect shapes the card measured, plus the MySQL family
176+
// that names a column rather than a value. Redacting these would be the
177+
// regression #8682's triage warned about, not a fix.
178+
for (const [statement, diagnostic] of [
179+
["insert into `t` (`c`) values ('v')", "Unknown column 'zzz' in 'field list'"],
180+
["insert into `t` (`c`) values ('v')", 'UNIQUE constraint failed: crm_account.email'],
181+
['insert into "t" ("c") values (\'v\')', 'duplicate key value violates unique constraint "crm_account_email_key"'],
182+
["insert into `t` (`c`) values ('v')", 'NOT NULL constraint failed: sys_team.organization_id'],
183+
]) {
184+
const out = redactStatementFromMessage(`${statement} - ${diagnostic}`);
185+
186+
expect(out).toBe(`${diagnostic} [statement and bound values redacted]`);
187+
expect(out).not.toContain('[value redacted]');
188+
}
189+
});
190+
191+
it('does not reach into a bound value that merely looks like the template', () => {
192+
// The templates are read only AFTER the cut, where nothing but the
193+
// database's own words is left — so a caller storing this text in a column
194+
// cannot steer what survives.
195+
const out = redactStatementFromMessage(
196+
"insert into `t` (`note`) values ('Duplicate entry \\'x\\' for key \\'k\\'')"
197+
+ ' - table t has no column named note',
198+
);
199+
200+
expect(out).toBe('table t has no column named note [statement and bound values redacted]');
201+
});
202+
});
203+
103204
describe('redactBoundStatement', () => {
104205
it('redacts `stack` too — the statement opened it a second time', () => {
105206
const original = new Error(BOUND_INSERT);
@@ -167,7 +268,18 @@ describe('#8682 half B — the write-path loggers', () => {
167268
return logger;
168269
}
169270

170-
async function insertAgainstADriftedColumn() {
271+
/**
272+
* The one driver double in this file. #8823 needed a MySQL-shaped fault and
273+
* the shape is a PARAMETER rather than a second double — one fake engine per
274+
* file keeps the contract the double implements reviewable in one place.
275+
*/
276+
const DRIFTED_COLUMN = {
277+
name: 'SqliteError',
278+
code: 'SQLITE_ERROR',
279+
diagnostic: (object: string) => `table ${object} has no column named secret_note`,
280+
};
281+
282+
async function insertAgainstADriftedColumn(fault = DRIFTED_COLUMN) {
171283
const logger = makeCapturingLogger();
172284
const engine = new ObjectQL({ logger });
173285
const driver: any = {
@@ -178,10 +290,11 @@ describe('#8682 half B — the write-path loggers', () => {
178290
async create(object: string, data: Record<string, unknown>) {
179291
const cols = Object.keys(data).sort();
180292
const stmt = `insert into \`${object}\` (${cols.map((c) => `\`${c}\``).join(', ')}) values (${cols.map((c) => `'${String(data[c])}'`).join(', ')}) returning *`;
181-
const e: any = new Error(`${stmt} - table ${object} has no column named secret_note`);
182-
e.name = 'SqliteError';
183-
e.code = 'SQLITE_ERROR';
184-
e.stack = `SqliteError: ${stmt} - table ${object} has no column named secret_note\n at Database.prepare (/x/better-sqlite3.js:1:1)`;
293+
const text = `${stmt} - ${fault.diagnostic(object)}`;
294+
const e: any = new Error(text);
295+
e.name = fault.name;
296+
e.code = fault.code;
297+
e.stack = `${fault.name}: ${text}\n at Database.prepare (/x/better-sqlite3.js:1:1)`;
185298
throw e;
186299
},
187300
async update() { return {}; }, async updateMany() { return 0; },
@@ -248,4 +361,48 @@ describe('#8682 half B — the write-path loggers', () => {
248361
expect(String(thrown?.message)).toContain('insert into');
249362
expect(String(thrown?.message)).toContain(SECRET);
250363
});
364+
365+
/**
366+
* [#8823] The same write path, with the fault MySQL raises instead — where
367+
* the caller's value is in the DIAGNOSTIC and not only in the statement, so
368+
* the statement cut alone never reached it.
369+
*/
370+
const MYSQL_DUPLICATE_ENTRY = {
371+
name: 'Error',
372+
code: 'ER_DUP_ENTRY',
373+
diagnostic: (object: string) => `Duplicate entry '${SECRET}' for key '${object}.secret_note'`,
374+
};
375+
376+
it('MySQL duplicate entry — the entry survives and still names the index', async () => {
377+
const { line } = await insertAgainstADriftedColumn(MYSQL_DUPLICATE_ENTRY);
378+
379+
expect(line).toBeDefined();
380+
expect(line!.level).toBe('error');
381+
expect(line!.meta).toEqual({ object: 'crm_account' });
382+
// The operator's answer to "which constraint?" is kept whole.
383+
expect(String(line!.err?.message)).toContain("for key 'crm_account.secret_note'");
384+
expect(String(line!.err?.stack)).toContain('at Database.prepare');
385+
});
386+
387+
it('MySQL duplicate entry — neither `message` nor `stack` carries the value', async () => {
388+
const { line } = await insertAgainstADriftedColumn(MYSQL_DUPLICATE_ENTRY);
389+
390+
for (const field of [String(line!.err?.message), String(line!.err?.stack)]) {
391+
expect(field).not.toContain(SECRET);
392+
expect(field).not.toContain(DESCRIPTION);
393+
expect(field).not.toContain('insert into');
394+
}
395+
});
396+
397+
it('MySQL duplicate entry — the RETHROWN error is still untouched', async () => {
398+
// Same boundary as above: the log narrows, the caller's answer does not
399+
// move. `isUniqueViolationError` and `uniqueViolationColumn` read this
400+
// message downstream and must keep seeing the driver's own text.
401+
const { thrown } = await insertAgainstADriftedColumn(MYSQL_DUPLICATE_ENTRY);
402+
403+
expect(String(thrown?.message)).toContain('insert into');
404+
expect(String(thrown?.message)).toContain(SECRET);
405+
expect(String(thrown?.message)).toContain('Duplicate entry');
406+
expect((thrown as any)?.code).toBe('ER_DUP_ENTRY');
407+
});
251408
});

packages/objectql/src/driver-fault-redaction.ts

Lines changed: 140 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -31,12 +31,49 @@
3131
* The driver's own diagnostic — the tail — is the half that names the failing
3232
* column and the condition (`table crm_account has no column named
3333
* zzz_nonexistent_field`, `NOT NULL constraint failed: sys_team.name`). It is
34-
* kept verbatim, and the log site keeps the `object` it already carried. ⛔ The
34+
* kept, and the log site keeps the `object` it already carried. ⛔ The
3535
* remedy for this exposure is NOT to lower the level or drop the entry: a
3636
* driver-level fault that logs nothing is a fault nobody can debug, which is
3737
* strictly worse than one logged too loudly. This narrows WHAT is written; the
3838
* level, the message and the entry are untouched.
3939
*
40+
* ## [#8823] …but "the tail names identifiers" is not true of every dialect
41+
*
42+
* The paragraph above was written with a premise attached: that whatever the
43+
* database prints after the separator names IDENTIFIERS — a column, a table, a
44+
* constraint. That premise was checked against SQLite and Postgres, and it is
45+
* false on MySQL for one family. MySQL's `ER_DUP_ENTRY` (1062) puts the
46+
* conflicting value in the diagnostic itself rather than in the statement:
47+
*
48+
* ```
49+
* mysql unknown column => "Unknown column 'zzz' in 'field list' […]"
50+
* mysql duplicate entry => "Duplicate entry 'acme@example.com' for key 'crm_account.email' […]"
51+
* sqlite unique violation => "UNIQUE constraint failed: crm_account.email […]"
52+
* pg unique violation => "duplicate key value violates unique constraint "crm_account_email_key" […]"
53+
* ```
54+
*
55+
* Three keep an identifier; the second keeps a caller's value. Measured through
56+
* this function, not predicted — and re-measured byte-identical after #9030
57+
* taught the shared leak predicate this phrasing, which moves the VERDICT but
58+
* not the cut.
59+
*
60+
* Postgres is not saved by the cut here — it is saved by an unrelated fact:
61+
* its conflicting value lives on `error.detail`, a field `Logger` never
62+
* serializes (it writes `message` and `stack`, nothing else). That is a
63+
* coincidence, not a defence, and nothing below makes `detail` reachable.
64+
*
65+
* So the tail is kept, minus the spans a dialect's own template documents as a
66+
* VALUE — see {@link redactDiagnosticValues}. Identifier-bearing tails are
67+
* untouched, which is the property #8682 paid for on purpose: MySQL's
68+
* `for key '…'` names an INDEX (`uniqueViolationColumn` in
69+
* `@objectstack/types` refuses to read a column out of it for exactly that
70+
* reason), and an operator debugging a duplicate needs that index name.
71+
*
72+
* ⛔ This is a server LOG. The rethrown error is untouched, every HTTP boundary
73+
* is unaffected, and no live MySQL deployment was measured — the input strings
74+
* are this repo's own recorded mysql2 phrasings (`unique-violation.ts`) driven
75+
* through the real function.
76+
*
4077
* ## Why the cut is at the separator, and not at a statement keyword
4178
*
4279
* "Is this a driver dump?" already has ONE owner in this repo —
@@ -86,6 +123,46 @@ const STATEMENT_SEPARATOR = ' - ';
86123
/** What replaces a statement that carried nothing but values. */
87124
const REDACTED_STATEMENT = '[statement and bound values redacted]';
88125

126+
/** [#8823] What replaces one caller value inlined in the database's own diagnostic. */
127+
const REDACTED_VALUE = '[value redacted]';
128+
129+
/**
130+
* [#8823] MySQL/MariaDB `ER_DUP_ENTRY` (1062), whole: the template's own head,
131+
* the conflicting VALUE, and the `for key <index>` tail that anchors it.
132+
*
133+
* `Duplicate entry '%-.192s' for key '%-.192s'` — the first slot is whatever the
134+
* caller tried to write, the second is the index name. MySQL escapes neither,
135+
* so the value's own closing quote is not distinguishable on sight
136+
* (`Duplicate entry 'O'Brien' for key 'i'` is a real shape) and only the
137+
* ` for key '…'` anchor bounds it. The key token requires quotes because that
138+
* is what separates this template from prose that merely contains the words.
139+
*
140+
* The value is matched GREEDILY, so an ambiguous message resolves to the LAST
141+
* anchor — `Duplicate entry 'a' for key 'b' for key 't.n'` reads as the value
142+
* `a' for key 'b`, not as a short value with a fragment left standing. Same
143+
* reasoning as the statement cut taking the last separator: when the shape is
144+
* ambiguous, discarding more is the only direction that cannot leak. Safe to be
145+
* greedy here precisely because this runs AFTER the cut, where no statement is
146+
* left for a match to reach across.
147+
*
148+
* The quote class and the key token deliberately mirror the `ER_DUP_ENTRY` limb
149+
* `DIALECT_LEAK_PHRASINGS` carries in `@objectstack/types` — two files reading
150+
* one dialect's one template should not disagree about its shape.
151+
*/
152+
const DUPLICATE_ENTRY = /(duplicate entry\s+)["'`][\s\S]*["'`](\s+for key\s+["'`][^"'`]+["'`])/gi;
153+
154+
/**
155+
* [#8823] The same template with its head already gone — what the statement cut
156+
* leaves behind when the conflicting VALUE itself contained ` - `.
157+
*
158+
* Measured: `insert into … values ('2026 - Q3 plan') - Duplicate entry '2026 -
159+
* Q3 plan' for key 't.label'` cuts at the separator INSIDE the value and logs
160+
* `Q3 plan' for key 't.label'`. Same exposure, one shape further on, so it is
161+
* closed here rather than left for the next reader to rediscover. Everything
162+
* before the anchor is value residue by construction and is dropped whole.
163+
*/
164+
const DUPLICATE_ENTRY_TAIL = /["'`](\s+for key\s+["'`][^"'`]+["'`])/gi;
165+
89166
/**
90167
* The first stack FRAME line (` at …`). Everything above it is the header
91168
* that repeats `name: message` — and therefore repeats the statement.
@@ -126,8 +203,12 @@ export function redactBoundStatement(error: unknown): unknown {
126203
export function redactStatementFromMessage(message: string): string {
127204
if (!message || !looksLikeInternalErrorLeak(message)) return message;
128205
const cut = message.lastIndexOf(STATEMENT_SEPARATOR);
129-
if (cut === -1) return message;
130-
const diagnostic = message.slice(cut + STATEMENT_SEPARATOR.length).trim();
206+
// No statement to cut — but a dialect may still have inlined a value in the
207+
// diagnostic itself, and since #9030 taught the shared predicate this
208+
// phrasing, a BARE `Duplicate entry …` now reaches this line instead of
209+
// being turned away above.
210+
if (cut === -1) return redactDiagnosticValues(message);
211+
const diagnostic = redactDiagnosticValues(message.slice(cut + STATEMENT_SEPARATOR.length).trim());
131212
// A dump whose tail is empty still had its head removed: report the
132213
// redaction rather than an empty message, so the entry never reads as a
133214
// fault with no detail at all.
@@ -136,6 +217,62 @@ export function redactStatementFromMessage(message: string): string {
136217
: REDACTED_STATEMENT;
137218
}
138219

220+
/**
221+
* [#8823] Drop the caller values a dialect inlines into its OWN diagnostic,
222+
* keeping every identifier around them.
223+
*
224+
* Runs on the tail the statement cut already produced, never on the whole
225+
* message: a bound value can contain anything, this file's own template
226+
* included, and matching before the cut would let a value in the STATEMENT
227+
* steer what survives. After the cut there is nothing left but the database's
228+
* words, so the templates below can be read literally.
229+
*
230+
* ⛔ Add a dialect's spelling here only once it has been measured off a THROWN
231+
* error, never from a reading of the manual — the standing rule in this
232+
* neighbourhood (`unique-violation.ts`), and the reason MySQL's other
233+
* value-bearing families are not listed. Over-matching is the expensive
234+
* direction: it deletes the diagnostic an operator came for.
235+
*/
236+
function redactDiagnosticValues(diagnostic: string): string {
237+
const whole = lastMatch(DUPLICATE_ENTRY, diagnostic);
238+
if (whole) {
239+
// The template's head survived, so keep it and MySQL's own wording around
240+
// it — only the value slot is replaced.
241+
return diagnostic.slice(0, whole.index)
242+
+ whole[1] + REDACTED_VALUE + whole[2]
243+
+ diagnostic.slice(whole.index + whole[0].length);
244+
}
245+
246+
const tail = lastMatch(DUPLICATE_ENTRY_TAIL, diagnostic);
247+
if (tail) {
248+
// Head gone: everything before the anchor is what is left of the value.
249+
// The words are NOT reconstructed — an anchor is evidence about the value,
250+
// not licence to assert which template printed it.
251+
return REDACTED_VALUE + tail[1] + diagnostic.slice(tail.index + tail[0].length);
252+
}
253+
254+
return diagnostic;
255+
}
256+
257+
/**
258+
* The LAST match of a sticky-free global pattern, or `undefined`.
259+
*
260+
* Last, not first, for the reason the statement cut takes the last separator:
261+
* a value may itself contain the anchor, and the later match is the one the
262+
* database printed. `lastIndex` is reset so the shared `RegExp` objects above
263+
* carry no state between calls.
264+
*/
265+
function lastMatch(pattern: RegExp, text: string): RegExpExecArray | undefined {
266+
pattern.lastIndex = 0;
267+
let found: RegExpExecArray | undefined;
268+
for (let m = pattern.exec(text); m !== null; m = pattern.exec(text)) {
269+
found = m;
270+
if (m[0].length === 0) break;
271+
}
272+
pattern.lastIndex = 0;
273+
return found;
274+
}
275+
139276
/**
140277
* Rebuild `stack` so its header carries the redacted message instead of the
141278
* statement, keeping every frame.

0 commit comments

Comments
 (0)