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: 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: Here's a gist with a patch, against 5.6.7RC1, that appears to fix the issue for me, at least for the things I tested. https://gist.github.com/bof/15173c7a11cb12a7b96f (patch contains lots of extra debug output, none of the ap_log_error calls I added would be good for merging) I basically rip out the whole parent_req handling attempts in php_handler(), and make ctx->request_processed be the only indicator regarding reentrancy to the interpreter. In case such a reentrancy is attempted, I error out early in php_handler() before any manipulation to interpreter state is done. The PHP virtual() function (provided in php_functions.c) will now cleanly fail when used to "embed" another PHP script (the worst reentrancy), but it continues to work when embedding an URI handled by any other handler (the not_for_us case). While testing I had a final issue with the ap_rflush() call in virtual() resulting in pool destruction of the in-flight request, due to the apache 2.4 EOR thing gmoniker mentioned in the previous comment. If anybody is curious, drop me an email, I've got the backtrace saved. For now I have disabled that ap_rflush() call in virtual(), and I don't know what could break by that. Anyway, after some light testing with this gist's patch applied, my own codebase keeps working normally, and the double-echo test now works without crashes for any of these cases: - two normal PHP requests in a row - two PHP requests in a row, each using virtual to embed another PHP script (embedded script NOT run, PHP warning message in virtual() caller) - two PHP requests in a row, using virtual to embed a non-PHP thing (/robots.txt tested...) - works as it should. Previous Comments: ------------------------------------------------------------------------ [2015-03-13 18:59:54] gmoniker at gmail dot com 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. ------------------------------------------------------------------------ [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... ------------------------------------------------------------------------ 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