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

headersTimeout on Agent appears to be broken since 6.20.0 #3798

Open
Stono opened this issue Nov 2, 2024 · 10 comments
Open

headersTimeout on Agent appears to be broken since 6.20.0 #3798

Stono opened this issue Nov 2, 2024 · 10 comments
Labels
Docs Changes related to the documentation

Comments

@Stono
Copy link

Stono commented Nov 2, 2024

Bug Description

Using fetch with an undici agent with configuration such as new Agent({ headersTimeout: 1}) on 6.19.8 would correctly throw a UND_ERR_HEADERS_TIMEOUT error whereas on 6.20.0 and 6.20.1 the request just hangs.

This was caught by some tests we have around our http client that ensures timeouts work, and they started failing after the undici bump.

Reproducible By

As above really.

Expected Behavior

UND_ERR_HEADERS_TIMEOUT to throw on a headers timeout.

Logs & Screenshots

Environment

node v22.5.1
undici v6.20.x

Additional context

@Stono Stono added the bug Something isn't working label Nov 2, 2024
@ronag
Copy link
Member

ronag commented Nov 2, 2024

Du you have a full repro?

@Stono
Copy link
Author

Stono commented Nov 2, 2024

import express from 'express'
import should from 'should'
import { Agent, fetch } from 'undici'

describe.only('undici', function () {
  it('headers timeouts', async () => {
    const app = express()
    app.get('/delayed', (req, res) => {
      setTimeout(() => {
        res.json({ ok: true })
      }, 5_000)
    })
    app.listen(3002)

    const fetchPromise = async () => {
      const dispatcher = new Agent({
        connectTimeout: 5000,
        bodyTimeout: 300000,
        headersTimeout: 1
      })

      const result = await fetch('http://127.0.0.1:3002/delayed', {
        redirect: 'manual',
        headers: { accept: 'application/json' },
        method: 'GET',
        keepalive: true,
        dispatcher
      })
      return result.status
    }
    const timeoutPromise = new Promise((resolve) =>
      setTimeout(() => resolve('undici broken?'), 500)
    )

    const result = await Promise.race([fetchPromise(), timeoutPromise])
    should(result).not.eql('undici broken?')
  })
})

On 6.19.8:
Screenshot 2024-11-02 at 19 22 36

On 6.20.1:
Screenshot 2024-11-02 at 19 23 16

@metcoder95
Copy link
Member

metcoder95 commented Nov 5, 2024

The behaviour is indeed changed, I couldn't reproduce it your code in isolation; but I was able to figure out that this might has to be something with the work done for the fast timers.

As, if e.g. headersTimeout is set to 1 and the server takes just a few ms to respond with the headers, undici still treats that response as valid; the difference should be notable to the timeout take effect.

For instance, my guess is that maybe mocha does something with timers that messes the fast timers implementation and causes undici to drift some the expected behaviour.

import { createServer } from 'node:http'
import { once } from 'node:events'
import { Agent, fetch } from './index.js' // main & v6.x behaves the same

const app = createServer((req, res) => {
  setTimeout(() => {
    res.writeHead(200, { 'Content-Type': 'text/plain' })
    res.end('hello world')
  }, 10) // Change to 500 or 1000 to cause a UND_ERR_HEADERS_TIMEOUT
})

app.listen(0)

await once(app, 'listening')

const dispatcher = new Agent({
  connectTimeout: 1,
  bodyTimeout: 1,
  headersTimeout: 1
})

const result = await fetch(`http://127.0.0.1:${app.address().port}/delayed`, {
  redirect: 'manual',
  headers: { accept: 'text/plain' },
  method: 'GET',
  keepalive: true,
  dispatcher
})

console.log(result.status, await result?.text())

Between v6.19 and v6.20 the fast timers were changed. v6.19.8...v6.20.1

@Stono
Copy link
Author

Stono commented Dec 19, 2024

@metcoder95 sorry for the ridiculously long delay getting back to you.... honestly i pinned undici and forgot about it :|

I'm now trying to upgrade and running into this again, I've actually realised the reason my mocha tests were failing is because they had a timeout(1_000), even with a headersTimeout of 10, the never version of undici never returns faster than 1_000. This is reproducible outside of mocha.

See this example code:

import { once } from 'node:events'
import { createServer } from 'node:http'

import { Agent, fetch } from 'undici'

const app = createServer((req, res) => {
  setTimeout(() => {
    res.writeHead(200, { 'Content-Type': 'text/plain' })
    res.end('hello world')
  }, 5_000)
})

app.listen(3000)

await once(app, 'listening')

const start = new Date().getTime()
const dispatcher = new Agent({
  connectTimeout: 1,
  bodyTimeout: 1,
  headersTimeout: 100
})

try {
  const result = await fetch(`http://127.0.0.1:3000/delayed`, {
    redirect: 'manual',
    headers: { accept: 'text/plain' },
    method: 'GET',
    keepalive: true,
    dispatcher
  })

  console.log(result.status, await result?.text())
} catch(ex) { 
  console.log(ex)
} finally {
  const end = new Date().getTime()
  console.log('time taken', end - start)
}

This does throw UND_ERR_HEADERS_TIMEOUT but time taken is always > 1_000.

On 6.19.8 this code returns time taken as closer to 100, as you'd expect.

@Uzlopak
Copy link
Contributor

Uzlopak commented Dec 19, 2024

Maybe we should change the resolution of the fast timers?

@Stono
Copy link
Author

Stono commented Dec 19, 2024

I suppose the question really is how much it matters. For my particular use case, not so much.

However you could argue for someone who had these settings configured low to "fail fast", it's somewhat of an unexpected breaking change in a minor release. But I don't know the broader intent/expectation of these config options for the project or the trade offs that come with making them more accurate.

@metcoder95
Copy link
Member

Indeed here the question will be a matter of tradeoffs. Such low timeout is not something common outside of testing, and given that no much issues has been raised around that; maybe the value of changing the resolution agains the value added might not be well amortized.

I'd suggest that, unless this brings more troubles in actual production-like workloads; we should keep it as is for the time being.

@Stono
Copy link
Author

Stono commented Dec 20, 2024

I do believe it should at least be documented, perhaps also on the jsdoc for those config items to let people know about the resolution.

@metcoder95
Copy link
Member

Good call, would you like to send a PR for that?

@metcoder95 metcoder95 added Docs Changes related to the documentation and removed bug Something isn't working labels Dec 20, 2024
@Stono
Copy link
Author

Stono commented Dec 20, 2024

I think it's better written by somebody who understands the timer implementation and the intent of the change.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Docs Changes related to the documentation
Projects
None yet
Development

No branches or pull requests

4 participants