httpd-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Michael Felt <mamf...@gmail.com>
Subject Re: Congradulations on the new release(s)
Date Thu, 16 Jul 2015 15:39:11 GMT
I really should have titled this differently - sigh!

On Thu, Jul 16, 2015 at 2:20 PM, Michael Felt <mamfelt@gmail.com> wrote:

> I am a bit behind - yet looking forward.
>
> 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!
>

Mime
View raw message