Skip to content
Draft
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
6 changes: 6 additions & 0 deletions .server-changes/sentry-request-attribution.md
Original file line number Diff line number Diff line change
@@ -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.
6 changes: 6 additions & 0 deletions .server-changes/tsql-query-error-log-levels.md
Original file line number Diff line number Diff line change
@@ -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.
26 changes: 25 additions & 1 deletion apps/webapp/app/v3/tracer.server.ts
Original file line number Diff line number Diff line change
@@ -1,6 +1,7 @@
import {
type Attributes,
type Context,
context as otelContext,
createContextKey,
DiagConsoleLogger,
DiagLogLevel,
Expand All @@ -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";
Expand Down Expand Up @@ -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"),
Expand Down Expand Up @@ -300,7 +324,7 @@ function setupTelemetry() {
);
}

provider.register();
provider.register({ contextManager: createContextManager() });

let instrumentations: Instrumentation[] = [
new AwsSdkInstrumentation({
Expand Down
51 changes: 51 additions & 0 deletions apps/webapp/test/sentryRequestIsolation.test.ts
Original file line number Diff line number Diff line change
@@ -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" });
});
});
69 changes: 61 additions & 8 deletions internal-packages/clickhouse/src/client/client.ts
Original file line number Diff line number Diff line change
Expand Up @@ -171,13 +171,19 @@ 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,
});
};

if (isClickhouseQuotaError(clickhouseError)) {
this.logger.warn("Query exceeded a ClickHouse limit", errorLogFields);
} else {
this.logger.error("Error querying clickhouse", errorLogFields);
}

recordClickhouseError(span, clickhouseError);

Expand Down Expand Up @@ -260,6 +266,11 @@ 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>;
}): ClickhouseQueryWithStatsFunction<z.input<TIn>, z.output<TOut>> {
return async (params, options) => {
const queryId = randomUUID();
Expand Down Expand Up @@ -320,13 +331,20 @@ 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,
});
};
Comment thread
coderabbitai[bot] marked this conversation as resolved.

if (isClickhouseQuotaError(clickhouseError)) {
this.logger.warn("Query exceeded a ClickHouse limit", errorLogFields);
} else {
this.logger.error("Error querying clickhouse", errorLogFields);
}

recordClickhouseError(span, clickhouseError);

Expand Down Expand Up @@ -453,13 +471,19 @@ 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,
});
};

if (isClickhouseQuotaError(clickhouseError)) {
this.logger.warn("Query exceeded a ClickHouse limit", errorLogFields);
} else {
this.logger.error("Error querying clickhouse", errorLogFields);
}

recordClickhouseError(span, clickhouseError);

Expand Down Expand Up @@ -599,13 +623,19 @@ 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,
});
};

if (error instanceof Error && isClickhouseQuotaError(error)) {
self.logger.warn("Streamed query exceeded a ClickHouse limit", errorLogFields);
} else {
self.logger.error("Error streaming clickhouse", errorLogFields);
}

if (error instanceof Error) {
recordClickhouseError(span, error);
Expand Down Expand Up @@ -1001,6 +1031,29 @@ export class ClickhouseClient implements ClickhouseReader, ClickhouseWriter {
}
}

/**
* ClickHouse error types raised by a query that is valid but asks for more than
* the caller is allowed to spend. The caller gets a 4xx and there is nothing on
* our side to fix, so these are logged at warn rather than error.
*/
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",
"QUERY_WAS_CANCELLED",
]);

function isClickhouseQuotaError(error: Error): boolean {
return (
error instanceof ClickHouseError &&
error.type !== undefined &&
CLICKHOUSE_QUOTA_ERROR_TYPES.has(error.type)
);
Comment thread
coderabbitai[bot] marked this conversation as resolved.
}

function recordClickhouseError(span: Span, error: Error): void {
if (error instanceof ClickHouseError) {
span.setAttributes({
Expand Down
16 changes: 13 additions & 3 deletions internal-packages/clickhouse/src/client/tsql.ts
Original file line number Diff line number Diff line change
Expand Up @@ -8,6 +8,7 @@
import type { ClickHouseSettings } from "@clickhouse/client";
import {
compileTSQL,
ExposedTSQLError,
type OutputColumnMetadata,
sanitizeErrorMessage,
transformResults,
Expand Down Expand Up @@ -207,6 +208,7 @@ 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 },
Comment thread
coderabbitai[bot] marked this conversation as resolved.
});

const [error, result] = await queryFn(params);
Expand Down Expand Up @@ -240,6 +242,7 @@ 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 },
});

const [additionalError, additionalResult] = await additionalQueryFn(params);
Expand Down Expand Up @@ -297,14 +300,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 = 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);
Expand Down
5 changes: 5 additions & 0 deletions internal-packages/clickhouse/src/client/types.ts
Original file line number Diff line number Diff line change
Expand Up @@ -135,6 +135,11 @@ 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>;
}): ClickhouseQueryWithStatsFunction<z.input<TIn>, z.output<TOut>>;

queryFast<TOut extends Record<string, any>, TParams extends Record<string, any>>(req: {
Expand Down
Loading
Loading