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 Mon, 29 Aug 2016 14:16:52 GMT
Am 29.08.2016 um 15:52 schrieb Stefan Eissing:
> 
>> Am 29.08.2016 um 15:43 schrieb Stefan Priebe - Profihost AG <s.priebe@profihost.ag>:
>>
>> Am 29.08.2016 um 15:31 schrieb Stefan Eissing:
>>>
>>>> Am 26.08.2016 um 20:02 schrieb Stefan Priebe - Profihost AG <s.priebe@profihost.ag>:
>>>>
>>>> [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.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
>>>
>>> What I can see here is that stream 45 is opened on connection 212 and
>>> scheduled for processing. The client then aborts the request (RST_STREAM)
>>> and start the new stream 47.
>>> During this, the CGI has produced a response ("open response") which
>>> leads to an error, since the stream is gone, and the CGI closes early
>>> (End of script output before headers)
>>
>> The problem is this happens only sporadic. You can reload the page X
>> times and in about 1/10 you get an internal server error. You never get
>> one if you close STDERR in the beginning of the script. This also never
>> happens with HTTP 1.1.
>>
>>
>>> So, I'd say from the log output, all seems as expected. Where is the internal
server error you mentioned?
>> What do you exactly mean? There is nothing else written to the log. Not
>> even an error log message.
> 
> What I mean is that I see no delivery to the client that contains an error. What exactly
do you see? A "500 blabla HTTP/2" status response? Or something else? That is not clear to
me (or I overlooked sth)

Response Header is:
accept-ranges:bytes
content-length:1751
content-type:text/html
date:Mon, 29 Aug 2016 14:06:56 GMT
last-modified:Wed, 10 Sep 2014 08:40:06 GMT
server:Apache
status:500
strict-transport-security:max-age=7776000
vary:User-Agent

May be this filtered log output is better:

It was produced by:
grep "131" server-error.log | egrep "=77|-77"

[Mon Aug 29 16:12:09.672322 2016] [http2:debug] [pid 28482:tid
139700455077632] h2_stream.c(205): [client X.X.X.X:51744] AH03082:
h2_stream(131-77): opened
[Mon Aug 29 16:12:09.672386 2016] [http2:debug] [pid 28482:tid
139700455077632] h2_session.c(432): [client X.X.X.X:51744] AH03066:
h2_session(131): recv FRAME[HEADERS[length=128, hend=1, stream=77,
eos=1]], frames=41/81 (r/s)
[Mon Aug 29 16:12:10.051331 2016] [http2:debug] [pid 28482:tid
139700455077632] h2_session.c(1461): [client X.X.X.X:51744] AH03073:
h2_stream(131-77): submit response 500, REMOTE_WINDOW_SIZE=6291456
[Mon Aug 29 16:12:10.051364 2016] [http2:debug] [pid 28482:tid
139700455077632] h2_session.c(652): [client X.X.X.X:51744] AH03068:
h2_session(131): sent FRAME[HEADERS[length=22, hend=1, stream=77,
eos=0]], frames=42/83 (r/s)
[Mon Aug 29 16:12:10.051381 2016] [http2:debug] [pid 28482:tid
139700455077632] h2_session.c(652): [client X.X.X.X:51744] AH03068:
h2_session(131): sent FRAME[DATA[length=1751, flags=1, stream=77,
padlen=0]], frames=42/84 (r/s)
[Mon Aug 29 16:12:15.969186 2016] [http2:debug] [pid 28482:tid
139700278830848] h2_session.c(652): [remote X.X.X.X:51744] AH03068:
h2_session(131): sent FRAME[GOAWAY[error=0, reason='timeout',
last_stream=77]], frames=42/85 (r/s)


Stefan



Mime
View raw message