Moving this to a thread with a better title!
A longish read - basically while 2.4.12 had few errors when built
against OpenSSL 0.9.8 LibreSSL has quite a few errors - perhaps because
it has removed many "unsafe" crypto combinations. The root question is:
is this LibreSSL misbehaving, or are the tests needing some work to
verify that "weak ciphers and key exchanges are not being used - e.g.,
via renegotiation.
+++
I wish to recall a pleasant get together last April in Texas just before
ApacheCon. At that time I mentioned LibreSSL and building httpd against it
(actually mod_ssl is all it amounts to).
The build itself was quite simple - I shall repeat that now for 2.4.16 and
trunk - and send the 'patch' in.
While build is simple - understanding the differences in test output is
daunting.
Here I have the output of just one test t/ssl/pr12355.t - and note the
differences in the ssl_access_log - not just the error messages (I have
removed all "debug" messages from the logs as they were "in the way".
LibreSSL is version 2.2.0, OpenSSL is version 0.9.8m (yes I know very old,
will test with latest patches later - I hope not relevant to here).
So, please note: LibreSSL says access is:
t/logs/ssl_request_log:[16/Jul/2015:11:47:12 +0000] 127.0.0.1 - - "POST
/require-sha-cgi/perl_echo.pl HTTP/1.1" 403 237
while OpenSSL says
t/logs/ssl_request_log:[16/Jul/2015:11:32:35 +0000] 127.0.0.1 TLSv1 RC4-SHA
"POST /require-sha-cgi/perl_echo.pl HTTP/1.1" 200 11
My question: what can I do to understand why OpenSSL is adding TLSv1
RC4-SHA while LibreSSL is "- -"
Note also in the
==> LibreSSL_pr12355.t.results<==
t/logs/error_log:[Thu Jul 16 11:47:12.425257 2015] [ssl:info] [pid
389322:tid 515] [client 127.0.0.1:48676] AH01964: Connection to child 0
established (server loopback:8532)
t/logs/error_log:[Thu Jul 16 11:47:12.613855 2015] [ssl:info] [pid
389322:tid 515] [client 127.0.0.1:48676] AH02221: Requesting connection
re-negotiation
t/logs/error_log:[Thu Jul 16 11:47:12.614004 2015] [ssl:info] [pid
389322:tid 515] [client 127.0.0.1:48676] AH02226: Awaiting re-negotiation
handshake
t/logs/error_log:[Thu Jul 16 11:47:12.620757 2015] [ssl:error] [pid
389322:tid 515] [client 127.0.0.1:48676] AH02261: Re-negotiation handshake
failed: Not accepted by client!?
t/logs/error_log:[Thu Jul 16 11:47:12.620803 2015] [ssl:info] [pid
389322:tid 515] [client 127.0.0.1:48676] AH02008: SSL library error 1 in
handshake (server loopback:8532)
t/logs/error_log:[Thu Jul 16 11:47:12.620825 2015] [ssl:info] [pid
389322:tid 515] SSL Library Error: error:1408E0F4:SSL
routines:SSL3_GET_MESSAGE:unexpected message
t/logs/error_log:[Thu Jul 16 11:47:12.620837 2015] [ssl:info] [pid
389322:tid 515] [client 127.0.0.1:48676] AH01998: Connection closed to
child 0 with abortive shutdown (server loopback:8532)
t/logs/error_log:[Thu Jul 16 11:47:17.073812 2015] [core:warn] [pid
344086:tid 1] AH00045: child process 389322 still did not exit, sending a
SIGTERM
t/logs/error_log:[Thu Jul 16 11:47:19.076308 2015] [core:info] [pid
344086:tid 1] AH00096: removed PID file
/data/prj/apache/httpd/test/t/logs/httpd.pid (pid=344086)
t/logs/error_log:[Thu Jul 16 11:47:19.076349 2015] [mpm_worker:notice] [pid
344086:tid 1] AH00295: caught SIGTERM, shutting down
t/logs/ssl_request_log:[16/Jul/2015:11:47:10 +0000] 127.0.0.1 - - "GET
/index.html HTTP/1.1" 200 26
t/logs/ssl_request_log:[16/Jul/2015:11:47:12 +0000] 127.0.0.1 - - "POST
/require-sha-cgi/perl_echo.pl HTTP/1.1" 403 237
t/logs/ssl_request_log:[16/Jul/2015:11:47:12 +0000] 127.0.0.1 - - "POST
/require-md5-cgi/perl_echo.pl HTTP/1.1" 403 237
t/logs/ssl_request_log:[16/Jul/2015:11:47:12 +0000] 127.0.0.1 - - "POST
/require-sha-cgi/perl_echo.pl HTTP/1.1" 403 237
t/logs/ssl_request_log:[16/Jul/2015:11:47:12 +0000] 127.0.0.1 - - "POST
/require-md5-cgi/perl_echo.pl HTTP/1.1" 403 237
==> OpenSSL_pr12355.t.results<==
t/logs/error_log:[Thu Jul 16 11:32:35.380665 2015] [ssl:info] [pid
417826:tid 515] [client 127.0.0.1:39151] AH02226: Awaiting re-negotiation
handshake
t/logs/error_log:[Thu Jul 16 11:32:35.423630 2015] [ssl:info] [pid
417826:tid 772] [client 127.0.0.1:39152] AH01964: Connection to child 1
established (server loopback:8532)
t/logs/error_log:[Thu Jul 16 11:32:35.571262 2015] [ssl:info] [pid
417826:tid 772] [client 127.0.0.1:39152] AH02221: Requesting connection
re-negotiation
t/logs/error_log:[Thu Jul 16 11:32:35.571354 2015] [ssl:info] [pid
417826:tid 772] [client 127.0.0.1:39152] AH02226: Awaiting re-negotiation
handshake
t/logs/error_log:[Thu Jul 16 11:32:35.613858 2015] [ssl:info] [pid
417826:tid 515] [client 127.0.0.1:39153] AH01964: Connection to child 0
established (server loopback:8532)
t/logs/error_log:[Thu Jul 16 11:32:35.771440 2015] [ssl:info] [pid
417826:tid 515] [client 127.0.0.1:39153] AH02221: Requesting connection
re-negotiation
t/logs/error_log:[Thu Jul 16 11:32:35.771533 2015] [ssl:info] [pid
417826:tid 515] [client 127.0.0.1:39153] AH02226: Awaiting re-negotiation
handshake
t/logs/error_log:[Thu Jul 16 11:32:40.284682 2015] [core:warn] [pid
385024:tid 1] AH00045: child process 417826 still did not exit, sending a
SIGTERM
t/logs/error_log:[Thu Jul 16 11:32:42.287551 2015] [core:info] [pid
385024:tid 1] AH00096: removed PID file
/data/prj/apache/httpd/test/t/logs/httpd.pid (pid=385024)
t/logs/error_log:[Thu Jul 16 11:32:42.287591 2015] [mpm_worker:notice] [pid
385024:tid 1] AH00295: caught SIGTERM, shutting down
t/logs/ssl_request_log:[16/Jul/2015:11:32:34 +0000] 127.0.0.1 - - "GET
/index.html HTTP/1.1" 200 26
t/logs/ssl_request_log:[16/Jul/2015:11:32:35 +0000] 127.0.0.1 TLSv1 RC4-SHA
"POST /require-sha-cgi/perl_echo.pl HTTP/1.1" 200 11
t/logs/ssl_request_log:[16/Jul/2015:11:32:35 +0000] 127.0.0.1 TLSv1 RC4-MD5
"POST /require-md5-cgi/perl_echo.pl HTTP/1.1" 200 11
t/logs/ssl_request_log:[16/Jul/2015:11:32:35 +0000] 127.0.0.1 TLSv1 RC4-SHA
"POST /require-sha-cgi/perl_echo.pl HTTP/1.1" 200 10000
t/logs/ssl_request_log:[16/Jul/2015:11:32:35 +0000] 127.0.0.1 TLSv1 RC4-MD5
"POST /require-md5-cgi/perl_echo.pl HTTP/1.1" 200 60000
One test in LibreSSL (first one) from test:
[Thu Jul 16 11:47:10.755088 2015] [authz_core:debug] [pid 389322:tid 515]
mod_authz_core.c(835): [client 127.0.0.1:48672] AH01628: authorization
result: granted (no directives)
[Thu Jul 16 11:47:10.755164 2015] [charset_lite:debug] [pid 389322:tid 515]
mod_charset_lite.c(219): [client 127.0.0.1:48672] AH01448: incomplete
configuration: src unspecified, dst unspe
cified
[Thu Jul 16 11:47:11.863488 2015] [ssl:info] [pid 389322:tid 772] [client
127.0.0.1:48673] AH01964: Connection to child 1 established (server
loopback:8532)
[Thu Jul 16 11:47:11.864018 2015] [ssl:debug] [pid 389322:tid 772]
ssl_engine_kernel.c(1908): [client 127.0.0.1:48673] AH02043: SSL virtual
host for servername loopback found
[Thu Jul 16 11:47:11.982116 2015] [ssl:debug] [pid 389322:tid 772]
ssl_engine_kernel.c(1841): [client 127.0.0.1:48673] AH02041: Protocol:
TLSv1.2, Cipher: ECDHE-RSA-CHACHA20-POLY1305 (256
/256 bits)
[Thu Jul 16 11:47:12.044850 2015] [ssl:debug] [pid 389322:tid 772]
ssl_engine_kernel.c(243): [client 127.0.0.1:48673] AH02034: Initial (No.1)
HTTPS request received for child 1 (server lo
opback:8532)
[Thu Jul 16 11:47:12.045068 2015] [ssl:debug] [pid 389322:tid 772]
ssl_engine_kernel.c(500): [client 127.0.0.1:48673] AH02220: Reconfigured
cipher suite will force renegotiation
[Thu Jul 16 11:47:12.045093 2015] [ssl:info] [pid 389322:tid 772] [client
127.0.0.1:48673] AH02221: Requesting connection re-negotiation
[Thu Jul 16 11:47:12.045113 2015] [ssl:debug] [pid 389322:tid 772]
ssl_engine_kernel.c(791): [client 127.0.0.1:48673] AH02260: Performing full
renegotiation: complete handshake protocol (
client does support secure renegotiation)
[Thu Jul 16 11:47:12.045174 2015] [ssl:info] [pid 389322:tid 772] [client
127.0.0.1:48673] AH02226: Awaiting re-negotiation handshake
[Thu Jul 16 11:47:12.045340 2015] [ssl:debug] [pid 389322:tid 772]
ssl_engine_kernel.c(1908): [client 127.0.0.1:48673] AH02043: SSL virtual
host for servername loopback found
[Thu Jul 16 11:47:12.051994 2015] [ssl:error] [pid 389322:tid 772] [client
127.0.0.1:48673] AH02261: Re-negotiation handshake failed: Not accepted by
client!?
[Thu Jul 16 11:47:12.052072 2015] [ssl:info] [pid 389322:tid 772] [client
127.0.0.1:48673] AH02008: SSL library error 1 in handshake (server
loopback:8532)
[Thu Jul 16 11:47:12.052157 2015] [ssl:info] [pid 389322:tid 772] SSL
Library Error: error:1408E0F4:SSL routines:SSL3_GET_MESSAGE:unexpected
message
[Thu Jul 16 11:47:12.052172 2015] [ssl:info] [pid 389322:tid 772] [client
127.0.0.1:48673] AH01998: Connection closed to child 1 with abortive
shutdown (server loopback:8532)
First test with OpenSSL
[Thu Jul 16 12:10:47.979101 2015] [ssl:info] [pid 385024:tid 515] [client
127.0.0.1:39154] AH01964: Connection to child 0 established (server
loopback:8532)
[Thu Jul 16 12:10:47.979609 2015] [ssl:debug] [pid 385024:tid 515]
ssl_engine_kernel.c(1936): [client 127.0.0.1:39154] AH02645: Server name
not provided via TLS extension (using default/first virtua
l host)
[Thu Jul 16 12:10:48.043295 2015] [ssl:debug] [pid 385024:tid 515]
ssl_engine_kernel.c(1841): [client 127.0.0.1:39154] AH02041: Protocol:
TLSv1, Cipher: DHE-RSA-AES256-SHA (256/256 bits)
[Thu Jul 16 12:10:48.107123 2015] [mpm_worker:error] [pid 467080:tid 1]
AH00287: server is within MinSpareThreads of MaxRequestWorkers, consider
raising the MaxRequestWorkers setting
[Thu Jul 16 12:10:48.107283 2015] [ssl:debug] [pid 385024:tid 515]
ssl_engine_kernel.c(243): [client 127.0.0.1:39154] AH02034: Initial (No.1)
HTTPS request received for child 0 (server loopback:8532
)
[Thu Jul 16 12:10:48.107746 2015] [ssl:debug] [pid 385024:tid 515]
ssl_engine_kernel.c(500): [client 127.0.0.1:39154] AH02220: Reconfigured
cipher suite will force renegotiation
[Thu Jul 16 12:10:48.107774 2015] [ssl:info] [pid 385024:tid 515] [client
127.0.0.1:39154] AH02221: Requesting connection re-negotiation
[Thu Jul 16 12:10:48.107795 2015] [ssl:debug] [pid 385024:tid 515]
ssl_engine_kernel.c(791): [client 127.0.0.1:39154] AH02260: Performing full
renegotiation: complete handshake protocol (client does
support secure renegotiation)
[Thu Jul 16 12:10:48.107868 2015] [ssl:info] [pid 385024:tid 515] [client
127.0.0.1:39154] AH02226: Awaiting re-negotiation handshake
[Thu Jul 16 12:10:48.108182 2015] [ssl:debug] [pid 385024:tid 515]
ssl_engine_kernel.c(1936): [client 127.0.0.1:39154] AH02645: Server name
not provided via TLS extension (using default/first virtua
l host)
[Thu Jul 16 12:10:48.114668 2015] [ssl:debug] [pid 385024:tid 515]
ssl_engine_kernel.c(1841): [client 127.0.0.1:39154] AH02041: Protocol:
TLSv1, Cipher: RC4-SHA (128/128 bits)
[Thu Jul 16 12:10:48.114708 2015] [authz_core:debug] [pid 385024:tid 515]
mod_authz_core.c(835): [client 127.0.0.1:39154] AH01628: authorization
result: granted (no directives)
[Thu Jul 16 12:10:48.114772 2015] [charset_lite:debug] [pid 385024:tid 515]
mod_charset_lite.c(219): [client 127.0.0.1:39154] AH01448: incomplete
configuration: src unspecified, dst unspecified
[Thu Jul 16 12:10:48.151528 2015] [ssl:debug] [pid 385024:tid 515]
ssl_engine_io.c(1003): [client 127.0.0.1:39154] AH02001: Connection closed
to child 0 with standard shutdown (server loopback:8532)
*Observation*: I am guessing the test is failing because the renegotiation
is failing because it is downgrading to "(near) export quality" - which
many recent CVE are reporting as "very bad".
Maybe, this fail is a false "FAIL" - that 0.9.8 will always PASS because
that is what 0.9.8 does.
*Last question*: IF you think this failure is because the renegotiation is
requesting something is bad - *then it would seem the server is responding
as it should* - and the test needs correction. Otherwise - some help with
moving forward is appreciated!
