Skip to content

Commit 660e7f1

Browse files
committed
fix(webapp,clickhouse): stop invalid customer queries alerting, and isolate Sentry scope per request
Three fixes to how query failures are reported. Invalid TSQL is a caller mistake, not ours: executeTSQL now logs ExposedTSQLError at warn and reserves error for InternalTSQLError and unanticipated exceptions, so a bad column name no longer raises an alert. The route above it already returned 400 and logged at warn; the layer below was overriding that decision. ClickHouse rejections that come from a query asking for too much (memory ceiling, timeout, row/byte caps) drop to warn as well. Those are decided in the client, which is the only place holding the parsed ClickHouseError type, and queryWithStats gained a logFields option so a failing query is recorded with the TSQL that generated it rather than the generated SQL alone. Sentry.init runs with skipOpenTelemetrySetup because we register our own OTel pipeline, which also skipped installing SentryContextManager. withIsolationScope only marks the context and relies on that manager to fork, so without it every request shared one global isolation scope and events were attributed to whichever request wrote last. The tracer now registers it, including on the path where tracing is disabled and register() was never called.
1 parent a3dca98 commit 660e7f1

8 files changed

Lines changed: 267 additions & 10 deletions

File tree

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,6 @@
1+
---
2+
area: webapp
3+
type: fix
4+
---
5+
6+
Fixed error reports being attributed to the wrong request when several requests were in flight at once.
Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,6 @@
1+
---
2+
area: webapp
3+
type: fix
4+
---
5+
6+
Invalid queries sent to the query API are no longer treated as internal errors, and a query that does fail is now recorded together with the query text that produced it.

apps/webapp/app/v3/tracer.server.ts

