flaky: test-child-process-pipe-dataflow #25988

refack · 2019-02-07T16:56:49Z

Job: https://ci.nodejs.org/job/node-test-binary-windows/23616/COMPILED_BY=vs2017,RUNNER=win10,RUN_SUBSET=3/testReport/junit/(root)/test/parallel_test_child_process_pipe_dataflow/
Worker: https://ci.nodejs.org/computer/test-azure_msft-win10-x64-3/
Code:
https://github.com/gireeshpunathil/node/blob/b1f82e4342f8a630b1ef83cd33781a725428f569/test/parallel/test-child-process-pipe-dataflow.js#L44-L46
Message:

assert.js:86
  throw new AssertionError(obj);
  ^

AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:

1 !== 0

    at ChildProcess.<anonymous> (c:\workspace\node-test-binary-windows\test\parallel\test-child-process-pipe-dataflow.js:45:12)
    at ChildProcess.<anonymous> (c:\workspace\node-test-binary-windows\test\common\index.js:367:15)
    at ChildProcess.emit (events.js:197:13)
    at Process.ChildProcess._handle.onexit (internal/child_process.js:254:12)

gireeshpunathil · 2019-02-08T05:01:00Z

if grep found less bytes than expected, that should result in another assertion.
if grep did not find any bytes, then it should hang (our pipe is fused into its stdin) leading to timeout
if grep shows up exit code 1 would mean strange: Is it that grep is not available on the system? in which case the failure should be consistent!

Is this system picked part of regular CI? @refack - can you please check if it has grep in the first place? My test semantics expects UNIX simulated grep, not the windows native one (though I am not sure how different they are in terms of arguments). thanks!

gireeshpunathil · 2019-02-08T11:44:37Z

ran a 3K times on the failing system but no reproduce.

It turns out that the assumptions about grep were not right - it works like in any other system, and there is nothing special. At the moment the best thing I believe is to catch the standard error streams of the child process as well, so that we know what happened to those.

If the test fails with errors from the child commands, there is no debug info. Suppliment the stderr data so that we know what to look for. Refs: nodejs#25988 PR-URL: nodejs#26007 Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: Luigi Pinca <luigipinca@gmail.com> Reviewed-By: Colin Ihrig <cjihrig@gmail.com>

If the test fails with errors from the child commands, there is no debug info. Suppliment the stderr data so that we know what to look for. Refs: #25988 PR-URL: #26007 Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: Luigi Pinca <luigipinca@gmail.com> Reviewed-By: Colin Ihrig <cjihrig@gmail.com>

Trott · 2019-03-16T12:58:28Z

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

test-azure_msft-win10-x64-4

00:22:57 not ok 61 parallel/test-child-process-pipe-dataflow
00:22:57   ---
00:22:57   duration_ms: 0.175
00:22:57   severity: fail
00:22:57   exitcode: 1
00:22:57   stack: |-
00:22:57     got unexpected data from child #0:
00:22:57     cat
00:22:57     got unexpected data from child #0:
00:22:57     :
00:22:57     got unexpected data from child #0:
00:22:57      
00:22:57     got unexpected data from child #0:
00:22:57     write error
00:22:57     got unexpected data from child #0:
00:22:57     : 
00:22:57     got unexpected data from child #0:
00:22:57     No space left on device
00:22:57     got unexpected data from child #0:
00:22:57     
00:22:57     
00:22:57     assert.js:85
00:22:57       throw new AssertionError(obj);
00:22:57       ^
00:22:57     
00:22:57     AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:
00:22:57     
00:22:57     1 !== 0
00:22:57     
00:22:57         at ChildProcess.<anonymous> (c:\workspace\node-test-binary-windows\test\parallel\test-child-process-pipe-dataflow.js:42:14)
00:22:57         at ChildProcess.<anonymous> (c:\workspace\node-test-binary-windows\test\common\index.js:358:15)
00:22:57         at ChildProcess.emit (events.js:198:13)
00:22:57         at Process.ChildProcess._handle.onexit (internal/child_process.js:254:12)
00:22:57   ...

