citest: add callback

[jchavarri]

#5471 (comment)

[jchavarri]

@cristianoc sorry, i was about to push fix 😓

[cristianoc]

@cristianoc sorry, i was about to push fix 😓

Was in the middle of checking that failures were reported, so I just had that at hand.

[cristianoc]

Next, I'll try like 100 times that test don't hang anymore. And we haven't just lowered the probability of hanging.
No more low hanging fruits probably.

[cristianoc]

There's one more outstanding issue: Windows unit tests enjoy returning a timeout from time to time. But that's unrelated to this.

[cristianoc]

% ps aux | grep rescript
cristianocalcagno 29200   0.1  0.4 447088464  36432   ??  S     9:43PM   0:04.48 /Applications/Visual Studio Code.app/Contents/Frameworks/Code Helper.app/Contents/MacOS/Code Helper --ms-enable-electron-run-as-node /Users/cristianocalcagno/.vscode/extensions/chenglou92.rescript-vscode-1.3.0/server/out/server.js --node-ipc --clientProcessId=16412
cristianocalcagno 33896   0.0  0.0 408628368   1600 s005  R+   10:21PM   0:00.00 grep rescript
cristianocalcagno 33521   0.0  0.0        0      0 s000  Z+   10:19PM   0:00.00 (rescript.exe)

[jchavarri]

I could just repro as well. So, back to sync?

[cristianoc]

I could just repro as well. So, back to sync?

Maybe try see what test is causing this. Haven't found out yet which one is hanging.

[cristianoc]

Can we have sync as a parameter, so we can switch back and forth between the two while trying to find out more.
And prob make sync the default right now.

[cristianoc]

It's install.

[cristianoc]

I suspect this:

    files.forEach(function (file) {
...
        cp.exec(
          `node input.js`,

is enough to create trouble.

[cristianoc]

I suspect this:

    files.forEach(function (file) {
...
        cp.exec(
          `node input.js`,

is enough to create trouble.

What if this is done in a .sh file instead. So to avoid the spawn-then-node pattern.

Some buildTests.sh.

[jchavarri]

hm in the checks I did, I could see a different test each time:

➜  rescript-compiler git:(citest-add-callback) ✗ ps auxww | grep "node input.js"
j                15204   0.0  0.1  4651848  21820 s001  S+   10:27PM   0:00.09 node input.js
➜  rescript-compiler git:(citest-add-callback) ✗ lsof -p 15204 | grep cwd
node    15204    j  cwd      DIR                1,5      320            55998130 /Users/j/Development/github/rescript-compiler/jscomp/build_tests/scoped_ppx
➜  rescript-compiler git:(citest-add-callback) ✗ ps aux | grep "node input.js"
j                22165   0.0  0.1  4633416  21584 s001  S+   10:32PM   0:00.08 node input.js
➜  rescript-compiler git:(citest-add-callback) ✗ lsof -p 22165 | grep cwd
node    22165    j  cwd      DIR                1,5      352            55997755 /Users/j/Development/github/rescript-compiler/jscomp/build_tests/custom_namespace
➜  rescript-compiler git:(citest-add-callback) ✗ ps aux | grep "node input.js"
j                24261   0.0  0.1  4642632  21764 s001  S+   10:34PM   0:00.09 node input.js
➜  rescript-compiler git:(citest-add-callback) ✗ lsof -p 24261 | grep cwd
node    24261    j  cwd      DIR                1,5      288            55997983 /Users/j/Development/github/rescript-compiler/jscomp/build_tests/nested

So i'm unsure it's a problem of a specific test, but rather how they're invoked from ciTest.js.

[jchavarri]

@cristianoc I tried using spawn instead of exec with no luck.

Then I noticed that the tests hanging would always be the ones that were overriding stdio with stdio: [0, 1, 2]. I removed all appearances of this, and it seems that was the problem (or at least, a problem). I tried tens of times and have not been able to hang the tests after the change.

Maybe if both parent and child scripts are using same stdio, they might end up waiting for each other before closing.

[cristianoc]

The probability has gone down a lot in the last commit.
Not quite zero

% ps aux | grep rescript
cristianocalcagno 49229   0.0  0.0 408628368   1616 s005  S+   11:11PM   0:00.00 grep rescript
cristianocalcagno 49029   0.0  0.0        0      0 s000  Z+   11:11PM   0:00.00 (rescript.exe)

[cristianoc]

The probability has gone down a lot in the last commit. Not quite zero

% ps aux | grep rescript
cristianocalcagno 49229   0.0  0.0 408628368   1616 s005  S+   11:11PM   0:00.00 grep rescript
cristianocalcagno 49029   0.0  0.0        0      0 s000  Z+   11:11PM   0:00.00 (rescript.exe)

Actually tested wrongly. Hold on.

[cristianoc]

While waiting for tests to run hundreds of times...

[cristianoc]

Maybe if both parent and child scripts are using same stdio, they might end up waiting for each other before closing.

Wish there was such a clear statement in one of the issues reported on node. Appears to be true though.

[jchavarri]

The stdio hypothesis makes sense for previous issues we debugged in super-errors, because bsc script that super-errors tests were invoking is overriding it too:

https://github.com/rescript-lang/rescript-compiler/blob/03f2614f44a81a66276c1fa85252370e1ae6d107/bsc#L16

[cristianoc]

Merging as resolved! (Until someone adds a test that redirects stdio).

[jchavarri]

ftr this section in node.js docs seems relevant:

The 'close' event is emitted after a process has ended and the stdio streams of a child process have been closed. This is distinct from the 'exit' event, since multiple processes might share the same stdio streams. The 'close' event will always emit after 'exit' was already emitted, or 'error' if the child failed to spawn.

[cristianoc]

ftr this section in node.js docs seems relevant:

The 'close' event is emitted after a process has ended and the stdio streams of a child process have been closed. This is distinct from the 'exit' event, since multiple processes might share the same stdio streams. The 'close' event will always emit after 'exit' was already emitted, or 'error' if the child failed to spawn.

Indeed that was linked in the previous issue too. Pretty indirect phrasing though.