Lines changed: 21 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,7 @@
11
import {
22
type Attributes,
33
type Context,
4+
context as otelContext,
45
createContextKey,
56
DiagConsoleLogger,
67
DiagLogLevel,
@@ -14,6 +15,7 @@ import {
1415
metrics,
1516
type Meter,
1617
} from "@opentelemetry/api";
18+
import { SentryContextManager } from "@sentry/remix";
1719
import { logs, SeverityNumber } from "@opentelemetry/api-logs";
1820
import { OTLPTraceExporter } from "@opentelemetry/exporter-trace-otlp-http";
1921
import { OTLPLogExporter } from "@opentelemetry/exporter-logs-otlp-http";
@@ -209,10 +211,28 @@ function getResource() {
209211
return baseResource.merge(detectedResource);
210212
}
211213

214+
/**
215+
* Sentry's `withIsolationScope` only marks the OTel context; the fork itself is
216+
* done by Sentry's context manager. We pass `skipOpenTelemetrySetup: true` to
217+
* `Sentry.init` because we run our own OTel pipeline, which also skips the
218+
* `setGlobalContextManager(new SentryContextManager())` that Sentry would
219+
* otherwise do. Registering it here is what keeps per-request scopes (and so
220+
* the request attributed to each Sentry event) from leaking between concurrent
221+
* requests. It extends `AsyncLocalStorageContextManager`, so OTel behaviour is
222+
* unchanged.
223+
*/
224+
function createContextManager() {
225+
return new SentryContextManager();
226+
}
227+
212228
function setupTelemetry() {
213229
if (env.INTERNAL_OTEL_TRACE_DISABLED === "1") {
214230
console.log(`🔦 Tracer disabled, returning a noop tracer`);
215231

232+
const contextManager = createContextManager();
233+
contextManager.enable();
234+
otelContext.setGlobalContextManager(contextManager);
235+
216236
return {
217237
tracer: trace.getTracer("trigger.dev", "3.3.12"),
218238
logger: logs.getLogger("trigger.dev", "3.3.12"),
@@ -300,7 +320,7 @@ function setupTelemetry() {
300320
);
301321
}
302322

303-
provider.register();
323+
provider.register({ contextManager: createContextManager() });
304324

305325
let instrumentations: Instrumentation[] = [
306326
new AwsSdkInstrumentation({
Lines changed: 51 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,51 @@
1+
import { context } from "@opentelemetry/api";
2+
import { NodeTracerProvider } from "@opentelemetry/sdk-trace-node";
3+
import * as Sentry from "@sentry/remix";
4+
import { SentryContextManager } from "@sentry/remix";
5+
import { afterEach, beforeAll, describe, expect, it } from "vitest";
6+
7+
/**
8+
* Two overlapping requests, each tagging its own isolation scope, mirroring what
9+
* `SentryHttpInstrumentation` does per incoming request. Returns what each one
10+
* reads back after the other has started.
11+
*/
12+
async function raceTwoRequests(): Promise<Record<string, unknown>> {
13+
const observed: Record<string, unknown> = {};
14+
15+
const handleRequest = (name: string, holdMs: number) =>
16+
Sentry.withIsolationScope(async () => {
17+
Sentry.getIsolationScope().setTag("request", name);
18+
await new Promise((resolve) => setTimeout(resolve, holdMs));
19+
observed[name] = Sentry.getIsolationScope().getScopeData().tags.request;
20+
});
21+
22+
await Promise.all([handleRequest("slow", 30), handleRequest("fast", 5)]);
23+
24+
return observed;
25+
}
26+
27+
describe("Sentry request isolation", () => {
28+
beforeAll(() => {
29+
Sentry.init({ dsn: undefined, defaultIntegrations: false, skipOpenTelemetrySetup: true });
30+
});
31+
32+
afterEach(() => {
33+
context.disable();
34+
});
35+
36+
it("leaks the isolation scope between concurrent requests without SentryContextManager", async () => {
37+
new NodeTracerProvider().register();
38+
39+
const observed = await raceTwoRequests();
40+
41+
expect(observed).toEqual({ slow: "fast", fast: "fast" });
42+
});
43+
44+
it("keeps each request's isolation scope separate with SentryContextManager", async () => {
45+
new NodeTracerProvider().register({ contextManager: new SentryContextManager() });
46+
47+
const observed = await raceTwoRequests();
48+
49+
expect(observed).toEqual({ slow: "slow", fast: "fast" });
50+
});
51+
});

internal-packages/clickhouse/src/client/client.ts

Lines changed: 53 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -171,13 +171,19 @@ export class ClickhouseClient implements ClickhouseReader, ClickhouseWriter {
171171
);
172172

173173
if (clickhouseError) {
174-
this.logger.error("Error querying clickhouse", {
174+
const errorLogFields = {
175175
name: req.name,
176176
error: clickhouseError,
177177
query: req.query,
178178
params,
179179
queryId,
180-
});
180+
};
181+
182+
if (isClickhouseQuotaError(clickhouseError)) {
183+
this.logger.warn("Query exceeded a ClickHouse limit", errorLogFields);
184+
} else {
185+
this.logger.error("Error querying clickhouse", errorLogFields);
186+
}
181187

182188
recordClickhouseError(span, clickhouseError);
183189

@@ -260,6 +266,11 @@ export class ClickhouseClient implements ClickhouseReader, ClickhouseWriter {
260266
* These will be merged with the default settings.
261267
*/
262268
settings?: ClickHouseSettings;
269+
/**
270+
* Extra fields to attach to the error log if the query fails. Use this to
271+
* record what produced the SQL, e.g. the TSQL a caller actually wrote.
272+
*/
273+
logFields?: Record<string, unknown>;
263274
}): ClickhouseQueryWithStatsFunction<z.input<TIn>, z.output<TOut>> {
264275
return async (params, options) => {
265276
const queryId = randomUUID();
@@ -320,13 +331,20 @@ export class ClickhouseClient implements ClickhouseReader, ClickhouseWriter {
320331
);
321332

322333
if (clickhouseError) {
323-
this.logger.error("Error querying clickhouse", {
334+
const errorLogFields = {
324335
name: req.name,
325336
error: clickhouseError,
326337
query: req.query,
327338
params,
328339
queryId,
329-
});
340+
...req.logFields,
341+
};
342+
343+
if (isClickhouseQuotaError(clickhouseError)) {
344+
this.logger.warn("Query exceeded a ClickHouse limit", errorLogFields);
345+
} else {
346+
this.logger.error("Error querying clickhouse", errorLogFields);
347+
}
330348

331349
recordClickhouseError(span, clickhouseError);
332350

@@ -453,13 +471,19 @@ export class ClickhouseClient implements ClickhouseReader, ClickhouseWriter {
453471
);
454472

455473
if (clickhouseError) {
456-
this.logger.error("Error querying clickhouse", {
474+
const errorLogFields = {
457475
name: req.name,
458476
error: clickhouseError,
459477
query: req.query,
460478
params,
461479
queryId,
462-
});
480+
};
481+
482+
if (isClickhouseQuotaError(clickhouseError)) {
483+
this.logger.warn("Query exceeded a ClickHouse limit", errorLogFields);
484+
} else {
485+
this.logger.error("Error querying clickhouse", errorLogFields);
486+
}
463487

464488
recordClickhouseError(span, clickhouseError);
465489

@@ -1001,6 +1025,29 @@ export class ClickhouseClient implements ClickhouseReader, ClickhouseWriter {
10011025
}
10021026
}
10031027

1028+
/**
1029+
* ClickHouse error types raised by a query that is valid but asks for more than
1030+
* the caller is allowed to spend. The caller gets a 4xx and there is nothing on
1031+
* our side to fix, so these are logged at warn rather than error.
1032+
*/
1033+
const CLICKHOUSE_QUOTA_ERROR_TYPES = new Set([
1034+
"MEMORY_LIMIT_EXCEEDED",
1035+
"TIMEOUT_EXCEEDED",
1036+
"TOO_SLOW",
1037+
"TOO_MANY_ROWS",
1038+
"TOO_MANY_BYTES",
1039+
"TOO_MANY_ROWS_OR_BYTES",
1040+
"QUERY_WAS_CANCELLED",
1041+
]);
1042+
1043+
function isClickhouseQuotaError(error: Error): boolean {
1044+
return (
1045+
error instanceof ClickHouseError &&
1046+
error.type !== undefined &&
1047+
CLICKHOUSE_QUOTA_ERROR_TYPES.has(error.type)
1048+
);
1049+
}
1050+
10041051
function recordClickhouseError(span: Span, error: Error): void {
10051052
if (error instanceof ClickHouseError) {
10061053
span.setAttributes({

internal-packages/clickhouse/src/client/tsql.ts

Lines changed: 12 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -8,6 +8,7 @@
88
import type { ClickHouseSettings } from "@clickhouse/client";
99
import {
1010
compileTSQL,
11+
ExposedTSQLError,
1112
type OutputColumnMetadata,
1213
sanitizeErrorMessage,
1314
transformResults,
@@ -207,6 +208,7 @@ export async function executeTSQL<TOut extends z.ZodSchema>(
207208
// EXPLAIN returns rows with an 'explain' column
208209
schema: isExplain ? z.object({ explain: z.string() }) : options.schema,
209210
settings: options.clickhouseSettings,
211+
logFields: { tsql: options.query },
210212
});
211213

212214
const [error, result] = await queryFn(params);
@@ -297,14 +299,21 @@ export async function executeTSQL<TOut extends z.ZodSchema>(
297299
} catch (error) {
298300
const errorMessage = error instanceof Error ? error.message : "Unknown error";
299301

300-
// Log TSQL compilation or unexpected errors (with original message for debugging)
301-
logger.error("[TSQL] Query error", {
302+
const logFields = {
302303
name: options.name,
303304
error: errorMessage,
304305
tsql: options.query,
305306
generatedSql: generatedSql ?? "(compilation failed)",
306307
generatedParams: generatedParams ?? {},
307-
});
308+
};
309+
310+
const callerWroteABadQuery = error instanceof ExposedTSQLError;
311+
312+
if (callerWroteABadQuery) {
313+
logger.warn("[TSQL] Invalid query", logFields);
314+
} else {
315+
logger.error("[TSQL] Query error", logFields);
316+
}
308317

309318
// Sanitize error message to show TSQL names instead of ClickHouse internals
310319
const sanitizedMessage = sanitizeErrorMessage(errorMessage, options.tableSchema);

internal-packages/clickhouse/src/client/types.ts

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -135,6 +135,11 @@ export interface ClickhouseReader {
135135
* These will be merged with the default settings.
136136
*/
137137
settings?: ClickHouseSettings;
138+
/**
139+
* Extra fields to attach to the error log if the query fails. Use this to
140+
* record what produced the SQL, e.g. the TSQL a caller actually wrote.
141+
*/
142+
logFields?: Record<string, unknown>;
138143
}): ClickhouseQueryWithStatsFunction<z.input<TIn>, z.output<TOut>>;
139144

140145
queryFast<TOut extends Record<string, any>, TParams extends Record<string, any>>(req: {

0 commit comments

Comments
 (0)