refack · 2019-03-16T13:40:56Z

No space left on device

Is this expected?

node/test/parallel/test-child-process-pipe-dataflow.js

Lines 36 to 44 in 269103a

    
           [cat, grep, wc].forEach((child, index) => { 
        
             child.stderr.on('data', (d) => { 
        
               // Don't want to assert here, as we might miss error code info. 
        
               console.error(`got unexpected data from child #${index}:\n${d}`); 
        
             }); 
        
             child.on('exit', common.mustCall(function(code) { 
        
               assert.strictEqual(code, 0); 
        
             })); 
        
           });

P.S. Worker had 60GB free disk space.

refack · 2019-03-16T13:41:33Z

P.S. I want to add a lint rule that looks for asserts with no message in loops 🤔

Trott · 2019-03-20T20:10:30Z

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

test-azure_msft-win10-x64-5

10:32:10 not ok 62 parallel/test-child-process-pipe-dataflow
10:32:10   ---
10:32:10   duration_ms: 0.212
10:32:10   severity: fail
10:32:10   exitcode: 1
10:32:10   stack: |-
10:32:10     assert.js:85
10:32:10       throw new AssertionError(obj);
10:32:10       ^
10:32:10     
10:32:10     AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:
10:32:10     
10:32:10     1 !== 0
10:32:10     
10:32:10         at ChildProcess.<anonymous> (c:\workspace\node-test-binary-windows\test\parallel\test-child-process-pipe-dataflow.js:42:14)
10:32:10         at ChildProcess.<anonymous> (c:\workspace\node-test-binary-windows\test\common\index.js:358:15)
10:32:10         at ChildProcess.emit (events.js:198:13)
10:32:10         at Process.ChildProcess._handle.onexit (internal/child_process.js:254:12)
10:32:10   ...

gireeshpunathil · 2019-03-21T04:58:03Z

looking for suggestions here!
the need for data flow integrity check between a -> b -> c is valid, and essential. However, selection of a, b, c and their interplay (being independent OS processes) seem to be proving less robust and less trustworthy?

refack · 2019-04-13T16:51:19Z

https://ci.nodejs.org/job/node-test-binary-windows-2/104/

Worker: https://ci.nodejs.org/computer/test-azure_msft-win10-x64-4

Trott · 2019-05-21T02:14:39Z

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

test-azure_msft-win10-x64-2

18:23:33 not ok 130 parallel/test-child-process-pipe-dataflow
18:23:33   ---
18:23:33   duration_ms: 0.147
18:23:33   severity: fail
18:23:33   exitcode: 1
18:23:33   stack: |-
18:23:33     assert.js:89
18:23:33       throw new AssertionError(obj);
18:23:33       ^
18:23:33     
18:23:33     AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:
18:23:33     
18:23:33     1 !== 0
18:23:33     
18:23:33         at ChildProcess.<anonymous> (c:\workspace\node-test-binary-windows-2\test\parallel\test-child-process-pipe-dataflow.js:46:14)
18:23:33         at ChildProcess.<anonymous> (c:\workspace\node-test-binary-windows-2\test\common\index.js:374:15)
18:23:33         at ChildProcess.emit (events.js:200:13)
18:23:33         at Process.ChildProcess._handle.onexit (internal/child_process.js:272:12) {
18:23:33       generatedMessage: true,
18:23:33       code: 'ERR_ASSERTION',
18:23:33       actual: 1,
18:23:33       expected: 0,
18:23:33       operator: 'strictEqual'
18:23:33     }
18:23:33   ...

gireeshpunathil · 2019-05-21T04:11:53Z

as there was no associated stderr messages from child, I would assume this is an early exit of one of the child process (with exit code 1) for an unknown reason. I know this info does not help much, but just stating, to localize the problem statement.

Trott · 2019-05-21T04:54:03Z

I'll open a PR to add more debugging data so that if this happens again, at least we'll know which subprocess is failing.

Trott · 2019-05-21T04:59:37Z

