Edit report at https://bugs.php.net/bug.php?id=68486&edit=1
ID: 68486
Comment by: php at bof dot de
Reported by: wattwood at tcstire dot com
Summary: PHP SegFault zend_hash_find
Status: Open
Type: Bug
Package: Apache2 related
Operating System: Ubuntu 14.04.1 LTS
PHP Version: 5.5.19
Block user comment: N
Private report: N
New Comment:
For completeness, here's a gist with the patch against PHP 5.6.7RC1 that I created the second
trace output in the previous comment with:
https://gist.github.com/anonymous/449a2726c876d187165b
In addition to the added logging, it contains the "1 ||" change at the start of
php_handler() which makes the issue go away for me in the normal, non-subrequest cases.
Previous Comments:
------------------------------------------------------------------------
[2015-03-13 14:50:56] php at bof dot de
To make sure the issue is not with the somewhat old Apache 2.4.6 of openSUSE 13.1, I have now
compiled a fresh Apache 2.4.12 (current release), and the problem still persists.
I also added some trace logging to the apache2handler code. Using the already described two-request
echo|netcat test, I see this with a segfaulting request:
[Fri Mar 13 15:31:13.034800 2015] [:error] [pid 22003] php_handler(ctx=0, ctx->r=0, r=3f425b0)
request_processed=-1
[Fri Mar 13 15:31:13.034818 2015] [:error] [pid 22003] php_handler(NEW ctx=3f47b80,
ctx->r=3f425b0, r=3f425b0)
[Fri Mar 13 15:31:13.034841 2015] [:error] [pid 22003]
php_apache_request_ctor(SG(server_context)=3f47b80, ctx=3f47b80, ctx->r=3f425b0, r=3f425b0)
[Fri Mar 13 15:31:13.037026 2015] [:error] [pid 22003] php_apache_request_dtor(ctx=3f47b80,
ctx->r=3f425b0, r=3f425b0)
[Fri Mar 13 15:31:13.045265 2015] [:error] [pid 22003] php_handler(ctx=3f47b80, ctx->r=3f425b0,
r=3f54b00) request_processed=1
[Fri Mar 13 15:31:13.045372 2015] [:error] [pid 22003] php_handler(OLD ctx=3f47b80,
parent_req=3f425b0, r=3f54b00)
[Fri Mar 13 15:31:13.045407 2015] [:error] [pid 22003] php_handler(ctx=3f47b80, parent_req=3f425b0,
r=3f54b00) PROCESSING SUBREQUEST
Compare this to the following trace, done with the patch I sent in [2015-03-10 09:22 UTC] applied:
[Fri Mar 13 15:44:26.381174 2015] [:error] [pid 19155] php_handler(ctx=0, ctx->r=0, r=4f7fb30)
request_processed=-1
[Fri Mar 13 15:44:26.381197 2015] [:error] [pid 19155] php_handler(NEW ctx=4f830f0,
ctx->r=4f7fb30, r=4f7fb30)
[Fri Mar 13 15:44:26.381218 2015] [:error] [pid 19155]
php_apache_request_ctor(SG(server_context)=4f830f0, ctx=4f830f0, ctx->r=4f7fb30, r=4f7fb30)
[Fri Mar 13 15:44:26.383660 2015] [:error] [pid 19155] php_apache_request_dtor(ctx=4f830f0,
ctx->r=4f7fb30, r=4f7fb30)
[Fri Mar 13 15:44:26.391144 2015] [:error] [pid 19155] php_handler(ctx=4f830f0, ctx->r=4f7fb30,
r=4f69300) request_processed=1
[Fri Mar 13 15:44:26.391192 2015] [:error] [pid 19155] php_handler(NEW ctx=4f8c3b0,
ctx->r=4f69300, r=4f69300)
[Fri Mar 13 15:44:26.391222 2015] [:error] [pid 19155]
php_apache_request_ctor(SG(server_context)=4f8c3b0, ctx=4f8c3b0, ctx->r=4f69300, r=4f69300)
[Fri Mar 13 15:44:26.392970 2015] [:error] [pid 19155] php_apache_request_dtor(ctx=4f8c3b0,
ctx->r=4f69300, r=4f69300)
[Fri Mar 13 15:44:26.398950 2015] [:error] [pid 19155] php_server_context_cleanup(4f8c3b0)
[Fri Mar 13 15:44:26.399008 2015] [:error] [pid 19155] php_server_context_cleanup(0)
So it is clear that apache 2.4 delays the call to the pool cleanup function,
php_server_context_cleanup.
Now, how to solve this... I would just rip out all the attempts to handle a parent_req with
interpreter reentrancy. This will make the virtual() function fail when both parent and subrequest
go to the PHP handler, but some testing even on apache 2.2 suggested to me that that is broken
anyway, resulting in crashes sometimes.
However, the comments / core about POST errors and 413 and so on, makes me nervous, because I have
no idea how that would be related, affected, or triggered. Some testing with post requests, also
overly long ones, did not show me reentrancy, but the code must have had some reason in the past.
HELP!
------------------------------------------------------------------------
[2015-03-11 08:27:20] php at bof dot de
After more debugging, and comparing with my apache 2.2 setup, the root cause of the problem is
pretty clear: Apache 2.4 no longer calls the pool cleanup php_server_context_cleanup() between the
two requests on the pipelined connection. This makes the second, independant request run with the
previous SG(server_context), like a subrequest - but the first request has already shut down the
interpreter...
With apache 2.2 there is a proper call to php_server_context_cleanup() after each request.
I'm still unsure what would be the correct fix; the logic in php_handler() covers several
cases, not all clear to me. Maybe somebody can clear this up: in what situation will we enter
php_handler with non-NULL ctx, ctx->request_processed == 1, and r->protocol ==
"INCLUDED" ?
------------------------------------------------------------------------
[2015-03-10 13:41:06] php at bof dot de
Just ran a single step session (xdebug + opcache disabled), first breakpoint in apache SAPI
php_handler line 669 (call to zend_execute_scripts, triggering on the second pipelined request),
then second breakpoint in compile_file() like 584 where the call
zend_stack_push(&CG(context_stack), (void *) &CG(context), sizeof(CG(context)));
bombed. Stepping into zend_stack_push I find:
(gdb) step
zend_stack_push (stack=stack@entry=0x7fbd1b595478 <compiler_globals+696>,
element=element@entry=0x7fbd1b595450 <compiler_globals+656>, size=size@entry=40)
at /usr/src/phb/build/release-5.6.7-Og/php-src/Zend/zend_stack.c:34
34 {
(gdb) step
35 if (stack->top >= stack->max) { /* we need to allocate more memory */
(gdb) print *stack
$1 = {top = 0, max = 64, elements = 0x0}
So the code thinks it does not need to allocate - and then bombs on the following assignment to
stack->elements[stack->top].
Looks like CG(context_stack).max is not properly reset somehow after the previous request...
------------------------------------------------------------------------
[2015-03-10 09:22:15] php at bof dot de
Happy to find this bug.... Ran into the same problems when trying to upgrade from an older openSUSE
system with Apache 2.2, to a current one with Apache 2.4. PHP in both cases, is a self-built 5.6.6
(also tested with 5.6.7RC1 and an older 5.6.4) build.
As soon as I tried this in production, I got, on a box with about 2000 req/min, 2-3 coredumps per
minute. Trials with opcache disabled, pointed to exactly the kind of backtraces reported here.
Trials with opcache enabled (normal production) almost always resulted in backtraces like this:
#0 0x00007fc2c1c0a347 in i_create_execute_data_from_op_array (
nested=<optimized out>, op_array=<optimized out>)
at /usr/src/phb/build/release-5.6.7-Og/php-src/Zend/zend_execute.c:1676
1676 EX(prev_execute_data) = EG(current_execute_data);
(gdb) bt
#0 0x00007fc2c1c0a347 in i_create_execute_data_from_op_array (
nested=<optimized out>, op_array=<optimized out>)
at /usr/src/phb/build/release-5.6.7-Og/php-src/Zend/zend_execute.c:1676
#1 zend_execute (op_array=0x7fc2c06c10f8)
at /usr/src/phb/build/release-5.6.7-Og/php-src/Zend/zend_vm_execute.h:388
#2 0x00007fc2c1b78bf3 in zend_execute_scripts (type=type@entry=2,
retval=retval@entry=0x0, file_count=file_count@entry=1)
at /usr/src/phb/build/release-5.6.7-Og/php-src/Zend/zend.c:1341
#3 0x00007fc2c1c0d672 in php_handler (r=<optimized out>)
at /usr/src/phb/build/release-5.6.7-Og/php-src/sapi/apache2handler/sapi_apache2.c:669
.....
I can fully reproduce the issue now on my development system, using the echo/netcat double request
from the last comment against a trivial (only one echo) test script.
The following patch, against the 5.6.7RC1 sources, fixes the coredump, and results in both pipelined
test script calls returning the expected result. I have not yet tested whether the patch has
negative consequences, though. Here it is:
diff --git a/sapi/apache2handler/sapi_apache2.c b/sapi/apache2handler/sapi_apache2.c
index 088ff77..0f80aee 100644
--- a/sapi/apache2handler/sapi_apache2.c
+++ b/sapi/apache2handler/sapi_apache2.c
@@ -549,7 +549,7 @@ static int php_handler(request_rec *r)
/* apply_config() needs r in some cases, so allocate server_context early */
ctx = SG(server_context);
- if (ctx == NULL || (ctx && ctx->request_processed && !strcmp(r->protocol,
"INCLUDED"))) {
+ if (1 || ctx == NULL || (ctx && ctx->request_processed &&
!strcmp(r->protocol, "INCLUDED"))) {
normal:
ctx = SG(server_context) = apr_pcalloc(r->pool, sizeof(*ctx));
/* register a cleanup so we clear out the SG(server_context)
------------------------------------------------------------------------
[2015-01-23 13:42:04] biggi at stefna dot is
I think this is related to HTTP pipelining and Apache version 2.4
To test it, do:
echo -e "GET /test.php HTTP/1.1\nHost: localhost\n\nGET /test.php HTTP/1.1\nHost:
localhost\n\n"|nc localhost 80
It does not matter what is in test.php, it can be empty.
Note that it does not always segfault. But if test.php outputs something, only the first output is
delivered, empty on the second one.
I've tested this on php versions 5.4.36, 5.5.1, 5.5.20 and 5.6.4 with version 2.2.29, 2.4.2 and
2.4.10 of apache.
Tested with clean compile of both apache and php (on ubuntu 14.04).
php configure: './configure' '--prefix=/tmp/testing/php5'
'--with-apxs2=/tmp/testing/apache2/bin/apxs' '--disable-all'
Segfaults for all tested version of php for apache 2.4, but never for 2.2.29.
Also, 2.2.29 outputs all pipelined requests.
Now, I did some digging and I guess the problem is in php_handler function in sapi_apache2.c:
https://github.com/php/php-src/blob/PHP-5.5.20/sapi/apache2handler/sapi_apache2.c#L536
The server_context is reused (parent_req is found), which ends up with a corrupt zend_file_handle
zfd (in line 669).
Note that php_server_context_cleanup is never called.
I assume the server_context should NOT be used again for these kind of requests.
Hopefully this helps.
I am getting a lot of segfaults these days. Seems that HTTP pipelining is enabled for safari on iOS
devices.
I am also seeing some "PHP Fatal Error Allowed memory size of 268435456 bytes exhausted (tried
to allocate 22455254144 bytes)". This definitely relates to this problem, and probably
something that can happen if there is no segfault.
------------------------------------------------------------------------
The remainder of the comments for this report are too long. To view
the rest of the comments, please view the bug report online at
https://bugs.php.net/bug.php?id=68486
--
Edit this bug report at https://bugs.php.net/bug.php?id=68486&edit=1