Hhvm: Frequent crashes after upgrading to 3.17.0

[Nikerabbit]

HHVM Version

3.17.0

Standalone code, or other way to reproduce the problem

Unknown so far.

Expected result

No crash.

Actual result

Host: translatewiki.net
ProcessID: 16047
ThreadID: 140243940407040
ThreadPID: 16082
Name: unknown program
Type: Aborted
Runtime: hhvm
Version: tags/HHVM-3.17.0-0-ga34af693b558ed98ffafc3f5127e00959e145e4f
DebuggerCount: 0

Assertion Failure: /tmp/tmp.2lmoaUGFKy/hphp/runtime/base/program-functions.cpp:2305: void HPHP::hphp_memory_cleanup(): assertion `g_context.isNull() || !g_context->hasRequestEventHandlers()' failed.

# 0  00000000033bb886
# 1  000000000146b892
# 2  00007f8d82c7b330
# 3  00007f8d7d9c6c37
# 4  00007f8d7d9ca028
# 5  0000000000db9439
# 6  0000000001327dd6
# 7  00000000033b3ae5
# 8  00000000015f1e06
# 9  00000000015f247e
# 10 00000000015e7e76
# 11 0000000000db9667
# 12 0000000001481427
# 13 00007f8d82c73184
# 14 00007f8d7da8a37d

PHP Stacktrace:

It is very frequent:

-rw------- 1 www-data www-data  770 Dec 23 19:17 stacktrace.28076.log
-rw------- 1 www-data www-data  770 Dec 23 19:18 stacktrace.28422.log
-rw------- 1 www-data www-data  770 Dec 23 19:24 stacktrace.28449.log
-rw------- 1 www-data www-data  770 Dec 23 19:26 stacktrace.28533.log
-rw------- 1 www-data www-data  770 Dec 23 19:27 stacktrace.28591.log
-rw------- 1 www-data www-data  770 Dec 23 19:28 stacktrace.27718.log
-rw------- 1 www-data www-data  770 Dec 23 19:28 stacktrace.28678.log
-rw------- 1 www-data www-data  770 Dec 23 19:30 stacktrace.28735.log
-rw------- 1 www-data www-data  770 Dec 23 19:35 stacktrace.28782.log
-rw------- 1 www-data www-data  770 Dec 23 19:42 stacktrace.28889.log
-rw------- 1 www-data www-data  770 Dec 23 20:04 stacktrace.29011.log
-rw------- 1 www-data www-data  770 Dec 23 20:10 stacktrace.29592.log
-rw------- 1 www-data www-data  770 Dec 23 20:23 stacktrace.29683.log
-rw------- 1 www-data www-data  770 Dec 23 20:43 stacktrace.29913.log
-rw------- 1 www-data www-data  770 Dec 23 20:48 stacktrace.30256.log
-rw------- 1 www-data www-data  770 Dec 23 20:48 stacktrace.31000.log
-rw------- 1 www-data www-data  770 Dec 23 20:49 stacktrace.28721.log
-rw------- 1 www-data www-data  770 Dec 23 20:49 stacktrace.32222.log
-rw------- 1 www-data www-data  770 Dec 23 21:16 stacktrace.32262.log
-rw------- 1 www-data www-data  768 Dec 23 21:26 stacktrace.1054.log
-rw------- 1 www-data www-data  768 Dec 23 21:45 stacktrace.1332.log
-rw------- 1 www-data www-data  768 Dec 23 21:45 stacktrace.1600.log
-rw------- 1 www-data www-data  768 Dec 23 21:46 stacktrace.1651.log
-rw------- 1 www-data www-data  768 Dec 23 21:51 stacktrace.1693.log
-rw------- 1 www-data www-data  770 Dec 23 21:51 stacktrace.15418.log
-rw------- 1 www-data www-data  770 Dec 23 21:53 stacktrace.15451.log
-rw------- 1 www-data www-data  770 Dec 23 21:54 stacktrace.15503.log
-rw------- 1 www-data www-data  770 Dec 23 21:54 stacktrace.15519.log
-rw------- 1 www-data www-data  770 Dec 23 22:00 stacktrace.15719.log
-rw------- 1 www-data www-data  770 Dec 23 22:05 stacktrace.15966.log
-rw------- 1 www-data www-data  769 Dec 23 22:05 stacktrace.32242.log
-rw------- 1 www-data www-data  770 Dec 23 22:31 stacktrace.16047.log
-rw------- 1 www-data www-data  766 Dec 23 22:31 stacktrace.354.log
-rw------- 1 www-data www-data  768 Dec 23 22:43 stacktrace.1614.log

I'm running MediaWiki, HHVM config is at

• https://github.com/wikimedia/translatewiki/blob/master/puppet/modules/hhvm/files/php.ini
• https://github.com/wikimedia/translatewiki/blob/master/puppet/modules/hhvm/files/server.ini

[edwardspec]

Having the same problem, and also with MediaWiki.

[mofarrell]

@Nikerabbit if you could get a backtrace using the debug packages (with symbols), that would be great. Also let me know if this is blocking you guys. I assume 3.15 is still working fine though.

[Nikerabbit]

I ran with hhvm-dbg a bit, but the backtrace was still empty. I then attached gdb for a while, but no crash happened (maybe it is a race and gdb makes it less likely?). A crash happened soon after I detached gdb. Now I am trying to get core dump to see if I can get a trace from that.

3.15 would probably be working, if I could install it somehow.

[Nikerabbit]

Does this help to debug this problem?
https://etherpad.wikimedia.org/p/8meqGIhXOi

Curiously I also got some more into in stacktrace file. But the assertion seems different, so is this the same crash?
https://etherpad.wikimedia.org/p/qig7nwzkN6

Anyway, here is a trace for a stacktrace file containing the same assertion as originally reported:
https://etherpad.wikimedia.org/p/bI7FIB5tjF

[paulbiss]

Looks like we encountered this as well (t14942662 and D4298341 for any curious fb folks). The fix appears to be 85dfe682b13d127cda773579a55c67fa5a57b7c4

If you can confirm this also fixes your crashes we can cherry-pick it into 3.17.1

[alex-mashin]

I can confirm this bug on a non-WikiMedia project.

If you can confirm this also fixes your crashes we can cherry-pick it into 3.17.1

You definitely should.

[alex-mashin]

And we need a workaround; urgently.
Unfortunately, downgrading is no option, as hhvm-dev 3.15 is broken in its own way.

[alex-mashin]

3.15 would probably be working, if I could install it somehow.

Most probably, you will not be able to compile luasandbox under hhvm-dev 3.15.

[alex-mashin]

Looks like we encountered this as well (t14942662 and D4298341 for any curious fb folks). The fix appears to be 85dfe68
If you can confirm this also fixes your crashes we can cherry-pick it into 3.17.1

git cherry-pick 85dfe682b13d127cda773579a55c67fa5a57b7c4 on master branch:
fatal: bad object 85dfe682b13d127cda773579a55c67fa5a57b7c4.

[paulbiss]

You may need to do a pull? It's definitely in the repository.

[alex-mashin]

If you can confirm this also fixes your crashes

I gave up the attempts to compile after:

In file included from /usr/include/ImageMagick-6/wand/MagickWand.h:29:0,
                 from (skipped)/dev/hhvm/hphp/runtime/ext/imagick/ext_imagick.h:25,
                 from (skipped)/dev/hhvm/hphp/runtime/ext/imagick/constants.cpp:19:
/usr/include/ImageMagick-6/magick/magick-config.h:21:38: fatal error: magick/magick-baseconfig.h: No such file or directory
 #include "magick/magick-baseconfig.h"

[mofarrell]

@alex-mashin Are you able to build without the patch? It seems like you might not have all the build dependencies installed. In this case libmagickwand-dev. See here for the rest.

[mofarrell]

The changes paul mentioned should be cherrypicked into 3.17.1 comment here if this continues to be an issue, and I will reopen.

[anoakie]

Still getting the same issue in tags/HHVM-3.17.1-0-gdb3429c2130e5f7539bfd550c27a6bea9444b669

Host: hostname
ProcessID: 1848220
ThreadID: 139865450608384
ThreadPID: 1848280
Name: unknown program
Type: Aborted
Runtime: hhvm
Version: tags/HHVM-3.17.1-0-gdb3429c2130e5f7539bfd550c27a6bea9444b669
DebuggerCount: 0

Assertion Failure: /tmp/tmp.WpghdUtCKE/hphp/runtime/base/program-functions.cpp:2305: void HPHP::hphp_memory_cleanup(): assertion `g_context.isNull() || !g_context->hasRequestEventHandlers()' failed.