I'll open a PR to add more debugging data so that if this happens again, at least we'll know which subprocess is failing.

#27790

Trott · 2019-11-25T21:59:59Z

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

test-azure_msft-win10-x64-2

00:11:03 not ok 135 parallel/test-child-process-pipe-dataflow
00:11:03   ---
00:11:03   duration_ms: 0.212
00:11:03   severity: fail
00:11:03   exitcode: 1
00:11:03   stack: |-
00:11:03     Can't clean tmpdir: c:\workspace\node-test-binary-windows-2\test\.tmp.134
00:11:03     Files blocking: [ 'data.txt' ]
00:11:03     
00:11:03     assert.js:93
00:11:03       throw new AssertionError(obj);
00:11:03       ^
00:11:03     
00:11:03     AssertionError [ERR_ASSERTION]: child 1 exited with code 1
00:11:03         at ChildProcess.<anonymous> (c:\workspace\node-test-binary-windows-2\test\parallel\test-child-process-pipe-dataflow.js:49:14)
00:11:03         at ChildProcess.<anonymous> (c:\workspace\node-test-binary-windows-2\test\common\index.js:372:15)
00:11:03         at ChildProcess.emit (events.js:223:5)
00:11:03         at Process.ChildProcess._handle.onexit (internal/child_process.js:270:12) {
00:11:03       generatedMessage: false,
00:11:03       code: 'ERR_ASSERTION',
00:11:03       actual: 1,
00:11:03       expected: 0,
00:11:03       operator: 'strictEqual'
00:11:03     }
00:11:03   ...

gireeshpunathil · 2019-11-26T04:04:46Z

this does not look like the usual symptom this test was manifesting - cat failure or grep failure. There was an infra failure yesterday (25/11) - could this be an indirect side effect of that?

Trott · 2019-12-02T12:52:31Z

this does not look like the usual symptom this test was manifesting - cat failure or grep failure. There was an infra failure yesterday (25/11) - could this be an indirect side effect of that?

It happened again a few hours ago:

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

test-azure_msft-win10-x64-2

00:09:26 not ok 135 parallel/test-child-process-pipe-dataflow
00:09:26   ---
00:09:26   duration_ms: 0.194
00:09:26   severity: fail
00:09:26   exitcode: 1
00:09:26   stack: |-
00:09:26     assert.js:98
00:09:26       throw new AssertionError(obj);
00:09:26       ^
00:09:26     
00:09:26     AssertionError [ERR_ASSERTION]: child 1 exited with code 1
00:09:26         at ChildProcess.<anonymous> (c:\workspace\node-test-binary-windows-2\test\parallel\test-child-process-pipe-dataflow.js:49:14)
00:09:26         at ChildProcess.<anonymous> (c:\workspace\node-test-binary-windows-2\test\common\index.js:372:15)
00:09:26         at ChildProcess.emit (events.js:219:5)
00:09:26         at Process.ChildProcess._handle.onexit (internal/child_process.js:274:12) {
00:09:26       generatedMessage: false,
00:09:26       code: 'ERR_ASSERTION',
00:09:26       actual: 1,
00:09:26       expected: 0,
00:09:26       operator: 'strictEqual'
00:09:26     }
00:09:26   ...

Trott · 2019-12-02T13:21:58Z

Since stdio can still be open when the subprocess exits, I wonder if we're losing information by asserting so early on the error code?

When the test fails, it usually ends up failing on the assertion that `wc` did not find as many bytes as it expected. That may not be helpful if it is caused by a failure earlier in the command pipeline ( cat | grep | wc ). Move the byte check to `process.on('exit')` so that other error handlers that report the existence of errors run first. Refs: nodejs#25988

When the test fails, it usually ends up failing on the assertion that `wc` did not find as many bytes as it expected. That may not be helpful if it is caused by a failure earlier in the command pipeline ( cat | grep | wc ). Move the byte check to `process.on('exit')` so that other error handlers that report the existence of errors run first. Refs: nodejs#25988 PR-URL: nodejs#37632 Reviewed-By: Gireesh Punathil <gpunathi@in.ibm.com> Reviewed-By: Colin Ihrig <cjihrig@gmail.com>

