FrankenPHP crashes on high loads

[mo7zayed]

Octane Version

v2.2.5

Laravel Version

10.38.2

PHP Version

8.2.13

What server type are you using?

FrankenPHP

Server Version

v1.0.1

Database Driver & Version

No response

Description

When I run a load test a fresh laravel app using apache utils tools ab the server suddenly caches. for example

pc@pc:~$ ab -n 100 -c 10 http://127.0.0.1:8000/
This is ApacheBench, Version 2.3 <$Revision: 1879490 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking 127.0.0.1 (be patient)...apr_socket_recv: Connection refused (111)
Total of 11 requests completed

This issue happens when the concurrency is high, when running 10 times the number of requests with low concurrency I get great results, Note that this scenario doesn't always happen, It happens randomly when load testing with high concurrency

pc@pc:~$ ab -n 1000 -c 1 http://127.0.0.1:8000/
This is ApacheBench, Version 2.3 <$Revision: 1879490 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking 127.0.0.1 (be patient)
Completed 100 requests
Completed 200 requests
Completed 300 requests
Completed 400 requests
Completed 500 requests
Completed 600 requests
Completed 700 requests
Completed 800 requests
Completed 900 requests
Completed 1000 requests
Finished 1000 requests

Server Software:        Caddy
Server Hostname:        127.0.0.1
Server Port:            8000

Document Path:          /
Document Length:        27514 bytes

