node 🚀 - Investigate flaky test-http2-large-file

I can only find one instance of this in the last 100 CI runs

Reason     sequential/test-http2-large-file
Type       JS_TEST_FAILURE
Failed PR  1 (#22269)
Appeared   test-rackspace-win2008r2-x64-3
Last CI    https://ci.nodejs.org/job/node-test-pull-request/16450/

joyeecheung on 15 Aug 2018

By the way I think I've seen this on my local Windows machine before..

joyeecheung on 15 Aug 2018

Yep, it's flaky but only extremely rarely.

jasnell on 15 Aug 2018

Spotted: https://ci.nodejs.org/job/node-test-binary-windows/19269/COMPILED_BY=vs2017,RUNNER=win2008r2-vs2017,RUN_SUBSET=3/console

Stress test: https://ci.nodejs.org/job/node-stress-single-test/1992/

refack on 17 Aug 2018

Flaky:

1000   OK: 947   NOT OK: 53   TOTAL: 1000

refack on 17 Aug 2018

https://ci.nodejs.org/job/node-test-binary-windows/19625/COMPILED_BY=vs2017,RUNNER=win2008r2-vs2017,RUN_SUBSET=2/console

03:45:21 not ok 578 sequential/test-http2-large-file
03:45:21   ---
03:45:21   duration_ms: 2.109
03:45:21   severity: fail
03:45:21   exitcode: 1
03:45:21   stack: |-
03:45:21     events.js:167
03:45:21           throw er; // Unhandled 'error' event
03:45:21           ^
03:45:21     
03:45:21     Error: read ECONNRESET
03:45:21         at TCP.onread (net.js:661:25)
03:45:21     Emitted 'error' event at:
03:45:21         at emitErrorNT (internal/streams/destroy.js:82:8)
03:45:21         at emitErrorAndCloseNT (internal/streams/destroy.js:50:3)
03:45:21         at process._tickCallback (internal/process/next_tick.js:63:19)
03:45:21   ...

Trott on 29 Aug 2018

Is it only happening on win2008r2? Because provider can make a difference, the one above is rackspace.

Trott on 29 Aug 2018

Is it only happening on win2008r2? Because provider can make a difference, the one above is rackspace.

I want to say that I run the stress on an Azure machine, but I'm not sure.

refack on 29 Aug 2018

Again on win2008r2 and a rackspace host (test-rackspace-win2008r2-x64-5).

https://ci.nodejs.org/job/node-test-binary-windows/19897/COMPILED_BY=vs2017,RUNNER=win2008r2-vs2017,RUN_SUBSET=0/console

01:33:41 not ok 580 sequential/test-http2-large-file
01:33:41   ---
01:33:41   duration_ms: 2.73
01:33:41   severity: fail
01:33:41   exitcode: 1
01:33:41   stack: |-
01:33:41     events.js:167
01:33:41           throw er; // Unhandled 'error' event
01:33:41           ^
01:33:41     
01:33:41     Error: read ECONNRESET
01:33:41         at TCP.onStreamRead (internal/stream_base_commons.js:112:27)
01:33:41     Emitted 'error' event at:
01:33:41         at emitErrorNT (internal/streams/destroy.js:82:8)
01:33:41         at emitErrorAndCloseNT (internal/streams/destroy.js:50:3)
01:33:41         at process._tickCallback (internal/process/next_tick.js:63:19)
01:33:41   ...

Trott on 10 Sep 2018

Once again on win2008r2, and again it was rackspace (test-rackspace-win2008r2-x64-6).

https://ci.nodejs.org/job/node-test-binary-windows/19974/COMPILED_BY=vs2017,RUNNER=win2008r2-vs2017,RUN_SUBSET=2/console

21:20:53 not ok 581 sequential/test-http2-large-file
21:20:53   ---
21:20:53   duration_ms: 1.796
21:20:53   severity: fail
21:20:53   exitcode: 1
21:20:53   stack: |-
21:20:53     events.js:167
21:20:53           throw er; // Unhandled 'error' event
21:20:53           ^
21:20:53     
21:20:53     Error: read ECONNRESET
21:20:53         at TCP.onStreamRead (internal/stream_base_commons.js:112:27)
21:20:53     Emitted 'error' event at:
21:20:53         at emitErrorNT (internal/streams/destroy.js:82:8)
21:20:53         at emitErrorAndCloseNT (internal/streams/destroy.js:50:3)
21:20:53         at process._tickCallback (internal/process/next_tick.js:63:19)
21:20:53   ...

Trott on 15 Sep 2018

@nodejs/platform-windows

Trott on 15 Sep 2018

I could be wrong, but the frequency with which this one occurs seems to be increasing...

Once again, it's on win2008r2--seems to be the only variant affected, at least on CI--and once again it's on one of the Rackspace hosts (test-rackspace-win2008r2-x64-4). I've never seen this on one of the Azure hosts. (I know there are differences in terms of memory and/or CPU, and probably other things. /ping @nodejs/build )

https://ci.nodejs.org/job/node-test-binary-windows/19980/COMPILED_BY=vs2017,RUNNER=win2008r2-vs2017,RUN_SUBSET=2/console

00:00:12 not ok 581 sequential/test-http2-large-file
00:00:12   ---
00:00:12   duration_ms: 1.698
00:00:12   severity: fail
00:00:12   exitcode: 1
00:00:12   stack: |-
00:00:12     events.js:167
00:00:12           throw er; // Unhandled 'error' event
00:00:12           ^
00:00:12     
00:00:12     Error: read ECONNRESET
00:00:12         at TCP.onStreamRead (internal/stream_base_commons.js:112:27)
00:00:12     Emitted 'error' event at:
00:00:12         at emitErrorNT (internal/streams/destroy.js:82:8)
00:00:12         at emitErrorAndCloseNT (internal/streams/destroy.js:50:3)
00:00:12         at process._tickCallback (internal/process/next_tick.js:63:19)
00:00:12   ...

Trott on 15 Sep 2018

Bug in http2? @nodejs/http2

Trott on 15 Sep 2018

Continues to seem to only manifest on win2008r2 Rackspace hosts. This one is test-rackspace-win2008r2-x64-6.

https://ci.nodejs.org/job/node-test-binary-windows/20005/COMPILED_BY=vs2017,RUNNER=win2008r2-vs2017,RUN_SUBSET=3/console

16:05:09 not ok 581 sequential/test-http2-large-file
16:05:09   ---
16:05:09   duration_ms: 2.96
16:05:09   severity: fail
16:05:09   exitcode: 1
16:05:09   stack: |-
16:05:09     events.js:167
16:05:09           throw er; // Unhandled 'error' event
16:05:09           ^
16:05:09     
16:05:09     Error: read ECONNRESET
16:05:09         at TCP.onStreamRead (internal/stream_base_commons.js:112:27)
16:05:09     Emitted 'error' event at:
16:05:09         at emitErrorNT (internal/streams/destroy.js:82:8)
16:05:09         at emitErrorAndCloseNT (internal/streams/destroy.js:50:3)
16:05:09         at process._tickCallback (internal/process/next_tick.js:63:19)
16:05:09   ...

Trott on 17 Sep 2018

Continues to happen only on rackspace win2008r2 hosts.
¯\_(ツ)_/¯

https://ci.nodejs.org/job/node-test-binary-windows/20167/COMPILED_BY=vs2017,RUNNER=win2008r2-vs2017,RUN_SUBSET=1/console

00:54:28 not ok 583 sequential/test-http2-large-file # TODO : Fix flaky test
00:54:28   ---
00:54:28   duration_ms: 3.534
00:54:28   severity: flaky
00:54:28   exitcode: 1
00:54:28   stack: |-
00:54:28     events.js:167
00:54:28           throw er; // Unhandled 'error' event
00:54:28           ^
00:54:28     
00:54:28     Error: read ECONNRESET
00:54:28         at TCP.onStreamRead (internal/stream_base_commons.js:112:27)
00:54:28     Emitted 'error' event at:
00:54:28         at emitErrorNT (internal/streams/destroy.js:82:8)
00:54:28         at emitErrorAndCloseNT (internal/streams/destroy.js:50:3)
00:54:28         at process._tickCallback (internal/process/next_tick.js:63:19)
00:54:28   ...

Trott on 21 Sep 2018

https://ci.nodejs.org/job/node-test-binary-windows/21052/COMPILED_BY=vs2017,RUNNER=win2008r2-vs2017,RUN_SUBSET=1/console on test-rackspace-win2008r2-x64-5

00:52:40 not ok 592 sequential/test-http2-large-file # TODO : Fix flaky test
00:52:40   ---
00:52:40   duration_ms: 3.305
00:52:40   severity: flaky
00:52:40   exitcode: 1
00:52:40   stack: |-
00:52:40     events.js:167
00:52:40           throw er; // Unhandled 'error' event
00:52:40           ^
00:52:40     
00:52:40     Error: read ECONNRESET
00:52:40         at TCP.onStreamRead (internal/stream_base_commons.js:121:27)
00:52:40     Emitted 'error' event at:
00:52:40         at emitErrorNT (internal/streams/destroy.js:82:8)
00:52:40         at emitErrorAndCloseNT (internal/streams/destroy.js:50:3)
00:52:40         at process.internalTickCallback (internal/process/next_tick.js:72:19)
00:52:40   ...

Trott on 26 Oct 2018

https://ci.nodejs.org/job/node-test-binary-windows/21260/COMPILED_BY=vs2017,RUNNER=win2008r2-vs2017,RUN_SUBSET=3/console on test-rackspace-win2008r2-x64-6

00:53:46 not ok 593 sequential/test-http2-large-file # TODO : Fix flaky test
00:53:46   ---
00:53:46   duration_ms: 2.708
00:53:46   severity: flaky
00:53:46   exitcode: 1
00:53:46   stack: |-
00:53:46     events.js:167
00:53:46           throw er; // Unhandled 'error' event
00:53:46           ^
00:53:46     
00:53:46     Error: read ECONNRESET
00:53:46         at TCP.onStreamRead (internal/stream_base_commons.js:139:27)
00:53:46     Emitted 'error' event at:
00:53:46         at emitErrorNT (internal/streams/destroy.js:82:8)
00:53:46         at emitErrorAndCloseNT (internal/streams/destroy.js:50:3)
00:53:46         at process.internalTickCallback (internal/process/next_tick.js:72:19)
00:53:46   ...

Trott on 5 Nov 2018

@nodejs/build Anything possibly significant about this only happening on Rackspace hosts and not on Azure hosts?

Trott on 5 Nov 2018

So first we see only WS2008R2...
I've checked the above machines and it seems like the rackspace one are more robust, with 8GB memory and 8 cores. While the Azure ones are 3.5GB with 1 core. So it's probably a race issue.

refack on 5 Nov 2018

👍1

Anyone have any ideas/suggestions for troubleshooting?

Trott on 14 Nov 2018

I'll give it a spin.

refack on 14 Nov 2018

So the issue is highly reproducible on test-rackspace-win2008r2-x64-6, with:

python tools\test.py --repeat 100 sequential/test-http2-large-file

(getting > 50% fails). But it's at the end of an async call so it's hard to say if it's a system error or a race in the test.

This is a core dump: node-bug-22327.zip

This is the output:

Path: sequential/test-http2-large-file
events.js:167
      throw er; // Unhandled 'error' event
      ^

Error: read ECONNRESET
    at TCP.onStreamRead (internal/stream_base_commons.js:139:27)
Emitted 'error' event at:
    at emitErrorNT (internal/streams/destroy.js:82:8)
    at emitErrorAndCloseNT (internal/streams/destroy.js:50:3)
    at process.internalTickCallback (internal/process/next_tick.js:72:19)
Command: C:\workspace\node-compile-windows\Release\node.exe C:\workspace\node-compile-windows\test\sequential\test-http2-large-file.js

And the real error is WSAECONNRESET
This is the stack:

node.exe!uv_translate_sys_error(int sys_errno) Line 94
    at c:\workspace\node-compile-windows\deps\uv\src\win\error.c(94)
node.exe!uv_process_tcp_read_req(uv_loop_s * loop, uv_tcp_s * handle, uv_req_s * req) Line 970
    at c:\workspace\node-compile-windows\deps\uv\src\win\tcp.c(970)
node.exe!uv_process_reqs(uv_loop_s * loop) Line 159
    at c:\workspace\node-compile-windows\deps\uv\src\win\req-inl.h(159)
node.exe!uv_run(uv_loop_s * loop, <unnamed-enum-UV_RUN_DEFAULT> mode) Line 520
    at c:\workspace\node-compile-windows\deps\uv\src\win\core.c(520)
node.exe!node::Start(v8::Isolate * isolate, node::IsolateData * isolate_data, const std::vector<std::basic_string<char,std::char_traits<char>,std::allocator<char> >,std::allocator<std::basic_string<char,std::char_traits<char>,std::allocator<char> > > > & args, const std::vector<std::basic_string<char,std::char_traits<char>,std::allocator<char> >,std::allocator<std::basic_string<char,std::char_traits<char>,std::allocator<char> > > > & exec_args) Line 2526
    at c:\workspace\node-compile-windows\src\node.cc(2526)
node.exe!node::Start(uv_loop_s * event_loop, const std::vector<std::basic_string<char,std::char_traits<char>,std::allocator<char> >,std::allocator<std::basic_string<char,std::char_traits<char>,std::allocator<char> > > > & args, const std::vector<std::basic_string<char,std::char_traits<char>,std::allocator<char> >,std::allocator<std::basic_string<char,std::char_traits<char>,std::allocator<char> > > > & exec_args) Line 2628
    at c:\workspace\node-compile-windows\src\node.cc(2628)
node.exe!node::Start(int argc, char * * argv) Line 2689
    at c:\workspace\node-compile-windows\src\node.cc(2689)
node.exe!wmain(int argc, wchar_t * * wargv) Line 72
    at c:\workspace\node-compile-windows\src\node_main.cc(72)
[Inline Frame] node.exe!invoke_main() Line 90
    at d:\agent\_work\2\s\src\vctools\crt\vcstartup\src\startup\exe_common.inl(90)
node.exe!__scrt_common_main_seh() Line 288
    at d:\agent\_work\2\s\src\vctools\crt\vcstartup\src\startup\exe_common.inl(288)
kernel32.dll!BaseThreadInitThunk() + 13 bytes
ntdll.dll!RtlUserThreadStart() + 29 bytes

This is the locals content of the uv_process_tcp_read_req frame:

| Name | Value | Type
-- | -- | -- | --
◢ | handle | 0x000000000270e370 {data=0x000000000270e2d0 loop=0x00000001412b58d0 {node.exe!uv_loop_s default_loop_struct} {...} ...} | uv_tcp_s *
| data | 0x000000000270e2d0 | void *
| ▶ loop | 0x00000001412b58d0 {node.exe!uv_loop_s default_loop_struct} {data=0x0000000000000000 active_handles=...} | uv_loop_s *
| type | UV_TCP (12) |
| close_cb | 0x0000000000000000 | void()(uv_handle_s *)
| ▶ handle_queue | 0x000000000270e390 {0x00000000026c2438, 0x00000000026ba5e0} | void *[2]
| ▶ u | {fd=-1 reserved=0x000000000270e3a0 {0x00000000ffffffff, 0x00000000038b1200, 0x000000000270e308, 0x000000000270e308} } |
| ▶ endgame_next | 0x000000000270e380 {data=0x000000000000000c loop=0x0000000000000000 type=40641592 ...} | uv_handle_s *
| flags | 21422216 | unsigned int
| write_queue_size | 0 | unsigned __int64
| alloc_cb | 0x000000013f4b7620 {node.exe!void (uv_handle_s *, unsigned __int64, uv_buf_t *)::(uv_handle_s *, unsigned __int64, uv_buf_t *)} | void()(uv_handle_s , unsigned __int64, uv_buf_t *)
| read_cb | 0x000000013f4b7580 {node.exe!::(uv_stream_s *, __int64, const uv_buf_t *)} | void()(uv_stream_s , __int64, const uv_buf_t *)
| reqs_pending | 1 | unsigned int
| activecnt | 0 | int
| ◢ read_req | {data=0x000000000270e370 type=UV_READ (14) reserved=0x000000000270e400 {0x000000000270e308, 0x00000000038b2268, ...} ...} | uv_read_s
| data | 0x000000000270e370 | void *
| type | UV_READ (14) | uv_req_type
| ◢ reserved | 0x000000000270e400 {0x000000000270e308, 0x00000000038b2268, 0x0000000000000000, 0x000000000270e308, ...} | void *[6]
| [0] | 0x000000000270e308 | void *
| [1] | 0x00000000038b2268 | void *
| [2] | 0x0000000000000000 | void *
| [3] | 0x000000000270e308 | void *
| [4] | 0x0000000000000000 | void *
| [5] | 0x0000000000000000 | void *
| ▶ u | {io={overlapped={Internal=18446744071562536773 InternalHigh=0 Offset=0 ...} queued_bytes=18446744073709551615 } } | uv_read_s::
| ◢ next_req | 0x00000000026e36b0 {data=0x000000000268a830 type=UV_ACCEPT (10) reserved=0x00000000026e36c0 {0x0000000000512250, ...} ...} | uv_req_s *
| data | 0x000000000268a830 | void *
| type | UV_ACCEPT (10) | uv_req_type
| ▶ reserved | 0x00000000026e36c0 {0x0000000000512250, 0x00000000026e0828, 0x0000000000000000, 0x00000000026e36c0, ...} | void *[6]
| ▶ u | {io={overlapped={Internal=3221225760 InternalHigh=0 Offset=0 ...} queued_bytes=0 } } | uv_req_s::
| ▶ next_req | 0x00000000026e3500 {data=0x000000000268a830 type=UV_ACCEPT (10) reserved=0x00000000026e3510 {0x00000000026e34e0, ...} ...} | uv_req_s *
| event_handle | 0x0000000000000000 | void *
| wait_handle | 0xffffffffffffffff | void *
| ◢ stream | {conn={write_reqs_pending=0 shutdown_req=0x0000000000000000 } serv={connection_cb=0x0000000000000000 } } |
| ▶ conn | {write_reqs_pending=0 shutdown_req=0x0000000000000000 } |
| ▶ serv | {connection_cb=0x0000000000000000 } |
| socket | 508 | unsigned __int64
| delayed_error | 0 | int
| ◢ tcp | {serv={accept_reqs=0x0000000000000000 processed_accepts=0 pending_accepts=0x0000000000000000 ...} ...} |
| ◢ serv | {accept_reqs=0x0000000000000000 processed_accepts=0 pending_accepts=0x0000000000000000 ...} |
| ▶ accept_reqs | 0x0000000000000000 | uv_tcp_accept_s *
| processed_accepts | 0 | unsigned int
| ▶ pending_accepts | 0x0000000000000000 | uv_tcp_accept_s *
| func_acceptex | 0x0000000000000000 | int()(unsigned __int64, unsigned __int64, void , unsigned long, unsigned long, unsigned long, unsigned long *, _OVERLAPPED *)
| ◢ conn | {read_buffer={len=0 base=0x0000000000000000 } func_connectex=0x0000000000000000 } |
| ▶ read_buffer | {len=0 base=0x0000000000000000 } | uv_buf_t
| func_connectex | 0x0000000000000000 | int()(unsigned __int64, const sockaddr , int, void *, unsigned long, unsigned long *, _OVERLAPPED *)
| handle->read_cb | 0x000000013f4b7580 {node.exe!::(uv_stream_s *, __int64, const uv_buf_t *)} | void()(uv_stream_s *, __int64, const uv_buf_t *)

refack on 15 Nov 2018

❤1

/CC @nodejs/streams @nodejs/http2

refack on 15 Nov 2018

Just in case the lack of activity here is misleading, this is still an issue. https://github.com/nodejs/node/issues/22327#issuecomment-438880432 seems to be the place with the most relevant information although I suppose there's a chance it may be out of date.

Here's a failure from the last node-daily-master run:

https://ci.nodejs.org/job/node-test-binary-windows/22925/COMPILED_BY=vs2017,RUNNER=win2008r2-vs2017,RUN_SUBSET=0/console

test-rackspace-win2008r2-x64-5

00:57:13 not ok 604 sequential/test-http2-large-file # TODO : Fix flaky test
00:57:13   ---
00:57:13   duration_ms: 3.706
00:57:13   severity: flaky
00:57:13   exitcode: 1
00:57:13   stack: |-
00:57:13     events.js:173
00:57:13           throw er; // Unhandled 'error' event
00:57:13           ^
00:57:13     
00:57:13     Error: read ECONNRESET
00:57:13         at TCP.onStreamRead (internal/stream_base_commons.js:162:27)
00:57:13     Emitted 'error' event at:
00:57:13         at emitErrorNT (internal/streams/destroy.js:82:8)
00:57:13         at emitErrorAndCloseNT (internal/streams/destroy.js:50:3)
00:57:13         at processTicksAndRejections (internal/process/next_tick.js:76:17)
00:57:13   ...

Trott on 8 Jan 2019

Still totally a thing.

https://ci.nodejs.org/job/node-test-binary-windows/23735/COMPILED_BY=vs2017,RUNNER=win2008r2-vs2017,RUN_SUBSET=3/console

test-rackspace-win2008r2-x64-3

01:10:29 not ok 611 sequential/test-http2-large-file # TODO : Fix flaky test
01:10:29   ---
01:10:29   duration_ms: 2.529
01:10:29   severity: flaky
01:10:29   exitcode: 1
01:10:29   stack: |-
01:10:29     events.js:173
01:10:29           throw er; // Unhandled 'error' event
01:10:29           ^
01:10:29     
01:10:29     Error: read ECONNRESET
01:10:29         at TCP.onStreamRead (internal/stream_base_commons.js:173:27)
01:10:29     Emitted 'error' event at:
01:10:29         at emitErrorNT (internal/streams/destroy.js:82:8)
01:10:29         at emitErrorAndCloseNT (internal/streams/destroy.js:50:3)
01:10:29         at processTicksAndRejections (internal/process/next_tick.js:76:17)
01:10:29   ...

Trott on 13 Feb 2019

And again today...

https://ci.nodejs.org/job/node-test-binary-windows/23755/COMPILED_BY=vs2017,RUNNER=win2008r2-vs2017,RUN_SUBSET=0/console

test-rackspace-win2008r2-x64-5

00:57:53 not ok 612 sequential/test-http2-large-file # TODO : Fix flaky test
00:57:53   ---
00:57:53   duration_ms: 3.606
00:57:53   severity: flaky
00:57:53   exitcode: 1
00:57:53   stack: |-
00:57:53     events.js:173
00:57:53           throw er; // Unhandled 'error' event
00:57:53           ^
00:57:53     
00:57:53     Error: read ECONNRESET
00:57:53         at TCP.onStreamRead (internal/stream_base_commons.js:173:27)
00:57:53     Emitted 'error' event at:
00:57:53         at emitErrorNT (internal/streams/destroy.js:82:8)
00:57:53         at emitErrorAndCloseNT (internal/streams/destroy.js:50:3)
00:57:53         at processTicksAndRejections (internal/process/next_tick.js:76:17)
00:57:53   ...

Trott on 14 Feb 2019

Again today. This seems to be increasing in frequency, but also still only occurring on Rackspace hosts running Win2008r2 with VS 2017.

https://ci.nodejs.org/job/node-test-binary-windows/23765/COMPILED_BY=vs2017,RUNNER=win2008r2-vs2017,RUN_SUBSET=0/console

test-rackspace-win2008r2-x64-5

00:22:37 not ok 612 sequential/test-http2-large-file # TODO : Fix flaky test
00:22:37   ---
00:22:37   duration_ms: 3.107
00:22:37   severity: flaky
00:22:37   exitcode: 1
00:22:37   stack: |-
00:22:37     events.js:173
00:22:37           throw er; // Unhandled 'error' event
00:22:37           ^
00:22:37     
00:22:37     Error: read ECONNRESET
00:22:37         at TCP.onStreamRead (internal/stream_base_commons.js:173:27)
00:22:37     Emitted 'error' event at:
00:22:37         at emitErrorNT (internal/streams/destroy.js:82:8)
00:22:37         at emitErrorAndCloseNT (internal/streams/destroy.js:50:3)
00:22:37         at processTicksAndRejections (internal/process/next_tick.js:76:17)
00:22:37   ...

Trott on 15 Feb 2019

https://ci.nodejs.org/job/node-test-binary-windows/24008/COMPILED_BY=vs2017,RUNNER=win2008r2-vs2017,RUN_SUBSET=1/console

test-rackspace-win2008r2-x64-3

00:34:30 not ok 615 sequential/test-http2-large-file # TODO : Fix flaky test
00:34:30   ---
00:34:30   duration_ms: 2.606
00:34:30   severity: flaky
00:34:30   exitcode: 1
00:34:30   stack: |-
00:34:30     events.js:173
00:34:30           throw er; // Unhandled 'error' event
00:34:30           ^
00:34:30     
00:34:30     Error: read ECONNRESET
00:34:30         at TCP.onStreamRead (internal/stream_base_commons.js:173:27)
00:34:30     Emitted 'error' event at:
00:34:30         at emitErrorNT (internal/streams/destroy.js:82:8)
00:34:30         at emitErrorAndCloseNT (internal/streams/destroy.js:50:3)
00:34:30         at processTicksAndRejections (internal/process/next_tick.js:76:17)
00:34:30   ...

Trott on 27 Feb 2019

https://ci.nodejs.org/job/node-test-binary-windows/24984/COMPILED_BY=vs2017,RUNNER=win2008r2-vs2017,RUN_SUBSET=1/console

test-rackspace-win2008r2-x64-3

00:25:39 not ok 626 sequential/test-http2-large-file # TODO : Fix flaky test
00:25:39   ---
00:25:39   duration_ms: 1.794
00:25:39   severity: flaky
00:25:39   exitcode: 1
00:25:39   stack: |-
00:25:39     events.js:171
00:25:39           throw er; // Unhandled 'error' event
00:25:39           ^
00:25:39     
00:25:39     Error: read ECONNRESET
00:25:39         at TCP.onStreamRead (internal/stream_base_commons.js:182:27)
00:25:39     Emitted 'error' event at:
00:25:39         at emitErrorNT (internal/streams/destroy.js:91:8)
00:25:39         at emitErrorAndCloseNT (internal/streams/destroy.js:59:3)
00:25:39         at processTicksAndRejections (internal/process/task_queues.js:81:17)
00:25:39   ...

Trott on 31 Mar 2019

https://ci.nodejs.org/job/node-test-binary-windows-2/494/COMPILED_BY=vs2017,RUNNER=win2008r2-vs2017,RUN_SUBSET=0/console

test-rackspace-win2008r2-x64-3

11:54:36 not ok 1209 sequential/test-http2-large-file # TODO : Fix flaky test
11:54:36   ---
11:54:36   duration_ms: 2.193
11:54:36   severity: flaky
11:54:36   exitcode: 1
11:54:36   stack: |-
11:54:36     events.js:173
11:54:36           throw er; // Unhandled 'error' event
11:54:36           ^
11:54:36     
11:54:36     Error: read ECONNRESET
11:54:36         at TCP.onStreamRead (internal/stream_base_commons.js:183:27)
11:54:36     Emitted 'error' event at:
11:54:36         at emitErrorNT (internal/streams/destroy.js:91:8)
11:54:36         at emitErrorAndCloseNT (internal/streams/destroy.js:59:3)
11:54:36         at processTicksAndRejections (internal/process/task_queues.js:84:17)
11:54:36   ...

mmarchini on 29 Apr 2019

test-http2-large-file fails on Windows almost every CI run. I don't suppose there's someone with a bit of time to dig in? https://github.com/nodejs/node/issues/22327#issuecomment-438880432 is the most thorough troubleshooting that's happened so far, as far as I know.

@nodejs/platform-windows @nodejs/http2 @nodejs/testing

Trott on 25 Jul 2019

@nodejs/collaborators Is anyone digging into this or interested in digging into it? It seems not-impossible that whatever is causing this may be causing other test unreliability on Windows. Best detailed description seems to be https://github.com/nodejs/node/issues/22327#issuecomment-438880432.

Trott on 10 Sep 2019

It's been a few months, so I'm popping in to say that this one still fails all the time.

https://ci.nodejs.org/job/node-test-binary-windows-js-suites/277/RUN_SUBSET=3,nodes=win2008r2-COMPILED_BY-vs2017/testReport/junit/(root)/test/sequential_test_http2_large_file_/

events.js:280
      throw er; // Unhandled 'error' event
      ^

Error: read ECONNRESET
    at TCP.onStreamRead (internal/stream_base_commons.js:205:27)
Emitted 'error' event on ServerHttp2Stream instance at:
    at emitErrorCloseNT (internal/streams/destroy.js:75:8)
    at processTicksAndRejections (internal/process/task_queues.js:84:21) {
  errno: -4077,
  code: 'ECONNRESET',
  syscall: 'read'
}

Trott on 10 Dec 2019

I required help from both @joyeecheung and @jasnell to get it right, but here's the output of a failing instance of this test with NODE_DEBUG set to http2.

19:33:52 not ok 1 sequential/test-http2-large-file
19:33:52   ---
19:33:52   duration_ms: 2.153
19:33:52   severity: fail
19:33:52   exitcode: 1
19:33:52   stack: |-
19:33:52     HTTP2 4420: Http2Session client: created
19:33:52     HTTP2 4420: Http2Session client: initiating request
19:33:52     (node:4420) Warning: Setting the NODE_DEBUG environment variable to 'http2' can expose sensitive data (such as passwords, tokens and authentication headers) in the resulting log.
19:33:52     HTTP2 4420: Http2Session client: setting up session handle
19:33:52     HTTP2 4420: Http2Session client: sending settings
19:33:52     HTTP2 4420: Http2Session client: submitting settings
19:33:52     HTTP2 4420: Http2Session client: connected, initializing request
19:33:52     HTTP2 4420: Http2Session server: received a connection
19:33:52     HTTP2 4420: Http2Session server: setting up session handle
19:33:52     HTTP2 4420: Http2Session server: sending settings
19:33:52     HTTP2 4420: Http2Session server: submitting settings
19:33:52     HTTP2 4420: Http2Session server: created
19:33:52     HTTP2 4420: Http2Stream 1 [Http2Session server]: headers received
19:33:52     HTTP2 4420: Http2Stream 1 [Http2Session server]: undefined
19:33:52     HTTP2 4420: Http2Stream 1 [Http2Session server]: undefined
19:33:52     HTTP2 4420: Http2Session client: settings received
19:33:52     HTTP2 4420: Http2Stream 1 [Http2Session client]: headers received
19:33:52     HTTP2 4420: Http2Stream 1 [Http2Session client]: emitting stream 'response' event
19:33:52     HTTP2 4420: Http2Session server: settings received
19:33:52     HTTP2 4420: Http2Stream 1 [Http2Session client]: undefined
19:33:52     HTTP2 4420: Http2Stream 1 [Http2Session client]: 0
19:33:52     HTTP2 4420: Http2Stream 1 [Http2Session client]: destroying stream
19:33:52     HTTP2 4420: Http2Session client: marking session closed
19:33:52     HTTP2 4420: Http2Session client: submitting goaway
19:33:52     HTTP2 4420: Http2Session client: destroying
19:33:52     HTTP2 4420: Http2Session <invalid>: socket error [read ECONNRESET]
19:33:52     HTTP2 4420: Http2Session server: destroying
19:33:52     HTTP2 4420: Http2Stream 1 [Http2Session server]: destroying stream
19:33:52     events.js:281
19:33:52           throw er; // Unhandled 'error' event
19:33:52           ^
19:33:52     
19:33:52     Error: read ECONNRESET
19:33:52         at TCP.onStreamRead (internal/stream_base_commons.js:205:27)
19:33:52     Emitted 'error' event on ServerHttp2Stream instance at:
19:33:52         at emitErrorCloseNT (internal/streams/destroy.js:75:8)
19:33:52         at processTicksAndRejections (internal/process/task_queues.js:84:21) {
19:33:52       errno: -4077,
19:33:52       code: 'ECONNRESET',
19:33:52       syscall: 'read'
19:33:52     }
19:33:52   ...

Trott on 12 Dec 2019

This is failing frequently in CI. No one reports it because it's marked as flaky. But it's still a broken test (or indicative of something broken in core). Please exercise caution when closing flaky test issues.

Trott on 20 Jun 2020

(Although don't misunderstand me: Thanks for all the triaging today, closing stale issues! More please! And yeah, that means you're going to close one once in a while that needs to be re-opened. And also, I realize now you were closing an issue you yourself opened, so doubly understandable.)

Trott on 20 Jun 2020

Node: Investigate flaky test-http2-large-file

All 36 comments

Related issues