onResFinished err object always undefined when using Express async requests ?

[saumets]

Using pino 7.0.2 and am using express-promise-router to handle my express async routes. Am trying to get pino-http going to replace winston, but am having an issue getting a thrown error object added to the logs. Looking at the pino-http/logger.js I believe the error object should be getting logged, unless I'm misunderstanding something.

Barebones example set up:

const http = require('http')
const express = require('express')
const Router = require('express-promise-router');
const expressLogger = require('pino-http')
const logger = require('./utils/logging/logger') // returns pino w/ transport to stdout

const router = new Router()

const app = express()

app.use(expressLogger({
  logger,
  autoLogging: true,
  customLogLevel: (res, err) => {
    if (res.statusCode >= 400 && res.statusCode < 500) {
      return 'warn'
    } if (res.statusCode >= 500 || err) {
      return 'error'
    }
    return 'info'
  }
}))

// dummy test function
async function wait (ms) {
  return new Promise((resolve) => {
    setTimeout(resolve, ms)
  });
}

router.get('/test', async (req, res, next) => {
  console.log('waiting', new Date());
  await wait(3 * 1000);
  const testError = new Error('Random Forbidden Error')
  testError.status = 403
  throw testError // THROW RANDOM 403 ERROR OBJ
})

app.use(router)

// final error handler for async routes.
app.use((err, req, res, next) => {
  if (res.headersSent) {
    next(err)
  } else {
    console.log('My error response handler:', err)
    res.status(err.status).end()
  }
})

module.exports = http.createServer(app)

When running the above barebones server, and when I hit the /test route this is the logged output:

