httpd-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Stefan Priebe - Profihost AG <s.pri...@profihost.ag>
Subject Re: mod_http2 - h2_session(): connections get's closed on graceful restart
Date Fri, 26 Aug 2016 18:02:10 GMT
Hi Stefan

tested today and works fine.

I just discovered another problem when using http2. Sadly i've no idea
what the problem is. May be you have an idea on how to debug.

I've a CGI Script written in perl which crashes with an internal server
error every 5-15 calls while running under http/2 details below.

What i've tested so far:
- works 100% with http/1.1

- works 100% with http2 if i close STDERR at the beginning this makes me
think it might be a http2 bug and not a perl bug or may be both.

- it happens only if i reload / or click fast enough it does not if i
leave 2-4s between each click

This might be the log (it's difficult to isolate the request):
[Fri Aug 26 19:54:05.303242 2016] [http2:debug] [pid 13222:tid
139700320794368] h2_session.c(1461): [client 1.2.3.4:38822] AH03073:
h2_stream(212-43): submit response 200, REMOTE_WINDOW_SIZE=6291456
[Fri Aug 26 19:54:05.303388 2016] [http2:debug] [pid 13222:tid
139700320794368] h2_session.c(652): [client 1.2.3.4:38822] AH03068:
h2_session(212): sent FRAME[HEADERS[length=34, hend=1, stream=43,
eos=0]], frames=25/45 (r/s)
[Fri Aug 26 19:54:05.303412 2016] [http2:debug] [pid 13222:tid
139700320794368] h2_session.c(652): [client 1.2.3.4:38822] AH03068:
h2_session(212): sent FRAME[DATA[length=3, flags=1, stream=43,
padlen=0]], frames=25/46 (r/s)
[Fri Aug 26 19:54:05.303789 2016] [http2:debug] [pid 13222:tid
139700320794368] h2_session.c(1707): [client 1.2.3.4:38822] AH03078:
h2_session(212): transit [BUSY] -- no io (keepalive) --> [IDLE]
[Fri Aug 26 19:54:05.321979 2016] [http2:debug] [pid 13222:tid
139700320794368] h2_stream.c(205): [client 1.2.3.4:38822] AH03082:
h2_stream(212-45): opened
[Fri Aug 26 19:54:05.322017 2016] [http2:debug] [pid 13222:tid
139700320794368] h2_session.c(432): [client 1.2.3.4:38822] AH03066:
h2_session(212): recv FRAME[HEADERS[length=126, hend=1, stream=45,
eos=1]], frames=25/47 (r/s)
[Fri Aug 26 19:54:05.322051 2016] [http2:debug] [pid 13222:tid
139700320794368] h2_session.c(1707): [client 1.2.3.4:38822] AH03078:
h2_session(212): transit [IDLE] -- data read --> [BUSY]
[Fri Aug 26 19:54:05.651654 2016] [http2:debug] [pid 13222:tid
139700320794368] h2_session.c(432): [client 1.2.3.4:38822] AH03066:
h2_session(212): recv FRAME[RST_STREAM[length=4, flags=0, stream=45]],
frames=26/47 (r/s)
[Fri Aug 26 19:54:05.651673 2016] [http2:debug] [pid 13222:tid
139700320794368] h2_session.c(501): [client 1.2.3.4:38822] AH03067:
h2_session(212-45): RST_STREAM by client, errror=8
[Fri Aug 26 19:54:05.651678 2016] [http2:debug] [pid 13222:tid
139700320794368] h2_session.c(340): [client 1.2.3.4:38822] AH03065:
h2_stream(212-45): closing with err=8 cancel
[Fri Aug 26 19:54:05.651697 2016] [http2:debug] [pid 13222:tid
139700320794368] h2_stream.c(205): [client 1.2.3.4:38822] AH03082:
h2_stream(212-47): opened
[Fri Aug 26 19:54:05.651720 2016] [http2:debug] [pid 13222:tid
139700320794368] h2_session.c(432): [client 1.2.3.4:38822] AH03066:
h2_session(212): recv FRAME[HEADERS[length=126, hend=1, stream=47,
eos=1]], frames=27/47 (r/s)
[Fri Aug 26 19:54:06.119019 2016] [http2:debug] [pid 13222:tid
139700772161280] h2_task.c(357): [client 1.2.3.4:38822] AH03348:
h2_task(212-45): open response to GET X.de /admin/admin.cgi?todo=admin
[Fri Aug 26 19:54:06.421545 2016] [cgid:error] [pid 13222:tid
139700755375872] [client 1.2.3.4:38822] End of script output before
headers: admin.cgi, referer: https://X.de/admin/admin.cgi?todo=admin
[Fri Aug 26 19:54:06.422195 2016] [http2:debug] [pid 13222:tid
139700755375872] h2_task.c(357): [client 1.2.3.4:38822] AH03348:
h2_task(212-47): open response to GET X.de /admin/admin.cgi?todo=admin
[Fri Aug 26 19:54:06.422276 2016] [http2:debug] [pid 13222:tid
139700320794368] h2_session.c(1461): [client 1.2.3.4:38822] AH03073:
h2_stream(212-47): submit response 500, REMOTE_WINDOW_SIZE=6291456
[Fri Aug 26 19:54:06.422302 2016] [http2:debug] [pid 13222:tid
139700320794368] h2_session.c(652): [client 1.2.3.4:38822] AH03068:
h2_session(212): sent FRAME[HEADERS[length=73, hend=1, stream=47,
eos=0]], frames=28/47 (r/s)
[Fri Aug 26 19:54:06.422319 2016] [http2:debug] [pid 13222:tid
139700320794368] h2_session.c(652): [client 1.2.3.4:38822] AH03068:
h2_session(212): sent FRAME[DATA[length=1751, flags=1, stream=47,
padlen=0]], frames=28/48 (r/s)
[Fri Aug 26 19:54:06.422615 2016] [http2:debug] [pid 13222:tid
139700320794368] h2_session.c(1707): [client 1.2.3.4:38822] AH03078:
h2_session(212): transit [BUSY] -- no io (keepalive) --> [IDLE]

Greets,
Stefan
Am 25.08.2016 um 10:26 schrieb Stefan Eissing:
> So, the fix is in both trunk and 2.4.x and the github repo has a new release. Can you
verify that it works for you also? Thanks!
> 
> 
>> Am 24.08.2016 um 10:18 schrieb Stefan Priebe - Profihost AG <s.priebe@profihost.ag>:
>>
>> Hi Stefan,
>>
>> were you able to reproduce? Did you need any help?
>>
>> Greets,
>> Stefan
>> Am 22.08.2016 um 18:07 schrieb Stefan Eissing:
>>> Hi Stefan,
>>>
>>> I am looking into this. It is definitely a bug in mod_http2.
>>>
>>>> Am 21.08.2016 um 14:26 schrieb Stefan Priebe <s.priebe@profihost.ag>:
>>>>
>>>> Hi,
>>>>
>>>> i'm running apache 2.4.23 with nghttpd 1.13 and i'm wondoring if it is correct
that chrome says:
>>>> ERR_CONNECTION_CLOSED
>>>>
>>>> while loading a page when the webserver does a graceful reload. This does
not happen with http 1/1 and mod_ssl.
>>>>
>>>> The log is below.
>>>>
>>>> Thanks,
>>>> Stefan
>>>>
>>>>
>>>> [Sun Aug 21 14:15:43.779555 2016] [http2:debug] [pid 29625:tid 140311678985984]
h2_session.c(1703): [client X.X.X.X:53763] AH03078: h2_session(0): transit [WAIT] -- wait
cycle --> [BUSY]
>>>> [Sun Aug 21 14:15:43.779619 2016] [http2:debug] [pid 29625:tid 140311678985984]
h2_session.c(1703): [client X.X.X.X:53763] AH03078: h2_session(0): transit [BUSY] -- no io
--> [WAIT]
>>>> [Sun Aug 21 14:15:43.979704 2016] [http2:debug] [pid 29625:tid 140311678985984]
h2_session.c(1703): [client X.X.X.X:53763] AH03078: h2_session(0): transit [WAIT] -- wait
cycle --> [BUSY]
>>>> [Sun Aug 21 14:15:43.979757 2016] [http2:debug] [pid 29625:tid 140311678985984]
h2_session.c(1703): [client X.X.X.X:53763] AH03078: h2_session(0): transit [BUSY] -- no io
--> [WAIT]
>>>> [Sun Aug 21 14:15:44.179865 2016] [http2:debug] [pid 29625:tid 140311678985984]
h2_session.c(1703): [client X.X.X.X:53763] AH03078: h2_session(0): transit [WAIT] -- wait
cycle --> [BUSY]
>>>> [Sun Aug 21 14:15:44.179922 2016] [http2:debug] [pid 29625:tid 140311678985984]
h2_session.c(1703): [client X.X.X.X:53763] AH03078: h2_session(0): transit [BUSY] -- no io
--> [WAIT]
>>>> [Sun Aug 21 14:15:44.380030 2016] [http2:debug] [pid 29625:tid 140311678985984]
h2_session.c(1703): [client X.X.X.X:53763] AH03078: h2_session(0): transit [WAIT] -- wait
cycle --> [BUSY]
>>>> [Sun Aug 21 14:15:44.380080 2016] [http2:debug] [pid 29625:tid 140311678985984]
h2_session.c(1703): [client X.X.X.X:53763] AH03078: h2_session(0): transit [BUSY] -- no io
--> [WAIT]
>>>> [Sun Aug 21 14:15:44.486387 2016] [mpm_event:notice] [pid 29610:tid 140311984822144]
AH00493: SIGUSR1 received.  Doing graceful restart
>>>> [Sun Aug 21 14:15:44.580194 2016] [http2:debug] [pid 29625:tid 140311678985984]
h2_session.c(1703): [client X.X.X.X:53763] AH03078: h2_session(0): transit [WAIT] -- wait
cycle --> [BUSY]
>>>> [Sun Aug 21 14:15:44.580242 2016] [http2:debug] [pid 29625:tid 140311678985984]
h2_session.c(655): [client X.X.X.X:53763] AH03068: h2_session(0): sent FRAME[GOAWAY[error=0,
reason='', last_stream=1]], frames=4/3 (r/s)
>>>> [Sun Aug 21 14:15:44.580296 2016] [http2:debug] [pid 29625:tid 140311678985984]
h2_session.c(752): [client X.X.X.X:53763] AH03069: session(0): sent GOAWAY, err=0, msg=
>>>> [Sun Aug 21 14:15:44.580301 2016] [http2:debug] [pid 29625:tid 140311678985984]
h2_session.c(1703): [client X.X.X.X:53763] AH03078: h2_session(0): transit [BUSY] -- local
goaway --> [LSHUTDOWN]
>>>> [Sun Aug 21 14:15:44.580333 2016] [ssl:debug] [pid 29625:tid 140311678985984]
ssl_engine_io.c(1033): [client X.X.X.X:53763] AH02001: Connection closed to child 0 with standard
shutdown (server XYZ:443)
>>>> [Sun Aug 21 14:15:47.495352 2016] [ldap:debug] [pid 29610:tid 140311984822144]
util_ldap.c(2533): AH01307: LDAP: SSL trusted mode - SSL
>>>> [Sun Aug 21 14:15:47.495871 2016] [ldap:debug] [pid 29610:tid 140311984822144]
util_ldap.c(2569): AH01308: LDAP: SSL verify server certificate - FALSE
>>>> [Sun Aug 21 14:15:47.544226 2016] [auth_digest:notice] [pid 29610:tid 140311984822144]
AH01757: generating secret for digest authentication ...
>>>> ...
>>>>
>>>
> 

Mime
View raw message