[openssl-project] update on sporadic test failures

Wed Jan 10 18:13:29 UTC 2018

I've been running 'make test' in a loop to try to reproduce the
sporadic failures that we've been seeing in the build farms.
Subjectively it seemed like it was easier to reproduce issues on
OpenSSL_1_1_0-stable than master, but I have seen "Dubious, test
returned 1 (wstat 256, 0x100)" on both.

My latest result is not of that form, though; rather, it's an
outright failure:

not ok 13 - Changed record version in TLS1.3

#   Failed test 'Changed record version in TLS1.3'
#   at ../test/recipes/70-test_sslrecords.t line 156.

I'll include the full V=1 output (starting from the end of the
previous subtest) below, in case it is enlightening.  (Needless to
say, this failure is not repeatable; I have only one occurrence in
O(50) runs.)

openssl is confiugred as:
./config --strict-warnings enable-tls1_3

and this is master as of commit
8e403a79b0e679c8df41a9686006c5fe052d79bd.

-Ben

ok 12 - Changed record version in TLS1.2
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 AES128-SHA:TLS13-AES-128-GCM-SHA256
Proxy started on port 4453
Client command: echo test | ../../util/shlib_wrap.sh ../../apps/openssl s_client -engine ossltest -connect localhost:4453
engine "ossltest" set.
engine "ossltest" set.
Using default temp DH parameters
ACCEPT
Connection opened
Received client packet
Packet length = 301
Processing flight 0
 Record 1 (client -> server)
  Content type: HANDSHAKE
  Version: TLS1.0
  Length: 296
  Message type: ClientHello
  Message Length: 292
    Client Version:771
    Session ID Len:32
    Ciphersuite len:62
    Compression Method Len:1
    Extensions Len:157

Forwarded packet length = 301

Received server packet
Packet length = 1543
Processing flight 1
 Record 1 (server -> client)
  Content type: HANDSHAKE
  Version: TLS1.2
  Length: 122
  Message type: ServerHello
  Message Length: 118
    Server Version:771
    Session ID Len:32
    Ciphersuite:4865
    Compression Method:0
    Extensions Len:46
 Record 2 (server -> client)
  Content type: CCS
  Version: TLS1.2
  Length: 1
 Record 3 (server -> client)
  Content type: APPLICATION DATA
  Version: TLS1.2
  Length: 23
  Inner content type: HANDSHAKE
  Message type: EncryptedExtensions
  Message Length: 2
    Extensions Len:0
 Record 4 (server -> client)
  Content type: APPLICATION DATA
  Version: TLS1.2
  Length: 1033
  Inner content type: HANDSHAKE
  Message type: Certificate
  Message Length: 1012
    Context:
    Certificate List Len:1008
    Certificate Len:1003
    Extensions Len:0
 Record 5 (server -> client)
  Content type: APPLICATION DATA
  Version: TLS1.2
  Length: 281
  Inner content type: HANDSHAKE
  Message type: CertificateVerify
  Message Length: 260
    SigAlg:2052
    Signature Len:256
 Record 6 (server -> client)
  Content type: APPLICATION DATA
  Version: TLS1.2
  Length: 53
  Inner content type: HANDSHAKE
  Message type: Finished
  Message Length: 32

Forwarded packet length = 1547

depth=0 C = UK, O = OpenSSL Group, OU = FOR TESTING PURPOSES ONLY, CN = Test Server Cert
verify error:num=20:unable to get local issuer certificate
verify return:1
depth=0 C = UK, O = OpenSSL Group, OU = FOR TESTING PURPOSES ONLY, CN = Test Server Cert
verify error:num=21:unable to verify the first certificate
verify return:1
Received client packet
Packet length = 64
Processing flight 2
 Record 1 (client -> server)
  Content type: CCS
  Version: TLS1.2
  Length: 1
 Record 2 (client -> server)
  Content type: APPLICATION DATA
  Version: TLS1.2
  Length: 53
  Inner content type: HANDSHAKE
  Message type: Finished
  Message Length: 32
CONNECTED(00000003)
---
Certificate chain
 0 s:C = UK, O = OpenSSL Group, OU = FOR TESTING PURPOSES ONLY, CN = Test Server Cert
   i:C = UK, O = OpenSSL Group, OU = FOR TESTING PURPOSES ONLY, CN = OpenSSL Test Intermediate CA
