[openssl-project] update on sporadic test failures

Richard Levitte levitte at openssl.org
Wed Jan 10 20:06:33 UTC 2018


In message <20180110193354.GK72574 at kduck.kaduk.org> on Wed, 10 Jan 2018 13:33:54 -0600, Benjamin Kaduk <kaduk at mit.edu> said:

kaduk> On Wed, Jan 10, 2018 at 12:13:29PM -0600, Benjamin Kaduk wrote:
kaduk> > I've been running 'make test' in a loop to try to reproduce the
kaduk> > sporadic failures that we've been seeing in the build farms.
kaduk> > Subjectively it seemed like it was easier to reproduce issues on
kaduk> > OpenSSL_1_1_0-stable than master, but I have seen "Dubious, test
kaduk> > returned 1 (wstat 256, 0x100)" on both.
kaduk> 
kaduk> And I managed to capture one of these, too.
kaduk> 
kaduk> %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%
kaduk> 
kaduk> ok 7 - No matching TLSv1.3 sigalgs
kaduk> Server command: ../../util/shlib_wrap.sh ../../apps/openssl s_server -no_comp -rev -engine ossltest -accept 4443 -cert ../../apps/server.pem -cert2 ../../apps/server.pem -naccept 1 -cipher ECDHE-RSA-AES128-SHA:TLS13-AES-128-GCM-SHA256 -no_tls1_3
kaduk> Proxy started on port 4453
kaduk> Client command: echo test | ../../util/shlib_wrap.sh ../../apps/openssl s_client -engine ossltest -connect localhost:4453
kaduk> engine "ossltest" set.
kaduk> Connection opened
kaduk> engine "ossltest" set.
kaduk> Using default temp DH parameters
kaduk> ACCEPT
kaduk> Received client packet
kaduk> Packet length = 301
kaduk> Processing flight 0
kaduk>  Record 1 (client -> server)
kaduk>   Content type: HANDSHAKE
kaduk>   Version: TLS1.0
kaduk>   Length: 296
kaduk>   Message type: ClientHello
kaduk>   Message Length: 292
kaduk>     Client Version:771
kaduk>     Session ID Len:32
kaduk>     Ciphersuite len:62
kaduk>     Compression Method Len:1
kaduk>     Extensions Len:157
kaduk> 
kaduk> Forwarded packet length = 301
kaduk> 
kaduk> Received server packet
kaduk> Packet length = 1406
kaduk> Processing flight 1
kaduk>  Record 1 (server -> client)
kaduk>   Content type: HANDSHAKE
kaduk>   Version: TLS1.2
kaduk>   Length: 69
kaduk>   Message type: ServerHello
kaduk>   Message Length: 65
kaduk>     Server Version:771
kaduk>     Session ID Len:0
kaduk>     Ciphersuite:49171
kaduk>     Compression Method:0
kaduk>     Extensions Len:25
kaduk>  Record 2 (server -> client)
kaduk>   Content type: HANDSHAKE
kaduk>   Version: TLS1.2
kaduk>   Length: 1013
kaduk>   Message type: Certificate
kaduk>   Message Length: 1009
kaduk>     Certificate List Len:1006
kaduk>     Certificate Len:1003
kaduk>  Record 3 (server -> client)
kaduk>   Content type: HANDSHAKE
kaduk>   Version: TLS1.2
kaduk>   Length: 300
kaduk>   Message type: ServerKeyExchange
kaduk>   Message Length: 296
kaduk>  Record 4 (server -> client)
kaduk>   Content type: HANDSHAKE
kaduk>   Version: TLS1.2
kaduk>   Length: 4
kaduk>   Message type: ServerHelloDone
kaduk>   Message Length: 0
kaduk> 
kaduk> Forwarded packet length = 1406
kaduk> 
kaduk> depth=0 C = UK, O = OpenSSL Group, OU = FOR TESTING PURPOSES ONLY, CN = Test Server Cert
kaduk> verify error:num=20:unable to get local issuer certificate
kaduk> verify return:1
kaduk> depth=0 C = UK, O = OpenSSL Group, OU = FOR TESTING PURPOSES ONLY, CN = Test Server Cert
kaduk> verify error:num=21:unable to verify the first certificate
kaduk> verify return:1
kaduk> Received client packet
kaduk> Packet length = 121
kaduk> Processing flight 2
kaduk>  Record 1 (client -> server)
kaduk>   Content type: HANDSHAKE
kaduk>   Version: TLS1.2
kaduk>   Length: 37
kaduk>   Message type: ClientKeyExchange
kaduk>   Message Length: 33
kaduk>  Record 2 (client -> server)
kaduk>   Content type: CCS
kaduk>   Version: TLS1.2
kaduk>   Length: 1
kaduk>  Record 3 (client -> server)
kaduk>   Content type: HANDSHAKE
kaduk>   Version: TLS1.2
kaduk>   Length: 68
kaduk>   Message type: Finished
kaduk>   Message Length: 12
kaduk> 
kaduk> Forwarded packet length = 121
kaduk> 
kaduk> CONNECTION ESTABLISHED
kaduk> Protocol version: TLSv1.2
kaduk> Client cipher list: ECDHE-ECDSA-AES256-GCM-SHA384:ECDHE-RSA-AES256-GCM-SHA384:DHE-RSA-AES256-GCM-SHA384:ECDHE-ECDSA-CHACHA20-POLY1305:ECDHE-RSA-CHACHA20-POLY1305:DHE-RSA-CHACHA20-POLY1305:ECDHE-ECDSA-AES128-GCM-SHA256:ECDHE-RSA-AES128-GCM-SHA256:DHE-RSA-AES128-GCM-SHA256:ECDHE-ECDSA-AES256-SHA384:ECDHE-RSA-AES256-SHA384:DHE-RSA-AES256-SHA256:ECDHE-ECDSA-AES128-SHA256:ECDHE-RSA-AES128-SHA256:DHE-RSA-AES128-SHA256:ECDHE-ECDSA-AES256-SHA:Received server packet
kaduk> ECDHE-RSA-AES256-SHA:DHE-RSA-AES256-SHA:Packet length = 270
kaduk> ECDHE-ECDSA-AES128-SHA:ECDHE-RSA-AES128-SHA:DHE-RSA-AES128-SHA:AES256-GCM-SHA384Processing flight 3
kaduk> :AES128-GCM-SHA256:TLS13-AES-256-GCM-SHA384:TLS13-CHACHA20-POLY1305-SHA256:TLS13-AES-128-GCM-SHA256:AES256-SHA256:AES128-SHA256 Record 1:AES256-SHA (server -> client)
kaduk> :AES128-SHA:TLS_EMPTY_RENEGOTIATION_INFO_SCSV
kaduk> Ciphersuite: ECDHE-RSA-AES128-SHA
kaduk> Signature Algorithms: ECDSA+SHA256:ECDSA+SHA384:ECDSA+SHA512:Ed25519:RSA-PSS+SHA256:RSA-PSS+SHA384:RSA-PSS+SHA512:RSA+SHA256:RSA+SHA384:RSA+SHA512:ECDSA  Content type: HANDSHAKE
kaduk> +SHA224:ECDSA  Version: TLS1.2
kaduk> +SHA1:RSA  Length: 186+SHA224:RSA
kaduk> +SHA1:DSA+SHA224:DSA+SHA1:DSA+SHA256:DSA+SHA384:DSA+SHA512
kaduk> No peer certificate
kaduk> Supported Elliptic Curve Point Formats: uncompressed:ansiX962_compressed_prime:ansiX962_compressed_char2
kaduk> Supported Elliptic Groups: X25519:P-256:P-521:P-384
kaduk>   Message type: NewSessionTicket
kaduk>   Message Length: 182
kaduk>  Record 2 (server -> client)
kaduk>   Content type: CCS
kaduk>   Version: TLS1.2
kaduk>   Length: 1
kaduk>  Record 3 (server -> client)
kaduk>   Content type: HANDSHAKE
kaduk>   Version: TLS1.2
kaduk>   Length: 68
kaduk>   Message type: Finished
kaduk>   Message Length: 12
kaduk> 
kaduk> Forwarded packet length = 270
kaduk> 
kaduk> CONNECTED(00000003)
kaduk> ---
kaduk> Certificate chain
kaduk>  0 s:C = UK, O = OpenSSL Group, OU = FOR TESTING PURPOSES ONLY, CN = Test Server Cert
kaduk>    i:C = UK, O = OpenSSL Group, OU = FOR TESTING PURPOSES ONLY, CN = OpenSSL Test Intermediate CA
kaduk> ---
kaduk> Server certificate
kaduk> -----BEGIN CERTIFICATE-----
kaduk> MIID5zCCAs+gAwIBAgIJALnu1NlVpZ6zMA0GCSqGSIb3DQEBBQUAMHAxCzAJBgNV
kaduk> BAYTAlVLMRYwFAYDVQQKDA1PcGVuU1NMIEdyb3VwMSIwIAYDVQQLDBlGT1IgVEVT
kaduk> VElORyBQVVJQT1NFUyBPTkxZMSUwIwYDVQQDDBxPcGVuU1NMIFRlc3QgSW50ZXJt
kaduk> ZWRpYXRlIENBMB4XDTExMTIwODE0MDE0OFoXDTIxMTAxNjE0MDE0OFowZDELMAkG
kaduk> A1UEBhMCVUsxFjAUBgNVBAoMDU9wZW5TU0wgR3JvdXAxIjAgBgNVBAsMGUZPUiBU
kaduk> RVNUSU5HIFBVUlBPU0VTIE9OTFkxGTAXBgNVBAMMEFRlc3QgU2VydmVyIENlcnQw
kaduk> ggEiMA0GCSqGSIb3DQEBAQUAA4IBDwAwggEKAoIBAQDzhPOSNtyyRspmeuUpxfNJ
kaduk> KCLTuf7g3uQ4zu4iHOmRO5TQci+HhVlLZrHF9XqFXcIP0y4pWDbMSGuiorUmzmfi
kaduk> R7bfSdI/+qIQt8KXRH6HNG1t8ou0VSvWId5TS5Dq/er5ODUr9OaaDva7EquHIcMv
kaduk> vPQGuI+OEAcnleVCy9HVEIySrO4P3CNIicnGkwwiAud05yUAq/gPXBC1hTtmlPD7
kaduk> TVcGVSEiJdvzqqlgv02qedGrkki6GY4S7GjZxrrf7Foc2EP+51LJzwLQx3/JfrCU
kaduk> 41NEWAsu/Sl0tQabXESN+zJ1pDqoZ3uHMgpQjeGiE0olr+YcsSW/tJmiU9OiAr8R
kaduk> AgMBAAGjgY8wgYwwDAYDVR0TAQH/BAIwADAOBgNVHQ8BAf8EBAMCBeAwLAYJYIZI
kaduk> AYb4QgENBB8WHU9wZW5TU0wgR2VuZXJhdGVkIENlcnRpZmljYXRlMB0GA1UdDgQW
kaduk> BBSCvM8AABPR9zklmifnr9LvIBturDAfBgNVHSMEGDAWgBQ2w2yI55X+sL3szj49
kaduk> hqshgYfa2jANBgkqhkiG9w0BAQUFAAOCAQEAqb1NV0B0/pbpK9Z4/bNjzPQLTRLK
kaduk> WnSNm/Jh5v0GEUOE/Beg7GNjNrmeNmqxAlpqWz9qoeoFZax+QBpIZYjROU3TS3fp
kaduk> yLsrnlr0CDQ5R7kCCDGa8dkXxemmpZZLbUCpW2Uoy8sAA4JjN9OtsZY7dvUXFgJ7
kaduk> vVNTRnI01ghknbtD+2SxSQd3CWF6QhcRMAzZJ1z1cbbwGDDzfvGFPzJ+Sq+zEPds
kaduk> xoVLLSetCiBc+40ZcDS5dV98h9XD7JMTQfxzA7mNGv73JoZJA6nFgj+ADSlJsY/t
kaduk> JBv+z1iQRueoh9Qeee+ZbRifPouCB8FDx+AltvHTANdAq0t/K3o+pplMVA==
kaduk> -----END CERTIFICATE-----
kaduk> subject=C = UK, O = OpenSSL Group, OU = FOR TESTING PURPOSES ONLY, CN = Test Server Cert
kaduk> 
kaduk> issuer=C = UK, O = OpenSSL Group, OU = FOR TESTING PURPOSES ONLY, CN = OpenSSL Test Intermediate CA
kaduk> 
kaduk> ---
kaduk> No client certificate CA names sent
kaduk> Peer signing digest: SHA256
kaduk> Peer signature type: RSA-PSS
kaduk> Server Temp Key: X25519, 253 bits
kaduk> ---
kaduk> SSL handshake has read 1676 bytes and written 422 bytes
kaduk> Verification error: unable to verify the first certificate
kaduk> ---
kaduk> New, TLSv1.0, Cipher is ECDHE-RSA-AES128-SHA
kaduk> Server public key is 2048 bit
kaduk> Secure Renegotiation IS supported
kaduk> Compression: NONE
kaduk> Expansion: NONE
kaduk> No ALPN negotiated
kaduk> SSL-Session:
kaduk>     Protocol  : TLSv1.2
kaduk>     Cipher    : ECDHE-RSA-AES128-SHA
kaduk>     Session-ID: 000102030405060708090A0B0C0D0E0F101112131415161718191A1B1C1D1E1F
kaduk>     Session-ID-ctx: 
kaduk>     Master-Key: 000102030405060708090A0B0C0D0E0F101112131415161718191A1B1C1D1E1F000102030405060708090A0B0C0D0E0F
kaduk>     PSK identity: None
kaduk>     PSK identity hint: None
kaduk>     SRP username: None
kaduk>     TLS session ticket lifetime hint: 7200 (seconds)
kaduk>     TLS session ticket:
kaduk>     0000 - 01 02 03 04 05 06 07 08-09 0a 0b 0c 0d 0e 0f 10   ................
kaduk>     0010 - 01 02 03 04 05 06 07 08-09 0a 0b 0c 0d 0e 0f 10   ................
kaduk>     0020 - 82 48 f7 82 0f 7f 21 bf-f4 19 28 80 63 9f da 52   .H....!...(.c..R
kaduk>     0030 - 3a 16 a9 85 de 2f 41 96-90 4d f7 f1 b1 11 b8 63   :..../A..M.....c
kaduk>     0040 - 2d c5 62 f7 e3 da be 90-aa 50 3c 9b e7 ad 41 35   -.b......P<...A5
kaduk>     0050 - c7 76 8d 18 a6 f7 9a 73-6b 25 4a 90 c7 ca 70 ef   .v.....sk%J...p.
kaduk>     0060 - 94 de be 7d e8 88 9f 16-57 c3 c6 c5 6c 94 dd c6   ...}....W...l...
kaduk>     0070 - 18 77 1e ff 26 30 ba 51-f2 dd 37 2e f1 b3 df 0a   .w..&0.Q..7.....
kaduk>     0080 - 02 db 47 a9 ad eb 1a f0-5d 5e d0 a8 85 ee d0 d2   ..G.....]^......
kaduk>     0090 - 00 01 02 03 04 05 06 07-08 09 0a 0b 0c 0d 0e 0f   ................
kaduk>     00a0 - 10 11 12 13 14 15 16 17-18 19 1a 1b 1c 1d 1e 1f   ................
kaduk> 
kaduk>     Start Time: 1515610433
kaduk>     Timeout   : 7200 (sec)
kaduk>     Verify return code: 21 (unable to verify the first certificate)
kaduk>     Extended master secret: yes
kaduk> ---
kaduk> DONE
kaduk> Received client packet
kaduk> Packet length = 57
kaduk> Processing flight 4
kaduk>  Record 1 (client -> server)
kaduk>   Content type: APPLICATION DATA
kaduk>   Version: TLS1.2
kaduk>   Length: 52
kaduk>   [ENCRYPTED APPLICATION DATA]
kaduk>   [test
kaduk> ]
kaduk> 
kaduk> Forwarded packet length = 57
kaduk> 
kaduk> Received server packet
kaduk> Packet length = 57
kaduk> Processing flight 5
kaduk>  Record 1 (server -> client)
kaduk>   Content type: APPLICATION DATA
kaduk>   Version: TLS1.2
kaduk>   Length: 52
kaduk>   [ENCRYPTED APPLICATION DATA]
kaduk>   [tset
kaduk> ]
kaduk> 
kaduk> Forwarded packet length = 57
kaduk> 
kaduk> Connection closed
kaduk> Waiting for server process to close: 26085
kaduk> CONNECTION CLOSED
kaduk>    0 items in the session cache
kaduk>    0 client connects (SSL_connect())
kaduk>    0 client renegotiates (SSL_connect())
kaduk>    0 client connects that finished
kaduk>    1 server accepts (SSL_accept())
kaduk>    0 server renegotiates (SSL_accept())
kaduk>    1 server accepts that finished
kaduk>    0 session cache hits
kaduk>    1 session cache misses
kaduk>    0 session cache timeouts
kaduk>    0 callback cache hits
kaduk>    0 cache full overflows (128 allowed)
kaduk> Waiting for client process to close: 26086
kaduk> not ok 8 - TLSv1.3 client TLSv1.2 server
kaduk> 
kaduk> #   Failed test 'TLSv1.3 client TLSv1.2 server'
kaduk> #   at ../test/recipes/70-test_sslsigalgs.t line 119.
kaduk> 
kaduk> %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%
kaduk> 
kaduk> In the pass-ing test, the last forwarded packet is client->server of
kaduk> type ALERT (but is still length 57 including record header).

Does this ever happen in non-verbose mode?

Does this patch make a difference?

diff --git a/util/perl/TLSProxy/Proxy.pm b/util/perl/TLSProxy/Proxy.pm
index 99b0dedd5b..9330ec2844 100644
--- a/util/perl/TLSProxy/Proxy.pm
+++ b/util/perl/TLSProxy/Proxy.pm
@@ -300,6 +302,7 @@ sub clientstart
             && $ctr < 10) {
         if (!(@ready = $sel->can_read(1))) {
             $ctr++;
+            usleep(100000);     # .1 s sleep, totalling 1 s of attempted reads
             next;
         }
         foreach my $hand (@ready) {


More information about the openssl-project mailing list