Fastify is not instrumented in combination with node profiling and tracesSampleRate

[Xhale1]

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

Framework Version

nodejs 20.17.0

Link to Sentry event

No response

Reproduction Example/SDK Setup

I made a repo here to demo the issue: https://github.com/Xhale1/sentry-repro

Steps to Reproduce

1. Clone the repo above
2. Add your own sentry dsn
3. Run the dev script
4. Observe that the error only occurs when both integrations: [nodeProfilingIntegration()] and tracesSampleRate: 1 are set. Removing one or the other seems to make the error go away.

Expected Result

Fastify is instrumented properly.

Actual Result

Sentry prints the following to the console:

[Sentry] fastify is not instrumented. This is likely because you required/imported fastify before calling `Sentry.init()`.

[andreiborza]

Hi @Xhale1, thanks for filing this.

I can confirm this is indeed not working, thank you for the reproduction. We're going to look into this.

One thing to note: The reason you're not seeing the issue when tracesSampleRate is not defined is because we only show this warning when tracing is enabled, but it doesn't mean the app was successfully instrumented.

So definitely some issue with using nodeProfilingIntegration.

cc @JonasBa

[andreiborza]

As a workaround, you can leave out the integration inside instrument.ts and set it up inside index.ts

import * as Sentry from "@sentry/node";
import { nodeProfilingIntegration } from "@sentry/profiling-node";
import Fastify from "fastify";

const fastify = Fastify();

Sentry.setupFastifyErrorHandler(fastify);
Sentry.addIntegration(nodeProfilingIntegration())

[JonasBa]

@andreiborza @Xhale1 are you seeing any profiling SDK logs if you set debug: true to the SDK init?

[Xhale1]

@JonasBa
With node profiling (reports as not-instrumented)

Sentry Logger [log]: Initializing Sentry: process: 65271, thread: main.
Sentry Logger [log]: Integration installed: InboundFilters
Sentry Logger [log]: Integration installed: FunctionToString
Sentry Logger [log]: Integration installed: LinkedErrors
Sentry Logger [log]: Integration installed: RequestData
Sentry Logger [log]: Integration installed: Console
Sentry Logger [log]: Integration installed: Http
Sentry Logger [log]: Integration installed: NodeFetch
Sentry Logger [log]: Integration installed: OnUncaughtException
Sentry Logger [log]: Integration installed: OnUnhandledRejection
Sentry Logger [log]: Integration installed: ContextLines
Sentry Logger [log]: Integration installed: LocalVariablesAsync
Sentry Logger [log]: Integration installed: Context
Sentry Logger [log]: Integration installed: Modules
Sentry Logger [log]: Integration installed: Express
Sentry Logger [log]: Integration installed: Fastify
Sentry Logger [log]: Integration installed: Graphql
Sentry Logger [log]: Integration installed: Mongo
Sentry Logger [log]: Integration installed: Mongoose
Sentry Logger [log]: Integration installed: Mysql
Sentry Logger [log]: Integration installed: Mysql2
Sentry Logger [log]: Integration installed: Redis
Sentry Logger [log]: Integration installed: Postgres
Sentry Logger [log]: Integration installed: Nest
Sentry Logger [log]: Integration installed: Hapi
Sentry Logger [log]: Integration installed: Koa
Sentry Logger [log]: Integration installed: Connect
Sentry Logger [log]: Integration installed: GenericPool
Sentry Logger [log]: Integration installed: Kafka
Sentry Logger [log]: [Profiling] Profiling integration setup.
Sentry Logger [log]: [Profiling] Continuous profiler mode enabled.
Sentry Logger [log]: Integration installed: ProfilingIntegration
Sentry Logger [log]: Running in CommonJS mode.
Sentry Logger [debug]: @opentelemetry/api: Registered a global for diag v1.9.0.
Sentry Logger [debug]: @opentelemetry/api: Registered a global for trace v1.9.0.
Sentry Logger [debug]: @opentelemetry/api: Registered a global for context v1.9.0.
Sentry Logger [debug]: @opentelemetry/api: Registered a global for propagation v1.9.0.
Sentry Logger [debug]: @opentelemetry/instrumentation-http Applying instrumentation patch for nodejs core module on require hook { module: 'http' }
Sentry Logger [debug]: @opentelemetry/instrumentation-http Applying instrumentation patch for nodejs core module on require hook { module: 'https' }
[Sentry] fastify is not instrumented. This is likely because you required/imported fastify before calling `Sentry.init()`.
Server listening at http://0.0.0.0:3000

