On 2015-07-17 12:39 PM, Yann Ylavic wrote:
But possibly "LogLevel trace5" in httpd.conf (or
t/conf/ssl/ssl.conf.in 's VirtualHost) would be enough to see what's
going on. Since the "error" (interruption) seems to be on the client
side though, it may also be interesting to start httpd with a
configuration like the framework's generated t/conf/ssl/ssl.conf file,
and then use openssl s_client (or libressl s_client? dunno the name of
that binary in libreSSL...) with -state and -debug to have the
client's POV...
(I see you just replied again Yann, so I'll just send this as "history")
Not knowing much - how much of a hint is it that there are references to
SSLv3 (aka TLSv1.0) while the initial connection is TLSv1.2?
Do the SSL Library numbers indicate where to look?
*[Fri Jul 17 14:44:19.946820 2015] [ssl:error] [pid 503958:tid 772] SSL
Library Error: error:060C1064:digital envelope
routines:AEAD_CHACHA20_POLY1305_OPEN:bad decrypt -- wrong pass phrase!?
[Fri Jul 17 14:44:19.946873 2015] [ssl:error] [pid 503958:tid 772] SSL
Library Error: error:**1408F119:SSL routines:SSL3_GET_RECORD:decryption
failed or bad record mac
*
[Fri Jul 17 14:44:19.878583 2015] [ssl:trace3] [pid 503958:tid 772]
ssl_engine_kernel.c(1810): [client 127.0.0.1:51835] OpenSSL: Loop: SSLv3
flush data
[Fri Jul 17 14:44:19.878600 2015] [ssl:trace3] [pid 503958:tid 772]
ssl_engine_kernel.c(1805): [client 127.0.0.1:51835] OpenSSL: Handshake: done
[Fri Jul 17 14:44:19.878614 2015] [ssl:debug] [pid 503958:tid 772]
ssl_engine_kernel.c(1854): [client 127.0.0.1:51835] AH02041: Protocol:
TLSv1.2, Cipher: ECDHE-RSA-CHACHA20-POLY1305 (256/256 bits)
[Fri Jul 17 14:44:19.939060 2015] [ssl:trace4] [pid 503958:tid 772]
ssl_engine_io.c(2050): [client 127.0.0.1:51835] OpenSSL: read 5/5 bytes
from BIO#20085f68 [mem: 202967fb] (BIO dump follows)
[Fri Jul 17 14:44:19.939080 2015] [ssl:trace4] [pid 503958:tid 772]
ssl_engine_io.c(2050): [client 127.0.0.1:51835] OpenSSL: read 244/244
bytes from BIO#20085f68 [mem: 20296800] (BIO dump follows)
[Fri Jul 17 14:44:19.939098 2015] [core:trace5] [pid 503958:tid 772]
protocol.c(618): [client 127.0.0.1:51835] Request received from client:
POST /require-aes256-cgi/perl_echo.pl HTTP/1.1
[Fri Jul 17 14:44:19.939147 2015] [ssl:debug] [pid 503958:tid 772]
ssl_engine_kernel.c(244): [client 127.0.0.1:51835] AH02034: Initial
(No.1) HTTPS request received for child 1 (server loopback:8532)
[Fri Jul 17 14:44:19.939161 2015] [http:trace4] [pid 503958:tid 772]
http_request.c(322): [client 127.0.0.1:51835] Headers received from client:
[Fri Jul 17 14:44:19.939170 2015] [http:trace4] [pid 503958:tid 772]
http_request.c(326): [client 127.0.0.1:51835] TE: deflate,gzip;q=0.3
[Fri Jul 17 14:44:19.939177 2015] [http:trace4] [pid 503958:tid 772]
http_request.c(326): [client 127.0.0.1:51835] Connection: TE, close
[Fri Jul 17 14:44:19.939185 2015] [http:trace4] [pid 503958:tid 772]
http_request.c(326): [client 127.0.0.1:51835] Host: loopback:8532
[Fri Jul 17 14:44:19.939193 2015] [http:trace4] [pid 503958:tid 772]
http_request.c(326): [client 127.0.0.1:51835] User-Agent: libwww-perl/6.13
[Fri Jul 17 14:44:19.939201 2015] [http:trace4] [pid 503958:tid 772]
http_request.c(326): [client 127.0.0.1:51835] Content-Length: 11
[Fri Jul 17 14:44:19.939209 2015] [http:trace4] [pid 503958:tid 772]
http_request.c(326): [client 127.0.0.1:51835] Content-Type:
application/x-www-form-urlencoded
[Fri Jul 17 14:44:19.939268 2015] [core:trace4] [pid 503958:tid 772]
util_expr_eval.c(860): [client 127.0.0.1:51835] Evaluation of expression
from /data/prj/apache/httpd/test/t/conf/extra.conf:924 gave: 0
[Fri Jul 17 14:44:19.939413 2015] [core:trace4] [pid 503958:tid 772]
util_expr_eval.c(860): [client 127.0.0.1:51835] Evaluation of expression
from /data/prj/apache/httpd/test/t/conf/extra.conf:924 gave: 0
[Fri Jul 17 14:44:19.939471 2015] [ssl:debug] [pid 503958:tid 772]
ssl_engine_kernel.c(511): [client 127.0.0.1:51835] AH02220: Reconfigured
cipher suite will force renegotiation
[Fri Jul 17 14:44:19.939482 2015] [ssl:trace4] [pid 503958:tid 772]
ssl_engine_io.c(1692): [client 127.0.0.1:51835] filling buffer, max size
131072 bytes
[Fri Jul 17 14:44:19.939503 2015] [ssl:trace4] [pid 503958:tid 772]
ssl_engine_io.c(1745): [client 127.0.0.1:51835] total of 11 bytes in
buffer, eos=1
[Fri Jul 17 14:44:19.939514 2015] [ssl:info] [pid 503958:tid 772]
[client 127.0.0.1:51835] AH02221: Requesting connection re-negotiation
[Fri Jul 17 14:44:19.939528 2015] [ssl:trace4] [pid 503958:tid 772]
ssl_engine_io.c(2059): [client 127.0.0.1:51835] OpenSSL: I/O error, 5
bytes expected to read on BIO#20085f68 [mem: 202967fb]
[Fri Jul 17 14:44:19.939543 2015] [ssl:debug] [pid 503958:tid 772]
ssl_engine_kernel.c(802): [client 127.0.0.1:51835] AH02260: Performing
full renegotiation: complete handshake protocol (client does support
secure renegotiation)
[Fri Jul 17 14:44:19.939556 2015] [ssl:trace3] [pid 503958:tid 772]
ssl_engine_kernel.c(1801): [client 127.0.0.1:51835] OpenSSL: Handshake:
start
[Fri Jul 17 14:44:19.939589 2015] [ssl:trace3] [pid 503958:tid 772]
ssl_engine_kernel.c(1810): [client 127.0.0.1:51835] OpenSSL: Loop: SSL
renegotiate ciphers
[Fri Jul 17 14:44:19.939602 2015] [ssl:trace4] [pid 503958:tid 772]
ssl_engine_io.c(2050): [client 127.0.0.1:51835] OpenSSL: write 25/25
bytes to BIO#20085f18 [mem: 202a9cbb] (BIO dump follows)
[Fri Jul 17 14:44:19.939616 2015] [ssl:trace3] [pid 503958:tid 772]
ssl_engine_kernel.c(1810): [client 127.0.0.1:51835] OpenSSL: Loop: SSLv3
write hello request A
[Fri Jul 17 14:44:19.939642 2015] [ssl:trace3] [pid 503958:tid 772]
ssl_engine_kernel.c(1810): [client 127.0.0.1:51835] OpenSSL: Loop: SSLv3
flush data
[Fri Jul 17 14:44:19.939652 2015] [ssl:trace3] [pid 503958:tid 772]
ssl_engine_kernel.c(1810): [client 127.0.0.1:51835] OpenSSL: Loop: SSLv3
write hello request C
[Fri Jul 17 14:44:19.939664 2015] [ssl:info] [pid 503958:tid 772]
[client 127.0.0.1:51835] AH02226: Awaiting re-negotiation handshake
[Fri Jul 17 14:44:19.939673 2015] [ssl:trace3] [pid 503958:tid 772]
ssl_engine_kernel.c(1801): [client 127.0.0.1:51835] OpenSSL: Handshake:
start
[Fri Jul 17 14:44:19.939690 2015] [ssl:trace3] [pid 503958:tid 772]
ssl_engine_kernel.c(1810): [client 127.0.0.1:51835] OpenSSL: Loop:
before accept initialization
[Fri Jul 17 14:44:19.939790 2015] [ssl:trace4] [pid 503958:tid 772]
ssl_engine_io.c(2050): [client 127.0.0.1:51835] OpenSSL: read 5/5 bytes
from BIO#20085f68 [mem: 202a1b6b] (BIO dump follows)
[Fri Jul 17 14:44:19.939806 2015] [ssl:trace4] [pid 503958:tid 772]
ssl_engine_io.c(2050): [client 127.0.0.1:51835] OpenSSL: read 621/621
bytes from BIO#20085f68 [mem: 202a1b70] (BIO dump follows)
[Fri Jul 17 14:44:19.939850 2015] [ssl:debug] [pid 503958:tid 772]
ssl_engine_kernel.c(1921): [client 127.0.0.1:51835] AH02043: SSL virtual
host for servername loopback found
[Fri Jul 17 14:44:19.939871 2015] [ssl:trace3] [pid 503958:tid 772]
ssl_engine_kernel.c(1810): [client 127.0.0.1:51835] OpenSSL: Loop: SSLv3
read client hello A
[Fri Jul 17 14:44:19.939884 2015] [ssl:trace4] [pid 503958:tid 772]
ssl_engine_io.c(2050): [client 127.0.0.1:51835] OpenSSL: write 102/102
bytes to BIO#20086938 [mem: 202a9cbb] (BIO dump follows)
[Fri Jul 17 14:44:19.939895 2015] [ssl:trace3] [pid 503958:tid 772]
ssl_engine_kernel.c(1810): [client 127.0.0.1:51835] OpenSSL: Loop: SSLv3
write server hello A
[Fri Jul 17 14:44:19.940843 2015] [ssl:trace4] [pid 503958:tid 772]
ssl_engine_io.c(2050): [client 127.0.0.1:51835] OpenSSL: write 1395/1395
bytes to BIO#20086938 [mem: 202a1b6b] (BIO dump follows)
[Fri Jul 17 14:44:19.940867 2015] [ssl:trace3] [pid 503958:tid 772]
ssl_engine_kernel.c(1810): [client 127.0.0.1:51835] OpenSSL: Loop: SSLv3
write certificate A
[Fri Jul 17 14:44:19.940917 2015] [ssl:trace4] [pid 503958:tid 772]
ssl_engine_io.c(2050): [client 127.0.0.1:51835] OpenSSL: write 25/25
bytes to BIO#20086938 [mem: 202a1b6b] (BIO dump follows)
[Fri Jul 17 14:44:19.940930 2015] [ssl:trace3] [pid 503958:tid 772]
ssl_engine_kernel.c(1810): [client 127.0.0.1:51835] OpenSSL: Loop: SSLv3
write server done A
[Fri Jul 17 14:44:19.940940 2015] [ssl:trace4] [pid 503958:tid 772]
ssl_engine_io.c(2050): [client 127.0.0.1:51835] OpenSSL: write 1522/1522
bytes to BIO#20085f18 [mem: 20291408] (BIO dump follows)
[Fri Jul 17 14:44:19.940967 2015] [ssl:trace3] [pid 503958:tid 772]
ssl_engine_kernel.c(1810): [client 127.0.0.1:51835] OpenSSL: Loop: SSLv3
flush data
[Fri Jul 17 14:44:19.942076 2015] [ssl:trace4] [pid 503958:tid 772]
ssl_engine_io.c(2050): [client 127.0.0.1:51835] OpenSSL: read 5/5 bytes
from BIO#20085f68 [mem: 202a1b6b] (BIO dump follows)
[Fri Jul 17 14:44:19.942091 2015] [ssl:trace4] [pid 503958:tid 772]
ssl_engine_io.c(2050): [client 127.0.0.1:51835] OpenSSL: read 150/150
bytes from BIO#20085f68 [mem: 202a1b70] (BIO dump follows)
[Fri Jul 17 14:44:19.946512 2015] [ssl:trace3] [pid 503958:tid 772]
ssl_engine_kernel.c(1810): [client 127.0.0.1:51835] OpenSSL: Loop: SSLv3
read client key exchange A
[Fri Jul 17 14:44:19.946526 2015] [ssl:trace4] [pid 503958:tid 772]
ssl_engine_io.c(2050): [client 127.0.0.1:51835] OpenSSL: read 5/5 bytes
from BIO#20085f68 [mem: 202a1b6b] (BIO dump follows)
[Fri Jul 17 14:44:19.946537 2015] [ssl:trace4] [pid 503958:tid 772]
ssl_engine_io.c(2050): [client 127.0.0.1:51835] OpenSSL: read 17/17
bytes from BIO#20085f68 [mem: 202a1b70] (BIO dump follows)
[Fri Jul 17 14:44:19.946684 2015] [ssl:trace4] [pid 503958:tid 772]
ssl_engine_io.c(2050): [client 127.0.0.1:51835] OpenSSL: read 5/5 bytes
from BIO#20085f68 [mem: 202a1b6b] (BIO dump follows)
[Fri Jul 17 14:44:19.946697 2015] [ssl:trace4] [pid 503958:tid 772]
ssl_engine_io.c(2050): [client 127.0.0.1:51835] OpenSSL: read 68/68
bytes from BIO#20085f68 [mem: 202a1b70] (BIO dump follows)
[Fri Jul 17 14:44:19.946728 2015] [ssl:trace4] [pid 503958:tid 772]
ssl_engine_io.c(2050): [client 127.0.0.1:51835] OpenSSL: write 23/23
bytes to BIO#20086938 [mem: 202a9cbb] (BIO dump follows)
[Fri Jul 17 14:44:19.946739 2015] [ssl:trace4] [pid 503958:tid 772]
ssl_engine_io.c(2050): [client 127.0.0.1:51835] OpenSSL: write 23/23
bytes to BIO#20085f18 [mem: 20291408] (BIO dump follows)
[Fri Jul 17 14:44:19.946764 2015] [ssl:trace3] [pid 503958:tid 772]
ssl_engine_kernel.c(1820): [client 127.0.0.1:51835] OpenSSL: Write:
SSLv3 read certificate verify A
[Fri Jul 17 14:44:19.946775 2015] [ssl:trace3] [pid 503958:tid 772]
ssl_engine_kernel.c(1839): [client 127.0.0.1:51835] OpenSSL: Exit: error
in SSLv3 read certificate verify A
[Fri Jul 17 14:44:19.946783 2015] [ssl:error] [pid 503958:tid 772]
[client 127.0.0.1:51835] AH02261: Re-negotiation handshake failed
*[Fri Jul 17 14:44:19.946820 2015] [ssl:error] [pid 503958:tid 772] SSL
Library Error: error:060C1064:digital envelope
routines:AEAD_CHACHA20_POLY1305_OPEN:bad decrypt -- wrong pass phrase!?
[Fri Jul 17 14:44:19.946873 2015] [ssl:error] [pid 503958:tid 772] SSL
Library Error: error:**1408F119:SSL routines:SSL3_GET_RECORD:decryption
failed or bad record mac*
[Fri Jul 17 14:44:19.946886 2015] [core:trace3] [pid 503958:tid 772]
request.c(119): [client 127.0.0.1:51835] auth phase 'check access (with
Satisfy All)' gave status 403: /require-aes256-cgi/perl_echo.pl
[Fri Jul 17 14:44:19.946923 2015] [http:trace3] [pid 503958:tid 772]
http_filters.c(1006): [client 127.0.0.1:51835] Response sent with status
403, headers:
[Fri Jul 17 14:44:19.946933 2015] [http:trace5] [pid 503958:tid 772]
http_filters.c(1013): [client 127.0.0.1:51835] Date: Fri, 17 Jul 2015
14:44:19 GMT
[Fri Jul 17 14:44:19.946940 2015] [http:trace5] [pid 503958:tid 772]
http_filters.c(1016): [client 127.0.0.1:51835] Server: Apache/2.4.16
(Unix) LibreSSL/2.2.0
[Fri Jul 17 14:44:19.946949 2015] [http:trace4] [pid 503958:tid 772]
http_filters.c(835): [client 127.0.0.1:51835] Content-Length: 240
[Fri Jul 17 14:44:19.946990 2015] [http:trace4] [pid 503958:tid 772]
http_filters.c(835): [client 127.0.0.1:51835] Connection: close
[Fri Jul 17 14:44:19.947002 2015] [http:trace4] [pid 503958:tid 772]
http_filters.c(835): [client 127.0.0.1:51835] Content-Type: text/html;
charset=iso-8859-1
[Fri Jul 17 14:44:19.947012 2015] [ssl:trace4] [pid 503958:tid 772]
ssl_engine_io.c(1489): [client 127.0.0.1:51835] coalesce: have 0 bytes,
adding 193 more
[Fri Jul 17 14:44:19.947026 2015] [ssl:trace4] [pid 503958:tid 772]
ssl_engine_io.c(2050): [client 127.0.0.1:51835] OpenSSL: write 23/23
bytes to BIO#20086938 [mem: 202a9cbb] (BIO dump follows)
[Fri Jul 17 14:44:19.947037 2015] [ssl:trace4] [pid 503958:tid 772]
ssl_engine_io.c(2050): [client 127.0.0.1:51835] OpenSSL: write 23/23
bytes to BIO#20085f18 [mem: 20291408] (BIO dump follows)
[Fri Jul 17 14:44:19.947057 2015] [ssl:trace3] [pid 503958:tid 772]
ssl_engine_kernel.c(1820): [client 127.0.0.1:51835] OpenSSL: Write:
SSLv3 read finished A
[Fri Jul 17 14:44:19.947068 2015] [ssl:trace3] [pid 503958:tid 772]
ssl_engine_kernel.c(1839): [client 127.0.0.1:51835] OpenSSL: Exit: error
in SSLv3 read finished A
[Fri Jul 17 14:44:19.947081 2015] [ssl:info] [pid 503958:tid 772]
[client 127.0.0.1:51835] AH02008: SSL library error 1 in handshake
(server loopback:8532)
[Fri Jul 17 14:44:19.947127 2015] [ssl:info] [pid 503958:tid 772] SSL
Library Error: error:1408E0F4:SSL routines:SSL3_GET_MESSAGE:unexpected
message
[Fri Jul 17 14:44:19.947140 2015] [ssl:info] [pid 503958:tid 772]
[client 127.0.0.1:51835] AH01998: Connection closed to child 1 with
abortive shutdown (server loopback:8532)
[Fri Jul 17 14:44:19.951012 2015] [ssl:info] [pid 503958:tid 515]
[client 127.0.0.1:51836] AH01964: Connection to child 0 established
(server loopback:8532)
[Fri Jul 17 14:44:19.951030 2015] [ssl:trace2] [pid 503958:tid 515]
ssl_engine_rand.c(126): Seeding PRNG with 136 bytes of entropy
[Fri Jul 17 14:44:19.951073 2015] [ssl:trace3] [pid 503958:tid 515]
ssl_engine_kernel.c(1801): [client 127.0.0.1:51836] OpenSSL: Handshake:
start
