Ok, analyzed the code. Here is what seems to be happening: - mod_http2, in the connection hook, does a blocking, speculative read to a) make sure the ALPN has been triggered b) check for the magic 24 bytes h2 preface in case H2Direct is on This works fine for HTTP/1.1 or protocols where the client starts sending bytes right away. If the client waits for something from the server first, it gives a timeout. This seems to be the NNTP case.
A. The important part is to get the ALPN triggered without a blocking read. Any advice from our TLS experts? B. When that is solved, the check for the 24 bytes can be folder deeper to just happen on a H2Direct enabled server/vhost. The fix for A ideally should be placed into mod_ssl, saving other protocol-selection code to mess with it, I think. But for the short term, I'd be happy with any advice on how to fix it in mod_http2 alone. //Stefan > Am 11.10.2015 um 18:26 schrieb Stefan Eissing <stefan.eiss...@greenbytes.de>: > > Hmm, will look into this. The module does a speculative non_blocking read on > the connection. > > That happens only if H2Direct is "on", which I enabled to allow test when the > client does not have ALPN. > > Then it can detect on the first 24 bytes if the client starts talking h2 > right away. Is doing a speculative read messing up the handshake? > > This is not a usual config. > > //stefan > >> Am 11.10.2015 um 15:32 schrieb Rainer Jung <rainer.j...@kippdata.de>: >> >> I get a test failure for 2.4.17 in the mod_nntp_like_ssl part. Te failure >> happens on Solaris. Note that the nntp tests are disabled by default on >> Linux because of problems with the kernel accept filter, so that many of you >> wont run this test and thus not observe the problem. >> >> The problems is that the test hangs after test 1 when waiting for the result >> of 2. On Solaris 8 the behavior changes a bit, there test 2 succeeds, but >> 3-5 receive an empty result. The difference might be due to slight perl test >> differences. I suspect a common root cause. >> >> Maybe the problem is due to some unclean brigade handling in >> mod_nntp_like_ssl (in light of recent dev list discussions)? Or mod_http2 is >> simply incompatible with mod_nntp_like_ssl and we should disable that test >> if mod_http2 is loaded? >> >> Trace 8 log comparison between good runs (without having mod_http2 loaded) >> and bad runs (having mod_http2 loaded): >> >> Good run (no mod_http2) >> >> - end of handshake and immediately write 52 bytes >> >> [Sun Oct 11 14:53:47.911105 2015] [ssl:trace3] [pid 23096:tid 27] >> ssl_engine_kernel.c(1810): [client 127.0.0.1:50990] OpenSSL: Handshake: done >> [Sun Oct 11 14:53:47.911142 2015] [ssl:debug] [pid 23096:tid 27] >> ssl_engine_kernel.c(1855): [client 127.0.0.1:50990] AH02041: Protocol: >> TLSv1.2, Cipher: ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits) >> [Sun Oct 11 14:53:47.911212 2015] [ssl:trace4] [pid 23096:tid 27] >> ssl_engine_io.c(2088): [client 127.0.0.1:50990] OpenSSL: write 52/52 bytes >> to BIO#2861b8 [mem: 2bd45b] (BIO dump follows) >> >> >> Bad run (including mod_http2) >> >> - end of handshake >> >> [Sun Oct 11 14:54:38.550476 2015] [ssl:trace3] [pid 23133:tid 50] >> ssl_engine_kernel.c(1810): [client 127.0.0.1:50994] OpenSSL: Handshake: done >> [Sun Oct 11 14:54:38.550520 2015] [ssl:debug] [pid 23133:tid 50] >> ssl_engine_kernel.c(1855): [client 127.0.0.1:50994] AH02041: Protocol: >> TLSv1.2, Cipher: ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits) >> [Sun Oct 11 14:54:38.550555 2015] [core:trace6] [pid 23133:tid 50] >> core_filters.c(523): [client 127.0.0.1:50994] core_output_filter: flushing >> because of FLUSH bucket >> >> - one minute established connection, but nothing else >> >> [Sun Oct 11 14:54:39.274796 2015] [mpm_event:trace6] [pid 23133:tid 53] >> event.c(1577): connections: 1 (clogged: 0 write-completion: 0 keep-alive: 0 >> lingering: 0 suspended: 0) >> ... >> >> - timeout after one minute and write 52 bytes >> >> [Sun Oct 11 14:55:38.551174 2015] [ssl:trace4] [pid 23133:tid 50] >> ssl_engine_io.c(2099): [client 127.0.0.1:50994] OpenSSL: I/O error, 5 bytes >> expected to read on BIO#273480 [mem: 3624e3] >> [Sun Oct 11 14:55:38.551253 2015] [ssl:info] [pid 23133:tid 50] (70007)The >> timeout specified has expired: [client 127.0.0.1:50994] AH01991: SSL input >> filter read failed. >> [Sun Oct 11 14:55:38.551316 2015] [http2:debug] [pid 23133:tid 50] >> h2_h2.c(189): (70007)The timeout specified has expired: [client >> 127.0.0.1:50994] h2_h2, error reading 24 bytes speculative >> [Sun Oct 11 14:55:38.551344 2015] [http2:trace1] [pid 23133:tid 50] >> h2_h2.c(205): [client 127.0.0.1:50994] h2_h2, declined >> [Sun Oct 11 14:55:38.551433 2015] [ssl:trace4] [pid 23133:tid 50] >> ssl_engine_io.c(2088): [client 127.0.0.1:50994] OpenSSL: write 52/52 bytes >> to BIO#282488 [mem: 36a633] (BIO dump follows) >> >> Regards, >> >> Rainer
