Declaring any preHandler hook breaks @opentelemetry/instrumentation-fastify

[NicholasGWK]

What version of OpenTelemetry are you using?

  "dependencies": {
    "@opentelemetry/api": "^1.9.0",
    "@opentelemetry/auto-instrumentations-node": "^0.48.0",
    "@opentelemetry/sdk-node": "^0.52.1",
    "fastify": "^4.28.1"
  }

What version of Node are you using?

Node 18.17.1

What did you do?

Debugging a full project, I wasn't able to add attributes to span inside a fastify request handler, because the span returned from trace.getActiveSpan() was already ended.

What did you expect to see?

Adding any number of hooks should be okay; when one calls trace.getActiveSpan() in a request handler, the span should not be ended yet to allow for adding attributes.

What did you see instead?

If ANY preHandler to fastify (even a no-op), calling trace.getActiveSpan() in a request handler will return an already ended span, preventing you from adding attributes.

It seems that for some reason, add other preHandler hook to fastify will cause the spans that should be auto-instrumented to end prematurely, before the handler actually runs.

I'm not totally sure why, but I'm guessing it has something to do with the fact the instrumentation seems to expect the handler to always run after the auto-instrumentation's own preHandler hook...I'm thinking declaring another hook adds a follow up to the first, which ends the span once it completes, instead of actually wrapping the handler.

It also wraps addHook, which might be trying to prevent this behaviour, but it doesn't seem to work.

opentelemetry-js-contrib/plugins/node/opentelemetry-instrumentation-fastify/src/instrumentation.ts

Line 193 in 6e8989d

app.addHook('preHandler', instrumentation._hookPreHandler());

Additional context

Sorry for the wall, but here's a small reproducible example using the Node SDK + Basic fastify setup:

"use strict";
const process = require("process");
const opentelemetry = require("@opentelemetry/sdk-node");
const {
  getNodeAutoInstrumentations,
} = require("@opentelemetry/auto-instrumentations-node");
const { ConsoleSpanExporter } = require("@opentelemetry/sdk-trace-base");
const { Resource } = require("@opentelemetry/resources");
const {
  SEMRESATTRS_SERVICE_NAME,
} = require("@opentelemetry/semantic-conventions");

const {
  trace,
  diag,
  DiagConsoleLogger,
  DiagLogLevel,
} = require("@opentelemetry/api");
diag.setLogger(new DiagConsoleLogger(), DiagLogLevel.DEBUG);

// configure the SDK to export telemetry data to the console
// enable all auto-instrumentations from the meta package
const traceExporter = new ConsoleSpanExporter();
const sdk = new opentelemetry.NodeSDK({
  resource: new Resource({
    [SEMRESATTRS_SERVICE_NAME]: "my-service",
  }),
  traceExporter,
  instrumentations: [getNodeAutoInstrumentations()],
});

// initialize the SDK and register with the OpenTelemetry API
// this enables the API to record telemetry
sdk.start();

// gracefully shut down the SDK on process exit
process.on("SIGTERM", () => {
  sdk
    .shutdown()
    .then(() => console.log("Tracing terminated"))
    .catch((error) => console.log("Error terminating tracing", error))
    .finally(() => process.exit(0));
});

// Server + Route
const Fastify = require("fastify");
const fastify = Fastify({
  logger: true,
});

fastify.addHook("preHandler", async () => {});

// Declare a route
fastify.get("/", async (request, reply) => {
  const span = trace.getActiveSpan();
  console.log("This span will already be ended :(", span);
  span?.setAttribute("attribute", "value");
  return reply.status(200).send("hello world");
});

// Run the server!
try {
  fastify.listen({ port: 3000 });
} catch (err) {
  fastify.log.error(err);
  process.exit(1);
}