Bug#697682: libapache2-mod-perl2: Intermittent FTBFS: t/apache/read3.t failure

[Niko Tyni]

tag 697682 = patch
thanks

On Thu, Aug 07, 2014 at 04:32:08PM +0300, Niko Tyni wrote:
> On Sat, Mar 30, 2013 at 03:26:55PM +0000, Dominic Hargreaves wrote:

> > This doesn't seem to be limited to s390; I've seen it in on i386 during
> > perl 5.16 rebuilds.
> 
> As a data point, t/apache/read3.t fails for me consistently on the
> kfreebsd-{i386,amd64} porter boxes (fischer and falla) but interestingly
> not on the kfreebsd buildds.
> 
> The test is getting an internal server error, with this in the
> error log:
> 
>   [Thu Aug 07 13:30:28.768239 2014] [perl:error] [pid 81995:tid 34593212160] [client 127.0.0.1:12832] Apache2::RequestIO::read: (70007) The timeout specified has expired at /home/ntyni/libapache2-mod-perl2-2.0.8+httpd24-r1449661/t/response/TestApache/read3.pm line 30

As this was fully reproducible on the Debian/kFreeBSD boxes, I spent
some time debugging it.

The test is about a client sending a 12000 byte POST request to the
server, which reads it in a loop 100 bytes at a time and checks that it
all came through.

Starting the server with
 t/TEST -httpd_conf $(pwd)/debian/apache2.conf -one-process -start-httpd

attaching ktrace to it
 ktrace -p $(pgrep apache2) -f ktrace.apache2.2000

and then running the client part under ktrace as well:
 ktrace -f ktrace.client.2000 -- perl -Iblib/lib -Iblib/arch t/apache/read3.t

gives nice traces to inspect with kdump.

The failure only happens when the POSTed string is large enough that
it doesn't fit in the same write() call with the HTTP headers. So
"foobar"x1300 doesn't exhibit the problem but "foobar"x2000 does.

There seems to be a deadlock here:

 client writes the HTTP headers of the POST request but not the data yet
   server reads HTTP headers
   server writes HTTP OK + part of the body
 client calls select(), gets 2 so there are two descriptors ready (read+write)
 client reads HTTP OK + part of the body
   server tries to read the POST data but gets EAGAIN (no data yet)
   server calls poll() and blocks until there's something to read
 client calls select() again and blocks

The client is using LWP::Protocol::http under the hood, and I see it
indeed stops writing to the server when it gets a full HTTP header (up
to two newlines.) This is around line 386 of lib/LWP/Protocol/http.pm
in libwww-perl_6.08-1. Also, I note that it sends the whole POST request
in one write() unless it's over eight kilobytes long (see line 276.)

I'm unsure if there's a fault with the client (it gets an FD that's
ready for writing from the first select() call but ignores it, calls
select() again and blocks because the server has already called poll()
on the same descriptor), but the deadlock can be fixed/worked around by
making the server not send a response before the full POST request has
been read. See the attached patch, which fixes this completely for me.

I can also reproduce the issue on amd64 by running the test in a loop and
putting some load on the host. The patch makes it go away there too.

Cc'ing the modperl dev list. Please consider applying the patch.
-- 
Niko Tyni   ntyni at debian.org
-------------- next part --------------
A non-text attachment was scrubbed...
Name: 0001-Don-t-answer-anything-to-the-client-before-it-s-done.patch
Type: text/x-diff
Size: 1283 bytes
Desc: not available
URL: <http://lists.alioth.debian.org/pipermail/pkg-perl-maintainers/attachments/20140809/86b5cacc/attachment-0001.patch>