Requests does not timeout when bodyTimeout & headersTimeout have values lower than 1 second

[mciocan]

We have an HTTP proxy were we are using fastify and @fastify/reply-from.
In order the fix some vulnerabilities for undici, we updated to the latest version and had some failed tests.

The issue is that some requests does not timeout when bodyTimeout & headersTimeout have values lower than 1 second.
We identified that the issue is related to undici@5.18.0, when faster timers where introduced (especially 1 second value used fast timer timeout - https://github.com/nodejs/undici/blob/main/lib/timers.js#L44).

In order to test this, we added a new test in https://github.com/nodejs/undici/blob/main/lib/agent.js.
We run tests using Node 18.14.1.

test('agent should timeout request (lower value timeouts)', t => {
  t.plan(4)
  const timeout = 1000
  const wanted = 'payload'

  const server = http.createServer((req, res) => {
    t.equal('/', req.url)
    t.equal('GET', req.method)
    t.equal(`localhost:${server.address().port}`, req.headers.host)

    res.setHeader('Content-Type', 'text/plain')

    setTimeout(() => {
      res.end(wanted)
    }, timeout * 3)
  })

  t.teardown(server.close.bind(server))

  server.listen(0, () => {
    const dispatcher = new Agent({ bodyTimeout: timeout, headersTimeout: timeout })
    request(`http://localhost:${server.address().port}`, { dispatcher })
      .then(({ statusCode, headers, body }) => {
        t.fail('Request should timeout')
      })
      .catch(err => {
        t.type(err, errors.HeadersTimeoutError)
      })
  })
})

🌈 SUMMARY RESULTS 🌈

Suites:   87 passed, 1 skip, 88 of 88 completed
Asserts:  7382 passed, 8 skip, of 7390
Time:   29s

This test will pass because the timeout is 1000 ms.

---

If we change the timeout to 100 ms, this test will fail.

 FAIL  test/agent.js
 ✖ Request should timeout

  test/agent.js
  191 |     request(`http://localhost:${server.address().port}`, { dispatcher })
  192 |       .then(({ statusCode, headers, body }) => {
> 193 |         t.fail('Request should timeout')
      | ----------^
  194 |       })
  195 |       .catch(err => {
  196 |         t.type(err, errors.HeadersTimeoutError)

  test: test/agent.js agent should timeout request (lower value timeouts)
  stack: |
    test/agent.js:193:11

🌈 SUMMARY RESULTS 🌈

 FAIL  test/agent.js 1 failed of 133 4s
 ✖ Request should timeout

Suites:   1 failed, 86 passed, 1 skip, 88 of 88 completed
Asserts:  1 failed, 7381 passed, 8 skip, of 7390
Time:   30s

If we change https://github.com/nodejs/undici/blob/main/lib/timers.js#L44 timeout value to 100ms, the test will pass.

---

I'm not sure what the correct fix should be and this is the reason why I've created an issue and not a PR.
I hope it's more clear to you and a fix is easy to implement!

Thank you in advance 🙏

[ronag]

This is expected. The timeout accuracy is ~1s. So if you put a timeout of 100ms and the request finishes in 300 ms then it's still within the expected range.

[mciocan]

I'm not sure I understand, sorry about that 😢
The minimum values of these timeouts are around 1 second? An error should be returned if 1s lower values are used?

If we expect a HTTP request to fail with bodyTimeout of 2 seconds (the server will respond in 3 seconds), it's natural to believe that requests with bodyTimeout of 500 ms will fail to.

If it's FAD, can you point me somewhere to the docs? 🙏

[mciocan]

I'll try to explain it again:

We have a server that will respond in 3 seconds

• 🆗 if we have bodyTimeout: 1s && headersTimeout: 1s the request will timeout, as expected
• ⚠️ If we have bodyTimeout: 100ms && headersTimeout: 100ms the request will succeed, which is not expected because the timeout values are ignored.

[ronag]

I'll try to explain it again:

We have a server that will respond in 3 seconds

• 🆗 if we have bodyTimeout: 1s && headersTimeout: 1s the request will timeout, as expected
• ⚠️ If we have bodyTimeout: 100ms && headersTimeout: 100ms the request will succeed, which is not expected because the timeout values are ignored.

Ah, that doesn't sound right. Can you provide a minimal reproducible sample?

[mciocan]

Sorry about copy paste 😞

The value of timeout is 100ms and the server will respond in 3 seconds.
This test should pass!

If you want another code sample, please let me know 🙏

test('agent should timeout request (lower value timeouts)', t => {
  t.plan(4)
  const timeout = 100
  const wanted = 'payload'

  const server = http.createServer((req, res) => {
    t.equal('/', req.url)
    t.equal('GET', req.method)
    t.equal(`localhost:${server.address().port}`, req.headers.host)

    res.setHeader('Content-Type', 'text/plain')

    setTimeout(() => {
      res.end(wanted)
    },  3 * 1000)
  })

  t.teardown(server.close.bind(server))

  server.listen(0, () => {
    const dispatcher = new Agent({ bodyTimeout: timeout, headersTimeout: timeout })
    request(`http://localhost:${server.address().port}`, { dispatcher })
      .then(({ statusCode, headers, body }) => {
        t.fail('Request should timeout')
      })
      .catch(err => {
        t.type(err, errors.HeadersTimeoutError)
      })
  })
})

[ronag]

This passes for me on main:

'use strict'

const { test } = require('tap')
const { Agent, request, errors } = require('..')
const { createServer } = require('http')

test('agent should timeout request (lower value timeouts)', t => {
  t.plan(4)
  const timeout = 100
  const wanted = 'payload'

  const server = createServer((req, res) => {
    t.equal('/', req.url)
    t.equal('GET', req.method)
    t.equal(`localhost:${server.address().port}`, req.headers.host)

    res.setHeader('Content-Type', 'text/plain')

    setTimeout(() => {
      res.end(wanted)
    },  3 * 1000)
  })

  t.teardown(server.close.bind(server))

  server.listen(0, () => {
    const dispatcher = new Agent({ bodyTimeout: timeout, headersTimeout: timeout })
    request(`http://localhost:${server.address().port}`, { dispatcher })
      .then(({ statusCode, headers, body }) => {
        t.fail('Request should timeout')
      })
      .catch(err => {
        t.type(err, errors.HeadersTimeoutError)
      })
  })
})

undici$ npx tap test/request-timeout3.js 
​ PASS ​ test/request-timeout3.js 4 OK 3s


                         
  🌈 SUMMARY RESULTS 🌈  
                         

Suites:   ​1 passed​, ​1 of 1 completed​
Asserts:  ​​​4 passed​, ​of 4​
​Time:​   ​3s​
undici$ 

[mciocan]

You example is working!

Can you try with 500ms server response timeout? 🙏 Sorry about that 😢
This is how I've managed to reproduce.

I'm missing something and I'm wasting your time for nothing?
Please let me know if I can help with anything else 🙏

setTimeout(() => {
      res.end(wanted)
    },  500)

[ronag]

With 500 ms it's within the margin of timeout accuracy. That's expected.

[mciocan]

The same result with 950ms (or values lower than this) - request will succeed ⚠️
Different result with 1000ms (or values greater than this) - the request will timeout 🆗

I really think it is something related with fast timers.
I've tried to use JS setTimeout instead of fast timers and the request will timeout every time (https://github.com/nodejs/undici/blob/main/lib/client.js#L460)

I really appreciate your time and your help!
Please let me know if this is FAD and if I should find a workaround? 🙏

[ronag]

What is FAD?

[ronag]

It is related to fast timers and it is expected behavior...

[mciocan]

FAD=functioning as designed

---

Let me give a more simpler example:

• basic HTTP server with response time 1500 ms (some DB operations, some intense request processing, etc)
• client with headersTimeout only of 500 ms (aggressive timeout for fast services)

const { test } = require('tap')
const { Agent, request, errors } = require('..')
const http = require('http')

test('agent timeout request (lower value timeouts)', t => {
  t.plan(1)

  const server = http.createServer((req, res) => {
    res.writeHead(200, { 'Content-Type': 'text/plain' })
    setTimeout(() => {res.end('OK')}, 1500)
  })

  t.teardown(server.close.bind(server))

  server.listen(0, () => {
    const dispatcher = new Agent({ headersTimeout: 500 })
    request(`http://localhost:${server.address().port}`, { dispatcher })
      .then(() => t.fail('Request should timeout'))
      .catch((err) => t.type(err, errors.HeadersTimeoutError))
  })
})

🌈 SUMMARY RESULTS 🌈


Suites:   1 passed, 1 of 1 completed
Asserts:  1 passed, of 1
Time:   2s

Request timed out and it's ok! Everything is working as expected

---

The same example, but now, the server is responding in 750ms:

• basic HTTP server with response time 750 ms (some DB operations, some intense request processing, some caching)
• client with headersTimeout only of 500 ms (aggressive timeout for fast services)

const { test } = require('tap')
const { Agent, request, errors } = require('..')
const http = require('http')

test('agent timeout request (lower value timeouts)', t => {
  t.plan(1)

  const server = http.createServer((req, res) => {
    res.writeHead(200, { 'Content-Type': 'text/plain' })
    setTimeout(() => {res.end('OK')}, 750)
  })

  t.teardown(server.close.bind(server))

  server.listen(0, () => {
    const dispatcher = new Agent({ headersTimeout: 500 })
    request(`http://localhost:${server.address().port}`, { dispatcher })
      .then(() => t.fail('Request should timeout'))
      .catch((err) => t.type(err, errors.HeadersTimeoutError))
  })
})

🌈 SUMMARY RESULTS 🌈

 FAIL  test/request-timeout3.js 1 failed of 1 4s
 ✖ Request should timeout


Suites:   1 failed, 1 of 1 completed
Asserts:  1 failed, of 1
Time:   4s

Request timeout ignored! This is clearly a bug

---

Starting with version 5.18.0, a new feature - fast timers - is introduced!
If we take semantic versioning into account, a change in behaviour that is not compatible with the previous minor is seen like a breaking change.

But beside semantic versioning, this is an strange behaviour and it's not transparent at all.

🆗 v5.17.1 - 2 test passed

~/W/g/undici>cat package.json | jq .version                                                                                                                                                                                         
"5.17.1"
~/W/g/undici>npx tap test/request-timeout3.js                                                                                                                                                                                       
test/request-timeout3.js 1> Server response timeout: 750
test/request-timeout3.js 1> Agent headersTimeout: 750
 
 PASS  test/request-timeout3.js 1 OK 790.595ms


  🌈 SUMMARY RESULTS 🌈


Suites:   1 passed, 1 of 1 completed
Asserts:  1 passed, of 1
Time:   1s

~/W/g/undici>npx tap test/request-timeout3.js        

test/request-timeout3.js 1> Server response timeout: 1500
test/request-timeout3.js 1> Agent headersTimeout: 500

 PASS  test/request-timeout3.js 1 OK 2s



  🌈 SUMMARY RESULTS 🌈


Suites:   1 passed, 1 of 1 completed
Asserts:  1 passed, of 1
Time:   2s

⚠️ 5.18.0 - 1 test passed, 1 test failed

~/W/g/undici>cat package.json | jq .version                                                                                                                                                                                         
"5.18.0"

~/W/g/undici>npx tap test/request-timeout3.js                                                                                                                                                                                       
test/request-timeout3.js 1> Server response timeout: 750
test/request-timeout3.js 1> Agent headersTimeout: 500
 FAIL  test/request-timeout3.js
 ✖ Request should timeout

  test/request-timeout3.js
  20 |     const dispatcher = new Agent({ headersTimeout: 500 })
  21 |     request(`http://localhost:${server.address().port}`, { dispatcher })
> 22 |       .then(() => t.fail('Request should timeout'))
     | --------------------^
  23 |       .catch((err) => t.type(err, errors.HeadersTimeoutError))
  24 |   })
  25 | })

  test: test/request-timeout3.js agent timeout request (lower value timeouts)
  stack: |
    test/request-timeout3.js:22:21

 FAIL  test/request-timeout3.js 1 failed of 1 4s
 ✖ Request should timeout


  🌈 SUMMARY RESULTS 🌈

 FAIL  test/request-timeout3.js 1 failed of 1 4s
 ✖ Request should timeout


Suites:   1 failed, 1 of 1 completed
Asserts:  1 failed, of 1
Time:   5s

~/W/g/undici[1]>npx tap test/request-timeout3.js                                                                                                                                                                                    

test/request-timeout3.js 1> Server response timeout: 1500
test/request-timeout3.js 1> Agent headersTimeout: 500
 PASS  test/request-timeout3.js 1 OK 2s


  🌈 SUMMARY RESULTS 🌈


Suites:   1 passed, 1 of 1 completed
Asserts:  1 passed, of 1
Time:   2s

---

@ronag, @mcollina (my apologies for summoning like this - like a said in the begging, this is used in @fastify/reply-from and it's hard to have a workaround), please consider a fix for this because we use these settings in testing environments and fast services 🙏

I'm happy to contribute with a PR if you show me the way or some guidence 👍

[ronag]

This is functioning as expected|designed, and I don't understand your use case. A timeout shorter than 1 second is not very meaningful in practical scenarios. @mcollina @KhafraDev do you have any opinions?