Skip to content

Commit a20aed2

Browse files
committed
fix(webapp): anchor the row hint and stop rethrowing a dead batch
Two problems with the recovery path, both found in review. The failing-row index came from the first `at row N` match anywhere in the untruncated error text, but ClickHouse embeds a snippet of the offending row's own data ahead of its real position suffix. A task whose output happened to contain text like "failed at row 7" therefore redirected the strip: an unrelated run landed with its output emptied, the un-ingestable run stayed broken, and with the default budget of one strip the batch then skipped that run entirely. The strip loop now reads the parenthesised `(at row N)` form and takes the last occurrence, so the server's own suffix wins over anything in user data, and gives up rather than guessing when no position is present. The existing helper keeps its first-match contract for the logging-only caller. A batch that ClickHouse rejected even with `allow_errors` also propagated out of both helpers. That failure is deterministic, so the run-replication retry layer re-ran the whole recovery on bytes that cannot change, and in the event repository a terminal throw skipped the flush scheduler's queue-depth decrement, leaking a counter that feeds its load-shedding and memory-pressure decisions. Such a batch is now counted as wholly dropped instead. Transient failures of that insert still rethrow so the retry layer keeps working.
1 parent e9ecce0 commit a20aed2

2 files changed

Lines changed: 289 additions & 3 deletions

File tree

apps/webapp/app/v3/eventRepository/sanitizeRowsOnParseError.server.ts

Lines changed: 118 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -81,6 +81,26 @@ export function parseRowNumberFromError(errorMessage: string): number | null {
8181
return match ? Number.parseInt(match[1], 10) : null;
8282
}
8383

