I really should have titled this differently - sigh! On Thu, Jul 16, 2015 at 2:20 PM, Michael Felt <[email protected]> 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! >