Without node profiling (reports as instrumented as far as I'm aware

Sentry Logger [log]: Initializing Sentry: process: 65327, thread: main.
Sentry Logger [log]: Integration installed: InboundFilters
Sentry Logger [log]: Integration installed: FunctionToString
Sentry Logger [log]: Integration installed: LinkedErrors
Sentry Logger [log]: Integration installed: RequestData
Sentry Logger [log]: Integration installed: Console
Sentry Logger [log]: Integration installed: Http
Sentry Logger [log]: Integration installed: NodeFetch
Sentry Logger [log]: Integration installed: OnUncaughtException
Sentry Logger [log]: Integration installed: OnUnhandledRejection
Sentry Logger [log]: Integration installed: ContextLines
Sentry Logger [log]: Integration installed: LocalVariablesAsync
Sentry Logger [log]: Integration installed: Context
Sentry Logger [log]: Integration installed: Express
Sentry Logger [log]: Integration installed: Fastify
Sentry Logger [log]: Integration installed: Graphql
Sentry Logger [log]: Integration installed: Mongo
Sentry Logger [log]: Integration installed: Mongoose
Sentry Logger [log]: Integration installed: Mysql
Sentry Logger [log]: Integration installed: Mysql2
Sentry Logger [log]: Integration installed: Redis
Sentry Logger [log]: Integration installed: Postgres
Sentry Logger [log]: Integration installed: Nest
Sentry Logger [log]: Integration installed: Hapi
Sentry Logger [log]: Integration installed: Koa
Sentry Logger [log]: Integration installed: Connect
Sentry Logger [log]: Integration installed: GenericPool
Sentry Logger [log]: Integration installed: Kafka
Sentry Logger [log]: Running in ESM mode.
Sentry Logger [debug]: @opentelemetry/api: Registered a global for diag v1.9.0.
Sentry Logger [debug]: @opentelemetry/api: Registered a global for trace v1.9.0.
Sentry Logger [debug]: @opentelemetry/api: Registered a global for context v1.9.0.
Sentry Logger [debug]: @opentelemetry/api: Registered a global for propagation v1.9.0.
Sentry Logger [debug]: @opentelemetry/instrumentation-http Applying instrumentation patch for nodejs core module on require hook { module: 'http' }
Sentry Logger [debug]: @opentelemetry/instrumentation-http Applying instrumentation patch for nodejs core module on require hook { module: 'https' }
Sentry Logger [debug]: @opentelemetry/instrumentation-fastify Applying instrumentation patch for module on require hook {
  module: 'fastify',
  version: '4.28.1',
  baseDir: '/Users/[...]/Code/sentry-openai/node_modules/.pnpm/fastify@4.28.1/node_modules/fastify'
}
Sentry Logger [debug]: @opentelemetry/instrumentation-fastify Patching fastify preHandler function
Sentry Logger [debug]: @opentelemetry/instrumentation-fastify Patching fastify server.addHook function
Sentry Logger [debug]: @opentelemetry/instrumentation-fastify Patching fastify route.handler function
Sentry Logger [debug]: @opentelemetry/instrumentation-fastify Patching fastify route.handler function
Server listening at http://0.0.0.0:3000

It seems that node profiling might force the sdk to run in commonjs mode instead of esm?

[JonasBa]

@Xhale1 are you setting profilesSampleRate as well, or is that not defined? I can see the SDK enables continuous profiling mode, which should only be enabled if profilesSampleRate and profilesSampler are not set

[Xhale1]

I was not, but I tried adding profilesSampleRate: 1 to my sdk init and it seems that did not resolve the issue.

Also, I edited my previous reply with additional logs for with-error and without-error

[JonasBa]

Let me look at the repo. If you setProfilesSampleRate, then the continuous profiling log should not appear, if it does, then that is an SDK bug. I'm going to investigate

[JonasBa]

Ok, so if I set profilesSampleRate to > 0 and curl the endpoint (curl localhost:3000), I can see that the profiler is started and stopped.

// instrument.ts
Sentry.init({
  dsn: "",
  debug: true,
  integrations: [nodeProfilingIntegration()],
  tracesSampleRate: 1,
  profilesSampleRate: 1,
});

Server logs

Server listening at http://0.0.0.0:3000
Sentry Logger [log]: Flushing client reports based on interval.
Sentry Logger [log]: Flushing outcomes...
Sentry Logger [log]: No outcomes to send
Sentry Logger [debug]: @opentelemetry/instrumentation-http http instrumentat
ion incomingRequest
Sentry Logger [log]: [Tracing] Starting sampled root span
  op: < unknown op >
  name: GET
  ID: aacdcc98567c0451
Sentry Logger [log]: [Profiling] started profiling transaction: GET
(node:78766) [FSTDEP017] DeprecationWarning: You are accessing the deprecate
d "request.routerPath" property. Use "request.routeOptions.url" instead. Pro
perty "req.routerPath" will be removed in `fastify@5`.
(Use `node --trace-deprecation ...` to show where the warning was created)
Sentry Logger [log]: [Tracing] Finishing "< unknown op >" root span "GET" wi
th ID aacdcc98567c0451
Sentry Logger [log]: [Profiling] stopped profiling of transaction: GET
Sentry Logger [log]: SpanExporter exported 1 spans, 0 unsent spans remaining
Sentry Logger [log]: [Profiling] max profile duration elapsed, stopping prof
iling for: GET
Sentry Logger [log]: [Profiling] stopped profiling of transaction: GET
Sentry Logger [log]: [Profiling] profiler returned null profile for: GET thi
s 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.
Sentry Logger [log]: Flushing outcomes...

Did you try sending a request to the server to see if the profiler is started and stopped?

What is happening here in my setup is that the profile is being filtered out by the client (null return log) and not sent to the server, as we require a minimum of 2 samples at ~100hz sampling rate (aka the handler should take 20ms+)

[Xhale1]

I have not tried to verify if profiling or tracing are working as expected or not

Are you saying that the [Sentry] fastify is not instrumented... log is misleading in this case and that the server is being properly instrumented as expected?

[andreiborza]

Hm, I don't think it is properly instrumented if you don't see @opentelemetry/instrumentation-fastify Applying instrumentation patch for module on require hook this line.

[JonasBa]

@Xhale1 That seems to be the case yes. I dont know exactly what the check relies on, maybe its, because there are no routes defined in the file?

[Xhale1]

I should clarify, I have not confirmed myself whether the warning message is accurate or not.

@JonasBa I experienced this warning message in our internal codebase at trainwell which has a number of routes defined so I don't think that's the case. I did not define routes in my repo to keep things as minimal as possible.

As far as I'm aware my repo follows the Sentry docs for getting started with Fastify closely with the biggest difference being the use of tsup. Are you able to comment on whether my repo seems to be setup appropriately according to the docs?

[JonasBa]

Hey everyone, I've made a change to scope require creation to the binding import here so that we dont end up tripping cjs detection.

[Xhale1]

@JonasBa

Hey everyone, I've made a change to scope require creation to the binding import #13834 so that we dont end up tripping cjs detection.

Thank you! That's a welcomed fix, should hopefully clear up some confusion.

Is this because of this issue, or is there some other problem that this is causing?

Truthfully we're not moving forward with sentry node profiling due to a lack of confidence in it. Seeing warnings being reported after setting up a minimal repo that (I think?) follows the getting started documentation makes me worried about how thoroughly it's been tested.

To be clear, I appreciate yours and your team's dedication, effort, and time towards sentry v8 and helping to triage issues in the open!

[JonasBa]

@JonasBa

Hey everyone, I've made a change to scope require creation to the binding import #13834 so that we dont end up tripping cjs detection.

Thank you! That's a welcomed fix, should hopefully clear up some confusion.

Is this because of this issue, or is there some other problem that this is causing?

Truthfully we're not moving forward with sentry node profiling due to a lack of confidence in it. Seeing warnings being reported after setting up a minimal repo that (I think?) follows the getting started documentation makes me worried about how thoroughly it's been tested.

To be clear, I appreciate yours and your team's dedication, effort, and time towards sentry v8 and helping to triage issues in the open!

Sounds good, I appreciate the honesty :) Unfortunately, I simply just wasn't aware of the CJS check in our node package (it makes no difference for profiling), we only test that the package runs fine in both environments.

