Something wrong with keep-alive agent sockets - networking hangs on OS level

[andrzej-woof]

Steps to Reproduce:

Following test

import { Selector } from 'testcafe';

fixture('Agent sockets')
    .page('https://videojs.github.io/autoplay-tests/videojs/attr/autoplay.html?AHKKKVR=KUSIK');

for(let i=0; i < 1000; i++) {
    test(`Test ${i}`, async (t) => {
        await t
            .expect(Selector('video').exists)
            .ok();
    });
}

2. to get some logging modify contents of node_modules/testcafe-hammerhead/lib/request-pipeline/destination-request/agent.js adding the following at the end of file

setInterval(() => {
  const result = [`--- DEBUG ${new Date()} ---`];
  let total = 0;
  for(const [key, agent] of Object.entries(agents)) {
    if(!agent.instance) {
      continue;
    }
    for(const [server, sockets] of Object.entries(agent.instance.sockets)) {
      total = total + sockets.length;
      result.push(`${server} = ${sockets.length}`);
    }
  }
  result.push(`--- Total sockets held = ${total} ---`);
  console.log(result.join('\n'));
  // resetKeepAliveConnections(); // uncomment this later
}, 5000);

3. Execute this command: ./node_modules/.bin/testcafe chrome:headless index.js -c 10
4. Wait for networking being dead - see end of my log:

$ ./node_modules/.bin/testcafe chrome:headless index.js -c 10
⠹
--- DEBUG Wed Oct 02 2019 20:33:29 GMT+0200 (Central European Summer Time) ---
 Running tests in:
 - HeadlessChrome 77.0.3865 / Mac OS X 10.14.5

 Agent sockets
--- DEBUG Wed Oct 02 2019 20:33:34 GMT+0200 (Central European Summer Time) ---
vjs.zencdn.net:443::::::::false:::::::auto::: = 12
--- Total sockets held = 12 ---
 ✓ Test 0
 ✓ Test 1
 ✓ Test 2
 ✓ Test 3
 ✓ Test 4
 ✓ Test 5
 ✓ Test 6
 ✓ Test 7
 ✓ Test 8
 ✓ Test 9
 ✓ Test 10
 ✓ Test 11
 ✓ Test 12
--- DEBUG Wed Oct 02 2019 20:33:39 GMT+0200 (Central European Summer Time) ---
vjs.zencdn.net:443::::::::false:::::::auto::: = 51
--- Total sockets held = 51 ---
 ✓ Test 13
 ✓ Test 14
 ✓ Test 15
 ✓ Test 16
 ✓ Test 17
 ✓ Test 18
 ✓ Test 19
 ✓ Test 20
 ✓ Test 21
 ✓ Test 22
 ✓ Test 23
 ✓ Test 24
 ✓ Test 25
 ✓ Test 26
 ✓ Test 27
 ✓ Test 28
 ✓ Test 29
 ✓ Test 30
 ✓ Test 31
--- DEBUG Wed Oct 02 2019 20:33:44 GMT+0200 (Central European Summer Time) ---
vjs.zencdn.net:443::::::::false:::::::auto::: = 91
--- Total sockets held = 91 ---
 ✓ Test 32
 ✓ Test 33
 ✓ Test 34
 ✓ Test 35
 ✓ Test 36
 ✓ Test 37
 ✓ Test 38
 ✓ Test 39
 ✓ Test 40
 ✓ Test 41
 ✓ Test 42
 ✓ Test 43
 ✓ Test 44
 ✓ Test 45
 ✓ Test 46
 ✓ Test 47
 ✓ Test 48
 ✓ Test 49
 ✓ Test 50
 ✓ Test 51
 ✓ Test 52
 ✓ Test 53
--- DEBUG Wed Oct 02 2019 20:33:49 GMT+0200 (Central European Summer Time) ---
vjs.zencdn.net:443::::::::false:::::::auto::: = 130
--- Total sockets held = 130 ---
 ✓ Test 54
 ✓ Test 55
 ✓ Test 56
 ✓ Test 57
 ✓ Test 58
 ✓ Test 59
 ✓ Test 60
 ✓ Test 61
 ✓ Test 62
 ✓ Test 63
 ✓ Test 64
 ✓ Test 65
 ✓ Test 66
 ✓ Test 67
 ✓ Test 68
 ✓ Test 69
 ✓ Test 70
 ✓ Test 71
 ✓ Test 72
