[restify] Span ending prematurely with non-promise async handlers

[andogq]

What version of OpenTelemetry are you using?

@opentelemetry/[email protected]

What version of Node are you using?

v16 - v21

What did you do?

Given the following handler:

server.get('/my_handler', (req, res, next) => {
  setTimeout(() => {
    // Currently, will output `true`
    console.log('span ended?', api.trace.getActiveSpan()._ended);

    res.end();
    next();
  }, 500);
});

What did you expect to see?

false should be emitted on the console, given that next has not yet been called and therefore the span should still be active.

What did you see instead?

true, indicating that the span is no longer active. In more handlers, this materialises as spans not being correctly nested, and events not emitting due to no span being active at that time.

Additional context

It appears like the problematic point in the instrumentation is:

https://github.com/open-telemetry/opentelemetry-js-contrib/blob/main/plugins/node/opentelemetry-instrumentation-restify/src/instrumentation.ts#L248-L253

The handler is called with patchedNext. The handler immediately resolves (no promises or synchronous code in the handler), leading to span.end() executing on line 252. Once the setTimeout completes, we call the provided next function as per Restify's documentation (see 'Using next()') header to continue the chain.

Similar to #1647, this causes the You can only call end() on a span once. error.

If I understand correctly, the span.end() call should be removed from line 252, and the responsibility of ending the span is differed to the patched next in order to be inline with Restify's handler convention. I would be more than happy to contribute this PR myself, just wanted some insight/clarification on whether this is actually the problem/solution. Specifically, I'm unsure how this may impact the context either...

---

On a side note, I'm wondering if this could be related to the nesting of middleware spans, as seen in the screenshot below.

[Flarna]

At least for express this is documented (see here).

As far as I know there are valid cases where next() is never called therefore ending the span in next() potentially never ends a span.

[andogq]

Upon completion of each function in the handler chain, you are responsible for calling next(). Calling next() will move to the next function in the chain.

Unlike other REST frameworks, calling res.send() does not trigger next() automatically. In many applications, work can continue to happen after res.send(), so flushing the response is not synonymous with completion of a request.

Just for clarification, this is the relevant piece from Restify’s documentation. I understand the semantics are likely different for other frameworks, but it appears that for Restify the framework expects the user to call next themselves at the end of their handlers.

If compatibility with Express handlers is desired, could this potentially be gated behind an option passed to the instrumentation construction (be it opt in or opt out - again am more than happy to contribute this).