Profiles not sent by express SDK

[rodolfoBee]

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

Framework Version

express v4.18.2

Link to Sentry event

No response

Reproduction Example/SDK Setup

instrument.js

const Sentry = require("@sentry/node");
const { nodeProfilingIntegration } = require("@sentry/profiling-node");

// Ensure to call this before requiring any other modules!
Sentry.init({
  debug:true,
  dsn: "....",
  integrations: [
    // Add our Profiling integration
    nodeProfilingIntegration(),
  ],
  // Add Tracing by setting tracesSampleRate
  // We recommend adjusting this value in production
  tracesSampleRate: 1.0,

  // Set sampling rate for profiling
  // This is relative to tracesSampleRate
  profilesSampleRate: 1.0,
});

app code:

require("./instrument");

// Now require other modules
const express = require("express");
const Sentry = require("@sentry/node");

const app = express()
const port = 8000
const http = require('http')

function bubble (arr){ //bubble sort for computation
  for (var i = 0; i < arr.length; i++) {
      for (var j = 0; j < (arr.length - i - 1); j++) {
          if (arr[j] > arr[j + 1]) {
              var temp = arr[j]
              arr[j] = arr[j + 1]
              arr[j + 1] = temp
          }
      }
  }
}

app.get("/", function rootHandler(req, res) {
  var arr = Array.from({length: 400000}, () => Math.floor(Math.random() * 4000));
  bubble(arr)
  res.end("hiii")
});

Sentry.setupExpressErrorHandler(app);
app.listen(port, () => console.log(`Example app listening at http://localhost:${port}`))

Steps to Reproduce

1. Run the app above
2. Go to localhost:8000

Expected Result

The SDK sends profiles and transactions to the Sentry project.

Actual Result

Transactions are sent but no profiles. Here is the SDK debug log attached. Noticeably are the lines:

Sentry Logger [log]: [Profiling] started profiling transaction: GET
Sentry Logger [log]: [Tracing] Inheriting parent's sampled decision for middleware - query: true
Sentry Logger [log]: [Tracing] Starting sampled span
....
Sentry Logger [log]: [Profiling] stopped profiling of transaction: GET /
Sentry Logger [log]: Flushing outcomes...
Sentry Logger [log]: No outcomes to send
Sentry Logger [log]: [Profiling] max profile duration elapsed, stopping profiling for: GET /
Sentry Logger [log]: [Profiling] stopped profiling of transaction: GET /
Sentry Logger [log]: [Profiling] profiler returned null profile for: GET / this may indicate an overlapping span or a call to stopProfiling with a profile title that was never started
Sentry Logger [log]: Flushing client reports based on interval.

These are the same log messages reported by the affected customer, which had profiles sent by the SDK normally prior to the update from v7.120.0 to v8.42.0

profilelogs.txt

[Lms24]

I believe @JonasBa mentioned recently that a root span needs to be active for a certain minimum amount of time (was it 20ms?) so that we can attach a profile. Any chance a too short root span is the problem?

[amardesai1]

Hi there. No most of our spans are 20-100ms

[rodolfoBee]

My root span is 907ms as well.
This used to report profiles correctly on v7.120.0

[Lms24]

I can reproduce this. Will spend some time today to figure out what's going on.
I created a GH repo with the code snippets from this issue for easier reproduction if more folks need to get involved: https://github.com/Lms24/node-express-profiling-not-sent

[Lms24]

Update: After some debugging, I think there are a couple of things that go wrong:

1. For some reason, the request handler span is finishing super early, way before the sorting call ends. This is weird but given it's only a child span, I'm not sure if it should influence profiling at all.
2. We put the profileId onto the profiling context on the current scope on span start of the root span. For some reason this context isn't applied to the event. If I locally add it to the isolation scope instead, things work. So we could just generally put the profiling id onto the isolation scope. WDYT @@JonasBa?
3. Even when the profile is sent correctly, I still get the debug log that the max profile duration elapsed. Not sure if this is by design but it seems wrong to me. Maybe we're not cleaning up a timeout correctly?

[JonasBa]

@Lms24

1. We listen for span end calls and stop the profile, so if it ends super early, the profile might end too soon
2. This used to work, has something changed? The reason this lives in the global scope is that in case of continuous profiling, we want all events that are created during a profiler session to inherit the profiling context. If this would still work, then that is ok. I suspect that if we dont use the global scope, we will need to change the this to assign context on each spanStart, which isn't ideal as I suspect it might be quite a hot path here.
3. This would hint towards us not properly catching a spanEnd here and failing to clear the timeout

[Lms24]

1. We listen for span end calls and stop the profile, so if it ends super early, the profile might end too soon

The duration is not the issue here. The txn lasts for over 2s in my repro and still the profile was not attached.
What I found in 1 is apparently an Otel instrumentation bug and is unrelated to profliling. This was already raised in the Otel repo and one of our contractors is gonna take a look at this.

2. This used to work, has something changed?

Not within v8 but between v7 and v8, with the entire hub/scope refactoring a lot changed. I'm not entirely sure tbh why the current scope at root span start is not applied to the event but with OTEL forking scopes on every span start, I suspect this can happen somehow. This could have also happened with a recent otel instrumentation update. The root span has the expected duration though so I'm not sure.

I suspect that if we dont use the global scope, we will need to change the this to assign context on each spanStart, which isn't ideal as I suspect it might be quite a hot path here.

I think for span-based profiling, it's fine to switch from the current to the isolation scope to set the profiling id as proposed in #14681.
For continuous profiling, the global scope makes sense intuitively. I'd suggest we leave it there as is for now?

3. This would hint towards us not properly catching a spanEnd here and failing to clear the timeout

Yup, out of the three things I noticed, this is the one I haven't looked at in too much detail.

[Lms24]

@amardesai1 @rodolfoBee I merged the PR that should restore profiles being sent. It will be released in the next days with the next SDK release. The "max profile duration elapsed" message might still appear but I think it shouldn't influence profile collection.

[amardesai1]

@Lms24 Thanks, could you please notify us when it's available? Then I can deploy it and see if we start seeing that profiling data.
Thanks!

[Lms24]

@amardesai1 You can subscribe to this PR which will trigger our release flow once it is merged: #14682

Also, you should receive an automatic reply on this issue once the release is published.

(I'm notoriously bad at informing folks about releases, sorry in advance if I'm not gonna notify you anymore)

[github-actions]

A PR closing this issue has just been released 🚀

This issue was referenced by PR #14681, which was included in the 8.45.0 release.

[amardesai1]

@Lms24 Are the @sentry/profiling-node and @sentry/node packages available for update now?

[Lms24]

Yes :)

[amardesai1]

Hi @Lms24 I ran nom update on these two packages and there was no update available.

Thanks for your help

[Lms24]

If you run npm install @sentry/node @sentry/profiling-node you should get updates. Both packages have 8.45.0 as the latest version:

• https://www.npmjs.com/package/@sentry/profiling-node
• https://www.npmjs.com/package/@sentry/node

[amardesai1]

@Lms24 Thanks! Resolved