Incorrect Express Timings

[ngauthier]

I mentioned this in #164 but it's a separate issue so splitting it out here.

The automatic express middleware finishes the trace when headers are sent:

https://github.com/honeycombio/beeline-nodejs/blob/master/lib/instrumentation/express.js#L149-L151

This means the timed duration is how long it takes the handler to send headers, not to send the entire response.

In our case, we have some streaming endpoints that send data from the database in chunks. These report a duration of a few ms, when in reality they are hundreds of ms to complete. By measuring at our router (and simply console.logging in development) it's clear that they take longer than a few ms.

An alternative implementation to bind to the finish event on the response would look like this:

  res.on("finish", function() {
    boundFinisher(this, tracker.getTracked());
  });

Was this behavior a mistake, or is it the intention to track duration as being when headers are first sent?

[toshok]

huh. mistake. two options here:

1. increase the existing span duration to include sending the response.
2. add another span for sending the response.

any strong preference for one over the other?

[ngauthier]

I would prefer (1), as long as it's guaranteed to send when there are errors as well. I wouldn't want extra spans if I can help it. If I wanted more spans, I would make them in my application code for the data sending phase. Thank you!

[vreynolds]

Hello,

We will be closing this issue as it is a low priority for us. It is unlikely that we'll ever get to it, and so we'd like to set expectations accordingly.

As we enter 2022 Q1, we are trimming our OSS backlog. This is so that we can focus better on areas that are more aligned with the OpenTelemetry-focused direction of telemetry ingest for Honeycomb.

If this issue is important to you, please feel free to ping here and we can discuss/re-open.