Open astormnewrelic opened 4 years ago
This looks like a Node.js core bug in v10 with async_hooks most likely. Thanks a lot for the repro!
@benjamingr Yup, agree that it's probably async_hooks
related -- we're trying to narrow it down before reporting over there. Do you happen to know if there's a good summary explanation of how BlueBird is using features from async_hooks
? (short of digging into BlueBird's guts and figuring it out? :) )
@addaleax anything else a report should contain?
Datapoint: Looks like this bug was not present in Node 10.1, but was/is present in Node 10.2. It's not present in Node 11.0.
tfw you wonder if you want to spend the time to hookup git bisect with a node build.
@astormnewrelic yes - I am on holiday at the moment - but if you can git-bisect this on Node with your repro and open an issue in the Node repo that would be helpful :]
Thanks @benjamingr -- I'll see what I can do w/r/t to a bisect -- although I've never done it on the node source tree before with a long C++ build in there, so we'll see how things go :). If anyone reading has known science for setting something like that up links/info would be appreciated.
Just more talking out loud to myself -- people on holiday should not respond ;)
I'm going to give the following script a try with git bisect run
between v10.2
and v10.1
. I've got things screen
ed off in a medium EC2 instance where builds are taking around an hour, and we're in roughly 7 steps territory between bisects.
We'll see what falls over in the (PST/Portland) morning :)
make clean || exit 125
./configure || exit 125
make -j4 || exit 125
cp out/Release/node ~/binaries/`git rev-parse HEAD`
for i in `seq 100`; do
./out/Release/node /home/ec2-user/repro-bluebird-segfault/methods.tap.js
if [ $? -ne 0 ]
then
exit 1
fi
done
@benjamingr I think a full core dump might be nice for a report. Also, just curious, what makes you think this is related to async_hooks? (Also, I can’t reproduce locally on x64 Linux.)
OK -- the bisect seems to be implicating this commit as the one that introduced this segmentation fault. https://github.com/nodejs/node/commit/56530f084499dba826f93a7b09b8d04ec4cc5df0
i.e. a out/Release/node
binary built at 41e1dc09dedc592b5c6dded64b18bc0fad9b8211
doesn't segmentation fault, but 56530f084499dba826f93a7b09b8d04ec4cc5df0
does.
@addaleax Nice to meet you! Not speaking for @benjamingr, but on our side we suspected async_hooks
because this segmentation fault started in BlueBird 3.6, and 3.6 is when BlueBird started using AsyncResources (_dereq_("async_hooks").AsyncResource
). Someone more familiar with BlueBird might be able to speak better to the specifics
@addaleax Also! I intend to open an issue for this over in the nodejs GitHub. I'll dockerize the reproduction (in addition to the already reported MacOS, we ran our git bisect and saw the segmentation fault on an Amazon Linux 2 AMI 64-bit (x86)), and I'll do a debug build and get a core dump for the issues as well. Would all that be enough for you'all to go on?
I've also experienced segfaults with Bluebird 3.6 and 3.7 + Node 10. However, I couldn't isolate the problem. Don't know it helps but here is the link to our Travis with a giant core dump: https://travis-ci.org/moleculerjs/moleculer/jobs/594295906 and a few screenshots of different errors that we've got while trying to figure out the source of the problem. In the end we've reverted to v3.5.5
OK -- the bisect seems to be implicating this commit as the one that introduced this segmentation fault. nodejs/node@56530f0
@astormnewrelic Are you sure? That commit doesn’t seem suitable to cause any kind of trouble at the first look, it’s basically only renaming a symbol to a string… Like, is there any chance that the flakiness in the test made it look like that was the first commit that caused trouble?
@addaleax Also! I intend to open an issue for this over in the nodejs GitHub. I'll dockerize the reproduction (in addition to the already reported MacOS, we ran our git bisect and saw the segmentation fault on an Amazon Linux 2 AMI 64-bit (x86)), and I'll do a debug build and get a core dump for the issues as well. Would all that be enough for you'all to go on?
I can’t speak for other core developers, but I personally strongly prefer a reproduction of the kind that you already have over a containerized one – that makes debugging a lot easier. But I’m also not developing on mac.
I've also experienced segfaults with Bluebird 3.6 and 3.7 + Node 10. However, I couldn't isolate the problem.
@AndreMaz Since you seem to be running Linux – is there any chance you could run the program under valgrind (valgrind node path/to/script.js
) and report back? Those reports are usually tremendously helpful for memory corruption issues, and your screenshots make it seem like that’s the case there.
Hey @addaleax my Linux machine is at my work so I'll do it tomorrow
Are you sure? That commit doesn’t seem suitable to cause any kind of trouble at the first look, it’s basically only renaming a symbol to a string… Like, is there any chance that the flakiness in the test made it look like that was the first commit that caused trouble?
As sure as I can be. I had the bisect make a backup of each node binary as it built things. I just ran the 41e1dc09dedc592b5c6dded64b18bc0fad9b8211
binary 1000 times and it didn't segfault, and the 56530f084499dba826f93a7b09b8d04ec4cc5df0
binary crashed almost immediately. I'll rerun the bisect using those two hashes and see what it produces.
@astormnewrelic I think that leaves two main options:
Either way, it might be worth trying to run something like valgrind (i.e. memory checkers) on this – I’ve heard valgrind itself doesn’t run too well on macOS, but it’s worth a shot, and maybe there are similar tools that I’m not aware of?
Hey @addaleax this is what I get when I run valgrind --log-file="log.txt" --leak-check=summary -v jest test/unit/middlewares/action-hook.spec.js
Log:
==18115== Memcheck, a memory error detector
==18115== Copyright (C) 2002-2017, and GNU GPL'd, by Julian Seward et al.
==18115== Using Valgrind-3.13.0 and LibVEX; rerun with -h for copyright info
==18115== Command: /usr/bin/jest test/unit/middlewares/action-hook.spec.js
==18115== Parent PID: 3762
==18115==
--18115--
--18115-- Valgrind options:
--18115-- --log-file=log.txt
--18115-- --leak-check=summary
--18115-- -v
--18115-- Contents of /proc/version:
--18115-- Linux version 5.0.0-31-generic (buildd@lgw01-amd64-046) (gcc version 7.4.0 (Ubuntu 7.4.0-1ubuntu1~18.04.1)) #33~18.04.1-Ubuntu SMP Tue Oct 1 10:20:39 UTC 2019
--18115--
--18115-- Arch and hwcaps: AMD64, LittleEndian, amd64-cx16-lzcnt-rdtscp-sse3-avx-avx2
--18115-- Page sizes: currently 4096, max supported 4096
--18115-- Valgrind library directory: /usr/lib/valgrind
--18115-- Reading syms from /usr/bin/env
--18115-- object doesn't have a symbol table
--18115-- Reading syms from /lib/x86_64-linux-gnu/ld-2.27.so
--18115-- Considering /lib/x86_64-linux-gnu/ld-2.27.so ..
--18115-- .. CRC mismatch (computed 1b7c895e wanted 2943108a)
--18115-- Considering /usr/lib/debug/lib/x86_64-linux-gnu/ld-2.27.so ..
--18115-- .. CRC is valid
--18115-- Reading syms from /usr/lib/valgrind/memcheck-amd64-linux
--18115-- Considering /usr/lib/valgrind/memcheck-amd64-linux ..
--18115-- .. CRC mismatch (computed c25f395c wanted 0a9602a8)
--18115-- object doesn't have a symbol table
--18115-- object doesn't have a dynamic symbol table
--18115-- Scheduler: using generic scheduler lock implementation.
--18115-- Reading suppressions file: /usr/lib/valgrind/default.supp
==18115== embedded gdbserver: reading from /tmp/vgdb-pipe-from-vgdb-to-18115-by-andmaz-on-???
==18115== embedded gdbserver: writing to /tmp/vgdb-pipe-to-vgdb-from-18115-by-andmaz-on-???
==18115== embedded gdbserver: shared mem /tmp/vgdb-pipe-shared-mem-vgdb-18115-by-andmaz-on-???
==18115==
==18115== TO CONTROL THIS PROCESS USING vgdb (which you probably
==18115== don't want to do, unless you know exactly what you're doing,
==18115== or are doing some strange experiment):
==18115== /usr/lib/valgrind/../../bin/vgdb --pid=18115 ...command...
==18115==
==18115== TO DEBUG THIS PROCESS USING GDB: start GDB like this
==18115== /path/to/gdb /usr/bin/jest
==18115== and then give GDB the following command
==18115== target remote | /usr/lib/valgrind/../../bin/vgdb --pid=18115
==18115== --pid is optional if only one valgrind process is running
==18115==
--18115-- REDIR: 0x401f2f0 (ld-linux-x86-64.so.2:strlen) redirected to 0x58060901 (???)
--18115-- REDIR: 0x401f0d0 (ld-linux-x86-64.so.2:index) redirected to 0x5806091b (???)
--18115-- Reading syms from /usr/lib/valgrind/vgpreload_core-amd64-linux.so
--18115-- Considering /usr/lib/valgrind/vgpreload_core-amd64-linux.so ..
--18115-- .. CRC mismatch (computed 4b63d83e wanted 670599e6)
--18115-- object doesn't have a symbol table
--18115-- Reading syms from /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so
--18115-- Considering /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so ..
--18115-- .. CRC mismatch (computed a4b37bee wanted 8ad4dc94)
--18115-- object doesn't have a symbol table
==18115== WARNING: new redirection conflicts with existing -- ignoring it
--18115-- old: 0x0401f2f0 (strlen ) R-> (0000.0) 0x58060901 ???
--18115-- new: 0x0401f2f0 (strlen ) R-> (2007.0) 0x04c32db0 strlen
--18115-- REDIR: 0x401d360 (ld-linux-x86-64.so.2:strcmp) redirected to 0x4c33ee0 (strcmp)
--18115-- REDIR: 0x401f830 (ld-linux-x86-64.so.2:mempcpy) redirected to 0x4c374f0 (mempcpy)
--18115-- Reading syms from /lib/x86_64-linux-gnu/libc-2.27.so
--18115-- Considering /lib/x86_64-linux-gnu/libc-2.27.so ..
--18115-- .. CRC mismatch (computed b1c74187 wanted 042cc048)
--18115-- Considering /usr/lib/debug/lib/x86_64-linux-gnu/libc-2.27.so ..
--18115-- .. CRC is valid
--18115-- REDIR: 0x4edac70 (libc.so.6:memmove) redirected to 0x4a2a6e0 (_vgnU_ifunc_wrapper)
--18115-- REDIR: 0x4ed9d40 (libc.so.6:strncpy) redirected to 0x4a2a6e0 (_vgnU_ifunc_wrapper)
--18115-- REDIR: 0x4edaf50 (libc.so.6:strcasecmp) redirected to 0x4a2a6e0 (_vgnU_ifunc_wrapper)
--18115-- REDIR: 0x4ed9790 (libc.so.6:strcat) redirected to 0x4a2a6e0 (_vgnU_ifunc_wrapper)
--18115-- REDIR: 0x4ed9d70 (libc.so.6:rindex) redirected to 0x4a2a6e0 (_vgnU_ifunc_wrapper)
--18115-- REDIR: 0x4edc7c0 (libc.so.6:rawmemchr) redirected to 0x4a2a6e0 (_vgnU_ifunc_wrapper)
--18115-- REDIR: 0x4edade0 (libc.so.6:mempcpy) redirected to 0x4a2a6e0 (_vgnU_ifunc_wrapper)
--18115-- REDIR: 0x4edac10 (libc.so.6:bcmp) redirected to 0x4a2a6e0 (_vgnU_ifunc_wrapper)
--18115-- REDIR: 0x4ed9d00 (libc.so.6:strncmp) redirected to 0x4a2a6e0 (_vgnU_ifunc_wrapper)
--18115-- REDIR: 0x4ed9800 (libc.so.6:strcmp) redirected to 0x4a2a6e0 (_vgnU_ifunc_wrapper)
--18115-- REDIR: 0x4edad40 (libc.so.6:memset) redirected to 0x4a2a6e0 (_vgnU_ifunc_wrapper)
--18115-- REDIR: 0x4ef80f0 (libc.so.6:wcschr) redirected to 0x4a2a6e0 (_vgnU_ifunc_wrapper)
--18115-- REDIR: 0x4ed9ca0 (libc.so.6:strnlen) redirected to 0x4a2a6e0 (_vgnU_ifunc_wrapper)
--18115-- REDIR: 0x4ed9870 (libc.so.6:strcspn) redirected to 0x4a2a6e0 (_vgnU_ifunc_wrapper)
--18115-- REDIR: 0x4edafa0 (libc.so.6:strncasecmp) redirected to 0x4a2a6e0 (_vgnU_ifunc_wrapper)
--18115-- REDIR: 0x4ed9840 (libc.so.6:strcpy) redirected to 0x4a2a6e0 (_vgnU_ifunc_wrapper)
--18115-- REDIR: 0x4edb0e0 (libc.so.6:memcpy@@GLIBC_2.14) redirected to 0x4a2a6e0 (_vgnU_ifunc_wrapper)
--18115-- REDIR: 0x4ed9da0 (libc.so.6:strpbrk) redirected to 0x4a2a6e0 (_vgnU_ifunc_wrapper)
--18115-- REDIR: 0x4ed97c0 (libc.so.6:index) redirected to 0x4a2a6e0 (_vgnU_ifunc_wrapper)
--18115-- REDIR: 0x4ed9c70 (libc.so.6:strlen) redirected to 0x4a2a6e0 (_vgnU_ifunc_wrapper)
--18115-- REDIR: 0x4ee46c0 (libc.so.6:memrchr) redirected to 0x4a2a6e0 (_vgnU_ifunc_wrapper)
--18115-- REDIR: 0x4edaff0 (libc.so.6:strcasecmp_l) redirected to 0x4a2a6e0 (_vgnU_ifunc_wrapper)
--18115-- REDIR: 0x4edabe0 (libc.so.6:memchr) redirected to 0x4a2a6e0 (_vgnU_ifunc_wrapper)
--18115-- REDIR: 0x4ef8eb0 (libc.so.6:wcslen) redirected to 0x4a2a6e0 (_vgnU_ifunc_wrapper)
--18115-- REDIR: 0x4eda050 (libc.so.6:strspn) redirected to 0x4a2a6e0 (_vgnU_ifunc_wrapper)
--18115-- REDIR: 0x4edaf20 (libc.so.6:stpncpy) redirected to 0x4a2a6e0 (_vgnU_ifunc_wrapper)
--18115-- REDIR: 0x4edaef0 (libc.so.6:stpcpy) redirected to 0x4a2a6e0 (_vgnU_ifunc_wrapper)
--18115-- REDIR: 0x4edc7f0 (libc.so.6:strchrnul) redirected to 0x4a2a6e0 (_vgnU_ifunc_wrapper)
--18115-- REDIR: 0x4edb040 (libc.so.6:strncasecmp_l) redirected to 0x4a2a6e0 (_vgnU_ifunc_wrapper)
--18115-- REDIR: 0x4fca3c0 (libc.so.6:__strrchr_avx2) redirected to 0x4c32730 (rindex)
--18115-- REDIR: 0x4fa5d60 (libc.so.6:__strcmp_ssse3) redirected to 0x4c33da0 (strcmp)
--18115-- REDIR: 0x4fca590 (libc.so.6:__strlen_avx2) redirected to 0x4c32cf0 (strlen)
--18115-- REDIR: 0x4fc1510 (libc.so.6:__strncmp_sse42) redirected to 0x4c33570 (__strncmp_sse42)
--18115-- REDIR: 0x4fc9fa0 (libc.so.6:__strchr_avx2) redirected to 0x4c32950 (index)
--18115-- REDIR: 0x4fc6420 (libc.so.6:__memchr_avx2) redirected to 0x4c33f80 (memchr)
--18115-- REDIR: 0x4fca1d0 (libc.so.6:__strchrnul_avx2) redirected to 0x4c37020 (strchrnul)
--18115-- REDIR: 0x4ed3070 (libc.so.6:malloc) redirected to 0x4c2faa0 (malloc)
--18115-- REDIR: 0x4fcaab0 (libc.so.6:__mempcpy_avx_unaligned_erms) redirected to 0x4c37130 (mempcpy)
--18115-- REDIR: 0x4fcaad0 (libc.so.6:__memcpy_avx_unaligned_erms) redirected to 0x4c366e0 (memmove)
--18115-- REDIR: 0x4ed3950 (libc.so.6:free) redirected to 0x4c30cd0 (free)
--18115-- REDIR: 0x4fbbc80 (libc.so.6:__stpcpy_ssse3) redirected to 0x4c35f60 (stpcpy)
--18115-- REDIR: 0x4fca720 (libc.so.6:__strnlen_avx2) redirected to 0x4c32c90 (strnlen)
Terminal:
@addaleax do you want me to run valgrind with some specific options?
@addaleax you might be right regarding this being unrelated to async_hooks
The changes also include https://github.com/petkaantonov/bluebird/commit/60ef7a0e23fd320a11281f67c64a39ff95612ce9#diff-d1f5ad3087cc94d3dc6651e3265219b7R59 which calls timer.refresh()
@AndreMaz can you see if removing the timer.refresh()
call there fixes the issue?
@addaleax runnning valgrind --tool=memcheck --log-file="full-log.txt" --leak-check=summary -v node /usr/bin/jest test/unit/middlewares/action-hook.spec.js
I get more verbose with things like:
==18415== Conditional jump or move depends on uninitialised value(s)
==18415== at 0x14CD96A: drbg_ctr_generate (in /usr/bin/node)
==18415== by 0x14D1A81: RAND_DRBG_generate (in /usr/bin/node)
==18415== by 0x14D2971: rand_drbg_get_entropy (in /usr/bin/node)
==18415== by 0x14D0043: RAND_DRBG_instantiate (in /usr/bin/node)
==18415== by 0x14D037D: drbg_setup (in /usr/bin/node)
==18415== by 0x14D1209: drbg_bytes (in /usr/bin/node)
==18415== by 0xA10F3A: node::crypto::EntropySource(unsigned char*, unsigned long) (in /usr/bin/node)
==18415== by 0x17AA892: v8::base::RandomNumberGenerator::RandomNumberGenerator() (in /usr/bin/node)
==18415== by 0x17A9A40: v8::base::CallOnceImpl(long*, std::function<void ()>) (in /usr/bin/node)
==18415== by 0x17AC2DE: v8::base::OS::GetRandomMmapAddr() (in /usr/bin/node)
==18415== by 0xAF83C6: v8::internal::GetRandomMmapAddr() (in /usr/bin/node)
==18415== by 0xF0422E: v8::internal::Heap::SetUp() (in /usr/bin/node)
Full log here full-log.txt
@AndreMaz can you see if removing the timer.refresh() call there fixes the issue?
@benjamingr will try it now
@benjamingr after removing the timer.refresh();
I got zero segfaults :smile: Everything seems to be working properly
@AndreMaz can you please try reproducing this with bluebird 3.7.1 ?
Talking to @petkaantonov refresh is removed there
@benjamingr yeah, updating to v3.7.1 seems to solve the issue.
No segfaults on my local machine and Travis is also happy
@benjamingr That still shouldn’t be an issue, right? Like, if calling timer.refresh()
makes the process crash, that’s not “just” a bluebird issue?
Sadly, those verbose valgrind warnings correspond to a known issue with OpenSSL that has been fixed since (and that is also known to not cause crashes)…
@benjamingr That still shouldn’t be an issue, right? Like, if calling timer.refresh() makes the process crash, that’s not “just” a bluebird issue?
Right, this still looks like a bug in core and I am still not sure why it happens. Why would OpenSSL even be related to timer.refresh()
causing a segfault?
@AndreMaz thanks for the update and for the thorough debugging! It is very appreciated.
Right, this still looks like a bug in core and I am still not sure why it happens. Why would OpenSSL even be related to
timer.refresh()
causing a segfault?
Just to be clear, the OpenSSL issue does really only cause nothing besides valgrind warnings. It’s unrelated.
@addaleax ah, that makes sense. Thanks! I was really confused about why the two would be related :]
Hey all -- got knocked down by a sinus infection so had to take a bit of a break from this. The repo at https://github.com/astormnewrelic/repro-bluebird-segfault now has a dockerfile that can reproduce the problem I was seeing in Amazon Linux -- README includes instructions for reproducting. Next I intend to work on getting that core dump from a debug build.
And I got the core dumps working -- I had to ulimit -c unlimited
before making the program crash which (apparently?) tells the OS how big the core dumps are allowed to get.
Core dump attached. This is from a debug build of node 10.16.3 built on Amazon Linux, running the program from my reproduction repo, and the program crashed with a segmentation fault. I'll try to get a bug report submitted to node core sometimes this week, but figured I'd share what I knew now in case it helps.
Update: The custom build that generated this core dump. http://18.222.178.114/node.zip
@astormnewrelic When working with custom builds, the binary used for causing the crash is just as much needed for debugging as the core dump itself :)
@addaleax Thank you! I've added a link to the post above that should point at the binary I used to generate this core dump. I you wouldn't mind answering a naive question -- what does having the original binary allow you to do with the core dump that you wouldn't be able to do otherwise? I've only every worked with gdb or lldb locally, and a lot of it's firmly in the "not sure what that's really doing seems like magic" column to me :)
@astormnewrelic As far as I know, the core dump doesn’t contain symbols, which are necessary to figure out what code actually corresponds to which functions in the original binary.
I might be wrong, but for me, running bt
inside lldb -c core.30607
gives only the raw function pointers, whereas the backtrace for lldb build/node/out/Debug/node -c core.30607
gives the actual corresponding function names (and line numbers) :slightly_smiling_face:
From a first look, it seems like the libuv timer heap has one entry, but that refers to a null pointer; that seems wrong, but it’s not obvious to me what led to that condition being true.
Also, weirdly enough, I couldn’t reproduce the issue even with your debug build locally – does it just take a really long time for that to happen? (I’ll keep it running overnight :smile:) And it’s basically a clean build of the v10.16.3 tag of the Node.js repo, right?
@addaleax the segmentation fault usually happens within 5 runs of the program -- and I've never seen it take more than 100 or so, so overnight might be overkill. Out of "black box reproduction" curiosity -- what distro/version are you running things on where you're not seeing the segmentation fault?
Re: clean build of the v10.16.3 tag of the Node.js repo -- yes, that's correct. make clean;./configure --debug; make
on the v10.16.3 tag.
@astorm I’m running Ubuntu 18.04, with Linux 4.15.0-65-generic on x64… and there’s nothing really special about my setup, I think
@addaleax One more confusing datapoint -- I tried switching up from Amazon Linux to on that docker container to Ubuntu 18.04 and the crashes still happened. So -- all very confusing.
TL;DR -- We're seeing an intermittent segmentation fault with BlueBird in one of our tap based test suites, and have a reproduction over here.
3.6 and 3.7
NodeJS version 10 on MacOS 10 -- it does not appear to happen on Node 12. Other plaforms not tested.
It does not happen with BlueBird 3.5.
Details
One of the tests in our test suite has been failing randomly with a segmentation fault recently. We found some time to track it down, and it seems like it started happening with BlueBird 3.6 (maybe the async_hooks stuff?). The segmentation fault doesn't happen on every run -- if you checkout this repository we've setup a small "run until fail" reproduction case. The code in the repro is significantly stripped down form the code in our actual test suite.
It's very "spooky action at a distance" style bug -- sometimes the test runs fine, sometimes it fails with something like the following
We also captured the crash in lldb with a debug build of node 10.
Full backtrace from same follows