84+
/**
85+
* Extracts the failing-row index for the strip loop, where a wrong answer empties
86+
* an innocent row's JSON instead of the poison one.
87+
*
88+
* ClickHouse reports the position as a parenthesised `(at row N)` suffix, but the
89+
* same message embeds a snippet of the offending row's own data ahead of it
90+
* (`Cannot parse JSON object here: {...}: (while reading ...): (at row N)`), so a
91+
* task whose output merely contains the text `at row 7` would otherwise win the
92+
* match. Requiring the parentheses and taking the LAST occurrence keeps the
93+
* server's own suffix authoritative, since user data appears before it.
94+
*
95+
* Returns `null` when no parenthesised position is present; the caller treats
96+
* that as "row not locatable" and bails to the skip insert rather than guessing.
97+
*/
98+
export function parseStrippableRowNumber(errorMessage: string): number | null {
99+
const matches = [...errorMessage.matchAll(/\(at row (\d+)\)/g)];
100+
if (matches.length === 0) return null;
101+
return Number.parseInt(matches[matches.length - 1][1], 10);
102+
}
103+
84104
/**
85105
* Walks `value` recursively and replaces any string leaf that contains a
86106
* lone UTF-16 surrogate with `INVALID_UTF16_SENTINEL`. Mutates objects
@@ -328,7 +348,7 @@ export async function insertWithLimitedStrip<T extends object>(params: {
328348
break;
329349
}
330350

331-
const hint = parseRowNumberFromError(rawErrorMessage(parseError));
351+
const hint = parseStrippableRowNumber(rawErrorMessage(parseError));
332352
const index = hint === null ? -1 : hint - 1;
333353

334354
if (index < 0 || index >= working.length || stripped[index]) {
@@ -341,7 +361,25 @@ export async function insertWithLimitedStrip<T extends object>(params: {
341361
rowsStripped += 1;
342362
}
343363

344-
const insertResult = await insertAllowingBadRows(working);
364+
const [skipError, insertResult] = await tryInsertAllowingBadRows(
365+
insertAllowingBadRows,
366+
working
367+
);
368+
369+
if (skipError) {
370+
return wholeBatchDropped({
371+
rows,
372+
contextLabel,
373+
logger,
374+
logContext,
375+
rowsStripped,
376+
capped: true,
377+
bailReason,
378+
firstMessage,
379+
skipError,
380+
});
381+
}
382+
345383
const dropped = droppedRowCount(insertResult, working.length, hasMaterializedViews);
346384

347385
logger.warn("Landed the batch via allow_errors and skipped the remaining un-ingestable rows", {
@@ -367,6 +405,69 @@ export async function insertWithLimitedStrip<T extends object>(params: {
367405
}
368406
}
369407

408+
/**
409+
* Runs the `allow_errors` skip insert, separating the two ways it can fail.
410+
*
411+
* A surviving `Cannot parse JSON object` is deterministic: the same bytes will
412+
* fail again, so it is returned for the caller to swallow and count. Anything
413+
* else (a connection drop, a server restart) is transient and rethrown so the
414+
* caller's retry layer still gets its chance.
415+
*/
416+
async function tryInsertAllowingBadRows<T extends object>(
417+
insertAllowingBadRows: (rows: T[]) => Promise<unknown>,
418+
rows: T[]
419+
): Promise<[unknown, undefined] | [undefined, unknown]> {
420+
try {
421+
return [undefined, await insertAllowingBadRows(rows)];
422+
} catch (error) {
423+
if (!isClickHouseJsonParseError(error)) throw error;
424+
return [error, undefined];
425+
}
426+
}
427+
428+
/**
429+
* Reports a batch that could not land even with `allow_errors`, without throwing.
430+
*
431+
* Handing a deterministic parse failure back to the caller's retry layer only
432+
* burns the whole recovery again on bytes that cannot change, and in the event
433+
* repository a terminal throw also skips the scheduler's queue-depth decrement,
434+
* leaking a counter that feeds its load-shedding and memory-pressure decisions.
435+
* Counting the batch as wholly dropped keeps both layers honest instead.
436+
*/
437+
function wholeBatchDropped<T extends object>(params: {
438+
rows: T[];
439+
contextLabel: string;
440+
logger: JsonParseRecoveryLogger;
441+
logContext?: Record<string, unknown>;
442+
rowsStripped: number;
443+
capped: boolean;
444+
bailReason?: RecoveryBailReason;
445+
firstMessage: string;
446+
skipError: unknown;
447+
}): JsonParseRecoveryOutcome {
448+
const { rows, contextLabel, logger, logContext, rowsStripped, capped, bailReason } = params;
449+
450+
logger.warn("Dropped the whole batch: ClickHouse rejected it even with allow_errors", {
451+
...logContext,
452+
contextLabel,
453+
bailReason,
454+
batchSize: rows.length,
455+
rowsStripped,
456+
rowsDropped: rows.length,
457+
clickhouseError: params.firstMessage.split("\n")[0],
458+
skipInsertError: errorMessage(params.skipError).split("\n")[0],
459+
});
460+
461+
return {
462+
kind: "recovered",
463+
rowsStripped,
464+
rowsDropped: rows.length,
465+
rowsDroppedExact: true,
466+
capped,
467+
bailReason,
468+
};
469+
}
470+
370471
function writtenRowCount(insertResult: unknown): number | null {
371472
if (typeof insertResult === "object" && insertResult !== null) {
372473
const summary = (insertResult as { summary?: { written_rows?: unknown } }).summary;
@@ -472,7 +573,21 @@ export async function insertWithBadRowSkip<T extends object>(params: {
472573
}
473574
}
474575

475-
const insertResult = await insertAllowingBadRows(rows);
576+
const [skipError, insertResult] = await tryInsertAllowingBadRows(insertAllowingBadRows, rows);
577+
578+
if (skipError) {
579+
return wholeBatchDropped({
580+
rows,
581+
contextLabel,
582+
logger,
583+
logContext,
584+
rowsStripped: 0,
585+
capped: false,
586+
firstMessage,
587+
skipError,
588+
});
589+
}
590+
476591
const dropped = droppedRowCount(insertResult, rows.length, hasMaterializedViews);
477592

478593
logger.warn(

apps/webapp/test/sanitizeRowsOnParseError.test.ts

Lines changed: 171 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -5,6 +5,7 @@ import {
55
insertWithLimitedStrip,
66
isClickHouseJsonParseError,
77
parseRowNumberFromError,
8+
parseStrippableRowNumber,
89
sanitizeRows,
910
sanitizeUnknownInPlace,
1011
} from "~/v3/eventRepository/sanitizeRowsOnParseError.server";
@@ -106,6 +107,37 @@ describe("parseRowNumberFromError", () => {
106107
});
107108
});
108109

110+
describe("parseStrippableRowNumber", () => {
111+
it("reads the parenthesised position ClickHouse appends", () => {
112+
expect(
113+
parseStrippableRowNumber(
114+
"Cannot parse JSON object here: { ... }: (while reading the value of key attributes): (at row 1942)\n: While executing ParallelParsingBlockInputFormat."
115+
)
116+
).toBe(1942);
117+
});
118+
119+
it("ignores an `at row N` that appears inside the offending row's own data", () => {
120+
const withDecoyInPayload =
121+
'Cannot parse JSON object here: {"output":{"dbError":"syntax error at row 7"}}: (while reading the value of key output): (at row 3)';
122+
123+
expect(parseStrippableRowNumber(withDecoyInPayload)).toBe(3);
124+
expect(parseRowNumberFromError(withDecoyInPayload)).toBe(7);
125+
});
126+
127+
it("takes the last parenthesised position when the payload fakes that form too", () => {
128+
expect(
129+
parseStrippableRowNumber(
130+
'Cannot parse JSON object here: {"msg":"failed (at row 99)"}: (at row 4)'
131+
)
132+
).toBe(4);
133+
});
134+
135+
it("returns null when no parenthesised position is present, so the caller bails", () => {
136+
expect(parseStrippableRowNumber("Cannot parse JSON object here: {...}: at row 5")).toBeNull();
137+
expect(parseStrippableRowNumber("Cannot parse JSON object, no position at all")).toBeNull();
138+
});
139+
});
140+
109141
describe("sanitizeUnknownInPlace", () => {
110142
it("returns the string unchanged when it has no surrogates", () => {
111143
const result = sanitizeUnknownInPlace("hello world");
@@ -515,6 +547,98 @@ describe("insertWithLimitedStrip", () => {
515547
})
516548
).rejects.toThrow("Connection refused");
517549
});
550+
551+
it("strips the row ClickHouse pointed at, not one named by the payload's own text", async () => {
552+
const landed: FakeRow[] = [];
553+
const insertSync = async (rows: FakeRow[]) => {
554+
const badIndex = rows.findIndex((r) => r.poison);
555+
if (badIndex >= 0) {
556+
throw new Error(
557+
`Cannot parse JSON object here: {"output":"failed at row 1"}: (at row ${badIndex + 1})`
558+
);
559+
}
560+
landed.push(...rows);
561+
return { summary: { written_rows: String(rows.length) } };
562+
};
563+
const insertAllowingBadRows = async (rows: FakeRow[]) => {
564+
const good = rows.filter((r) => !r.poison);
565+
landed.push(...good);
566+
return { summary: { written_rows: String(good.length) } };
567+
};
568+
569+
const outcome = await insertWithLimitedStrip({
570+
rows: [clean(0), clean(1), { id: 2, poison: true }],
571+
contextLabel: "test",
572+
logger: silentLogger,
573+
insert: insertSync,
574+
insertSync,
575+
insertAllowingBadRows,
576+
stripJsonColumns: (row) => ({ ...row, poison: false, stripped: true }),
577+
});
578+
579+
expect(outcome).toEqual({
580+
kind: "recovered",
581+
rowsStripped: 1,
582+
rowsDropped: 0,
583+
rowsDroppedExact: true,
584+
capped: false,
585+
});
586+
expect(landed.map((r) => r.id).sort((a, b) => a - b)).toEqual([0, 1, 2]);
587+
expect(landed.find((r) => r.id === 2)?.stripped).toBe(true);
588+
expect(landed.filter((r) => r.id !== 2).every((r) => !r.stripped)).toBe(true);
589+
});
590+
591+
it("counts the batch as dropped instead of throwing when even allow_errors is rejected", async () => {
592+
const insertSync = async () => {
593+
throw parseErrorAtRow(1);
594+
};
595+
let allowCalls = 0;
596+
const insertAllowingBadRows = async () => {
597+
allowCalls += 1;
598+
throw new Error("Cannot parse JSON object here: {...}: (at row 1)");
599+
};
600+
601+
const outcome = await insertWithLimitedStrip({
602+
rows: [clean(0), { id: 1, poison: true }],
603+
contextLabel: "test",
604+
logger: silentLogger,
605+
insert: insertSync,
606+
insertSync,
607+
insertAllowingBadRows,
608+
stripJsonColumns: (row) => row,
609+
});
610+
611+
expect(outcome).toEqual({
612+
kind: "recovered",
613+
rowsStripped: 1,
614+
rowsDropped: 2,
615+
rowsDroppedExact: true,
616+
capped: true,
617+
bailReason: "strip_budget_spent",
618+
});
619+
expect(allowCalls).toBe(1);
620+
});
621+
622+
it("rethrows a transient failure of the allow_errors insert so the retry layer still runs", async () => {
623+
const insertSync = async () => {
624+
throw parseErrorAtRow(1);
625+
};
626+
const insertAllowingBadRows = async () => {
627+
throw new Error("Connection refused");
628+
};
629+
630+
await expect(
631+
insertWithLimitedStrip({
632+
rows: [clean(0), { id: 1, poison: true }],
633+
contextLabel: "test",
634+
logger: silentLogger,
635+
insert: insertSync,
636+
insertSync,
637+
insertAllowingBadRows,
638+
stripJsonColumns: (row) => row,
639+
})
640+
).rejects.toThrow("Connection refused");
641+
});
518642
});
519643

