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]


Adding another debug snippet at the end ...

Am 13.10.2018 um 13:14 schrieb Rainer Jung:
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.

... and verbose output from the nghttp client bundled with the nghttp2 library (the same one that was used to build curl, version 1.33.0):

Trying next address 127.0.0.1
[  0.001] Connected
The negotiated protocol: h2
[  0.019] send SETTINGS frame <length=12, flags=0x00, stream_id=0>
          (niv=2)
          [SETTINGS_MAX_CONCURRENT_STREAMS(0x03):100]
          [SETTINGS_INITIAL_WINDOW_SIZE(0x04):65535]
[  0.019] send PRIORITY frame <length=5, flags=0x00, stream_id=3>
          (dep_stream_id=0, weight=201, exclusive=0)
[  0.020] send PRIORITY frame <length=5, flags=0x00, stream_id=5>
          (dep_stream_id=0, weight=101, exclusive=0)
[  0.020] send PRIORITY frame <length=5, flags=0x00, stream_id=7>
          (dep_stream_id=0, weight=1, exclusive=0)
[  0.020] send PRIORITY frame <length=5, flags=0x00, stream_id=9>
          (dep_stream_id=7, weight=1, exclusive=0)
[  0.020] send PRIORITY frame <length=5, flags=0x00, stream_id=11>
          (dep_stream_id=3, weight=1, exclusive=0)
[  0.020] send HEADERS frame <length=38, flags=0x25, stream_id=13>
          ; END_STREAM | END_HEADERS | PRIORITY
          (padlen=0, dep_stream_id=11, weight=16, exclusive=0)
          ; Open new stream
          :method: GET
          :path: /
          :scheme: https
          :authority: localhost:8557
          accept: */*
          accept-encoding: gzip, deflate
          user-agent: nghttp2/1.33.0
[  0.020] recv SETTINGS frame <length=6, flags=0x00, stream_id=0>
          (niv=1)
          [SETTINGS_MAX_CONCURRENT_STREAMS(0x03):100]
[  0.020] recv WINDOW_UPDATE frame <length=4, flags=0x00, stream_id=0>
          (window_size_increment=2147418112)
[  0.020] recv GOAWAY frame <length=8, flags=0x00, stream_id=0>
          (last_stream_id=0, error_code=NO_ERROR(0x00), opaque_data(0)=[])
Some requests were not processed. total=1, processed=0

and on the server:

...
13:17:09.122788 [ssl:trace3] ssl_engine_kernel.c(2195): OpenSSL: Handshake: done 13:17:09.122797 [ssl:debug] ssl_engine_kernel.c(2244): AH02041: Protocol: TLSv1.3, Cipher: TLS_AES_256_GCM_SHA384 (256/256 bits) 13:17:09.122892 [http2:debug] h2_session.c(924): AH03200: h2_session(128,INIT,0): created, max_streams=100, stream_mem=32768, workers_limit=6, workers_max=37, push_diary(type=1,N=256) 13:17:09.122919 [http2:debug] h2_session.c(1017): AH03201: h2_session(128,INIT,0): start, INITIAL_WINDOW_SIZE=65535, MAX_CONCURRENT_STREAMS=100 13:17:09.122938 [http2:debug] h2_session.c(2105): AH03079: h2_session(128,INIT,0): started on localhost:8557 13:17:09.122945 [http2:debug] h2_session.c(1670): AH03078: h2_session(128,BUSY,0): transit [INIT] -- init --> [BUSY] 13:17:09.122987 [ssl:trace4] ssl_engine_io.c(2213): OpenSSL: read 5/5 bytes from BIO#7fe688007b20 [mem: 7fe6880200f3] (BIO dump follows) 13:17:09.123010 [ssl:trace4] ssl_engine_io.c(2213): OpenSSL: read 179/179 bytes from BIO#7fe688007b20 [mem: 7fe6880200f8] (BIO dump follows) 13:17:09.123122 [http2:debug] h2_session.c(341): AH03066: h2_session(128,BUSY,0): recv FRAME[SETTINGS[length=12, stream=0]], frames=0/0 (r/s) 13:17:09.123141 [http2:debug] h2_session.c(341): AH03066: h2_session(128,BUSY,0): recv FRAME[PRIORITY[length=5, flags=0, stream=3]], frames=1/0 (r/s) 13:17:09.123148 [http2:debug] h2_session.c(341): AH03066: h2_session(128,BUSY,0): recv FRAME[PRIORITY[length=5, flags=0, stream=5]], frames=2/0 (r/s) 13:17:09.123153 [http2:debug] h2_session.c(341): AH03066: h2_session(128,BUSY,0): recv FRAME[PRIORITY[length=5, flags=0, stream=7]], frames=3/0 (r/s) 13:17:09.123168 [http2:debug] h2_session.c(341): AH03066: h2_session(128,BUSY,0): recv FRAME[PRIORITY[length=5, flags=0, stream=9]], frames=4/0 (r/s) 13:17:09.123174 [http2:debug] h2_session.c(341): AH03066: h2_session(128,BUSY,0): recv FRAME[PRIORITY[length=5, flags=0, stream=11]], frames=5/0 (r/s) 13:17:09.123187 [http2:debug] h2_stream.c(552): AH03082: h2_stream(128-13,IDLE): created 13:17:09.123245 [http2:debug] h2_session.c(341): AH03066: h2_session(128,BUSY,1): recv FRAME[HEADERS[length=38, hend=1, stream=13, eos=1]], frames=6/0 (r/s) 13:17:09.123274 [ssl:trace4] ssl_engine_io.c(2213): OpenSSL: read 0/5 bytes from BIO#7fe688007b20 [mem: 7fe6880200f3] (BIO dump follows) 13:17:09.123405 [http2:debug] h2_session.c(589): AH03068: h2_session(128,BUSY,1): sent FRAME[SETTINGS[length=6, stream=0]], frames=7/1 (r/s) 13:17:09.123418 [http2:debug] h2_session.c(589): AH03068: h2_session(128,BUSY,1): sent FRAME[SETTINGS[ack=1, stream=0]], frames=7/2 (r/s) 13:17:09.123423 [http2:debug] h2_session.c(589): AH03068: h2_session(128,BUSY,1): sent FRAME[WINDOW_UPDATE[stream=0, incr=2147418112]], frames=7/3 (r/s) 13:17:09.123449 [core:trace8] core_filters.c(580): brigade contains: bytes: 59, non-file bytes: 59, eor buckets: 0, morphing buckets: 0 13:17:09.123462 [ssl:trace4] ssl_engine_io.c(2213): OpenSSL: write 59/59 bytes to BIO#7fe688004a50 [mem: 7fe6880114b3] (BIO dump follows) 13:17:09.123505 [core:trace6] core_filters.c(525): will flush because of FLUSH bucket 13:17:09.123508 [core:trace8] core_filters.c(535): seen in brigade so far: bytes: 59, non-file bytes: 59, eor buckets: 0, morphing buckets: 0
13:17:09.123512 [core:trace8] core_filters.c(554): flushing now
13:17:09.123532 [core:trace8] core_filters.c(569): total bytes written: 3181
13:17:09.123537 [core:trace8] core_filters.c(580): brigade contains: bytes: 0, non-file bytes: 0, eor buckets: 0, morphing buckets: 0 13:17:09.123554 [ssl:trace4] ssl_engine_io.c(2213): OpenSSL: read 0/5 bytes from BIO#7fe688007b20 [mem: 7fe6880200f3] (BIO dump follows) 13:17:09.123568 [http2:debug] h2_session.c(1760): AH03401: h2_session(128,BUSY,1): conn error -> shutdown
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^

13:17:09.123576 [http2:debug] h2_session.c(589): AH03068: h2_session(128,BUSY,1): sent FRAME[GOAWAY[error=0, reason='', last_stream=13]], frames=7/4 (r/s)
...