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 > <[email protected]>: > > Am 29.08.2016 um 15:52 schrieb Stefan Eissing: >> >>> Am 29.08.2016 um 15:43 schrieb Stefan Priebe - Profihost AG >>> <[email protected]>: >>> >>> Am 29.08.2016 um 15:31 schrieb Stefan Eissing: >>>> >>>>> Am 26.08.2016 um 20:02 schrieb Stefan Priebe - Profihost AG >>>>> <[email protected]>: >>>>> >>>>> [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
