test: flakiness in building addons with `make`

[refack]

• Version: master
• Platform: macOS
• Subsystem: build,test

test phase fails around building the test addons with ENOENT, probably while looking for the node binary, while it's clearly built and at the correct place since previous steps use is (e.g. node-gyp)

This happened either during the test/addons/.buildstamp target
https://ci.nodejs.org/job/node-test-commit-osx/nodes=osx1012/20041/console

10:54:27 gyp info spawn make
10:54:27 gyp info spawn args [ 'BUILDTYPE=Release', '-C', 'build', '--jobs', 2 ]
10:54:27 gyp info ok 
10:54:27 Building addon in /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/test/addons/zlib-binding
10:54:27 /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/tools/build-addons.js:58
10:54:27 main(process.argv[3]).catch((err) => setImmediate(() => { throw err; }));
10:54:27                                                           ^
10:54:27 
10:54:27 Error: spawn /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/node ENOENT
10:54:27     at Process.ChildProcess._handle.onexit (internal/child_process.js:229:19)
10:54:27     at onErrorNT (internal/child_process.js:406:16)
10:54:27     at process._tickCallback (internal/process/next_tick.js:63:19)
10:54:27 make[1]: *** [test/addons/.buildstamp] Error 1

Or right after
https://ci.nodejs.org/job/node-test-commit-osx/nodes=osx1012/20042/console

13:28:08 gyp info spawn make
13:28:08 gyp info spawn args [ 'BUILDTYPE=Release', '-C', 'build', '--jobs', 2 ]
13:28:08 gyp info ok 
13:28:08 touch test/addons/.buildstamp
13:28:09 if [ -x /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/./node ] && [ -e /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/./node ]; then /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/./node  tools/doc/generate.js --node-version=v11.0.0 --analytics= doc/api/addons.md --output-directory=out/doc/api; elif [ -x `which node` ] && [ -e `which node` ] && [ `which node` ]; then `which node`  tools/doc/generate.js --node-version=v11.0.0 --analytics= doc/api/addons.md --output-directory=out/doc/api; else echo "No available node, cannot run \"node  tools/doc/generate.js --node-version=v11.0.0 --analytics= doc/api/addons.md --output-directory=out/doc/api\""; exit 1; fi;
13:28:09 No available node, cannot run "node  tools/doc/generate.js --node-version=v11.0.0 --analytics= doc/api/addons.md --output-directory=out/doc/api"
13:28:09 make[2]: *** [out/doc/api/addons.html] Error 1

[refack]

• Recently moving to a new macOS provider in CI and the machines are a bit thinner on resources than they used to be, so builds are failing more often.
• Recently changing addons to build in parallel rather than in series. It's possible all these failures in building addons are revealing a race condition there that isn't showing up elsewhere.

Since it's happening near the end of the addons build (either last addon or next to last in the directory) it might be bad interaction between node, make and bash

[refack]

I couldn't find any occurrences on macOS 10.10 _{we stopped testing master on 10.10}

But I spotted one that is "far" from target start or finish (addons/async-hello-world):
https://ci.nodejs.org/job/node-test-commit-osx/nodes=osx1011/20035/console

Looking at the surrounding make targets being built it seems like it is sandwiched between relinkin of the binary. This might be because we're recursively spawning make while JOBS=2, so it might race with itself.

06:31:36 rm ab44d261d5eee77f30a9729f8502ae1eca1260e4.intermediate 5942863992b65f87a6b23335633e527c76a5419b.intermediate 8bde6021d7f76f37155f81b6949420e6304169c0.intermediate
06:31:36 if [ ! -r node -o ! -L node ]; then ln -fs out/Release/node node; fi
06:31:36 /Library/Developer/CommandLineTools/usr/bin/make test-ci
06:31:36 # Clean up any leftover processes but don't error if found.

[refack]

Since this is first time I've seen this (https://ci.nodejs.org/job/node-test-commit-osx/nodes=osx1011/19994/ canary build), my current working assumption is that this is due to some new dependency cycle introduced by V8 6.4

[rubys]

Are we seeing this with any other pull request?

[refack]

Are we seeing this with any other pull request?

@rubys yes, for example the last link I posted (job 19994) was run 2 days ago on the v8 canary branch.

[rubys]

Back home. Did 8 parallel clones of node from github on a macOS High Sierra 10.13.5 machine (4 GHz Intel Core i7 iMac late 2014). Ran ./configure; make test-ci concurrently on each. All completed successfully.

[Trott]

Back home. Did 8 parallel clones of node from github on a macOS High Sierra 10.13.5 machine (4 GHz Intel Core i7 iMac late 2014). Ran ./configure; make test-ci concurrently on each. All completed successfully.

Here's the specs on one of the machines where we're seeing failures:

Intel(R) Xeon(R) CPU X5570 @ 2.93GHz
Processor Speed: 2.79 GHz
Number of Processors: 2
Memory: 4 GB

[refack]

@rubys, I think the problem is more pronounced with the run-ci target:

node/Makefile

Lines 483 to 484 in e3a4702

	run-ci: build-ci
	$(MAKE) test-ci

First the build-ci sub-target actually builds a node binary. Then the recursive call to test-ci start to in parallel re-build the binary, and bootstrap the testing. Those two task unsurprisingly clash.

That following was apparently just a ninja bug with long paths.
I believe the crux of the problem is a self referencing dependency in the new V8 patch that causes it to always rebuild. For example calling ninja torque again after it completes, shows a constant dirtiness detection.

>ninja -v -d explain -C out/Release torque
ninja: Entering directory `out\Release'
ninja explain: output obj/deps/v8/third_party/antlr4/runtime/Cpp/runtime/src/torque.ANTLRErrorListener.obj doesn't exist
ninja explain: obj/deps/v8/third_party/antlr4/runtime/Cpp/runtime/src/torque.ANTLRErrorListener.obj is dirty
...
ninja explain: torque.exe is dirty


>ninja -v -d explain -C out/Release torque
ninja: Entering directory `out\Release'
ninja explain: output obj/deps/v8/third_party/antlr4/runtime/Cpp/runtime/src/torque.ANTLRErrorListener.obj doesn't exist
ninja explain: obj/deps/v8/third_party/antlr4/runtime/Cpp/runtime/src/torque.ANTLRErrorListener.obj is dirty
...
ninja explain: torque.exe is dirty

[targos]

The dependency on antlr4 was removed in a recent V8 commit. Maybe backporting it could help?

[refack]

The dependency on antlr4 was removed in a recent V8 commit. Maybe backporting it could help?

I'm doing some testing trying to figure out where and if there's a self referencing dependency (my current guess is it's one of the -I include directories, so anyway we need to make sure the codegen part doesn't "dirty" itself) Nope