Trott · 2021-03-14T05:28:06Z

Different way of failing than the last time. A timeout this time.

https://ci.nodejs.org/job/node-test-binary-windows-js-suites/8791/RUN_SUBSET=0,nodes=win10-COMPILED_BY-vs2019/console

00:33:15 not ok 781 parallel/test-child-process-pipe-dataflow
00:33:15   ---
00:33:15   duration_ms: 120.257
00:33:15   severity: fail
00:33:15   exitcode: 1
00:33:15   stack: |-
00:33:15     timeout
00:33:15   ...

When the test fails, it usually ends up failing on the assertion that `wc` did not find as many bytes as it expected. That may not be helpful if it is caused by a failure earlier in the command pipeline ( cat | grep | wc ). Move the byte check to `process.on('exit')` so that other error handlers that report the existence of errors run first. Refs: #25988 PR-URL: #37632 Reviewed-By: Gireesh Punathil <gpunathi@in.ibm.com> Reviewed-By: Colin Ihrig <cjihrig@gmail.com>

Make sure all the `wc` process stdout data is received before checking its validity. Fixes: #25988 PR-URL: #36366 Reviewed-By: Gireesh Punathil <gpunathi@in.ibm.com> Reviewed-By: Colin Ihrig <cjihrig@gmail.com> Reviewed-By: Luigi Pinca <luigipinca@gmail.com> Reviewed-By: Rich Trott <rtrott@gmail.com> Reviewed-By: James M Snell <jasnell@gmail.com>

When the test fails, it usually ends up failing on the assertion that `wc` did not find as many bytes as it expected. That may not be helpful if it is caused by a failure earlier in the command pipeline ( cat | grep | wc ). Move the byte check to `process.on('exit')` so that other error handlers that report the existence of errors run first. Refs: #25988 PR-URL: #37632 Reviewed-By: Gireesh Punathil <gpunathi@in.ibm.com> Reviewed-By: Colin Ihrig <cjihrig@gmail.com>

targos · 2021-11-17T10:37:56Z

This test started to fail again. Almost 100% of Windows CI runs are red.

lpinca · 2021-11-17T12:04:22Z

@targos this seems to fix the issue in my Windows machine:

diff --git a/test/parallel/test-child-process-pipe-dataflow.js b/test/parallel/test-child-process-pipe-dataflow.js
index 2e2edc65e9..5b34ea1429 100644
--- a/test/parallel/test-child-process-pipe-dataflow.js
+++ b/test/parallel/test-child-process-pipe-dataflow.js
@@ -27,7 +27,7 @@ const MB = KB * KB;
   // So cut the buffer into lines at some points, forcing
   // data flow to be split in the stream.
   for (let i = 1; i < KB; i++)
-    buf.write(os.EOL, i * KB);
+    buf.write('\n', i * KB);
   fs.writeFileSync(file, buf.toString());

   cat = spawn('cat', [file]);

Fixes: nodejs#25988

Fixes: #25988 PR-URL: #40838 Reviewed-By: Michaël Zasso <targos@protonmail.com> Reviewed-By: Tobias Nießen <tniessen@tnie.de> Reviewed-By: Michael Dawson <midawson@redhat.com> Reviewed-By: Rich Trott <rtrott@gmail.com>

joyeecheung · 2023-08-18T00:52:21Z

This almost always fail in the Windows CI now

lpinca · 2024-09-23T07:47:50Z

I'm closing this as the test is now skipped (#49563) and the current flakiness is caused by a Cygwin bug. See also #48300.

refack added windows Issues and PRs related to the Windows platform. test Issues and PRs related to the tests. flaky-test Issues and PRs related to the tests with unstable failures on the CI. labels Feb 7, 2019

refack mentioned this issue Feb 7, 2019

child_process: close pipe ends that are re-piped #21209

Merged

4 tasks

refack mentioned this issue Feb 7, 2019

