Skip to content

supabaseIntegration double-ends every PostgREST span (span.end() inside a trace.startSpan callback that also auto-ends) #24116

Description

@crblab

Is there an existing issue for this?

I searched and found no open issue covering this. The closest are #12260 (Hapi span warnings) and #12697 (Error on span using sentry-opentelemetry), both closed and neither specific to supabaseIntegration.

How do you use Sentry?

Sentry Saas (sentry.io)

Which SDK are you using?

@sentry/nestjs

SDK Version

10.68.0 (also verified present in 10.73.0)

Framework Version

NestJS 11

Link to Sentry event

No response

Reproduction Example/SDK Setup

Sentry.init({
  dsn,
  integrations: [Sentry.supabaseIntegration({ supabaseClient: SupabaseClient })],
});

// Install any diag logger so OTel's internal warnings are visible.
// This is the only reason the bug is observable at all — see below.
import { diag, DiagConsoleLogger, DiagLogLevel } from '@opentelemetry/api';
diag.setLogger(new DiagConsoleLogger(), DiagLogLevel.WARN);

// Then make any PostgREST call:
await supabase.from('some_table').select('*');

Steps to Reproduce

  1. Initialise @sentry/nestjs with supabaseIntegration.
  2. Install any OpenTelemetry diag logger (diag.setLogger(...)). Without this the bug is completely silent, because OTel's default diag logger is a no-op.
  3. Make any Supabase PostgREST call.

Expected Result

The span is ended once.

Actual Result

Every instrumented Supabase call ends its span twice, and OTel emits two diagnostic records per call.

@sentry/core's integrations/supabase.js calls span.end() inside a trace.startSpan callback:

return trace.startSpan(
  { name: description, attributes },
  (span) => {
    return Reflect.apply(target, thisArg, []).then(
      (res) => { /* ... */ span.end(); /* ... */ return res },   // end #1
      (err) => { /* ... */ span.end(); throw err },
    ).then(...argumentsList);
  }
);

But startSpan(options, callback) is _startSpan(options, callback, autoEnd = true) in @sentry/opentelemetry, which runs:

core.handleCallbackErrors(
  () => callback(span),
  setErrorStatus,
  autoEnd ? () => span.end() : undefined,   // end #2
);

handleCallbackErrors invokes that third argument when the callback's returned thenable settles. The callback has already ended the span, so end #2 always follows end #1.

OTel's SpanImpl then emits two records per call:

warn : Cannot execute the operation on ended Span {traceId: …, spanId: …}   (+ 6-frame stack)
error: <name> <traceId>-<spanId> - You can only call end() on a span once.

(@opentelemetry/sdk-trace Span.js_isSpanEnded() emits the warn, end() emits the error.)

Observed frames, which line the two ends up exactly:

at SpanImpl._isSpanEnded   @opentelemetry/sdk-trace/src/Span.ts:475
at SpanImpl.end            @opentelemetry/sdk-trace/src/Span.ts:356
at SpanImpl.span.end       @sentry/opentelemetry/src/trace.ts:227   <- patchSpanEnd wrapper
at <anonymous>             @sentry/opentelemetry/src/trace.ts:102   <- _startSpan's autoEnd
at <anonymous>             @sentry/core/src/utils/handleCallbackErrors.ts:83
at <anonymous>             @sentry/core/src/utils/chain-and-copy-promiselike.ts:20

Affected call sites in 10.73.0 (build/cjs/integrations/supabase.js): span.end() at lines 176, 180 (instrumentAuthOperation) and 300, 350 (instrumentPostgRESTFilterBuilder) — all inside trace.startSpan callbacks that also auto-end.

Impact

Tracing itself is unaffected: the second end() returns early, so duration and export come from the first. The cost is log volume, and it is not small. On two of our NestJS services this was 73–75% of all log output and ~100% of the error channel — about 10,700 records per hour per pod, ~13 MiB/hour/pod. Error-rate alerting on those services was meaningless until we filtered it.

It is invisible for most users only because OTel's default diag logger is a no-op. Anyone who installs a diag logger to debug OTLP export gets this instead.

Suggested fix

Either drop the inner span.end() calls and let startSpan's autoEnd do it, or switch these call sites to startSpanManual so the manual end() is the only one.

Workaround, for anyone finding this via search

Wrap the diag logger and drop the two anchored signatures (prefix for the warn, suffix for the error), rather than raising the level to ERROR — DiagLogLevel.ERROR also silences Dropped N spans because maxQueueSize reached and Received Partial Success response, which are the only signals for silent span loss.

Activity

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions