httpd-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Stefan Eissing <stefan.eiss...@greenbytes.de>
Subject Re: svn commit: r1735176 - in /httpd/httpd/trunk: CHANGES modules/http/http_core.c
Date Wed, 16 Mar 2016 12:06:51 GMT
What I see here on a single process server (-X) for simplicity:

[Wed Mar 16 12:00:25.191155 2016] [mpm_event:trace6] [pid 95897:tid 123145323229184] event.c(1779):
connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Wed Mar 16 12:00:26.218216 2016] [mpm_event:trace6] [pid 95897:tid 123145323229184] event.c(1779):
connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Wed Mar 16 12:00:27.240436 2016] [mpm_event:trace6] [pid 95897:tid 123145323229184] event.c(1779):
connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Wed Mar 16 12:00:28.267453 2016] [mpm_event:trace6] [pid 95897:tid 123145323229184] event.c(1779):
connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Wed Mar 16 12:00:29.283653 2016] [mpm_event:trace6] [pid 95897:tid 123145323229184] event.c(1779):
connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Wed Mar 16 12:00:30.286473 2016] [mpm_event:trace6] [pid 95897:tid 123145323229184] event.c(1779):
connections: 1 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Wed Mar 16 12:00:31.306868 2016] [mpm_event:trace6] [pid 95897:tid 123145323229184] event.c(1779):
connections: 1 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Wed Mar 16 12:00:32.331939 2016] [mpm_event:trace6] [pid 95897:tid 123145323229184] event.c(1779):
connections: 1 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)

