investigate flaky test-util-callbackify

Like a number of flaky tests right now, this one looks like it is caused by #25007.

https://ci.nodejs.org/job/node-test-commit-aix/19751/nodes=aix61-ppc64/console

test-osuosl-aix61-ppc64_be-1

10:18:13 not ok 1990 parallel/test-util-callbackify
10:18:13   ---
10:18:13   duration_ms: 3.731
10:18:13   severity: fail
10:18:13   exitcode: 1
10:18:13   stack: |-
10:18:13     assert.js:86
10:18:13       throw new AssertionError(obj);
10:18:13       ^
10:18:13     
10:18:13     AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:
10:18:13     
10:18:13     null !== 1
10:18:13     
10:18:13         at common.mustCall (/home/iojs/build/workspace/node-test-commit-aix/nodes/aix61-ppc64/test/parallel/test-util-callbackify.js:205:14)
10:18:13         at /home/iojs/build/workspace/node-test-commit-aix/nodes/aix61-ppc64/test/common/index.js:335:15
10:18:13         at ChildProcess.exithandler (child_process.js:301:5)
10:18:13         at ChildProcess.emit (events.js:189:13)
10:18:13         at maybeClose (internal/child_process.js:978:16)
10:18:13         at Process.ChildProcess._handle.onexit (internal/child_process.js:265:5)
10:18:13   ...

https://ci.nodejs.org/job/node-test-commit-aix/20112/nodes=aix61-ppc64/console

test-osuosl-aix61-ppc64_be-2

00:54:27 not ok 2000 parallel/test-util-callbackify
00:54:27   ---
00:54:27   duration_ms: 7.620
00:54:27   severity: fail
00:54:27   exitcode: 1
00:54:27   stack: |-
00:54:27     assert.js:86
00:54:27       throw new AssertionError(obj);
00:54:27       ^
00:54:27     
00:54:27     AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:
00:54:27     
00:54:27     null !== 1
00:54:27     
00:54:27         at common.mustCall (/home/iojs/build/workspace/node-test-commit-aix/nodes/aix61-ppc64/test/parallel/test-util-callbackify.js:205:14)
00:54:27         at /home/iojs/build/workspace/node-test-commit-aix/nodes/aix61-ppc64/test/common/index.js:377:15
00:54:27         at ChildProcess.exithandler (child_process.js:304:5)
00:54:27         at ChildProcess.emit (events.js:188:13)
00:54:27         at maybeClose (internal/child_process.js:978:16)
00:54:27         at Process.ChildProcess._handle.onexit (internal/child_process.js:265:5)
00:54:27   ...

Probably caused by #25007.

test: mark test-util-callbackify flaky on AIX

unable to reproduce in a 1000 runs. Looks like this has vanished?

@gireeshpunathil

unable to reproduce in a 1000 runs. Looks like this has vanished?

@gireeshpunathil Here it is failing on FreeBSD in CI yesterday:

https://ci.nodejs.org/job/node-test-commit-freebsd/nodes=freebsd11-x64/23246/console

test-digitalocean-freebsd11-x64-2

22:55:45 not ok 1996 parallel/test-util-callbackify
22:55:45   ---
22:55:45   duration_ms: 0.357
22:55:45   severity: fail
22:55:45   exitcode: 1
22:55:45   stack: |-
22:55:45     assert.js:86
22:55:45       throw new AssertionError(obj);
22:55:45       ^
22:55:45     
22:55:45     AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:
22:55:45     
22:55:45     null !== 1
22:55:45     
22:55:45         at common.mustCall (/usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd11-x64/test/parallel/test-util-callbackify.js:205:14)
22:55:45         at /usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd11-x64/test/common/index.js:376:15
22:55:45         at ChildProcess.exithandler (child_process.js:302:5)
22:55:45         at ChildProcess.emit (events.js:188:13)
22:55:45         at maybeClose (internal/child_process.js:978:16)
22:55:45         at Process.ChildProcess._handle.onexit (internal/child_process.js:265:5)
22:55:45   ...

To reproduce it, you might have more luck with something like tools/test.py -j 16 --repeat 100 test/parallel/test-util-callbackify.js. (But you also might not...)

@Trott

thanks @Trott for the info; I will try my luck on freebsd today.

able to reproduce in __freebsd__

