Hhvm: HHVM crashes or becomes unresponsive -- likely due to the use of \HH\Asio\curl*

Created on 9 Nov 2017 · 17Comments · Source: facebook/hhvm

HHVM Version

In particular, 3.21.3-lts, 3.22.1. Multiple OSes, running on hardware, virtualized, containerized etc. At this point we can crash it pretty much anywhere, although the severity and particulars needed to cause the crash may vary. We're currently using proxygen across the board, but we've first run into this problem while using nginx+fastcgi.

HipHop VM 3.21.3 (rel)
Compiler: tags/HHVM-3.21.3-0-gce34e5458e6a75931438a2d8fc41b91454a2f2b2
Repo schema: 90ed4216b98563d0585cf5c87959dc9ff7c2e1a1

HipHop VM 3.22.1 (rel)
Compiler: tags/HHVM-3.22.1-0-ge8ce62608d2d14e6418772b07ebaddcbdb37598f
Repo schema: 05fc45ee8e70c9f18dfb1e867219c8528be87996

I would hazard a guess that the problem is long-standing, and all reasonably recent versions are affected.

Standalone code, or other way to reproduce the problem

https://github.com/genych/burn

See instructions in the README.md. This can be deployed and run on an existing HHVM node, but also includes a docker-compose recipe to run the three components in isolated containers.

The repro includes three components:

CLI script that initiates calls to the "service".
Remote service retrieving another remote resource using \HH\Asio\curl_exec -- this is the part that causes the crashes.
"Static" resource retrieved by part 2.

Note that this is not guaranteed to produce a crash in a single run. Increasing the number of attempts or simultaneous connections increases the likelihood of success.

Response time for part 3 also seems to affect reproducibility. Very short response times are much more likely to result in a crash, so it's best to use a locally deployed static resource.

Expected result

HHVM continues serving requests or at least crashes gracefully.

Actual result

Several outcomes possible.

HHVM crashes with:

Finished singleJitRequest 1
Finished singleJitRequest 2
Finished singleJitRequest 4
Finished singleJitRequest 3
Finished singleJitRequest 5
Finished singleJitRequest 6
Finished singleJitRequest 7
Finished singleJitRequest 8
Finished singleJitRequest 9
Finished singleJitRequest 10
Finished singleJitRequest 11
Finished singleJitRequest 12
Finished singleJitRequest 13
Finished singleJitRequest 14
Finished singleJitRequest 15
Finished singleJitRequest 16
Finished singleJitRequest 17
Finished singleJitRequest 18
Finished singleJitRequest 19
Finished singleJitRequest 20
Finished singleJitRequest 21
Finished singleJitRequest 22
pure virtual method called
terminate called without an active exception
Core dumped: Aborted
Stack trace in /tmp/stacktrace.29196.log
Aborted (core dumped)

Stack trace contains:

Host: xub
ProcessID: 29196
ThreadID: 140377659008768
ThreadPID: 29223
Name: /usr/bin/hhvm
Type: Aborted
Runtime: hhvm
Version: tags/HHVM-3.22.1-0-ge8ce62608d2d14e6418772b07ebaddcbdb37598f
DebuggerCount: 0


# 0  0000000000dd20d6
# 1  00000000011cb452
# 2  00007fac76c31390
# 3  00007fac701a0428
# 4  00007fac701a202a
# 5  00007fac70ae384d
# 6  00007fac70ae16b6
# 7  00007fac70ae1701
# 8  00007fac70ae223f
# 9  00007fac777094c9
# 10 00000000036d2ee6
# 11 0000000003135c19
# 12 00007fac70b0cc80
# 13 00007fac76c276ba
# 14 00007fac702723dd

This is the preferrable outcome from our standpoint as we can at least detect the problem and revive the service. It's still quite unsatisfactory of course.

HHVM becomes unresponsive and will not respond to any further HTTP requests. This may be accompanied by CPU usage for the process stuck at 100%. Naturally, this is highly undesirable, as everything deployed on the affected node just goes belly up until someone intervenes.

Possible causes/related issues

8029, #8037 - early reports on -- probably -- the same problem. Since @genych managed to put together an isolated repro without any external dependencies (the previous reports refer to the proprietary software we're working on), I decided to file this separately.

7972, #6500, #6518 look closely related, assuming our hypothesis about asio being the culprit is correct. #7972 includes an isolated, purely local repro. #6518 is marked as closed, but there's a later comment https://github.com/facebook/hhvm/pull/6518#issuecomment-174083842 claiming that the fix is incorrect. This comment may also explain the fact that the repro is more likely to cause crashes when "static remote resource" in part 3 responds very quickly.

