Internal stack trace logged

[linde12]

Hi.

I think i'm just a bit confused about the way express-pino-logger/pino-http handles errors, i would expect any thrown errors to be caught & logged by pino, instead it seems they are caught but the thrown error itself is discarded and instead a default error (with useless stack trace) is logged (See 'failed with status code': https://github.com/pinojs/pino-http/blob/master/logger.js#L48)

This is because express doesn't emit the error event on the response object whenever an error is caught. I need the correct stack trace to be logged so what i had to do was to write this error-catching middleware:

app.use(function (err, req, res, next) {
  res.emit('error', err)
  res.status(500).json({ ... })
})

I saw that in examples.js there is a middleware that does req.log.error(err) and this actually logs the error with the stack trace, but then the internal stack trace (on LOC pasted above) is also logged:

"err":{"type":"Error","message":"failed with status code 500","stack":"Error: failed with status code 500\n    at ServerResponse.onResFinished (/xxxxxx/pino-http/logger.js:48:33)\n    at ServerResponse.emit (events.js:194:15)\n    at onFinish (_http_outgoing.js:671:10)\n    at process._tickCallback (internal/process/next_tick.js:61:11)"}

I don't want to see the internal stack trace in my log, i just want to see the request/response & eventual errors in the same json blob. Is there any sane way of doing this, i mean without doing res.emit('error', err) which is just a hack i use temporarily? Basically i just want all thrown errors to to be caught & logged with correct stack trace

[mcollina]

That's a different error. It's this line that gets logged whenever there is no error.

https://github.com/pinojs/pino-http/blob/80ec732c9d8c6693b61921a8147fae5715d23d07/logger.js#L46-L50

IMHO we might change it so no stacktrace is actually printed if there is no one, as that's there for no good reasons that I can find.

Would you like to send a PR to change that?

[linde12]

@mcollina Sounds good. I'll send a PR once i'm home where i remove the default error condition, but the main issue still remains. If you run example.js & GET 127.0.0.1:3000/error then both the actual error that was passed to next and the default error are logged in two separate entries.

[ex-tag]

Probably better just to get rid of the stack trace. This really confused me. I was looking to get a stack trace on my application, and thought this was giving me one. Also had a lot of trouble figuring out how to actually get a trace to work, and tried request.log.trace() but that did not work. Finally figured out that I could pass the Error object, as request.log.error(Error(message))...