build: fixed clang's warning when building openssl. #25954

Closed

2 tasks

gireeshpunathil mentioned this issue Feb 8, 2019

test: capture stderr from child processes #26007

Merged

4 tasks

Trott mentioned this issue May 21, 2019

test: increase debugging information on failure #27790

Closed

2 tasks

richardlau mentioned this issue Oct 5, 2019

We could use your help improving Node.js' Windows testing #29852

Closed

7 tasks

saitonakamura mentioned this issue Nov 6, 2019

Failing test-child-process-pipe-dataflow test on Windows #30294

Closed

bnoordhuis mentioned this issue Nov 6, 2019

child_process: create proper public API for channel #30165

Closed

4 tasks

Trott mentioned this issue Mar 6, 2021

test: improve error reporting in test-child-process-pipe-dataflow #37632

Merged

targos pinned this issue Nov 17, 2021

lpinca mentioned this issue Nov 17, 2021

test: deflake child-process-pipe-dataflow #40838

Closed

lpinca added a commit to lpinca/node that referenced this issue Nov 17, 2021

test: deflake child-process-pipe-dataflow

cfe7395

Fixes: nodejs#25988

lpinca added a commit to lpinca/node that referenced this issue Nov 17, 2021

test: deflake child-process-pipe-dataflow

5739f62

Fixes: nodejs#25988

lpinca added a commit to lpinca/node that referenced this issue Nov 17, 2021

test: deflake child-process-pipe-dataflow

b175af8

Fixes: nodejs#25988

Trott closed this as completed in 0c2011c Nov 18, 2021

Ayase-252 mentioned this issue Nov 18, 2021

test: Add auth option case for url.format #40516

Merged

targos unpinned this issue Nov 18, 2021

joyeecheung reopened this Aug 18, 2023

lpinca closed this as completed Sep 23, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

flaky: test-child-process-pipe-dataflow #25988

flaky: test-child-process-pipe-dataflow #25988

refack commented Feb 7, 2019

gireeshpunathil commented Feb 8, 2019

gireeshpunathil commented Feb 8, 2019

Trott commented Mar 16, 2019

refack commented Mar 16, 2019 •

edited

Loading

refack commented Mar 16, 2019

Trott commented Mar 20, 2019

gireeshpunathil commented Mar 21, 2019

refack commented Apr 13, 2019

Trott commented May 21, 2019

gireeshpunathil commented May 21, 2019

Trott commented May 21, 2019

Trott commented May 21, 2019

Trott commented Nov 25, 2019

gireeshpunathil commented Nov 26, 2019

Trott commented Dec 2, 2019

Trott commented Dec 2, 2019

Trott commented Mar 14, 2021

targos commented Nov 17, 2021

lpinca commented Nov 17, 2021 •

edited

Loading

joyeecheung commented Aug 18, 2023

lpinca commented Sep 23, 2024

flaky: test-child-process-pipe-dataflow #25988

flaky: test-child-process-pipe-dataflow #25988

Comments

refack commented Feb 7, 2019

gireeshpunathil commented Feb 8, 2019

gireeshpunathil commented Feb 8, 2019

Trott commented Mar 16, 2019

refack commented Mar 16, 2019 • edited Loading

refack commented Mar 16, 2019

Trott commented Mar 20, 2019

gireeshpunathil commented Mar 21, 2019

refack commented Apr 13, 2019

Trott commented May 21, 2019

gireeshpunathil commented May 21, 2019

Trott commented May 21, 2019

Trott commented May 21, 2019

Trott commented Nov 25, 2019

gireeshpunathil commented Nov 26, 2019

Trott commented Dec 2, 2019

Trott commented Dec 2, 2019

Trott commented Mar 14, 2021

targos commented Nov 17, 2021

lpinca commented Nov 17, 2021 • edited Loading

joyeecheung commented Aug 18, 2023

lpinca commented Sep 23, 2024

refack commented Mar 16, 2019 •

edited

Loading

lpinca commented Nov 17, 2021 •

edited

Loading