--- DEBUG Wed Oct 02 2019 20:33:54 GMT+0200 (Central European Summer Time) ---
vjs.zencdn.net:443::::::::false:::::::auto::: = 168
videojs.github.io:443::::::::false:::::::auto::: = 1
--- Total sockets held = 169 ---
 ✓ Test 73
 ✓ Test 74
 ✓ Test 75
 ✓ Test 76
 ✓ Test 77
 ✓ Test 78
 ✓ Test 79
 ✓ Test 80
 ✓ Test 81
 ✓ Test 82
 ✓ Test 83
 ✓ Test 84
 ✓ Test 85
 ✓ Test 86
 ✓ Test 87
--- DEBUG Wed Oct 02 2019 20:33:59 GMT+0200 (Central European Summer Time) ---
vjs.zencdn.net:443::::::::false:::::::auto::: = 192
videojs.github.io:443::::::::false:::::::auto::: = 4
--- Total sockets held = 196 ---
--- DEBUG Wed Oct 02 2019 20:34:04 GMT+0200 (Central European Summer Time) ---
vjs.zencdn.net:443::::::::false:::::::auto::: = 192
videojs.github.io:443::::::::false:::::::auto::: = 4
--- Total sockets held = 196 ---
--- DEBUG Wed Oct 02 2019 20:34:09 GMT+0200 (Central European Summer Time) ---
vjs.zencdn.net:443::::::::false:::::::auto::: = 192
videojs.github.io:443::::::::false:::::::auto::: = 4
--- Total sockets held = 196 ---
--- DEBUG Wed Oct 02 2019 20:34:14 GMT+0200 (Central European Summer Time) ---
vjs.zencdn.net:443::::::::false:::::::auto::: = 192
videojs.github.io:443::::::::false:::::::auto::: = 4
--- Total sockets held = 196 ---
--- DEBUG Wed Oct 02 2019 20:34:19 GMT+0200 (Central European Summer Time) ---
vjs.zencdn.net:443::::::::false:::::::auto::: = 192
videojs.github.io:443::::::::false:::::::auto::: = 1
--- Total sockets held = 193 ---
--- DEBUG Wed Oct 02 2019 20:34:24 GMT+0200 (Central European Summer Time) ---
vjs.zencdn.net:443::::::::false:::::::auto::: = 185
--- Total sockets held = 185 ---
--- DEBUG Wed Oct 02 2019 20:34:29 GMT+0200 (Central European Summer Time) ---
vjs.zencdn.net:443::::::::false:::::::auto::: = 185
--- Total sockets held = 185 ---
--- DEBUG Wed Oct 02 2019 20:34:34 GMT+0200 (Central European Summer Time) ---
vjs.zencdn.net:443::::::::false:::::::auto::: = 185
--- Total sockets held = 185 ---
--- DEBUG Wed Oct 02 2019 20:34:39 GMT+0200 (Central European Summer Time) ---
vjs.zencdn.net:443::::::::false:::::::auto::: = 185
--- Total sockets held = 185 ---
--- DEBUG Wed Oct 02 2019 20:34:44 GMT+0200 (Central European Summer Time) ---
vjs.zencdn.net:443::::::::false:::::::auto::: = 185
--- Total sockets held = 185 ---
--- DEBUG Wed Oct 02 2019 20:34:49 GMT+0200 (Central European Summer Time) ---
vjs.zencdn.net:443::::::::false:::::::auto::: = 182
--- Total sockets held = 182 ---
--- DEBUG Wed Oct 02 2019 20:34:54 GMT+0200 (Central European Summer Time) ---
vjs.zencdn.net:443::::::::false:::::::auto::: = 182
--- Total sockets held = 182 ---
--- DEBUG Wed Oct 02 2019 20:34:59 GMT+0200 (Central European Summer Time) ---
vjs.zencdn.net:443::::::::false:::::::auto::: = 182
--- Total sockets held = 182 ---
--- DEBUG Wed Oct 02 2019 20:35:04 GMT+0200 (Central European Summer Time) ---
vjs.zencdn.net:443::::::::false:::::::auto::: = 182
--- Total sockets held = 182 ---
--- DEBUG Wed Oct 02 2019 20:35:09 GMT+0200 (Central European Summer Time) ---
vjs.zencdn.net:443::::::::false:::::::auto::: = 182
--- Total sockets held = 182 ---
--- DEBUG Wed Oct 02 2019 20:35:14 GMT+0200 (Central European Summer Time) ---
vjs.zencdn.net:443::::::::false:::::::auto::: = 180
--- Total sockets held = 180 ---
--- DEBUG Wed Oct 02 2019 20:35:19 GMT+0200 (Central European Summer Time) ---
vjs.zencdn.net:443::::::::false:::::::auto::: = 180
--- Total sockets held = 180 ---
--- DEBUG Wed Oct 02 2019 20:35:24 GMT+0200 (Central European Summer Time) ---
vjs.zencdn.net:443::::::::false:::::::auto::: = 180
--- Total sockets held = 180 ---
--- DEBUG Wed Oct 02 2019 20:35:29 GMT+0200 (Central European Summer Time) ---
vjs.zencdn.net:443::::::::false:::::::auto::: = 180
--- Total sockets held = 180 ---
--- DEBUG Wed Oct 02 2019 20:35:34 GMT+0200 (Central European Summer Time) ---
vjs.zencdn.net:443::::::::false:::::::auto::: = 180
--- Total sockets held = 180 ---
--- DEBUG Wed Oct 02 2019 20:35:39 GMT+0200 (Central European Summer Time) ---
vjs.zencdn.net:443::::::::false:::::::auto::: = 180
--- Total sockets held = 180 ---
--- DEBUG Wed Oct 02 2019 20:35:44 GMT+0200 (Central European Summer Time) ---
vjs.zencdn.net:443::::::::false:::::::auto::: = 180
--- Total sockets held = 180 ---
^C%
# sockets are still held, wifi got auto-disconnected, networking died in the entire OS
# killed process here with Ctrl+C and everything went back to normal