If this is indeed caused by asio, that would at least be manageable from our POV. We've already started weeding out all uses of async I/O across the project. It's a letdown, as async I/O was one of the three major reasons for choosing Hack for the project, and it's gonna be a major undertaking, but at least it's something we can "fix" on our side, and unstable web nodes showing the symptoms described above would be a complete deal-breaker.

We'll be trying to narrow down the problem further. I'll report any new findings here.

Source

pbl64k

👍2

Most helpful comment

Are there any alternatives for making async http requests? I mean how is Facebook working around this issue internally?

eryi on 14 Dec 2017

👍6

All 17 comments

Everything does point towards Asio. The problem is not reproducible with synchronous curl in part 2:

https://github.com/pbl64k/burn/tree/sync-curl

It's reproducible using stream_await akin to #7972:

https://github.com/pbl64k/burn/tree/async-file

On one of the runs of the latter the HHVM crash looked a bit different:

Finished singleJitRequest 1
Finished singleJitRequest 2
Finished singleJitRequest 3
Finished singleJitRequest 4
Finished singleJitRequest 5
Finished singleJitRequest 6
Finished singleJitRequest 7
Finished singleJitRequest 8
Finished singleJitRequest 9
Finished singleJitRequest 11
Finished singleJitRequest 10
Finished singleJitRequest 12
Finished singleJitRequest 13
Finished singleJitRequest 14
Finished singleJitRequest 15
Finished singleJitRequest 16
Finished singleJitRequest 17
Finished singleJitRequest 18
Finished singleJitRequest 19
Finished singleJitRequest 20
Finished singleJitRequest 21
Finished singleJitRequest 22
Finished singleJitRequest 23
[err] event_queue_remove: 0x7f44c5196f58(fd 46) not on queue 8
terminate called after throwing an instance of 'std::system_error'
  what():  Resource deadlock avoided
Core dumped: Aborted
Stack trace in /tmp/stacktrace.929.log
Aborted (core dumped)

Host: xub
ProcessID: 929
ThreadID: 139932777576192
ThreadPID: 950
Name: /usr/bin/hhvm
Type: Aborted
Runtime: hhvm
Version: tags/HHVM-3.22.1-0-ge8ce62608d2d14e6418772b07ebaddcbdb37598f
DebuggerCount: 0


# 0  0000000000dd20d6
# 1  00000000011cb452
# 2  00007f44db2b2390
# 3  00007f44d4821428
# 4  00007f44d482302a
# 5  00007f44d516484d
# 6  00007f44d51626b6
# 7  00007f44d51616a9
# 8  00007f44d5162005
# 9  00007f44d4bc5f83
# 10 00007f44d4bc62eb
# 11 00007f44d516290c
# 12 00007f44d518b7fe
# 13 00007f44d518db88
# 14 0000000002ca9103
# 15 00000000013b41dc
# 16 00000000030ad16c
# 17 00007f44d4825ff8
# 18 00007f44d4826045
# 19 00007f44dbd9b4c5
# 20 00007f44dbd9b8b8
# 21 00007f44dbd8732f
# 22 00007f44dbd8abc8
# 23 00000000036d2ee6
# 24 0000000003135c19
# 25 00007f44d518dc80
# 26 00007f44db2a86ba
# 27 00007f44d48f33dd

pbl64k on 9 Nov 2017

I rewrote the repro explicitly using curl_multi_await() instead of \HH\Asio\curl_exec() trying to establish whether this could be related to timeouts on asynchronous awaits:

https://github.com/pbl64k/burn/tree/curl-multi-await

That does not seem to be the case, as the repro still causes crashes when using curl_multi_await() with 0.0 as the second argument. Nonetheless, using this version I observed another variant of deeply disturbing behavior: HHVM will continue to function and serve requests (e.g. it will return phpinfo() page without any issue), but all further calls to curl_multi_await() seem to hang indefinitely until the request is killed:

\nFatal error: entire web request took longer than 5 seconds and timed out in /mnt/hhvm/public_html/git/generic-backoffice/debug/tst/burn/src/burn.hh on line 23
\nFatal error: entire web request took longer than 5 seconds and timed out in /mnt/hhvm/public_html/git/generic-backoffice/debug/tst/burn/src/burn.hh on line 23
\nFatal error: entire web request took longer than 5 seconds and timed out in /mnt/hhvm/public_html/git/generic-backoffice/debug/tst/burn/src/burn.hh on line 23
\nFatal error: entire web request took longer than 5 seconds and timed out in /mnt/hhvm/public_html/git/generic-backoffice/debug/tst/burn/src/burn.hh on line 23
\nFatal error: entire web request took longer than 5 seconds and timed out in /mnt/hhvm/public_html/git/generic-backoffice/debug/tst/burn/src/burn.hh on line 23

