opentelemetry-js-contrib: Inconsistent start and end time, startTime > endTime issues with express

What version of OpenTelemetry are you using?

$ npm list @opentelemetry/instrumentation-express   

test-obs@0.0.0 /Users/alexandre/Dev/Alteia/test-observability/test-obs
└─┬ @opentelemetry/auto-instrumentations-node@0.32.1
  └── @opentelemetry/instrumentation-express@0.31.1

What version of Node are you using?

$ node -v  
v16.17.0

Running on a M1 MacBook Pro

What did you do?

I am running a simple nest app to familiarize with open telemetry instrumentation and tooling. I have added the auto-instrumentation as mentioned in the docs, and running a custom nest app. After some times (especially If the Macbook go to sleep) I start to see such warning in the output :

Inconsistent start and end time, startTime > endTime [ 1664350641, 619671106 ] [ 1664350641, 619333687 ]

Jaeger traces looks completely wrong image

What did you expect to see?

Here is the jaeger traces before the problem is appearing

image

What did you see instead?

The timing for the express span is getting completely off.

Additional context

I did a quick debugging session and source code analysis and I am very suspicious about the following code : https://github.com/open-telemetry/opentelemetry-js-contrib/blob/1c450f5fe31437aa7157ff6bb8602d330dc3b429/plugins/node/opentelemetry-instrumentation-express/src/instrumentation.ts#L266

https://github.com/open-telemetry/opentelemetry-js-contrib/blob/1c450f5fe31437aa7157ff6bb8602d330dc3b429/plugins/node/opentelemetry-instrumentation-express/src/instrumentation.ts#L274

It seems it is using a performance timer for the span end time, which may somehow differ from the wall time (https://github.com/open-telemetry/opentelemetry-js/issues/852 looks related), whereas other instrumentations does not override the span end time and works correctly in my case.

About this issue

  • Original URL
  • State: closed
  • Created 2 years ago
  • Comments: 15 (9 by maintainers)

Commits related to this issue

Most upvoted comments

usually noone passes start/end times and lets the SDK do this. But it seems express instrumentation has a special situations where a span is started and then it notices that the span is “useless” and they end the span using a manual provided time to get a span with 0 duration.

I think it would be better to just call span.end() in express even in these cases which would choose the same time source for start/end and avoid this problem.

Also noted, that even in the “good” trace, the request handler - /api span is much shorter than the actual request processing which should be ~2.2s (I am using setTimeouts in my toy service/repo to simulate serial/parallel processing).