osdir.com


[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

Re: Failing http2.t in 2.4.36 [Was: NOTICE: Intent to T&R 2.4.36]


Hi Stefan,

it is the "input gone" (APR_EOF) case which went unnoticed by me. Although I patch the test suite to run with trace8 log level, http2 was set to debug in the test suite config and the "input gone" message is a trace message. See below for more details. The question is still whether this should have been handled non-fatally. Currently curl fails to do h2 with httpd 2.4.36 as set up by the test suite.

Am 13.10.2018 um 18:53 schrieb Stefan Eissing:
Hi Rainer,

according to the log, the h2 code must be in the H2_SESSION_ST_BUSY state and the only cause I see is the same as you, namely an unexpected status from h2_session_read(), which should come via

         status = ap_get_brigade(c->input_filters,
                                 session->bbtmp, AP_MODE_READBYTES,
                                 block? APR_BLOCK_READ : APR_NONBLOCK_READ,
                                 H2MAX(APR_BUCKET_BUFF_SIZE, readlen));

block is 0 here and readlen should be (unless reconfigured via H2StreamMaxMemSize) 32kb.

Maybe you could just add a log line there to see what ap_get_brigade() returned there?

Strange.

I hope most of the added http2:debug log lines with logno AH9999* are self-explaining:

...

22:25:25.934782 [core:trace8] core_filters.c(554): [client 127.0.0.1:36318] flushing now

22:25:25.934810 [core:trace8] core_filters.c(569): [client 127.0.0.1:36318] total bytes written: 3197

22:25:25.934816 [core:trace8] core_filters.c(580): [client 127.0.0.1:36318] brigade contains: bytes: 0, non-file bytes: 0, eor buckets: 0, morphing buckets: 0

22:25:25.934823 [http2:debug] h2_session.c(1552): [client 127.0.0.1:36318] AH99997: h2_session(75,BUSY,1): Into session_read non-blocking readlen 65536 read_start 103

22:25:25.934828 [http2:trace1] h2_filter.c(145): [client 127.0.0.1:36318] h2_session(75): read, NONBLOCK_READ, mode=0, readbytes=65536

22:25:25.934878 [ssl:trace4] ssl_engine_io.c(2213): [client 127.0.0.1:36318] OpenSSL: read 0/5 bytes from BIO#7ff098002b10 [mem: 7ff0980164d3] (BIO dump follows)

22:25:25.934894 [ssl:trace7] ssl_engine_io.c(2136): [client 127.0.0.1:36318] +-------------------------------------------------------------------------+

22:25:25.934898 [ssl:trace7] ssl_engine_io.c(2180): [client 127.0.0.1:36318] +-------------------------------------------------------------------------+

22:25:25.934903 [http2:trace1] h2_filter.c(190): (70014)End of file found: [client 127.0.0.1:36318] h2_session(75): read

22:25:25.934908 [http2:debug] h2_session.c(1563): (70014)End of file found: [client 127.0.0.1:36318] AH99990: h2_session(75,BUSY,1): session_read non-blocking readlen 65536 ap_get_brigade returned status 70014

22:25:25.934913 [http2:debug] h2_session.c(1603): (70014)End of file found: [client 127.0.0.1:36318] AH99998: h2_session(75,BUSY,1): input gone

22:25:25.934917 [http2:trace1] h2_session.c(1605): (70014)End of file found: [client 127.0.0.1:36318] h2_session(75,BUSY,1): input gone

22:25:25.934921 [http2:debug] h2_session.c(1616): [client 127.0.0.1:36318] AH99994: h2_session(75,BUSY,1): session_read non-blocking readlen 65536 status 70014 (default case) session->io.bytes_read == read_start (103 == 103) returning status 70014

22:25:25.934926 [http2:debug] h2_session.c(1645): (70014)End of file found: [client 127.0.0.1:36318] AH99999: h2_session(75,BUSY,1): h2_session_read non-blocking returning 70014

22:25:25.934931 [http2:debug] h2_session.c(1794): [client 127.0.0.1:36318] AH03401: h2_session(75,BUSY,1): conn error -> shutdown

22:25:25.934938 [http2:debug] h2_session.c(589): [client 127.0.0.1:36318] AH03068: h2_session(75,BUSY,1): sent FRAME[GOAWAY[error=0, reason='', last_stream=1]], frames=3/4 (r/s)


I reduced my long list of loaded modules to check, whether a filter in some module interacts badly, but the problem still happens with the following modules loaded:

mod_mpm_event.so
mod_authn_file.so
mod_authn_anon.so
mod_authn_socache.so
mod_authn_core.so
mod_authz_host.so
mod_authz_groupfile.so
mod_authz_user.so
mod_authz_owner.so
mod_authz_core.so
mod_access_compat.so
mod_auth_basic.so
mod_allowmethods.so
mod_socache_shmcb.so
mod_watchdog.so
mod_macro.so
mod_reqtimeout.so
mod_filter.so
mod_mime.so
mod_log_debug.so
mod_env.so
mod_headers.so
mod_unique_id.so
mod_setenvif.so
mod_version.so
mod_remoteip.so
mod_slotmem_shm.so
mod_slotmem_plain.so
mod_ssl.so
mod_http2.so
mod_unixd.so
mod_heartbeat.so
mod_heartmonitor.so
mod_status.so
mod_info.so
mod_cgid.so
mod_cgi.so
mod_dir.so
mod_alias.so
mod_rewrite.so

and the usual test modules:

mod_eat_post.so
mod_input_body_filter.so
mod_test_pass_brigade.so
mod_echo_post.so
mod_nntp_like.so
mod_fold.so
mod_client_add_filter.so
mod_memory_track.so
mod_test_ssl.so
mod_test_apr_uri.so
mod_list_modules.so
mod_random_chunk.so
mod_authany.so
mod_test_utilities.so
mod_echo_post_chunk.so
mod_test_rwrite.so
mod_mime.so
mod_alias.so


I don't know how to correctly distinguish a real client gone from a 0 byte non-blocking read.

Regards,

Rainer

Am 13.10.2018 um 13:14 schrieb Rainer Jung <rainer.jung@xxxxxxxxxxx>:

Hi Stefan,

Am 10.10.2018 um 16:04 schrieb Stefan Eissing:
Am 10.10.2018 um 15:06 schrieb Joe Orton <jorton@xxxxxxxxxx>:

I believe that t/modules/http2.t is dying in this:

    my $old_ref = \&{ 'AnyEvent::TLS::_get_session' };
    *{ 'AnyEvent::TLS::_get_session' } = sub($$;$$) {

piece of magic which I don't understand but possibly needs updating for
TLSv1.3? Session handling is different now... everything is broken.
I think there was no official way to add SNI to AnyEvent and I had to hack this. Unless anyone has another suggestion, I am in favour of removing the t/modules/http2.t again.

Note that if I manually send http2 requests using a recent curl, I get failures as well (for 2.4.36).

The t/modules/http2.t indeed fails for each https test, even the simple first one retrieving / and checking for status 200. One bug seems to me in the test script, that it fails silently and simply notes that not all tests have run at the end.

But if I only start the server using "t/TEST -start-httpd" and then run a curl test request against the h2 port 8557, I get failures as well. The server was build with TLS 1.3 support, but the failures occur with an 1.3 client but also with an 1.2 client (different builds of curl). I marked below lines probably indicating the failure with ^^^^^^^^ .

Here are details:

curl TLS 1.3 client output
==========================

*   Trying 127.0.0.1...
* TCP_NODELAY set
* Connected to localhost (127.0.0.1) port 8557 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
* TLSv1.3 (IN), TLS handshake, Server hello (2):
* TLSv1.3 (IN), TLS handshake, [no content] (0):
* TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
* TLSv1.3 (IN), TLS handshake, [no content] (0):
* TLSv1.3 (IN), TLS handshake, Certificate (11):
* TLSv1.3 (IN), TLS handshake, [no content] (0):
* TLSv1.3 (IN), TLS handshake, CERT verify (15):
* TLSv1.3 (IN), TLS handshake, [no content] (0):
* TLSv1.3 (IN), TLS handshake, Finished (20):
* TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
* TLSv1.3 (OUT), TLS handshake, [no content] (0):
* TLSv1.3 (OUT), TLS handshake, Finished (20):
* SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384
* ALPN, server accepted to use h2
* Server certificate:
*  subject: C=US; ST=California; L=San Francisco; O=ASF; OU=httpd-test/rsa-test; CN=localhost; emailAddress=test-dev@xxxxxxxxxxxxxxxx
*  start date: Oct 13 08:40:49 2018 GMT
*  expire date: Oct 13 08:40:49 2019 GMT
*  issuer: C=US; ST=California; L=San Francisco; O=ASF; OU=httpd-test; CN=ca; emailAddress=test-dev@xxxxxxxxxxxxxxxx
*  SSL certificate verify result: self signed certificate in certificate chain (19), continuing anyway.
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
* TLSv1.3 (OUT), TLS app data, [no content] (0):
* TLSv1.3 (OUT), TLS app data, [no content] (0):
* TLSv1.3 (OUT), TLS app data, [no content] (0):
* Using Stream ID: 1 (easy handle 0x26ab080)
* TLSv1.3 (OUT), TLS app data, [no content] (0):
GET / HTTP/2
Host: localhost:8557
User-Agent: curl/7.61.1
Accept: */*

* TLSv1.3 (IN), TLS handshake, [no content] (0):
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* TLSv1.3 (IN), TLS handshake, [no content] (0):
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* TLSv1.3 (IN), TLS app data, [no content] (0):
* Connection state changed (MAX_CONCURRENT_STREAMS == 100)!
* TLSv1.3 (OUT), TLS app data, [no content] (0):
* TLSv1.3 (IN), TLS app data, [no content] (0):
* TLSv1.3 (IN), TLS alert, [no content] (0):
* TLSv1.3 (IN), TLS alert, close notify (256):
* Empty reply from server
^^^^^^^^^^^^^^^^^^^^^^^^^
* Connection #0 to host localhost left intact
curl: (52) Empty reply from server

curl TLS 1.3 server error log
=============================

12:37:23.974210 [example_hooks:notice] x_create_connection()
12:37:23.974598 [ssl:info] AH01964: Connection to child 66 established (server localhost:8557)
12:37:23.974726 [ssl:trace2] ssl_engine_rand.c(126): Server: Seeding PRNG with 144 bytes of entropy
12:37:23.974787 [ssl:trace6] ssl_engine_io.c(2077): Enabling non-blocking writes
12:37:23.974817 [ssl:trace3] ssl_engine_kernel.c(2191): OpenSSL: Handshake: start
12:37:23.974860 [ssl:trace3] ssl_engine_kernel.c(2200): OpenSSL: Loop: before SSL initialization
12:37:23.974886 [ssl:trace4] ssl_engine_io.c(2213): OpenSSL: read 5/5 bytes from BIO#7fe690002b00 [mem: 7fe6900083c3] (BIO dump follows)
12:37:23.974917 [ssl:trace4] ssl_engine_io.c(2213): OpenSSL: read 512/512 bytes from BIO#7fe690002b00 [mem: 7fe6900083c8] (BIO dump follows)
12:37:23.975115 [ssl:trace3] ssl_engine_kernel.c(2200): OpenSSL: Loop: before SSL initialization
12:37:23.975181 [ssl:debug] ssl_engine_kernel.c(2328): AH02043: SSL virtual host for servername localhost found
12:37:23.975202 [ssl:debug] ssl_engine_kernel.c(2328): AH02043: SSL virtual host for servername localhost found
12:37:23.975208 [core:debug] protocol.c(2314): AH03155: select protocol from h2,http/1.1, choices=h2,http/1.1 for server localhost
12:37:23.975219 [core:debug] protocol.c(2359): AH03156: select protocol, proposals=h2,http/1.1 preferences=h2,http/1.1 configured=h2,http/1.1
12:37:23.975224 [core:debug] protocol.c(2377): AH03157: selected protocol=h2
12:37:23.975272 [ssl:trace3] ssl_engine_kernel.c(2200): OpenSSL: Loop: SSLv3/TLS read client hello
12:37:23.975567 [ssl:trace3] ssl_engine_kernel.c(2200): OpenSSL: Loop: SSLv3/TLS write server hello
12:37:23.975644 [ssl:trace3] ssl_engine_kernel.c(2200): OpenSSL: Loop: SSLv3/TLS write change cipher spec
12:37:23.975665 [ssl:trace3] ssl_engine_kernel.c(2200): OpenSSL: Loop: TLSv1.3 write encrypted extensions
12:37:23.977991 [ssl:trace3] ssl_engine_kernel.c(2200): OpenSSL: Loop: SSLv3/TLS write certificate
12:37:23.981471 [ssl:trace3] ssl_engine_kernel.c(2200): OpenSSL: Loop: TLSv1.3 write server certificate verify
12:37:23.981515 [core:trace8] core_filters.c(580): brigade contains: bytes: 2532, non-file bytes: 2532, eor buckets: 0, morphing buckets: 0
12:37:23.981527 [ssl:trace4] ssl_engine_io.c(2213): OpenSSL: write 2532/2532 bytes to BIO#7fe690002a40 [mem: 7fe690011670] (BIO dump follows)
12:37:23.982723 [core:trace6] core_filters.c(525): will flush because of FLUSH bucket
12:37:23.982729 [core:trace8] core_filters.c(535): seen in brigade so far: bytes: 2532, non-file bytes: 2532, eor buckets: 0, morphing buckets: 0
12:37:23.982734 [core:trace8] core_filters.c(554): flushing now
12:37:23.982776 [core:trace8] core_filters.c(569): total bytes written: 2532
12:37:23.982783 [core:trace8] core_filters.c(580): brigade contains: bytes: 0, non-file bytes: 0, eor buckets: 0, morphing buckets: 0
12:37:23.982911 [ssl:trace3] ssl_engine_kernel.c(2200): OpenSSL: Loop: SSLv3/TLS write finished
12:37:23.982924 [ssl:trace3] ssl_engine_kernel.c(2200): OpenSSL: Loop: TLSv1.3 early data
12:37:23.985161 [ssl:trace4] ssl_engine_io.c(2213): OpenSSL: read 5/5 bytes from BIO#7fe690002b00 [mem: 7fe690012683] (BIO dump follows)
12:37:23.985206 [ssl:trace4] ssl_engine_io.c(2213): OpenSSL: read 1/1 bytes from BIO#7fe690002b00 [mem: 7fe690012688] (BIO dump follows)
12:37:23.985226 [ssl:trace4] ssl_engine_io.c(2213): OpenSSL: read 5/5 bytes from BIO#7fe690002b00 [mem: 7fe690012683] (BIO dump follows)
12:37:23.985258 [ssl:trace4] ssl_engine_io.c(2213): OpenSSL: read 69/69 bytes from BIO#7fe690002b00 [mem: 7fe690012688] (BIO dump follows)
12:37:23.985318 [ssl:trace3] ssl_engine_kernel.c(2200): OpenSSL: Loop: TLSv1.3 early data
12:37:23.985395 [ssl:trace3] ssl_engine_kernel.c(2200): OpenSSL: Loop: SSLv3/TLS read finished
12:37:23.985404 [ssl:trace3] ssl_engine_kernel.c(2195): OpenSSL: Handshake: done
12:37:23.985434 [ssl:debug] ssl_engine_kernel.c(2244): AH02041: Protocol: TLSv1.3, Cipher: TLS_AES_256_GCM_SHA384 (256/256 bits)
12:37:23.985444 [ssl:trace3] ssl_engine_kernel.c(2191): OpenSSL: Handshake: start
12:37:23.985588 [core:trace8] core_filters.c(580): brigade contains: bytes: 287, non-file bytes: 287, eor buckets: 0, morphing buckets: 0
12:37:23.985602 [ssl:trace4] ssl_engine_io.c(2213): OpenSSL: write 287/287 bytes to BIO#7fe690002a40 [mem: 7fe690011670] (BIO dump follows)
12:37:23.985747 [core:trace6] core_filters.c(525): will flush because of FLUSH bucket
12:37:23.985751 [core:trace8] core_filters.c(535): seen in brigade so far: bytes: 287, non-file bytes: 287, eor buckets: 0, morphing buckets: 0
12:37:23.985756 [core:trace8] core_filters.c(554): flushing now
12:37:23.985801 [core:trace8] core_filters.c(569): total bytes written: 2819
12:37:23.985810 [core:trace8] core_filters.c(580): brigade contains: bytes: 0, non-file bytes: 0, eor buckets: 0, morphing buckets: 0
12:37:23.985817 [ssl:trace3] ssl_engine_kernel.c(2200): OpenSSL: Loop: SSLv3/TLS write session ticket
12:37:23.985823 [ssl:trace3] ssl_engine_kernel.c(2195): OpenSSL: Handshake: done
12:37:23.985832 [ssl:debug] ssl_engine_kernel.c(2244): AH02041: Protocol: TLSv1.3, Cipher: TLS_AES_256_GCM_SHA384 (256/256 bits)
12:37:23.985836 [ssl:trace3] ssl_engine_kernel.c(2191): OpenSSL: Handshake: start
12:37:23.985946 [core:trace8] core_filters.c(580): brigade contains: bytes: 303, non-file bytes: 303, eor buckets: 0, morphing buckets: 0
12:37:23.985968 [ssl:trace4] ssl_engine_io.c(2213): OpenSSL: write 303/303 bytes to BIO#7fe690002a40 [mem: 7fe690011670] (BIO dump follows)
12:37:23.986138 [core:trace6] core_filters.c(525): will flush because of FLUSH bucket
12:37:23.986150 [core:trace8] core_filters.c(535): seen in brigade so far: bytes: 303, non-file bytes: 303, eor buckets: 0, morphing buckets: 0
12:37:23.986154 [core:trace8] core_filters.c(554): flushing now
12:37:23.986172 [core:trace8] core_filters.c(569): total bytes written: 3122
12:37:23.986177 [core:trace8] core_filters.c(580): brigade contains: bytes: 0, non-file bytes: 0, eor buckets: 0, morphing buckets: 0
12:37:23.986183 [ssl:trace3] ssl_engine_kernel.c(2200): OpenSSL: Loop: SSLv3/TLS write session ticket
12:37:23.986202 [ssl:trace3] ssl_engine_kernel.c(2195): OpenSSL: Handshake: done
12:37:23.986215 [ssl:debug] ssl_engine_kernel.c(2244): AH02041: Protocol: TLSv1.3, Cipher: TLS_AES_256_GCM_SHA384 (256/256 bits)
12:37:23.986272 [http2:debug] h2_session.c(924): AH03200: h2_session(66,INIT,0): created, max_streams=100, stream_mem=32768, workers_limit=6, workers_max=37, push_diary(type=1,N=256)
12:37:23.986289 [http2:debug] h2_session.c(1017): AH03201: h2_session(66,INIT,0): start, INITIAL_WINDOW_SIZE=65535, MAX_CONCURRENT_STREAMS=100
12:37:23.986308 [http2:debug] h2_session.c(2105): AH03079: h2_session(66,INIT,0): started on localhost:8557
12:37:23.986314 [http2:debug] h2_session.c(1670): AH03078: h2_session(66,BUSY,0): transit [INIT] -- init --> [BUSY]
12:37:23.986343 [ssl:trace4] ssl_engine_io.c(2213): OpenSSL: read 5/5 bytes from BIO#7fe690002b00 [mem: 7fe690014593] (BIO dump follows)
12:37:23.986367 [ssl:trace4] ssl_engine_io.c(2213): OpenSSL: read 41/41 bytes from BIO#7fe690002b00 [mem: 7fe690014598] (BIO dump follows)
12:37:23.986441 [ssl:trace4] ssl_engine_io.c(2213): OpenSSL: read 5/5 bytes from BIO#7fe690002b00 [mem: 7fe690014593] (BIO dump follows)
12:37:23.986472 [ssl:trace4] ssl_engine_io.c(2213): OpenSSL: read 44/44 bytes from BIO#7fe690002b00 [mem: 7fe690014598] (BIO dump follows)
12:37:23.986530 [http2:debug] h2_session.c(341): AH03066: h2_session(66,BUSY,0): recv FRAME[SETTINGS[length=18, stream=0]], frames=0/0 (r/s)
12:37:23.986544 [ssl:trace4] ssl_engine_io.c(2213): OpenSSL: read 5/5 bytes from BIO#7fe690002b00 [mem: 7fe690014593] (BIO dump follows)
12:37:23.986564 [ssl:trace4] ssl_engine_io.c(2213): OpenSSL: read 30/30 bytes from BIO#7fe690002b00 [mem: 7fe690014598] (BIO dump follows)
12:37:23.986596 [http2:debug] h2_session.c(341): AH03066: h2_session(66,BUSY,0): recv FRAME[WINDOW_UPDATE[stream=0, incr=1073676289]], frames=1/0 (r/s)
12:37:23.986606 [ssl:trace4] ssl_engine_io.c(2213): OpenSSL: read 5/5 bytes from BIO#7fe690002b00 [mem: 7fe690014593] (BIO dump follows)
12:37:23.986630 [ssl:trace4] ssl_engine_io.c(2213): OpenSSL: read 56/56 bytes from BIO#7fe690002b00 [mem: 7fe690014598] (BIO dump follows)
12:37:23.986684 [http2:debug] h2_stream.c(552): AH03082: h2_stream(66-1,IDLE): created
12:37:23.986837 [http2:debug] h2_session.c(341): AH03066: h2_session(66,BUSY,1): recv FRAME[HEADERS[length=30, hend=1, stream=1, eos=1]], frames=2/0 (r/s)
12:37:23.986873 [ssl:trace4] ssl_engine_io.c(2213): OpenSSL: read 0/5 bytes from BIO#7fe690002b00 [mem: 7fe6900165a3] (BIO dump follows)
12:37:23.986926 [http2:debug] h2_session.c(589): AH03068: h2_session(66,BUSY,1): sent FRAME[SETTINGS[length=6, stream=0]], frames=3/1 (r/s)
12:37:23.986937 [http2:debug] h2_session.c(589): AH03068: h2_session(66,BUSY,1): sent FRAME[SETTINGS[ack=1, stream=0]], frames=3/2 (r/s)
12:37:23.986944 [http2:debug] h2_session.c(589): AH03068: h2_session(66,BUSY,1): sent FRAME[WINDOW_UPDATE[stream=0, incr=2147418112]], frames=3/3 (r/s)
12:37:23.986971 [core:trace8] core_filters.c(580): brigade contains: bytes: 59, non-file bytes: 59, eor buckets: 0, morphing buckets: 0
12:37:23.986980 [ssl:trace4] ssl_engine_io.c(2213): OpenSSL: write 59/59 bytes to BIO#7fe690002a40 [mem: 7fe69000c433] (BIO dump follows)
12:37:23.987029 [core:trace6] core_filters.c(525): will flush because of FLUSH bucket
12:37:23.987033 [core:trace8] core_filters.c(535): seen in brigade so far: bytes: 59, non-file bytes: 59, eor buckets: 0, morphing buckets: 0
12:37:23.987037 [core:trace8] core_filters.c(554): flushing now
12:37:23.987060 [core:trace8] core_filters.c(569): total bytes written: 3181
12:37:23.987066 [core:trace8] core_filters.c(580): brigade contains: bytes: 0, non-file bytes: 0, eor buckets: 0, morphing buckets: 0
12:37:23.987081 [ssl:trace4] ssl_engine_io.c(2213): OpenSSL: read 0/5 bytes from BIO#7fe690002b00 [mem: 7fe6900165a3] (BIO dump follows)
12:37:23.987097 [http2:debug] h2_session.c(1760): AH03401: h2_session(66,BUSY,1): conn error -> shutdown
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^

12:37:23.987105 [http2:debug] h2_session.c(589): AH03068: h2_session(66,BUSY,1): sent FRAME[GOAWAY[error=0, reason='', last_stream=1]], frames=3/4 (r/s)
12:37:23.987122 [core:trace8] core_filters.c(580): brigade contains: bytes: 39, non-file bytes: 39, eor buckets: 0, morphing buckets: 0
12:37:23.987130 [ssl:trace4] ssl_engine_io.c(2213): OpenSSL: write 39/39 bytes to BIO#7fe690002a40 [mem: 7fe69000c433] (BIO dump follows)
12:37:23.987172 [core:trace6] core_filters.c(525): will flush because of FLUSH bucket
12:37:23.987176 [core:trace8] core_filters.c(535): seen in brigade so far: bytes: 39, non-file bytes: 39, eor buckets: 0, morphing buckets: 0
12:37:23.987180 [core:trace8] core_filters.c(554): flushing now
12:37:23.987195 [core:trace8] core_filters.c(569): total bytes written: 3220
12:37:23.987200 [core:trace8] core_filters.c(580): brigade contains: bytes: 0, non-file bytes: 0, eor buckets: 0, morphing buckets: 0
12:37:23.987205 [http2:debug] h2_session.c(715): AH03069: h2_session(66,BUSY,1): sent GOAWAY, err=0, msg=
12:37:23.987212 [http2:debug] h2_session.c(1670): AH03078: h2_session(66,DONE,1): transit [BUSY] -- local goaway --> [DONE]
12:37:23.987219 [http2:debug] h2_conn.c(217): (70014)End of file found: AH03045: h2_session(66,DONE,1): process, closing conn
12:37:23.987228 [http2:debug] h2_session.c(1670): AH03078: h2_session(66,CLEANUP,1): transit [DONE] -- pre_close --> [CLEANUP]
12:37:23.992165 [optional_hook_import:error] AH01866: Optional hook test said: GET / HTTP/2.0
12:37:23.992176 [optional_fn_export:error] AH01871: Optional function test said: GET / HTTP/2.0
12:37:23.992337 [core:trace6] core_filters.c(525): will flush because of FLUSH bucket
12:37:23.992348 [core:trace8] core_filters.c(535): seen in brigade so far: bytes: 0, non-file bytes: 0, eor buckets: 0, morphing buckets: 0
12:37:23.992353 [core:trace8] core_filters.c(554): flushing now
12:37:23.992357 [core:trace8] core_filters.c(569): total bytes written: 3220
12:37:23.992361 [core:trace8] core_filters.c(580): brigade contains: bytes: 0, non-file bytes: 0, eor buckets: 0, morphing buckets: 0
12:37:23.992387 [core:trace8] core_filters.c(580): brigade contains: bytes: 24, non-file bytes: 24, eor buckets: 0, morphing buckets: 0
12:37:23.992395 [ssl:trace4] ssl_engine_io.c(2213): OpenSSL: write 24/24 bytes to BIO#7fe690002a40 [mem: 7fe69000c433] (BIO dump follows)
12:37:23.992426 [core:trace6] core_filters.c(525): will flush because of FLUSH bucket
12:37:23.992430 [core:trace8] core_filters.c(535): seen in brigade so far: bytes: 24, non-file bytes: 24, eor buckets: 0, morphing buckets: 0
12:37:23.992434 [core:trace8] core_filters.c(554): flushing now
12:37:23.992470 [core:trace8] core_filters.c(569): total bytes written: 3244
12:37:23.992479 [core:trace8] core_filters.c(580): brigade contains: bytes: 0, non-file bytes: 0, eor buckets: 0, morphing buckets: 0
12:37:23.992485 [ssl:trace3] ssl_engine_kernel.c(2210): OpenSSL: Write: SSL negotiation finished successfully
12:37:23.992491 [core:trace6] core_filters.c(525): will flush because of FLUSH bucket
12:37:23.992495 [core:trace8] core_filters.c(535): seen in brigade so far: bytes: 0, non-file bytes: 0, eor buckets: 0, morphing buckets: 0
12:37:23.992499 [core:trace8] core_filters.c(554): flushing now
12:37:23.992503 [core:trace8] core_filters.c(569): total bytes written: 3244
12:37:23.992506 [core:trace8] core_filters.c(580): brigade contains: bytes: 0, non-file bytes: 0, eor buckets: 0, morphing buckets: 0
12:37:23.992511 [ssl:debug] ssl_engine_io.c(1105): AH02001: Connection closed to child 66 with standard shutdown (server localhost:8557)
12:37:23.992616 [core:trace8] core_filters.c(580): brigade contains: bytes: 0, non-file bytes: 0, eor buckets: 0, morphing buckets: 0


curl TLS 1.2 client output
==========================

*   Trying 127.0.0.1...
* TCP_NODELAY set
* Connected to localhost (127.0.0.1) port 8557 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* TLSv1.2 (OUT), TLS handshake, Client hello (1):
* TLSv1.2 (IN), TLS handshake, Server hello (2):
* TLSv1.2 (IN), TLS handshake, Certificate (11):
* TLSv1.2 (IN), TLS handshake, Server key exchange (12):
* TLSv1.2 (IN), TLS handshake, Server finished (14):
* TLSv1.2 (OUT), TLS handshake, Client key exchange (16):
* TLSv1.2 (OUT), TLS change cipher, Change cipher spec (1):
* TLSv1.2 (OUT), TLS handshake, Finished (20):
* TLSv1.2 (IN), TLS handshake, Finished (20):
* SSL connection using TLSv1.2 / ECDHE-RSA-AES256-GCM-SHA384
* ALPN, server accepted to use h2
* Server certificate:
*  subject: C=US; ST=California; L=San Francisco; O=ASF; OU=httpd-test/rsa-test; CN=localhost; emailAddress=test-dev@xxxxxxxxxxxxxxxx
*  start date: Oct 13 08:40:49 2018 GMT
*  expire date: Oct 13 08:40:49 2019 GMT
*  issuer: C=US; ST=California; L=San Francisco; O=ASF; OU=httpd-test; CN=ca; emailAddress=test-dev@xxxxxxxxxxxxxxxx
*  SSL certificate verify result: self signed certificate in certificate chain (19), continuing anyway.
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
* Using Stream ID: 1 (easy handle 0x1d5e5e0)
GET / HTTP/2
Host: localhost:8557
User-Agent: curl/7.61.1
Accept: */*

* Connection state changed (MAX_CONCURRENT_STREAMS == 100)!
* TLSv1.2 (IN), TLS alert, close notify (256):
* Empty reply from server
^^^^^^^^^^^^^^^^^^^^^^^^^
* Connection #0 to host localhost left intact
curl: (52) Empty reply from server


curl TLS 1.2 server error log
=============================

12:43:43.580661 [ssl:info] AH01964: Connection to child 83 established (server localhost:8557)
12:43:43.580842 [ssl:trace6] ssl_engine_io.c(2077): Enabling non-blocking writes
12:43:43.580885 [ssl:trace3] ssl_engine_kernel.c(2191): OpenSSL: Handshake: start
12:43:43.580944 [ssl:trace3] ssl_engine_kernel.c(2200): OpenSSL: Loop: before SSL initialization
12:43:43.580971 [ssl:trace4] ssl_engine_io.c(2213): OpenSSL: read 5/5 bytes from BIO#7fe678002b00 [mem: 7fe6780083c3] (BIO dump follows)
12:43:43.581009 [ssl:trace4] ssl_engine_io.c(2213): OpenSSL: read 512/512 bytes from BIO#7fe678002b00 [mem: 7fe6780083c8] (BIO dump follows)
12:43:43.581181 [ssl:trace3] ssl_engine_kernel.c(2200): OpenSSL: Loop: before SSL initialization
12:43:43.581289 [ssl:debug] ssl_engine_kernel.c(2328): AH02043: SSL virtual host for servername localhost found
12:43:43.581334 [ssl:debug] ssl_engine_kernel.c(2328): AH02043: SSL virtual host for servername localhost found
12:43:43.581343 [core:debug] protocol.c(2314): AH03155: select protocol from h2,http/1.1, choices=h2,http/1.1 for server localhost
12:43:43.581352 [core:debug] protocol.c(2359): AH03156: select protocol, proposals=h2,http/1.1 preferences=h2,http/1.1 configured=h2,http/1.1
12:43:43.581366 [core:debug] protocol.c(2377): AH03157: selected protocol=h2
12:43:43.581374 [ssl:trace3] ssl_engine_kernel.c(2200): OpenSSL: Loop: SSLv3/TLS read client hello
12:43:43.581415 [ssl:trace3] ssl_engine_kernel.c(2200): OpenSSL: Loop: SSLv3/TLS write server hello
12:43:43.581877 [ssl:trace3] ssl_engine_kernel.c(2200): OpenSSL: Loop: SSLv3/TLS write certificate
12:43:43.584573 [ssl:trace3] ssl_engine_kernel.c(2200): OpenSSL: Loop: SSLv3/TLS write key exchange
12:43:43.584595 [core:trace8] core_filters.c(580): brigade contains: bytes: 2398, non-file bytes: 2398, eor buckets: 0, morphing buckets: 0
12:43:43.584605 [ssl:trace4] ssl_engine_io.c(2213): OpenSSL: write 2398/2398 bytes to BIO#7fe678002a40 [mem: 7fe678011670] (BIO dump follows)
12:43:43.585620 [core:trace6] core_filters.c(525): will flush because of FLUSH bucket
12:43:43.585624 [core:trace8] core_filters.c(535): seen in brigade so far: bytes: 2398, non-file bytes: 2398, eor buckets: 0, morphing buckets: 0
12:43:43.585634 [core:trace8] core_filters.c(554): flushing now
12:43:43.585682 [core:trace8] core_filters.c(569): total bytes written: 2398
12:43:43.585690 [core:trace8] core_filters.c(580): brigade contains: bytes: 0, non-file bytes: 0, eor buckets: 0, morphing buckets: 0
12:43:43.585696 [ssl:trace3] ssl_engine_kernel.c(2200): OpenSSL: Loop: SSLv3/TLS write server done
12:43:43.587042 [ssl:trace4] ssl_engine_io.c(2213): OpenSSL: read 5/5 bytes from BIO#7fe678002b00 [mem: 7fe6780127c3] (BIO dump follows)
12:43:43.587078 [ssl:trace4] ssl_engine_io.c(2213): OpenSSL: read 70/70 bytes from BIO#7fe678002b00 [mem: 7fe6780127c8] (BIO dump follows)
12:43:43.587126 [ssl:trace3] ssl_engine_kernel.c(2200): OpenSSL: Loop: SSLv3/TLS write server done
12:43:43.587435 [ssl:trace4] ssl_engine_io.c(2213): OpenSSL: read 5/5 bytes from BIO#7fe678002b00 [mem: 7fe678012683] (BIO dump follows)
12:43:43.587470 [ssl:trace4] ssl_engine_io.c(2213): OpenSSL: read 1/1 bytes from BIO#7fe678002b00 [mem: 7fe678012688] (BIO dump follows)
12:43:43.587489 [ssl:trace3] ssl_engine_kernel.c(2200): OpenSSL: Loop: SSLv3/TLS read client key exchange
12:43:43.587541 [ssl:trace4] ssl_engine_io.c(2213): OpenSSL: read 5/5 bytes from BIO#7fe678002b00 [mem: 7fe678012683] (BIO dump follows)
12:43:43.587561 [ssl:trace4] ssl_engine_io.c(2213): OpenSSL: read 40/40 bytes from BIO#7fe678002b00 [mem: 7fe678012688] (BIO dump follows)
12:43:43.587595 [ssl:trace3] ssl_engine_kernel.c(2200): OpenSSL: Loop: SSLv3/TLS read change cipher spec
12:43:43.587624 [ssl:trace3] ssl_engine_kernel.c(2200): OpenSSL: Loop: SSLv3/TLS read finished
12:43:43.587648 [ssl:trace3] ssl_engine_kernel.c(2200): OpenSSL: Loop: SSLv3/TLS write change cipher spec
12:43:43.587686 [core:trace8] core_filters.c(580): brigade contains: bytes: 51, non-file bytes: 51, eor buckets: 0, morphing buckets: 0
12:43:43.587694 [ssl:trace4] ssl_engine_io.c(2213): OpenSSL: write 51/51 bytes to BIO#7fe678002a40 [mem: 7fe678011670] (BIO dump follows)
12:43:43.587737 [core:trace6] core_filters.c(525): will flush because of FLUSH bucket
12:43:43.587740 [core:trace8] core_filters.c(535): seen in brigade so far: bytes: 51, non-file bytes: 51, eor buckets: 0, morphing buckets: 0
12:43:43.587744 [core:trace8] core_filters.c(554): flushing now
12:43:43.587779 [core:trace8] core_filters.c(569): total bytes written: 2449
12:43:43.587787 [core:trace8] core_filters.c(580): brigade contains: bytes: 0, non-file bytes: 0, eor buckets: 0, morphing buckets: 0
12:43:43.587792 [ssl:trace3] ssl_engine_kernel.c(2200): OpenSSL: Loop: SSLv3/TLS write finished
12:43:43.587831 [ssl:trace3] ssl_engine_kernel.c(2195): OpenSSL: Handshake: done
12:43:43.587848 [ssl:debug] ssl_engine_kernel.c(2244): AH02041: Protocol: TLSv1.2, Cipher: ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
12:43:43.587888 [http2:debug] h2_session.c(924): AH03200: h2_session(83,INIT,0): created, max_streams=100, stream_mem=32768, workers_limit=6, workers_max=37, push_diary(type=1,N=256)
12:43:43.587902 [http2:debug] h2_session.c(1017): AH03201: h2_session(83,INIT,0): start, INITIAL_WINDOW_SIZE=65535, MAX_CONCURRENT_STREAMS=100
12:43:43.587912 [http2:debug] h2_session.c(2105): AH03079: h2_session(83,INIT,0): started on localhost:8557
12:43:43.587916 [http2:debug] h2_session.c(1670): AH03078: h2_session(83,BUSY,0): transit [INIT] -- init --> [BUSY]
12:43:43.587944 [ssl:trace4] ssl_engine_io.c(2213): OpenSSL: read 0/5 bytes from BIO#7fe678002b00 [mem: 7fe678014563] (BIO dump follows)
12:43:43.587972 [http2:debug] h2_session.c(1760): AH03401: h2_session(83,BUSY,0): conn error -> shutdown
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^

12:43:43.587985 [http2:debug] h2_session.c(589): AH03068: h2_session(83,BUSY,0): sent FRAME[SETTINGS[length=6, stream=0]], frames=0/1 (r/s)
12:43:43.587992 [http2:debug] h2_session.c(589): AH03068: h2_session(83,BUSY,0): sent FRAME[WINDOW_UPDATE[stream=0, incr=2147418112]], frames=0/2 (r/s)
12:43:43.587998 [http2:debug] h2_session.c(589): AH03068: h2_session(83,BUSY,0): sent FRAME[GOAWAY[error=0, reason='', last_stream=0]], frames=0/3 (r/s)
12:43:43.588029 [core:trace8] core_filters.c(580): brigade contains: bytes: 74, non-file bytes: 74, eor buckets: 0, morphing buckets: 0
12:43:43.588044 [ssl:trace4] ssl_engine_io.c(2213): OpenSSL: write 74/74 bytes to BIO#7fe678002a40 [mem: 7fe67800c4e3] (BIO dump follows)
12:43:43.588090 [core:trace6] core_filters.c(525): will flush because of FLUSH bucket
12:43:43.588093 [core:trace8] core_filters.c(535): seen in brigade so far: bytes: 74, non-file bytes: 74, eor buckets: 0, morphing buckets: 0
12:43:43.588097 [core:trace8] core_filters.c(554): flushing now
12:43:43.588112 [core:trace8] core_filters.c(569): total bytes written: 2523
12:43:43.588117 [core:trace8] core_filters.c(580): brigade contains: bytes: 0, non-file bytes: 0, eor buckets: 0, morphing buckets: 0
12:43:43.588122 [http2:debug] h2_session.c(715): AH03069: h2_session(83,BUSY,0): sent GOAWAY, err=0, msg=
12:43:43.588128 [http2:debug] h2_session.c(1670): AH03078: h2_session(83,DONE,0): transit [BUSY] -- local goaway --> [DONE]
12:43:43.588136 [http2:debug] h2_conn.c(217): (70014)End of file found: AH03045: h2_session(83,DONE,0): process, closing conn
12:43:43.588147 [http2:debug] h2_session.c(1670): AH03078: h2_session(83,CLEANUP,0): transit [DONE] -- pre_close --> [CLEANUP]
12:43:43.588163 [core:trace6] core_filters.c(525): will flush because of FLUSH bucket
12:43:43.588168 [core:trace8] core_filters.c(535): seen in brigade so far: bytes: 0, non-file bytes: 0, eor buckets: 0, morphing buckets: 0
12:43:43.588171 [core:trace8] core_filters.c(554): flushing now
12:43:43.588174 [core:trace8] core_filters.c(569): total bytes written: 2523
12:43:43.588177 [core:trace8] core_filters.c(580): brigade contains: bytes: 0, non-file bytes: 0, eor buckets: 0, morphing buckets: 0
12:43:43.588188 [core:trace8] core_filters.c(580): brigade contains: bytes: 31, non-file bytes: 31, eor buckets: 0, morphing buckets: 0
12:43:43.588194 [ssl:trace4] ssl_engine_io.c(2213): OpenSSL: write 31/31 bytes to BIO#7fe678002a40 [mem: 7fe67800c4e3] (BIO dump follows)
12:43:43.588219 [core:trace6] core_filters.c(525): will flush because of FLUSH bucket
12:43:43.588222 [core:trace8] core_filters.c(535): seen in brigade so far: bytes: 31, non-file bytes: 31, eor buckets: 0, morphing buckets: 0
12:43:43.588226 [core:trace8] core_filters.c(554): flushing now
12:43:43.588239 [core:trace8] core_filters.c(569): total bytes written: 2554
12:43:43.588244 [core:trace8] core_filters.c(580): brigade contains: bytes: 0, non-file bytes: 0, eor buckets: 0, morphing buckets: 0
12:43:43.588249 [ssl:trace3] ssl_engine_kernel.c(2210): OpenSSL: Write: SSL negotiation finished successfully
12:43:43.588253 [core:trace6] core_filters.c(525): will flush because of FLUSH bucket
12:43:43.588257 [core:trace8] core_filters.c(535): seen in brigade so far: bytes: 0, non-file bytes: 0, eor buckets: 0, morphing buckets: 0
12:43:43.588260 [core:trace8] core_filters.c(554): flushing now
12:43:43.588263 [core:trace8] core_filters.c(569): total bytes written: 2554
12:43:43.588269 [core:trace8] core_filters.c(580): brigade contains: bytes: 0, non-file bytes: 0, eor buckets: 0, morphing buckets: 0
12:43:43.588275 [ssl:debug] ssl_engine_io.c(1105): AH02001: Connection closed to child 83 with standard shutdown (server localhost:8557)
12:43:43.588295 [core:trace8] core_filters.c(580): brigade contains: bytes: 0, non-file bytes: 0, eor buckets: 0, morphing buckets: 0

Could it be, that the ssl read directly above the conn error detected is the culprit. It reads 0 bytes. Maybe we are in h2_session.c in this block:

2215             case H2_SESSION_ST_BUSY:
2216                 if (nghttp2_session_want_read(session->ngh2)) {
2217                     ap_update_child_status(session->c->sbh, SERVER_BUSY_READ, NULL);
2218                     h2_filter_cin_timeout_set(session->cin, session->s->timeout);
2219                     status = h2_session_read(session, 0);
2220                     if (status == APR_SUCCESS) {
2221                         session->have_read = 1;
2222                     }
2223                     else if (status == APR_EAGAIN) {
2224                         /* nothing to read */
2225                     }
2226                     else if (APR_STATUS_IS_TIMEUP(status)) {
2227                         dispatch_event(session, H2_SESSION_EV_CONN_TIMEOUT, 0, NULL);
2228                         break;
2229                     }
2230                     else {
2231                         dispatch_event(session, H2_SESSION_EV_CONN_ERROR, 0, NULL);
2232                     }
2233                 }

and maybe h2_session_read() (using session_read()) returns an unexpected result code? Although I must confess, this is speculation and I don't really see, where this could happen.

Regards,

Rainer