Resulting in Service Unavailable HTTP error returned by the server for these requests.

pbl64k on 10 Nov 2017

Identical or closely related to #7485.

pbl64k on 10 Nov 2017

Reproduced on:

HipHop VM 3.22.1 (dbg)
Compiler: tags/HHVM-3.22.1-0-ge8ce62608d2d14e6418772b07ebaddcbdb37598f
Repo schema: 05fc45ee8e70c9f18dfb1e867219c8528be87996

...with gdb attached.

Once hhvm segfaults with:

pure virtual method called
terminate called without an active exception

...thread apply all bt produces this:

[New Thread 0x7f12483ff700 (LWP 31487)]
[New Thread 0x7f1246bfc700 (LWP 31486)]
[New Thread 0x7f1243bfe700 (LWP 31485)]

Thread 13 "hhvm" received signal SIGABRT, Aborted.
[Switching to Thread 0x7f12463fb700 (LWP 10190)]
0x00007f1279245428 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:54
54  ../sysdeps/unix/sysv/linux/raise.c: No such file or directory.
(gdb) thread apply all bt

Thread 21166 (Thread 0x7f1243bfe700 (LWP 31485)):
#0  0x00007f1281ae6378 in ?? () from /usr/lib/x86_64-linux-gnu/libjemalloc.so.1
#1  0x00007f1281b020bf in ?? () from /usr/lib/x86_64-linux-gnu/libjemalloc.so.1
#2  0x00007f1281addb31 in realloc () from /usr/lib/x86_64-linux-gnu/libjemalloc.so.1
#3  0x00007f1279334865 in make_request (pid=10006, fd=27) at ../sysdeps/unix/sysv/linux/check_pf.c:232
#4  __check_pf (seen_ipv4=seen_ipv4@entry=0x7f1243bf9a22, seen_ipv6=seen_ipv6@entry=0x7f1243bf9a23, in6ai=in6ai@entry=0x7f1243bf9a30, 
    in6ailen=in6ailen@entry=0x7f1243bf9a38) at ../sysdeps/unix/sysv/linux/check_pf.c:326
#5  0x00007f12792ff6d1 in __GI_getaddrinfo (name=<optimized out>, service=<optimized out>, hints=<optimized out>, pai=0x7f1243bf9b70) at ../sysdeps/posix/getaddrinfo.c:2477
#6  0x00007f128056eea7 in ?? () from /usr/lib/x86_64-linux-gnu/libcurl.so.4
#7  0x00007f1280579cea in ?? () from /usr/lib/x86_64-linux-gnu/libcurl.so.4
#8  0x00007f128057747b in ?? () from /usr/lib/x86_64-linux-gnu/libcurl.so.4
#9  0x00007f127fccc6ba in start_thread (arg=0x7f1243bfe700) at pthread_create.c:333
#10 0x00007f12793173dd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

Thread 21165 (Thread 0x7f1246bfc700 (LWP 31486)):
#0  0x00007f1281add0b0 in free () from /usr/lib/x86_64-linux-gnu/libjemalloc.so.1
#1  0x00007f12792496ab in __GI___qsort_r (b=b@entry=0x7f1246bf7990, n=n@entry=2, s=s@entry=8, cmp=cmp@entry=0x7f12792fdd50 <rfc3484_sort>, arg=arg@entry=0x7f1246bf7a50)
    at msort.c:299
#2  0x00007f12792ff71e in __GI_getaddrinfo (name=<optimized out>, service=<optimized out>, hints=<optimized out>, pai=<optimized out>)
    at ../sysdeps/posix/getaddrinfo.c:2654
#3  0x00007f128056eea7 in ?? () from /usr/lib/x86_64-linux-gnu/libcurl.so.4
#4  0x00007f1280579cea in ?? () from /usr/lib/x86_64-linux-gnu/libcurl.so.4
#5  0x00007f128057747b in ?? () from /usr/lib/x86_64-linux-gnu/libcurl.so.4
#6  0x00007f127fccc6ba in start_thread (arg=0x7f1246bfc700) at pthread_create.c:333
#7  0x00007f12793173dd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

Thread 21164 (Thread 0x7f12483ff700 (LWP 31487)):
#0  clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:81
#1  0x00007f127fccc5f0 in ?? () at allocatestack.c:289 from /lib/x86_64-linux-gnu/libpthread.so.0
#2  0x00007f12483ff700 in ?? ()
#3  0x0000000000000000 in ?? ()