---
Server certificate
-----BEGIN CERTIFICATE-----
MIID5zCCAs+gAwIBAgIJALnu1NlVpZ6zMA0GCSqGSIb3DQEBBQUAMHAxCzAJBgNV
BAYTAlVLMRYwFAYDVQQKDA1PcGVuU1NMIEdyb3VwMSIwIAYDVQQLDBlGT1IgVEVT
VElORyBQVVJQT1NFUyBPTkxZMSUwIwYDVQQDDBxPcGVuU1NMIFRlc3QgSW50ZXJt
ZWRpYXRlIENBMB4XDTExMTIwODE0MDE0OFoXDTIxMTAxNjE0MDE0OFowZDELMAkG
A1UEBhMCVUsxFjAUBgNVBAoMDU9wZW5TU0wgR3JvdXAxIjAgBgNVBAsMGUZPUiBU
RVNUSU5HIFBVUlBPU0VTIE9OTFkxGTAXBgNVBAMMEFRlc3QgU2VydmVyIENlcnQw
ggEiMA0GCSqGSIb3DQEBAQUAA4IBDwAwggEKAoIBAQDzhPOSNtyyRspmeuUpxfNJ
KCLTuf7g3uQ4zu4iHOmRO5TQci+HhVlLZrHF9XqFXcIP0y4pWDbMSGuiorUmzmfi
R7bfSdI/+qIQt8KXRH6HNG1t8ou0VSvWId5TS5Dq/er5ODUr9OaaDva7EquHIcMv
vPQGuI+OEAcnleVCy9HVEIySrO4P3CNIicnGkwwiAud05yUAq/gPXBC1hTtmlPD7
TVcGVSEiJdvzqqlgv02qedGrkki6GY4S7GjZxrrf7Foc2EP+51LJzwLQx3/JfrCU
41NEWAsu/Sl0tQabXESN+zJ1pDqoZ3uHMgpQjeGiE0olr+YcsSW/tJmiU9OiAr8R
AgMBAAGjgY8wgYwwDAYDVR0TAQH/BAIwADAOBgNVHQ8BAf8EBAMCBeAwLAYJYIZI
AYb4QgENBB8WHU9wZW5TU0wgR2VuZXJhdGVkIENlcnRpZmljYXRlMB0GA1UdDgQW
BBSCvM8AABPR9zklmifnr9LvIBturDAfBgNVHSMEGDAWgBQ2w2yI55X+sL3szj49
hqshgYfa2jANBgkqhkiG9w0BAQUFAAOCAQEAqb1NV0B0/pbpK9Z4/bNjzPQLTRLK
WnSNm/Jh5v0GEUOE/Beg7GNjNrmeNmqxAlpqWz9qoeoFZax+QBpIZYjROU3TS3fp
yLsrnlr0CDQ5R7kCCDGa8dkXxemmpZZLbUCpW2Uoy8sAA4JjN9OtsZY7dvUXFgJ7
vVNTRnI01ghknbtD+2SxSQd3CWF6QhcRMAzZJ1z1cbbwGDDzfvGFPzJ+Sq+zEPds
xoVLLSetCiBc+40ZcDS5dV98h9XD7JMTQfxzA7mNGv73JoZJA6nFgj+ADSlJsY/t
JBv+z1iQRueoh9Qeee+ZbRifPouCB8FDx+AltvHTANdAq0t/K3o+pplMVA==
-----END CERTIFICATE-----
subject=C = UK, O = OpenSSL Group, OU = FOR TESTING PURPOSES ONLY, CN = Test Server Cert

issuer=C = UK, O = OpenSSL Group, OU = FOR TESTING PURPOSES ONLY, CN = OpenSSL Test Intermediate CA

---
No client certificate CA names sent
Peer signing digest: SHA256
Peer signature type: RSA-PSS
Server Temp Key: X25519, 253 bits
---
SSL handshake has read 1547 bytes and written 365 bytes
Verification error: unable to verify the first certificate
---
New, TLSv1.3, Cipher is TLS13-AES-128-GCM-SHA256
Server public key is 2048 bit
Secure Renegotiation IS NOT supported
Compression: NONE
Expansion: NONE
No ALPN negotiated
Early data was not sent
SSL-Session:
    Protocol  : TLSv1.3
    Cipher    : TLS13-AES-128-GCM-SHA256
    Session-ID: 
    Session-ID-ctx: 
    Master-Key: 000102030405060708090A0B0C0D0E0F101112131415161718191A1B1C1D1E1F
    PSK identity: None
    PSK identity hint: None
    SRP username: None
    Start Time: 1515606815
    Timeout   : 7200 (sec)
    Verify return code: 21 (unable to verify the first certificate)
    Extended master secret: no
---

DONE
Forwarded packet length = 65

CONNECTION ESTABLISHED
Protocol version: TLSv1.3
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:ECDHE-RSA-AES256-SHA:DHE-RSA-AES256-SHA:ECDHE-ECDSA-AES128-SHA:ECDHE-RSA-AES128-SHA:DHE-RSA-AES128-SHA:AES256-GCM-SHA384:AES128-GCM-SHA256:TLS13-AES-256-GCM-SHA384:TLS13-CHACHA20-POLY1305-SHA256:TLS13-AES-128-GCM-SHA256:AES256-SHA256:AES128-SHA256:AES256-SHA:AES128-SHA:TLS_EMPTY_RENEGOTIATION_INFO_SCSV
Ciphersuite: TLS13-AES-128-GCM-SHA256
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+SHA224:ECDSA+SHA1:RSA+SHA224:RSA+SHA1:DSA+SHA224:DSA+SHA1:DSA+SHA256:DSA+SHA384:DSA+SHA512
No peer certificate
Supported Elliptic Groups: X25519:P-256:P-521:P-384
Received server packet
Packet length = 224
Processing flight 3
 Record 1 (server -> client)
  Content type: APPLICATION DATA
  Version: TLS1.2
  Length: 219
  Inner content type: HANDSHAKE
  Message type: NewSessionTicket
  Message Length: 198

Forwarded packet length = 225

Connection closed
Waiting for server process to close: 31948
CONNECTION CLOSED
   1 items in the session cache
   0 client connects (SSL_connect())
   0 client renegotiates (SSL_connect())
   0 client connects that finished
   1 server accepts (SSL_accept())
   0 server renegotiates (SSL_accept())
   1 server accepts that finished
   0 session cache hits
   0 session cache misses
   0 session cache timeouts
   0 callback cache hits
   0 cache full overflows (128 allowed)
Waiting for client process to close: 31949
not ok 13 - Changed record version in TLS1.3

#   Failed test 'Changed record version in TLS1.3'
#   at ../test/recipes/70-test_sslrecords.t line 156.