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 >> <[email protected]>: >> >> 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 <[email protected]>: >>>> >>>> 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 ... >>>> ... >>>> >>> >