Thread 13 (Thread 0x7f12463fb700 (LWP 10190)):
#0  0x00007f1279245428 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:54
#1  0x00007f127924702a in __GI_abort () at abort.c:89
#2  0x00007f1279b8884d in __gnu_cxx::__verbose_terminate_handler() () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#3  0x00007f1279b866b6 in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#4  0x00007f1279b86701 in std::terminate() () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#5  0x00007f1279b8723f in __cxa_pure_virtual () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#6  0x0000000008516c3d in folly::EventHandler::libeventCallback (fd=26, events=2, arg=0x7f124541a490)
    at /tmp/tmp.llavvboTck/third-party/folly/src/folly/io/async/EventHandler.cpp:160
#7  0x00007f12807ae4c9 in event_base_loop () from /usr/lib/x86_64-linux-gnu/libevent-2.0.so.5
#8  0x000000000850bd1e in folly::EventBase::loopBody (this=0x7f1250a94e80, flags=0) at /tmp/tmp.llavvboTck/third-party/folly/src/folly/io/async/EventBase.cpp:314
---Type <return> to continue, or q <return> to quit---
#9  0x000000000850b88b in folly::EventBase::loop (this=0x7f1250a94e80) at /tmp/tmp.llavvboTck/third-party/folly/src/folly/io/async/EventBase.cpp:253

#10 0x000000000850cd42 in folly::EventBase::loopForever (this=0x7f1250a94e80) at /tmp/tmp.llavvboTck/third-party/folly/src/folly/io/async/EventBase.cpp:451
#11 0x00000000079e0947 in facebook::memcache::mcrouter::CarbonRouterInstance<facebook::memcache::MemcacheRouterInfo>::createRaw(facebook::memcache::McrouterOptions, std::vector<folly::EventBase*, std::allocator<folly::EventBase*> > const&)::{lambda()#1}::operator()() const (__closure=0x7f1269f848a8)
    at /tmp/tmp.llavvboTck/third-party/mcrouter/src/mcrouter/CarbonRouterInstance-inl.h:191
#12 0x0000000007efd4d0 in std::_Bind_simple<HPHP::AsioEventBase::AsioEventBase()::<lambda()>()>::_M_invoke<>(std::_Index_tuple<>) (this=0x7f1269f848a8)
    at /usr/include/c++/5/functional:1531
#13 0x0000000007efd48e in std::_Bind_simple<HPHP::AsioEventBase::AsioEventBase()::<lambda()>()>::operator()(void) (this=0x7f1269f848a8)
    at /usr/include/c++/5/functional:1520
#14 0x0000000007efd45e in std::thread::_Impl<std::_Bind_simple<HPHP::AsioEventBase::AsioEventBase()::<lambda()>()> >::_M_run(void) (this=0x7f1269f84890)
    at /usr/include/c++/5/thread:115
#15 0x00007f1279bb1c80 in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#16 0x00007f127fccc6ba in start_thread (arg=0x7f12463fb700) at pthread_create.c:333
#17 0x00007f12793173dd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

Thread 7 (Thread 0x7f12553ff700 (LWP 10174)):
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225
#1  0x0000000005e07152 in __gthread_cond_timedwait (__cond=0x7f1268882088, __mutex=0x7f1268882060, __abs_timeout=0x7f12553f92b0)
    at /usr/include/x86_64-linux-gnu/c++/5/bits/gthr-default.h:871
#2  0x0000000005e09012 in std::condition_variable::__wait_until_impl<std::chrono::duration<long, std::ratio<1l, 1000000000l> > > (this=0x7f1268882088, __lock=..., 
    __atime=...) at /usr/include/c++/5/condition_variable:165
#3  0x0000000007ed83f2 in std::condition_variable::wait_until<std::chrono::_V2::steady_clock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > > (
    this=0x7f1268882088, __lock=..., __atime=...) at /usr/include/c++/5/condition_variable:118
#4  0x0000000007ed7fb9 in HPHP::AsioExternalThreadEventQueue::receiveSomeUntil (this=0x7f1268882050, waketime=...)
    at /tmp/tmp.llavvboTck/hphp/runtime/ext/asio/asio-external-thread-event-queue.cpp:101
#5  0x0000000007ed07ff in HPHP::AsioContext::runUntil (this=0x7f126888ec20, wait_handle=0x7f1268882230) at /tmp/tmp.llavvboTck/hphp/runtime/ext/asio/asio-context.cpp:212
#6  0x0000000007efdd5b in HPHP::c_WaitableWaitHandle::join (this=0x7f1268882230) at /tmp/tmp.llavvboTck/hphp/runtime/ext/asio/ext_waitable-wait-handle.cpp:58
#7  0x0000000007ef5605 in HPHP::f_join (obj=...) at /tmp/tmp.llavvboTck/hphp/runtime/ext/asio/ext_asio.cpp:76
#8  0x000000000be00906 in ?? ()
#9  0x000000000be0004f in ?? ()
#10 0x00007f1248401008 in ?? ()
#11 0x00007f12553f9660 in ?? ()
#12 0x00000000070a9c81 in HPHP::jit::enterTCImpl (start=0x100000150 <error: Cannot access memory at address 0x100000150>, stashedAR=0x7f126887ad10)
    at /tmp/tmp.llavvboTck/hphp/runtime/vm/jit/unique-stubs.cpp:1486
