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

[efreiberg]

Running test/async-hooks/test-callback-error.js test on the master branch(no local changes) reports failures on async hooks tests.

• Version: v9.0.0-pre
• Platform: Darwin Kernel Version 15.5.0: Tue Apr 19 18:36:36 PDT 2016; root:xnu-3248.50.21~8/RELEASE_X86_64 x86_64
• Subsystem: async_hooks

$ ./node ./test/async-hooks/test-callback-error.js 
start case 1
end case 1: 85.844ms
start case 2
end case 2: 86.863ms
start case 3
end case 3: 4.478ms
Error: test_callback_abort
    at ActivityCollector.initHooks.oninit.common.mustCall (/Users/efreiberg/Documents/node_demo_2/node/test/async-hooks/test-callback-error.js:36:45)
    at ActivityCollector.oninit (/Users/efreiberg/Documents/node_demo_2/node/test/common/index.js:517:15)
    at ActivityCollector._init (/Users/efreiberg/Documents/node_demo_2/node/test/async-hooks/init-hooks.js:182:10)
    at emitInitNative (async_hooks.js:466:43)
    at Object.emitInitScript [as emitInit] (async_hooks.js:369:3)
    at Object.<anonymous> (/Users/efreiberg/Documents/node_demo_2/node/test/async-hooks/test-callback-error.js:38:17)
    at Module._compile (module.js:600:30)
    at Object.Module._extensions..js (module.js:611:10)
    at Module.load (module.js:521:32)
    at tryModuleLoad (module.js:484:12)
 1: node::Abort() [/Users/efreiberg/Documents/node_demo_2/node/out/Release/node]
 2: node::Chdir(v8::FunctionCallbackInfo<v8::Value> const&) [/Users/efreiberg/Documents/node_demo_2/node/out/Release/node]
 3: v8::internal::FunctionCallbackArguments::Call(void (*)(v8::FunctionCallbackInfo<v8::Value> const&)) [/Users/efreiberg/Documents/node_demo_2/node/out/Release/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/efreiberg/Documents/node_demo_2/node/out/Release/node]
 5: v8::internal::Builtin_Impl_HandleApiCall(v8::internal::BuiltinArguments, v8::internal::Isolate*) [/Users/efreiberg/Documents/node_demo_2/node/out/Release/node]
 6: 0x35a344a0463d

$ sw_vers -productVersion 
10.11.5

[ghost]

Getting the same error in OSX10.13 too. It is intermittent.

[cjihrig]

Related to #15208?

[Trott]

@Fishrock123 was investigating this at Code + Learn and might have some more information to add.

[MylesBorins]

Just ran into this while running the 8.x test suite on my 10.10.5 machine

[gibfahn]

I think I'm seeing the same thing on v8.x, on both macOS and Linux.

=== release test-callback-error ===                                            
Path: async-hooks/test-callback-error
start case 1
end case 1: 380.437ms
start case 2
end case 2: 648.707ms
start case 3
end case 3: 12.625ms
Error: test_callback_abort
    at ActivityCollector.initHooks.oninit.common.mustCall (/Users/gib/wrk/com/DANGER/node/test/async-hooks/test-callback-error.js:36:45)
    at ActivityCollector.oninit (/Users/gib/wrk/com/DANGER/node/test/common/index.js:533:15)
    at ActivityCollector._init (/Users/gib/wrk/com/DANGER/node/test/async-hooks/init-hooks.js:185:10)
    at emitInitNative (async_hooks.js:472:43)
    at Object.emitInitScript [as emitInit] (async_hooks.js:388:3)
    at Object.<anonymous> (/Users/gib/wrk/com/DANGER/node/test/async-hooks/test-callback-error.js:38:17)
    at Module._compile (module.js:635:30)
    at Object.Module._extensions..js (module.js:646:10)
    at Module.load (module.js:554:32)
    at tryModuleLoad (module.js:497:12)
 1: node::Abort() [/Users/gib/wrk/com/DANGER/node/out/Release/node]
 2: node::Chdir(v8::FunctionCallbackInfo<v8::Value> const&) [/Users/gib/wrk/com/DANGER/node/out/Release/node]
 3: v8::internal::FunctionCallbackArguments::Call(void (*)(v8::FunctionCallbackInfo<v8::Value> const&)) [/Users/gib/wrk/com/DANGER/node/out/Release/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/gib/wrk/com/DANGER/node/out/Release/node]
 5: v8::internal::Builtin_Impl_HandleApiCall(v8::internal::BuiltinArguments, v8::internal::Isolate*) [/Users/gib/wrk/com/DANGER/node/out/Release/node]
 6: 0x2ae711d8463d

I'm also seeing cores dumped even when the test passes, which is odd. Testing with commit ab46b8ebaa13da05513976ec2f33949aef2fae94.

[Trott]

@nodejs/async_hooks

[kysnm]

Getting the same error in
v10.0.0-pre
sw_vers -productVersion
10.11.6

[kysnm]

Error does not occur in the following environment
v 10.0.0-pre
sw_vers -productVersion
10.12.6

[shisama]

Hasn't this problem been fixed yet?

Error occurs in
v 11.0.0-pre
sw_vers -productVersion
10.13.4

[Trott]

Hasn't this problem been fixed yet?

Unless someone knows the source of the problem, how can anyone know if it's fixed? The error happens unpredictably. I'm not convinced the macOS version is a significant factor. I'm running 10.11.6 and do not see this error occurring.

[shisama]

Unless someone knows the source of the problem, how can anyone know if it's fixed?

Sorry, I had a bad comment. I don't know the source of the problem.

I'm not convinced the macOS version is a significant factor.

The error occurs once yesterday. Today, the error doesn't occurs despite the same version.

[Trott]

Sorry, I had a bad comment. I don't know the source of the problem.

I was just trying to understand the question. I apologize if it seemed like I was judging the quality of your comment. I think I genuinely misunderstood you but I think I understand now.

[Trott]

Can folks who are experiencing this try this out to see if it solves the problem?

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

(I think that disables writing crash reports to disk. So, you know, if you care about that stuff, don't do it, or know how to reverse it, which is probably running launchctl load rather than launchctl unload but check the docs to make sure I'm right about that before doing anything, ok? ok.)

[shisama]

@Trott Althogh error occurred before running the launchctl unload commands, error doesn't occur after running them.

[Trott]

Hmmm...OK, so I'm of the opinion that while it's acceptable that the crash report writing on macOS might cause a test to timeout, it should not cause a test to crash.

@nodejs/async_hooks @nodejs/testing @nodejs/platform-macos Are we all on board that this is a genuine bug to be fixed? Or is there a subtlety I'm missing such that this is acceptable behavior for the test?

[addaleax]

@Trott The crashes here are part of the tests, so, for one, we should probably move it to test/abort?

[joyeecheung]

This happened quite a few times again recently (same stack)

Refs: https://github.com/nodejs/reliability/issues/12

Reason     async-hooks/test-callback-error
Type       JS_TEST_FAILURE
Failed PR  6 (#22266, #22211, #22274, #22289, #22284, #22293)
Appeared   test-digitalocean-fedora27-x64-1
First CI   https://ci.nodejs.org/job/node-test-pull-request/16383/
Last CI    https://ci.nodejs.org/job/node-test-pull-request/16413/

[joyeecheung]

Note that this also happens on fedora

[addaleax]

I have a fix in #22655.