On Mon, Nov 25, 2013 at 4:28 PM, olli hauer <oha...@gmx.de> wrote:
> On 2013-11-25 22:14, Jeff Trawick wrote:
> > On Sun, Nov 24, 2013 at 8:39 PM, Jeff Trawick <traw...@gmail.com> wrote:
> >
> >> Let's move this to dev@httpd and omit dev@apr (after this e-mail)...
> >>
> >>
> >> On Sun, Nov 24, 2013 at 8:28 AM, olli hauer <oha...@gmx.de> wrote:
> >>
> >>> On 2013-11-22 00:08, Jeff Trawick wrote:
> >>>> On Thu, Nov 21, 2013 at 5:48 PM, olli hauer <oha...@gmx.de> wrote:
> >>>>
> >>>>> Hi,
> >>>>>
> >>>>> sorry for late response to apr-1.5.0 ...
> >>>>>
> >>>>> I've done some tests with apr-1.5.0 on FreeBSD 10 (amd64)
> >>>>> and it seems there is an issue that breaks apache24.
> >>>>>
> >>>>> With apr-1.5.0 apache22 works but apache24 is broken.
> >>>>> apache starts fine, nothing special in the logs or during
> >>>>> start with -X but no response is coming back.
> >>>>>
> >>>>> apr/apr-util test:
> >>>>> ========================================
> >>>>> apr-1.5.0: all tests passed [1]
> >>>>> apr-util-1.5.3: all tests passed
> >>>>>
> >>>>>
> >>>>> working configurations (FreeBSD beta3 [1]
> >>>>> =========================================
> >>>>> apache22-2.2.26 apr-1.4.8 apr-util-1.5.3
> >>>>> apache22-2.2.26 apr-1.5.0 apr-util-1.5.3
> >>>>> apache24-2.4.6 apr-1.4.8 apr-util-1.5.2
> >>>>> apache24-2.4.7 apr-1.4.8 apr-util-1.5.2
> >>>>> apache24-2.4.6 apr-1.4.8 apr-util-1.5.3
> >>>>> apache24-2.4.7 apr-1.4.8 apr-util-1.5.3
> >>>>>
> >>>>> broken combinations:
> >>>>> =========================================
> >>>>> apache24-2.4.6 apr-1.5.0 apr-util-1.5.3
> >>>>> apache24-2.4.7 apr-1.5.0 apr-util-1.5.3
> >>>>>
> >>>>> All tests where done with MPM worker.
> >>>>>
> >>>>>
> >>>>> FreeBSD 8.4 (amd64) seems OK in all combinations
> >>>>> FreeBSD 9.2 (amd64) seems OK in all combinations
> >>>>>
> >>>>> [1] FreeBSD 10 beta3 with iconv UTF7 patch r258316
> >>>>> (head/lib/libiconv_modules/UTF7/citrus_utf7.c)
> >>>>>
> >>>>> Any hints where to start?
> >>>>>
> >>>>
> >>>> Set LogLevel trace8 and compare good vs. bad.
> >>>> Start with -X then attach with dtruss and compare good vs. bad.
> >>>> Get open fds displayed by lsof and compare good vs. bad.
> >>>> Is connection to client held open? Get backtraces.
> >>>>
> >>>> I just compared 1.4.8 vs. 1.5.0 and didn't see anything that looked
> >>>> remotely likely.
> >>>>
> >>>
> >>> Comparing trace8 outputs showed the request is processed
> >>> but the following code snippet in server/core_filters.c
> >>> never get TRUE except the client cancels the request.
> >>>
> >>> To get some better log entries I've used server/core_filters.c
> >>> r1510295 from trunk.
> >>>
> >>>
> >>> @@server/core_filters.c (line 510)
> >>> if (APR_BUCKET_IS_FLUSH(bucket)
> >>> || non_file_bytes_in_brigade >= THRESHOLD_MAX_BUFFER
> >>> || morphing_bucket_in_brigade
> >>> || eor_buckets_in_brigade > MAX_REQUESTS_IN_PIPELINE) {
> >>> ...
> >>> }
> >>>
> >>> [http:trace3] http_filters.c(974):[client x.x.x.x:x] Response sent with
> >>> status 200, headers:
> >>> [http:trace5] http_filters.c(983):[client x.x.x.x:x] Date: Sun, 24
> Nov
> >>> 2013 10:28:37 GMT
> >>> [http:trace5] http_filters.c(986):[client x.x.x.x:x] Server:
> >>> Apache/2.4.7 (FreeBSD)
> >>> [http:trace4] http_filters.c(804):[client x.x.x.x:x] Last-Modified:
> >>> Sat, 23 Nov 2013 16:51:58 GMT
> >>> [http:trace4] http_filters.c(804):[client x.x.x.x:x] ETag:
> >>> \\"be-4ebdaf2ef2780\\"
> >>> [http:trace4] http_filters.c(804):[client x.x.x.x:x] Accept-Ranges:
> >>> bytes
> >>> [http:trace4] http_filters.c(804):[client x.x.x.x:x] Content-Length:
> 190
> >>> [http:trace4] http_filters.c(804):[client x.x.x.x:x] Keep-Alive:
> >>> timeout=5, max=100
> >>> [http:trace4] http_filters.c(804):[client x.x.x.x:x] Connection:
> >>> Keep-Alive
> >>> [http:trace4] http_filters.c(804):[client x.x.x.x:x] Content-Type:
> >>> text/html
> >>> [core:trace8] core_filters.c(576):[client x.x.x.x:x] brigade contains:
> >>> bytes: 284, non-file bytes: 284, eor buckets: 0, morphing buckets: 0
> >>> [core:trace8] core_filters.c(576):[client x.x.x.x:x] brigade contains:
> >>> bytes: 474, non-file bytes: 284, eor buckets: 0, morphing buckets: 0
> >>> [core:trace8] core_filters.c(576):[client x.x.x.x:x] brigade contains:
> >>> bytes: 474, non-file bytes: 284, eor buckets: 1, morphing buckets: 0
> >>>
> >>>
> >>> This following lines are only seen if
> >>> apr-1-5.0 was build without IPv6 support
> >>> or apache24 was build with v4-mapping enabled
> >>> or "Listen $IP:$port" is given in httpd.conf
> >>>
> >>> [core:trace6] core_filters.c(526):[client x.x.x.x:x] will flush because
> >>> of FLUSH bucket
> >>> [core:trace8] core_filters.c(528):[client x.x.x.x:x] seen in brigade so
> >>> far: bytes: 474, non-file bytes: 284, eor buckets: 1, morphing
> buckets: 0
> >>> [core:trace8] core_filters.c(555):[client x.x.x.x:x] flushing now
> >>> [core:trace8] core_filters.c(568):[client x.x.x.x:x] total bytes
> written:
> >>> 474
> >>> [core:trace8] core_filters.c(576):[client x.x.x.x:x] brigade contains:
> >>> bytes: 0, non-file bytes: 0, eor buckets: 0, morphing buckets: 0
> >>>
> >>> However a flush is triggered if the client cancels the request, but no
> >>> data is sent over the wire ...
> >>>
> >>>
> >>> I've searched if other also have seen a similar issue and found
> >>> instead the following interesting article from Nov. 2002 ;)
> >>> http://people.apache.org/~trawick/v4mapped.html
> >>>
> >>>
> >> I haven't analyzed the trace messages you showed above. Here's what I
> did
> >> on FreeBSD 9:
> >>
> >> Apply this patch to fix the version check for disabling v4mapped
> addresses:
> >>
> >> Index: configure.in
> >> ===================================================================
> >> --- configure.in (revision 1545127)
> >> +++ configure.in (working copy)
> >> @@ -774,7 +774,10 @@
> >> ],
> >> [
> >> case $host in
> >> - *freebsd5*|*netbsd*|*openbsd*)
> >> + *freebsd[1234].*)
> >> + v4mapped=yes
> >> + ;;
> >> + *freebsd*|*netbsd*|*openbsd*)
> >> v4mapped=no
> >> ;;
> >> *)
> >>
> >> That gives me
> >>
> >> $ bin/apachectl -V
> >> AH00558: httpd: Could not reliably determine the server's fully
> qualified
> >> domain name, using 127.0.0.1. Set the 'ServerName' directive globally to
> >> suppress this message
> >> Server version: Apache/2.4.8-dev (Unix)
> >> Server built: Nov 24 2013 20:21:30
> >> Server's Module Magic Number: 20120211:27
> >> Server loaded: APR 1.5.1-dev, APR-UTIL 1.5.4-dev
> >> Compiled using: APR 1.5.1-dev, APR-UTIL 1.5.4-dev
> >> Architecture: 64-bit
> >> Server MPM: worker
> >> threaded: yes (fixed thread count)
> >> forked: yes (variable process count)
> >> Server compiled with....
> >> -D APR_HAS_SENDFILE
> >> -D APR_HAS_MMAP
> >> -D APR_HAVE_IPV6 (IPv4-mapped addresses disabled)
> >>
> >> The last line shown indicates that mapped addresses are disabled in this
> >> build.
> >>
> >> The only Listen I have is "Listen 8080". procstat says I have separate
> >> sockets, as expected:
> >>
> >> 60734 httpd 3 s - rw---n--- 9 0 TCP ::.8080 ::.0
> >> 60734 httpd 4 s - rw---n--- 9 0 TCP 0.0.0.0:8080
> >> 0.0.0.0:0
> >>
> >> From netstat:
> >>
> >> tcp4 0 0 *.8080 *.* LISTEN
> >> tcp6 0 0 *.8080 *.* LISTEN
> >>
> >> (You had shown sockstat before; this is the same stuff.)
> >>
> >> --/--
> >>
> >> Are you able to check for the issue on FreeBSD 9?
> >>
> >> When it hangs, are you connecting to the IPv4 listener or the IPv6
> >> listener? Does it matter whether you use loopback or the address of a
> >> network interface?
> >>
> >> You're using a regular web browser in the failing case, right? Have you
> >> tried something as simple as netcat for the failing address/port?
> Example:
> >>
> >> $ echo "GET /" | nc 127.0.0.1 8080
> >> <html><body><h1>It works!</h1></body></html>
> >>
> >> --
> >> Born in Roswell... married an alien...
> >> http://emptyhammock.com/
> >>
> >
> > I see the hang on FreeBSD 10 Beta 3 using the same sources, though clang
> is
> > installed instead of gcc.
> >
> > FWIW, the simple "GET /<EOF>" request works but an HTTP/1.1 request from
> > telnet or from Firefox hangs. I am able to try loopback over IPv4 and
> IPv6
> > and they both hang.
> >
> > Now move the gcc binaries from FreeBSD 9 to FreeBSD 10 (along with
> > libpcre.0): I don't see the hang with the simple testcases that triggered
> > it with the clang builds.
> >
> > I wouldn't be surprised if your apr-1.5-as-trigger observation reflects
> > "accidents" like code moving around and/or changing in size. I didn't
> see
> > any interesting changes in the source that would affect the path where
> the
> > hang occurs. But who really knows :)
> >
>
> Playing with the code (damage included), moving 'flush_upto = next;'
> and the page loads. I still have some problems to understand how complete
> code is working (or even not).
>
> What is not clear to me why 'if (APR_BUCKET_IS_FLUSH(bucket)' is not
> triggered?
>
It is for me at least during lingering close, and I go into the "if
(flush_upto != NULL) {" block as expected.
>From the start of a response to the simple index.html I see a HEAP bucket
(hdrs?), FILE bucket, EOS bucket, EOR bucket, and maybe something else I
glossed over, but no flush bucket.
I think the issue may be that after generating the response for one
request, httpd thinks there is a pipelined request and instead of flushing
the first response it goes to read the next request but none is available.
Yep, hung here:
Breakpoint 1, check_pipeline (c=0x8026282b8) at http_request.c:221
221 if (c->keepalive != AP_CONN_CLOSE) {
Current language: auto; currently minimal
(gdb) p c->keepalive
$1 = AP_CONN_KEEPALIVE
(gdb) n
223 apr_bucket_brigade *bb = apr_brigade_create(c->pool,
c->bucket_alloc);
(gdb)
225 rv = ap_get_brigade(c->input_filters, bb, AP_MODE_SPECULATIVE,
(gdb) list
220 {
221 if (c->keepalive != AP_CONN_CLOSE) {
222 apr_status_t rv;
223 apr_bucket_brigade *bb = apr_brigade_create(c->pool,
c->bucket_alloc);
224
225 rv = ap_get_brigade(c->input_filters, bb, AP_MODE_SPECULATIVE,
226 APR_NONBLOCK_READ, 1);
227 if (rv != APR_SUCCESS || APR_BRIGADE_EMPTY(bb)) {
228 /*
229 * Error or empty brigade: There is no data present in the
input
(gdb) n
(HANGING in call at line 225)
>
> --- core_filters.c.orig
> +++ core_filters.c
> @@ -527,13 +527,14 @@
> /*
> * Defer the actual blocking write to avoid doing many writes.
> */
> - flush_upto = next;
> +// flush_upto = next;
>
> bytes_in_brigade = 0;
> non_file_bytes_in_brigade = 0;
> eor_buckets_in_brigade = 0;
> morphing_bucket_in_brigade = 0;
> }
> + flush_upto = next;
> }
>
> if (flush_upto != NULL) {
>
> --
> olli
>
--
Born in Roswell... married an alien...
http://emptyhammock.com/
