fix(webapp,clickhouse): stop invalid customer queries alerting, and isolate Sentry scope per request (#4372)
## Summary
A query sent to the query API with a typo in it, like a column name that
does not exist, was being reported as a server error. That put customer
SQL mistakes into our error alerting, where they made up almost all of
the volume on one of our noisiest alerts, and it drowned out the
failures that are actually ours to fix. This makes the level match who
is at fault, and fixes two related problems found alongside it.
## Invalid queries are the caller's, not ours
The query API route already got this right. It checks for `QueryError`,
logs at warn, and returns a 400, with a comment saying the system
handles it gracefully and no alert is needed.
The layer underneath ignored that. `executeTSQL` logged every exception
out of its catch block at error, including the compile failures the
route was about to turn into a 400, and error-level logs are forwarded
to error reporting.
The TSQL package already draws the line we need:
```ts
export class ExposedTSQLError extends BaseTSQLError {
/** An exception that can be exposed to the user. */
}
export class InternalTSQLError extends BaseTSQLError {
/** An internal exception in the TSQL engine. */
}
```
`SyntaxError` and `QueryError` extend the first. So the catch block now
branches on `ExposedTSQLError` and logs those at warn, keeping error for
`InternalTSQLError` and anything unanticipated, which is a genuine
compiler bug.
## SQL the caller wrote is their mistake, not ours
The same asymmetry showed up one level down. A query that compiles fine
can still be rejected by ClickHouse at execution, and most of those
rejections mean the caller's SQL is wrong rather than that we generated
something bad.
This is where the volume actually is. Checking production, one error
group alone, a missing `GROUP BY` on the public query API
(`NOT_AN_AGGREGATE`), accounts for over a million events across hundreds
of users. It is by far the largest error group in the project, and
classifying only by resource limit would have left every one of those at
error level.
So rejections are split three ways in `ClickhouseClient`, which is the
only place holding the parsed `ClickHouseError` and its symbolic type.
By the time the error reaches `executeTSQL` it has been wrapped and the
type is gone, and the type never appears in the message text, so it
cannot be recovered by string matching.
- **Resource limits** (memory ceiling, timeout, row/byte caps) log at
warn. The query is valid, it just asked for more than it is allowed to
spend.
- **Invalid SQL** (`NOT_AN_AGGREGATE`, `UNKNOWN_IDENTIFIER`,
`SYNTAX_ERROR`, the type and parse families) logs at warn **only when
the caller wrote the SQL**.
- **Everything else** keeps alerting.
That gate matters. The client is shared, so the identical rejection on
TRQL *we* generated is our bug and has to stay at error. Callers opt in
with `userAuthoredQuery`:
| caller | who wrote the SQL | opts in |
| --- | --- | --- |
| public query API | the customer | yes |
| query editor | the customer | yes |
| agent charts | the agent's model | yes |
| built-in dashboard tiles | us, in code | no |
| queue metric cards | us, in code | no |
| health report | us, in code | no |
The agent is the one judgement call. Its TRQL is not typed by a person,
but it is also not something a code fix makes correct, so a query it
gets wrong is not worth waking anyone for. The same endpoint serves
built-in tiles whose TRQL we do write, so the opt-in lives with the
caller rather than the route.
Separately, when one of these queries did fail, the log recorded the
generated ClickHouse SQL but not the query the caller actually wrote,
which made the reports hard to act on. `queryWithStats` takes an
optional `logFields` that `executeTSQL` uses to attach the original
TSQL.
## Events were attributed to the wrong request
Chasing the above turned up something broader: only a tenth of the
events on that alert pointed at the query API. The rest were pinned to
unrelated requests that happened to be in flight at the same time, so
the alert looked like the trigger endpoint was failing.
`Sentry.init` runs with `skipOpenTelemetrySetup: true`, because we
register our own OTel pipeline. That skips `initOpenTelemetry`, and one
of the things it does is:
```js
api.context.setGlobalContextManager(new SentryContextManager());
```
The async-context strategy is still installed, but `withIsolationScope`
only marks the OTel context and delegates the actual fork to that
context manager:
```js
// "We depend on the otelContextManager to handle the context/hub"
return api.context.with(ctx.setValue(SENTRY_FORK_ISOLATION_SCOPE_CONTEXT_KEY, true), ...)
```
`provider.register()` installed a plain
`AsyncLocalStorageContextManager`, which does not know that key. The
lookup found no scopes on the context and fell back to the
process-global default isolation scope, so every request wrote its
request data into the same object and the last writer won.
The tracer now registers `SentryContextManager`, which subclasses
`AsyncLocalStorageContextManager`, so OTel behaviour is unchanged. It is
also registered on the path where tracing is disabled, which previously
never called `register()` at all and so had no context manager of its
own.
Tenant tags were always correct, because those come from our own async
local storage rather than the isolation scope. That is why the
attribution being wrong was not obvious.
This affects every error report the webapp sends, not just the query
API.
## Verification
`internal-packages/clickhouse`: 76 tests pass, including eight covering
each level decision against a real ClickHouse container. Three pairs pin
the gate open and shut at both layers: an invalid query, a compile
failure, and a real limit breach driven with `max_rows_to_read` each log
at warn with `userAuthoredQuery` and at error without it.
The isolation fix has a test that reproduces the leak before asserting
the fix. Two overlapping requests each tag their own isolation scope;
with the plain context manager the slower one reads back the other's
tag, and with `SentryContextManager` each reads back its own.
Measured separately against a faithful reproduction of the server's
wiring (own OTel pipeline, CommonJS entry) at 200 concurrent requests:
per-request attribution goes from 0.5% to 100%, while span nesting,
context propagation across awaits, and distinct trace IDs are identical
before and after.
This commit is contained in:
@@ -0,0 +1,6 @@
|
||||
---
|
||||
area: webapp
|
||||
type: fix
|
||||
---
|
||||
|
||||
Fixed error reports being attributed to the wrong request when several requests were in flight at once.
|
||||
@@ -0,0 +1,6 @@
|
||||
---
|
||||
area: webapp
|
||||
type: fix
|
||||
---
|
||||
|
||||
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.
|
||||
@@ -67,6 +67,7 @@ export function AgentChart({ block }: { block: ChartBlock }) {
|
||||
period: block.period ?? null,
|
||||
from: null,
|
||||
to: null,
|
||||
userAuthoredQuery: true,
|
||||
}),
|
||||
signal: controller.signal,
|
||||
})
|
||||
|
||||
+1
@@ -183,6 +183,7 @@ export const action = async ({ request, params }: ActionFunctionArgs) => {
|
||||
const queryResult = await executeQuery({
|
||||
name: "query-page",
|
||||
query,
|
||||
userAuthoredQuery: true,
|
||||
scope,
|
||||
organizationId: project.organizationId,
|
||||
projectId: project.id,
|
||||
|
||||
@@ -54,6 +54,7 @@ const { action, loader } = createActionApiRoute(
|
||||
const queryResult = await executeQuery({
|
||||
name: "api-query",
|
||||
query,
|
||||
userAuthoredQuery: true,
|
||||
scope: scope as QueryScope,
|
||||
organizationId: env.organization.id,
|
||||
projectId: env.project.id,
|
||||
|
||||
@@ -52,6 +52,7 @@ const MetricWidgetQuery = z.object({
|
||||
tags: z.array(z.string()).optional(),
|
||||
// Opt into server-side gap fill (carry-forward for gauges, zero-fill for counters).
|
||||
fillGaps: z.boolean().optional(),
|
||||
userAuthoredQuery: z.boolean().optional(),
|
||||
});
|
||||
|
||||
export const action = async ({ request }: ActionFunctionArgs) => {
|
||||
@@ -88,6 +89,7 @@ export const action = async ({ request }: ActionFunctionArgs) => {
|
||||
providers,
|
||||
tags: _tags,
|
||||
fillGaps,
|
||||
userAuthoredQuery,
|
||||
} = submission.data;
|
||||
|
||||
// Check they should be able to access it
|
||||
@@ -126,6 +128,7 @@ export const action = async ({ request }: ActionFunctionArgs) => {
|
||||
operations,
|
||||
providers,
|
||||
fillGaps,
|
||||
userAuthoredQuery,
|
||||
// Set higher concurrency if many widgets are on screen at once
|
||||
customOrgConcurrencyLimit: env.METRIC_WIDGET_DEFAULT_ORG_CONCURRENCY_LIMIT,
|
||||
});
|
||||
|
||||
@@ -100,6 +100,13 @@ export type ExecuteQueryOptions<TOut extends z.ZodSchema> = Omit<
|
||||
};
|
||||
/** Custom per-org concurrency limit (overrides default) */
|
||||
customOrgConcurrencyLimit?: number;
|
||||
/**
|
||||
* Set when the caller wrote `query` themselves, as on the public query API and
|
||||
* the query editor. ClickHouse rejecting their SQL is then their mistake, so it
|
||||
* is logged as a warning instead of raising an alert. Leave unset for TRQL we
|
||||
* generate, where the same rejection is a bug worth alerting on.
|
||||
*/
|
||||
userAuthoredQuery?: boolean;
|
||||
};
|
||||
|
||||
/**
|
||||
|
||||
@@ -1,6 +1,7 @@
|
||||
import {
|
||||
type Attributes,
|
||||
type Context,
|
||||
context as otelContext,
|
||||
createContextKey,
|
||||
DiagConsoleLogger,
|
||||
DiagLogLevel,
|
||||
@@ -14,6 +15,7 @@ import {
|
||||
metrics,
|
||||
type Meter,
|
||||
} from "@opentelemetry/api";
|
||||
import sentryRemix from "@sentry/remix";
|
||||
import { logs, SeverityNumber } from "@opentelemetry/api-logs";
|
||||
import { OTLPTraceExporter } from "@opentelemetry/exporter-trace-otlp-http";
|
||||
import { OTLPLogExporter } from "@opentelemetry/exporter-logs-otlp-http";
|
||||
@@ -209,10 +211,32 @@ function getResource() {
|
||||
return baseResource.merge(detectedResource);
|
||||
}
|
||||
|
||||
/**
|
||||
* Sentry's `withIsolationScope` only marks the OTel context; the fork itself is
|
||||
* done by Sentry's context manager. We pass `skipOpenTelemetrySetup: true` to
|
||||
* `Sentry.init` because we run our own OTel pipeline, which also skips the
|
||||
* `setGlobalContextManager(new SentryContextManager())` that Sentry would
|
||||
* otherwise do. Registering it here is what keeps per-request scopes (and so
|
||||
* the request attributed to each Sentry event) from leaking between concurrent
|
||||
* requests. It extends `AsyncLocalStorageContextManager`, so OTel behaviour is
|
||||
* unchanged.
|
||||
*
|
||||
* Reached through the default export because `@sentry/remix` is CommonJS and
|
||||
* Node's ESM loader does not detect this transitively re-exported name, so a
|
||||
* named import resolves at build time and then fails when the server boots.
|
||||
*/
|
||||
function createContextManager() {
|
||||
return new sentryRemix.SentryContextManager();
|
||||
}
|
||||
|
||||
function setupTelemetry() {
|
||||
if (env.INTERNAL_OTEL_TRACE_DISABLED === "1") {
|
||||
console.log(`🔦 Tracer disabled, returning a noop tracer`);
|
||||
|
||||
const contextManager = createContextManager();
|
||||
contextManager.enable();
|
||||
otelContext.setGlobalContextManager(contextManager);
|
||||
|
||||
return {
|
||||
tracer: trace.getTracer("trigger.dev", "3.3.12"),
|
||||
logger: logs.getLogger("trigger.dev", "3.3.12"),
|
||||
@@ -300,7 +324,7 @@ function setupTelemetry() {
|
||||
);
|
||||
}
|
||||
|
||||
provider.register();
|
||||
provider.register({ contextManager: createContextManager() });
|
||||
|
||||
let instrumentations: Instrumentation[] = [
|
||||
new AwsSdkInstrumentation({
|
||||
|
||||
@@ -0,0 +1,51 @@
|
||||
import { context } from "@opentelemetry/api";
|
||||
import { NodeTracerProvider } from "@opentelemetry/sdk-trace-node";
|
||||
import * as Sentry from "@sentry/remix";
|
||||
import sentryRemix from "@sentry/remix";
|
||||
import { afterEach, beforeAll, describe, expect, it } from "vitest";
|
||||
|
||||
/**
|
||||
* Two overlapping requests, each tagging its own isolation scope, mirroring what
|
||||
* `SentryHttpInstrumentation` does per incoming request. Returns what each one
|
||||
* reads back after the other has started.
|
||||
*/
|
||||
async function raceTwoRequests(): Promise<Record<string, unknown>> {
|
||||
const observed: Record<string, unknown> = {};
|
||||
|
||||
const handleRequest = (name: string, holdMs: number) =>
|
||||
Sentry.withIsolationScope(async () => {
|
||||
Sentry.getIsolationScope().setTag("request", name);
|
||||
await new Promise((resolve) => setTimeout(resolve, holdMs));
|
||||
observed[name] = Sentry.getIsolationScope().getScopeData().tags.request;
|
||||
});
|
||||
|
||||
await Promise.all([handleRequest("slow", 30), handleRequest("fast", 5)]);
|
||||
|
||||
return observed;
|
||||
}
|
||||
|
||||
describe("Sentry request isolation", () => {
|
||||
beforeAll(() => {
|
||||
Sentry.init({ dsn: undefined, defaultIntegrations: false, skipOpenTelemetrySetup: true });
|
||||
});
|
||||
|
||||
afterEach(() => {
|
||||
context.disable();
|
||||
});
|
||||
|
||||
it("leaks the isolation scope between concurrent requests without SentryContextManager", async () => {
|
||||
new NodeTracerProvider().register();
|
||||
|
||||
const observed = await raceTwoRequests();
|
||||
|
||||
expect(observed).toEqual({ slow: "fast", fast: "fast" });
|
||||
});
|
||||
|
||||
it("keeps each request's isolation scope separate with SentryContextManager", async () => {
|
||||
new NodeTracerProvider().register({ contextManager: new sentryRemix.SentryContextManager() });
|
||||
|
||||
const observed = await raceTwoRequests();
|
||||
|
||||
expect(observed).toEqual({ slow: "slow", fast: "fast" });
|
||||
});
|
||||
});
|
||||
@@ -171,13 +171,15 @@ export class ClickhouseClient implements ClickhouseReader, ClickhouseWriter {
|
||||
);
|
||||
|
||||
if (clickhouseError) {
|
||||
this.logger.error("Error querying clickhouse", {
|
||||
const errorLogFields = {
|
||||
name: req.name,
|
||||
error: clickhouseError,
|
||||
query: req.query,
|
||||
params,
|
||||
queryId,
|
||||
});
|
||||
};
|
||||
|
||||
this.logger.error("Error querying clickhouse", errorLogFields);
|
||||
|
||||
recordClickhouseError(span, clickhouseError);
|
||||
|
||||
@@ -260,6 +262,16 @@ export class ClickhouseClient implements ClickhouseReader, ClickhouseWriter {
|
||||
* These will be merged with the default settings.
|
||||
*/
|
||||
settings?: ClickHouseSettings;
|
||||
/**
|
||||
* Extra fields to attach to the error log if the query fails. Use this to
|
||||
* record what produced the SQL, e.g. the TSQL a caller actually wrote.
|
||||
*/
|
||||
logFields?: Record<string, unknown>;
|
||||
/**
|
||||
* Set when the SQL originates from whoever made the request rather than
|
||||
* from us. Invalid-SQL rejections are then their mistake, not a bug.
|
||||
*/
|
||||
userAuthoredQuery?: boolean;
|
||||
}): ClickhouseQueryWithStatsFunction<z.input<TIn>, z.output<TOut>> {
|
||||
return async (params, options) => {
|
||||
const queryId = randomUUID();
|
||||
@@ -320,13 +332,25 @@ export class ClickhouseClient implements ClickhouseReader, ClickhouseWriter {
|
||||
);
|
||||
|
||||
if (clickhouseError) {
|
||||
this.logger.error("Error querying clickhouse", {
|
||||
const errorLogFields = {
|
||||
...req.logFields,
|
||||
name: req.name,
|
||||
error: clickhouseError,
|
||||
query: req.query,
|
||||
params,
|
||||
queryId,
|
||||
});
|
||||
};
|
||||
|
||||
switch (classifyClickhouseError(clickhouseError, req.userAuthoredQuery)) {
|
||||
case "quota":
|
||||
this.logger.warn("Query exceeded a ClickHouse limit", errorLogFields);
|
||||
break;
|
||||
case "invalid-sql":
|
||||
this.logger.warn("ClickHouse rejected an invalid query", errorLogFields);
|
||||
break;
|
||||
default:
|
||||
this.logger.error("Error querying clickhouse", errorLogFields);
|
||||
}
|
||||
|
||||
recordClickhouseError(span, clickhouseError);
|
||||
|
||||
@@ -453,13 +477,15 @@ export class ClickhouseClient implements ClickhouseReader, ClickhouseWriter {
|
||||
);
|
||||
|
||||
if (clickhouseError) {
|
||||
this.logger.error("Error querying clickhouse", {
|
||||
const errorLogFields = {
|
||||
name: req.name,
|
||||
error: clickhouseError,
|
||||
query: req.query,
|
||||
params,
|
||||
queryId,
|
||||
});
|
||||
};
|
||||
|
||||
this.logger.error("Error querying clickhouse", errorLogFields);
|
||||
|
||||
recordClickhouseError(span, clickhouseError);
|
||||
|
||||
@@ -599,13 +625,15 @@ export class ClickhouseClient implements ClickhouseReader, ClickhouseWriter {
|
||||
|
||||
span.setAttributes({ "clickhouse.rows": rowCount });
|
||||
} catch (error) {
|
||||
self.logger.error("Error streaming clickhouse", {
|
||||
const errorLogFields = {
|
||||
name: req.name,
|
||||
error,
|
||||
query: req.query,
|
||||
params,
|
||||
queryId,
|
||||
});
|
||||
};
|
||||
|
||||
self.logger.error("Error streaming clickhouse", errorLogFields);
|
||||
|
||||
if (error instanceof Error) {
|
||||
recordClickhouseError(span, error);
|
||||
@@ -1001,6 +1029,65 @@ export class ClickhouseClient implements ClickhouseReader, ClickhouseWriter {
|
||||
}
|
||||
}
|
||||
|
||||
/**
|
||||
* ClickHouse error types raised by a query that is valid but asks for more than
|
||||
* it is allowed to spend. Only downgraded for SQL the caller wrote: a runaway
|
||||
* query we generated is our bug and still has to alert.
|
||||
*/
|
||||
const CLICKHOUSE_QUOTA_ERROR_TYPES = new Set([
|
||||
"MEMORY_LIMIT_EXCEEDED",
|
||||
"TIMEOUT_EXCEEDED",
|
||||
"TOO_SLOW",
|
||||
"TOO_MANY_ROWS",
|
||||
"TOO_MANY_BYTES",
|
||||
"TOO_MANY_ROWS_OR_BYTES",
|
||||
]);
|
||||
|
||||
/**
|
||||
* ClickHouse error types that mean the SQL itself is wrong. Only treated as the
|
||||
* caller's fault when the query was written by the caller — the same error on a
|
||||
* query we generated is our bug and has to keep alerting.
|
||||
*/
|
||||
const CLICKHOUSE_INVALID_SQL_ERROR_TYPES = new Set([
|
||||
"NOT_AN_AGGREGATE",
|
||||
"ILLEGAL_AGGREGATION",
|
||||
"UNKNOWN_IDENTIFIER",
|
||||
"UNKNOWN_FUNCTION",
|
||||
"UNKNOWN_TABLE",
|
||||
"AMBIGUOUS_COLUMN_NAME",
|
||||
"MULTIPLE_EXPRESSIONS_FOR_ALIAS",
|
||||
"SYNTAX_ERROR",
|
||||
"BAD_ARGUMENTS",
|
||||
"TYPE_MISMATCH",
|
||||
"NO_COMMON_TYPE",
|
||||
"ILLEGAL_TYPE_OF_ARGUMENT",
|
||||
"ILLEGAL_COLUMN",
|
||||
"CANNOT_CONVERT_TYPE",
|
||||
"CANNOT_PARSE_TEXT",
|
||||
"CANNOT_PARSE_NUMBER",
|
||||
"CANNOT_PARSE_DATE",
|
||||
"CANNOT_PARSE_DATETIME",
|
||||
"CANNOT_PARSE_INPUT_ASSERTION_FAILED",
|
||||
]);
|
||||
|
||||
type ClickhouseErrorCategory = "quota" | "invalid-sql" | "fault";
|
||||
|
||||
function classifyClickhouseError(
|
||||
error: Error,
|
||||
userAuthoredQuery: boolean | undefined
|
||||
): ClickhouseErrorCategory {
|
||||
if (!userAuthoredQuery || !(error instanceof ClickHouseError) || error.type === undefined) {
|
||||
return "fault";
|
||||
}
|
||||
if (CLICKHOUSE_QUOTA_ERROR_TYPES.has(error.type)) {
|
||||
return "quota";
|
||||
}
|
||||
if (CLICKHOUSE_INVALID_SQL_ERROR_TYPES.has(error.type)) {
|
||||
return "invalid-sql";
|
||||
}
|
||||
return "fault";
|
||||
}
|
||||
|
||||
function recordClickhouseError(span: Span, error: Error): void {
|
||||
if (error instanceof ClickHouseError) {
|
||||
span.setAttributes({
|
||||
|
||||
@@ -8,6 +8,7 @@
|
||||
import type { ClickHouseSettings } from "@clickhouse/client";
|
||||
import {
|
||||
compileTSQL,
|
||||
ExposedTSQLError,
|
||||
type OutputColumnMetadata,
|
||||
sanitizeErrorMessage,
|
||||
transformResults,
|
||||
@@ -113,6 +114,11 @@ export interface ExecuteTSQLOptions<TOut extends z.ZodSchema> {
|
||||
* (counters zero-fill, gauges carry forward). Off by default.
|
||||
*/
|
||||
fillGaps?: boolean;
|
||||
/**
|
||||
* Set when `query` was written by whoever made the request rather than by us.
|
||||
* A rejection of their SQL is then their mistake, not a bug on our side.
|
||||
*/
|
||||
userAuthoredQuery?: boolean;
|
||||
}
|
||||
|
||||
/**
|
||||
@@ -213,6 +219,8 @@ export async function executeTSQL<TOut extends z.ZodSchema>(
|
||||
// EXPLAIN returns rows with an 'explain' column
|
||||
schema: isExplain ? z.object({ explain: z.string() }) : options.schema,
|
||||
settings: options.clickhouseSettings,
|
||||
logFields: { tsql: options.query },
|
||||
userAuthoredQuery: options.userAuthoredQuery,
|
||||
});
|
||||
|
||||
const [error, result] = await queryFn(params);
|
||||
@@ -246,6 +254,8 @@ export async function executeTSQL<TOut extends z.ZodSchema>(
|
||||
params: z.record(z.any()),
|
||||
schema: z.object({ explain: z.string() }),
|
||||
settings: options.clickhouseSettings,
|
||||
logFields: { tsql: options.query },
|
||||
userAuthoredQuery: options.userAuthoredQuery,
|
||||
});
|
||||
|
||||
const [additionalError, additionalResult] = await additionalQueryFn(params);
|
||||
@@ -303,14 +313,21 @@ export async function executeTSQL<TOut extends z.ZodSchema>(
|
||||
} catch (error) {
|
||||
const errorMessage = error instanceof Error ? error.message : "Unknown error";
|
||||
|
||||
// Log TSQL compilation or unexpected errors (with original message for debugging)
|
||||
logger.error("[TSQL] Query error", {
|
||||
const logFields = {
|
||||
name: options.name,
|
||||
error: errorMessage,
|
||||
tsql: options.query,
|
||||
generatedSql: generatedSql ?? "(compilation failed)",
|
||||
generatedParams: generatedParams ?? {},
|
||||
});
|
||||
};
|
||||
|
||||
const callerWroteABadQuery = options.userAuthoredQuery && error instanceof ExposedTSQLError;
|
||||
|
||||
if (callerWroteABadQuery) {
|
||||
logger.warn("[TSQL] Invalid query", logFields);
|
||||
} else {
|
||||
logger.error("[TSQL] Query error", logFields);
|
||||
}
|
||||
|
||||
// Sanitize error message to show TSQL names instead of ClickHouse internals
|
||||
const sanitizedMessage = sanitizeErrorMessage(errorMessage, options.tableSchema);
|
||||
|
||||
@@ -135,6 +135,16 @@ export interface ClickhouseReader {
|
||||
* These will be merged with the default settings.
|
||||
*/
|
||||
settings?: ClickHouseSettings;
|
||||
/**
|
||||
* Extra fields to attach to the error log if the query fails. Use this to
|
||||
* record what produced the SQL, e.g. the TSQL a caller actually wrote.
|
||||
*/
|
||||
logFields?: Record<string, unknown>;
|
||||
/**
|
||||
* Set when the SQL originates from whoever made the request rather than
|
||||
* from us. Invalid-SQL rejections are then their mistake, not a bug.
|
||||
*/
|
||||
userAuthoredQuery?: boolean;
|
||||
}): ClickhouseQueryWithStatsFunction<z.input<TIn>, z.output<TOut>>;
|
||||
|
||||
queryFast<TOut extends Record<string, any>, TParams extends Record<string, any>>(req: {
|
||||
|
||||
@@ -1,4 +1,5 @@
|
||||
import { clickhouseTest } from "@internal/testcontainers";
|
||||
import type { MockInstance } from "vitest";
|
||||
import { z } from "zod";
|
||||
import { ClickhouseClient } from "./client/client.js";
|
||||
import { executeTSQL, createTSQLExecutor, type TableSchema } from "./client/tsql.js";
|
||||
@@ -1609,3 +1610,222 @@ describe("Field Mapping Tests", () => {
|
||||
expect(result?.rows?.map((r) => r.run_id).sort()).toEqual(["run_fm_in1", "run_fm_in2"]);
|
||||
});
|
||||
});
|
||||
|
||||
describe("TSQL Error Log Levels", () => {
|
||||
let warnSpy: MockInstance<typeof console.warn>;
|
||||
let errorSpy: MockInstance<typeof console.error>;
|
||||
|
||||
beforeEach(() => {
|
||||
warnSpy = vi.spyOn(console, "warn").mockImplementation(() => {});
|
||||
errorSpy = vi.spyOn(console, "error").mockImplementation(() => {});
|
||||
});
|
||||
|
||||
afterEach(() => {
|
||||
vi.restoreAllMocks();
|
||||
});
|
||||
|
||||
function logged(spy: MockInstance<typeof console.warn>): string {
|
||||
return spy.mock.calls.map(([line]) => String(line)).join("\n");
|
||||
}
|
||||
|
||||
clickhouseTest("logs an unknown column as a warning", async ({ clickhouseContainer }) => {
|
||||
const client = new ClickhouseClient({
|
||||
name: "test",
|
||||
url: clickhouseContainer.getConnectionUrl(),
|
||||
});
|
||||
|
||||
const [error] = await executeTSQL(client, {
|
||||
name: "test-unknown-column",
|
||||
query: "SELECT nope FROM task_runs",
|
||||
schema: z.object({ nope: z.string() }),
|
||||
enforcedWhereClause: {
|
||||
organization_id: { op: "eq", value: "org_tenant1" },
|
||||
},
|
||||
tableSchema: [taskRunsSchema],
|
||||
userAuthoredQuery: true,
|
||||
});
|
||||
|
||||
expect(error).not.toBeNull();
|
||||
expect(logged(warnSpy)).toContain("[TSQL] Invalid query");
|
||||
expect(logged(errorSpy)).not.toContain("[TSQL] Query error");
|
||||
});
|
||||
|
||||
clickhouseTest("logs a syntax error as a warning", async ({ clickhouseContainer }) => {
|
||||
const client = new ClickhouseClient({
|
||||
name: "test",
|
||||
url: clickhouseContainer.getConnectionUrl(),
|
||||
});
|
||||
|
||||
const [error] = await executeTSQL(client, {
|
||||
name: "test-syntax-error",
|
||||
query: "SELECT FROM WHERE",
|
||||
schema: z.object({ run_id: z.string() }),
|
||||
enforcedWhereClause: {
|
||||
organization_id: { op: "eq", value: "org_tenant1" },
|
||||
},
|
||||
tableSchema: [taskRunsSchema],
|
||||
userAuthoredQuery: true,
|
||||
});
|
||||
|
||||
expect(error).not.toBeNull();
|
||||
expect(logged(warnSpy)).toContain("[TSQL] Invalid query");
|
||||
expect(logged(errorSpy)).not.toContain("[TSQL] Query error");
|
||||
});
|
||||
|
||||
clickhouseTest(
|
||||
"logs a query ClickHouse rejects at execution as an error, with the TSQL that produced it",
|
||||
async ({ clickhouseContainer }) => {
|
||||
const client = new ClickhouseClient({
|
||||
name: "test",
|
||||
url: clickhouseContainer.getConnectionUrl(),
|
||||
});
|
||||
|
||||
const [error] = await executeTSQL(client, {
|
||||
name: "test-execution-error",
|
||||
query: "SELECT toDateTime(tags) AS bad FROM task_runs",
|
||||
schema: z.object({ bad: z.string() }),
|
||||
enforcedWhereClause: {
|
||||
organization_id: { op: "eq", value: "org_tenant1" },
|
||||
},
|
||||
tableSchema: [taskRunsSchema],
|
||||
});
|
||||
|
||||
expect(error).not.toBeNull();
|
||||
expect(logged(errorSpy)).toContain("Error querying clickhouse");
|
||||
expect(logged(errorSpy)).toContain("SELECT toDateTime(tags) AS bad FROM task_runs");
|
||||
}
|
||||
);
|
||||
|
||||
clickhouseTest(
|
||||
"keeps a compile failure on TRQL we generated at error level",
|
||||
async ({ clickhouseContainer }) => {
|
||||
const client = new ClickhouseClient({
|
||||
name: "test",
|
||||
url: clickhouseContainer.getConnectionUrl(),
|
||||
});
|
||||
|
||||
const [error] = await executeTSQL(client, {
|
||||
name: "test-internal-compile-error",
|
||||
query: "SELECT nope FROM task_runs",
|
||||
schema: z.object({ nope: z.string() }),
|
||||
enforcedWhereClause: {
|
||||
organization_id: { op: "eq", value: "org_tenant1" },
|
||||
},
|
||||
tableSchema: [taskRunsSchema],
|
||||
});
|
||||
|
||||
expect(error).not.toBeNull();
|
||||
expect(logged(errorSpy)).toContain("[TSQL] Query error");
|
||||
expect(logged(warnSpy)).not.toContain("[TSQL] Invalid query");
|
||||
}
|
||||
);
|
||||
|
||||
clickhouseTest(
|
||||
"logs invalid caller-written SQL as a warning",
|
||||
async ({ clickhouseContainer }) => {
|
||||
const client = new ClickhouseClient({
|
||||
name: "test",
|
||||
url: clickhouseContainer.getConnectionUrl(),
|
||||
});
|
||||
|
||||
const [error] = await executeTSQL(client, {
|
||||
name: "test-user-authored-invalid",
|
||||
query: "SELECT status, sum(is_test) AS n FROM task_runs",
|
||||
schema: z.object({ status: z.string(), n: z.number() }),
|
||||
enforcedWhereClause: {
|
||||
organization_id: { op: "eq", value: "org_tenant1" },
|
||||
},
|
||||
tableSchema: [taskRunsSchema],
|
||||
userAuthoredQuery: true,
|
||||
});
|
||||
|
||||
expect(error).not.toBeNull();
|
||||
expect(logged(warnSpy)).toContain("ClickHouse rejected an invalid query");
|
||||
expect(logged(errorSpy)).not.toContain("Error querying clickhouse");
|
||||
}
|
||||
);
|
||||
|
||||
clickhouseTest(
|
||||
"keeps invalid SQL we generated at error level",
|
||||
async ({ clickhouseContainer }) => {
|
||||
const client = new ClickhouseClient({
|
||||
name: "test",
|
||||
url: clickhouseContainer.getConnectionUrl(),
|
||||
});
|
||||
|
||||
const [error] = await executeTSQL(client, {
|
||||
name: "test-internal-invalid",
|
||||
query: "SELECT status, sum(is_test) AS n FROM task_runs",
|
||||
schema: z.object({ status: z.string(), n: z.number() }),
|
||||
enforcedWhereClause: {
|
||||
organization_id: { op: "eq", value: "org_tenant1" },
|
||||
},
|
||||
tableSchema: [taskRunsSchema],
|
||||
});
|
||||
|
||||
expect(error).not.toBeNull();
|
||||
expect(logged(errorSpy)).toContain("Error querying clickhouse");
|
||||
expect(logged(warnSpy)).not.toContain("ClickHouse rejected an invalid query");
|
||||
}
|
||||
);
|
||||
|
||||
clickhouseTest("logs a ClickHouse limit breach as a warning", async ({ clickhouseContainer }) => {
|
||||
const client = new ClickhouseClient({
|
||||
name: "test",
|
||||
url: clickhouseContainer.getConnectionUrl(),
|
||||
});
|
||||
|
||||
await insertTaskRuns(client, { async_insert: 0 })([
|
||||
createTaskRun({ run_id: "run_limit1" }),
|
||||
createTaskRun({ run_id: "run_limit2" }),
|
||||
createTaskRun({ run_id: "run_limit3" }),
|
||||
]);
|
||||
|
||||
const [error] = await executeTSQL(client, {
|
||||
name: "test-resource-limit",
|
||||
query: "SELECT run_id FROM task_runs",
|
||||
schema: z.object({ run_id: z.string() }),
|
||||
enforcedWhereClause: {
|
||||
organization_id: { op: "eq", value: "org_tenant1" },
|
||||
},
|
||||
tableSchema: [taskRunsSchema],
|
||||
userAuthoredQuery: true,
|
||||
clickhouseSettings: { max_rows_to_read: "1" },
|
||||
});
|
||||
|
||||
expect(error).not.toBeNull();
|
||||
expect(logged(warnSpy)).toContain("Query exceeded a ClickHouse limit");
|
||||
expect(logged(errorSpy)).not.toContain("Error querying clickhouse");
|
||||
});
|
||||
|
||||
clickhouseTest(
|
||||
"keeps a limit breach on a query we generated at error level",
|
||||
async ({ clickhouseContainer }) => {
|
||||
const client = new ClickhouseClient({
|
||||
name: "test",
|
||||
url: clickhouseContainer.getConnectionUrl(),
|
||||
});
|
||||
|
||||
await insertTaskRuns(client, { async_insert: 0 })([
|
||||
createTaskRun({ run_id: "run_intlimit1" }),
|
||||
createTaskRun({ run_id: "run_intlimit2" }),
|
||||
createTaskRun({ run_id: "run_intlimit3" }),
|
||||
]);
|
||||
|
||||
const [error] = await executeTSQL(client, {
|
||||
name: "test-internal-resource-limit",
|
||||
query: "SELECT run_id FROM task_runs",
|
||||
schema: z.object({ run_id: z.string() }),
|
||||
enforcedWhereClause: {
|
||||
organization_id: { op: "eq", value: "org_tenant1" },
|
||||
},
|
||||
tableSchema: [taskRunsSchema],
|
||||
clickhouseSettings: { max_rows_to_read: "1" },
|
||||
});
|
||||
|
||||
expect(error).not.toBeNull();
|
||||
expect(logged(errorSpy)).toContain("Error querying clickhouse");
|
||||
expect(logged(warnSpy)).not.toContain("Query exceeded a ClickHouse limit");
|
||||
}
|
||||
);
|
||||
});
|
||||
|
||||
Reference in New Issue
Block a user