pinojs/pino-http

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

Ouverte

#348 ouverte le 26 août 2024

 (8 commentaires) (2 réactions) (0 personne assignée)JavaScript (128 forks)github user discovery
help wanted

Métriques du dépôt

Stars
 (694 étoiles)
Métriques de merge PR
 (Merge moyen 1m) (2 PRs mergées en 30 j)

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?

Guide contributeur