Investigate flaky test/async-hooks/test-callback-error

Version: v9.0.0-pre
Platform: osx1010
Subsystem: test, async_hooks, child_process

https://ci.nodejs.org/job/node-test-commit-osx/10336/nodes=osx1010/console

not ok 167 async-hooks/test-callback-error
  ---
  duration_ms: 60.132
  severity: fail
  stack: |-
    timeout

I think we should make the test more robust by only running the spawnSync part if process.argv[2] is not set. The way it is currently written, If there is a bug it will cause a recursion resulting in a timeout.

Happened again today:

https://ci.nodejs.org/job/node-test-commit-osx/10360/nodes=osx1010/console

not ok 167 async-hooks/test-callback-error
  ---
  duration_ms: 60.68
  severity: fail
  stack: |-
    timeout

/cc @nodejs/async_hooks

It might be good to split the three test cases in that file into three separate tests/test files so that we can see which one is the one that's timing out. (I'm pretty sure it's test_callback_abort.)

could add console.log('staring X'/'stopping X')
Cooking now.

@AndreasMadsen

So finally I have data, seems like it is test_callback_abort. Maybe the time to create a coredump? anyway it fluctuates from 19s to over 60s. @AndreasMadsen what can we do? skip this case on macOS?

+ python tools/test.py -p tap --mode=release --timeout 35 async-hooks/test-callback-error
TAP version 13
1..1
not ok 1 async-hooks/test-callback-error
  ---
  duration_ms: 31.297
  severity: fail
  stack: |-
    2017-06-09T04:03:20.423Z init
    2017-06-09T04:03:20.457Z required
    2017-06-09T04:03:20.467Z required ./init-hooks
    2017-06-09T04:03:20.467Z staring test_init_callback
    2017-06-09T04:03:20.547Z finished test_init_callback
    2017-06-09T04:03:20.548Z staring test_callback
    2017-06-09T04:03:20.626Z finished test_callback
    2017-06-09T04:03:20.626Z staring test_callback_abort
    2017-06-09T04:03:51.210Z finished test_callback_abort
    assert.js:586
    assert.ifError = function ifError(err) { if (err) throw err; };
                                                      ^
    
    Error: spawnSync /Users/iojs/build/workspace/node-stress-single-test/nodes/osx1010/out/Release/node ETIMEDOUT
        at exports._errnoException (util.js:1012:11)
        at spawnSync (child_process.js:546:20)
        at Object.<anonymous> (/Users/iojs/build/workspace/node-stress-single-test/nodes/osx1010/test/async-hooks/test-callback-error.js:56:12)
        at Module._compile (module.js:569:30)
        at Object.Module._extensions..js (module.js:580:10)
        at Module.load (module.js:503:32)
        at tryModuleLoad (module.js:466:12)
        at Function.Module._load (module.js:458:3)
        at Function.Module.runMain (module.js:605:10)
        at startup (bootstrap_node.js:158:16)
  ...
+ NOK=1
+ echo '1   OK: 0   NOT OK: 1   TOTAL: 100'
1   OK: 0   NOT OK: 1   TOTAL: 100
+ for i in '`seq $RUN_TIMES`'
+ python tools/test.py -p tap --mode=release --timeout 35 async-hooks/test-callback-error
TAP version 13
1..1
ok 1 async-hooks/test-callback-error
  ---
  duration_ms: 19.5
  ...
+ OK=1
+ echo '2   OK: 1   NOT OK: 1   TOTAL: 100'
2   OK: 1   NOT OK: 1   TOTAL: 100
+ for i in '`seq $RUN_TIMES`'
+ python tools/test.py -p tap --mode=release --timeout 35 async-hooks/test-callback-error
TAP version 13
1..1
ok 1 async-hooks/test-callback-error
  ---
  duration_ms: 18.279
  ...
+ OK=2
+ echo '3   OK: 2   NOT OK: 1   TOTAL: 100'
3   OK: 2   NOT OK: 1   TOTAL: 100
+ for i in '`seq $RUN_TIMES`'
+ python tools/test.py -p tap --mode=release --timeout 35 async-hooks/test-callback-error
TAP version 13
1..1
ok 1 async-hooks/test-callback-error
  ---
  duration_ms: 17.398
  ...
