SDK 8.x SpanExporter bug

[rahul-kumar-saini]

Is there an existing issue for this?

• I have checked for existing issues https://github.com/getsentry/sentry-javascript/issues
• I have reviewed the documentation https://docs.sentry.io/
• I am using the latest SDK release https://github.com/getsentry/sentry-javascript/releases

How do you use Sentry?

Sentry Saas (sentry.io)

Which SDK are you using?

@sentry/node

SDK Version

8.9.2

Framework Version

Node v18

Link to Sentry event

https://testorgrahul-ah.sentry.io/performance/summary/events/?project=4507431605108736&query=&statsPeriod=24h&transaction=sentry-sdk-8

SDK Setup

Sentry.init({
  debug: true,
  dsn: MY_DSN,
  tracesSampleRate: 1.0,
});

Steps to Reproduce

So ever since I upgraded to SDK 8.x, I've noticed any transaction I have that takes more than 5 minutes to run omits a ton of spans in the beginning of the transaction. I don't know why 5 minutes, but that seems to be the point where any transaction longer starts omitting initial spans entirely.

This was not an issue at all with SDK 7.x

Just in case I was going crazy and maybe something was wrong with our application itself, I created a script to try and reproduce this minimally. My executions of this script are available to view in the "Link to Sentry Event" above.

All this does is run for the number of minutes specified, and creates 1 span every 10 seconds within the transaction.

npx ts-node --transpile-only sentry-test-script.ts <number_of_minutes_to_run_the_script>

import * as Sentry from '@sentry/node';

const MY_DSN = '';

Sentry.init({
  debug: true,
  dsn: MY_DSN,
  tracesSampleRate: 1.0,
});

async function someLongFunction(step: number) {
  await Sentry.startSpan({ name: `step-${step}`, op: 'function' }, async () => {
    console.log(`Step ${step} started.`);
    await new Promise((resolve) => setTimeout(resolve, 10000));
  });
}

async function runScript() {
  await Sentry.startSpan({ name: 'sentry-sdk-8', op: 'script' }, async () => {
    const minutes = parseInt(process.argv[2]);
    console.log(`Running for ${minutes} minute(s).`);
    for (let i = 1; i <= minutes * 6; i++) {
      await someLongFunction(i);
    }
    console.log('All steps completed.');
  });
  await Sentry.close(5000);
}

void runScript();

Expected Result

I expect to see all spans within the # of spans limit for a single transaction. A transaction taking more than 5 minutes but having total number of spans within the span limit of a transactions should show all spans in the transaction.

Actual Result

✅ Any transactions taking <= 5 minutes to run include all spans
❌ Any transactions taking ~5 minutes to run omit the first few spans
❌ Any transactions taking > 5 minutes to run omit an increasing number of spans in the beginning of the transaction

It seems only the latest ~28 top level spans (within the transaction) are reported

Example script execution of 10 minutes omitting initial spans:

Some important debug console output for a 20 minute execution

...
Step 120 started.
Sentry Logger [log]: [Tracing] Finishing "function" span "step-120" with ID 506560f6d827b11b
Sentry Logger [log]: SpanExporter has 30 unsent spans remaining
Sentry Logger [log]: SpanExporter dropping span step-91 (97b089b25ebc5747) because it is pending for more than 5 minutes.
All steps completed.
Sentry Logger [log]: [Tracing] Finishing "script" root span "sentry-sdk-8" with ID f12a71d80086229b
Sentry Logger [log]: SpanExporter exported 30 spans, 0 unsent spans remaining

SpanExporter dropping span step-91 (97b089b25ebc5747) because it is pending for more than 5 minutes.

It's pending because the transaction hasn't finished yet!

Sentry Logger [log]: SpanExporter exported 30 spans, 0 unsent spans remaining

Only exporting the last 30 spans at the end of the transaction 😭

[rahul-kumar-saini]

Alright seems like this exact issue is getting fixed here: #12492

However, I think this needs some high priority communication in migration docs - Anyone upgrading from 7.x to 8.x and has transactions >5 mins will see their transactions have less data now, and will likely revert back to 7.x.

[rahul-kumar-saini]

Also oops, duplicates #12491

[mydea]

However, I think this needs some high priority communication in migration docs - Anyone upgrading from 7.x to 8.x and has transactions >5 mins will see their transactions have less data now, and will likely revert back to 7.x.

I think this is a valid point! We'll discuss this in the team, also possibly extending the default (at least to some extend).

[mydea]

Update, we investigated this some more, and identified a way how we can "really" fix this, without config: #12510

[andreiborza]

Why was this issue closed?

A fix has been implemented in #12610 allowing users to configure the wait duration for spans.

Please feel free to leave a comment if you think this issue should be reopened.