pinojs/pino-http

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

Open

#348 opened on Aug 26, 2024

 (8 comments) (2 reactions) (0 assignees)JavaScript (128 forks)github user discovery
help wanted

Repository metrics

Stars
 (694 stars)
PR merge metrics
 (Avg merge 1m) (2 merged PRs in 30d)

Description

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?

Contributor guide