Backtrace stopped: previous frame inner to this frame (corrupt stack?)

Thread 6 (Thread 0x7f1255fff700 (LWP 10173)):
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225
#1  0x0000000005e07152 in __gthread_cond_timedwait (__cond=0x7f125a812088, __mutex=0x7f125a812060, __abs_timeout=0x7f1255ff92b0)
    at /usr/include/x86_64-linux-gnu/c++/5/bits/gthr-default.h:871
#2  0x0000000005e09012 in std::condition_variable::__wait_until_impl<std::chrono::duration<long, std::ratio<1l, 1000000000l> > > (this=0x7f125a812088, __lock=..., 
    __atime=...) at /usr/include/c++/5/condition_variable:165
#3  0x0000000007ed83f2 in std::condition_variable::wait_until<std::chrono::_V2::steady_clock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > > (
    this=0x7f125a812088, __lock=..., __atime=...) at /usr/include/c++/5/condition_variable:118
---Type <return> to continue, or q <return> to quit---
#4  0x0000000007ed7fb9 in HPHP::AsioExternalThreadEventQueue::receiveSomeUntil (this=0x7f125a812050, waketime=...)
    at /tmp/tmp.llavvboTck/hphp/runtime/ext/asio/asio-external-thread-event-queue.cpp:101
#5  0x0000000007ed07ff in HPHP::AsioContext::runUntil (this=0x7f125a81ec20, wait_handle=0x7f125a812230) at /tmp/tmp.llavvboTck/hphp/runtime/ext/asio/asio-context.cpp:212
#6  0x0000000007efdd5b in HPHP::c_WaitableWaitHandle::join (this=0x7f125a812230) at /tmp/tmp.llavvboTck/hphp/runtime/ext/asio/ext_waitable-wait-handle.cpp:58
#7  0x0000000007ef5605 in HPHP::f_join (obj=...) at /tmp/tmp.llavvboTck/hphp/runtime/ext/asio/ext_asio.cpp:76
#8  0x000000000be00906 in ?? ()
#9  0x000000000be0004f in ?? ()
#10 0x00007f124c801008 in ?? ()
#11 0x00007f1255ff9660 in ?? ()
#12 0x00000000070a9c81 in HPHP::jit::enterTCImpl (start=0x100000150 <error: Cannot access memory at address 0x100000150>, stashedAR=0x7f125a80ad10)
    at /tmp/tmp.llavvboTck/hphp/runtime/vm/jit/unique-stubs.cpp:1486
Backtrace stopped: previous frame inner to this frame (corrupt stack?)

Thread 5 (Thread 0x7f125a7ff700 (LWP 10172)):
#0  clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:81
#1  0x00007f127fccb14a in create_thread (pd=pd@entry=0x7f12483ff700, attr=attr@entry=0x7f125a7f8f50, stopped_start=<optimized out>, stopped_start@entry=false, 
    stackaddr=<optimized out>, thread_ran=0x7f125a7f8f4f) at ../sysdeps/unix/sysv/linux/createthread.c:102
#2  0x00007f127fccce84 in __pthread_create_2_1 (newthread=<optimized out>, attr=<optimized out>, start_routine=<optimized out>, arg=<optimized out>) at pthread_create.c:679
#3  0x00007f12805774e2 in ?? () from /usr/lib/x86_64-linux-gnu/libcurl.so.4
#4  0x00007f128057a35f in ?? () from /usr/lib/x86_64-linux-gnu/libcurl.so.4
#5  0x00007f128053d89f in ?? () from /usr/lib/x86_64-linux-gnu/libcurl.so.4
#6  0x00007f128055777d in ?? () from /usr/lib/x86_64-linux-gnu/libcurl.so.4
#7  0x00007f1280568493 in ?? () from /usr/lib/x86_64-linux-gnu/libcurl.so.4
#8  0x00007f1280568eed in curl_multi_perform () from /usr/lib/x86_64-linux-gnu/libcurl.so.4
#9  0x0000000007dfaf1e in HPHP::f_curl_multi_exec (mh=..., still_running=...) at /tmp/tmp.llavvboTck/hphp/runtime/ext/curl/ext_curl.cpp:529
#10 0x000000000be02338 in ?? ()
#11 0x00007f124c77fe70 in ?? ()
#12 0x000000000be00716 in ?? ()
#13 0x000000000be0004f in ?? ()
#14 0x00007f1250c01008 in ?? ()
#15 0x00007f125a7f9660 in ?? ()
#16 0x00000000070a9c81 in HPHP::jit::enterTCImpl (start=0x74 <error: Cannot access memory at address 0x74>, stashedAR=0xb2fa4b0 <HPHP::s_theEmptyArray>)
    at /tmp/tmp.llavvboTck/hphp/runtime/vm/jit/unique-stubs.cpp:1486