520644
/**
@@ -713,4 +837,51 @@ describe("insertWithBadRowSkip", () => {
713837
})
714838
).rejects.toThrow("Connection refused");
715839
});
840+
841+
it("counts the batch as dropped instead of throwing when even allow_errors is rejected", async () => {
842+
const insert = async () => {
843+
throw parseErrorAtRow(1);
844+
};
845+
let allowCalls = 0;
846+
const insertAllowingBadRows = async () => {
847+
allowCalls += 1;
848+
throw new Error("Cannot parse JSON object here: {...}: (at row 1)");
849+
};
850+
851+
const outcome = await insertWithBadRowSkip({
852+
rows: [clean(0), { id: 1, poison: true }, clean(2)],
853+
contextLabel: "test",
854+
logger: silentLogger,
855+
insert,
856+
insertAllowingBadRows,
857+
});
858+
859+
expect(outcome).toEqual({
860+
kind: "recovered",
861+
rowsStripped: 0,
862+
rowsDropped: 3,
863+
rowsDroppedExact: true,
864+
capped: false,
865+
});
866+
expect(allowCalls).toBe(1);
867+
});
868+
869+
it("rethrows a transient failure of the allow_errors insert so the retry layer still runs", async () => {
870+
const insert = async () => {
871+
throw parseErrorAtRow(1);
872+
};
873+
const insertAllowingBadRows = async () => {
874+
throw new Error("Connection refused");
875+
};
876+
877+
await expect(
878+
insertWithBadRowSkip({
879+
rows: [clean(0), { id: 1, poison: true }],
880+
contextLabel: "test",
881+
logger: silentLogger,
882+
insert,
883+
insertAllowingBadRows,
884+
})
885+
).rejects.toThrow("Connection refused");
886+
});
716887
});

0 commit comments

Comments
 (0)