test: test-tick-processor failed

[ghaiklor]

• Version: v6.0.0-pre
• Platform: Darwin Kernel Version 15.4.0
• Subsystem: test

When running make test, I got the following:

/usr/bin/python tools/test.py --mode=release message parallel sequential -J
=== release test-tick-processor ===
Path: parallel/test-tick-processor
assert.js:89
  throw new assert.AssertionError({
  ^
AssertionError: false == true
    at runTest (/Users/ghaiklor/Library/Projects/node/test/parallel/test-tick-processor.js:58:3)
    at Object.<anonymous> (/Users/ghaiklor/Library/Projects/node/test/parallel/test-tick-processor.js:38:1)
    at Module._compile (module.js:417:34)
    at Object.Module._extensions..js (module.js:426:10)
    at Module.load (module.js:357:32)
    at Function.Module._load (module.js:314:12)
    at Function.Module.runMain (module.js:451:10)
    at startup (node.js:155:18)
    at node.js:433:3
Command: out/Release/node /Users/ghaiklor/Library/Projects/node/test/parallel/test-tick-processor.js
[00:55|% 100|+ 1062|-   1]: Done
make: *** [test] Error 1

Assertion error in this code:

runTest(/RunInDebugContext/,
  `function f() {
     require(\'vm\').runInDebugContext(\'Debug\');
     setImmediate(function() { f(); });
   };
   setTimeout(function() { process.exit(0); }, 2000);
   f();`);

[thefourtheye]

I wonder why this is not caught in CI.

[Trott]

I wonder why this is not caught in CI.

The test already has open issues for it being flaky on two other platforms. It is a non-deterministic test that will vary a lot based on how powerful your computer is, so that's probably what's going on here.

[balupton]

Getting the same here on OSX 10.11.4 (15E65)

14:39:14:balupton@balmac.local:/Users/balupton/Projects/uni/node:(HEAD detached at v5.9.1)
$ make test
/Applications/Xcode.app/Contents/Developer/usr/bin/make -C out BUILDTYPE=Release V=1
make[1]: Nothing to be done for `all'.
ln -fs out/Release/node node
Running main() from gtest_main.cc
[==========] Running 1 test from 1 test case.
[----------] Global test environment set-up.
[----------] 1 test from UtilTest
[ RUN      ] UtilTest.ListHead
[       OK ] UtilTest.ListHead (0 ms)
[----------] 1 test from UtilTest (0 ms total)

[----------] Global test environment tear-down
[==========] 1 test from 1 test case ran. (0 ms total)
[  PASSED  ] 1 test.
/usr/local/opt/python/bin/python2.7 tools/test.py --mode=release message parallel sequential -J
=== release test-tick-processor ===                                            
Path: parallel/test-tick-processor
assert.js:89
  throw new assert.AssertionError({
  ^
AssertionError: false == true
    at runTest (/Users/balupton/Projects/uni/node/test/parallel/test-tick-processor.js:58:3)
    at Object.<anonymous> (/Users/balupton/Projects/uni/node/test/parallel/test-tick-processor.js:38:1)
    at Module._compile (module.js:413:34)
    at Object.Module._extensions..js (module.js:422:10)
    at Module.load (module.js:357:32)
    at Function.Module._load (module.js:314:12)
    at Function.Module.runMain (module.js:447:10)
    at startup (node.js:142:18)
    at node.js:939:3
Command: out/Release/node /Users/balupton/Projects/uni/node/test/parallel/test-tick-processor.js
[00:58|% 100|+ 1046|-   1]: Done                                               
make: *** [test] Error 1

[balupton]

There is also #4427 for the same test file - not sure if it is related.

[Trott]

/cc @nodejs/v8

[indutny]

I got this too

[indutny]

I believe this is a culprit:

$ foo() { nm "$@" | (c++filt -p -i || cat) }; foo $@ -n -f /Users/findutnyy/Code/indutny/node/out/Release/node
nm: for the -format option: Cannot find option named '/Users/findutnyy/Code/indutny/node/out/Release/node'!

Looking...

[indutny]

Fix:

diff --git a/deps/v8/tools/tickprocessor.js b/deps/v8/tools/tickprocessor.js
index 600d2ee..ccdb11e 100644
--- a/deps/v8/tools/tickprocessor.js
+++ b/deps/v8/tools/tickprocessor.js
@@ -757,8 +757,10 @@ inherits(MacCppEntriesProvider, UnixCppEntriesProvider);
 MacCppEntriesProvider.prototype.loadSymbols = function(libName) {
   this.parsePos = 0;
   libName = this.targetRootFS + libName;
+
+  // It seems that with OS X 10.11.4, `nm` thinks that `-f` is a format option
   try {
-    this.symbols = [os.system(this.nmExec, ['-n', '-f', libName], -1, -1), ''];
+    this.symbols = [os.system(this.nmExec, ['-n', libName], -1, -1), ''];
   } catch (e) {
     // If the library cannot be found on this system let's not panic.
     this.symbols = '';

Going to submit it to V8 team.

[indutny]

CL: https://codereview.chromium.org/1840633002/

[matthewloring]

@indutny The test still passes on my end with your fix applied.

[ghaiklor]

@matthewloring @indutny on my end too. Issue can be closed.

[deendayal-garg]

This is still failing for me. Tried to run the test cases today and getting the same error.

OS X 10.11

[santigimeno]

It looks like it's failing again: https://ci.nodejs.org/job/node-test-commit-osx/nodes=osx1010/3097/

# 
# assert.js:90
#   throw new assert.AssertionError({
#   ^
# AssertionError: false == true
#     at runTest (/Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1010/test/parallel/test-tick-processor.js:58:3)
#     at Object.<anonymous> (/Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1010/test/parallel/test-tick-processor.js:38:1)
#     at Module._compile (module.js:541:32)
#     at Object.Module._extensions..js (module.js:550:10)
#     at Module.load (module.js:456:32)
#     at tryModuleLoad (module.js:415:12)
#     at Function.Module._load (module.js:407:3)
#     at Function.Module.runMain (module.js:575:10)
#     at startup (node.js:159:18)
#     at node.js:444:3

/cc @indutny

[jasnell]

Hmm.. quite odd. I'm not able to reproduce this on OS X 10.11. I run these tests frequently and haven't seen this lately :-/ ... @indutny any ideas what could be going on?

[indutny]

@jasnell idk yet, looks like the symbol is gone again:

   1357   83.5%  /Users/findutnyy/Code/indutny/node/./node
   1060   78.1%    /Users/findutnyy/Code/indutny/node/./node
    522   49.2%      LazyCompile: ~exports.runInDebugContext vm.js:38:37
    522  100.0%        LazyCompile: ~f /Users/findutnyy/Code/indutny/node/1.js:3:11
    518   99.2%          LazyCompile: ~<anonymous> /Users/findutnyy/Code/indutny/node/1.js:5:27
    518  100.0%            LazyCompile: tryOnImmediate timers.js:540:24

[Fishrock123]

Can confirm I'm also experiencing this. OS X 10.10.5

[jasnell]

hmm.. just checked to make sure I'm not completely crazy... the OSX CI run for the v6.x release didn't have this: https://ci.nodejs.org/job/node-test-commit-osx/3092/ ... and I haven't seen it locally yet... and yet it showed up in the next CI run from master https://ci.nodejs.org/job/node-test-commit-osx/3093/nodes=osx1010/console.

[indutny]

So this is what happens:

shared-library,"/Users/findutnyy/Code/indutny/node/./node",0x1012be800,0x101aada4d

While RunInDebugContext lives at:

000000010077a6ea T __ZN4node17ContextifyContext17RunInDebugContextERKN2v820FunctionCallbackInfoINS1_5ValueEEE

I guess for some reason the tick doesn't get recorded at RunInDebugContext. Will look more deeply into it.

[Trott]

@jasnell It's probably not too surprising that the test sometimes doesn't fail. One of the thorny issues with this test is that it is non-deterministic. It's kind of a "run this a large number of times and sooner or later we should see X" kind of thing. I've never taken the time to fully understand the nature of this particular test, but in previous issue tracker discussions with @matthewloring, it seemed to be indicated that it was very difficult or perhaps even impossible to make the test deterministic.

[Trott]

I guess one naive question (that may not have an answer yet?): Is it failing because the test is flaky or because there is an issue with profiling (or whatever) on OS X in the current version?

[matthewloring]

@Trott I am looking into this issue as well. Looking at the output of a profile and checking for node specific C++ symbols is a good indication of whether or not the test is flaky (if functions with the prefix node::ContextifyContext or v8::internal appear in the C++ section of the output this is a good indication that the run was a flake). The test has been modified from its original version to make flakes very very rare at the cost of running a little longer. In this instance, I am not seeing any node specific C++ symbols so this appears to be a legitimate issue.

[indutny]

I modified test to run for 20 sec, and it is still failing. I'll figure it out by the end of the day, unless distracted.

[Trott]

This is surprising to me, but git bisect flags 204f3a8 as the commit that introduces the problem.

Can someone else compile that commit on OS X and confirm that ./node test/parallel/test-tick-processor.js fails? And then compile dd67608 (the immediately prior commit) and confirm that the same test succeeds?

/cc @ChALkeR @ofrobots @thealphanerd

[Trott]

Looks like that 204f3a8 was landed without a CI run, so if it really is the culprit, that explains why CI didn't catch the problem. :-/

[bnoordhuis]

It looks like the test is failing due to new ASLR features that MACOSX_DEPLOYMENT_TARGET=10.7 enables. If you build with make LINK="c++ -Wl,-no_pie", the test starts passing again.

[indutny]

@bnoordhuis thank you, this is indeed matches my observations.

(And sorry everyone, I was distracted)

[bnoordhuis]

#6453 for a proposed (hopefully temporary) workaround.