5. Now go back to agent.js and uncomment the line in interval function with resetKeepAliveConnections()
6. Launch tests again... besides some failures (due to executing agent.destroy() in the middle of test) all of 1000 tests were executed and most of them passed (see end of my log)

 ✓ Test 957
--- DEBUG Wed Oct 02 2019 20:40:45 GMT+0200 (Central European Summer Time) ---
vjs.zencdn.net:443::::::::false:::::::auto::: = 53
--- Total sockets held = 53 ---
 ✓ Test 958
 ✓ Test 959
 ✓ Test 960
 ✓ Test 961
 ✓ Test 962
 ✓ Test 963
 ✓ Test 964
 ✖ Test 965

   1) A JavaScript error occurred on "https://videojs.github.io/autoplay-tests/videojs/attr/autoplay.html?AHKKKVR=XHFVX".
      Repeat test actions in the browser and check the console for errors.
      If you see this error, it means that the tested website caused it. You can fix it or disable tracking JavaScript errors in TestCafe. To do the latter, enable the "--skip-js-errors" option.
      If this error does not occur, please write a new issue at:
      "https://github.com/DevExpress/testcafe/issues/new?template=bug-report.md".

      JavaScript error details:
      SyntaxError: Unexpected end of input

      Browser: HeadlessChrome 77.0.3865 / Mac OS X 10.14.5


 ✖ Test 966

   1) A JavaScript error occurred on "https://videojs.github.io/autoplay-tests/videojs/attr/autoplay.html?AHKKKVR=XHFVX".
      Repeat test actions in the browser and check the console for errors.
      If you see this error, it means that the tested website caused it. You can fix it or disable tracking JavaScript errors in TestCafe. To do the latter, enable the "--skip-js-errors" option.
      If this error does not occur, please write a new issue at:
      "https://github.com/DevExpress/testcafe/issues/new?template=bug-report.md".

      JavaScript error details:
      SyntaxError: Unexpected end of input

      Browser: HeadlessChrome 77.0.3865 / Mac OS X 10.14.5


 ✓ Test 967
 ✓ Test 968
 ✓ Test 969
 ✓ Test 970
 ✓ Test 971
 ✓ Test 972
 ✓ Test 973
 ✓ Test 974
 ✓ Test 975
 ✓ Test 976
 ✓ Test 977
