Bug #68486 [Com]: PHP SegFault zend_hash_find

Edit report at https://bugs.php.net/bug.php?id=68486&edit=1 ID: 68486 Comment by: gmoniker at gmail dot com 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: Bug hunting: I am trying to reopen this bug at the Apache httpd bugzilla: https://bz.apache.org/bugzilla/show_bug.cgi?id=56984 Thanks to the mention of php_server_context_cleanup() by *php at bof dot de* I decided to look at the source code of the php sapi module and the Apache/APR code which causes it to be called. The PHP sapi module uses the pool register/cleanup philosophy enabled by the APR module of Apache (@see http://www.apachetutor.org/dev/pools) and stores its SG(server_context) in the request pool, depending on it to be cleaned up at the end of the request, before the Apache worker feeds it a new request. In Apache 2.2 the code in modules/http/http_core.c is fairly straightforward: static int ap_process_http_connection(conn_rec *c) [...] while ((r = ap_read_request(c)) != NULL) { [...] if (r->status == HTTP_OK) ap_process_request(r); if (ap_extended_status) ap_increment_counts(c->sbh, r); if (c->keepalive != AP_CONN_KEEPALIVE || c->aborted) break; ap_update_child_status(c->sbh, SERVER_BUSY_KEEPALIVE, r); apr_pool_destroy(r->pool); [...] } So before handling the next request the pool is destroyed and ergo the php_server_context_cleanup() gets called because it is registered to the pools cleanup list. In Apache 2.4 things have been rewritten quite extensively and in a way that is completely breaking the primary functionality of the APR pools, in that they should provide an easy declarative cleanup where a client registers a cleanup and can count on the server to execute it at the moment the server sees the pool should be destroyed. Apache 2.4.7 code (and 2.4.12):: static int ap_process_http_sync_connection(conn_rec *c) [...] while ((r = ap_read_request(c)) != NULL) { c->keepalive = AP_CONN_UNKNOWN; /* process the request if it was read without error */ ap_update_child_status(c->sbh, SERVER_BUSY_WRITE, r); if (r->status == HTTP_OK) { if (cs) cs->state = CONN_STATE_HANDLER; ap_process_request(r); /* After the call to ap_process_request, the * request pool will have been deleted. We set * r=NULL here to ensure that any dereference * of r that might be added later in this function * will result in a segfault immediately instead * of nondeterministic failures later. */ r = NULL; } [...] } So, there clearly is no pool cleanup anymore in this place. But surely, you say, it has just been moved to a place deeper in the stack? Following the ap_process_request, ap_process_async_request chain, however crushes this hope slowly but surely. There is still an attempt to let the pool be cleaned up after the request. After the handler (for example PHP) had its go at the request, the method ap_process_request_after_handler(r) is called. (it's in modules/http/http_request.c) The after_handler routine creates an EOR bucket and puts it in the output of the request connection. This bucket registers a eor_bucket_cleanup function to the request pool pre_cleanup list that would instruct the destruction of the request pool. However this routine can only be called by apr_pool_clear of apr_pool_destroy and the problem is exactly that as long as the connection with requests or responses doesn't end, then those methods are not called for this pool or a parent pool that might exist, at least not anywhere in the prefork worker that I could see. So it seems that in Apache 2.4 at present the request pool has become a connection pool after all. Apparently the problem is well masked by PHP opcaching, which has practically become the default. When the script gets cached it apparently doesn't matter that the server_context is reused (because it doesn't have to use the Zend_cache?). And also in many cases there might be multiple requests on one pipeline but just one of them would be a php script. This could be a major problem for the PHP5 sapi module on current Apache 2.4 servers. Previous Comments: ------------------------------------------------------------------------ [2015-03-13 17:48:33] php at bof dot de 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. ------------------------------------------------------------------------ [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) ------------------------------------------------------------------------ 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