Backtrace stopped: previous frame inner to this frame (corrupt stack?)

Thread 4 (Thread 0x7f125f3ff700 (LWP 10171)):
#0  clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:81
#1  0x00007f127fccb14a in create_thread (pd=pd@entry=0x7f1246bfc700, attr=attr@entry=0x7f125f3f8f50, stopped_start=<optimized out>, stopped_start@entry=false, 
    stackaddr=<optimized out>, thread_ran=0x7f125f3f8f4f) at ../sysdeps/unix/sysv/linux/createthread.c:102
#2  0x00007f127fccce84 in __pthread_create_2_1 (newthread=<optimized out>, attr=<optimized out>, start_routine=<optimized out>, arg=<optimized out>) at pthread_create.c:679
#3  0x00007f12805774e2 in ?? () from /usr/lib/x86_64-linux-gnu/libcurl.so.4
#4  0x00007f128057a35f in ?? () from /usr/lib/x86_64-linux-gnu/libcurl.so.4
#5  0x00007f128053d89f in ?? () from /usr/lib/x86_64-linux-gnu/libcurl.so.4
#6  0x00007f128055777d in ?? () from /usr/lib/x86_64-linux-gnu/libcurl.so.4
---Type <return> to continue, or q <return> to quit---
#7  0x00007f1280568493 in ?? () from /usr/lib/x86_64-linux-gnu/libcurl.so.4
#8  0x00007f1280568eed in curl_multi_perform () from /usr/lib/x86_64-linux-gnu/libcurl.so.4
#9  0x0000000007dfaf1e in HPHP::f_curl_multi_exec (mh=..., still_running=...) at /tmp/tmp.llavvboTck/hphp/runtime/ext/curl/ext_curl.cpp:529
#10 0x000000000be02338 in ?? ()
#11 0x00007f125aabfe70 in ?? ()
#12 0x000000000be00716 in ?? ()
#13 0x000000000be0004f in ?? ()
#14 0x00007f1256001008 in ?? ()
#15 0x00007f125f3f9660 in ?? ()
#16 0x00000000070a9c81 in HPHP::jit::enterTCImpl (start=0x7a7a7a7a7a7a7a7a <error: Cannot access memory at address 0x7a7a7a7a7a7a7a7a>, stashedAR=0x7a7a7a7a7a7a7a7a)
    at /tmp/tmp.llavvboTck/hphp/runtime/vm/jit/unique-stubs.cpp:1486
Backtrace stopped: previous frame inner to this frame (corrupt stack?)

Thread 3 (Thread 0x7f125fbff700 (LWP 10170)):
#0  clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:81
#1  0x00007f127fccb14a in create_thread (pd=pd@entry=0x7f1243bfe700, attr=attr@entry=0x7f125fbf8f50, stopped_start=<optimized out>, stopped_start@entry=false, 
    stackaddr=<optimized out>, thread_ran=0x7f125fbf8f4f) at ../sysdeps/unix/sysv/linux/createthread.c:102
#2  0x00007f127fccce84 in __pthread_create_2_1 (newthread=<optimized out>, attr=<optimized out>, start_routine=<optimized out>, arg=<optimized out>) at pthread_create.c:679
#3  0x00007f12805774e2 in ?? () from /usr/lib/x86_64-linux-gnu/libcurl.so.4
#4  0x00007f128057a35f in ?? () from /usr/lib/x86_64-linux-gnu/libcurl.so.4
#5  0x00007f128053d89f in ?? () from /usr/lib/x86_64-linux-gnu/libcurl.so.4
#6  0x00007f128055777d in ?? () from /usr/lib/x86_64-linux-gnu/libcurl.so.4
#7  0x00007f1280568493 in ?? () from /usr/lib/x86_64-linux-gnu/libcurl.so.4
#8  0x00007f1280568eed in curl_multi_perform () from /usr/lib/x86_64-linux-gnu/libcurl.so.4
#9  0x0000000007dfaf1e in HPHP::f_curl_multi_exec (mh=..., still_running=...) at /tmp/tmp.llavvboTck/hphp/runtime/ext/curl/ext_curl.cpp:529
#10 0x000000000be02338 in ?? ()
#11 0x00007f1268bbfe70 in ?? ()
#12 0x000000000be00716 in ?? ()
#13 0x000000000be0004f in ?? ()
#14 0x00007f125ac01008 in ?? ()
#15 0x00007f125fbf9660 in ?? ()
#16 0x00000000070a9c81 in HPHP::jit::enterTCImpl (start=0x7a7a7a7a7a7a7a7a <error: Cannot access memory at address 0x7a7a7a7a7a7a7a7a>, stashedAR=0x7a7a7a7a7a7a7a7a)
    at /tmp/tmp.llavvboTck/hphp/runtime/vm/jit/unique-stubs.cpp:1486
