ap_run_log_transaction() appears to run prior to request finishing

[Paul Stengel <ps...@gmail.com>]

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