search

nodejs / node

Node.js JavaScript runtime ✨🐢🚀✨
https://nodejs.org
Other
106.94k stars 29.19k forks source link

flaky: parallel/test-http2-large-write-multiple-requests #52550

Open mhdawson opened 5 months ago

mhdawson commented 5 months ago

Test

parallel/test-http2-large-write-multiple-requests

Platform

Linux x64

Console output

not ok 2765 parallel/test-http2-large-write-multiple-requests
16:22:27   ---
16:22:27   duration_ms: 120028.14200
16:22:27   severity: fail
16:22:27   exitcode: -15
16:22:27   stack: |-
16:22:27     timeout
16:22:27     server sends content 1
16:22:27     server sends content 2
16:22:27     server sends content 3
16:22:27     server sends content 4
16:22:27     server sends content 5
16:22:27     server sends content 6
16:22:27     server sends content 7
16:22:27     server sends content 8
16:22:27     server sends content 9
16:22:27     server sends content 10
16:22:27     server sends content 11
16:22:27     server sends content 12
16:22:27     server sends content 13
16:22:27     server sends content 14
16:22:27     server sends content 15
16:22:27     server sends content 16
16:22:27     server sends content 17
16:22:27     server sends content 18
16:22:27     server sends content 19
16:22:27     server sends content 20
16:22:27     server sends content 21
16:22:27     server sends content 22
16:22:27     server sends content 23
16:22:27     server sends content 24
16:22:27     server sends content 25
16:22:27     server sends content 26
16:22:27     server sends content 27
16:22:27     server sends content 28
16:22:27     server sends content 29
16:22:27     server sends content 30
16:22:27     server sends content 31
16:22:27     server sends content 32
16:22:27     server sends content 33
16:22:27     server sends content 34
16:22:27     server sends content 35
16:22:27     server sends content 36
16:22:27     server sends content 37
16:22:27     server sends content 38
16:22:27     server sends content 39
16:22:27     server sends content 40
16:22:27     server sends content 41
16:22:27     server sends content 42
16:22:27     server sends content 43
16:22:27     server sends content 44
16:22:27     server sends content 45
16:22:27     server sends content 46
16:22:27     server sends content 47
16:22:27     server sends content 48
16:22:27     server sends content 49
16:22:27     server sends content 50
16:22:27     server sends content 51
16:22:27     server sends content 52
16:22:27     server sends content 53
16:22:27     server sends content 54
16:22:27     server sends content 55
16:22:27     server sends content 56
16:22:27     server sends content 57
16:22:27     server sends content 58
16:22:27     server sends content 59
16:22:27     server sends content 60
16:22:27     server sends content 61
16:22:27     server sends content 62
16:22:27     server sends content 63
16:22:27     server sends content 64
16:22:27     server sends content 65
16:22:27     server sends content 66
16:22:27     server sends content 67
16:22:27     server sends content 68
16:22:27     server sends content 69
16:22:27     server sends content 70
16:22:27     server sends content 71
16:22:27     server sends content 72
16:22:27     server sends content 73
16:22:27     server sends content 74
16:22:27     server sends content 75
16:22:27     server sends content 76
16:22:27     server sends content 77
16:22:27     server sends content 78
16:22:27     server sends content 79
16:22:27     server sends content 80
16:22:27     server sends content 81
16:22:27     server sends content 82
16:22:27     server sends content 83
16:22:27     server sends content 84
16:22:27     server sends content 85
16:22:27     server sends content 86
16:22:27     server sends content 87
16:22:27     server sends content 88
16:22:27     server sends content 89
16:22:27     server sends content 90
16:22:27     server sends content 91
16:22:27     server sends content 92
16:22:27     server sends content 93
16:22:27     server sends content 94
16:22:27     server sends content 95
16:22:27     server sends content 96
16:22:27     server sends content 97
16:22:27     server sends content 98
16:22:27     server sends content 99
16:22:27     server sends content 100
16:22:27     client receives content 1
16:22:27     client receives content 2
16:22:27     client receives content 3
16:22:27     client receives content 4
16:22:27     client receives content 5
16:22:27     client receives content 6
16:22:27     client receives content 7
16:22:27     client receives content 8
16:22:27     client receives content 9
16:22:27     client receives content 10
16:22:27     client receives content 11
16:22:27     client receives content 12
16:22:27     client receives content 13
16:22:27     client receives content 14
16:22:27     client receives content 15
16:22:27     client receives content 16
16:22:27     client receives content 17
16:22:27     client receives content 18
16:22:27     client receives content 19
16:22:27     client receives content 20
16:22:27     client receives content 21
16:22:27     client receives content 22
16:22:27     client receives content 23
16:22:27     client receives content 24
16:22:27     client receives content 25
16:22:27     client receives content 26
16:22:27     client receives content 27
16:22:27     client receives content 28
16:22:27     client receives content 29
16:22:27     client receives content 30
16:22:27     client receives content 31
16:22:27     client receives content 32
16:22:27     client receives content 33
16:22:27     client receives content 34
16:22:27     client receives content 35
16:22:27     client receives content 36
16:22:27     client receives content 37
16:22:27     client receives content 38
16:22:27     client receives content 39
16:22:27     client receives content 40
16:22:27     client receives content 41
16:22:27     client receives content 42
16:22:27     client receives content 43
16:22:27     client receives content 44
16:22:27     client receives content 45
16:22:27     client receives content 46
16:22:27     client receives content 47
16:22:27     client receives content 48
16:22:27     client receives content 49
16:22:27     client receives content 50
16:22:27     client receives content 51
16:22:27     client receives content 52
16:22:27     client receives content 53
16:22:27     client receives content 54
16:22:27     client receives content 55
16:22:27     client receives content 56
16:22:27     client receives content 57
16:22:27     client receives content 58
16:22:27     client receives content 59
16:22:27     client receives content 60
16:22:27     client receives content 61
16:22:27     client receives content 62
16:22:27     client receives content 63
16:22:27     client receives content 64
16:22:27     client receives content 65
16:22:27     client receives content 66
16:22:27     client receives content 67
16:22:27     client receives content 68
16:22:27     client receives content 69
16:22:27     client receives content 70
16:22:27     client receives content 71
16:22:27     client receives content 72
16:22:27     client receives content 73
16:22:27     client receives content 74
16:22:27     client receives content 75
16:22:27     client receives content 76
16:22:27     client receives content 77
16:22:27     client receives content 78
16:22:27     client receives content 79
16:22:27     client receives content 80
16:22:27     client receives content 81
16:22:27     client receives content 82
16:22:27     client receives content 83
16:22:27     client receives content 84
16:22:27     client receives content 85
16:22:27     client receives content 86
16:22:27     client receives content 87
16:22:27     client receives content 88
16:22:27     client receives content 89
16:22:27     client receives content 90
16:22:27     client receives content 91
16:22:27     client receives content 92
16:22:27     client receives content 93
16:22:27     client receives content 94
16:22:27     client receives content 95
16:22:27     client receives content 96
16:22:27     client receives content 97
16:22:27     client receives content 98
16:22:27     client receives content 99
16:22:27     client receives content 100
16:22:27   ...
16:22:27 ok 2766 parallel/test-snapshot-typescript
16:22:27   ---