#17 0x000000000be00c4c in ?? ()
#18 0x00007f126fb80200 in ?? ()
#19 0x0000000200000091 in ?? ()
#20 0x00007f125540ad10 in ?? ()
#21 0x0000000000000000 in ?? ()

Thread 2 (Thread 0x7f12687ff700 (LWP 10008)):
#0  0x00007f12793179d3 in epoll_wait () at ../sysdeps/unix/syscall-template.S:84
#1  0x00007f12807c3b18 in ?? () from /usr/lib/x86_64-linux-gnu/libevent-2.0.so.5
#2  0x00007f12807ade2d in event_base_loop () from /usr/lib/x86_64-linux-gnu/libevent-2.0.so.5
#3  0x000000000850bd1e in folly::EventBase::loopBody (this=0x7f1269ceeb40, flags=0) at /tmp/tmp.llavvboTck/third-party/folly/src/folly/io/async/EventBase.cpp:314
---Type <return> to continue, or q <return> to quit---
#4  0x000000000850b88b in folly::EventBase::loop (this=0x7f1269ceeb40) at /tmp/tmp.llavvboTck/third-party/folly/src/folly/io/async/EventBase.cpp:253
#5  0x000000000850cd42 in folly::EventBase::loopForever (this=0x7f1269ceeb40) at /tmp/tmp.llavvboTck/third-party/folly/src/folly/io/async/EventBase.cpp:451
#6  0x0000000008833798 in proxygen::WorkerThread::runLoop (this=0x7f1269ceeb00) at /tmp/tmp.llavvboTck/third-party/proxygen/src/proxygen/lib/services/WorkerThread.cpp:140
#7  0x0000000008832d1a in proxygen::WorkerThread::<lambda()>::operator()(void) (__closure=0x7f1269ee6248)
    at /tmp/tmp.llavvboTck/third-party/proxygen/src/proxygen/lib/services/WorkerThread.cpp:44
#8  0x000000000883478e in std::_Bind_simple<proxygen::WorkerThread::start()::<lambda()>()>::_M_invoke<>(std::_Index_tuple<>) (this=0x7f1269ee6248)
    at /usr/include/c++/5/functional:1531
#9  0x000000000883474c in std::_Bind_simple<proxygen::WorkerThread::start()::<lambda()>()>::operator()(void) (this=0x7f1269ee6248) at /usr/include/c++/5/functional:1520
#10 0x000000000883471c in std::thread::_Impl<std::_Bind_simple<proxygen::WorkerThread::start()::<lambda()>()> >::_M_run(void) (this=0x7f1269ee6230)
    at /usr/include/c++/5/thread:115
#11 0x00007f1279bb1c80 in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#12 0x00007f127fccc6ba in start_thread (arg=0x7f12687ff700) at pthread_create.c:333
#13 0x00007f12793173dd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

Thread 1 (Thread 0x7f1281ee6a40 (LWP 10006)):
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1  0x0000000005421754 in HPHP::Synchronizable::wait (this=0x7f1269d3a610) at /tmp/tmp.llavvboTck/hphp/util/synchronizable.cpp:38
#2  0x0000000005d98b9c in HPHP::HttpServer::runOrExitProcess (this=0x7f1269d3a610) at /tmp/tmp.llavvboTck/hphp/runtime/server/http-server.cpp:372
#3  0x0000000005bb4c40 in HPHP::start_server (username="", xhprof=0) at /tmp/tmp.llavvboTck/hphp/runtime/base/program-functions.cpp:1142
#4  0x0000000005bb9809 in HPHP::execute_program_impl (argc=5, argv=0x7fff61e43778) at /tmp/tmp.llavvboTck/hphp/runtime/base/program-functions.cpp:1991
#5  0x0000000005bb568a in HPHP::execute_program (argc=5, argv=0x7fff61e43778) at /tmp/tmp.llavvboTck/hphp/runtime/base/program-functions.cpp:1200
#6  0x0000000005119a4a in main (argc=5, argv=0x7fff61e43778) at /tmp/tmp.llavvboTck/hphp/hhvm/main.cpp:85
(gdb)

