pinojs/pino-http

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

オープン

#348 opened on 2024/08/26

 (8 件のコメント) (2 件のリアクション) (0 人の担当者)JavaScript (128 件のフォーク)github user discovery
help wanted

Repository metrics

Stars
 (694 個のスター)
PR merge metrics
 (平均マージ 1m) (30d で 2 merged PRs)

説明

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?

コントリビューターガイド