php.net |  support |  documentation |  report a bug |  advanced search |  search howto |  statistics |  random bug |  login
Bug #81380 Crash in Apache 2 module with opcache and observers after Apache reload
Submitted: 2021-08-24 14:42 UTC Modified: 2021-09-28 14:55 UTC
Votes:1
Avg. Score:5.0 ± 0.0
Reproduced:1 of 1 (100.0%)
Same Version:1 (100.0%)
Same OS:1 (100.0%)
From: f dot sowade at r9e dot de Assigned: krakjoe (profile)
Status: Closed Package: Apache2 related
PHP Version: 8.0.9 OS: Linux
Private report: No CVE-ID: None
Welcome back! If you're the original bug submitter, here's where you can edit the bug or add additional notes.
If this is not your bug, you can add a comment by following this link.
If this is your bug, but you forgot your password, you can retrieve your password here.
Password:
Status:
Package:
Bug Type:
Summary:
From: f dot sowade at r9e dot de
New email:
PHP Version: OS:

 

 [2021-08-24 14:42 UTC] f dot sowade at r9e dot de
Description:
------------
I built PHP 8.0.9 as an Apache 2 module with the opcache and with the zend-test extensions:

./configure --disable-all --enable-zend-test --with-apxs2 --enable-zts --enable-opcache

I then used the following php.ini which uses the zend-test extension to register an observer:

zend_extension=opcache.so
zend_test.observer.enabled=1

And I used a test script which just calls phpinfo();

The script works as expected after starting Apache. But when reloading Apache (systemctl reload apache2.service) I get a segmentation fault when accessing the script. This is the corresponding line from Apache's error.log:

[Tue Aug 24 16:31:24.739107 2021] [core:notice] [pid 258215:tid 140253313567808] AH00051: child pid 258527 exit signal Segmentation fault (11), possible coredump in /etc/apache2

When restarting Apache (systemctl restart apache2.service) the script works again as expected.

The problem also occurs with a custom PHP extension which uses the observer API. But since I was able to reproduce it with the zend-test extension, I thought that it was the easiest reproduction case.

The problem does not occur if I don't load the opcache extension.

Test script:
---------------
<?php
phpinfo();


Patches

Add a Patch

Pull Requests

Pull requests:

Add a Pull Request

History

AllCommentsChangesGit/SVN commitsRelated reports
 [2021-08-24 15:31 UTC] f dot sowade at r9e dot de
Here is the backtrace of the crash from gdb:

#0  ZEND_DO_ICALL_SPEC_RETVAL_UNUSED_HANDLER () at /root/php-src/php-8.0.9/Zend/zend_vm_execute.h:1234
#1  execute_ex (ex=0x7f1084413070) at /root/php-src/php-8.0.9/Zend/zend_vm_execute.h:54520
#2  0x00007f10971cf4ea in zend_execute (op_array=0x7f1084463000, return_value=0x0) at /root/php-src/php-8.0.9/Zend/zend_vm_execute.h:58871
#3  0x00007f109716279b in zend_execute_scripts (type=-2076102624, type@entry=8, retval=retval@entry=0x0, file_count=file_count@entry=3) at /root/php-src/php-8.0.9/Zend/zend.c:1680
#4  0x00007f10970fa058 in php_execute_script (primary_file=primary_file@entry=0x7f10963fdae0) at /root/php-src/php-8.0.9/main/main.c:2524
#5  0x00007f10971f6dc0 in php_handler (r=<optimized out>) at /root/php-src/php-8.0.9/sapi/apache2handler/sapi_apache2.c:704
#6  0x00005622133b76a8 in ap_run_handler ()
#7  0x00005622133b7c56 in ap_invoke_handler ()
#8  0x00005622133d0403 in ap_process_async_request ()
#9  0x00005622133cc7c3 in ?? ()
#10 0x00005622133c13e8 in ap_run_process_connection ()
#11 0x00007f1097bdd10e in ?? () from /usr/lib/apache2/modules/mod_mpm_event.so
#12 0x00007f1097bddb17 in ?? () from /usr/lib/apache2/modules/mod_mpm_event.so
#13 0x00007f1097f2a609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#14 0x00007f1097e51293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 [2021-08-24 15:42 UTC] f dot sowade at r9e dot de
I was also able to reproduce the crash with 8.1.0 beta3 with the following backtrace:

