Hello, I am developing a module which extends mod_log_config and provides a custom log format for CPU time elapsed per request. In order to do this, once the request reaches the ap_run_log_transaction() hook, the Apache worker must apr_proc_wait() for any child processes related to the request to finish. Most of the time, the module functions without a problem and requests are logged with accurate CPU time.
However, some requests hang. I have not been able to reproduce the issue in testing, but I have been able to observe the deadlock on live servers. For example, using mod_suphp, some PHP requests will launch and begin processing, but prior to completing and writing out its entire response, the Apache worker moves to the ap_run_log_transaction() hook. The deadlock occurs when the logging function that my module uses begins its apr_proc_wait(). The PHP process will the be stuck in a write(), presumably waiting for Apache to read() more data, and the Apache child will be stuck in a waitpid(), waiting for the PHP process to terminate. Both processes hang indefinitely. Their backtraces are as follows: PHP process: #0 0x000063569ff13930 in __write_nocancel () from /lib64/libpthread.so.0 #1 0x000000000073cf48 in sapi_cgibin_single_write (str=<value optimized out>, str_length=320) at /home/cpeasyapache/src/php-5.2.17/sapi/cgi/cgi_main.c:270 #2 sapi_cgibin_ub_write (str=<value optimized out>, str_length=320) at /home/cpeasyapache/src/php-5.2.17/sapi/cgi/cgi_main.c:286 #3 0x0000000000688204 in php_ub_body_write_no_header (str=0x1 <Address 0x1 out of bounds>, str_length=18340616) at /home/cpeasyapache/src/php-5.2.17/main/output.c:684 #4 0x00000000006bb1b7 in zend_print_zval_ex (write_func=0x6771f0 <php_body_write_wrapper>, expr=0x11b7b78, indent=<value optimized out>) at /home/cpeasyapache/src/php-5.2.17/Zend/zend.c:294 #5 0x00000000006de48b in ZEND_ECHO_SPEC_CONST_HANDLER (execute_data=0x718e57d8fc90) at /home/cpeasyapache/src/php-5.2.17/Zend/zend_vm_execute.h:1500 #6 0x00000000006d95bc in execute (op_array=0x1177198) at /home/cpeasyapache/src/php-5.2.17/Zend/zend_vm_execute.h:92 #7 0x000063569dda890f in zend_oe () from /usr/local/Zend/lib/Optimizer-3.3.9/php-5.2.x/ZendOptimizer.so #8 0x00000000006b9b0d in zend_execute_scripts (type=8, retval=<value optimized out>, file_count=3) at /home/cpeasyapache/src/php-5.2.17/Zend/zend.c:1134 #9 0x0000000000676e3d in php_execute_script (primary_file=0x718e57d92430) at /home/cpeasyapache/src/php-5.2.17/main/main.c:2036 #10 0x000000000073daff in main (argc=2, argv=0x718e57d92608) at /home/cpeasyapache/src/php-5.2.17/sapi/cgi/cgi_main.c:1999 Apache thread: #0 0x000071742e3bf75f in waitpid () from /lib64/libpthread.so.0 #1 0x000071742ec3d912 in apr_proc_wait () from /usr/local/apache/lib/libapr-1.so.0 #2 0x000071742bf0f9a6 in log_cpu_elapsed () from /usr/local/apache/modules/mod_logcpu.so #3 0x000000000046d754 in process_item () #4 0x000000000046d968 in config_log_transaction () #5 0x000000000046db03 in multi_log_transaction () #6 0x000000000043937d in ap_run_log_transaction () #7 0x00000000004b44f8 in ap_process_request () #8 0x00000000004b0ba2 in ap_process_http_async_connection () #9 0x000000000045238c in ap_run_process_connection () #10 0x00000000004ddc50 in process_socket () #11 0x00000000004de9c1 in worker_thread () #12 0x000071742ec3e0a5 in dummy_worker () from /usr/local/apache/lib/libapr-1.so.0 #13 0x000071742e3b777d in start_thread () from /lib64/libpthread.so.0 #14 0x000071742df2925d in clone () from /lib64/libc.so.6 Why is this occurring, and couldn't this be affecting other logging functions such as those that count bytes communicated? Is there a way to ensure that the request has completely finished, and if not, yield to the PHP process and return to the logging function once it actually has finished? I suspect this may be due to faulty logic in check_pipeline_flush(), which is called prior to ap_run_log_transaction() in ap_process_request() (modules/http/http_request.c). This function appears to have been completely removed in 2.4 and replaced with a similar check_pipeline(). I've not yet tested my module with 2.4; I am developing on 2.2 and need this module to be compatible with 2.2. -Paul