Leak and very long hanging when fetch throws `ConnectTimeoutError(UND_ERR_CONNECT_TIMEOUT)`
Nobody has claimed this yet.
- Dominant language
- JavaScript
- Stars
- 7.7k
- Forks
- 880
- Avg merge
- 2d 16h
- Merged PRs (30d)
- 68
Description
Version
v21.0.0
Platform
Linux archhost 6.5.7-arch1-1 nodejs/node#1 SMP PREEMPT_DYNAMIC Tue, 10 Oct 2023 21:10:21 +0000 x86_64 GNU/Linux
Subsystem
No response
What steps will reproduce the bug?
- pull https://github.com/nikelborm/fetch_timeout_poc
- enable wifi and connect to network with internet
- connect to wireguard vpn with sending all trafic through this vpn server
- disable wifi
- run
npm start
index.js
"use strict";
const startedAt = Date.now();
console.log('started fetch at: ', new Date(startedAt));
try {
await fetch('https://jsonplaceholder.typicode.com/todos/1');
} catch (error) {
console.log(error);
}
const finishedAt = Date.now();
console.log('finished fetch at: ', new Date(finishedAt))
console.log(`fetch took ${finishedAt - startedAt} ms`)
console.log('timestamp when script should finish: ', Date.now())
package.json
{
"name": "poc",
"version": "1.0.0",
"description": "",
"main": "index.js",
"type": "module",
"scripts": {
"start": "node index.js; node -e \"console.log('timestamp when script actually finished: ', Date.now())\""
}
}
How often does it reproduce? Is there a required condition?
It reproduces every time with described network configuration. No other condition. Same behavior in node v20.7.0 and v18.18.0
What is the expected behavior? Why is that the expected behavior?
Fetch waits 10 seconds, throws error UND_ERR_CONNECT_TIMEOUT. Then script exits immediately after it completed. Difference between timestamp when script should finish and timestamp when script actually finished should be near zero.
What do you see instead?
Fetch is being executed as expected. It kills itself after about 10 seconds and then returns control back to the script.
But the problem is that something in the background is still blocking node.js and does not allow process to exit. It just hangs waiting for something to be finished even if the script was completed.
started fetch at: 2023-10-21T00:37:09.239Z
TypeError: fetch failed
at Object.fetch (node:internal/deps/undici/undici:11372:11)
at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
at async file:///home/nikel/projects/alarm/index.js:7:3 {
cause: _ConnectTimeoutError: Connect Timeout Error
at onConnectTimeout (node:internal/deps/undici/undici:6616:28)
at node:internal/deps/undici/undici:6574:50
at Immediate._onImmediate (node:internal/deps/undici/undici:6605:13)
at process.processImmediate (node:internal/timers:478:21) {
code: 'UND_ERR_CONNECT_TIMEOUT'
}
}
finished fetch at: 2023-10-21T00:37:19.391Z
fetch took 10152 ms
timestamp when script should finish: 1697848639391
timestamp when script actually finished: 1697848749482
After all code in the script been executed it takes 110 seconds (1697848749482 - 1697848639391 = 110091) to exit from process.
But enabling wifi back (restoring internet connection) during process's hanging (after the moment fetch already failed and logged error) magically speeds up exit from process.
Additional information
Running completely offline
If we skip 2-3 steps and just run script offline we get other kind of error and expected behavior.
Following is being printed to console:
started fetch at: 2023-10-21T00:54:31.085Z
TypeError: fetch failed
at Object.fetch (node:internal/deps/undici/undici:11372:11)
at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
at async file:///home/nikel/projects/alarm/index.js:7:3 {
cause: Error: getaddrinfo EAI_AGAIN jsonplaceholder.typicode.com
at GetAddrInfoReqWrap.onlookupall [as oncomplete] (node:dns:118:26) {
errno: -3001,
code: 'EAI_AGAIN',
syscall: 'getaddrinfo',
hostname: 'jsonplaceholder.typicode.com'
}
}
finished fetch at: 2023-10-21T00:54:31.250Z
fetch took 165 ms
timestamp when script should finish: 1697849671250
timestamp when script actually finished: 1697849671310
Difference between timestamp when script should finish and timestamp when script actually finished is 60 ms what is fine.
Running online
If we skip 4 step and just run script online we get no errors and expected behavior.
Following is being printed to console:
started fetch at: 2023-10-21T00:58:19.347Z
finished fetch at: 2023-10-21T00:58:19.995Z
fetch took 648 ms
timestamp when script should finish: 1697849899995
timestamp when script actually finished: 1697849900162
Difference between timestamp when script should finish and timestamp when script actually finished is 167 ms what also seems fine.
Running using node-fetch with described network configuration
If we install node-fetch with npm i node-fetch and then import it in the beginning using import fetch from 'node-fetch'; it will replace original fetch and will give us different behavior:
started fetch at: 2023-10-21T01:48:05.984Z
FetchError: request to https://jsonplaceholder.typicode.com/todos/1 failed, reason: getaddrinfo EAI_AGAIN jsonplaceholder.typicode.com
at ClientRequest.<anonymous> (file:///home/nikel/projects/alarm/node_modules/node-fetch/src/index.js:108:11)
at ClientRequest.emit (node:events:517:28)
at TLSSocket.socketErrorListener (node:_http_client:501:9)
at TLSSocket.emit (node:events:517:28)
at emitErrorNT (node:internal/streams/destroy:151:8)
at emitErrorCloseNT (node:internal/streams/destroy:116:3)
at process.processTicksAndRejections (node:internal/process/task_queues:82:21) {
type: 'system',
errno: 'EAI_AGAIN',
code: 'EAI_AGAIN',
erroredSysCall: 'getaddrinfo'
}
finished fetch at: 2023-10-21T01:50:06.143Z
fetch took 120159 ms
timestamp when script should finish: 1697853006143
timestamp when script actually finished: 1697853006236
When fetch from node-fetch fails, it logs last few lines to console and script exits immediately. Difference between timestamp when script should finish and timestamp when script actually finished is 93 ms what also seems fine.
The interesting thing is that fetch from node-fetch throws the same error as error thrown by original fetch when vpn disabled and notebook completely offline.
fetch from node-fetch returns control after 120 seconds. Original fetch returns control after 10 seconds and then hangs in the background 110 seconds. Looks very suspicious (120 == 110 + 10).
Contributor guide
First steps
- Read the whole issue, then the project's contributing guide.
- Comment on the issue to say you are picking it up — it saves two people doing the same work.
- Fork the repository and make your change on a branch.
- Open a pull request that references the issue number.
Research direction
Reproduce the behavior with the network and WireGuard steps in index.js, then use package.json to run the npm start command. Trace the fetch failure and the process shutdown behavior in the affected networking path. Done means the script exits promptly after the ConnectTimeoutError, without the additional hang.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- javascript, node.js
- Domain
- networking
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Mostly clear
- Newbie friendliness
- 42/100