cls-rtracer causes pino-http >= version 7.1 to log success message (responses) twice

[holzerch]

When the cls-rtracer middleware is added before a logging middleware based on pino-http >= 7.1.0 the success messages (responses) are logged twice.

The problem happens since the merge of this PR in pino-http: https://github.com/pinojs/pino-http/pull/219 So after this response event listener was added: res.on('close', onResFinished) in addition to the already existing one res.on('finish', onResFinished)

For further reference please check the rejected issue at pino-http: https://github.com/pinojs/pino-http/issues/234 and the sample app to reproduce the issue provided by @Simon-Campbell : https://github.com/Simon-Campbell/pino-http-double-success

[puzpuzpuz]

Thanks for the detailed issue description. I'll be looking into it later this week. In the meantime, if you'd like to contribute a patch, that would be awesome.

[puzpuzpuz]

A simple workaround is to register pino-http before cls-rtracer:

$ git diff
diff --git a/index.js b/index.js
index 2ab461f..7c0a88b 100644
--- a/index.js
+++ b/index.js
@@ -4,8 +4,8 @@ const pino = require('pino-http')()
 const app = express()
 const port = 3000

-app.use(rTracer.expressMiddleware())
 app.use(pino)
+app.use(rTracer.expressMiddleware())

 app.get('/', (req, res) => {
   req.log.info('Hello')

[holzerch]

A simple workaround is to register pino-http before cls-rtracer:

That is true, but in this case the log messages by pino-http cannot contain the request id generated by cls-rtracer

[puzpuzpuz]

Yup, that's right. I'm looking into it to provide a proper fix. Just wanted to share a workaround.

[puzpuzpuz]

The issue should be fixed in 2.6.1. Let me know if you notice any problems.

[holzerch]

Thanks a lot for the very fast fix.

[puzpuzpuz]

@holzerch A heads up: v2.6.1 had a critical bug (#61) which should be fixed in 2.6.2. Please consider upgrading.

[holzerch]

@holzerch A heads up: v2.6.1 had a critical bug (#61) which should be fixed in 2.6.2. Please consider upgrading.

Thanks for the heads-up. I noticed the memory leak as well and thought it would be a general problem with the lib.

[puzpuzpuz]

No that's just me overlooking what's being mutated. Sorry for the trouble.