Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
mciocan opened this issue Feb 21, 2023 · 20 comments · Fixed by #1961
Closed

Comments

@mciocan
Copy link

mciocan commented Feb 21, 2023

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 🙏

@mciocan mciocan added the bug Something isn't working label Feb 21, 2023
@ronag
Copy link
Member

ronag commented Feb 21, 2023

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.

@ronag ronag removed the bug Something isn't working label Feb 21, 2023
@mciocan
Copy link
Author

mciocan commented Feb 21, 2023

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
Copy link
Author

mciocan commented Feb 21, 2023

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
Copy link
Member

ronag commented Feb 21, 2023

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
Copy link
Author

mciocan commented Feb 21, 2023

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
Copy link
Member

ronag commented Feb 21, 2023

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
Copy link
Author

mciocan commented Feb 21, 2023

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
Copy link
Member

ronag commented Feb 21, 2023

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

@mciocan
Copy link
Author

mciocan commented Feb 21, 2023

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
Copy link
Member

ronag commented Feb 21, 2023

What is FAD?

@ronag
Copy link
Member

ronag commented Feb 21, 2023

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

@mciocan
Copy link
Author

mciocan commented Feb 21, 2023

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
Copy link
Member

ronag commented Feb 21, 2023

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?

@mciocan
Copy link
Author

mciocan commented Feb 21, 2023

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?

I agree that this is not a very common scenario 😢

@mcollina
Copy link
Member

What is the production situation you want to handle? I'm lost.
I see the test situation, but that's not something we should really handle.

@mciocan
Copy link
Author

mciocan commented Feb 21, 2023

Proxy servers with upstreams that should respond as fast as possible, under 500ms.
These proxy servers can broadcast the request to multiple upstreams and pick the fastest response.

Also, in our CI/CD pipelines we run tests and we configure services with the lowest possible values for timeouts.

@mciocan
Copy link
Author

mciocan commented Feb 21, 2023

I understand that fast timers brings some performance, but these features should not introduce breaking changes.

If it's something you want to stick with, please consider to add some docs around it to be more transparent 🙏

Either way, I thank you all for your time and patience 💯

@mcollina
Copy link
Member

Thanks, the use case is helpful: now I understand the problem.

@ronag I think we might want to put the new fast timers behind an option, or possibly have a way to handle this situation without a regression

@ronag
Copy link
Member

ronag commented Feb 22, 2023

I think the easiest is to not use fast timers if the timeout is set to something less than 1 second.

@mciocan
Copy link
Author

mciocan commented Feb 22, 2023

Thank you!

Please let me know if there is anything I can help with 🙏

ronag added a commit that referenced this issue Feb 22, 2023
ronag added a commit that referenced this issue Feb 22, 2023
ronag added a commit that referenced this issue Feb 22, 2023
metcoder95 pushed a commit to metcoder95/undici that referenced this issue Jul 21, 2023
crysmags pushed a commit to crysmags/undici that referenced this issue Feb 27, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants