Sporadic tracer id logging

[liester]

I spent about 2 hours and a good deal of coffee tracking this down and thought it might be beneficial to others.

TL;DR. calling app.use(rTracer.expressMiddleware()) before express-session middleware caused erratic logging behavior. Trace Ids were not correct/showing inconsistently.

In the troubleshooting section of the readme it says to open a github issue if we run across any issues around async calls. Even if this isn't that exact issue I thought I should let someone smarter than me know about it.

I was seeing sporadic tracer id logging happening. See the image below. As you can see there is the normal express started message. Then the log statements for the api requests through some custom authentication middleware. I call the endpoint a few times in the next few minutes. Then magically there is a log with the tracer id, then nothing, then tracer id again, but now its showing the same tracer id for four different requests.

I change the following middleware order from:

app.use(rTracer.expressMiddleware());
app.use(session(sessionOptions));
app.use(authenticationMiddleware);

to

app.use(session(sessionOptions));
app.use(rTracer.expressMiddleware());
app.use(authenticationMiddleware);

and no more issues.

[aigoncharov]

express-session seems to be losing context due to its implementation.
othiym23/node-continuation-local-storage#29
I'm wondering if the last comment from that issue could help.

[puzpuzpuz]

@liester
Thanks for reporting this issue.

As @aigoncharov mentioned, some middlewares (and libraries that they use internally) may loose CLS (i.e. Async Hooks) context and looks like that's what you have faced. Unfortunately, such issues have to be addressed individually and I'm glad that reordering middlewares was sufficient in your case. I'm going to mention this in the readme and add a link to this issue.

[puzpuzpuz]

Closing this issue as a workaround was found. Feel free to reopen it if any help is needed.