Build links

Additional information

No response

joyeecheung commented 5 months ago

hmm, maybe we can add an unref'ed timer in the test that logs out the active handles after around 1 minute to figure out what's keeping the process alive..

mhdawson commented 5 months ago

again - https://ci.nodejs.org/job/node-test-commit-linux-containered/nodes=ubuntu2204_sharedlibs_withoutintl_x64/42904/

jakecastelli commented 2 months ago

Failed again - https://ci.nodejs.org/job/node-test-commit-osx/nodes=osx11-x64/59933/

jakecastelli commented 2 months ago

again - https://ci.nodejs.org/job/node-test-binary-windows-js-suites/RUN_SUBSET=2,nodes=win2019-COMPILED_BY-vs2022/28880/ on this PR

jakecastelli commented 2 months ago

again - https://ci.nodejs.org/job/node-test-commit-linux-containered/nodes=ubuntu2204_sharedlibs_withoutintl_x64/44960

pmarchini commented 1 month ago

Again - https://ci.nodejs.org/job/node-test-commit-linux/nodes=ubuntu2204-64/59826/

aduh95 commented 3 weeks ago

I'm unable to reproduce locally on macOS:

$ ./tools/test.py --repeat 9999 -t 2 test/parallel/test-http2-large-write-multiple-requests.js 
[05:07|% 100|+ 9999|-   0]: Done                                              

