[openssl-project] update on sporadic test failures
Benjamin Kaduk
kaduk at mit.edu
Wed Jan 10 20:12:05 UTC 2018
On Wed, Jan 10, 2018 at 09:06:33PM +0100, Richard Levitte wrote:
> 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
Looking at the 'git diff --no-index --color-words' output between
the passing and failing case, there is a lot of output inteleaving
going on, so it's hard to tell what is "real" and what is artifact.
But I will note that the "ACCEPT" line comes before "Connection
opened" in the passing case, and after in the failing case. Could
we somehow be talking to a proxy/server that was left over from the
previous test? (I assume not, but have to mention the possibility.)
> 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?
What is "this"? I have gotten the "Dubious" test failures in both
verbose and 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) {
I will give it a shot, but seeing how unreliable my reproducer is,
it's hard to say that it will give much confidence of anything.
-Ben
More information about the openssl-project
mailing list