pbl64k on 10 Nov 2017

...and what does CarbonRouterInstance have to do with this or #7972?

pbl64k on 10 Nov 2017

Any news on this?
It could explain why something weird happened on our production servers.
Do you know if 3.22 or 3.23 fixes that?

Rowern on 13 Dec 2017

Sorry, I'm unable to check this myself. We're currently on 3.21.3. 3.22.1 is definitely affected. If you have a 3.23 available, you can easily check this yourself, #7972 has a simple local repro.

I haven't heard any news on this, and I don't believe it's likely to be fixed any time soon. This (or closely related) problem has first been reported over a year ago, and I've yet to see any meaningful response from Facebook staff in any of the seemingly related tasks I've been able to dig up. Apparently, their own deployments are either unaffected, or they're employing some kind of workaround that suffices for their particular circumstances, and just random segfaults are not a FIX YESTERDAY priority for the dev team.

The problem is almost certainly a race condition somewhere in the wrappers around libevent, at least segfaults seem to be triggered when libevent hits the handler that has either been deallocated already or is in the process of being destroyed. Unfortunately, I'm not conversant enough with the mysteries of multi-threaded C++ to track it down from there on my own. I hoped the problem was in hphp/runtime/base/file-await.cpp but that does not seem to be the case, judging by my attempts to identify the cause by leaving out stuff in FileAwait's constructor and destructor. It could even be in facebook/folly rather than hhvm itself.

While Asio is definitely affected, it might not be sole culprit. We stopped using async I/O altogether, but we've started seeing similar symptoms - segfaults and hhvm process just becoming unresponsive - about a week ago once again.

Frankly, at this point I really regret having advocated Hack for one my projects. We have a mission critical project running on HHVM, we can't even make sure our nodes crash gracefully if they do crash, and no one gives a damn. Lose it if you still can. @fredemmott, I recall you were interested in hearing stories from industrial adopters. Here's how mine goes so far.

pbl64k on 13 Dec 2017

👍3 ❤1

stream_await and asio curl_exec are known to be problematic; we're honestly having trouble to decide on if we should 'properly' fix curl_exec, or just reimplement it as a wrapper around curl_multi + reschedulewaithandle - the latter actually ends up being more performant in most workloads we try.

ASIO in general is solid, but these two functions, not so much.

fredemmott on 13 Dec 2017

There's also that while yes, we're far behind where we want to be on issues generally, issues that don't include a small, isolated, inline example are at the bottom of the pile, as the time-to-investigate vs benefit-of-fixing is in general much lower.

fredemmott on 13 Dec 2017

I've only recently got back on the team - I'll take a quick look at this + stream_await when I've finished my current work; my guess (without looking at the code/traces, just history of this kind of bug) is that we're running cleanup via the job queue, rather than blocking - so some of the memory may have been freed before the cleanup code is executed.

fredemmott on 13 Dec 2017

🎉2

8037 looks unrelated

fredemmott on 13 Dec 2017

Are there any alternatives for making async http requests? I mean how is Facebook working around this issue internally?

eryi on 14 Dec 2017

👍6

Oops, my bad, #8037 probably is unrelated. We spent ~four weeks trying to narrow down the problem before we got to the stage of repro I originally posted here, and we've run into a few other issues along the way. #8037 is one of them, unfortunately, I don't think we can repro it.

ASIO in general is solid

I understand that folly::EventHandler is not used for MySQL and memcached? I can't help but suspect it must be EventHandler itself.

I'll take a quick look at this + stream_await when I've finished my current work

I'm really glad to hear that.

issues that don't include a small, isolated, inline example are at the bottom of the pile, as the time-to-investigate vs benefit-of-fixing is in general much lower.

It's obviously a value judgement, but the stream_await repro in #7972 is probably as good as it could get for an issue like this, and HHVM just ceasing to serve requests without even terminating, normally or abnormally, is about as nasty an effect as I can imagine.

pbl64k on 14 Dec 2017

Are there any alternatives for making async http requests? I mean how is Facebook working around this issue internally?

We use curl_multi_select() with no timeout in a loop with the equivalent of await HH\Asio\Later(); this wasn't actually a workaround, we're primarily doing this as for our loads, it appears that the overhead of doing it in another thread (like HH\Asio\curl* do) is more than the gains.

I might 'fix' this by changing HH\Asio\curl* to just be exactly that, no native functions.

fredemmott on 15 Dec 2017

❤1