You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@httpd.apache.org by Rainer Jung <ra...@kippdata.de> on 2018/10/13 22:46:46 UTC
h2 broken in 2.4.36 with OpenSSL 1.1.1? Related to
SSL_MODE_AUTO_RETRY?
It seems the h2 failure only happens when building httpd against OpenSSL
1.1.1 (independent of TLS version used). I did a quick check with an
httpd build against 1.1.0i and there the same vhost of the test
framework instance worked with the same clients, that failed for 1.1.1.
The client side OpenSSL version seems not to matter.
When using 1.1.1 in the server even browsers seem to fail with h2.
Anyone who can successfully use h2 with 2.4.36 build against OpenSSL 1.1.1?
When comparing trace logs between the 1.1.1 server and the 1.1.0i
server, one can see, that a failing OpenSSL read (0 bytes) results in
APR_EOF (70014) for 1.1.1 but in errno 11 (EAGAIN) for 1.1.0i. I wonder
whether this is due to the new SSL_MODE_AUTO_RETRY and maybe the
following change:
+#if OPENSSL_VERSION_NUMBER >= 0x1010100fL
+ /* For OpenSSL >=1.1.1, disable auto-retry mode so it's possible
+ * to consume handshake records without blocking for app-data.
+ * https://github.com/openssl/openssl/issues/7178 */
+ SSL_CTX_clear_mode(ctx, SSL_MODE_AUTO_RETRY);
+#endif
The logs:
< OpenSSL 1.1.1
> OpenSSL 1.1.0i
< 23:35:16.021201 h2_session.c(1704): AH03078: h2_session(81,BUSY,0):
transit [INIT] -- init --> [BUSY]
> 23:39:55.715439 h2_session.c(1670): AH03078: h2_session(66,BUSY,0):
transit [INIT] -- init --> [BUSY]
Some additional early stuff for 1.1.0i
> 23:39:55.715448 h2_filter.c(145): h2_session(66): read,
NONBLOCK_READ, mode=0, readbytes=65536
> 23:39:55.715470 ssl_engine_io.c(2222): OpenSSL: I/O error, 5 bytes
expected to read on BIO#7efee0005280 [mem: 7efee0014ee3]
> 23:39:55.715480 h2_filter.c(190): (11)Resource temporarily
unavailable: h2_session(66): read
> 23:39:55.715508 h2_mplx.c(1240): h2_mplx(66): dispatch events
> 23:39:55.715536 h2_session.c(589): AH03068: h2_session(66,BUSY,0):
sent FRAME[SETTINGS[length=6, stream=0]], frames=0/1 (r/s)
> 23:39:55.715548 h2_session.c(589): AH03068: h2_session(66,BUSY,0):
sent FRAME[WINDOW_UPDATE[stream=0, incr=2147418112]], frames=0/2 (r/s)
> 23:39:55.715565 h2_conn_io.c(122): h2_session(66)-out: heap[28] flush
> 23:39:55.715590 core_filters.c(580): brigade contains: bytes: 57,
non-file bytes: 57, eor buckets: 0, morphing buckets: 0
> 23:39:55.715598 ssl_engine_io.c(2213): OpenSSL: write 57/57 bytes to
BIO#7efee00021b0 [mem: 7efee0014ee3]
> 23:39:55.715648 core_filters.c(525): will flush because of FLUSH bucket
> 23:39:55.715653 core_filters.c(535): seen in brigade so far: bytes:
57, non-file bytes: 57, eor buckets: 0, morphing buckets: 0
> 23:39:55.715657 core_filters.c(554): flushing now
> 23:39:55.715683 core_filters.c(569): total bytes written: 2466
> 23:39:55.715690 core_filters.c(580): brigade contains: bytes: 0,
non-file bytes: 0, eor buckets: 0, morphing buckets: 0
Then many things identical
< 23:35:16.021217 h2_filter.c(145): h2_session(81): read, NONBLOCK_READ,
mode=0, readbytes=65536
> 23:39:55.715697 h2_filter.c(145): h2_session(66): read,
NONBLOCK_READ, mode=0, readbytes=65536
< 23:35:16.021252 ssl_engine_io.c(2213): OpenSSL: read 5/5 bytes from
BIO#7f1d04002b10 [mem: 7f1d040145a3]
< 23:35:16.021277 ssl_engine_io.c(2213): OpenSSL: read 41/41 bytes from
BIO#7f1d04002b10 [mem: 7f1d040145a8]
< 23:35:16.021318 h2_filter.c(93): bb_dump(81): RAW_in(TRANSIENT[24])
< 23:35:16.021340 h2_filter.c(64): h2_session(81,BUSY,0): fed 24 bytes
to nghttp2, 24 read
> 23:39:55.715713 ssl_engine_io.c(2213): OpenSSL: read 5/5 bytes from
BIO#7efee0005280 [mem: 7efee0014ee3]
> 23:39:55.715734 ssl_engine_io.c(2213): OpenSSL: read 48/48 bytes from
BIO#7efee0005280 [mem: 7efee0014ee8]
> 23:39:55.715774 h2_filter.c(93): bb_dump(66): RAW_in(TRANSIENT[24])
> 23:39:55.715786 h2_filter.c(64): h2_session(66,BUSY,0): fed 24 bytes
to nghttp2, 24 read
< 23:35:16.021355 h2_filter.c(145): h2_session(81): read, NONBLOCK_READ,
mode=0, readbytes=65536
< 23:35:16.021364 ssl_engine_io.c(2213): OpenSSL: read 5/5 bytes from
BIO#7f1d04002b10 [mem: 7f1d040145a3]
< 23:35:16.021384 ssl_engine_io.c(2213): OpenSSL: read 44/44 bytes from
BIO#7f1d04002b10 [mem: 7f1d040145a8]
< 23:35:16.021428 h2_filter.c(93): bb_dump(81): RAW_in(TRANSIENT[27])
< 23:35:16.021442 h2_session.c(341): AH03066: h2_session(81,BUSY,0):
recv FRAME[SETTINGS[length=18, stream=0]], frames=0/0 (r/s)
< 23:35:16.021447 h2_session.c(414): h2_session(81,BUSY,0): SETTINGS, len=18
> 23:39:55.715792 h2_filter.c(145): h2_session(66): read,
NONBLOCK_READ, mode=0, readbytes=65536
> 23:39:55.715804 ssl_engine_io.c(2213): OpenSSL: read 5/5 bytes from
BIO#7efee0005280 [mem: 7efee0014ee3]
> 23:39:55.715825 ssl_engine_io.c(2213): OpenSSL: read 51/51 bytes from
BIO#7efee0005280 [mem: 7efee0014ee8]
> 23:39:55.715897 h2_filter.c(93): bb_dump(66): RAW_in(TRANSIENT[27])
> 23:39:55.715926 h2_session.c(341): AH03066: h2_session(66,BUSY,0):
recv FRAME[SETTINGS[length=18, stream=0]], frames=0/2 (r/s)
> 23:39:55.715934 h2_session.c(414): h2_session(66,BUSY,0): SETTINGS,
len=18
< 23:35:16.021451 h2_filter.c(64): h2_session(81,BUSY,0): fed 27 bytes
to nghttp2, 27 read
< 23:35:16.021464 h2_filter.c(145): h2_session(81): read, NONBLOCK_READ,
mode=0, readbytes=65536
< 23:35:16.021471 ssl_engine_io.c(2213): OpenSSL: read 5/5 bytes from
BIO#7f1d04002b10 [mem: 7f1d040145a3]
< 23:35:16.021491 ssl_engine_io.c(2213): OpenSSL: read 30/30 bytes from
BIO#7f1d04002b10 [mem: 7f1d040145a8]
< 23:35:16.021535 h2_filter.c(93): bb_dump(81): RAW_in(TRANSIENT[13])
< 23:35:16.021542 h2_session.c(341): AH03066: h2_session(81,BUSY,0):
recv FRAME[WINDOW_UPDATE[stream=0, incr=1073676289]], frames=1/0 (r/s)
> 23:39:55.715939 h2_filter.c(64): h2_session(66,BUSY,0): fed 27 bytes
to nghttp2, 27 read
> 23:39:55.715943 h2_filter.c(145): h2_session(66): read,
NONBLOCK_READ, mode=0, readbytes=65536
> 23:39:55.715953 ssl_engine_io.c(2213): OpenSSL: read 5/5 bytes from
BIO#7efee0005280 [mem: 7efee0014ee3]
> 23:39:55.715973 ssl_engine_io.c(2213): OpenSSL: read 37/37 bytes from
BIO#7efee0005280 [mem: 7efee0014ee8]
> 23:39:55.716015 h2_filter.c(93): bb_dump(66): RAW_in(TRANSIENT[13])
> 23:39:55.716024 h2_session.c(341): AH03066: h2_session(66,BUSY,0):
recv FRAME[WINDOW_UPDATE[stream=0, incr=1073676289]], frames=1/2 (r/s)
< 23:35:16.021547 h2_session.c(381): h2_stream(81-0): WINDOW_UPDATE
incr=1073676289
< 23:35:16.021552 h2_filter.c(64): h2_session(81,BUSY,0): fed 13 bytes
to nghttp2, 13 read
< 23:35:16.021563 h2_filter.c(145): h2_session(81): read, NONBLOCK_READ,
mode=0, readbytes=65536
< 23:35:16.021571 ssl_engine_io.c(2213): OpenSSL: read 5/5 bytes from
BIO#7f1d04002b10 [mem: 7f1d040145a3]
< 23:35:16.021591 ssl_engine_io.c(2213): OpenSSL: read 56/56 bytes from
BIO#7f1d04002b10 [mem: 7f1d040145a8]
< 23:35:16.021632 h2_filter.c(93): bb_dump(81): RAW_in(TRANSIENT[39])
> 23:39:55.716029 h2_session.c(381): h2_stream(66-0): WINDOW_UPDATE
incr=1073676289
> 23:39:55.716034 h2_filter.c(64): h2_session(66,BUSY,0): fed 13 bytes
to nghttp2, 13 read
> 23:39:55.716039 h2_filter.c(145): h2_session(66): read,
NONBLOCK_READ, mode=0, readbytes=65536
> 23:39:55.716045 ssl_engine_io.c(2213): OpenSSL: read 5/5 bytes from
BIO#7efee0005280 [mem: 7efee0014ee3]
> 23:39:55.716065 ssl_engine_io.c(2213): OpenSSL: read 63/63 bytes from
BIO#7efee0005280 [mem: 7efee0014ee8]
> 23:39:55.716114 h2_filter.c(93): bb_dump(66): RAW_in(TRANSIENT[39])
< 23:35:16.021652 h2_stream.c(552): AH03082: h2_stream(81-1,IDLE): created
< 23:35:16.021665 h2_session.c(1960): h2_stream(81-1,IDLE): entered state
< 23:35:16.021699 h2_session.c(341): AH03066: h2_session(81,BUSY,1):
recv FRAME[HEADERS[length=30, hend=1, stream=1, eos=1]], frames=2/0 (r/s)
< 23:35:16.021709 h2_stream.c(302): h2_stream(81-1,IDLE): transit to [OPEN]
> 23:39:55.716138 h2_stream.c(552): AH03082: h2_stream(66-1,IDLE): created
> 23:39:55.716146 h2_session.c(1926): h2_stream(66-1,IDLE): entered state
> 23:39:55.716185 h2_session.c(341): AH03066: h2_session(66,BUSY,1):
recv FRAME[HEADERS[length=30, hend=1, stream=1, eos=1]], frames=2/2 (r/s)
> 23:39:55.716197 h2_stream.c(302): h2_stream(66-1,IDLE): transit to [OPEN]
< 23:35:16.021714 h2_session.c(1960): h2_stream(81-1,OPEN): entered state
< 23:35:16.021732 h2_stream.c(302): h2_stream(81-1,OPEN): transit to
[HALF_CLOSED_REMOTE]
< 23:35:16.021736 h2_stream.c(211): h2_stream(81-1,HALF_CLOSED_REMOTE):
closing input
< 23:35:16.021740 h2_session.c(1960):
h2_stream(81-1,HALF_CLOSED_REMOTE): entered state
> 23:39:55.716201 h2_session.c(1926): h2_stream(66-1,OPEN): entered state
> 23:39:55.716206 h2_stream.c(302): h2_stream(66-1,OPEN): transit to
[HALF_CLOSED_REMOTE]
> 23:39:55.716210 h2_stream.c(211): h2_stream(66-1,HALF_CLOSED_REMOTE):
closing input
> 23:39:55.716214 h2_session.c(1926):
h2_stream(66-1,HALF_CLOSED_REMOTE): entered state
< 23:35:16.021744 h2_filter.c(64): h2_session(81,BUSY,1): fed 39 bytes
to nghttp2, 39 read
< 23:35:16.021757 h2_filter.c(145): h2_session(81): read, NONBLOCK_READ,
mode=0, readbytes=65536
> 23:39:55.716219 h2_filter.c(64): h2_session(66,BUSY,1): fed 39 bytes
to nghttp2, 39 read
> 23:39:55.716224 h2_filter.c(145): h2_session(66): read,
NONBLOCK_READ, mode=0, readbytes=65536
Again some additional stuff for 1.1.0i
> 23:39:55.716254 ssl_engine_io.c(2213): OpenSSL: read 5/5 bytes from
BIO#7efee0005280 [mem: 7efee0014ee3]
> 23:39:55.716277 ssl_engine_io.c(2213): OpenSSL: read 33/33 bytes from
BIO#7efee0005280 [mem: 7efee0014ee8]
> 23:39:55.716320 h2_filter.c(93): bb_dump(66): RAW_in(TRANSIENT[9])
> 23:39:55.716328 h2_session.c(341): AH03066: h2_session(66,BUSY,1):
recv FRAME[SETTINGS[ack=1, stream=0]], frames=3/2 (r/s)
> 23:39:55.716333 h2_session.c(414): h2_session(66,BUSY,1): SETTINGS, len=0
> 23:39:55.716337 h2_filter.c(64): h2_session(66,BUSY,1): fed 9 bytes
to nghttp2, 9 read
> 23:39:55.716341 h2_filter.c(145): h2_session(66): read,
NONBLOCK_READ, mode=0, readbytes=65536
And now differences, 1.1.1 gets 0 bytes but 70014 (APR_EOF), 1.1.0i 0
bytes but 11 (EAGAIN?)
< 23:35:16.021774 ssl_engine_io.c(2213): OpenSSL: read 0/5 bytes from
BIO#7f1d04002b10 [mem: 7f1d040165b3]
< 23:35:16.021790 h2_filter.c(190): (70014)End of file found:
h2_session(81): read
< 23:35:16.021809 h2_stream.c(594): h2_stream(81-1,HALF_CLOSED_REMOTE):
schedule GET https://localhost:8557/ chunked=0
< 23:35:16.021841 h2_mplx.c(703): h2_stream(81-1,HALF_CLOSED_REMOTE):
process, added to q
< 23:35:16.021872 h2_mplx.c(1240): h2_mplx(81): dispatch events
> 23:39:55.716352 ssl_engine_io.c(2222): OpenSSL: I/O error, 5 bytes
expected to read on BIO#7efee0005280 [mem: 7efee0014ee3]
> 23:39:55.716359 h2_filter.c(190): (11)Resource temporarily
unavailable: h2_session(66): read
> 23:39:55.716368 h2_stream.c(594): h2_stream(66-1,HALF_CLOSED_REMOTE):
schedule GET https://localhost:8557/ chunked=0
> 23:39:55.716400 h2_mplx.c(703): h2_stream(66-1,HALF_CLOSED_REMOTE):
process, added to q
> 23:39:55.716408 h2_mplx.c(1240): h2_mplx(66): dispatch events
< 23:35:16.021879 SLAVE h2_conn.c(271): h2_stream(81-1): create slave
< 23:35:16.021895 h2_session.c(589): AH03068: h2_session(81,BUSY,1):
sent FRAME[SETTINGS[length=6, stream=0]], frames=3/1 (r/s)
< 23:35:16.021905 h2_session.c(589): AH03068: h2_session(81,BUSY,1):
sent FRAME[SETTINGS[ack=1, stream=0]], frames=3/2 (r/s)
< 23:35:16.021911 h2_session.c(589): AH03068: h2_session(81,BUSY,1):
sent FRAME[WINDOW_UPDATE[stream=0, incr=2147418112]], frames=3/3 (r/s)
> 23:39:55.716416 h2_session.c(589): AH03068: h2_session(66,BUSY,1):
sent FRAME[SETTINGS[ack=1, stream=0]], frames=4/3 (r/s)
< 23:35:16.022541 h2_conn_io.c(122): h2_session(81)-out: heap[37] flush
< 23:35:16.022573 core_filters.c(580): brigade contains: bytes: 59,
non-file bytes: 59, eor buckets: 0, morphing buckets: 0
< 23:35:16.022591 ssl_engine_io.c(2213): OpenSSL: write 59/59 bytes to
BIO#7f1d04002a50 [mem: 7f1d0400c443]
< 23:35:16.022613 SLAVE h2_conn.c(336): h2_stream(81-1): created slave
< 23:35:16.022635 core_filters.c(525): will flush because of FLUSH bucket
> 23:39:55.716425 h2_conn_io.c(122): h2_session(66)-out: heap[9] flush
> 23:39:55.716437 core_filters.c(580): brigade contains: bytes: 38,
non-file bytes: 38, eor buckets: 0, morphing buckets: 0
> 23:39:55.716444 ssl_engine_io.c(2213): OpenSSL: write 38/38 bytes to
BIO#7efee00021b0 [mem: 7efee0014ee3]
> 23:39:55.716443 SLAVE h2_conn.c(271): h2_stream(66-1): create slave
> 23:39:55.716481 core_filters.c(525): will flush because of FLUSH bucket
< 23:35:16.022636 SLAVE h2_task.c(507): h2_h2, pre_connection, found
stream task
< 23:35:16.022639 core_filters.c(535): seen in brigade so far: bytes:
59, non-file bytes: 59, eor buckets: 0, morphing buckets: 0
> 23:39:55.716485 core_filters.c(535): seen in brigade so far: bytes:
38, non-file bytes: 38, eor buckets: 0, morphing buckets: 0
> 23:39:55.716490 SLAVE h2_conn.c(336): h2_stream(66-1): created slave
< 23:35:16.022643 core_filters.c(554): flushing now
> 23:39:55.716497 core_filters.c(554): flushing now
< 23:35:16.022656 SLAVE h2_task.c(632): h2_task(81-1): process connection
< 23:35:16.022662 SLAVE h2_task.c(731): h2_h2, processing request directly
> 23:39:55.716512 SLAVE h2_task.c(507): h2_h2, pre_connection, found
stream task
< 23:35:16.022664 core_filters.c(569): total bytes written: 3181
> 23:39:55.716525 core_filters.c(569): total bytes written: 2504
< 23:35:16.022666 SLAVE h2_task.c(658): h2_task(81-1): create request_rec
< 23:35:16.022670 core_filters.c(580): brigade contains: bytes: 0,
non-file bytes: 0, eor buckets: 0, morphing buckets: 0
> 23:39:55.716532 core_filters.c(580): brigade contains: bytes: 0,
non-file bytes: 0, eor buckets: 0, morphing buckets: 0
> 23:39:55.716537 SLAVE h2_task.c(632): h2_task(66-1): process connection
< 23:35:16.022689 h2_filter.c(145): h2_session(81): read, NONBLOCK_READ,
mode=0, readbytes=65536
> 23:39:55.716539 h2_filter.c(145): h2_session(66): read,
NONBLOCK_READ, mode=0, readbytes=65536
> 23:39:55.716543 SLAVE h2_task.c(731): h2_h2, processing request directly
> 23:39:55.716548 SLAVE h2_task.c(658): h2_task(66-1): create request_rec
Again 70014 versus 11 when no bytes could be read:
< 23:35:16.022702 ssl_engine_io.c(2213): OpenSSL: read 0/5 bytes from
BIO#7f1d04002b10 [mem: 7f1d040165b3]
< 23:35:16.022718 h2_filter.c(190): (70014)End of file found:
h2_session(81): read
> 23:39:55.716551 ssl_engine_io.c(2222): OpenSSL: I/O error, 5 bytes
expected to read on BIO#7efee0005280 [mem: 7efee0014ee3]
> 23:39:55.716559 h2_filter.c(190): (11)Resource temporarily
unavailable: h2_session(66): read
< 23:35:16.022692 [example_hooks:notice] SLAVE x_create_request()
> 23:39:55.716571 [example_hooks:notice] SLAVE x_create_request()
And here resulting in GOAWAY versus WAIT:
< 23:35:16.022730 h2_session.c(1605): (70014)End of file found:
h2_session(81,BUSY,1): input gone
< 23:35:16.022745 h2_session.c(1794): AH03401: h2_session(81,BUSY,1):
conn error -> shutdown
< 23:35:16.022753 h2_session.c(589): AH03068: h2_session(81,BUSY,1):
sent FRAME[GOAWAY[error=0, reason='', last_stream=1]], frames=3/4 (r/s)
< 23:35:16.022762 h2_conn_io.c(122): h2_session(81)-out: heap[17] flush
< 23:35:16.022775 core_filters.c(580): brigade contains: bytes: 39,
non-file bytes: 39, eor buckets: 0, morphing buckets: 0
< 23:35:16.022783 ssl_engine_io.c(2213): OpenSSL: write 39/39 bytes to
BIO#7f1d04002a50 [mem: 7f1d0400c443]
> 23:39:55.716567 h2_mplx.c(1240): h2_mplx(66): dispatch events
> 23:39:55.716572 h2_session.c(1796): h2_session(66,BUSY,1): NO_IO
event, 1 streams open
> 23:39:55.716579 h2_session.c(1670): AH03078: h2_session(66,WAIT,1):
transit [BUSY] -- no io --> [WAIT]
> 23:39:55.716584 h2_session.c(2283): h2_session: wait for data, 10 micros
SLAVES looking OK
< 23:35:16.022736 SLAVE h2_h2.c(722): h2_task(81-1): adding request filters
> 23:39:55.716598 SLAVE h2_h2.c(722): h2_task(66-1): adding request filters
< 23:35:16.022782 SLAVE ssl_engine_kernel.c(383): AH02034: Subsequent
(No.2) HTTPS request received for child 347892350977 (server localhost:8557)
< 23:35:16.022799 SLAVE h2_task.c(676): h2_task(81-1): start process_request
< 23:35:16.022811 [http:trace4] SLAVE http_request.c(437): Headers
received from client:
< 23:35:16.022817 [http:trace4] SLAVE http_request.c(441): User-Agent:
curl/7.61.1
< 23:35:16.022822 [http:trace4] SLAVE http_request.c(441): Accept: */*
> 23:39:55.716635 SLAVE ssl_engine_kernel.c(383): AH02034: Subsequent
(No.2) HTTPS request received for child 283467841537 (server localhost:8557)
> 23:39:55.716646 SLAVE h2_task.c(676): h2_task(66-1): start
process_request
> 23:39:55.716652 [http:trace4] SLAVE http_request.c(437): Headers
received from client:
> 23:39:55.716658 [http:trace4] SLAVE http_request.c(441):
User-Agent: curl/7.61.1
> 23:39:55.716661 [http:trace4] SLAVE http_request.c(441): Accept: */*
> 23:39:55.716665 [http:trace4] SLAVE http_request.c(441): Host:
localhost:8557
But then failure (empty result) for 1.1.1 due to GOAWAY
< 23:35:16.022824 core_filters.c(525): will flush because of FLUSH bucket
< 23:35:16.022825 [http:trace4] SLAVE http_request.c(441): Host:
localhost:8557
< 23:35:16.022828 core_filters.c(535): seen in brigade so far: bytes:
39, non-file bytes: 39, eor buckets: 0, morphing buckets: 0
< 23:35:16.022833 core_filters.c(554): flushing now
< 23:35:16.022874 core_filters.c(569): total bytes written: 3220
< 23:35:16.022882 core_filters.c(580): brigade contains: bytes: 0,
non-file bytes: 0, eor buckets: 0, morphing buckets: 0
< 23:35:16.022887 h2_session.c(715): AH03069: h2_session(81,BUSY,1):
sent GOAWAY, err=0, msg=
< 23:35:16.022895 h2_session.c(1704): AH03078: h2_session(81,DONE,1):
transit [BUSY] -- local goaway --> [DONE]
< 23:35:16.022900 h2_mplx.c(1240): h2_mplx(81): dispatch events
< 23:35:16.022905 h2_session.c(2364): h2_session(81,DONE,1): process returns
< 23:35:16.022909 h2_conn.c(217): (70014)End of file found: AH03045:
h2_session(81,DONE,1): process, closing conn
< 23:35:16.022916 h2_session.c(2382): h2_session(81,DONE,1): pre_close
< 23:35:16.022920 h2_session.c(725): h2_session(81,DONE,1): pool_cleanup
< 23:35:16.022924 h2_session.c(1704): AH03078:
h2_session(81,CLEANUP,1): transit [DONE] -- pre_close --> [CLEANUP]
< 23:35:16.022929 h2_stream.c(612): h2_stream(81-1,HALF_CLOSED_REMOTE):
reset, error=0
< 23:35:16.022941 h2_stream.c(344): h2_stream(81-1,HALF_CLOSED_REMOTE):
dispatch event 2
< 23:35:16.022945 h2_stream.c(302): h2_stream(81-1,HALF_CLOSED_REMOTE):
transit to [CLOSED]
< 23:35:16.022949 h2_stream.c(211): h2_stream(81-1,CLOSED): closing input
< 23:35:16.022953 h2_stream.c(344): h2_stream(81-1,CLOSED): dispatch event 3
< 23:35:16.022957 h2_stream.c(302): h2_stream(81-1,CLOSED): transit to
[CLEANUP]
< 23:35:16.022963 h2_ngn_shed.c(144): AH03394: h2_ngn_shed(81): abort
Whereas 1.1.0i proceeds processing and sends the result back
...
Regards,
Rainer
Am 13.10.2018 um 23:07 schrieb Rainer Jung:
> Hi Stefan,
>
> it is the "input gone" (APR_EOF) case which went unnoticed by me.
> Although I patch the test suite to run with trace8 log level, http2 was
> set to debug in the test suite config and the "input gone" message is a
> trace message. See below for more details. The question is still whether
> this should have been handled non-fatally. Currently curl fails to do h2
> with httpd 2.4.36 as set up by the test suite.
>
> Am 13.10.2018 um 18:53 schrieb Stefan Eissing:
>> Hi Rainer,
>>
>> according to the log, the h2 code must be in the H2_SESSION_ST_BUSY
>> state and the only cause I see is the same as you, namely an
>> unexpected status from h2_session_read(), which should come via
>>
>> status = ap_get_brigade(c->input_filters,
>> session->bbtmp, AP_MODE_READBYTES,
>> block? APR_BLOCK_READ :
>> APR_NONBLOCK_READ,
>> H2MAX(APR_BUCKET_BUFF_SIZE, readlen));
>>
>> block is 0 here and readlen should be (unless reconfigured via
>> H2StreamMaxMemSize) 32kb.
>>
>> Maybe you could just add a log line there to see what ap_get_brigade()
>> returned there?
>>
>> Strange.
>
> I hope most of the added http2:debug log lines with logno AH9999* are
> self-explaining:
>
> ...
>
> 22:25:25.934782 [core:trace8] core_filters.c(554): [client
> 127.0.0.1:36318] flushing now
>
> 22:25:25.934810 [core:trace8] core_filters.c(569): [client
> 127.0.0.1:36318] total bytes written: 3197
>
> 22:25:25.934816 [core:trace8] core_filters.c(580): [client
> 127.0.0.1:36318] brigade contains: bytes: 0, non-file bytes: 0, eor
> buckets: 0, morphing buckets: 0
>
> 22:25:25.934823 [http2:debug] h2_session.c(1552): [client
> 127.0.0.1:36318] AH99997: h2_session(75,BUSY,1): Into session_read
> non-blocking readlen 65536 read_start 103
>
> 22:25:25.934828 [http2:trace1] h2_filter.c(145): [client
> 127.0.0.1:36318] h2_session(75): read, NONBLOCK_READ, mode=0,
> readbytes=65536
>
> 22:25:25.934878 [ssl:trace4] ssl_engine_io.c(2213): [client
> 127.0.0.1:36318] OpenSSL: read 0/5 bytes from BIO#7ff098002b10 [mem:
> 7ff0980164d3] (BIO dump follows)
>
> 22:25:25.934894 [ssl:trace7] ssl_engine_io.c(2136): [client
> 127.0.0.1:36318]
> +-------------------------------------------------------------------------+
>
> 22:25:25.934898 [ssl:trace7] ssl_engine_io.c(2180): [client
> 127.0.0.1:36318]
> +-------------------------------------------------------------------------+
>
> 22:25:25.934903 [http2:trace1] h2_filter.c(190): (70014)End of file
> found: [client 127.0.0.1:36318] h2_session(75): read
>
> 22:25:25.934908 [http2:debug] h2_session.c(1563): (70014)End of file
> found: [client 127.0.0.1:36318] AH99990: h2_session(75,BUSY,1):
> session_read non-blocking readlen 65536 ap_get_brigade returned status
> 70014
>
> 22:25:25.934913 [http2:debug] h2_session.c(1603): (70014)End of file
> found: [client 127.0.0.1:36318] AH99998: h2_session(75,BUSY,1): input gone
>
> 22:25:25.934917 [http2:trace1] h2_session.c(1605): (70014)End of file
> found: [client 127.0.0.1:36318] h2_session(75,BUSY,1): input gone
>
> 22:25:25.934921 [http2:debug] h2_session.c(1616): [client
> 127.0.0.1:36318] AH99994: h2_session(75,BUSY,1): session_read
> non-blocking readlen 65536 status 70014 (default case)
> session->io.bytes_read == read_start (103 == 103) returning status 70014
>
> 22:25:25.934926 [http2:debug] h2_session.c(1645): (70014)End of file
> found: [client 127.0.0.1:36318] AH99999: h2_session(75,BUSY,1):
> h2_session_read non-blocking returning 70014
>
> 22:25:25.934931 [http2:debug] h2_session.c(1794): [client
> 127.0.0.1:36318] AH03401: h2_session(75,BUSY,1): conn error -> shutdown
>
> 22:25:25.934938 [http2:debug] h2_session.c(589): [client
> 127.0.0.1:36318] AH03068: h2_session(75,BUSY,1): sent
> FRAME[GOAWAY[error=0, reason='', last_stream=1]], frames=3/4 (r/s)
>
>
> I reduced my long list of loaded modules to check, whether a filter in
> some module interacts badly, but the problem still happens with the
> following modules loaded:
>
> mod_mpm_event.so
> mod_authn_file.so
> mod_authn_anon.so
> mod_authn_socache.so
> mod_authn_core.so
> mod_authz_host.so
> mod_authz_groupfile.so
> mod_authz_user.so
> mod_authz_owner.so
> mod_authz_core.so
> mod_access_compat.so
> mod_auth_basic.so
> mod_allowmethods.so
> mod_socache_shmcb.so
> mod_watchdog.so
> mod_macro.so
> mod_reqtimeout.so
> mod_filter.so
> mod_mime.so
> mod_log_debug.so
> mod_env.so
> mod_headers.so
> mod_unique_id.so
> mod_setenvif.so
> mod_version.so
> mod_remoteip.so
> mod_slotmem_shm.so
> mod_slotmem_plain.so
> mod_ssl.so
> mod_http2.so
> mod_unixd.so
> mod_heartbeat.so
> mod_heartmonitor.so
> mod_status.so
> mod_info.so
> mod_cgid.so
> mod_cgi.so
> mod_dir.so
> mod_alias.so
> mod_rewrite.so
>
> and the usual test modules:
>
> mod_eat_post.so
> mod_input_body_filter.so
> mod_test_pass_brigade.so
> mod_echo_post.so
> mod_nntp_like.so
> mod_fold.so
> mod_client_add_filter.so
> mod_memory_track.so
> mod_test_ssl.so
> mod_test_apr_uri.so
> mod_list_modules.so
> mod_random_chunk.so
> mod_authany.so
> mod_test_utilities.so
> mod_echo_post_chunk.so
> mod_test_rwrite.so
> mod_mime.so
> mod_alias.so
>
>
> I don't know how to correctly distinguish a real client gone from a 0
> byte non-blocking read.
>
> Regards,
>
> Rainer
>
>>> Am 13.10.2018 um 13:14 schrieb Rainer Jung <ra...@kippdata.de>:
>>>
>>> Hi Stefan,
>>>
>>> Am 10.10.2018 um 16:04 schrieb Stefan Eissing:
>>>>> Am 10.10.2018 um 15:06 schrieb Joe Orton <jo...@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-dev@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-dev@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-dev@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-dev@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
Re: h2 broken in 2.4.36 with OpenSSL 1.1.1? Related to
SSL_MODE_AUTO_RETRY?
Posted by Rainer Jung <ra...@kippdata.de>.
Hi Stefan, Joe and all,
Am 16.10.2018 um 11:15 schrieb Joe Orton:
> On Mon, Oct 15, 2018 at 12:55:45PM +0200, Rainer Jung wrote:
>> I'm currently testing the following patch which looks OK wrt. test suite
>> results. Need to run more combinations (OpenSSL version client versus
>> server) though. Server with 1.1.1 and with 1.0.2p both look OK (including
>> the h2 tests). Maybe some cases could be folded together or be dropped, but
>> I tried to make the logic changes not to big. The SSL_ERROR_ZERO_RETURN part
>> is new, because without that we get an ssl:info log line AH01992 with error
>> 6 (SSL_ERROR_ZERO_RETURN) at the end of the response (at least with 1.1.1).
>
> Thanks a lot Rainer & Stefan, sorry I didn't follow through on that
> ticket/issue far enough. Strike it down as another way that 1.1.1
> really is ABI-incompatible with <1.1.1 :(
>
> The change committed to ssl_engine_io.c makes sense to me. I wonder if
> mod_ssl should also handle SSL_ERROR_WANT_WRITE here as well. It will be
> clearly logged if that happens ("SSL library error 3 reading data") so
> we should find out anyway.
Thanks to you both for double checking.
I tried to keep behavior change restricted to the observed problem but
yes, it might be, that a more complete approach would cover more cases,
that we are just not aware right now. It is just that I don't feel
myself in a position for that more complete approach.
I will propose the current trunk change for 2.4 but any suggestions for
improvements would be highly welcome. My testing currently at least
shows no problems with the httpd test suite.
Regards,
Rainer
Re: h2 broken in 2.4.36 with OpenSSL 1.1.1? Related to
SSL_MODE_AUTO_RETRY?
Posted by Joe Orton <jo...@redhat.com>.
On Mon, Oct 15, 2018 at 12:55:45PM +0200, Rainer Jung wrote:
> I'm currently testing the following patch which looks OK wrt. test suite
> results. Need to run more combinations (OpenSSL version client versus
> server) though. Server with 1.1.1 and with 1.0.2p both look OK (including
> the h2 tests). Maybe some cases could be folded together or be dropped, but
> I tried to make the logic changes not to big. The SSL_ERROR_ZERO_RETURN part
> is new, because without that we get an ssl:info log line AH01992 with error
> 6 (SSL_ERROR_ZERO_RETURN) at the end of the response (at least with 1.1.1).
Thanks a lot Rainer & Stefan, sorry I didn't follow through on that
ticket/issue far enough. Strike it down as another way that 1.1.1
really is ABI-incompatible with <1.1.1 :(
The change committed to ssl_engine_io.c makes sense to me. I wonder if
mod_ssl should also handle SSL_ERROR_WANT_WRITE here as well. It will be
clearly logged if that happens ("SSL library error 3 reading data") so
we should find out anyway.
Regards, Joe
Re: h2 broken in 2.4.36 with OpenSSL 1.1.1? Related to
SSL_MODE_AUTO_RETRY?
Posted by Stefan Eissing <st...@greenbytes.de>.
> Am 15.10.2018 um 23:16 schrieb Rainer Jung <ra...@kippdata.de>:
>
> Adjusted SSL_read() rc value 0 handling applied in r1843954 to trunk. I'll let it sit there until tomorrow for comments and then suggest for backport.
Thanks, Rainer!
The h2 test suite runs as smoothly as it did before on my machine with OpenSSL 1.1.1 in trunk. I am all for backporting and testing von 2.4.x on this.
-Stefan
>
> Am 15.10.2018 um 12:55 schrieb Rainer Jung:
>> Am 15.10.2018 um 10:02 schrieb Stefan Eissing:
>>>
>>>
>>>> Am 14.10.2018 um 00:46 schrieb Rainer Jung <ra...@kippdata.de>:
>>>>
>>>> It seems the h2 failure only happens when building httpd against OpenSSL 1.1.1 (independent of TLS version used). I did a quick check with an httpd build against 1.1.0i and there the same vhost of the test framework instance worked with the same clients, that failed for 1.1.1.
>>>>
>>>> The client side OpenSSL version seems not to matter.
>>>>
>>>> When using 1.1.1 in the server even browsers seem to fail with h2.
>>>>
>>>> Anyone who can successfully use h2 with 2.4.36 build against OpenSSL 1.1.1?
>>>
>>> Me, and I got reports from others.
>>>
>>>> When comparing trace logs between the 1.1.1 server and the 1.1.0i server, one can see, that a failing OpenSSL read (0 bytes) results in APR_EOF (70014) for 1.1.1 but in errno 11 (EAGAIN) for 1.1.0i. I wonder whether this is due to the new SSL_MODE_AUTO_RETRY and maybe the following change:
>>>>
>>>> +#if OPENSSL_VERSION_NUMBER >= 0x1010100fL
>>>> + /* For OpenSSL >=1.1.1, disable auto-retry mode so it's possible
>>>> + * to consume handshake records without blocking for app-data.
>>>> + * https://github.com/openssl/openssl/issues/7178 */
>>>> + SSL_CTX_clear_mode(ctx, SSL_MODE_AUTO_RETRY);
>>>> +#endif
>>>
>>> Hmm, just read the ticket made by Joe regarding this change.
>>>
>>> I try to summarize my understanding:
>>>
>>> - this has nothing to do with HTTP/2 in particular. It's only triggered by the h2 calling sequence.
>>> - SSL_read() only returns transport data, but sometimes reads (part of) TLS meta data, such as handshake messages.
>>> - When it reads this meta data (and has processed it), it can either do another read directly after or return with
>>> its equivalent of EAGAIN. By default, it does the first.
>>> - The change in handshake handling between TLSv1.2 and TLSv1.3 led, in Joe's testing, to the case where SSL_read()'s
>>> internal re-read() on the socket blocked, as the client was not sending anything.
>>> - So, after discussion on the openssl issue tracker, Joe changed the OpenSSL behaviour of this by inserting the code above.
>>> - Now, when SSL_read() is called, processes some meta data, it will not read() on the socket again, but return a read of length 0.
>>> - mod_ssl interprets this as EOF:
>>> ssl_engine_io.c, lines 673..
>>>
>>> else if (rc == 0) {
>>> /* If EAGAIN, we will loop given a blocking read,
>>> * otherwise consider ourselves at EOF.
>>> */
>>>
>>> and returns APR_EOF to h2 which then shuts the connection down.
>>>
>>> To my understanding, mod_ssl's ssl_engine_io.c, ssl_io_input_read() has the special case handling that:
>>> - if it gets a SSL_ERROR_WANT_READ from SSL_read(), it remembers that, calls again
>>> - if SSL_read() == 0, non-blocking, it
>>> a) on having seen SSL_ERROR_WANT_READ before, return APR_EGAIN
>>> b) otherwise, return APR_EOF
>>>
>>> OpenSSL's documentation of SSL_read() now states:
>>>
>>>> Old documentation indicated a difference between 0 and -1, and that -1 was retry-able.
>>>> You should instead call SSL_get_error() to find out if it's retry-able.
>>>
>>> So, we should change our logic here. Anyone having the courage to do so? ;-)
>> Thanks for the further investigations.
>> I'm currently testing the following patch which looks OK wrt. test suite results. Need to run more combinations (OpenSSL version client versus server) though. Server with 1.1.1 and with 1.0.2p both look OK (including the h2 tests). Maybe some cases could be folded together or be dropped, but I tried to make the logic changes not to big. The SSL_ERROR_ZERO_RETURN part is new, because without that we get an ssl:info log line AH01992 with error 6 (SSL_ERROR_ZERO_RETURN) at the end of the response (at least with 1.1.1).
>> --- modules/ssl/ssl_engine_io.c.orig 2018-08-15 17:01:08.000000000 +0200
>> +++ modules/ssl/ssl_engine_io.c 2018-10-15 11:46:01.258042000 +0200
>> @@ -680,35 +680,32 @@
>> }
>> return inctx->rc;
>> }
>> - else if (rc == 0) {
>> - /* If EAGAIN, we will loop given a blocking read,
>> - * otherwise consider ourselves at EOF.
>> - */
>> - if (APR_STATUS_IS_EAGAIN(inctx->rc)
>> - || APR_STATUS_IS_EINTR(inctx->rc)) {
>> - /* Already read something, return APR_SUCCESS instead.
>> - * On win32 in particular, but perhaps on other kernels,
>> - * a blocking call isn't 'always' blocking.
>> + else /* (rc <= 0) */ {
>> + if (rc == 0) {
>> + /* If EAGAIN, we will loop given a blocking read,
>> + * otherwise consider ourselves at EOF.
>> */
>> - if (*len > 0) {
>> - inctx->rc = APR_SUCCESS;
>> - break;
>> - }
>> - if (inctx->block == APR_NONBLOCK_READ) {
>> - break;
>> - }
>> - }
>> - else {
>> - if (*len > 0) {
>> - inctx->rc = APR_SUCCESS;
>> + if (APR_STATUS_IS_EAGAIN(inctx->rc)
>> + || APR_STATUS_IS_EINTR(inctx->rc)) {
>> + /* Already read something, return APR_SUCCESS instead.
>> + * On win32 in particular, but perhaps on other kernels,
>> + * a blocking call isn't 'always' blocking.
>> + */
>> + if (*len > 0) {
>> + inctx->rc = APR_SUCCESS;
>> + break;
>> + }
>> + if (inctx->block == APR_NONBLOCK_READ) {
>> + break;
>> + }
>> }
>> else {
>> - inctx->rc = APR_EOF;
>> + if (*len > 0) {
>> + inctx->rc = APR_SUCCESS;
>> + break;
>> + }
>> }
>> - break;
>> }
>> - }
>> - else /* (rc < 0) */ {
>> int ssl_err = SSL_get_error(inctx->filter_ctx->pssl, rc);
>> conn_rec *c = (conn_rec*)SSL_get_app_data(inctx->filter_ctx->pssl);
>> @@ -754,6 +751,10 @@
>> "SSL input filter read failed.");
>> }
>> }
>> + else if (rc == 0 && ssl_err == SSL_ERROR_ZERO_RETURN) {
>> + inctx->rc = APR_EOF;
>> + break;
>> + }
>> else /* if (ssl_err == SSL_ERROR_SSL) */ {
>> /*
>> * Log SSL errors and any unexpected conditions.
>> @@ -763,6 +764,10 @@
>> ssl_log_ssl_error(SSLLOG_MARK, APLOG_INFO, mySrvFromConn(c));
>> }
>> + if (rc == 0) {
>> + inctx->rc = APR_EOF;
>> + break;
>> + }
>> if (inctx->rc == APR_SUCCESS) {
>> inctx->rc = APR_EGENERAL;
>> }
>> Regards,
>> Rainer
Re: h2 broken in 2.4.36 with OpenSSL 1.1.1? Related to
SSL_MODE_AUTO_RETRY?
Posted by Rainer Jung <ra...@kippdata.de>.
Adjusted SSL_read() rc value 0 handling applied in r1843954 to trunk.
I'll let it sit there until tomorrow for comments and then suggest for
backport.
Am 15.10.2018 um 12:55 schrieb Rainer Jung:
> Am 15.10.2018 um 10:02 schrieb Stefan Eissing:
>>
>>
>>> Am 14.10.2018 um 00:46 schrieb Rainer Jung <ra...@kippdata.de>:
>>>
>>> It seems the h2 failure only happens when building httpd against
>>> OpenSSL 1.1.1 (independent of TLS version used). I did a quick check
>>> with an httpd build against 1.1.0i and there the same vhost of the
>>> test framework instance worked with the same clients, that failed for
>>> 1.1.1.
>>>
>>> The client side OpenSSL version seems not to matter.
>>>
>>> When using 1.1.1 in the server even browsers seem to fail with h2.
>>>
>>> Anyone who can successfully use h2 with 2.4.36 build against OpenSSL
>>> 1.1.1?
>>
>> Me, and I got reports from others.
>>
>>> When comparing trace logs between the 1.1.1 server and the 1.1.0i
>>> server, one can see, that a failing OpenSSL read (0 bytes) results in
>>> APR_EOF (70014) for 1.1.1 but in errno 11 (EAGAIN) for 1.1.0i. I
>>> wonder whether this is due to the new SSL_MODE_AUTO_RETRY and maybe
>>> the following change:
>>>
>>> +#if OPENSSL_VERSION_NUMBER >= 0x1010100fL
>>> + /* For OpenSSL >=1.1.1, disable auto-retry mode so it's possible
>>> + * to consume handshake records without blocking for app-data.
>>> + * https://github.com/openssl/openssl/issues/7178 */
>>> + SSL_CTX_clear_mode(ctx, SSL_MODE_AUTO_RETRY);
>>> +#endif
>>
>> Hmm, just read the ticket made by Joe regarding this change.
>>
>> I try to summarize my understanding:
>>
>> - this has nothing to do with HTTP/2 in particular. It's only
>> triggered by the h2 calling sequence.
>> - SSL_read() only returns transport data, but sometimes reads (part
>> of) TLS meta data, such as handshake messages.
>> - When it reads this meta data (and has processed it), it can either
>> do another read directly after or return with
>> its equivalent of EAGAIN. By default, it does the first.
>> - The change in handshake handling between TLSv1.2 and TLSv1.3 led, in
>> Joe's testing, to the case where SSL_read()'s
>> internal re-read() on the socket blocked, as the client was not
>> sending anything.
>> - So, after discussion on the openssl issue tracker, Joe changed the
>> OpenSSL behaviour of this by inserting the code above.
>> - Now, when SSL_read() is called, processes some meta data, it will
>> not read() on the socket again, but return a read of length 0.
>> - mod_ssl interprets this as EOF:
>> ssl_engine_io.c, lines 673..
>>
>> else if (rc == 0) {
>> /* If EAGAIN, we will loop given a blocking read,
>> * otherwise consider ourselves at EOF.
>> */
>>
>> and returns APR_EOF to h2 which then shuts the connection down.
>>
>> To my understanding, mod_ssl's ssl_engine_io.c, ssl_io_input_read()
>> has the special case handling that:
>> - if it gets a SSL_ERROR_WANT_READ from SSL_read(), it remembers that,
>> calls again
>> - if SSL_read() == 0, non-blocking, it
>> a) on having seen SSL_ERROR_WANT_READ before, return APR_EGAIN
>> b) otherwise, return APR_EOF
>>
>> OpenSSL's documentation of SSL_read() now states:
>>
>>> Old documentation indicated a difference between 0 and -1, and that
>>> -1 was retry-able.
>>> You should instead call SSL_get_error() to find out if it's retry-able.
>>
>> So, we should change our logic here. Anyone having the courage to do
>> so? ;-)
>
> Thanks for the further investigations.
>
> I'm currently testing the following patch which looks OK wrt. test suite
> results. Need to run more combinations (OpenSSL version client versus
> server) though. Server with 1.1.1 and with 1.0.2p both look OK
> (including the h2 tests). Maybe some cases could be folded together or
> be dropped, but I tried to make the logic changes not to big. The
> SSL_ERROR_ZERO_RETURN part is new, because without that we get an
> ssl:info log line AH01992 with error 6 (SSL_ERROR_ZERO_RETURN) at the
> end of the response (at least with 1.1.1).
>
> --- modules/ssl/ssl_engine_io.c.orig 2018-08-15 17:01:08.000000000 +0200
> +++ modules/ssl/ssl_engine_io.c 2018-10-15 11:46:01.258042000 +0200
> @@ -680,35 +680,32 @@
> }
> return inctx->rc;
> }
> - else if (rc == 0) {
> - /* If EAGAIN, we will loop given a blocking read,
> - * otherwise consider ourselves at EOF.
> - */
> - if (APR_STATUS_IS_EAGAIN(inctx->rc)
> - || APR_STATUS_IS_EINTR(inctx->rc)) {
> - /* Already read something, return APR_SUCCESS instead.
> - * On win32 in particular, but perhaps on other kernels,
> - * a blocking call isn't 'always' blocking.
> + else /* (rc <= 0) */ {
> + if (rc == 0) {
> + /* If EAGAIN, we will loop given a blocking read,
> + * otherwise consider ourselves at EOF.
> */
> - if (*len > 0) {
> - inctx->rc = APR_SUCCESS;
> - break;
> - }
> - if (inctx->block == APR_NONBLOCK_READ) {
> - break;
> - }
> - }
> - else {
> - if (*len > 0) {
> - inctx->rc = APR_SUCCESS;
> + if (APR_STATUS_IS_EAGAIN(inctx->rc)
> + || APR_STATUS_IS_EINTR(inctx->rc)) {
> + /* Already read something, return APR_SUCCESS instead.
> + * On win32 in particular, but perhaps on other
> kernels,
> + * a blocking call isn't 'always' blocking.
> + */
> + if (*len > 0) {
> + inctx->rc = APR_SUCCESS;
> + break;
> + }
> + if (inctx->block == APR_NONBLOCK_READ) {
> + break;
> + }
> }
> else {
> - inctx->rc = APR_EOF;
> + if (*len > 0) {
> + inctx->rc = APR_SUCCESS;
> + break;
> + }
> }
> - break;
> }
> - }
> - else /* (rc < 0) */ {
> int ssl_err = SSL_get_error(inctx->filter_ctx->pssl, rc);
> conn_rec *c =
> (conn_rec*)SSL_get_app_data(inctx->filter_ctx->pssl);
>
> @@ -754,6 +751,10 @@
> "SSL input filter read failed.");
> }
> }
> + else if (rc == 0 && ssl_err == SSL_ERROR_ZERO_RETURN) {
> + inctx->rc = APR_EOF;
> + break;
> + }
> else /* if (ssl_err == SSL_ERROR_SSL) */ {
> /*
> * Log SSL errors and any unexpected conditions.
> @@ -763,6 +764,10 @@
> ssl_log_ssl_error(SSLLOG_MARK, APLOG_INFO,
> mySrvFromConn(c));
>
> }
> + if (rc == 0) {
> + inctx->rc = APR_EOF;
> + break;
> + }
> if (inctx->rc == APR_SUCCESS) {
> inctx->rc = APR_EGENERAL;
> }
>
> Regards,
>
> Rainer
Re: h2 broken in 2.4.36 with OpenSSL 1.1.1? Related to
SSL_MODE_AUTO_RETRY?
Posted by Rainer Jung <ra...@kippdata.de>.
Am 15.10.2018 um 10:02 schrieb Stefan Eissing:
>
>
>> Am 14.10.2018 um 00:46 schrieb Rainer Jung <ra...@kippdata.de>:
>>
>> It seems the h2 failure only happens when building httpd against OpenSSL 1.1.1 (independent of TLS version used). I did a quick check with an httpd build against 1.1.0i and there the same vhost of the test framework instance worked with the same clients, that failed for 1.1.1.
>>
>> The client side OpenSSL version seems not to matter.
>>
>> When using 1.1.1 in the server even browsers seem to fail with h2.
>>
>> Anyone who can successfully use h2 with 2.4.36 build against OpenSSL 1.1.1?
>
> Me, and I got reports from others.
>
>> When comparing trace logs between the 1.1.1 server and the 1.1.0i server, one can see, that a failing OpenSSL read (0 bytes) results in APR_EOF (70014) for 1.1.1 but in errno 11 (EAGAIN) for 1.1.0i. I wonder whether this is due to the new SSL_MODE_AUTO_RETRY and maybe the following change:
>>
>> +#if OPENSSL_VERSION_NUMBER >= 0x1010100fL
>> + /* For OpenSSL >=1.1.1, disable auto-retry mode so it's possible
>> + * to consume handshake records without blocking for app-data.
>> + * https://github.com/openssl/openssl/issues/7178 */
>> + SSL_CTX_clear_mode(ctx, SSL_MODE_AUTO_RETRY);
>> +#endif
>
> Hmm, just read the ticket made by Joe regarding this change.
>
> I try to summarize my understanding:
>
> - this has nothing to do with HTTP/2 in particular. It's only triggered by the h2 calling sequence.
> - SSL_read() only returns transport data, but sometimes reads (part of) TLS meta data, such as handshake messages.
> - When it reads this meta data (and has processed it), it can either do another read directly after or return with
> its equivalent of EAGAIN. By default, it does the first.
> - The change in handshake handling between TLSv1.2 and TLSv1.3 led, in Joe's testing, to the case where SSL_read()'s
> internal re-read() on the socket blocked, as the client was not sending anything.
> - So, after discussion on the openssl issue tracker, Joe changed the OpenSSL behaviour of this by inserting the code above.
> - Now, when SSL_read() is called, processes some meta data, it will not read() on the socket again, but return a read of length 0.
> - mod_ssl interprets this as EOF:
> ssl_engine_io.c, lines 673..
>
> else if (rc == 0) {
> /* If EAGAIN, we will loop given a blocking read,
> * otherwise consider ourselves at EOF.
> */
>
> and returns APR_EOF to h2 which then shuts the connection down.
>
> To my understanding, mod_ssl's ssl_engine_io.c, ssl_io_input_read() has the special case handling that:
> - if it gets a SSL_ERROR_WANT_READ from SSL_read(), it remembers that, calls again
> - if SSL_read() == 0, non-blocking, it
> a) on having seen SSL_ERROR_WANT_READ before, return APR_EGAIN
> b) otherwise, return APR_EOF
>
> OpenSSL's documentation of SSL_read() now states:
>
>> Old documentation indicated a difference between 0 and -1, and that -1 was retry-able.
>> You should instead call SSL_get_error() to find out if it's retry-able.
>
> So, we should change our logic here. Anyone having the courage to do so? ;-)
Thanks for the further investigations.
I'm currently testing the following patch which looks OK wrt. test suite
results. Need to run more combinations (OpenSSL version client versus
server) though. Server with 1.1.1 and with 1.0.2p both look OK
(including the h2 tests). Maybe some cases could be folded together or
be dropped, but I tried to make the logic changes not to big. The
SSL_ERROR_ZERO_RETURN part is new, because without that we get an
ssl:info log line AH01992 with error 6 (SSL_ERROR_ZERO_RETURN) at the
end of the response (at least with 1.1.1).
--- modules/ssl/ssl_engine_io.c.orig 2018-08-15 17:01:08.000000000 +0200
+++ modules/ssl/ssl_engine_io.c 2018-10-15 11:46:01.258042000 +0200
@@ -680,35 +680,32 @@
}
return inctx->rc;
}
- else if (rc == 0) {
- /* If EAGAIN, we will loop given a blocking read,
- * otherwise consider ourselves at EOF.
- */
- if (APR_STATUS_IS_EAGAIN(inctx->rc)
- || APR_STATUS_IS_EINTR(inctx->rc)) {
- /* Already read something, return APR_SUCCESS instead.
- * On win32 in particular, but perhaps on other kernels,
- * a blocking call isn't 'always' blocking.
+ else /* (rc <= 0) */ {
+ if (rc == 0) {
+ /* If EAGAIN, we will loop given a blocking read,
+ * otherwise consider ourselves at EOF.
*/
- if (*len > 0) {
- inctx->rc = APR_SUCCESS;
- break;
- }
- if (inctx->block == APR_NONBLOCK_READ) {
- break;
- }
- }
- else {
- if (*len > 0) {
- inctx->rc = APR_SUCCESS;
+ if (APR_STATUS_IS_EAGAIN(inctx->rc)
+ || APR_STATUS_IS_EINTR(inctx->rc)) {
+ /* Already read something, return APR_SUCCESS instead.
+ * On win32 in particular, but perhaps on other
kernels,
+ * a blocking call isn't 'always' blocking.
+ */
+ if (*len > 0) {
+ inctx->rc = APR_SUCCESS;
+ break;
+ }
+ if (inctx->block == APR_NONBLOCK_READ) {
+ break;
+ }
}
else {
- inctx->rc = APR_EOF;
+ if (*len > 0) {
+ inctx->rc = APR_SUCCESS;
+ break;
+ }
}
- break;
}
- }
- else /* (rc < 0) */ {
int ssl_err = SSL_get_error(inctx->filter_ctx->pssl, rc);
conn_rec *c =
(conn_rec*)SSL_get_app_data(inctx->filter_ctx->pssl);
@@ -754,6 +751,10 @@
"SSL input filter read failed.");
}
}
+ else if (rc == 0 && ssl_err == SSL_ERROR_ZERO_RETURN) {
+ inctx->rc = APR_EOF;
+ break;
+ }
else /* if (ssl_err == SSL_ERROR_SSL) */ {
/*
* Log SSL errors and any unexpected conditions.
@@ -763,6 +764,10 @@
ssl_log_ssl_error(SSLLOG_MARK, APLOG_INFO,
mySrvFromConn(c));
}
+ if (rc == 0) {
+ inctx->rc = APR_EOF;
+ break;
+ }
if (inctx->rc == APR_SUCCESS) {
inctx->rc = APR_EGENERAL;
}
Regards,
Rainer
Re: h2 broken in 2.4.36 with OpenSSL 1.1.1? Related to
SSL_MODE_AUTO_RETRY?
Posted by Stefan Eissing <st...@greenbytes.de>.
> Am 14.10.2018 um 00:46 schrieb Rainer Jung <ra...@kippdata.de>:
>
> It seems the h2 failure only happens when building httpd against OpenSSL 1.1.1 (independent of TLS version used). I did a quick check with an httpd build against 1.1.0i and there the same vhost of the test framework instance worked with the same clients, that failed for 1.1.1.
>
> The client side OpenSSL version seems not to matter.
>
> When using 1.1.1 in the server even browsers seem to fail with h2.
>
> Anyone who can successfully use h2 with 2.4.36 build against OpenSSL 1.1.1?
Me, and I got reports from others.
> When comparing trace logs between the 1.1.1 server and the 1.1.0i server, one can see, that a failing OpenSSL read (0 bytes) results in APR_EOF (70014) for 1.1.1 but in errno 11 (EAGAIN) for 1.1.0i. I wonder whether this is due to the new SSL_MODE_AUTO_RETRY and maybe the following change:
>
> +#if OPENSSL_VERSION_NUMBER >= 0x1010100fL
> + /* For OpenSSL >=1.1.1, disable auto-retry mode so it's possible
> + * to consume handshake records without blocking for app-data.
> + * https://github.com/openssl/openssl/issues/7178 */
> + SSL_CTX_clear_mode(ctx, SSL_MODE_AUTO_RETRY);
> +#endif
Hmm, just read the ticket made by Joe regarding this change.
I try to summarize my understanding:
- this has nothing to do with HTTP/2 in particular. It's only triggered by the h2 calling sequence.
- SSL_read() only returns transport data, but sometimes reads (part of) TLS meta data, such as handshake messages.
- When it reads this meta data (and has processed it), it can either do another read directly after or return with
its equivalent of EAGAIN. By default, it does the first.
- The change in handshake handling between TLSv1.2 and TLSv1.3 led, in Joe's testing, to the case where SSL_read()'s
internal re-read() on the socket blocked, as the client was not sending anything.
- So, after discussion on the openssl issue tracker, Joe changed the OpenSSL behaviour of this by inserting the code above.
- Now, when SSL_read() is called, processes some meta data, it will not read() on the socket again, but return a read of length 0.
- mod_ssl interprets this as EOF:
ssl_engine_io.c, lines 673..
else if (rc == 0) {
/* If EAGAIN, we will loop given a blocking read,
* otherwise consider ourselves at EOF.
*/
and returns APR_EOF to h2 which then shuts the connection down.
To my understanding, mod_ssl's ssl_engine_io.c, ssl_io_input_read() has the special case handling that:
- if it gets a SSL_ERROR_WANT_READ from SSL_read(), it remembers that, calls again
- if SSL_read() == 0, non-blocking, it
a) on having seen SSL_ERROR_WANT_READ before, return APR_EGAIN
b) otherwise, return APR_EOF
OpenSSL's documentation of SSL_read() now states:
> Old documentation indicated a difference between 0 and -1, and that -1 was retry-able.
> You should instead call SSL_get_error() to find out if it's retry-able.
So, we should change our logic here. Anyone having the courage to do so? ;-)
-Stefan
>
> The logs:
>
> < OpenSSL 1.1.1
> > OpenSSL 1.1.0i
>
> < 23:35:16.021201 h2_session.c(1704): AH03078: h2_session(81,BUSY,0): transit [INIT] -- init --> [BUSY]
> > 23:39:55.715439 h2_session.c(1670): AH03078: h2_session(66,BUSY,0): transit [INIT] -- init --> [BUSY]
>
> Some additional early stuff for 1.1.0i
>
> > 23:39:55.715448 h2_filter.c(145): h2_session(66): read, NONBLOCK_READ, mode=0, readbytes=65536
> > 23:39:55.715470 ssl_engine_io.c(2222): OpenSSL: I/O error, 5 bytes expected to read on BIO#7efee0005280 [mem: 7efee0014ee3]
> > 23:39:55.715480 h2_filter.c(190): (11)Resource temporarily unavailable: h2_session(66): read
> > 23:39:55.715508 h2_mplx.c(1240): h2_mplx(66): dispatch events
> > 23:39:55.715536 h2_session.c(589): AH03068: h2_session(66,BUSY,0): sent FRAME[SETTINGS[length=6, stream=0]], frames=0/1 (r/s)
> > 23:39:55.715548 h2_session.c(589): AH03068: h2_session(66,BUSY,0): sent FRAME[WINDOW_UPDATE[stream=0, incr=2147418112]], frames=0/2 (r/s)
> > 23:39:55.715565 h2_conn_io.c(122): h2_session(66)-out: heap[28] flush
> > 23:39:55.715590 core_filters.c(580): brigade contains: bytes: 57, non-file bytes: 57, eor buckets: 0, morphing buckets: 0
> > 23:39:55.715598 ssl_engine_io.c(2213): OpenSSL: write 57/57 bytes to BIO#7efee00021b0 [mem: 7efee0014ee3]
> > 23:39:55.715648 core_filters.c(525): will flush because of FLUSH bucket
> > 23:39:55.715653 core_filters.c(535): seen in brigade so far: bytes: 57, non-file bytes: 57, eor buckets: 0, morphing buckets: 0
> > 23:39:55.715657 core_filters.c(554): flushing now
> > 23:39:55.715683 core_filters.c(569): total bytes written: 2466
> > 23:39:55.715690 core_filters.c(580): brigade contains: bytes: 0, non-file bytes: 0, eor buckets: 0, morphing buckets: 0
>
> Then many things identical
>
> < 23:35:16.021217 h2_filter.c(145): h2_session(81): read, NONBLOCK_READ, mode=0, readbytes=65536
> > 23:39:55.715697 h2_filter.c(145): h2_session(66): read, NONBLOCK_READ, mode=0, readbytes=65536
> < 23:35:16.021252 ssl_engine_io.c(2213): OpenSSL: read 5/5 bytes from BIO#7f1d04002b10 [mem: 7f1d040145a3]
> < 23:35:16.021277 ssl_engine_io.c(2213): OpenSSL: read 41/41 bytes from BIO#7f1d04002b10 [mem: 7f1d040145a8]
> < 23:35:16.021318 h2_filter.c(93): bb_dump(81): RAW_in(TRANSIENT[24])
> < 23:35:16.021340 h2_filter.c(64): h2_session(81,BUSY,0): fed 24 bytes to nghttp2, 24 read
> > 23:39:55.715713 ssl_engine_io.c(2213): OpenSSL: read 5/5 bytes from BIO#7efee0005280 [mem: 7efee0014ee3]
> > 23:39:55.715734 ssl_engine_io.c(2213): OpenSSL: read 48/48 bytes from BIO#7efee0005280 [mem: 7efee0014ee8]
> > 23:39:55.715774 h2_filter.c(93): bb_dump(66): RAW_in(TRANSIENT[24])
> > 23:39:55.715786 h2_filter.c(64): h2_session(66,BUSY,0): fed 24 bytes to nghttp2, 24 read
> < 23:35:16.021355 h2_filter.c(145): h2_session(81): read, NONBLOCK_READ, mode=0, readbytes=65536
> < 23:35:16.021364 ssl_engine_io.c(2213): OpenSSL: read 5/5 bytes from BIO#7f1d04002b10 [mem: 7f1d040145a3]
> < 23:35:16.021384 ssl_engine_io.c(2213): OpenSSL: read 44/44 bytes from BIO#7f1d04002b10 [mem: 7f1d040145a8]
> < 23:35:16.021428 h2_filter.c(93): bb_dump(81): RAW_in(TRANSIENT[27])
> < 23:35:16.021442 h2_session.c(341): AH03066: h2_session(81,BUSY,0): recv FRAME[SETTINGS[length=18, stream=0]], frames=0/0 (r/s)
> < 23:35:16.021447 h2_session.c(414): h2_session(81,BUSY,0): SETTINGS, len=18
> > 23:39:55.715792 h2_filter.c(145): h2_session(66): read, NONBLOCK_READ, mode=0, readbytes=65536
> > 23:39:55.715804 ssl_engine_io.c(2213): OpenSSL: read 5/5 bytes from BIO#7efee0005280 [mem: 7efee0014ee3]
> > 23:39:55.715825 ssl_engine_io.c(2213): OpenSSL: read 51/51 bytes from BIO#7efee0005280 [mem: 7efee0014ee8]
> > 23:39:55.715897 h2_filter.c(93): bb_dump(66): RAW_in(TRANSIENT[27])
> > 23:39:55.715926 h2_session.c(341): AH03066: h2_session(66,BUSY,0): recv FRAME[SETTINGS[length=18, stream=0]], frames=0/2 (r/s)
> > 23:39:55.715934 h2_session.c(414): h2_session(66,BUSY,0): SETTINGS, len=18
> < 23:35:16.021451 h2_filter.c(64): h2_session(81,BUSY,0): fed 27 bytes to nghttp2, 27 read
> < 23:35:16.021464 h2_filter.c(145): h2_session(81): read, NONBLOCK_READ, mode=0, readbytes=65536
> < 23:35:16.021471 ssl_engine_io.c(2213): OpenSSL: read 5/5 bytes from BIO#7f1d04002b10 [mem: 7f1d040145a3]
> < 23:35:16.021491 ssl_engine_io.c(2213): OpenSSL: read 30/30 bytes from BIO#7f1d04002b10 [mem: 7f1d040145a8]
> < 23:35:16.021535 h2_filter.c(93): bb_dump(81): RAW_in(TRANSIENT[13])
> < 23:35:16.021542 h2_session.c(341): AH03066: h2_session(81,BUSY,0): recv FRAME[WINDOW_UPDATE[stream=0, incr=1073676289]], frames=1/0 (r/s)
> > 23:39:55.715939 h2_filter.c(64): h2_session(66,BUSY,0): fed 27 bytes to nghttp2, 27 read
> > 23:39:55.715943 h2_filter.c(145): h2_session(66): read, NONBLOCK_READ, mode=0, readbytes=65536
> > 23:39:55.715953 ssl_engine_io.c(2213): OpenSSL: read 5/5 bytes from BIO#7efee0005280 [mem: 7efee0014ee3]
> > 23:39:55.715973 ssl_engine_io.c(2213): OpenSSL: read 37/37 bytes from BIO#7efee0005280 [mem: 7efee0014ee8]
> > 23:39:55.716015 h2_filter.c(93): bb_dump(66): RAW_in(TRANSIENT[13])
> > 23:39:55.716024 h2_session.c(341): AH03066: h2_session(66,BUSY,0): recv FRAME[WINDOW_UPDATE[stream=0, incr=1073676289]], frames=1/2 (r/s)
> < 23:35:16.021547 h2_session.c(381): h2_stream(81-0): WINDOW_UPDATE incr=1073676289
> < 23:35:16.021552 h2_filter.c(64): h2_session(81,BUSY,0): fed 13 bytes to nghttp2, 13 read
> < 23:35:16.021563 h2_filter.c(145): h2_session(81): read, NONBLOCK_READ, mode=0, readbytes=65536
> < 23:35:16.021571 ssl_engine_io.c(2213): OpenSSL: read 5/5 bytes from BIO#7f1d04002b10 [mem: 7f1d040145a3]
> < 23:35:16.021591 ssl_engine_io.c(2213): OpenSSL: read 56/56 bytes from BIO#7f1d04002b10 [mem: 7f1d040145a8]
> < 23:35:16.021632 h2_filter.c(93): bb_dump(81): RAW_in(TRANSIENT[39])
> > 23:39:55.716029 h2_session.c(381): h2_stream(66-0): WINDOW_UPDATE incr=1073676289
> > 23:39:55.716034 h2_filter.c(64): h2_session(66,BUSY,0): fed 13 bytes to nghttp2, 13 read
> > 23:39:55.716039 h2_filter.c(145): h2_session(66): read, NONBLOCK_READ, mode=0, readbytes=65536
> > 23:39:55.716045 ssl_engine_io.c(2213): OpenSSL: read 5/5 bytes from BIO#7efee0005280 [mem: 7efee0014ee3]
> > 23:39:55.716065 ssl_engine_io.c(2213): OpenSSL: read 63/63 bytes from BIO#7efee0005280 [mem: 7efee0014ee8]
> > 23:39:55.716114 h2_filter.c(93): bb_dump(66): RAW_in(TRANSIENT[39])
> < 23:35:16.021652 h2_stream.c(552): AH03082: h2_stream(81-1,IDLE): created
> < 23:35:16.021665 h2_session.c(1960): h2_stream(81-1,IDLE): entered state
> < 23:35:16.021699 h2_session.c(341): AH03066: h2_session(81,BUSY,1): recv FRAME[HEADERS[length=30, hend=1, stream=1, eos=1]], frames=2/0 (r/s)
> < 23:35:16.021709 h2_stream.c(302): h2_stream(81-1,IDLE): transit to [OPEN]
> > 23:39:55.716138 h2_stream.c(552): AH03082: h2_stream(66-1,IDLE): created
> > 23:39:55.716146 h2_session.c(1926): h2_stream(66-1,IDLE): entered state
> > 23:39:55.716185 h2_session.c(341): AH03066: h2_session(66,BUSY,1): recv FRAME[HEADERS[length=30, hend=1, stream=1, eos=1]], frames=2/2 (r/s)
> > 23:39:55.716197 h2_stream.c(302): h2_stream(66-1,IDLE): transit to [OPEN]
> < 23:35:16.021714 h2_session.c(1960): h2_stream(81-1,OPEN): entered state
> < 23:35:16.021732 h2_stream.c(302): h2_stream(81-1,OPEN): transit to [HALF_CLOSED_REMOTE]
> < 23:35:16.021736 h2_stream.c(211): h2_stream(81-1,HALF_CLOSED_REMOTE): closing input
> < 23:35:16.021740 h2_session.c(1960): h2_stream(81-1,HALF_CLOSED_REMOTE): entered state
> > 23:39:55.716201 h2_session.c(1926): h2_stream(66-1,OPEN): entered state
> > 23:39:55.716206 h2_stream.c(302): h2_stream(66-1,OPEN): transit to [HALF_CLOSED_REMOTE]
> > 23:39:55.716210 h2_stream.c(211): h2_stream(66-1,HALF_CLOSED_REMOTE): closing input
> > 23:39:55.716214 h2_session.c(1926): h2_stream(66-1,HALF_CLOSED_REMOTE): entered state
> < 23:35:16.021744 h2_filter.c(64): h2_session(81,BUSY,1): fed 39 bytes to nghttp2, 39 read
> < 23:35:16.021757 h2_filter.c(145): h2_session(81): read, NONBLOCK_READ, mode=0, readbytes=65536
> > 23:39:55.716219 h2_filter.c(64): h2_session(66,BUSY,1): fed 39 bytes to nghttp2, 39 read
> > 23:39:55.716224 h2_filter.c(145): h2_session(66): read, NONBLOCK_READ, mode=0, readbytes=65536
>
> Again some additional stuff for 1.1.0i
>
> > 23:39:55.716254 ssl_engine_io.c(2213): OpenSSL: read 5/5 bytes from BIO#7efee0005280 [mem: 7efee0014ee3]
> > 23:39:55.716277 ssl_engine_io.c(2213): OpenSSL: read 33/33 bytes from BIO#7efee0005280 [mem: 7efee0014ee8]
> > 23:39:55.716320 h2_filter.c(93): bb_dump(66): RAW_in(TRANSIENT[9])
> > 23:39:55.716328 h2_session.c(341): AH03066: h2_session(66,BUSY,1): recv FRAME[SETTINGS[ack=1, stream=0]], frames=3/2 (r/s)
> > 23:39:55.716333 h2_session.c(414): h2_session(66,BUSY,1): SETTINGS, len=0
> > 23:39:55.716337 h2_filter.c(64): h2_session(66,BUSY,1): fed 9 bytes to nghttp2, 9 read
> > 23:39:55.716341 h2_filter.c(145): h2_session(66): read, NONBLOCK_READ, mode=0, readbytes=65536
>
> And now differences, 1.1.1 gets 0 bytes but 70014 (APR_EOF), 1.1.0i 0 bytes but 11 (EAGAIN?)
>
> < 23:35:16.021774 ssl_engine_io.c(2213): OpenSSL: read 0/5 bytes from BIO#7f1d04002b10 [mem: 7f1d040165b3]
> < 23:35:16.021790 h2_filter.c(190): (70014)End of file found: h2_session(81): read
> < 23:35:16.021809 h2_stream.c(594): h2_stream(81-1,HALF_CLOSED_REMOTE): schedule GET https://localhost:8557/ chunked=0
> < 23:35:16.021841 h2_mplx.c(703): h2_stream(81-1,HALF_CLOSED_REMOTE): process, added to q
> < 23:35:16.021872 h2_mplx.c(1240): h2_mplx(81): dispatch events
> > 23:39:55.716352 ssl_engine_io.c(2222): OpenSSL: I/O error, 5 bytes expected to read on BIO#7efee0005280 [mem: 7efee0014ee3]
> > 23:39:55.716359 h2_filter.c(190): (11)Resource temporarily unavailable: h2_session(66): read
> > 23:39:55.716368 h2_stream.c(594): h2_stream(66-1,HALF_CLOSED_REMOTE): schedule GET https://localhost:8557/ chunked=0
> > 23:39:55.716400 h2_mplx.c(703): h2_stream(66-1,HALF_CLOSED_REMOTE): process, added to q
> > 23:39:55.716408 h2_mplx.c(1240): h2_mplx(66): dispatch events
>
> < 23:35:16.021879 SLAVE h2_conn.c(271): h2_stream(81-1): create slave
>
> < 23:35:16.021895 h2_session.c(589): AH03068: h2_session(81,BUSY,1): sent FRAME[SETTINGS[length=6, stream=0]], frames=3/1 (r/s)
> < 23:35:16.021905 h2_session.c(589): AH03068: h2_session(81,BUSY,1): sent FRAME[SETTINGS[ack=1, stream=0]], frames=3/2 (r/s)
> < 23:35:16.021911 h2_session.c(589): AH03068: h2_session(81,BUSY,1): sent FRAME[WINDOW_UPDATE[stream=0, incr=2147418112]], frames=3/3 (r/s)
>
> > 23:39:55.716416 h2_session.c(589): AH03068: h2_session(66,BUSY,1): sent FRAME[SETTINGS[ack=1, stream=0]], frames=4/3 (r/s)
>
> < 23:35:16.022541 h2_conn_io.c(122): h2_session(81)-out: heap[37] flush
> < 23:35:16.022573 core_filters.c(580): brigade contains: bytes: 59, non-file bytes: 59, eor buckets: 0, morphing buckets: 0
> < 23:35:16.022591 ssl_engine_io.c(2213): OpenSSL: write 59/59 bytes to BIO#7f1d04002a50 [mem: 7f1d0400c443]
> < 23:35:16.022613 SLAVE h2_conn.c(336): h2_stream(81-1): created slave
> < 23:35:16.022635 core_filters.c(525): will flush because of FLUSH bucket
> > 23:39:55.716425 h2_conn_io.c(122): h2_session(66)-out: heap[9] flush
> > 23:39:55.716437 core_filters.c(580): brigade contains: bytes: 38, non-file bytes: 38, eor buckets: 0, morphing buckets: 0
> > 23:39:55.716444 ssl_engine_io.c(2213): OpenSSL: write 38/38 bytes to BIO#7efee00021b0 [mem: 7efee0014ee3]
> > 23:39:55.716443 SLAVE h2_conn.c(271): h2_stream(66-1): create slave
> > 23:39:55.716481 core_filters.c(525): will flush because of FLUSH bucket
>
> < 23:35:16.022636 SLAVE h2_task.c(507): h2_h2, pre_connection, found stream task
>
> < 23:35:16.022639 core_filters.c(535): seen in brigade so far: bytes: 59, non-file bytes: 59, eor buckets: 0, morphing buckets: 0
> > 23:39:55.716485 core_filters.c(535): seen in brigade so far: bytes: 38, non-file bytes: 38, eor buckets: 0, morphing buckets: 0
>
> > 23:39:55.716490 SLAVE h2_conn.c(336): h2_stream(66-1): created slave
>
> < 23:35:16.022643 core_filters.c(554): flushing now
> > 23:39:55.716497 core_filters.c(554): flushing now
>
> < 23:35:16.022656 SLAVE h2_task.c(632): h2_task(81-1): process connection
> < 23:35:16.022662 SLAVE h2_task.c(731): h2_h2, processing request directly
>
> > 23:39:55.716512 SLAVE h2_task.c(507): h2_h2, pre_connection, found stream task
>
> < 23:35:16.022664 core_filters.c(569): total bytes written: 3181
> > 23:39:55.716525 core_filters.c(569): total bytes written: 2504
>
> < 23:35:16.022666 SLAVE h2_task.c(658): h2_task(81-1): create request_rec
>
> < 23:35:16.022670 core_filters.c(580): brigade contains: bytes: 0, non-file bytes: 0, eor buckets: 0, morphing buckets: 0
> > 23:39:55.716532 core_filters.c(580): brigade contains: bytes: 0, non-file bytes: 0, eor buckets: 0, morphing buckets: 0
>
> > 23:39:55.716537 SLAVE h2_task.c(632): h2_task(66-1): process connection
>
> < 23:35:16.022689 h2_filter.c(145): h2_session(81): read, NONBLOCK_READ, mode=0, readbytes=65536
> > 23:39:55.716539 h2_filter.c(145): h2_session(66): read, NONBLOCK_READ, mode=0, readbytes=65536
>
> > 23:39:55.716543 SLAVE h2_task.c(731): h2_h2, processing request directly
> > 23:39:55.716548 SLAVE h2_task.c(658): h2_task(66-1): create request_rec
>
> Again 70014 versus 11 when no bytes could be read:
>
> < 23:35:16.022702 ssl_engine_io.c(2213): OpenSSL: read 0/5 bytes from BIO#7f1d04002b10 [mem: 7f1d040165b3]
> < 23:35:16.022718 h2_filter.c(190): (70014)End of file found: h2_session(81): read
> > 23:39:55.716551 ssl_engine_io.c(2222): OpenSSL: I/O error, 5 bytes expected to read on BIO#7efee0005280 [mem: 7efee0014ee3]
> > 23:39:55.716559 h2_filter.c(190): (11)Resource temporarily unavailable: h2_session(66): read
>
> < 23:35:16.022692 [example_hooks:notice] SLAVE x_create_request()
> > 23:39:55.716571 [example_hooks:notice] SLAVE x_create_request()
>
> And here resulting in GOAWAY versus WAIT:
>
> < 23:35:16.022730 h2_session.c(1605): (70014)End of file found: h2_session(81,BUSY,1): input gone
> < 23:35:16.022745 h2_session.c(1794): AH03401: h2_session(81,BUSY,1): conn error -> shutdown
> < 23:35:16.022753 h2_session.c(589): AH03068: h2_session(81,BUSY,1): sent FRAME[GOAWAY[error=0, reason='', last_stream=1]], frames=3/4 (r/s)
> < 23:35:16.022762 h2_conn_io.c(122): h2_session(81)-out: heap[17] flush
> < 23:35:16.022775 core_filters.c(580): brigade contains: bytes: 39, non-file bytes: 39, eor buckets: 0, morphing buckets: 0
> < 23:35:16.022783 ssl_engine_io.c(2213): OpenSSL: write 39/39 bytes to BIO#7f1d04002a50 [mem: 7f1d0400c443]
>
> > 23:39:55.716567 h2_mplx.c(1240): h2_mplx(66): dispatch events
> > 23:39:55.716572 h2_session.c(1796): h2_session(66,BUSY,1): NO_IO event, 1 streams open
> > 23:39:55.716579 h2_session.c(1670): AH03078: h2_session(66,WAIT,1): transit [BUSY] -- no io --> [WAIT]
> > 23:39:55.716584 h2_session.c(2283): h2_session: wait for data, 10 micros
>
> SLAVES looking OK
>
> < 23:35:16.022736 SLAVE h2_h2.c(722): h2_task(81-1): adding request filters
> > 23:39:55.716598 SLAVE h2_h2.c(722): h2_task(66-1): adding request filters
>
> < 23:35:16.022782 SLAVE ssl_engine_kernel.c(383): AH02034: Subsequent (No.2) HTTPS request received for child 347892350977 (server localhost:8557)
> < 23:35:16.022799 SLAVE h2_task.c(676): h2_task(81-1): start process_request
> < 23:35:16.022811 [http:trace4] SLAVE http_request.c(437): Headers received from client:
> < 23:35:16.022817 [http:trace4] SLAVE http_request.c(441): User-Agent: curl/7.61.1
> < 23:35:16.022822 [http:trace4] SLAVE http_request.c(441): Accept: */*
> > 23:39:55.716635 SLAVE ssl_engine_kernel.c(383): AH02034: Subsequent (No.2) HTTPS request received for child 283467841537 (server localhost:8557)
> > 23:39:55.716646 SLAVE h2_task.c(676): h2_task(66-1): start process_request
> > 23:39:55.716652 [http:trace4] SLAVE http_request.c(437): Headers received from client:
> > 23:39:55.716658 [http:trace4] SLAVE http_request.c(441): User-Agent: curl/7.61.1
> > 23:39:55.716661 [http:trace4] SLAVE http_request.c(441): Accept: */*
> > 23:39:55.716665 [http:trace4] SLAVE http_request.c(441): Host: localhost:8557
>
> But then failure (empty result) for 1.1.1 due to GOAWAY
>
> < 23:35:16.022824 core_filters.c(525): will flush because of FLUSH bucket
> < 23:35:16.022825 [http:trace4] SLAVE http_request.c(441): Host: localhost:8557
> < 23:35:16.022828 core_filters.c(535): seen in brigade so far: bytes: 39, non-file bytes: 39, eor buckets: 0, morphing buckets: 0
> < 23:35:16.022833 core_filters.c(554): flushing now
> < 23:35:16.022874 core_filters.c(569): total bytes written: 3220
> < 23:35:16.022882 core_filters.c(580): brigade contains: bytes: 0, non-file bytes: 0, eor buckets: 0, morphing buckets: 0
> < 23:35:16.022887 h2_session.c(715): AH03069: h2_session(81,BUSY,1): sent GOAWAY, err=0, msg=
> < 23:35:16.022895 h2_session.c(1704): AH03078: h2_session(81,DONE,1): transit [BUSY] -- local goaway --> [DONE]
> < 23:35:16.022900 h2_mplx.c(1240): h2_mplx(81): dispatch events
> < 23:35:16.022905 h2_session.c(2364): h2_session(81,DONE,1): process returns
> < 23:35:16.022909 h2_conn.c(217): (70014)End of file found: AH03045: h2_session(81,DONE,1): process, closing conn
> < 23:35:16.022916 h2_session.c(2382): h2_session(81,DONE,1): pre_close
> < 23:35:16.022920 h2_session.c(725): h2_session(81,DONE,1): pool_cleanup
> < 23:35:16.022924 h2_session.c(1704): AH03078: h2_session(81,CLEANUP,1): transit [DONE] -- pre_close --> [CLEANUP]
> < 23:35:16.022929 h2_stream.c(612): h2_stream(81-1,HALF_CLOSED_REMOTE): reset, error=0
> < 23:35:16.022941 h2_stream.c(344): h2_stream(81-1,HALF_CLOSED_REMOTE): dispatch event 2
> < 23:35:16.022945 h2_stream.c(302): h2_stream(81-1,HALF_CLOSED_REMOTE): transit to [CLOSED]
> < 23:35:16.022949 h2_stream.c(211): h2_stream(81-1,CLOSED): closing input
> < 23:35:16.022953 h2_stream.c(344): h2_stream(81-1,CLOSED): dispatch event 3
> < 23:35:16.022957 h2_stream.c(302): h2_stream(81-1,CLOSED): transit to [CLEANUP]
> < 23:35:16.022963 h2_ngn_shed.c(144): AH03394: h2_ngn_shed(81): abort
>
> Whereas 1.1.0i proceeds processing and sends the result back
> ...
>
>
> Regards,
>
> Rainer
>
> Am 13.10.2018 um 23:07 schrieb Rainer Jung:
>> Hi Stefan,
>> it is the "input gone" (APR_EOF) case which went unnoticed by me. Although I patch the test suite to run with trace8 log level, http2 was set to debug in the test suite config and the "input gone" message is a trace message. See below for more details. The question is still whether this should have been handled non-fatally. Currently curl fails to do h2 with httpd 2.4.36 as set up by the test suite.
>> Am 13.10.2018 um 18:53 schrieb Stefan Eissing:
>>> Hi Rainer,
>>>
>>> according to the log, the h2 code must be in the H2_SESSION_ST_BUSY state and the only cause I see is the same as you, namely an unexpected status from h2_session_read(), which should come via
>>>
>>> status = ap_get_brigade(c->input_filters,
>>> session->bbtmp, AP_MODE_READBYTES,
>>> block? APR_BLOCK_READ : APR_NONBLOCK_READ,
>>> H2MAX(APR_BUCKET_BUFF_SIZE, readlen));
>>>
>>> block is 0 here and readlen should be (unless reconfigured via H2StreamMaxMemSize) 32kb.
>>>
>>> Maybe you could just add a log line there to see what ap_get_brigade() returned there?
>>>
>>> Strange.
>> I hope most of the added http2:debug log lines with logno AH9999* are self-explaining:
>> ...
>> 22:25:25.934782 [core:trace8] core_filters.c(554): [client 127.0.0.1:36318] flushing now
>> 22:25:25.934810 [core:trace8] core_filters.c(569): [client 127.0.0.1:36318] total bytes written: 3197
>> 22:25:25.934816 [core:trace8] core_filters.c(580): [client 127.0.0.1:36318] brigade contains: bytes: 0, non-file bytes: 0, eor buckets: 0, morphing buckets: 0
>> 22:25:25.934823 [http2:debug] h2_session.c(1552): [client 127.0.0.1:36318] AH99997: h2_session(75,BUSY,1): Into session_read non-blocking readlen 65536 read_start 103
>> 22:25:25.934828 [http2:trace1] h2_filter.c(145): [client 127.0.0.1:36318] h2_session(75): read, NONBLOCK_READ, mode=0, readbytes=65536
>> 22:25:25.934878 [ssl:trace4] ssl_engine_io.c(2213): [client 127.0.0.1:36318] OpenSSL: read 0/5 bytes from BIO#7ff098002b10 [mem: 7ff0980164d3] (BIO dump follows)
>> 22:25:25.934894 [ssl:trace7] ssl_engine_io.c(2136): [client 127.0.0.1:36318] +-------------------------------------------------------------------------+
>> 22:25:25.934898 [ssl:trace7] ssl_engine_io.c(2180): [client 127.0.0.1:36318] +-------------------------------------------------------------------------+
>> 22:25:25.934903 [http2:trace1] h2_filter.c(190): (70014)End of file found: [client 127.0.0.1:36318] h2_session(75): read
>> 22:25:25.934908 [http2:debug] h2_session.c(1563): (70014)End of file found: [client 127.0.0.1:36318] AH99990: h2_session(75,BUSY,1): session_read non-blocking readlen 65536 ap_get_brigade returned status 70014
>> 22:25:25.934913 [http2:debug] h2_session.c(1603): (70014)End of file found: [client 127.0.0.1:36318] AH99998: h2_session(75,BUSY,1): input gone
>> 22:25:25.934917 [http2:trace1] h2_session.c(1605): (70014)End of file found: [client 127.0.0.1:36318] h2_session(75,BUSY,1): input gone
>> 22:25:25.934921 [http2:debug] h2_session.c(1616): [client 127.0.0.1:36318] AH99994: h2_session(75,BUSY,1): session_read non-blocking readlen 65536 status 70014 (default case) session->io.bytes_read == read_start (103 == 103) returning status 70014
>> 22:25:25.934926 [http2:debug] h2_session.c(1645): (70014)End of file found: [client 127.0.0.1:36318] AH99999: h2_session(75,BUSY,1): h2_session_read non-blocking returning 70014
>> 22:25:25.934931 [http2:debug] h2_session.c(1794): [client 127.0.0.1:36318] AH03401: h2_session(75,BUSY,1): conn error -> shutdown
>> 22:25:25.934938 [http2:debug] h2_session.c(589): [client 127.0.0.1:36318] AH03068: h2_session(75,BUSY,1): sent FRAME[GOAWAY[error=0, reason='', last_stream=1]], frames=3/4 (r/s)
>> I reduced my long list of loaded modules to check, whether a filter in some module interacts badly, but the problem still happens with the following modules loaded:
>> mod_mpm_event.so
>> mod_authn_file.so
>> mod_authn_anon.so
>> mod_authn_socache.so
>> mod_authn_core.so
>> mod_authz_host.so
>> mod_authz_groupfile.so
>> mod_authz_user.so
>> mod_authz_owner.so
>> mod_authz_core.so
>> mod_access_compat.so
>> mod_auth_basic.so
>> mod_allowmethods.so
>> mod_socache_shmcb.so
>> mod_watchdog.so
>> mod_macro.so
>> mod_reqtimeout.so
>> mod_filter.so
>> mod_mime.so
>> mod_log_debug.so
>> mod_env.so
>> mod_headers.so
>> mod_unique_id.so
>> mod_setenvif.so
>> mod_version.so
>> mod_remoteip.so
>> mod_slotmem_shm.so
>> mod_slotmem_plain.so
>> mod_ssl.so
>> mod_http2.so
>> mod_unixd.so
>> mod_heartbeat.so
>> mod_heartmonitor.so
>> mod_status.so
>> mod_info.so
>> mod_cgid.so
>> mod_cgi.so
>> mod_dir.so
>> mod_alias.so
>> mod_rewrite.so
>> and the usual test modules:
>> mod_eat_post.so
>> mod_input_body_filter.so
>> mod_test_pass_brigade.so
>> mod_echo_post.so
>> mod_nntp_like.so
>> mod_fold.so
>> mod_client_add_filter.so
>> mod_memory_track.so
>> mod_test_ssl.so
>> mod_test_apr_uri.so
>> mod_list_modules.so
>> mod_random_chunk.so
>> mod_authany.so
>> mod_test_utilities.so
>> mod_echo_post_chunk.so
>> mod_test_rwrite.so
>> mod_mime.so
>> mod_alias.so
>> I don't know how to correctly distinguish a real client gone from a 0 byte non-blocking read.
>> Regards,
>> Rainer
>>>> Am 13.10.2018 um 13:14 schrieb Rainer Jung <ra...@kippdata.de>:
>>>>
>>>> Hi Stefan,
>>>>
>>>> Am 10.10.2018 um 16:04 schrieb Stefan Eissing:
>>>>>> Am 10.10.2018 um 15:06 schrieb Joe Orton <jo...@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-dev@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-dev@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-dev@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-dev@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