Lighttpd

Our fix for now is in the cgi program.
1. We close the pipe on our side (fclose stdout).
2. Sleep 2 seconds before exiting process.

This makes sure that lighttpd fd event poll detects the closed pipe, invokes mod_cgi's read loop and finishes the HTTP transaction, before reaping the child.

I have seen the same issue. I'm currently testing a patch that calls the same cleanup code performed on FDEVENT_HUP in mod_cgi.c before closing the descriptor in the subrequest handler. I'll try to post it here if it turns out to work well.

Thanks for the code. I had tried something very similar, but wasn't sure of implications or other side effects. So I elected to implement a workaround in the cgi program instead, and wait for an official patch to be released.

Let me know how your fix works. Also, what kernel version are you using?
Thanks!

Charles

I am using a kernel based on 2.6.27.44. I did not see this problem after 50 tries on 2.6.27.31 but that could just mean that it's rarer. It seemed to take less than 20 tries to reproduce it with the later kernel. With the patch I ran curl 500+ times on the problematic page without seeing the problem, so I think the patches fixes the problem, but it has not been thoroughly tested.

I use gentoo stable kernel 2.6.32-gentoo-r7 and lighttpd-1.4.23 (built from source) and also meet this problem:

The cgi script is tiny:

#!/bin/sh
echo "Content-type: text/html" 
echo "" 
echo "Plain text cxx!" 

I use ab to test it:

$ /usr/sbin/ab -n 1000 -c 20 http://localhost:60002/cgi-bin/test

And this is the result:

Benchmarking localhost (be patient)
...
...
Completed 800 requests
Completed 900 requests
apr_poll: The timeout specified has expired (70007)
Total of 998 requests completed

One or more request always timeout.

Was my problem same as this one?

(PS: I have apply the patch but timeout problem still exists)

We are the authors of Snitchaser . We are trying to find the root cause of this issue for showing the effectiveness of our tool. Snitchaser is a record-replay tool which allow developers to record non-deterministic events during execution, and replay non-deterministic bugs using our replay tool. We want to share our debugging results and experience here.

The root cause of this issue is race condition in mod_cgi.c.

In cgi_demux_response(), lighttpd loop read() from cgi process' pipe to retrieve results. In normal situation, the last read() returns 0, which indicates the finish of data transfer. Sometimes read() returns EAGAIN because of non-blocking IO. In this situation, when the pipe becomes readable or broken (cgi process terminates), the main loop in service.c will get an fdevent (FDEVENT_IN or FDEVENT_HUP), cgi_handle_fdevent() will be called again. If the cgi process terminates, cgi_handle_fdevent() will receive FDEVENT_HUP and the con->file_finished will be set to "1".

However, mod_cgi_handle_subrequest() may be called before the fdevent_poll(). mod_cgi_handle_subrequest() use waitpid() to get the state of cgi process. If the process terminates, it will do the cleanup work and remove pipe's fd from fdevent. Therefore, lighttpd never gets the following FDEVENT_HUP event, so never set con->file_finished to "1". As a result, in the connection state machine, the buggy connection won't get closed correctly, which causes a timeout of an http transaction.

To solve this problem, a small patch is enough:

--- b/src/mod_cgi.c    2009-04-29 02:29:17.000000000 +0800
+++ a/src/mod_cgi.c    2010-07-27 17:21:19.675916561 +0800
@@ -1348,10 +1348,13 @@
          * check if we already got the response
          */

-        if (!con->file_started) return HANDLER_WAIT_FOR_EVENT;
+        hctx->pid = 0;
+
+        if (con->file_started) return HANDLER_FINISHED;

         if (WIFEXITED(status)) {
             /* nothing */
+            return HANDLER_WAIT_FOR_EVENT;
         } else {
             log_error_write(srv, __FILE__, __LINE__, "s", "cgi died ?");

This patch doesn't remove pipe from fdevent when cgi process exit normally. Which allows cgi_handle_fdevent() to receive FDEVENT_HUP and do the correct processing.

Snitchaser shows its power on debugging such non-deterministic issue. We first generate a buggy trace which contain 10 requests and 1 timeout, then replay the execution under gdb control over and over again. The following work is just like traditional cyclic debugging.

1. By tracing accept() and close(), we realize that one of sockets never get closed. This is the direct reason of timeout;
2. We identify the buggy connection using its address (addresses are same in different replay), and trace its processing, and witness the EAGAIN returned by read();
3. Compare with some correct execution, we find that in this situation, cgi_handle_fdevent() should receive an FDEVENT_HUP event later and the con->file_finished will be set to "1";
4. After some hacking and replay, we realize that the problem is caused by the removal of pipe's fd from fdevent.
5. After we find the root cause, to fix this issue is straightforward.

Snitchaser has shown its ability of converting non-deterministic bug (Heisenbug) to traditional Bohrbug in this case study. Currently it is under fast development. It is unstable and may have many problems. However, we hope you to try it and report their problems and experience to us to help us improve this tool. We also want you to tell us about some non-deterministic bugs in modern open source software. We will try to fix them under the help of Snitchaser.

Thank you for your reading.

Yes, pretty good description. Just have a look at my commit and you will find a very similar diff (i hope i fixed some more problems) :)