#0  ZEND_DO_ICALL_SPEC_RETVAL_UNUSED_HANDLER () at /root/php-src/php-8.1.0beta3/Zend/zend_vm_execute.h:1235
#1  execute_ex (ex=0x7f1160213070) at /root/php-src/php-8.1.0beta3/Zend/zend_vm_execute.h:54456
#2  0x00007f1161bf17ea in zend_execute (op_array=0x7f1160266000, return_value=0x0) at /root/php-src/php-8.1.0beta3/Zend/zend_vm_execute.h:58819
#3  0x00007f1161b80a53 in zend_execute_scripts (type=type@entry=8, retval=retval@entry=0x0, file_count=file_count@entry=3) at /root/php-src/php-8.1.0beta3/Zend/zend.c:1755
#4  0x00007f1161b17a07 in php_execute_script (primary_file=primary_file@entry=0x7f1160dfdae0) at /root/php-src/php-8.1.0beta3/main/main.c:2519
#5  0x00007f1161c688d0 in php_handler (r=<optimized out>) at /root/php-src/php-8.1.0beta3/sapi/apache2handler/sapi_apache2.c:705
#6  0x00005635a03a66a8 in ap_run_handler ()
#7  0x00005635a03a6c56 in ap_invoke_handler ()
#8  0x00005635a03bf403 in ap_process_async_request ()
#9  0x00005635a03bb7c3 in ?? ()
#10 0x00005635a03b03e8 in ap_run_process_connection ()
#11 0x00007f116263810e in ?? () from /usr/lib/apache2/modules/mod_mpm_event.so
#12 0x00007f1162638b17 in ?? () from /usr/lib/apache2/modules/mod_mpm_event.so
#13 0x00007f1162984609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#14 0x00007f11628ab293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 [2021-08-25 09:02 UTC] nikic@php.net
-Assigned To: +Assigned To: levim
 [2021-09-28 14:20 UTC] beberlei@php.net
-Assigned To: levim +Assigned To: dmitry
 [2021-09-28 14:20 UTC] beberlei@php.net
Joe investigated this some more and had the following comments, specifically this seems to be only triggered by Observer but the root cause is something in Opcache. As such I am going to re-assign this to you, Dmitry. Hope that is alright :-)

> here's what is happening ... after reload, result.num of INIT_FCALL (which is cache slot num) is 0, and so occupies the same slot as the observer data, INIT_FCALL is fetching observer data and trying to execute it as fbc ... not quite sure why yet ... cache_size before reload is 16, after is 8. I've watched cache size (in persistent script) until process is destroyed and it has not changed, something in-between the process being destroyed and recreated (which I cannot find a way to debug) is doing something bad to cache_size ... I'm sure dmitry is going to see what is happening but I don't ...

I'll attach a debug session from him:

krakjoe@Fiji:/opt/src/php-src$ sudo service apache2 restart
krakjoe@Fiji:/opt/src/php-src$ ps aux | grep apache2
www-data  330780  0.0  0.0 2144832 7236 ?        Sl   15:21   0:00 /usr/sbin/apache2 -k start
krakjoe@Fiji:/opt/src/php-src$ sudo gdb -p 330780
-- SNIPPED --
(gdb) break zend_accel_load_script 
Breakpoint 1 at 0x7f30928ca6ae: file /opt/src/php-src/ext/opcache/zend_accelerator_util_funcs.c, line 229.
(gdb) c
Continuing.
[Switching to Thread 0x7f309130e640 (LWP 330782)]

