Re: mod_http2 - h2_session(): connections get's closed on graceful restart

[Stefan Priebe - Profihost AG <s....@profihost.ag>]

Hi,

sadly i can't send you that script. It's a big bunch of libs and code
and does not run on every server.

I'll first try to investigate further. Thanks!

Stefan
Am 31.08.2016 um 13:37 schrieb Stefan Eissing:
> It really looks as if the CGI process simply died without sending a (part of a) response. How that is tied to closing stderr or not, I have not the slightest idea. Can you send me your cgi/perl related config, so I might do some tests on my own? thanks!
> 
> 
>> Am 29.08.2016 um 16:16 schrieb Stefan Priebe - Profihost AG <s....@profihost.ag>:
>>
>> Am 29.08.2016 um 15:52 schrieb Stefan Eissing:
>>>
>>>> Am 29.08.2016 um 15:43 schrieb Stefan Priebe - Profihost AG <s....@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....@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
>