when I connect via curl, but no response comes back:
12:59:58 delight:~/projects/httpd/test/mod_h2/trunk> /opt/apache-trunk/bin/curl -vvv http://test.example.org:12345
* Rebuilt URL to: http://test.example.org:12345/
*   Trying 127.0.0.1...
* Connected to test.example.org (127.0.0.1) port 12345 (#0)
> GET / HTTP/1.1
> Host: test.example.org:12345
> User-Agent: curl/7.47.1
> Accept: */*
> 
^C

A direct HTTP/2 connection via nghttp works:

Wed Mar 16 12:02:31.967934 2016] [core:trace6] [pid 95897:tid 123145310887936] util_filter.c(801):
[client 127.0.0.1:58729] reinstate empty brigade to full brigade in 'core' output filter
[Wed Mar 16 12:02:31.967954 2016] [core:trace6] [pid 95897:tid 123145310887936] util_filter.c(884):
[client 127.0.0.1:58729] will flush because of FLUSH bucket
[Wed Mar 16 12:02:31.967959 2016] [core:trace8] [pid 95897:tid 123145310887936] util_filter.c(886):
[client 127.0.0.1:58729] seen in brigade so far: bytes: 37, non-file bytes: 37, eor buckets:
0, morphing buckets: 0
[Wed Mar 16 12:02:31.967964 2016] [core:trace8] [pid 95897:tid 123145310887936] util_filter.c(910):
[client 127.0.0.1:58729] brigade contains: bytes: 0, non-file bytes: 0, eor buckets: 0, morphing
buckets: 0
[Wed Mar 16 12:02:31.967980 2016] [core:trace8] [pid 95897:tid 123145310887936] core_filters.c(446):
[client 127.0.0.1:58729] flushing now
[Wed Mar 16 12:02:31.967964 2016] [http:trace4] [pid 95897:tid 123145302839296] http_request.c(398):
[client 127.0.0.1:58729] Headers received from client:
[Wed Mar 16 12:02:31.967998 2016] [http:trace4] [pid 95897:tid 123145302839296] http_request.c(401):
[client 127.0.0.1:58729]   Accept: */*
[Wed Mar 16 12:02:31.968009 2016] [http:trace4] [pid 95897:tid 123145302839296] http_request.c(401):
[client 127.0.0.1:58729]   Accept-Encoding: gzip, deflate
[Wed Mar 16 12:02:31.968004 2016] [core:trace8] [pid 95897:tid 123145310887936] core_filters.c(460):
[client 127.0.0.1:58729] total bytes written: 37
[Wed Mar 16 12:02:31.968027 2016] [core:trace8] [pid 95897:tid 123145310887936] core_filters.c(480):
[client 127.0.0.1:58729] tried nonblocking write, total bytes written: 37
[Wed Mar 16 12:02:31.968036 2016] [core:trace6] [pid 95897:tid 123145310887936] util_filter.c(741):
[client 127.0.0.1:58729] setaside empty brigade to empty brigade in 'core' output filter
[Wed Mar 16 12:02:31.968017 2016] [http:trace4] [pid 95897:tid 123145302839296] http_request.c(401):
[client 127.0.0.1:58729]   User-Agent: nghttp2/1.8.0
[Wed Mar 16 12:02:31.968051 2016] [http:trace4] [pid 95897:tid 123145302839296] http_request.c(401):
[client 127.0.0.1:58729]   Host: test.example.org:12345
[Wed Mar 16 12:02:31.968110 2016] [rewrite:trace2] [pid 95897:tid 123145302839296] mod_rewrite.c(485):
[client 127.0.0.1:58729] 127.0.0.1 - - [test.example.org/sid#7fd4318a6b78][rid#7fd4318e56a0/initial]
init rewrite engine with requested uri /
[Wed Mar 16 12:02:31.968120 2016] [rewrite:trace3] [pid 95897:tid 123145302839296] mod_rewrite.c(485):
[client 127.0.0.1:58729] 127.0.0.1 - - [test.example.org/sid#7fd4318a6b78][rid#7fd4318e56a0/initial]
applying pattern '^/latest.tar.gz$' to uri '/'
[Wed Mar 16 12:02:31.968154 2016] [rewrite:trace3] [pid 95897:tid 123145302839296] mod_rewrite.c(485):
[client 127.0.0.1:58729] 127.0.0.1 - - [test.example.org/sid#7fd4318a6b78][rid#7fd4318e56a0/initial]
applying pattern '/rewrite(.*)' to uri '/'
[Wed Mar 16 12:02:31.968162 2016] [rewrite:trace3] [pid 95897:tid 123145302839296] mod_rewrite.c(485):
[client 127.0.0.1:58729] 127.0.0.1 - - [test.example.org/sid#7fd4318a6b78][rid#7fd4318e56a0/initial]
applying pattern '/redirect(.*)' to uri '/'
[Wed Mar 16 12:02:31.968168 2016] [rewrite:trace1] [pid 95897:tid 123145302839296] mod_rewrite.c(485):
[client 127.0.0.1:58729] 127.0.0.1 - - [test.example.org/sid#7fd4318a6b78][rid#7fd4318e56a0/initial]
pass through /
[Wed Mar 16 12:02:31.968258 2016] [authz_core:debug] [pid 95897:tid 123145302839296] mod_authz_core.c(806):
[client 127.0.0.1:58729] AH01626: authorization result of Require all granted: granted
[Wed Mar 16 12:02:31.968267 2016] [authz_core:debug] [pid 95897:tid 123145302839296] mod_authz_core.c(806):
[client 127.0.0.1:58729] AH01626: authorization result of <RequireAny>: granted
[Wed Mar 16 12:02:31.968271 2016] [core:trace3] [pid 95897:tid 123145302839296] request.c(295):
[client 127.0.0.1:58729] request authorized without authentication by access_checker_ex hook:
/
[Wed Mar 16 12:02:31.968296 2016] [rewrite:trace2] [pid 95897:tid 123145302839296] mod_rewrite.c(485):
[client 127.0.0.1:58729] 127.0.0.1 - - [test.example.org/sid#7fd4318a6b78][rid#7fd4318e96a0/subreq]
init rewrite engine with requested uri /index.html
[Wed Mar 16 12:02:31.968304 2016] [rewrite:trace3] [pid 95897:tid 123145302839296] mod_rewrite.c(485):
[client 127.0.0.1:58729] 127.0.0.1 - - [test.example.org/sid#7fd4318a6b78][rid#7fd4318e96a0/subreq]
applying pattern '/rewrite(.*)' to uri '/index.html'
[Wed Mar 16 12:02:31.968317 2016] [rewrite:trace3] [pid 95897:tid 123145302839296] mod_rewrite.c(485):
[client 127.0.0.1:58729] 127.0.0.1 - - [test.example.org/sid#7fd4318a6b78][rid#7fd4318e96a0/subreq]
applying pattern '/redirect(.*)' to uri '/index.html'
[Wed Mar 16 12:02:31.968324 2016] [rewrite:trace1] [pid 95897:tid 123145302839296] mod_rewrite.c(485):
[client 127.0.0.1:58729] 127.0.0.1 - - [test.example.org/sid#7fd4318a6b78][rid#7fd4318e96a0/subreq]
pass through /index.html
[Wed Mar 16 12:02:31.968542 2016] [core:trace6] [pid 95897:tid 123145302839296] util_filter.c(801):
[client 127.0.0.1:58729] reinstate empty brigade to full brigade in 'req_core' output filter
[Wed Mar 16 12:02:31.968554 2016] [core:trace8] [pid 95897:tid 123145302839296] util_filter.c(910):
[client 127.0.0.1:58729] brigade contains: bytes: 2005, non-file bytes: 0, eor buckets: 0,
morphing buckets: 0
[Wed Mar 16 12:02:31.968613 2016] [core:trace6] [pid 95897:tid 123145302839296] util_filter.c(741):
[client 127.0.0.1:58729] setaside empty brigade to empty brigade in 'req_core' output filter
[Wed Mar 16 12:02:31.968633 2016] [core:trace6] [pid 95897:tid 123145302839296] util_filter.c(801):
[client 127.0.0.1:58729] reinstate empty brigade to full brigade in 'req_core' output filter
[Wed Mar 16 12:02:31.968644 2016] [core:trace8] [pid 95897:tid 123145302839296] util_filter.c(910):
[client 127.0.0.1:58729] brigade contains: bytes: 0, non-file bytes: 0, eor buckets: 1, morphing
buckets: 0
[Wed Mar 16 12:02:31.968666 2016] [core:trace6] [pid 95897:tid 123145302839296] util_filter.c(741):
[client 127.0.0.1:58729] setaside empty brigade to empty brigade in 'req_core' output filter
[Wed Mar 16 12:02:31.968673 2016] [core:trace6] [pid 95897:tid 123145310887936] util_filter.c(801):
[client 127.0.0.1:58729] reinstate empty brigade to full brigade in 'core' output filter
[Wed Mar 16 12:02:31.968697 2016] [core:trace6] [pid 95897:tid 123145310887936] util_filter.c(884):
[client 127.0.0.1:58729] will flush because of FLUSH bucket
[Wed Mar 16 12:02:31.968705 2016] [core:trace8] [pid 95897:tid 123145310887936] util_filter.c(886):
[client 127.0.0.1:58729] seen in brigade so far: bytes: 2142, non-file bytes: 137, eor buckets:
0, morphing buckets: 0
[Wed Mar 16 12:02:31.968711 2016] [core:trace8] [pid 95897:tid 123145310887936] util_filter.c(910):
[client 127.0.0.1:58729] brigade contains: bytes: 0, non-file bytes: 0, eor buckets: 0, morphing
buckets: 0
[Wed Mar 16 12:02:31.968716 2016] [core:trace8] [pid 95897:tid 123145310887936] core_filters.c(446):
[client 127.0.0.1:58729] flushing now
[Wed Mar 16 12:02:31.968766 2016] [core:trace8] [pid 95897:tid 123145310887936] core_filters.c(460):
[client 127.0.0.1:58729] total bytes written: 2179
[Wed Mar 16 12:02:31.968774 2016] [core:trace8] [pid 95897:tid 123145310887936] core_filters.c(480):
[client 127.0.0.1:58729] tried nonblocking write, total bytes written: 2179
[Wed Mar 16 12:02:31.968779 2016] [core:trace6] [pid 95897:tid 123145310887936] util_filter.c(741):
[client 127.0.0.1:58729] setaside empty brigade to empty brigade in 'core' output filter
[Wed Mar 16 12:02:31.969067 2016] [core:trace6] [pid 95897:tid 123145310887936] util_filter.c(801):
[client 127.0.0.1:58729] reinstate empty brigade to full brigade in 'core' output filter
[Wed Mar 16 12:02:31.969077 2016] [core:trace8] [pid 95897:tid 123145310887936] util_filter.c(910):
[client 127.0.0.1:58729] brigade contains: bytes: 0, non-file bytes: 0, eor buckets: 0, morphing
buckets: 0
[Wed Mar 16 12:02:31.969098 2016] [core:trace8] [pid 95897:tid 123145310887936] core_filters.c(480):
[client 127.0.0.1:58729] tried nonblocking write, total bytes written: 2179
[Wed Mar 16 12:02:31.969103 2016] [core:trace6] [pid 95897:tid 123145310887936] util_filter.c(741):
[client 127.0.0.1:58729] setaside empty brigade to empty brigade in 'core' output filter
[Wed Mar 16 12:02:31.969112 2016] [core:trace6] [pid 95897:tid 123145310887936] util_filter.c(801):
[client 127.0.0.1:58729] reinstate empty brigade to full brigade in 'core' output filter
[Wed Mar 16 12:02:31.969130 2016] [core:trace6] [pid 95897:tid 123145310887936] util_filter.c(884):
[client 127.0.0.1:58729] will flush because of FLUSH bucket
[Wed Mar 16 12:02:31.969135 2016] [core:trace8] [pid 95897:tid 123145310887936] util_filter.c(886):
[client 127.0.0.1:58729] seen in brigade so far: bytes: 0, non-file bytes: 0, eor buckets:
0, morphing buckets: 0
[Wed Mar 16 12:02:31.969142 2016] [core:trace8] [pid 95897:tid 123145310887936] util_filter.c(910):
[client 127.0.0.1:58729] brigade contains: bytes: 0, non-file bytes: 0, eor buckets: 0, morphing
buckets: 0
[Wed Mar 16 12:02:31.969157 2016] [core:trace8] [pid 95897:tid 123145310887936] core_filters.c(446):
[client 127.0.0.1:58729] flushing now
[Wed Mar 16 12:02:31.969164 2016] [core:trace8] [pid 95897:tid 123145310887936] core_filters.c(460):
[client 127.0.0.1:58729] total bytes written: 2179
[Wed Mar 16 12:02:31.969170 2016] [core:trace8] [pid 95897:tid 123145310887936] core_filters.c(480):
[client 127.0.0.1:58729] tried nonblocking write, total bytes written: 2179
[Wed Mar 16 12:02:31.969179 2016] [core:trace6] [pid 95897:tid 123145310887936] util_filter.c(741):
[client 127.0.0.1:58729] setaside empty brigade to empty brigade in 'core' output filter
[Wed Mar 16 12:02:32.594197 2016] [mpm_event:trace6] [pid 95897:tid 123145323229184] event.c(1779):
connections: 1 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Wed Mar 16 12:02:33.640128 2016] [mpm_event:trace6] [pid 95897:tid 123145323229184] event.c(1779):
connections: 1 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Wed Mar 16 12:02:34.663879 2016] [mpm_event:trace6] [pid 95897:tid 123145323229184] event.c(1779):
connections: 1 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[
> Am 16.03.2016 um 12:25 schrieb Graham Leggett <minfrin@sharp.fm>:
> 
> On 16 Mar 2016, at 1:08 PM, Stefan Eissing <stefan.eissing@greenbytes.de> wrote:
> 
>> I needed to revert r1735174 to make HTTP/1.1 work again. I submitted this to trunk
since other people are affected too.
>> 
>> Graham: if you are unable to reproduce this and need any additional data, pls let
me know.
> 
> The test suite runs clean for me - when it hangs can you confirm where it is hanging?
> 
> Regards,
> Graham
> —
> 


Mime
View raw message