#26494 [Fbk->Opn]: mod_php4 fails Timeout setting while writing to a dead client on Apache 1.3

ID: 26494 User updated by: hexer at studentcenter dot org Reported By: hexer at studentcenter dot org -Status: Feedback +Status: Open Bug Type: Apache related Operating System: Linux PHP Version: 4.3.10 New Comment: Ok I tried it, same results. It's the problem in mod_php4.c also just as a side note, our php is compiled-in to apache. Previous Comments: ------------------------------------------------------------------------ [2005-01-25 15:25:56] sniper@php.net Please try using this CVS snapshot: http://snaps.php.net/php4-STABLE-latest.tar.gz For Windows: http://snaps.php.net/win32/php4-win32-STABLE-latest.zip Always try the snapshot first.. ------------------------------------------------------------------------ [2005-01-11 21:50:43] hexer at studentcenter dot org Ok here is a more detailed step-by-step on how to reproduce: Use php 4.3.10 compiled-in with Apache 1.3.33 1. Compile Apache 1.3 with php-4.3.10 compiled-in: In source tree: ./configure --prefix=/usr/local/apache In PHP source tree: ./configure --with-mysql \ --with-xml \ --with-apache=../apache_1.3.33 \ --enable-track-vars \ --with-gd \ --enable-discard-path \ --enable-bcmath \ --enable-gd-native-tt \ --with-freetype-dir=/usr/local \ --with-png-dir=/usr/local \ --with-jpeg-dir=/usr/local \ --with-zlib=/usr/local make make install In Apache source tree: ./configure \ --activate-module=src/modules/php4/libphp4.a \ --enable-module=php4 \ --enable-module=rewrite \ --enable-module=so \ --prefix=/usr/local/apache make make install 2. Edit httpd.conf and make sure you have the following enabled in httpd.conf: TimeOut 60 AddModule mod_status.c ExtendedStatus On <Location /server-status> SetHandler server-status Order deny,allow Allow from all </Location> 3. Create the test output script (test.php): <?php for($i = 0; $i < 1000000; $i++) { echo "XXXXXXXXXXXXXXXXXXXXXXXX<br>\n"; } ?> 4. On a different computer, open the browser and point it to test.php, as soon as test.php starts loading unplug the computer from the network, before it finishes loading. This one's important. You have to make a true dead connection without the server knowing about it. Make sure your network does not notify the server immediately that the connection was closed or there is a broken pipe etc. (by default the Linux recv has a very long timeout) 5. Check the server-status page. You will see something like this: 0-1 4990 0/177/15106 W 0.45 9 0 0.0 0.19 43.85 x.x.x.x your.server.com GET /test.php Note the 'W' under status in that particular process. 6. You will see the SS value start going way beyond the timeout setting. This _must_ happen unless the system has somehow managed to find out that the connection is broken. If the process is not in W status and 60 seconds have not passed that means the system somehow found out that the connection is broken so the dead-connection condition hasn't been simulated. Also another good experiment would be to see if the TimeOut overrides max_execution_time. If in your scenario TimeOut does in fact work, it probably overrides the max_execution_time and causes the script to abort if it runs longer than TimeOut seconds. ------------------------------------------------------------------------ [2005-01-11 20:28:39] rasmus@php.net I haven't been able to reproduce this either even with MySQL enabled. ------------------------------------------------------------------------ [2005-01-11 19:10:22] hexer at studentcenter dot org Update: More test results, some improvements to the patch. After some testing on our production cluster I've made some improvements on the patch. (Scroll down for the patch itself) For a better way on reproducing this, check out the newsgroups post that talks more about this problem: http://groups-beta.google.com/group/php.general/browse_frm/thread/f18f3da1cc3b51a7/1e7c60d14432f6c5?q=mod_php+timeout&_done=%2Fgroups%3Fq%3Dmod_php+timeout%26hl%3Den%26lr%3D%26sa%3DN%26tab%3Dwg%26&_doneTitle=Back+to+Search&&d#1e7c60d14432f6c5 (Reproducible with latest version of Apache 1.3 and php 4.3.10) THE PATCH: (mod_php) List of changes since the initial version of the patch: 1. hard_timeout is no longer set before the main entry into the php engine execution. (TimeOut must only be used to monitor for stalled client connections according to the apache spec) 2. fixed for proper use of apache timeout in the READ post section. (timer is now primed before the start the read loop, timer refreshes in between the reads and is killed after the read loop so that TimeOut is tracked during communication and refreshed accordingly. 3. changed to ap_soft_timeout in the ub_write section. This makes PHP's ignore_user_abort possible again. (ap_soft_timeout causes apache to close socket instead of forcing a quit) Our test results: Upon setting apache TimeOut to 60, the server closes the connection with the client if and only if the connection has been stalled for more than 60 seconds during transfers. Since long script execution times are not considered stalls, the server only primes TimeOut timer during non-I/O operations of php and "kills" it afterwards. In other words, a php page can run for more than TimeOut number of seconds until max_execution_time if it is doing something other than outputting to the client or transfering POST data. Performance analysis: We have been running the earlier version of this patch on our production servers since this bug was first opened for several months now. There has been no noticable performance penalty. This new version of the patch has been running for about a week. We suggest a more thorough testing just in case. Especially with stalled POST's because that was the new addition to this patch. NOTE: To replicate this problem you MUST simulate a connection stall before a php page finishes its output. Hitting the stop button on a browser is not sufficient. We had to literally unplug the client computer's ethernet connection immediately after request to a php page to test this. --- /usr/local/src/php-4.3.10/sapi/apache/mod_php4.c 2005-01-10 15:11:53.000000000 -0500 *************** *** 97,107 **** static int sapi_apache_ub_write(const char *str, uint str_length TSRMLS_DC) { int ret=0; if (SG(server_context)) { ! ret = rwrite(str, str_length, (request_rec *) SG(server_context)); } if (ret != str_length) { php_handle_aborted_connection(); } return ret; --- 97,109 ---- static int sapi_apache_ub_write(const char *str, uint str_length TSRMLS_DC) { int ret=0; if (SG(server_context)) { ! ap_soft_timeout("php send body", (request_rec *) SG(server_context)); ! ret = rwrite(str, str_length, (request_rec *) SG(server_context)); ! ap_kill_timeout((request_rec *) SG(server_context)); } if (ret != str_length) { php_handle_aborted_connection(); } return ret; *************** *** 139,157 **** if (!SG(read_post_bytes) && !ap_should_client_block(r)) { return total_read_bytes; } handler = signal(SIGPIPE, SIG_IGN); while (total_read_bytes<count_bytes) { - hard_timeout("Read POST information", r); /* start timeout timer */ read_bytes = get_client_block(r, buffer+total_read_bytes, count_bytes-total_read_bytes); ! reset_timeout(r); if (read_bytes<=0) { break; } total_read_bytes += read_bytes; } signal(SIGPIPE, handler); return total_read_bytes; } /* }}} */ --- 141,161 ---- if (!SG(read_post_bytes) && !ap_should_client_block(r)) { return total_read_bytes; } handler = signal(SIGPIPE, SIG_IGN); + + ap_hard_timeout("Read POST information", r); /* start timeout timer */ while (total_read_bytes<count_bytes) { read_bytes = get_client_block(r, buffer+total_read_bytes, count_bytes-total_read_bytes); ! ap_reset_timeout(r); if (read_bytes<=0) { break; } total_read_bytes += read_bytes; } + ap_kill_timeout(r); signal(SIGPIPE, handler); return total_read_bytes; } /* }}} */ *************** *** 606,617 **** } /* Assume output will be of the default MIME type. Individual scripts may change this later in the request. */ r->content_type = php_apache_get_default_mimetype(r TSRMLS_CC); - /* Init timeout */ - hard_timeout("send", r); SG(server_context) = r; php_save_umask(); add_common_vars(r); --- 610,619 ---- *************** *** 620,630 **** init_request_info(TSRMLS_C); apache_php_module_main(r, display_source_mode TSRMLS_CC); /* Done, restore umask, turn off timeout, close file and return */ php_restore_umask(); - kill_timeout(r); } zend_end_try(); return OK; } /* }}} */ --- 622,631 ---- ------------------------------------------------------------------------ [2004-12-23 00:02:13] hexer at studentcenter dot org Note: The issue still persists in version 4.3.10 and all versions in between. ------------------------------------------------------------------------ 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 http://bugs.php.net/26494 -- Edit this bug report at http://bugs.php.net/?id=26494&edit=1