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
