Pino-http logs a different error from the one sent by express

[theo-m]

Reproduction

https://github.com/theo-m/repro-pino-http-error

You'll observe that express does send the responses appropriately with the right errors - but, what's logged by Pino is entirely different.

What the client receives (👍 )

> curl localhost:8080 | jq -r '.error.stack'

  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100  1462  100  1462    0     0  20883      0 --:--:-- --:--:-- --:--:-- 21188
Error: not happy
    at /repro-sentry-logging/app.ts:23:9
    at Layer.handle [as handle_request] (/repro-sentry-logging/node_modules/.pnpm/express@4.19.2/node_modules/express/lib/router/layer.js:95:5)
    at next (/repro-sentry-logging/node_modules/.pnpm/express@4.19.2/node_modules/express/lib/router/route.js:149:13)
    at Route.dispatch (/repro-sentry-logging/node_modules/.pnpm/express@4.19.2/node_modules/express/lib/router/route.js:119:3)
    at Layer.handle [as handle_request] (/repro-sentry-logging/node_modules/.pnpm/express@4.19.2/node_modules/express/lib/router/layer.js:95:5)
    at /repro-sentry-logging/node_modules/.pnpm/express@4.19.2/node_modules/express/lib/router/index.js:284:15
    at Function.process_params (/repro-sentry-logging/node_modules/.pnpm/express@4.19.2/node_modules/express/lib/router/index.js:346:12)
    at next (/repro-sentry-logging/node_modules/.pnpm/express@4.19.2/node_modules/express/lib/router/index.js:280:10)
    at loggingMiddleware (/repro-sentry-logging/node_modules/.pnpm/pino-http@10.2.0/node_modules/pino-http/logger.js:206:7)
    at result (/repro-sentry-logging/node_modules/.pnpm/pino-http@10.2.0/node_modules/pino-http/logger.js:90:12)

What the logger emits (👎 )

[14:28:14.237] INFO (52167): request errored {"req":{"id":1,"method":"GET","url":"/","query":{},"params":{},"headers":{"host":"localhost:8080","user-agent":"curl/8.6.0","accept":"*/*"},"remoteAddress":"::1","remotePort":50130},"res":{"statusCode":500,"headers":{"x-powered-by":"Express","content-type":"application/json; charset=utf-8","content-length":"1462","etag":"W/\"5b6-g3EC2/ru12Gn/Ky0ozTDg1MvZkg\""}},"responseTime":68}
    err: {
      "type": "Error",
      "message": "failed with status code 500",
      "stack":
          Error: failed with status code 500
              at onResFinished (/repro-sentry-logging/node_modules/.pnpm/pino-http@10.2.0/node_modules/pino-http/logger.js:115:39)
              at ServerResponse.onResponseComplete (/repro-sentry-logging/node_modules/.pnpm/pino-http@10.2.0/node_modules/pino-http/logger.js:178:14)
              at ServerResponse.emit (node:events:530:35)
              at onFinish (node:_http_outgoing:1005:10)
              at callback (node:internal/streams/writable:756:21)
              at afterWrite (node:internal/streams/writable:701:5)
              at afterWriteTick (node:internal/streams/writable:687:10)
              at processTicksAndRejections (node:internal/process/task_queues:81:21)
    }

I had initially submitted this problem to Sentry as I had messed up my repro and the logger's stack trace pointed to Sentry/OTel - but even without these packages the problem persists.

---

Looking at this part of the lib, I can get what I want with this patch, but it seems hacky?

diff --git a/app.ts b/app.ts
index b383da9..7d87e43 100644
--- a/app.ts
+++ b/app.ts
@@ -24,6 +24,8 @@ app.get("/", (_req, _res) => {
 });

 const errHandler: ErrorRequestHandler = (err, _req, res, _next) => {
+  res.err = err;
+
   return res
     .status(500)
     .json({ error: { name: err.name, message: err.message, stack: err.stack } })

It seems this line expects an event, but it doesn't seem to exist on node's Response or OutgoingMessage objects?

[jsumners]

Please provide a minimal reproducible example. Doing so will help us diagnose your issue. It should be the bare minimum code needed to trigger the issue, and easily runnable without any changes or extra code.

You may use a GitHub repository to host the code if it is too much to fit in a code block (or two).

[theo-m]

I'm not sure I understand, the first two line of the issue read like this:

Reproduction https://github.com/theo-m/repro-pino-http-error

You'll find a minimal reproducible example in that repo

[mcollina]

You'll find a minimal reproducible example in that repo

I would hardly consider that minimal, given the build step, but I was able to reproduce anyway.

---

I've checked the example and pino-http behaves as expected. The "hacky" fix is indeed the correct one.

However, I think we could provide an express-specific variant that where the middleware intercept the first, error argument:

https://github.com/pinojs/pino-http/blob/a4b581a0e1fe3b5ef9013c404bc9ceec66c04c46/logger.js#L89-L93

In this way we can intercept the error as it's passing through the middleware chain.

Would you like to send a PR?

[theo-m]

I would hardly consider that minimal, given the build step, but I was able to reproduce anyway.

Not to stray from the issue, but having a build step seems inevitable since pino-http has typescript support? The docs do mention esbuild support too and suggest using the plugin that's setup in the repro.

It seems to me the repro is quite "portable" and has two commands that would run without additional setup, what would you guys expect?

---

I'd gladly help with the PR, but I'm not sure what's entailed by an express-specific variant, what user API do you have in mind?

[jsumners]

For me, I want a JavaScript reproduction. I have updated my saved reply to indicate as much as a result of this thread. But I also just didn't see the link originally. I had skimmed the report enough to recognize that we'd need one for clarity, but I missed the link. 🤷‍♂️

[mcollina]

A middleware like:

 const result = (req, res, next) => { 
   return loggingMiddleware(logger, req, res, next) 
 } 
 result.logger = logger
 result.express = (err, req, res, next) => {
   res.err = err
   return loggingMiddleware(logger, req, res, next) 
 }
 return result