# 0  0000000003446b66
# 1  00000000010aa432
# 2  00007f350d1d8390
# 3  00007f3507d16428
# 4  00007f3507d1802a
# 5  0000000000d6b7b4
# 6  000000000136731d
# 7  0000000003441e02
# 8  000000000158133d
# 9  0000000001581cf2
# 10 0000000000d855d3
# 11 000000000131a296
# 12 00007f350d1ce6ba
# 13 00007f3507de782d

PHP Stacktrace:

[alex-mashin]

Still the same issue in 3.17.1.

[alex-mashin]

And in 3.17.2.

[alex-mashin]

I git pull'ed and git submodule update --init --recursive'ed the source code and tried to build again.
This time the error was:
```Finished, 30 targets (0 cached) in 00:00:04.

• /home/alexander/dev/hhvm/third-party/ocaml/build/bin/ocamlc.opt -c -g -w A -w -3-4-6-29-35-44-48-50-52 -I ide_rpc -I search -I decl -I client -I naming -I stubs -I recorder -I options -I dfind -I typing -I debug -I globals -I format -I server -I hhi -I parsing -I heap -I watchman -I h2tp -I full_fidelity -I utils -I libancillary -I hh_matcher -I deps -I fsnotify_linux -I monitor -I emitter -I socket -I procs -I find -I injection/default_injector -I h2tp/mapper -I h2tp/unparser -I h2tp/common -I full_fidelity/schema -I utils/hh_json -I utils/collections -I utils/disk -I hh_matcher/test -I third-party/core -I third-party/inotify -I third-party/avl -o ide_rpc/ide_message.cmo ide_rpc/ide_message.ml
  File "ide_rpc/ide_message.ml", line 1:
  Error: server/symbolOccurrence.cmi
  is not a compiled interface for this version of OCaml.
  It seems to be for an older version of OCaml.
  Command exited with code 2.
  Compilation unsuccessful after building 433 targets (153 cached) in 00:00:28.
  Makefile:175: recipe for target '_build/hh_server.native' failed
  make[3]: * [_build/hh_server.native] Error 10
  hphp/hack/CMakeFiles/hack.dir/build.make:57: recipe for target 'hphp/hack/CMakeFiles/hack' failed
  make[2]: [hphp/hack/CMakeFiles/hack] Error 2
  CMakeFiles/Makefile2:1472: recipe for target 'hphp/hack/CMakeFiles/hack.dir/all' failed
  make[1]: [hphp/hack/CMakeFiles/hack.dir/all] Error 2
  Makefile:127: recipe for target 'all' failed
  make: * [all] Error 2
  ```