+ OK=3
+ echo '4   OK: 3   NOT OK: 1   TOTAL: 100'
4   OK: 3   NOT OK: 1   TOTAL: 100

/cc @DavidCai1993

Skip this case on macOS?

We don't have a good reason to expect spawnSync to timeout on MacOS. Also, we do we get an ETIMEDOUT now, if it is not a recursion then I would expect the same error as before.

-1 on skip this case on macOS at this time, too. Seems that the problem is somehow related to process.abort() ...?

We don't have a good reason to expect spawnSync to timeout on MacOS. Also, we do we get an ETIMEDOUT now, if it is not a recursion then I would expect the same error as before.

I added a timeout on spawnSync

const c3 = spawnSync(process.execPath, a, { timeout: 30000 });
console.log((new Date()).toISOString() + ' finished test_callback_abort');
assert.ifError(c3.error);

and ifError so we'd see if and why, the call failed.
I could add:

if (common.isOSX && c3.error && c3.error.code === 'ETIMEDOUT') return common.skip()

Or simply return (no skip) so we acknowledge this might fail, but essentially that's ok.

I ran this test 1000 times on my Mac, all tests finished within 200-400 ms.

Thanks for explaining the ETIMEOUT. But I still think, we don't have a good reason to expect spawnSync to timeout on MacOS.

does duration_ms: 31.297 mean 31 seconds? That is confusing.

@Trott

@Trott why does the abort tests not run on the CI? At least that is what the test/README.md says.

@benjamingr

OK, it's almost definitely user setup at this point. When I run the program, while it's hanging, a process named ReportCrash goes way up to 99% CPU. Main thing at this point is probably to:

figure out how to disable it or give it the permissions it needs or whatever, then...
..fix the issue on CI, then...
...document the issue somewhere so Collaborators like me and @benjamingr who run into the issue know what to do :-D

Although...if I run as root, things work just fine, no delay, etc. So maybe the real issue is to figure that out rather than disabling crash reporting... ¯\(ツ)/¯

Again, I wouldn't be going on and on about problems with my own personal setup if it weren't for the fact that we're seeing it in CI too, and we need to fix it there....

test: improve async-hooks/test-callback-error

I wonder what the node::Chdir is about in the stack trace...

Logging on to the CI machine, I don't get the long delay with simple cases like that described in
#13527 (comment). But I do get a long delay if I do what the test does from the command line:

Details

test-nodesource-osx1010-x64-1:osx1010 iojs$ time ./node --abort-on-uncaught-exception test/async-hooks/test-callback-error.js test_callback_abort
Error: test_callback_abort
    at ActivityCollector.initHooks.oninit.common.mustCall (/Users/iojs/build/workspace/node-stress-single-test/nodes/osx1010/test/async-hooks/test-callback-error.js:30:45)
    at ActivityCollector.oninit (/Users/iojs/build/workspace/node-stress-single-test/nodes/osx1010/test/common/index.js:517:15)
    at ActivityCollector._init (/Users/iojs/build/workspace/node-stress-single-test/nodes/osx1010/test/async-hooks/init-hooks.js:170:10)
    at init (async_hooks.js:467:43)
    at Object.emitInitS [as emitInit] (async_hooks.js:337:3)
    at Object.<anonymous> (/Users/iojs/build/workspace/node-stress-single-test/nodes/osx1010/test/async-hooks/test-callback-error.js:33:17)
    at Module._compile (module.js:569:30)
    at Object.Module._extensions..js (module.js:580:10)
    at Module.load (module.js:503:32)
    at tryModuleLoad (module.js:466:12)
 1: node::Abort() [/Users/iojs/build/workspace/node-stress-single-test/nodes/osx1010/./node]
 2: node::Chdir(v8::FunctionCallbackInfo<v8::Value> const&) [/Users/iojs/build/workspace/node-stress-single-test/nodes/osx1010/./node]
 3: v8::internal::FunctionCallbackArguments::Call(void (*)(v8::FunctionCallbackInfo<v8::Value> const&)) [/Users/iojs/build/workspace/node-stress-single-test/nodes/osx1010/./node]
 4: v8::internal::MaybeHandle<v8::internal::Object> v8::internal::(anonymous namespace)::HandleApiCallHelper<false>(v8::internal::Isolate*, v8::internal::Handle<v8::internal::HeapObject>, v8::internal::Handle<v8::internal::HeapObject>, v8::internal::Handle<v8::internal::FunctionTemplateInfo>, v8::internal::Handle<v8::internal::Object>, v8::internal::BuiltinArguments) [/Users/iojs/build/workspace/node-stress-single-test/nodes/osx1010/./node]
 5: v8::internal::Builtin_Impl_HandleApiCall(v8::internal::BuiltinArguments, v8::internal::Isolate*) [/Users/iojs/build/workspace/node-stress-single-test/nodes/osx1010/./node]
 6: 0x3a7608e043fd
 7: 0x3a7608ef7c49