Thread 2 "apache2" hit Breakpoint 1, zend_accel_load_script (persistent_script=0x41edf380, from_shared_memory=32560) at /opt/src/php-src/ext/opcache/zend_accelerator_util_funcs.c:229
229	{
(gdb) n
232		op_array = (zend_op_array *) emalloc(sizeof(zend_op_array));
(gdb) 
233		*op_array = persistent_script->script.main_op_array;
(gdb) 
235		if (zend_hash_num_elements(&persistent_script->script.function_table) > 0) {
(gdb) p op_array.cache_size
$1 = 16
(gdb) q
A debugging session is active.

	Inferior 1 [process 330780] will be detached.

Quit anyway? (y or n) y
Detaching from program: target:/usr/sbin/apache2, process 330780
[Inferior 1 (process 330780) detached]
krakjoe@Fiji:/opt/src/php-src$ sudo service apache2 reload
krakjoe@Fiji:/opt/src/php-src$ ps aux | grep apache2
www-data  330869  0.0  0.0 2145004 7408 ?        Sl   15:22   0:00 /usr/sbin/apache2 -k start
krakjoe@Fiji:/opt/src/php-src$ sudo gdb -p 330869
-- SNIPPED --
(gdb) break zend_accel_load_script
Breakpoint 1 at 0x7f30928ca6ae: file /opt/src/php-src/ext/opcache/zend_accelerator_util_funcs.c, line 229.
(gdb) c
Continuing.
[Switching to Thread 0x7f3090ffe640 (LWP 330871)]

Thread 2 "apache2" hit Breakpoint 1, zend_accel_load_script (persistent_script=0x42299380, from_shared_memory=32560) at /opt/src/php-src/ext/opcache/zend_accelerator_util_funcs.c:229
229	{
(gdb) n
232		op_array = (zend_op_array *) emalloc(sizeof(zend_op_array));
(gdb) 
233		*op_array = persistent_script->script.main_op_array;
(gdb) 
235		if (zend_hash_num_elements(&persistent_script->script.function_table) > 0) {
(gdb) p op_array.cache_size
$1 = 8
 [2021-09-28 14:22 UTC] beberlei@php.net
And a first attempt at a patch:

diff --git a/Zend/zend_extensions.c b/Zend/zend_extensions.c
index 4d4b1ffe09..adf9c57785 100644
--- a/Zend/zend_extensions.c
+++ b/Zend/zend_extensions.c
@@ -207,7 +207,7 @@ void zend_startup_extensions_mechanism()
 {
        /* Startup extensions mechanism */
        zend_llist_init(&zend_extensions, sizeof(zend_extension), (void (*)(void *)) zend_extension_dtor, 1);
-       zend_op_array_extension_handles = 0;
+       //zend_op_array_extension_handles = 0;
        last_resource_number = 0;
 }
 [2021-09-28 14:55 UTC] krakjoe@php.net
-Assigned To: dmitry +Assigned To: krakjoe
 [2021-09-28 15:00 UTC] krakjoe@php.net
The following pull request has been associated:

Patch Name: Fix #81380 observer may not be initialized properly
On GitHub:  https://github.com/php/php-src/pull/7524
Patch:      https://github.com/php/php-src/pull/7524.patch
 [2021-09-28 15:43 UTC] levim@php.net
I think the bug stems from my lack of understanding of PHP's request and process lifecycle with Apache and prefork. I've been discussing this with Joe Watkins and Derick Rethans, and Joe may have a fix:

https://github.com/php/php-src/pull/7524

But, I don't yet understand _why_ this would fix the bug. I think Apache's model is wrong, or at least different from what other SAPIs seem to be doing, and hence the bug.
 [2021-09-29 10:44 UTC] git@php.net
Automatic comment on behalf of krakjoe
Revision: https://github.com/php/php-src/commit/c884a5a21eaf1ca0aad4690e3348d645e1fdae25
Log: Fix #81380 observer may not be initialized properly
 [2021-09-29 10:44 UTC] git@php.net
-Status: Assigned +Status: Closed
 
PHP Copyright © 2001-2021 The PHP Group
All rights reserved.
Last updated: Mon Nov 29 19:03:12 2021 UTC