(gdb) thr 1
[Switching to thread 1 (process 101816)]#0  0x000000080323d277 in pthread_mutex_destroy ()
   from /lib/libthr.so.3
(gdb) where
#0  0x000000080323d277 in pthread_mutex_destroy () from /lib/libthr.so.3
#1  0x000000080323c7e6 in pthread_mutex_lock () from /lib/libthr.so.3
#2  0x000000000145b86d in v8::platform::tracing::TracingController::GetCategoryGroupEnabledInternal ()
#3  0x0000000000e60316 in v8::internal::CancelableLambdaTask<v8::internal::ArrayBufferCollector::FreeAllocations()::$_0>::RunInternal ()
#4  0x0000000000980fb6 in node::(anonymous namespace)::PlatformWorkerThread ()
#5  0x0000000803235c06 in pthread_create () from /lib/libthr.so.3
#6  0x0000000000000000 in ?? ()
(gdb) thr 2
[Switching to thread 2 (process 100871)]
(gdb) where
#0  0x00000000008fdeb5 in std::__1::__tree< ...> ::destroy ()
#1  0x00000000008fdebd in std::__1::__tree< ...> ::destroy ()
#2  0x00000000008fdec9 in std::__1::__tree< ...> ::destroy ()
#3  0x00000000008fdebd in std::__1::__tree< ...> ::destroy ()
#4  0x00000000008fdec9 in std::__1::__tree< ...> ::destroy ()
#5  0x00000000008fdec9 in std::__1::__tree< ...> ::destroy ()
#6  0x00000000008fdec9 in std::__1::__tree< ...> ::destroy ()
#8  0x00000000008fc5f3 in node::native_module::NativeModuleLoader::~NativeModuleLoader ()
#9  0x0000000803591911 in __cxa_finalize () from /lib/libc.so.7
#10 0x000000080351f001 in exit () from /lib/libc.so.7
#11 0x000000000091e5a7 in node::FatalException ()
#12 0x0000000000f886d2 in v8::internal::MessageHandler::ReportMessageNoExceptions ()
#13 0x0000000000f88578 in v8::internal::MessageHandler::ReportMessage ()
#14 0x0000000000f57d1f in v8::internal::Isolate::ReportPendingMessagesImpl ()
#15 0x0000000000e41e70 in v8::internal::(anonymous namespace)::Invoke ()
#16 0x0000000000e41b38 in v8::internal::Execution::Call ()
#17 0x0000000000abea61 in v8::Function::Call ()
#18 0x00000000008f9e3d in node::LoadEnvironment ()
#19 0x00000000008feb13 in node::Start ()
#20 0x00000000008fdd8a in node::Start ()
#21 0x00000000008fbfdb in node::Start ()
#22 0x00000000008ae095 in _start ()
#23 0x00000008022f0000 in ?? ()
#24 0x0000000000000000 in ?? ()

this is essentially the same as #24921 , tracked through #25007 with 2 visible differences:

in thread 2 is in its exit route due to a fatalException in the JS land - which is expected as the child ('test/fixtures/uncaught-exceptions/callbackify1.js') is actually throwing an exception that leads to its termination.
while thread 2 is thus cleaning up things in one side, thread 1 is progressing with tracing. In Investigate flaky sequential/test-child-process-execsync on AIX #24921 the TracingController object itself was stae due to the Agent destruction, here it went ahead one or two steps but succumbed to crash when it attempted to access a mutex that was already destroyed (by thread 2)

I will produce and analyze a couple of more core files to see if there are other pattern(s).

got a bunch of those. So while the victim thread shows always the same stack at tracing, the offender thread (exiting thread) are seen at these different stages, with __cxa_finalize as a common vortex:

pattern 2:

#0  0x0000000000974ba4 in node::options_parser::OptionsParser<node::PerProcessOptions>::~OptionsParser ()
#1  0x0000000803591911 in __cxa_finalize () from /lib/libc.so.7
#2  0x000000080351f001 in exit () from /lib/libc.so.7
#3  0x000000000091e5a7 in node::FatalException ()
#4  0x0000000000f886d2 in v8::internal::MessageHandler::ReportMessageNoExceptions ()
#5  0x0000000000f88578 in v8::internal::MessageHandler::ReportMessage ()
#6  0x0000000000f57d1f in v8::internal::Isolate::ReportPendingMessagesImpl ()
#7  0x0000000000e41e70 in v8::internal::(anonymous namespace)::Invoke ()
#8  0x0000000000e41b38 in v8::internal::Execution::Call ()
#9  0x0000000000abea61 in v8::Function::Call ()
#10 0x00000000008f9e3d in node::LoadEnvironment ()
#11 0x00000000008feb13 in node::Start ()
#12 0x00000000008fdd8a in node::Start ()
#13 0x00000000008fbfdb in node::Start ()
#14 0x00000000008ae095 in _start ()
#15 0x00000008022f0000 in ?? ()
#16 0x0000000000000000 in ?? ()