[aorenste]

@alex-mashin That error means that you're trying to mix build files from the old version of ocaml with build files from the new version of ocaml. Make sure to completely clean your tree:

git clean -dfx
rm -rf third-party
git submodule update --init --recursive
cmake .
make

[alex-mashin]

Done all this; still the same error.

[paulbiss]

That error looks like it's complaining about build artifacts in the hphp/hack/src directory. We recently changed the required version of ocaml, and the ocaml build has been notoriously bad about cleaning up stale artifacts...

[mofarrell]

The git clean -fdx should remove all the untracked files including the build artifacts in hphp/hack/src
Its worth noting that symbolOccurrence.ml was moved into src/utils from src/server. So builds should not produce a server/symbolOccurrence.cmi file.

[Norbyte]

I've managed to reproduce the same crash on my machine (HHVM 3.18.0). It seems to be triggered by the hhvm.server.stat_cache = true config option, as it doesn't crash (or at least crashes with a different stack trace) when the stat cache is disabled.

Trace and message:

Assertion failure: /home/norbyte/hhvm/hhvm-3.18/hhvm/hphp/runtime/base/program-functions.cpp:2319: void HPHP::hphp_memory_cleanup(): assertion `g_context.isNull() || !g_context->hasRequestEventHandlers()' failed.

Program received signal SIGABRT, Aborted.
[Switching to Thread 0x7fffd53ff700 (LWP 6780)]
0x00007fffef9b41d7 in raise () from /lib64/libc.so.6
(gdb) bt
#0  0x00007fffef9b41d7 in raise () from /lib64/libc.so.6
#1  0x00007fffef9b58c8 in abort () from /lib64/libc.so.6
#2  0x0000000000d9b189 in HPHP::assert_fail(char const*, char const*, unsigned int, char const*, std::string const&) ()
#3  0x0000000001361422 in HPHP::hphp_session_exit() ()
#4  0x0000000003455235 in HPHP::HttpRequestHandler::teardownRequest(HPHP::Transport*) ()
#5  0x000000000161df46 in HPHP::ServerWorker<std::shared_ptr<HPHP::FastCGIJob>, HPHP::FastCGITransportTraits>::doJobImpl(std::shared_ptr<HPHP::FastCGIJob>, bool) ()
#6  0x000000000161e5be in HPHP::ServerWorker<std::shared_ptr<HPHP::FastCGIJob>, HPHP::FastCGITransportTraits>::doJob(std::shared_ptr<HPHP::FastCGIJob>) ()
#7  0x000000000160a9e6 in HPHP::JobQueueWorker<std::shared_ptr<HPHP::FastCGIJob>, HPHP::Server*, true, false, HPHP::JobQueueDropVMStack>::start() ()
#8  0x0000000000d9b3b7 in HPHP::AsyncFuncImpl::ThreadFunc(void*) ()
#9  0x000000000142ae97 in HPHP::start_routine_wrapper(void*) ()
#10 0x00007ffff559fdc5 in start_thread () from /lib64/libpthread.so.0
#11 0x00007fffefa7673d in clone () from /lib64/libc.so.6

Update: I can reproduce this crash (at least using our codebase) almost everytime with an ab -c 10 -n 10000 http://<url> benchmark.

[alex-mashin]

I confirm that after setting hhvm.server.stat_cache = false HHVM 3.18.0 under Yakkety stopped crashing.

[alex-mashin]

This info might be useful: the crashes happen (with hhvm.server.stat_cache = true) especially often when _MediaWiki_ extension _Syntaxhighlight_, which uses _pygment_ library, is invoked, i.e. while rendering, saving or editing pages in _MediaWiki_ and _Module_ namespaces. The probability of crash, if hhvm service was started more than a couple of seconds ago, is about 100%.

The _ResourceLoader_, which bundles styles and scripts, also crashes HHVM rather often.

Can it be because there is not enough memory for stat_cache?

[Nikerabbit]

Is there any interaction with stat_cache and streams? Since pygments came up I am thinking whether https://phabricator.wikimedia.org/T151523 is related.

[Reasno]

Thanks for sharing this. I had the same problem with hhvm 3.18 & mediawiki. Turning off stat_cache servers us well for now.

[azmng]

We've got the same issue with 3.18.1
Turning off hhvm.server.stat_cache works around the problem but leads to significantly higher SYS CPU usage because of constant uncached stat() calls.

[mofarrell]

Does anyone have a better repro case than run with my codebase and issue a ton of requests?

[mmuehlenhoff]

@mofarrell I don't have a trimmed down reproducer, but if you're interested I can provide you with SSH access to the Wikimedia Beta Cluster, which runs mediawiki on HHVM 3.18.1 and which exhibits the problem. If you're interested, please contact me at [email protected]

[mofarrell]

I have managed to find a repro, and bisect it back to a change. I have ideas about why it might be happening, but can't find exactly what is causing it.

[mofarrell]

A fix is on its way.

[mofarrell]

Let me know if there are any more issues with this on master.

[mmuehlenhoff]

@mofarrell Thanks for the fix! I upgraded the Wikimedia Beta cluster to 3.18.1 with your fix cherrypicked from master and I can confirm it's effective: Previously we had about 10 crashes per hour and by now we've been running this for 15 hours without the error having reoccured. Since this also affects the 3.18 LTS series, it would be really nice if that patch could also be merged into 3.18.2.

[mofarrell]

I will see what I can do. Should be no problem.