Concurrency Level:      1
Time taken for tests:   4.885 seconds
Complete requests:      1000
Failed requests:        0
Total transferred:      28621000 bytes
HTML transferred:       27514000 bytes
Requests per second:    204.72 [#/sec] (mean)
Time per request:       4.885 [ms] (mean)
Time per request:       4.885 [ms] (mean, across all concurrent requests)
Transfer rate:          5721.89 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.0      0       0
Processing:     1    5  36.6      1     399
Waiting:        1    1   0.7      1      11
Total:          1    5  36.6      1     399

Percentage of the requests served within a certain time (ms)
  50%      1
  66%      1
  75%      1
  80%      1
  90%      1
  95%      2
  98%      5
  99%    161
 100%    399 (longest request)

While debugging this, I noticed when running ./frankenphp -v I see that the used php version is 8.3.0 while my local php version is used to serve the application is 8.2.13

Steps To Reproduce

Here is a github repo containing a fresh laravel app with latest octane installed, just pull and run the following commands

• composer i
• cp .env.example .env
• php artisan key:generate
• php artisan octane:install --server=frankenphp
• php artisan octane:start --server=frankenphp

Then in another terminal tab run ab -n 1000 -c 10 http://127.0.0.1:8000/

https://github.com/mo7zayed/frankenphp-issue

[sneycampos]

Could be a problem in Octane? i've faced a problem something like: call a endpoint with sleep(30) multiple times (using insomnia plugin to parallel calls or chrome tab groups) Octane stopped to respond for a few seconds and crashed (supervisord spinned up again)

Think is related to worker numbers, if you get more requests and there aren't workers available to process the request it "stops"

Tried with 10 workers and crashed Tried with 50 workers and received 100% of requests

@binaryfire could you increase your octane workers and run the tests again? something like 20 workers? It's recommended 1 worker per core but...

[dunglas]

Thanks to the help of @binaryfire, I managed to reproduce on a Linux box.

This is a problem with the OpenSSL PHP extension, which doesn't look directly to FrankenPHP. As a workaround, using the Docker image instead of the static build seems to fix the issue.

Here is the stack trace:

Stack trace

``` #1 0x0000783330654ec3 in __libc_free (p=0x7832da600cb0) at src/malloc/mallocng/free.c:105 #2 0x000078332fef89f0 in EVP_CIPHER_CTX_reset () #3 0x000078332f15bf83 in php_openssl_encrypt (data=0x7832d67946a8 "cdcfc94a44f1372ecc088f6e0abca9d4c1416db0|XFaOVGRiKdwkZpamJ3fb2fXpv4vvguazIfVNxK8R", data_len=81, method=0x7832d7995220 "aes-256-cbc", method_len=11, password=0x7832d67acd88 "\036\216/a\363-\257e\332Wu㖂&\033%\341\307\036O\243hOX(\257\204\346j\334\t", password_len=32, options=0, iv=0x7832d6686558 "\\\226\024Y\204:#b\276+1b\332\034%\225", iv_len=16, tag=0x7832d7818a40, tag_len=16, aad=0x783330d21ef5 "", aad_len=0) at /go/src/app/dist/static-php-cli/source/php-src/ext/openssl/openssl.c:7700 #4 0x000078332f15c126 in zif_openssl_encrypt (execute_data=0x7832d78189a0, return_value=0x7832d7818970) at /go/src/app/dist/static-php-cli/source/php-src/ext/openssl/openssl.c:7719 #5 0x000078332ef7351f in ZEND_DO_ICALL_SPEC_RETVAL_USED_HANDLER () at /go/src/app/dist/static-php-cli/source/php-src/Zend/zend_vm_execute.h:1337 #6 execute_ex (ex=0x7832d78171d0) at /go/src/app/dist/static-php-cli/source/php-src/Zend/zend_vm_execute.h:57216 #7 0x000078332edcfec2 in zend_call_function (fci=0x7832dafe9720, fci_cache=0x7832dafe96f0) at /go/src/app/dist/static-php-cli/source/php-src/Zend/zend_execute_API.c:957 #8 0x000078332eca9591 in zif_frankenphp_handle_request (execute_data=, return_value=0x7832d7817140) at frankenphp.c:371 #9 0x000078332ef7351f in ZEND_DO_ICALL_SPEC_RETVAL_USED_HANDLER () at /go/src/app/dist/static-php-cli/source/php-src/Zend/zend_vm_execute.h:1337 #10 execute_ex (ex=0x7832d7817020) at /go/src/app/dist/static-php-cli/source/php-src/Zend/zend_vm_execute.h:57216 #11 0x000078332ef908a7 in zend_execute (op_array=0x7832d7866000, return_value=0x0) at /go/src/app/dist/static-php-cli/source/php-src/Zend/zend_vm_execute.h:61604 #12 0x000078332edfca5c in zend_execute_scripts (type=8, retval=0x0, file_count=3) at /go/src/app/dist/static-php-cli/source/php-src/Zend/zend.c:1881 #13 0x000078332ed3d05a in php_execute_script (primary_file=0x7832dafef660) at /go/src/app/dist/static-php-cli/source/php-src/main/main.c:2523 #14 0x000078332ecaa4f1 in frankenphp_execute_script (file_name=0x7832d946ab00 "4b48bc1af71891ab467ffde5c30d1b724928ab8c9dee168d597ce7f9e1dc9498") at frankenphp.c:825 #15 0x000078332eca7c37 in _cgo_d49d0ae4a108_Cfunc_frankenphp_execute_script (v=0xc000810dd8) at /tmp/go-build/cgo-gcc-prolog:55 #16 0x000078332d966a01 in runtime.asmcgocall () at /usr/local/go/src/runtime/asm_amd64.s:918 #17 0x000000c0008016c0 in ?? () #18 0x00007832dafef7d0 in ?? () #19 0x00007832dafef834 in ?? () #20 0x0000000000000000 in ?? () ```

[binaryfire]

@dunglas Yep, I'm seeing the same thing. Here's the stack trace from one of my bare metal servers:

Thread 15 "thpool-0" received signal SIGSEGV, Segmentation fault.
[Switching to LWP 2433692]
get_meta (p=p@entry=0x7f41742bbcb0 "HTTP/1.0") at src/malloc/mallocng/meta.h:141
141     src/malloc/mallocng/meta.h: No such file or directory.
(gdb) bt
#0  get_meta (p=p@entry=0x7f41742bbcb0 "HTTP/1.0") at src/malloc/mallocng/meta.h:141
#1  0x00007f41ca5b7ec3 in __libc_free (p=0x7f41742bbcb0) at src/malloc/mallocng/free.c:105
#2  0x00007f41c9e5b9f0 in EVP_CIPHER_CTX_reset ()
#3  0x00007f41c90bef83 in php_openssl_encrypt (data=0x7f41749ec478 "392bde1585ab0bd096105de5526b9a82c44ac7b1|WsQYiV8jNxq8upssNbiRPvSaWTTu5OWmoi2F9zR7", data_len=81, method=0x7f4174804f40 "aes-256-cbc", method_len=11,
    password=0x7f4172fc3d38 "#\031\067\352\032\030\343\224\355\263{\227\066gƱq\202\207\231_2pަ\005v\231\306\b\\(", password_len=32, options=0, iv=0x7f41749951c8 "\323{\217\330\064fUr\220\260J\021J\021E\222", iv_len=16,
    tag=0x7f4174817a40, tag_len=16, aad=0x7f41cac84ef5 "", aad_len=0) at /go/src/app/dist/static-php-cli/source/php-src/ext/openssl/openssl.c:7700
