diff --git a/.changeset/value-bearing-diagnostic-probe.md b/.changeset/value-bearing-diagnostic-probe.md new file mode 100644 index 0000000000..0598b4e3ad --- /dev/null +++ b/.changeset/value-bearing-diagnostic-probe.md @@ -0,0 +1,68 @@ +--- +"@objectstack/objectql": patch +"@objectstack/driver-sql": patch +--- + +fix(objectql): stop logging the caller's value for four MORE diagnostic families — measured off live MySQL 8.0 / PostgreSQL 16, not read off a manual (#9160) + +#8823 established that a database's diagnostic does not always name only +IDENTIFIERS: MySQL's `ER_DUP_ENTRY` inlines the conflicting VALUE, and +`redactStatementFromMessage` redacts that one slot while keeping the index name +an operator needs. + +The list it introduced had **exactly one entry and no way to notice a second was +missing**. Nothing measured whether a diagnostic a driver produced carried a +value; the single entry got there because a human read one template closely, and +the standing rule (`packages/types/src/unique-violation.ts`) — a dialect's +spelling goes in once measured off a thrown error, never from a reading of the +manual — correctly prevented the list from growing on a guess. + +**The instrument now exists.** `sql-driver-diagnostic-value-probe.test.ts` plants +a canary, raises each candidate family through the driver's own bind path against +the live MySQL 8.0 / PostgreSQL 16 services the `Temporal Conformance (live PG + +MySQL)` job already stands up, and asserts of every family — value-bearing or not +— **where the canary lands**: `error.message` (which `ObjectLogger.write` +serializes, so an exposure) or `error.detail` (which it does not). A family that +starts inlining a value it did not inline before is now a named red naming the +file to edit, instead of a silent leak. + +Measured with a positive control first (`ER_DUP_ENTRY`, the known-value-bearing +neighbour, reproduced verbatim — without it a zero elsewhere would be +uninterpretable): + +| dialect | family | diagnostic, verbatim | verdict | +|:--|:--|:--|:--| +| mysql | 1062 | `Duplicate entry 'CANARY' for key 'probe.uq'` | value on `message` (already encoded) | +| mysql | 1366 | `Incorrect integer value: 'CANARY' for column 'age' at row 1` | **value on `message`** | +| mysql | 1292 | `Incorrect datetime value: 'CANARY' for column 'when_at' at row 1` | **value on `message`** | +| mysql | 1264 | `Out of range value for column 'age' at row 1` | identifier only | +| mysql | 1406 | `Data too long for column 'label' at row 1` | identifier only | +| mysql | 1054 | `Unknown column 'zzz…' in 'field list'` | identifier only | +| pg | 22P02 | `invalid input syntax for type integer: "CANARY"` | **value on `message`** | +| pg | 22007 | `invalid input syntax for type timestamp with time zone: "CANARY"` | **value on `message`** | +| pg | 22003 | `value "99999999999" is out of range for type integer` | **value on `message`** | +| pg | 23505 | `duplicate key value violates unique constraint "…"` | value on `detail` only | +| pg | 23502 | `null value in column "id" … violates not-null constraint` | value on `detail` only | +| pg | 22001 | `value too long for type character varying(20)` | identifier only | + +Both families the card named as candidates **are** value-bearing, and the +Postgres one is the sharper result: #8823 recorded that Postgres escapes the +unique-violation leak only because its value sits on `error.detail`, a field the +logger never serializes — *"coincidence, not a defence"*. `22P02` / `22007` / +`22003` put the caller's value on **`error.message`**, the field that IS +serialized, so the coincidence does not cover them. + +The one-off regex pair is now an enumerable `VALUE_BEARING_TEMPLATES` table, one +row per measured family, each citing the live server that produced it. Every +identifier-bearing tail is still kept whole — over-matching deletes the +diagnostic an operator came for, which is the expensive direction #8682 paid to +avoid, and the six identifier-only families above are pinned against exactly that +regression. + +**Known residue, measured and deliberately not closed here:** when the caller's +value itself contains ` - `, the statement cut lands inside it and eats the +template head. Families with a right anchor (`for key …`, `for column … at row +N`) recover; the two whose value runs to end of message (pg 22P02/22007, mysql +1292's `Truncated incorrect …` spelling) have no anchor and leave a suffix +standing. Closing that requires the cut itself to become template-aware — a +change to #8682's contract, filed rather than decided. diff --git a/packages/drivers/driver-sql/src/sql-driver-diagnostic-value-probe.test.ts b/packages/drivers/driver-sql/src/sql-driver-diagnostic-value-probe.test.ts new file mode 100644 index 0000000000..799b6bed10 --- /dev/null +++ b/packages/drivers/driver-sql/src/sql-driver-diagnostic-value-probe.test.ts @@ -0,0 +1,344 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. + +/** + * [#9160] The instrument #8823 did not have: raise each candidate diagnostic + * family against a LIVE server and record what the server actually printed. + * + * ## Why this file exists + * + * `redactStatementFromMessage` (`@objectstack/objectql`) keeps the database's + * diagnostic after the statement cut, on the premise that a diagnostic names + * IDENTIFIERS. #8823 found one family where that is false — MySQL's + * `ER_DUP_ENTRY` inlines the conflicting VALUE — and redacted that one slot. + * + * The list it introduced had exactly one entry and **no way to notice a second + * was missing**. Nothing measured whether a diagnostic a driver produced carried + * a value; the single entry got there because a human read one template closely, + * and the next one would have needed the same accident. The standing rule + * (`packages/types/src/unique-violation.ts`) says a dialect's spelling may be + * added only once measured off a THROWN error, never from a reading of the + * manual — which is correct, and which is exactly why the list could not grow. + * + * This file closes that loop. It plants a canary value, provokes each family + * through the driver's own bind path, and records **where the canary lands**: + * `error.message` (which `ObjectLogger.write` serializes — an exposure) or + * `error.detail` (which it does not — not an exposure, and only by coincidence). + * + * ## The zero is not a measurement without a positive control + * + * {@link POSITIVE_CONTROL} raises `ER_DUP_ENTRY` (1062) FIRST — the one family + * already known value-bearing and already encoded. If the known-present + * neighbour does not answer, the instrument is broken and every other verdict + * here is uninterpretable, so its failure message says so rather than reading as + * an ordinary red. + * + * ## What a failure here means + * + * Each case declares the placement it was measured at. A red means the server + * changed its mind — either a family that named only identifiers has started + * inlining a value (**a new leak; add it to `VALUE_BEARING_TEMPLATES` in + * `driver-fault-redaction.ts`, and cite this probe's output as the warrant**), + * or a template's phrasing drifted and the entry that matched it no longer does. + * Both are the notification #9160 asked for. + * + * ⛔ This probe deliberately does NOT import the redactor. `driver-sql` does not + * depend on `@objectstack/objectql`, and widening that package's public surface + * to reach an internal function is a contract change this card does not carry. + * The division is: this file establishes WHAT THE SERVER SAYS; the redactor's own + * suite (`packages/objectql/src/driver-fault-redaction.test.ts`) drives these + * exact recorded strings through the function. The recorded literals below are + * duplicated there on purpose, with this file named as their warrant. + * + * Runs in `Temporal Conformance (live PG + MySQL)`, the one job that stands up + * `postgres:16` and `mysql:8.0`. Without the URLs each cell is a named skip. + */ + +import { describe, expect, it, afterAll, beforeAll } from 'vitest'; +import knex, { type Knex } from 'knex'; +import { DIALECT_CELLS, declareDialectCell, type DialectCell } from './live-dialect-matrix.testkit.js'; + +/** The matrix name this cell list belongs to, for the un-provisioned declaration. */ +const MATRIX = 'value-bearing diagnostic'; + +/** Planted so a leak is unmistakable in the recorded output. */ +const CANARY = 'SENSITIVE-CANARY-9160'; + +/** Where a caller's value landed on the thrown error. */ +type Placement = + /** On `error.message` — the field `ObjectLogger.write` serializes. An exposure. */ + | 'message' + /** On `error.detail` only — not serialized, so not an exposure. Coincidence, not a defence. */ + | 'detail' + /** Nowhere: the diagnostic named identifiers only. */ + | 'absent'; + +interface ProbeCase { + /** The server's own error code, as it identifies the family. */ + readonly family: string; + /** + * The caller value this case plants, as it would appear in the diagnostic. + * Defaults to {@link CANARY}; a family that can only be provoked by a value of + * a particular SHAPE (an out-of-range number cannot also be a canary string) + * declares its own, so "did the caller's value survive?" stays answerable. + */ + readonly canary?: string; + /** Where the canary was MEASURED to land. A change here is the notification. */ + readonly placement: Placement; + /** + * The diagnostic tail exactly as the server printed it, with the canary and + * any generated identifiers folded out. Asserted as a SUBSTRING of the tail so + * a phrasing drift is a named red. + */ + readonly phrasing: string; + /** Provoke the family. Must reject. */ + readonly raise: (db: Knex) => Promise; +} + +/** knex joins the bound statement to the server's own words with this. */ +const SEPARATOR = ' - '; + +/** The database's own half of a knex driver message — everything after the LAST separator. */ +function diagnosticOf(message: string): string { + const cut = message.lastIndexOf(SEPARATOR); + return cut === -1 ? message : message.slice(cut + SEPARATOR.length).trim(); +} + +// --------------------------------------------------------------------------- +// MySQL +// --------------------------------------------------------------------------- + +const MYSQL_TABLE = 'probe_9160_mysql'; + +/** + * ⛔ The positive control. Known value-bearing, already encoded, and asserted + * first — a probe that cannot reproduce it is not measuring anything. + */ +const POSITIVE_CONTROL: ProbeCase = { + family: 'ER_DUP_ENTRY (1062)', + placement: 'message', + phrasing: 'Duplicate entry', + raise: async (db) => { + await db(MYSQL_TABLE).insert({ email: CANARY }); + return db(MYSQL_TABLE).insert({ email: CANARY }); + }, +}; + +const MYSQL_CASES: readonly ProbeCase[] = [ + POSITIVE_CONTROL, + { + // The card's first named candidate. Measured: matches the manual exactly. + family: 'ER_TRUNCATED_WRONG_VALUE_FOR_FIELD (1366)', + placement: 'message', + phrasing: 'Incorrect integer value:', + raise: (db) => db(MYSQL_TABLE).insert({ age: CANARY }), + }, + { + family: 'ER_TRUNCATED_WRONG_VALUE (1292), datetime spelling', + placement: 'message', + phrasing: 'Incorrect datetime value:', + raise: (db) => db(MYSQL_TABLE).insert({ when_at: CANARY }), + }, + { + // Identifier-only NEIGHBOURS. These are the cases that make a zero readable: + // the probe raises them too, so "no value here" is a measurement rather than + // an absence of one. + family: 'ER_WARN_DATA_OUT_OF_RANGE (1264)', + canary: '999999999999', + placement: 'absent', + phrasing: "Out of range value for column 'age' at row 1", + raise: (db) => db(MYSQL_TABLE).insert({ age: 999999999999 }), + }, + { + family: 'ER_DATA_TOO_LONG (1406)', + placement: 'absent', + phrasing: "Data too long for column 'label' at row 1", + raise: (db) => db(MYSQL_TABLE).insert({ label: `${CANARY}${'z'.repeat(300)}` }), + }, + { + family: 'ER_BAD_FIELD_ERROR (1054)', + placement: 'absent', + phrasing: "in 'field list'", + raise: (db) => db(MYSQL_TABLE).insert({ zzz_nonexistent_field: CANARY }), + }, +]; + +// --------------------------------------------------------------------------- +// Postgres +// --------------------------------------------------------------------------- + +const PG_TABLE = 'probe_9160_pg'; + +const PG_CASES: readonly ProbeCase[] = [ + { + // The card's second named candidate, and the one whose answer matters most: + // unlike 23505 below, this puts the caller's value on `message`. + family: 'invalid_text_representation (22P02)', + placement: 'message', + phrasing: 'invalid input syntax for type integer:', + raise: (db) => db(PG_TABLE).insert({ age: CANARY }), + }, + { + family: 'invalid_datetime_format (22007)', + placement: 'message', + phrasing: 'invalid input syntax for type timestamp with time zone:', + raise: (db) => db(PG_TABLE).insert({ when_at: CANARY }), + }, + { + family: 'numeric_value_out_of_range (22003)', + canary: '99999999999', + placement: 'message', + phrasing: 'is out of range for type integer', + raise: (db) => db(PG_TABLE).insert({ age: 99999999999 }), + }, + { + // #8823's coincidence, re-measured. The value is on `detail`, which + // `ObjectLogger.write` does not serialize — so Postgres is saved here by a + // fact about our Logger, not by the cut. + family: 'unique_violation (23505)', + placement: 'detail', + phrasing: 'duplicate key value violates unique constraint', + raise: async (db) => { + await db(PG_TABLE).insert({ email: CANARY }); + return db(PG_TABLE).insert({ email: CANARY }); + }, + }, + { + family: 'not_null_violation (23502)', + placement: 'detail', + phrasing: 'violates not-null constraint', + raise: (db) => db.raw(`insert into ${PG_TABLE} (id, email) values (null, ?)`, [CANARY]), + }, + { + family: 'string_data_right_truncation (22001)', + placement: 'absent', + phrasing: 'value too long for type character varying(20)', + raise: (db) => db(PG_TABLE).insert({ label: `${CANARY}${'z'.repeat(50)}` }), + }, +]; + +// --------------------------------------------------------------------------- + +const SCHEMAS: Record Promise; cases: readonly ProbeCase[] }> = { + mysql: { + table: MYSQL_TABLE, + cases: MYSQL_CASES, + ddl: (db) => + db.raw( + `create table ${MYSQL_TABLE} (` + + ' id int primary key auto_increment,' + + ' email varchar(191), age int, when_at datetime, label varchar(20),' + + ` unique key uq_${MYSQL_TABLE}_email (email))`, + ), + }, + pg: { + table: PG_TABLE, + cases: PG_CASES, + ddl: (db) => + db.raw( + `create table ${PG_TABLE} (` + + ' id serial primary key,' + + ' email text unique, age int, when_at timestamptz, label varchar(20))', + ), + }, +}; + +for (const cell of DIALECT_CELLS) { + // SQLite has no server to interrogate and none of these families; the driver + // axis still reports it rather than omitting it. + if (!cell.live) continue; + + declareDialectCell(cell, MATRIX, (live: DialectCell) => { + const plan = SCHEMAS[live.id]; + + describe(`sql-driver — ${MATRIX} probe (${live.label})`, () => { + let db: Knex; + /** family → the thrown error, captured once in `beforeAll`. */ + const raised = new Map(); + + beforeAll(async () => { + db = knex(live.config() as Knex.Config); + await db.raw(`drop table if exists ${plan.table}`); + await plan.ddl(db); + + for (const probe of plan.cases) { + try { + await probe.raise(db); + raised.set(probe.family, undefined); + } catch (err) { + raised.set(probe.family, err); + } + } + }, 60_000); + + afterAll(async () => { + if (!db) return; + await db.raw(`drop table if exists ${plan.table}`).catch(() => {}); + await db.destroy(); + }); + + if (live.id === 'mysql') { + it('POSITIVE CONTROL — ER_DUP_ENTRY still answers, and still inlines the value', () => { + const err = raised.get(POSITIVE_CONTROL.family); + + expect( + err, + 'the positive control raised NO error: this probe is not measuring anything, and every ' + + 'other verdict in this file is uninterpretable. Fix the instrument before reading them.', + ).toBeInstanceOf(Error); + + const diagnostic = diagnosticOf(String(err.message)); + // The phrasing the single encoded entry matches, reproduced off a live + // server rather than off this repo's recorded strings. + expect(diagnostic).toContain('Duplicate entry'); + expect(diagnostic).toContain(CANARY); + expect(diagnostic).toMatch(/for key '[^']+'/); + }); + } + + for (const probe of plan.cases) { + it(`${probe.family} — canary lands on \`${probe.placement}\``, () => { + const err = raised.get(probe.family); + + expect( + err, + `${probe.family} could not be raised through the driver's bind path. An unraisable ` + + 'family is a documented negative result, not a silent pass — record it here rather ' + + 'than deleting the case.', + ).toBeInstanceOf(Error); + + const message = String(err.message); + const diagnostic = diagnosticOf(message); + const detail = typeof err.detail === 'string' ? err.detail : ''; + + // 1. The server still prints what it was measured to print. + expect( + diagnostic, + `${probe.family} changed its phrasing. Whatever entry in VALUE_BEARING_TEMPLATES ` + + '(objectql/src/driver-fault-redaction.ts) was written against it no longer matches. ' + + `Server said: ${JSON.stringify(diagnostic)}`, + ).toContain(probe.phrasing); + + // 2. …and the caller's value is still where it was measured to be. + // This is the assertion that notices a NEW value-bearing family. + const planted = probe.canary ?? CANARY; + const actual: Placement = diagnostic.includes(planted) + ? 'message' + : detail.includes(planted) + ? 'detail' + : 'absent'; + + expect( + actual, + `${probe.family} moved the caller's value from \`${probe.placement}\` to \`${actual}\`. ` + + (actual === 'message' + ? 'It now inlines a caller value into the diagnostic `ObjectLogger.write` SERIALIZES — ' + + 'this is a new leak. Add the template to VALUE_BEARING_TEMPLATES in ' + + 'objectql/src/driver-fault-redaction.ts and cite this output as the warrant. ' + : 'The exposure changed shape; re-read the redactor before relaxing this. ') + + `Server said: ${JSON.stringify(diagnostic)}`, + ).toBe(probe.placement); + }); + } + }); + }); +} diff --git a/packages/objectql/src/driver-fault-redaction.test.ts b/packages/objectql/src/driver-fault-redaction.test.ts index 1157948577..13a1eeaa90 100644 --- a/packages/objectql/src/driver-fault-redaction.test.ts +++ b/packages/objectql/src/driver-fault-redaction.test.ts @@ -201,6 +201,181 @@ describe('#8823 — a caller value inlined in the diagnostic itself', () => { }); }); +// #9160 — the families the LIVE probe raised, driven through the real function. +// +// ⛔ Every message below was raised off a thrown error against MySQL 8.0.46 and +// PostgreSQL 16.13 by `sql-driver-diagnostic-value-probe.test.ts`, and is copied +// here byte-for-byte with only the canary and the generated table name folded to +// readable ones. That probe is the WARRANT for each entry: nothing here comes +// from a reading of the manual, which is the standing rule +// (`packages/types/src/unique-violation.ts`). If the probe goes red because a +// server changed its phrasing, these fixtures are the stale half. +// +// The probe lives in `driver-sql` rather than here because that is the package +// the `Temporal Conformance (live PG + MySQL)` job runs against live servers, +// and because reaching this internal function from there would mean widening +// `@objectstack/objectql`'s public surface. +describe('#9160 — the value-bearing families the live probe measured', () => { + const CANARY = 'SENSITIVE-CANARY-9160'; + + describe('mysql ER_TRUNCATED_WRONG_VALUE_FOR_FIELD (1366)', () => { + // Verbatim: "Incorrect integer value: 'SENSITIVE-CANARY-9160' for column 'age' at row 1" + const diagnostic = `Incorrect integer value: '${CANARY}' for column 'age' at row 1`; + + it('drops the caller value and keeps the column the operator needs', () => { + const out = redactStatementFromMessage( + `insert into \`t\` (\`age\`) values ('${CANARY}') - ${diagnostic}`, + ); + + expect(out).not.toContain(CANARY); + // The failing column is the answer to "which field?" and survives whole. + expect(out).toContain("for column 'age' at row 1"); + expect(out).toContain('Incorrect integer value:'); + expect(out).toBe( + "Incorrect integer value: [value redacted] for column 'age' at row 1" + + ' [statement and bound values redacted]', + ); + }); + + it('handles the `decimal` and `datetime` spellings the same way', () => { + // Both measured live; 1292 reuses this template for datetimes. + for (const [type, column] of [['decimal', 'amount'], ['datetime', 'when_at']]) { + const out = redactStatementFromMessage( + `insert into \`t\` (\`${column}\`) values ('${CANARY}')` + + ` - Incorrect ${type} value: '${CANARY}' for column '${column}' at row 1`, + ); + + expect(out).not.toContain(CANARY); + expect(out).toContain(`for column '${column}' at row 1`); + } + }); + + it('resolves an anchor-mimicking value to the LAST anchor', () => { + // Measured: a value spelled `…' for column 'x' at row 1` really does print + // two anchors. Greedy discards both — the only direction that cannot leak. + const out = redactStatementFromMessage( + "insert into `t` (`age`) values ('x')" + + " - Incorrect integer value: 'CANARY' for column 'x' at row 1' for column 'age' at row 1", + ); + + expect(out).not.toContain('CANARY'); + expect(out).not.toContain("for column 'x'"); + expect(out).toContain("for column 'age' at row 1"); + }); + + it('recovers when the value itself contained " - " and ate the head', () => { + // The cut takes the LAST separator, which lands inside a value spelled + // like this. The `for column … at row N` anchor is what recovers it. + const out = redactStatementFromMessage( + "insert into `t` (`age`) values ('2026 - Q3 plan')" + + " - Incorrect integer value: '2026 - Q3 plan' for column 'age' at row 1", + ); + + expect(out).not.toContain('Q3 plan'); + expect(out).not.toContain('2026'); + expect(out).toContain("for column 'age' at row 1"); + }); + }); + + describe('postgres invalid_text_representation (22P02) / invalid_datetime_format (22007)', () => { + // ⛔ The family the #8823 note was waiting for. Postgres' UNIQUE violation is + // saved only because its value sits on `error.detail`, which + // `ObjectLogger.write` never serializes — "coincidence, not a defence". This + // family puts the caller's value on `error.message`, which IS serialized, so + // the coincidence does not cover it. Measured, not predicted. + it('drops the caller value and keeps the type Postgres named', () => { + const out = redactStatementFromMessage( + `insert into "t" ("age") values ($1) - invalid input syntax for type integer: "${CANARY}"`, + ); + + expect(out).not.toContain(CANARY); + // "which type did it fail to parse as?" is the operator's question. + expect(out).toContain('invalid input syntax for type integer:'); + expect(out).toBe( + 'invalid input syntax for type integer: [value redacted]' + + ' [statement and bound values redacted]', + ); + }); + + it('handles multi-word type names', () => { + // Measured live: `timestamp with time zone`, plus numeric/boolean/uuid. + for (const type of ['timestamp with time zone', 'numeric', 'boolean', 'uuid']) { + const out = redactStatementFromMessage( + `insert into "t" ("c") values ($1) - invalid input syntax for type ${type}: "${CANARY}"`, + ); + + expect(out).not.toContain(CANARY); + expect(out).toContain(`invalid input syntax for type ${type}:`); + } + }); + + it('leaves the VALUELESS json spelling untouched', () => { + // Measured: `invalid input syntax for type json` carries no caller value on + // `message` at all (its offending token is on `detail`). Redacting it would + // delete a diagnostic that never leaked. + const out = redactStatementFromMessage( + `insert into "t" ("doc") values ('${CANARY}'::json) - invalid input syntax for type json`, + ); + + expect(out).toBe('invalid input syntax for type json [statement and bound values redacted]'); + expect(out).not.toContain('[value redacted]'); + }); + }); + + describe('postgres numeric_value_out_of_range (22003)', () => { + it('drops the out-of-range value and keeps the type', () => { + // Verbatim: `value "99999999999" is out of range for type integer`. + const out = redactStatementFromMessage( + 'insert into "t" ("age") values ($1) - value "99999999999" is out of range for type integer', + ); + + expect(out).not.toContain('99999999999'); + expect(out).toContain('is out of range for type integer'); + expect(out).toBe( + 'value [value redacted] is out of range for type integer' + + ' [statement and bound values redacted]', + ); + }); + }); + + describe('mysql ER_TRUNCATED_WRONG_VALUE (1292), the column-less spelling', () => { + it('drops the value that runs to end of message', () => { + // Measured, but only raisable through a raw `cast(… as signed)` — recorded + // as a fact about SHAPE, not a claim that a write path produces it. + const out = redactStatementFromMessage( + `insert into t (age) select cast('${CANARY}' as signed)` + + ` - Truncated incorrect INTEGER value: '${CANARY}'`, + ); + + expect(out).not.toContain(CANARY); + expect(out).toContain('Truncated incorrect INTEGER value:'); + }); + }); + + it('leaves every family the probe measured as IDENTIFIER-ONLY exactly as it was', () => { + // ⛔ The other half of the contract, and the reason the probe raises these + // too: a zero is only readable next to a positive. Redacting any of these + // would delete the diagnostic an operator came for — the expensive + // direction #8682 paid to avoid. All six raised live. + for (const diagnostic of [ + // mysql + "Out of range value for column 'age' at row 1", // 1264 + "Data too long for column 'label' at row 1", // 1406 + "Unknown column 'zzz_nonexistent_field' in 'field list'", // 1054 + // postgres — value on `detail`, never on `message` + 'duplicate key value violates unique constraint "t_email_key"', // 23505 + 'null value in column "id" of relation "t" violates not-null constraint', // 23502 + 'value too long for type character varying(20)', // 22001 + 'numeric field overflow', // 22003 sibling + ]) { + const out = redactStatementFromMessage(`insert into \`t\` (\`c\`) values ('v') - ${diagnostic}`); + + expect(out).toBe(`${diagnostic} [statement and bound values redacted]`); + expect(out).not.toContain('[value redacted]'); + } + }); +}); + describe('redactBoundStatement', () => { it('redacts `stack` too — the statement opened it a second time', () => { const original = new Error(BOUND_INSERT); diff --git a/packages/objectql/src/driver-fault-redaction.ts b/packages/objectql/src/driver-fault-redaction.ts index 165aaf1e89..f2200a4868 100644 --- a/packages/objectql/src/driver-fault-redaction.ts +++ b/packages/objectql/src/driver-fault-redaction.ts @@ -69,10 +69,52 @@ * `@objectstack/types` refuses to read a column out of it for exactly that * reason), and an operator debugging a duplicate needs that index name. * - * ⛔ This is a server LOG. The rethrown error is untouched, every HTTP boundary - * is unaffected, and no live MySQL deployment was measured — the input strings - * are this repo's own recorded mysql2 phrasings (`unique-violation.ts`) driven - * through the real function. + * ⛔ This is a server LOG. The rethrown error is untouched and every HTTP + * boundary is unaffected. + * + * ## [#9160] The list is now MEASURED, and there is a way to notice a gap + * + * #8823 left one entry and no instrument: nothing measured whether a diagnostic + * a driver produced carried a value, so the next entry needed the same accident + * that found the first. `sql-driver-diagnostic-value-probe.test.ts` is that + * instrument. It plants a canary value, raises each candidate family against + * the live MySQL 8.0 / PostgreSQL 16 services the `Temporal Conformance (live + * PG + MySQL)` job stands up, and asserts of EVERY family — value-bearing or + * not — whether the canary reaches `error.message`. A family that starts + * inlining a value it did not inline before is a named red, not a silent leak. + * + * What it measured (MySQL 8.0.46, PostgreSQL 16.13), verbatim: + * + * ``` + * mysql 1062 Duplicate entry 'CANARY-abc' for key 'probe.uq' VALUE + * mysql 1366 Incorrect integer value: 'CANARY-abc' for column 'age' at row 1 VALUE + * mysql 1292 Incorrect datetime value: 'CANARY' for column 'when_at' at row 1 VALUE + * mysql 1264 Out of range value for column 'age' at row 1 identifier only + * mysql 1406 Data too long for column 'label' at row 1 identifier only + * mysql 1054 Unknown column 'zzz_nonexistent_field' in 'field list' identifier only + * pg 22P02 invalid input syntax for type integer: "CANARY-abc" VALUE + * pg 22007 invalid input syntax for type timestamp with time zone: "…" VALUE + * pg 22003 value "99999999999" is out of range for type integer VALUE + * pg 23505 duplicate key value violates unique constraint "…_key" identifier only¹ + * pg 23502 null value in column "id" of relation "t" violates not-null… identifier only¹ + * pg 22001 value too long for type character varying(20) identifier only + * ``` + * + * ¹ on `error.message`. Both put the caller's row on `error.detail`, which + * `ObjectLogger.write` does not serialize — the coincidence #8823 recorded, and + * it is still only a coincidence. **The three Postgres families marked VALUE put + * the caller's value on `message`, the field that IS serialized**, so nothing + * covers them but the entries below. That was the open question #9160 asked and + * the answer is the one the card feared. + * + * ⛔ Known residue, measured and NOT closed here: when the caller's value itself + * contains ` - `, the statement cut lands inside it and eats the template head. + * Families with a right anchor (`for key …`, `for column … at row N`) recover + * via their `tail` pattern; the two whose value runs to end of message + * (pg 22P02/22007, mysql 1292's `Truncated incorrect …` spelling) have no + * anchor to recover from and leave a suffix of the value standing. Closing that + * needs the cut itself to become template-aware, which is a change to #8682's + * contract and is filed rather than decided. * * ## Why the cut is at the separator, and not at a statement keyword * @@ -163,6 +205,133 @@ const DUPLICATE_ENTRY = /(duplicate entry\s+)["'`][\s\S]*["'`](\s+for key\s+["'` */ const DUPLICATE_ENTRY_TAIL = /["'`](\s+for key\s+["'`][^"'`]+["'`])/gi; +/** + * [#9160] MySQL `ER_TRUNCATED_WRONG_VALUE_FOR_FIELD` (1366) and the + * column-bound spelling of `ER_TRUNCATED_WRONG_VALUE` (1292). + * + * `Incorrect %-.32s value: '%-.128s' for column %.192s at row %ld` — slot one is + * a TYPE name, slot two is the caller's value, and the `for column '…' at row N` + * tail names the identifier an operator needs. Measured off a thrown error on + * live MySQL 8.0.46 (see `sql-driver-diagnostic-value-probe.test.ts`), three + * type spellings, byte-identical to the manual's template: + * + * ``` + * Incorrect integer value: 'CANARY-abc' for column 'age' at row 1 + * Incorrect decimal value: 'CANARY-notanum' for column 'amount' at row 1 + * Incorrect datetime value: 'CANARY-notadate' for column 'when_at' at row 1 + * ``` + * + * Greedy for the same reason `DUPLICATE_ENTRY` is: MySQL escapes the value's + * quotes no more here than there, so a value that mimics the anchor resolves to + * the LAST one. Measured: a value spelled `CANARY' for column 'x' at row 1` + * really does print two anchors, and the greedy read discards both. + * + * ⛔ The neighbouring identifier-only families — `Out of range value for column + * 'age' at row 1` (1264) and `Data too long for column 'label' at row 1` (1406) + * — were raised by the same probe and carry NO caller value. They must not + * match: the anchor here requires the value's closing quote immediately before + * ` for column`, which those two do not have. + */ +const MYSQL_INCORRECT_VALUE = /(incorrect \w+ value:\s+)'[\s\S]*'(\s+for column\s+'[^']*'\s+at row\s+\d+)/gi; + +/** [#9160] {@link MYSQL_INCORRECT_VALUE} with its head cut away by a value containing ` - `. */ +const MYSQL_INCORRECT_VALUE_TAIL = /'(\s+for column\s+'[^']*'\s+at row\s+\d+)/gi; + +/** + * [#9160] Postgres `invalid_text_representation` (22P02) and the datetime + * spelling `invalid_datetime_format` (22007). + * + * `invalid input syntax for type %s: "%s"` — the type name is Postgres' own + * word, the quoted tail is the caller's value. Measured on live PostgreSQL + * 16.13 across `integer`, `numeric`, `boolean`, `uuid` and `timestamp with time + * zone`, hence the space-tolerant type class: + * + * ``` + * invalid input syntax for type integer: "CANARY-abc" + * invalid input syntax for type timestamp with time zone: "CANARY-notadate" + * ``` + * + * **This is the family the #8823 note was waiting for.** Postgres' unique + * violation is saved only because its value sits on `error.detail`, which + * `ObjectLogger.write` does not serialize — recorded there as "coincidence, not + * a defence". Here the value is on `error.message`, the field that IS + * serialized, so the coincidence does not cover it and the cut alone does not + * either. + * + * The value runs to END OF MESSAGE with no right anchor, so everything from the + * opening quote onward is dropped. The valueless spelling + * `invalid input syntax for type json` (whose token sits on `detail`) has no + * `: "` and is deliberately left untouched. + */ +const PG_INVALID_INPUT_SYNTAX = /(invalid input syntax for type [a-z0-9 ]+?:\s+)"[\s\S]*$()/gi; + +/** + * [#9160] Postgres `numeric_value_out_of_range` (22003). + * + * `value "%s" is out of range for type %s` — measured live as + * `value "99999999999" is out of range for type integer`. The out-of-range + * value is the caller's own, and the type after the anchor is Postgres' word. + * + * ⛔ Must not reach `duplicate key value violates unique constraint "…"`: that + * one has no ` is out of range for type` anchor, and the anchor is what + * discriminates. The sibling spelling `numeric field overflow` carries no + * caller value on `message` at all (its precision note is on `detail`). + */ +const PG_VALUE_OUT_OF_RANGE = /(value\s+)"[\s\S]*"(\s+is out of range for type [a-z0-9 ]+)/gi; + +/** + * [#9160] MySQL `ER_TRUNCATED_WRONG_VALUE` (1292), the spelling that names no + * column: `Truncated incorrect %-.32s value: '%-.128s'`. + * + * Measured live as `Truncated incorrect INTEGER value: 'CANARY-xyz'`, raised by + * an explicit `cast(… as signed)`. Recorded as a real negative about REACH as + * well as a positive about shape: the probe could only provoke this spelling + * through raw SQL, never through the driver's own bind path, which reaches the + * column-bound 1366/1292 wording above instead. It is listed because it was + * measured, not because a write path is known to produce it. + * + * Value runs to end of message; no right anchor exists to recover a head-gone + * residue. + */ +const MYSQL_TRUNCATED_INCORRECT_VALUE = /(truncated incorrect \w+ value:\s+)'[\s\S]*$()/gi; + +/** + * [#9160] Every dialect template MEASURED to inline a caller's value in the + * database's own diagnostic, in the order they are tried. + * + * ⛔ The standing rule (`unique-violation.ts`) governs this list: a row goes in + * once its phrasing has been raised off a THROWN error, never from a reading of + * the manual. Every row below cites the live server that produced it, and + * `sql-driver-diagnostic-value-probe.test.ts` re-raises each one against the + * MySQL/Postgres services the `Temporal Conformance (live PG + MySQL)` job + * stands up — so a row whose phrasing drifts, or a NEW family that starts + * inlining a value, becomes a named red instead of a silent leak. That probe is + * the answer to "how would anyone notice a second entry is missing"; this list + * is only half of the pair and must not be extended without it. + * + * `whole` matches head + value + kept tail (group 1 kept before the value, + * group 2 kept after). `tail` is the same template after the statement cut has + * eaten its head — which happens when the VALUE itself contained ` - ` — and + * drops everything before the anchor, because an anchor is evidence about the + * value, not licence to assert which template printed it. + */ +interface ValueBearingTemplate { + /** Dialect and the server's own error code, as the probe raises it. */ + readonly id: string; + /** Head + value + anchor. */ + readonly whole: RegExp; + /** The head-gone residue, when the template has a right anchor to recover it. */ + readonly tail?: RegExp; +} + +const VALUE_BEARING_TEMPLATES: readonly ValueBearingTemplate[] = [ + { id: 'mysql/1062 ER_DUP_ENTRY', whole: DUPLICATE_ENTRY, tail: DUPLICATE_ENTRY_TAIL }, + { id: 'mysql/1366 ER_TRUNCATED_WRONG_VALUE_FOR_FIELD', whole: MYSQL_INCORRECT_VALUE, tail: MYSQL_INCORRECT_VALUE_TAIL }, + { id: 'mysql/1292 ER_TRUNCATED_WRONG_VALUE', whole: MYSQL_TRUNCATED_INCORRECT_VALUE }, + { id: 'pg/22P02 invalid_text_representation', whole: PG_INVALID_INPUT_SYNTAX }, + { id: 'pg/22003 numeric_value_out_of_range', whole: PG_VALUE_OUT_OF_RANGE }, +]; + /** * The first stack FRAME line (` at …`). Everything above it is the header * that repeats `name: message` — and therefore repeats the statement. @@ -227,28 +396,40 @@ export function redactStatementFromMessage(message: string): string { * steer what survives. After the cut there is nothing left but the database's * words, so the templates below can be read literally. * - * ⛔ Add a dialect's spelling here only once it has been measured off a THROWN - * error, never from a reading of the manual — the standing rule in this - * neighbourhood (`unique-violation.ts`), and the reason MySQL's other - * value-bearing families are not listed. Over-matching is the expensive - * direction: it deletes the diagnostic an operator came for. + * ⛔ Add a dialect's spelling to {@link VALUE_BEARING_TEMPLATES} only once it has + * been measured off a THROWN error, never from a reading of the manual — the + * standing rule in this neighbourhood (`unique-violation.ts`). Since #9160 that + * measurement has a home: add the family to the live probe, read what the server + * actually printed, and let the recording be the warrant. Over-matching is still + * the expensive direction — it deletes the diagnostic an operator came for — so + * a row that the probe cannot raise does not go in. */ function redactDiagnosticValues(diagnostic: string): string { - const whole = lastMatch(DUPLICATE_ENTRY, diagnostic); - if (whole) { - // The template's head survived, so keep it and MySQL's own wording around - // it — only the value slot is replaced. - return diagnostic.slice(0, whole.index) - + whole[1] + REDACTED_VALUE + whole[2] - + diagnostic.slice(whole.index + whole[0].length); + // Every INTACT template first, then every head-gone residue. Whole-before-tail + // is global rather than per-template on purpose: a diagnostic that still + // carries a recognisable head should be reported with that head, whichever + // family it belongs to, rather than collapsed into a bare anchor by an + // earlier row's tail pattern. + for (const template of VALUE_BEARING_TEMPLATES) { + const whole = lastMatch(template.whole, diagnostic); + if (whole) { + // The template's head survived, so keep it and the database's own wording + // around it — only the value slot is replaced. + return diagnostic.slice(0, whole.index) + + whole[1] + REDACTED_VALUE + whole[2] + + diagnostic.slice(whole.index + whole[0].length); + } } - const tail = lastMatch(DUPLICATE_ENTRY_TAIL, diagnostic); - if (tail) { - // Head gone: everything before the anchor is what is left of the value. - // The words are NOT reconstructed — an anchor is evidence about the value, - // not licence to assert which template printed it. - return REDACTED_VALUE + tail[1] + diagnostic.slice(tail.index + tail[0].length); + for (const template of VALUE_BEARING_TEMPLATES) { + if (!template.tail) continue; + const tail = lastMatch(template.tail, diagnostic); + if (tail) { + // Head gone: everything before the anchor is what is left of the value. + // The words are NOT reconstructed — an anchor is evidence about the value, + // not licence to assert which template printed it. + return REDACTED_VALUE + tail[1] + diagnostic.slice(tail.index + tail[0].length); + } } return diagnostic;