[Xhale1]

Sounds good, I appreciate the honesty :) Unfortunately, I simply just wasn't aware of the CJS check in our node package (it makes no difference for profiling), we only test that the package runs fine in both environments.

Do you happen to know if the improved CJS check logic will fix the [Sentry] fastify is not instrumented. This is likely because you required/imported fastify before calling message being reported when node profiling is included?

My apologies if that was already addressed, it's totally possible I missed it.

[JonasBa]

@Xhale1 Yes, it will. Right now what is happening is that your code still runs in ESM, however since profiling creates a require function and stores it under global scope, that check ends up returning true and generating a false positive message.

I tested on a local fastify server, and even though Sentry was saying my code is not instrumented, after I fired a few requests, I could see the data was coming into Sentry, confirming that it was a false positive

[getsantry]

This issue has gone three weeks without activity. In another week, I will close it.

But! If you comment or otherwise update it, I will reset the clock, and if you remove the label Waiting for: Community, I will leave it alone ... forever!

---

"A weed is but an unloved flower." ― Ella Wheeler Wilcox 🥀

[netgfx]

What is the verdict on this? Is it fixed on some version and up? Is there a workaround? Do we just ignore the warning?

[andreiborza]

@netgfx for now still just ignore the warning, but be sure to double check that you see your expected data in Sentry. If you are missing fastify spans please file a new issue.

cc @JonasBa