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
What did you expect to see?
Here is the jaeger traces before the problem is appearing

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