From: Niko Tyni <ntyni@iki.fi>
To: submit@bugs.debian.org
Subject: speedy-cgi-perl: error messages from die() are lost

I think I have run into a race condition in the communication between
the speedy frontend and Apache. When the perl script running in the
backend calls die(), the error message doesn't always reach the web
server error log.

The problem is 100% reproducible for me with SpeedyCGI 2.22 on Debian
Sarge using this CGI script:

-------------------
#!/usr/bin/speedy -w

use strict;
use CGI;

my $q = new CGI;
print $q->header;
print "foo\n";
die("bar\n");
-------------------

When invoked with a browser (Firefox), the first "bar" always ends up
in the error log, but nearly none of subsequent ones (about 1/10 or
thereabouts) from a reload do.  

When using curl from the command line, the behaviour is similar to
Firefox.

When using the 'GET' perl program from the libwww-perl library, no error
messages are lost.  The difference seems to be the 'Connection: close'
HTTP header that libwww-perl sends but Firefox and curl don't.


From studying the strace output of 'apache -X', it seems that the problem
triggers when the speedy frontend closes its STDOUT (going to Apache).
Apache then reacts by killing the CGI with SIGTERM, and sometimes this
happens before the frontend has had time to read the error output from
the backend and copy it to its own STDERR.

The STDOUT closing apparently happens in try_close(), called from around
line 350 in src/speedy_main.c. The copy loop there handles and closes
STDOUT before handling STDERR, which AIUI causes the bug.

I'm attaching a proposed patch, which fixes the behaviour completely for
me. Hope it makes sense. I can also provide strace outputs if you want,
but they are obviously quite lengthy.

Versions of relevant programs on my system:
- SpeedyCGI: 2.22   (speedy-cgi-perl 2.22-1)
- Apache:    1.3.33 (apache 1.3.33-6)
- Perl:      5.8.4  (perl 5.8.4-8)

(I have also reproduced the problem with the CVS version of
speedy_main.c, containing the 'Frontend was turning off O_APPEND flag
on stdout/stderr' patch, so it's not the same problem.)


--- src/speedy_main.c	2005/08/31 19:56:57	1.1
+++ src/speedy_main.c	2005/08/31 19:57:42
@@ -299,6 +299,7 @@
     /* Copy streams */
     while (1) {
 	/* Do reads/writes */
+        int close_stdout_delayed = 0;
 	for (i = 0; i < NUMFDS; ++i) {
 	    register CopyBuf *b = cb + i;
 	    int do_read  = my_canread(b) &&
@@ -346,10 +347,17 @@
 		/* Try to close files now, so we can wake up the backend
 		 * and do more I/O before dropping into select
 		 */
-		if (!do_read && !do_write)
-		    try_close(b);
-	    }
-	}
+		if (!do_read && !do_write) {
+                    if (i == 1)
+                        /* delay closing STDOUT until all the other fds are closed */
+                        close_stdout_delayed = 1;
+                    else
+		        try_close(b);
+                }
+            }
+        }
+        if (close_stdout_delayed)
+            try_close(cb+1);
 
 	/* All done with reads/writes after backend exited */
 	if (backend_exited) {