Received signal 6

==== C stack trace ===============================

 [0x000100c4402b]
 [0x7fff8d42bf1a]
 [0x000000000002]
 [0x7fff8a9d79a3]
 [0x000100ac4e0d]
 [0x000100ac8a2e]
 [0x000100216c92]
 [0x0001002925d0]
 [0x000100291b59]
 [0x3a7608e043fd]
 [0x3a7608ef7c49]
[end of stack trace]

Abort trap: 6

real	2m2.042s
user	0m0.072s
sys	0m0.051s
test-nodesource-osx1010-x64-1:osx1010 iojs$

And if I run top -o cpu in another terminal, it shows ReportCrash at the top, unsurprisingly.

I don't have root or sudo access on the machine so I can't see what happens if I run as root and I can't experiment with using launchctl to try to disable ReportCrash. (Running launchctl list without root doesn't show ReportCrash.) @nodejs/build

@rvagg

Assuming you're using test-requireio-osx1010-x64-1, then nodejs/build#753 (comment) is the discussion around getting root.

@rvagg could you put the test key in the rvagg user? Presumably we'd also need the password to run sudo commands with it, IDK how we handle that normally.

...
real	2m2.042s
...

😵

If the plan is to move to MacStadium and not use requireio for Mac testing, then this may all be a moot point, at least in terms of CI. How soon can we move to MacStadium?

@rvagg

Good news! @rvagg reports that disabling ReportCrash with launchctl reduces the time from over two minutes to just 220ms when running time ./node --abort-on-uncaught-exception test/async-hooks/test-callback-error.js test_callback_abort. So this should be enough to turn CI green for OS X. All that's needed is to document this in the ansible scripts that build out the OS X hosts. That's a PR for the build repo.

@rvagg

This has been fixed since @rvagg ran these two commands on the host:

launchctl unload -w /System/Library/LaunchAgents/com.apple.ReportCrash.plist
sudo launchctl unload -w /System/Library/LaunchDaemons/com.apple.ReportCrash.Root.plist

Note that they need to be run from a GUI login or else they error out.

There's an issue open to get this into the provisioning for OS X machines. But for now, the problem is resolved, so I'm going to close this.

test: improve async-hooks/test-callback-error

Navigation Menu

Repository navigation

Investigate flaky test/async-hooks/test-callback-error #13527

54 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Investigate flaky test/async-hooks/test-callback-error #13527

Description

Activity

AndreasMadsen commented on Jun 8, 2017

Trott commented on Jun 8, 2017

AndreasMadsen commented on Jun 8, 2017

Trott commented on Jun 8, 2017

refack commented on Jun 8, 2017

refack commented on Jun 9, 2017

Trott commented on Jun 9, 2017

AndreasMadsen commented on Jun 9, 2017

DavidCai1111 commented on Jun 9, 2017

refack commented on Jun 9, 2017

AndreasMadsen commented on Jun 9, 2017

AndreasMadsen commented on Jun 9, 2017

54 remaining items

Trott commented on Jun 21, 2017

Trott commented on Jun 21, 2017

Trott commented on Jun 26, 2017

Trott commented on Jun 26, 2017

gibfahn commented on Jun 26, 2017

refack commented on Jun 26, 2017

Trott commented on Jun 26, 2017

Trott commented on Jun 27, 2017

Trott commented on Jun 28, 2017

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions