Repository navigation
test: flakiness in building addons with make #22006
Description
Activity
- 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,makeandbashI couldn't find any occurrences on macOS 10.10we stopped testing master on 10.10But 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/consoleLooking 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
makewhileJOBS=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.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
Are we seeing this with any other pull request?
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-ciconcurrently on each. All completed successfully.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@rubys, I think the problem is more pronounced with the
run-citarget:
Lines 483 to 484 in e3a4702
First thebuild-cisub-target actually builds a node binary. Then the recursive call totest-cistart 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 callingninja torqueagain after it completes, shows a constant dirtiness detection.Details
>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 dirtyThe dependency on antlr4 was removed in a recent V8 commit. Maybe backporting it could help?
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 theNope-Iinclude directories, so anyway we need to make sure the codegen part doesn't "dirty" itself)TL;DR: Possible courses of action (non-exclusive):
- work to ensure that
makefollowingmakedoes nothing as everything is up to date - examine the build process and ensure that NODE_EXE is build exactly once
- make a hard dependency so that building of addons waits until the NODE_EXE is built.
Analysis:
$ grep -a out\/Release\/node consoleText LD_LIBRARY_PATH=/Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/lib.host:/Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/lib.target:$LD_LIBRARY_PATH; export LD_LIBRARY_PATH; cd ../.; mkdir -p /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release; tools/specialize_node_d.py "/Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/node.d" src/node.d mac x64 c++ -Wl,-force_load,/Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/libnode.a -Wl,-force_load,/Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/libv8_base.a -Wl,-force_load,/Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/libzlib.a -Wl,-force_load,/Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/libuv.a -Wl,-force_load,/Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/libopenssl.a -Wl,-no_pie -Wl,-search_paths_first -mmacosx-version-min=10.7 -arch x86_64 -L/Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release -stdlib=libc++ -o "/Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/node" /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/obj.target/node/src/node_main.o /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/libnode.a /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/libv8_libplatform.a /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/libicui18n.a /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/libzlib.a /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/libhttp_parser.a /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/libcares.a /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/libuv.a /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/libnghttp2.a /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/libopenssl.a /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/libv8_base.a /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/libv8_libbase.a /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/libv8_libsampler.a /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/libicuucx.a /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/libicudata.a /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/libicustubdata.a /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/libv8_snapshot.a -framework CoreFoundation -lm if [ ! -r node -o ! -L node ]; then ln -fs out/Release/node node; fi c++ -Wl,-force_load,/Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/libnode.a -Wl,-force_load,/Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/libv8_base.a -Wl,-force_load,/Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/libzlib.a -Wl,-force_load,/Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/libuv.a -Wl,-force_load,/Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/libopenssl.a -Wl,-no_pie -Wl,-search_paths_first -mmacosx-version-min=10.7 -arch x86_64 -L/Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release -stdlib=libc++ -o "/Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/node" /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/obj.target/node/src/node_main.o /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/libnode.a /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/libv8_libplatform.a /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/libicui18n.a /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/libzlib.a /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/libhttp_parser.a /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/libcares.a /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/libuv.a /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/libnghttp2.a /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/libopenssl.a /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/libv8_base.a /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/libv8_libbase.a /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/libv8_libsampler.a /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/libicuucx.a /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/libicudata.a /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/libicustubdata.a /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/libv8_snapshot.a -framework CoreFoundation -lm Error: spawn /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/out/Release/node ENOENT if [ ! -r node -o ! -L node ]; then ln -fs out/Release/node node; fiCommentary:
- First match is a false match: it is for
node.d - Second match links the executable
- Third match links the executable to the root directory
- Fourth match links the executable again
- Fifth match is the error message: executable not found
- Sixth match links the executable to the root directory again
Possible theory: the second link takes a while, during which
gypis quickly run and thenBuilding addonstarts. The fact that the error occurs between the second c++ linker step and the creation of the symbolic link is consistent with this theory.Further searches in consoleText finds two occurrences of the following text:
/Library/Developer/CommandLineTools/usr/bin/make -C out BUILDTYPE=Release V=1The second rebuilds a number of targets. This is unsurprising given there is a number of steps marked with
FORCE_DO_CMD, and the fact that stamp option inCheckProtocolCompatibility.pydoesn't update the timestamp, possible fix:diff --git a/deps/v8/third_party/inspector_protocol/CheckProtocolCompatibility.py b/deps/v8/third_party/inspector_protocol/CheckProtocolCompatibility.py index c70162a2a4..886ffbed7f 100755 --- a/deps/v8/third_party/inspector_protocol/CheckProtocolCompatibility.py +++ b/deps/v8/third_party/inspector_protocol/CheckProtocolCompatibility.py @@ -473,7 +473,7 @@ def main(): if arg_options.stamp: with open(arg_options.stamp, 'a') as _: - pass + os.utime(arg_options.stamp, None) if __name__ == '__main__': sys.exit(main())
Related: this is an excerpt from the root level
Makefile:.PHONY: build-addons # .buildstamp needs $(NODE_EXE) but cannot depend on it # directly because it calls make recursively. The parent make cannot know # if the subprocess touched anything so it pessimistically assumes that # .buildstamp is out of date and need a rebuild. # Just goes to show that recursive make really is harmful... # TODO(bnoordhuis) Force rebuild after gyp update. build-addons: | $(NODE_EXE) test/addons/.buildstamp- work to ensure that
8 remaining items
@refack be aware that that would require changing not only v8, but also v8's third party dependencies. See
deps/v8/third_party/inspector_protocol/CheckProtocolCompatibility.pypatch above for an example. As currently coded, it creates a timestamp if one does not exist, but will not update the timestamp if the file already exists. This is problematic for us, but may not be for v8 or the third party tool.Net: the fix itself is straightforward, but the process to push it upstream is uncertain and with an outcome unknown. Alternatively, maintaining our own patches creates its own headache.
I'm certainly willing to work towards that as a goal, but meanwhile I do feel that we need immediate relief from the intermittent failures that we are seeing.
Since this causes the nightlies to sometimes not build the headers it is also causing the n-api jobs to fail: https://ci.nodejs.org/view/x%20-%20Abi%20stable%20module%20API/job/node-test-node-addon-api/488/
Unless there is a straightforward safe fix I think we should back out the v8 upgrade until we can find a solution.
Just found a similar on macOS cousin freebsd11-x64
15:17:19 rm 963c22820f466518f8d3027cd2fa5173e73fb881.intermediate 07e7fc21bc8186f21549155b9cac0303d820db5d.intermediate 8aee6c816e03cc2085aec3267c634cc05c87824b.intermediate 15:17:19 if [ ! -r node -o ! -L node ]; then ln -fs out/Release/node node; fi 15:17:19 gmake test-ci 15:17:23 Clean up any leftover processes but don't error if found. 15:17:23 ps awwx | grep Release/node | grep -v grep | cat 15:17:23 gmake -C out BUILDTYPE=Release V=1 15:17:23 57870 0 S+ 0:00.18 out/Release/node /usr/home/freebsd/ofrobots/test/parallel/test-trace-events-fs-sync.js 15:17:23 57956 0 R+ 0:00.10 /usr/home/freebsd/ofrobots/out/Release/node --trace-events-enabled --trace-event-categories node.fs.sync -e fs.writeFileSync("fs.txt", "123", "utf8");fs.statSync("fs.txt");fs.unlinkSync("fs.txt") 15:17:23 kill: 57870: Operation not permitted 15:17:23 kill: 57964: Operation not permitted 15:17:23 Makefile:415: recipe for target 'clear-stalled' failed 15:17:23 gmake[1]: *** [clear-stalled] Error 1 15:17:23 gmake[1]: *** Waiting for unfinished jobs.... 15:17:41 touch 07e7fc21bc8186f21549155b9cac0303d820db5d.intermediate 15:17:41 touch 8aee6c816e03cc2085aec3267c634cc05c87824b.intermediate 15:17:41 LD_LIBRARY_PATH=/usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd11-x64/out/Release/lib.host:/usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd11-x64/out/Release/lib.target:$LD_LIBRARY_PATH; export LD_LIBRARY_PATH; cd ../.; mkdir -p /usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd11-x64/out/Release/obj/gen/src/node/inspector/protocol; python tools/inspector_protocol/CodeGenerator.py --jinja_dir tools/inspector_protocol/.. --output_base "/usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd11-x64/out/Release/obj/gen/src/" --config "/usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd11-x64/out/Release/obj/gen/node_protocol_config.json" 15:17:42 LD_LIBRARY_PATH=/usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd11-x64/out/Release/lib.host:/usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd11-x64/out/Release/lib.target:$LD_LIBRARY_PATH; export LD_LIBRARY_PATH; cd ../deps/v8/gypfiles; mkdir -p /usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd11-x64/out/Release/obj/gen/src/inspector/protocol /usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd11-x64/out/Release/obj/gen/include/inspector; python ../third_party/inspector_protocol/CodeGenerator.py --jinja_dir ../third_party --output_base "/usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd11-x64/out/Release/obj/gen/src/inspector" --config ../src/inspector/inspector_protocol_config.json 15:17:43 touch 963c22820f466518f8d3027cd2fa5173e73fb881.intermediate 15:17:43 LD_LIBRARY_PATH=/usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd11-x64/out/Release/lib.host:/usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd11-x64/out/Release/lib.target:$LD_LIBRARY_PATH; export LD_LIBRARY_PATH; cd ../deps/v8/gypfiles; mkdir -p /usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd11-x64/out/Release/obj/gen/torque-generated; "/usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd11-x64/out/Release/torque" ../src/builtins/base.tq ../src/builtins/array.tq ../src/builtins/array-foreach.tq ../src/builtins/array-sort.tq ../src/builtins/typed-array.tq ../src/builtins/data-view.tq -o "/usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd11-x64/out/Release/obj/gen/torque-generated" 15:17:45 rm 963c22820f466518f8d3027cd2fa5173e73fb881.intermediate 07e7fc21bc8186f21549155b9cac0303d820db5d.intermediate 8aee6c816e03cc2085aec3267c634cc05c87824b.intermediate 15:17:45 if [ ! -r node -o ! -L node ]; then ln -fs out/Release/node node; fi 15:17:45 Makefile:490: recipe for target 'run-ci' failedhttps://ci.nodejs.org/job/node-test-commit-freebsd/20589/nodes=freebsd11-x64/console
But I now know how to solve this. There's a solution possible by fixing GYP/some-gyp-files.
- added a commit that references this issue
on Oct 20, 2018 - added a commit that references this issue
on Oct 21, 2018 - added a commit that references this issue
on Oct 29, 2018 Issue is still open, and can impact all platforms using
make- changed the title
[-]test: flakiness in building addons on macOS[/-][+]test: flakiness in building addons with `make`[/+]on Jan 22, 2019 - pinned this issue
on Jan 23, 2019 - unpinned this issue
on Feb 13, 2019 Haven't seen this in a long time.
mastermacOStest 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/.buildstamptargethttps://ci.nodejs.org/job/node-test-commit-osx/nodes=osx1012/20041/console
Or right after
https://ci.nodejs.org/job/node-test-commit-osx/nodes=osx1012/20042/console