All tests passed.
lpinca commented 3 weeks ago

I can reproduce on Ubuntu

$ ./tools/test.py --repeat=10000 test/parallel/test-http2-large-write-multiple-requests.js
=== release test-http2-large-write-multiple-requests ===
Path: parallel/test-http2-large-write-multiple-requests

...

Command: out/Release/node /home/luigi/node/test/parallel/test-http2-large-write-multiple-requests.js
--- TIMEOUT ---

...

[05:05|%  99|+ 9996|-   3]: Done

Failed tests:
out/Release/node /home/luigi/node/test/parallel/test-http2-large-write-multiple-requests.js
out/Release/node /home/luigi/node/test/parallel/test-http2-large-write-multiple-requests.js
out/Release/node /home/luigi/node/test/parallel/test-http2-large-write-multiple-requests.js

Similarly to parallel/test-net-write-fully-async-hex-string, the test correctly finishes but the process does not exit. The following patch

diff --git a/test/parallel/test-http2-large-write-multiple-requests.js b/test/parallel/test-http2-large-write-multiple-requests.js
index bcbb1434cb..b5a698e47f 100644
--- a/test/parallel/test-http2-large-write-multiple-requests.js
+++ b/test/parallel/test-http2-large-write-multiple-requests.js
@@ -1,4 +1,5 @@
 'use strict';
+// Flags: --jitless
 const common = require('../common');
 if (!common.hasCrypto)
   common.skip('missing crypto');

fixes the issue for both tests on my machine.

targos commented 3 weeks ago

I'm able to relatively quickly reproduce on https://ci.nodejs.org/computer/test%2Dibm%2Drhel8%2Dx64%2D3/

After attaching gdb to the hanging process, I get this:

Attaching to program: /home/iojs/build/workspace/node-test-commit-linux/node, process 3703811
[New LWP 3703812]
[New LWP 3703813]
[New LWP 3703814]
[New LWP 3703815]
[New LWP 3703816]
[New LWP 3703817]
[New LWP 3703825]
[New LWP 3703826]
[New LWP 3703827]
[New LWP 3703828]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
0x00007f1be59dc48c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
Missing separate debuginfos, use: yum debuginfo-install glibc-2.28-251.el8_10.2.x86_64 libgcc-8.5.0-22.el8_10.x86_64 libstdc++-8.5.0-22.el8_10.x86_64
(gdb) bt
#0  0x00007f1be59dc48c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x0000000001fea079 in uv_cond_wait (cond=<optimized out>, mutex=<optimized out>) at ../deps/uv/src/unix/thread.c:814
#2  0x000000000105d48b in node::NodePlatform::DrainTasks(v8::Isolate*) ()
#3  0x0000000000eb0dc2 in node::SpinEventLoopInternal(node::Environment*) ()
#4  0x000000000101f0b2 in node::NodeMainInstance::Run() ()
#5  0x0000000000f71782 in node::Start(int, char**) ()
#6  0x00007f1be56327e5 in __libc_start_main () from /lib64/libc.so.6
#7  0x0000000000eade0e in _start ()
targos commented 3 weeks ago

I'm starting to believe that all these random timeouts are related to these: https://github.com/nodejs/node/pull/47450 https://github.com/nodejs/node/issues/47297 https://github.com/nodejs/node/pull/47452 https://github.com/nodejs/node/pull/47461

targos commented 3 weeks ago

In other words, a revert of e600de93cf443f057bd6d1135d1768ba5a39d110 might make the issues much easier to reproduce on fast CPUs

lpinca commented 3 weeks ago

FWIW, I get no failures (for this test) with the patch from https://github.com/nodejs/node/pull/47452 applied on main.

targos commented 3 weeks ago

I confirm. Let's reopen that pull request.

lpinca commented 3 weeks ago

The are a bunch of other tests that fail with that patch, though.