pattern 3:

#0  0x0000000803517544 in free () from /lib/libc.so.7
#1  0x0000000000974cf2 in node::options_parser::OptionsParser<node::PerProcessOptions>::~OptionsParser ()
#2  0x0000000803591911 in __cxa_finalize () from /lib/libc.so.7
#3  0x000000080351f001 in exit () from /lib/libc.so.7
#4  0x000000000091e5a7 in node::FatalException ()
#5  0x0000000000f886d2 in v8::internal::MessageHandler::ReportMessageNoExceptions ()
#6  0x0000000000f88578 in v8::internal::MessageHandler::ReportMessage ()
#7  0x0000000000f57d1f in v8::internal::Isolate::ReportPendingMessagesImpl ()
#8  0x0000000000e41e70 in v8::internal::(anonymous namespace)::Invoke ()
#9  0x0000000000e41b38 in v8::internal::Execution::Call ()
#10 0x0000000000abea61 in v8::Function::Call ()
#11 0x00000000008f9e3d in node::LoadEnvironment ()
#12 0x00000000008feb13 in node::Start ()
#13 0x00000000008fdd8a in node::Start ()
#14 0x00000000008fbfdb in node::Start ()
#15 0x00000000008ae095 in _start ()
#16 0x00000008022f0000 in ?? ()
#17 0x0000000000000000 in ?? ()

pattern 4:

#0  0x000000080350c197 in _pthread_mutex_init_calloc_cb () from /lib/libc.so.7
#1  0x00000008034f1cd7 in _malloc_thread_cleanup () from /lib/libc.so.7
#2  0x0000000803517224 in realloc () from /lib/libc.so.7
#3  0x00000008035175b1 in free () from /lib/libc.so.7
#4  0x0000000000974cd1 in node::options_parser::OptionsParser<node::PerProcessOptions>::~OptionsParser ()
#5  0x0000000803591911 in __cxa_finalize () from /lib/libc.so.7
#6  0x000000080351f001 in exit () from /lib/libc.so.7
#7  0x000000000091e5a7 in node::FatalException ()
#8  0x0000000000f886d2 in v8::internal::MessageHandler::ReportMessageNoExceptions ()
#9  0x0000000000f88578 in v8::internal::MessageHandler::ReportMessage ()
#10 0x0000000000f57d1f in v8::internal::Isolate::ReportPendingMessagesImpl ()
#11 0x0000000000e41e70 in v8::internal::(anonymous namespace)::Invoke ()
#12 0x0000000000e41b38 in v8::internal::Execution::Call ()
#13 0x0000000000abea61 in v8::Function::Call ()
#14 0x00000000008f9e3d in node::LoadEnvironment ()
#15 0x00000000008feb13 in node::Start ()
#16 0x00000000008fdd8a in node::Start ()
#17 0x00000000008fbfdb in node::Start ()
#18 0x00000000008ae095 in _start ()
#19 0x00000008022f0000 in ?? ()
#20 0x0000000000000000 in ?? ()

Just like #24921 , this should be fixed by #25061 .

test: mark test-util-callbackify flaky on AIX

the test is active for the last one week with no failures, so as expected #25061 has fixed the underlying issue. Closing.

test: mark test-util-callbackify flaky on AIX

Navigation Menu

Repository navigation

investigate flaky test-util-callbackify #25068

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

investigate flaky test-util-callbackify #25068

Description

Activity

Trott commented on Dec 30, 2018

Trott commented on Dec 30, 2018

gireeshpunathil commented on Jan 9, 2019

Trott commented on Jan 9, 2019

gireeshpunathil commented on Jan 10, 2019

gireeshpunathil commented on Jan 10, 2019

gireeshpunathil commented on Jan 10, 2019

gireeshpunathil commented on Jan 30, 2019

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions