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.
-Stefan
> Am 13.10.2018 um 13:14 schrieb Rainer Jung <rainer.j...@kippdata.de>:
>
> Hi Stefan,
>
> Am 10.10.2018 um 16:04 schrieb Stefan Eissing:
>>> Am 10.10.2018 um 15:06 schrieb Joe Orton <jor...@redhat.com>:
>>>
>>> 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-...@httpd.apache.org
> * 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-...@httpd.apache.org
> * 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-...@httpd.apache.org
> * 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-...@httpd.apache.org
> * 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
