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

Sat, 13 Oct 2018 14:07:47 -0700 

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 <[email protected]>:

Hi Stefan,

Am 10.10.2018 um 16:04 schrieb Stefan Eissing:

Am 10.10.2018 um 15:06 schrieb Joe Orton <[email protected]>:

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; [email protected]
*  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; 
[email protected]
*  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; [email protected]
*  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; 
[email protected]
*  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

























					Reply via email to