onError hook is called before errorHandler when error is thrown in onRequest hook

[jillro]

Prerequisites

• I have written a descriptive issue title
• I have searched existing issues to ensure the bug has not already been reported

Fastify version

4.28

Plugin version

No response

Node.js version

16.20

Operating system

Linux

Operating system version (i.e. 20.04, 11.3, 10)

Ubuntu 23.10

Description

const app = require('fastify')()
const request = require('supertest')

const onErrorHookHandler = jest.fn(async (req, res, error) => {})

app.addHook('onError', onErrorHookHandler)

app.setErrorHandler((error, req, res) => {
  if (error.message === 'unauthorized') {
    return res.code(401).send('unauthorized')
  }

  throw error
})

app.get('/should_not_be_logged', {
  onRequest: async () => {
    throw Error('unauthorized')
  }
}, async (req, res) => {
  res.send('OK')
})

app.get('/should_be_logged', {
  onRequest: async () => {
    throw Error('unhandled error')
  }
}, async (req, res) => {
  res.send('OK')
})

describe('Fastify handling errors in onRequest hooks', () => {
  beforeAll(async () => {
    return app.ready()
  })

  test('should call on Error hook for errors handled by custom error handler', async () => {
    const res = await request(app.server).get('/should_not_be_logged')

    expect(res.statusCode).toBe(401)
    expect(onErrorHookHandler).not.toHaveBeenCalled()
  })

  test('should call onError hook for unhandled errors', async () => {
    const res = await request(app.server).get('/should_be_logged')

    expect(res.statusCode).toBe(500)
    expect(onErrorHookHandler).toHaveBeenCalled()
  })
})

According to documentation onError hook will be executed only after the Custom Error Handler set by setErrorHandler has been executed, and only if the custom error handler sends an error back to the user (Note that the default error handler always sends the error back to the user).

In this case, the first test does not pass, and the onError hook is called before the custom error handler. This ruins the point of the onError hook, which according to documentation is useful if you need to do some custom error logging or add some specific header in case of error, because for logging (as it is used by the new Sentry plugin), it does not allow using the error handler to handle errors before they are logged.

Link to code that reproduces the bug

No response

Expected Behavior

The hook should be executed only after the Custom Error Handler set by setErrorHandler has been executed, and only if the custom error handler sends an error back to the user (Note that the default error handler always sends the error back to the user), even when the error has been thrown from a hook.

[mcollina]

Was it working in some cases before this? Or has it always been buggy?

[mcollina]

A PR with a fix would really be nice.

[Eomm]

Can replicate with:

const t = require('tap')
const test = t.test
const Fastify = require('.')

test('Fastify should throw on wrong options', async t => {
  const app = Fastify()

  app.addHook('onError', async (req, res, error) => {
    t.pass('onError called')
  })

  app.setErrorHandler((error, req, res) => {
    t.pass('errorHandler called')
    if (error.message === 'unauthorized') {
      return res.code(401).send('unauthorized')
    }

    throw error
  })

  app.get('/should_not_be_logged', {
    onRequest: async () => {
      throw new Error('unauthorized')
    }
  }, async (req, res) => {
    res.send('OK')
  })

  app.get('/should_be_logged', {
    onRequest: async () => {
      throw new Error('unhandled error')
    }
  }, async (req, res) => {
    res.send('OK')
  })

  await app.ready()

  const res = await app.inject({
    method: 'GET',
    url: '/should_not_be_logged'
  })
  t.same(res.statusCode, 401)

  const res2 = await app.inject({
    method: 'GET',
    url: '/should_be_logged'
  })
  t.same(res2.statusCode, 500)

  t.end()
})

We should check.

In v3 I get:

# Subtest: Fastify should throw on wrong options
    ok 1 - errorHandler called
    ok 2 - should be equivalent
    ok 3 - errorHandler called
    ok 4 - onError called
    ok 5 - should be equivalent
    1..5
ok 1 - Fastify should throw on wrong options # time=55.848ms

In v4.10.0:

# Subtest: Fastify should throw on wrong options
    ok 1 - onError called
    ok 2 - errorHandler called
    ok 3 - should be equivalent
    ok 4 - onError called
    ok 5 - errorHandler called
    not ok 6 - unhandled error // memory error

It may me think if we have outdated docs, but for sure we must add a test to assert the order

[metcoder95]

Did we change that on purpose? Couldn't find a PR/commit that did that (maybe I overlooked)

[cesarvspr]

I'm surprised this issue was not reported before, looks like old issue in v4

[giuliowaitforitdavide]

Can replicate with:

const t = require('tap')
const test = t.test
const Fastify = require('.')

test('Fastify should throw on wrong options', async t => {
  const app = Fastify()

  app.addHook('onError', async (req, res, error) => {
    t.pass('onError called')
  })

  app.setErrorHandler((error, req, res) => {
    t.pass('errorHandler called')
    if (error.message === 'unauthorized') {
      return res.code(401).send('unauthorized')
    }

    throw error
  })

  app.get('/should_not_be_logged', {
    onRequest: async () => {
      throw new Error('unauthorized')
    }
  }, async (req, res) => {
    res.send('OK')
  })

  app.get('/should_be_logged', {
    onRequest: async () => {
      throw new Error('unhandled error')
    }
  }, async (req, res) => {
    res.send('OK')
  })

  await app.ready()

  const res = await app.inject({
    method: 'GET',
    url: '/should_not_be_logged'
  })
  t.same(res.statusCode, 401)

  const res2 = await app.inject({
    method: 'GET',
    url: '/should_be_logged'
  })
  t.same(res2.statusCode, 500)

  t.end()
})

We should check.

In v3 I get:

# Subtest: Fastify should throw on wrong options
    ok 1 - errorHandler called
    ok 2 - should be equivalent
    ok 3 - errorHandler called
    ok 4 - onError called
    ok 5 - should be equivalent
    1..5
ok 1 - Fastify should throw on wrong options # time=55.848ms

In v4.10.0:

# Subtest: Fastify should throw on wrong options
    ok 1 - onError called
    ok 2 - errorHandler called
    ok 3 - should be equivalent
    ok 4 - onError called
    ok 5 - errorHandler called
    not ok 6 - unhandled error // memory error

It may me think if we have outdated docs, but for sure we must add a test to assert the order

is this still an issue? I tried to reproduce this bug in main and 4.x branches without success