startSpan experience weird behavior with events

[zhiyan114]

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.32.0

Framework Version

No response

Link to Sentry event

No response

Reproduction Example/SDK Setup

Assume two different file and index.js will always be the first to load AND
require("./main.js"); will be inserted somewhere in index.js for the main to run.

index.js:

// index.ts

//require("./main.js"); // sentry will capture span correctly, but it breaks OpenTelemetry Hook for redisIntegration
import { init as SentryInit, prismaIntegration, extraErrorDataIntegration, rewriteFramesIntegration,  redisIntegration } from "@sentry/node";
SentryInit({
  dsn: "DSN",
  debug: true,
  integrations: [
      extraErrorDataIntegration({
        depth: 3
      }),
      rewriteFramesIntegration({
        iteratee(frame) {
          const absPath = frame.filename;
          if(!absPath) return frame;
          frame.filename = `/${path.relative(__dirname, absPath).replace(/\\/g, "/")}`
          return frame;
        }
      }),
      prismaIntegration(),
      redisIntegration({cachePrefixes: ["tester:"]}),
    ],
    tracesSampleRate: 1.0,
        
    ignoreErrors: [
      "ETIMEDOUT",
      "EADDRINUSE",
      "ENOTFOUND",
      "TimeoutError",
      "AbortError",
      "NetworkError",
      "ECONNREFUSED",
      "ECONNRESET",
    ]
});

//require("./main.js"); // startSpan requires `setParent: null` to avoid timing out, but will properly run the hooked version of ioredis

main.js:

import { Client, GatewayIntentBits, Partials } from "discord.js";
import {  startSpan, withScope } from "@sentry/node";
const cli = new Client({
    intents: [
        GatewayIntentBits.Guilds,
        GatewayIntentBits.GuildMembers,
        GatewayIntentBits.MessageContent,
        GatewayIntentBits.GuildMessages,
      ],
      partials: [
        Partials.Channel,
        Partials.GuildMember,
        Partials.User,
      ]
})

cli.on("messageCreate", async (message)=>{
    if(message.author.bot) return;
    await withScope(async (scope)=>{
      scope.setTag("user", message.author.id);
      await startSpan({
        name: "ChatHandler",
        op: "processMessage",
      }, async () => {
        
        const content = message.content;
        if(content === "!ping")
          return await message.reply("Pong!");
        await message.reply("Fail!")
      });
    });
});

cli.login("BOT TOKEN").then(()=>console.log("SERVER OPERATED!"));

Steps to Reproduce

Make sentry init run first (as intended) before other code (aka require("./main.js"); will be set at the bottom of the index.js)

Expected Result

All the tracing should process through properly when sentry is initialized first.

Actual Result

1. Span will eventually hit the 5 minutes timeout and be dropped unless spanParent: null is set inside startSpan (only required if the span is the parent of the rootSpan or "trace span").

2. startSpan will also reuse trace ID for the duration of the software's lifetime, requiring me to use the following workaround to ensure each event callback is assigned a unique rootSpan ID:

scope.setPropagationContext({
    traceId: randomBytes(16).toString("hex"),
    spanId: randomBytes(16).toString("hex"),
});

[lforst]

Hi, thanks for writing in! I don't yet fully understand in what way the SDK has seemingly weird behaviour. Would you mind giving a bit of context, of what you are trying to achieve and what you want your traces to look like?

[zhiyan114]

Hi, unfortunately I can't find much information on how exactly startSpan behaves so I'm just going off of what I found when testing SDK and reading the available docs.

So currently, I want to trace events that are wrapped with withScope under EventEmitter.
Example Code:

SomeClass.on('someEvent', async(data) => {
await withScope(async (scope)=>{
      scope.setTag("user", data.user.id);
      await startSpan({
        name: "ChatHandler",
        op: "processMessage",
      }, async () => {
        if(content === "!ping")
          return await data.reply("Pong!");
        await data.reply("Fail!")
      });
    });
});

I'm expecting the SDK to automatically treat each trace uniquely under the EventEmitter's callback function (which I may be wrong if that's not the intended behavior for spanStart). Instead, the trace "session" are being shared each time when the events are invoked.

To better explain:
For the image above, each processMessage is suppose to get its own traceId since they're a separate function callback. But instead, when the event are being invoked, a new traceId are not regenerated.
Because of that persistent behavior, each "Top Span" needed to have parentSpan: null, otherwise I'll just get stuck with the traceId that its attached to and eventually hit the timeout limit.

Spans that are not under the event callback functions (i.e. Prisma call inside a startup function), will be traced as normal.

[lforst]

All of this is intended behaviour and more or less matches what opentelemetry does for their tracing. I recommend you update your event handler to the following:

SomeClass.on('someEvent', data => {
  return Sentry.withIsolationScope(() => {
    return Sentry.withActiveSpan(null, async () => {
      Sentry.setTag('user', data.user.id);
      await Sentry.startSpan(
        {
          name: 'ChatHandler',
          op: 'processMessage',
        },
        async () => {
          if (content === '!ping') return await data.reply('Pong!');
          await data.reply('Fail!');
        },
      );
    });
  });
});

You probably read this already, but if not, I recommend this docs page: https://docs.sentry.io/platforms/javascript/tracing/instrumentation/custom-instrumentation/ It explains all the primitives.

[zhiyan114]

Thanks for the solution! Unfortunately, that did not solve the issue which all spans will be sharing the same traceId.

Am I suppose to use setPropagationContext to manually generate new traceId when the event invokes?

[lforst]

Ah sorry, I had a brainfart. Instead of doing withActiveSpan(null, ...) you need to do startNewTrace(() => ...)

[zhiyan114]

This solves the issue, thanks again!

[zhiyan114]

@lforst Hi, so after running the software for a while, I did notice another behaivor. From the doc startSpan({onlyIfParent: true}); should only create a span listing IF the code is executed under startSpan (i.e. has a parent). But from the current entries spans I find in the dashboard, that flag seems to be ignored?

Is it possible that startNewTrace itself behaves like parent span?