#4  0x00007f41c90bf126 in zif_openssl_encrypt (execute_data=0x7f41748179a0, return_value=0x7f4174817970) at /go/src/app/dist/static-php-cli/source/php-src/ext/openssl/openssl.c:7719
#5  0x00007f41c8ed651f in ZEND_DO_ICALL_SPEC_RETVAL_USED_HANDLER () at /go/src/app/dist/static-php-cli/source/php-src/Zend/zend_vm_execute.h:1337
#6  execute_ex (ex=0x7f41748161d0) at /go/src/app/dist/static-php-cli/source/php-src/Zend/zend_vm_execute.h:57216
#7  0x00007f41c8d32ec2 in zend_call_function (fci=0x7f417d4e8720, fci_cache=0x7f417d4e86f0) at /go/src/app/dist/static-php-cli/source/php-src/Zend/zend_execute_API.c:957
#8  0x00007f41c8c0c591 in zif_frankenphp_handle_request (execute_data=<optimized out>, return_value=0x7f4174816140) at frankenphp.c:371
#9  0x00007f41c8ed651f in ZEND_DO_ICALL_SPEC_RETVAL_USED_HANDLER () at /go/src/app/dist/static-php-cli/source/php-src/Zend/zend_vm_execute.h:1337
#10 execute_ex (ex=0x7f4174816020) at /go/src/app/dist/static-php-cli/source/php-src/Zend/zend_vm_execute.h:57216
#11 0x00007f41c8ef38a7 in zend_execute (op_array=0x7f417486b000, return_value=0x0) at /go/src/app/dist/static-php-cli/source/php-src/Zend/zend_vm_execute.h:61604
#12 0x00007f41c8d5fa5c in zend_execute_scripts (type=8, retval=0x0, file_count=3) at /go/src/app/dist/static-php-cli/source/php-src/Zend/zend.c:1881
#13 0x00007f41c8ca005a in php_execute_script (primary_file=0x7f417d4ee660) at /go/src/app/dist/static-php-cli/source/php-src/main/main.c:2523
#14 0x00007f41c8c0d4f1 in frankenphp_execute_script (file_name=0x7f41c7161f90 "\001") at frankenphp.c:825
#15 0x00007f41c8c0ac37 in _cgo_d49d0ae4a108_Cfunc_frankenphp_execute_script (v=0xc000807dd8) at /tmp/go-build/cgo-gcc-prolog:55
#16 0x00007f41c78c9a01 in runtime.asmcgocall () at /usr/local/go/src/runtime/asm_amd64.s:918
#17 0x000000c000603880 in ?? ()
#18 0x00007f417d4ee7d0 in ?? ()
#19 0x00007f417d4ee834 in ?? ()
#20 0x0000000000000000 in ?? ()
(gdb)

[binaryfire]

@sneycampos Worker count doesn't make a difference for me. I'm able to reproduce the problem with 1, 10 and 20 workers.

[crrodriguez]

SO what's going on in frame 2 and 3.. can someone share a complete trace ? Looks like EVP_CIPHER_CTX_reset(cipher_ctx); is stepping into 🐶 💩 or almost certainly trying to free willy but is free already.

[dunglas]

@crrodriguez the stack trace looks complete, it looks like Musl's hardened allocator crashes when calling EVP_CIPHER_CTX_reset(), this smells like a double-free issue or something like that.

[dunglas]

The bug is being tracked upstream: https://github.com/php/php-src/issues/13648 It seems to only affect projects using a recent version of OpenSSL with a recent version of Musl (it's the case of the static binary of FrankenPHP).

In the meantime, a workaround is to use the Docker image instead of the static binary, or to compile a dynamically linked build of FrankenPHP.

As this bug isn't in Octane (nor in FrankenPHP directly), I think that this issue can be closed or locked.

[driesvints]

Thanks @dunglas

[ia-kaishen]

anyone managed to load test with docker / php built from source? i tried php built from source but still crashing under high load

[sneycampos]

anyone managed to load test with docker / php built from source?

i tried php built from source but still crashing under high load

Maybe is related to https://github.com/php/php-src/issues/13648

[dunglas]

@sneycampos yes it is! @ia-kaishen do you have a stack trace? I didn't manage to reproduce the problem with glibc, I have the crash only with musl+mallocng and musl+mimalloc. If it breaks also with glibc, this would allow @bukka and I to eliminate the allocator bug hypothesis and indicate a bug in PHP or OpenSSL.

[sneycampos]

Complementing @dunglas, if you don't have time, tell me how did you run your tests and i can try to get the stack trace. I have Ubuntu amd64 and arm64 available. @dunglas if you need a vps amd64 or arm64 tell me and i can spin up for you in hetzner in my account.

[dunglas]

For the record, I created a guide explaining how to gather a stack trace with Octane and similar solutions: https://frankenphp.dev/docs/contributing/#debugging-segmentation-faults-with-static-builds It uses static builds, but once you have a dynamic build (https://frankenphp.dev/docs/compile/), the process is the same.