--- DEBUG Wed Oct 02 2019 20:40:50 GMT+0200 (Central European Summer Time) ---
vjs.zencdn.net:443::::::::false:::::::auto::: = 48
--- Total sockets held = 48 ---
 ✓ Test 978
 ✓ Test 979
 ✓ Test 980
 ✓ Test 981
 ✓ Test 982
 ✓ Test 983
 ✓ Test 984
 ✓ Test 985
 ✓ Test 986
 ✓ Test 987
 ✖ Test 988

   1) A JavaScript error occurred on "https://videojs.github.io/autoplay-tests/videojs/attr/autoplay.html?AHKKKVR=XHFVX".
      Repeat test actions in the browser and check the console for errors.
      If you see this error, it means that the tested website caused it. You can fix it or disable tracking JavaScript errors in TestCafe. To do the latter, enable the "--skip-js-errors" option.
      If this error does not occur, please write a new issue at:
      "https://github.com/DevExpress/testcafe/issues/new?template=bug-report.md".

      JavaScript error details:
      SyntaxError: Unexpected end of input

      Browser: HeadlessChrome 77.0.3865 / Mac OS X 10.14.5


 ✖ Test 989

   1) A JavaScript error occurred on "https://videojs.github.io/autoplay-tests/videojs/attr/autoplay.html?AHKKKVR=XHFVX".
      Repeat test actions in the browser and check the console for errors.
      If you see this error, it means that the tested website caused it. You can fix it or disable tracking JavaScript errors in TestCafe. To do the latter, enable the "--skip-js-errors" option.
      If this error does not occur, please write a new issue at:
      "https://github.com/DevExpress/testcafe/issues/new?template=bug-report.md".

      JavaScript error details:
      SyntaxError: Unexpected end of input

      Browser: HeadlessChrome 77.0.3865 / Mac OS X 10.14.5


 ✖ Test 990

   1) A JavaScript error occurred on "https://videojs.github.io/autoplay-tests/videojs/attr/autoplay.html?AHKKKVR=XHFVX".
      Repeat test actions in the browser and check the console for errors.
      If you see this error, it means that the tested website caused it. You can fix it or disable tracking JavaScript errors in TestCafe. To do the latter, enable the "--skip-js-errors" option.
      If this error does not occur, please write a new issue at:
      "https://github.com/DevExpress/testcafe/issues/new?template=bug-report.md".

      JavaScript error details:
      SyntaxError: Unexpected end of input

      Browser: HeadlessChrome 77.0.3865 / Mac OS X 10.14.5


 ✓ Test 991
 ✓ Test 992
 ✓ Test 993
 ✓ Test 994
 ✓ Test 995
 ✓ Test 996
 ✓ Test 997
 ✓ Test 998
 ✓ Test 999


 47/1000 failed (3m 41s)
--- DEBUG Wed Oct 02 2019 20:40:55 GMT+0200 (Central European Summer Time) ---
vjs.zencdn.net:443::::::::false:::::::auto::: = 26
--- Total sockets held = 26 ---

Your Environment details:

• node.js version: v10.16.3
• browser name and version: Version 76.0.3809.132 (Official Build) (64-bit)
• platform and version: macOS 10.14.5 (18F132) / Darwin 18.6.0
• other: same issue occurred with running on CI in Ubuntu based docker image, happens also with lower concurrency levels but takes more time to bump into the issue

I guess it's the cause of what was reported here DevExpress/testcafe#2864 and probably many other issues with hanging browser.
My blind guess would be it might have something to do with HTTP 206 partial content responses 🤷‍♀

[LavrovArtem]

Thank you for the provided details. I've reproduced the error. We need time to research this problem.

[andrzej-woof]

As a hint, I've injected into your code socket.setTimeout and socket.on('timeout', () => socket.destroy); for all these agent.instance.sockets that are created. With some tuning this seems to at least solve my issue with accumulation of open sockets during long running tests.
Still doesn't solve problem with opening many of them too fast - but I think it would be good practice to handle timeouts on these sockets.

[lock]

This thread has been automatically locked since it is closed and there has not been any recent activity. Please open a new issue for related bugs or feature requests. We recommend you ask TestCafe API, usage and configuration inquiries on StackOverflow.