[nodemon] starting `node src/index.js`
{"level":30,"time":1634651614518,"pid":6287,"hostname":"My-Macbook-Pro.local","msg":"Started on port 4000"}
Wrote to development
derp 2021-10-19T13:53:43.303Z
My error response handler: Error: Random Forbidden Error
    at /dev/app/server-test.js:41:21 {
  status: 403
}
---
onResFinished Error Object: undefined
---
{"level":40,"time":1634651626309,"pid":6287,"hostname":"My-Macbook-Pro.local","req":{
    "level": 40,
    "time": 1634651626309,
    "pid": 6287,
    "hostname": "My-Macbook-Pro.local",
    "req":
    {
        "id": 1,
        "method": "GET",
        "url": "/test",
        "query":
        {},
        "params":
        {},
        "headers":
        {
            "content-type": "application/json",
            "environment": "main",
            "user-agent": "PostmanRuntime/7.28.4",
            "accept": "*/*",
            "cache-control": "no-cache",
            "postman-token": "d76f18b3-0fa5-4e43-ade1-0b90157d582a",
            "host": "local.dev.com:4000",
            "accept-encoding": "gzip, deflate, br",
            "connection": "keep-alive"
        },
        "remoteAddress": "::ffff:127.0.0.1",
        "remotePort": 50282
    },
    "res":
    {
        "statusCode": 403,
        "headers":
        {
            "x-powered-by": "Express"
        }
    },
    "responseTime": 3006,
    "msg": "request completed"
}
Wrote to development

I prettified the output here for the purposes of the issue, and added the console output within the onResFinished handler in pino-http/logger.js to check the err obj.

In my barebones example my My error response handler middleware has the error. It has the err object from the console output, but the err object to onResFinished is undefined for some reason. In the above example I'm expecting to see an "err" key with the error object attached, no?

Am I doing something completely wrong in this setup? 🤔

[mcollina]

I don't know what express-promise-router does, but that's likely the culprit of the problem. I don't really know how to help with this.

[saumets]

@mcollina thanks for the prompt response. express-promise-router is just wrapped around the Express Router. From it's docs (https://www.npmjs.com/package/express-promise-router):

Middleware and route handlers can simply return a promise. If the promise is rejected, express-promise-router will call next with the reason. This functionality removes the need to explicitly define a rejection handler.

I've re-written my use-case without express-promise-router to eliminate it. Here is my updated example:

const http = require('http')
const express = require('express')
const expressLogger = require('pino-http')
const logger = require('./utils/logging/logger')

const app = express()

app.use(expressLogger({
  logger,
  autoLogging: true,
  customLogLevel: (res, err) => {
    if (res.statusCode >= 400 && res.statusCode < 500) {
      return 'warn'
    } if (res.statusCode >= 500 || err) {
      return 'error'
    }
    return 'info'
  }
}))

async function wait (ms) {
  return new Promise((resolve) => {
    setTimeout(resolve, ms)
  });
}

app.get('/test', async (req, res, next) => {
  console.log('derp', new Date());
  await wait(3 * 1000);
  const testError = new Error('Random Forbidden Error')
  testError.status = 403
  Promise.reject(testError).catch(next)
})

app.use((err, req, res, next) => {
  if (res.headersSent) {
    next(err)
  } else {
    console.log('My error response handler:', err)
    console.log('---')
    res.status(err.status).end()
  }
})

module.exports = http.createServer(app)

This results in the same output response as I originally posted, and the err object is missing still 😞

[mcollina]

I don't have a clue :(.

[saumets]

😢 If it matters I've been using Node v16.x.x for this, but I've managed to replicate it down to v12.x.x (didn't try any lower). Was looking forward to moving away from winston finally but will keep this open, and hopefully someone else can confirm they see the same thing, and/or we discover why this may be happening.

[jsumners]

The issue is that none of the maintainers are Express users. Also, this repository is for pino-http which is meant to be used with the Node.js core http module. So it's unclear why Express would even be a factor in this issue tracker. Regardless, given our lack of knowledge about Express, we can only help you help yourself. Have you stepped through the issue with the debugger?

[saumets]

@jsumners My apologies, and I suppose I could have posted this in the express-pino-logger repo. Looking there I saw it was a simple wrapper for pino-http, and the pino docs for web frameworks + Express pointed here. It seemed the most appropriate place to post.

The tricky thing with the debugger is that there is no actual error being raised. The err object is just not being passed to the onResFinished event handler of pino-http for some oddball reason.

That all being said here are the results from using the debugger:

< {"level":30,"time":1634691947437,"pid":20135,"hostname":"My-Macbook-Pro.local","msg":"Started on port 4000"}
< Wrote to development
< derp 2021-10-20T01:05:51.376Z
< Error: Random Forbidden Error
<     at /dev/app/server-test.js:29:21 {
<   status: 403
< }
< My error response handler: Error: Random Forbidden Error
<     at /dev/app/server-test.js:29:21 {
<   status: 403
< }
< ---
break in src/server-test.js:44
 42     console.log('My error response handler:', err)
 43     console.log('---')
>44     debugger;
 45     res.status(err.status).end()
 46   }
debug> repl
Press Ctrl + C to leave debug repl
> err
{ status: 403,
  stack: 'Error: Random Forbidden Error\n' +
  '    at /Users/paulsa…/platform-ops/shippy-api/src/server-test.js:29:21',
  message: 'Random Forbidden Error' }
debug> c
break in node_modules/pino-http/logger.js:69
 67
 68   function onResFinished (err) {
>69     debugger;
 70     this.removeListener('error', onResFinished)
 71     this.removeListener('finish', onResFinished)
debug> repl
Press Ctrl + C to leave debug repl
> err
undefined
>

Note line 44 where I set the first debugger breakpoint. Jumped into repl and verified that err exists at this point, and we are about to finish the response by calling res.status(err.status).end(). This will fire res.on('finish', onResFinished). My second breakpoint was at the start of onResFinished and again diving into repl we can see that err is undefined 😢

It's a real head scratcher. Unsure where to potentially look next. I'm fine with closing this if you'd like. That all being said it's incredibly odd that this would break with express simply by using async requests?!

[jsumners]

That all being said it's incredibly odd that this would break with express simply by using async requests?!

I don't think so. To my knowledge, Express doesn't support promises and any module adding them is a hack at best.

[saumets]

I don't think so. To my knowledge, Express doesn't support promises and any module adding them is a hack at best.

Duly noted, and time to move to Fastify I suppose. We can close this then.