[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