[openssl-project] update on sporadic test failures

Wed Jan 10 19:33:54 UTC 2018

On Wed, Jan 10, 2018 at 12:13:29PM -0600, Benjamin Kaduk wrote:
> 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.

And I managed to capture one of these, too.

%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%

ok 7 - No matching TLSv1.3 sigalgs
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
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.
Connection opened
engine "ossltest" set.
Using default temp DH parameters
ACCEPT
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 = 1406
Processing flight 1
 Record 1 (server -> client)
  Content type: HANDSHAKE
  Version: TLS1.2
  Length: 69
  Message type: ServerHello
  Message Length: 65
    Server Version:771
    Session ID Len:0
    Ciphersuite:49171
    Compression Method:0
    Extensions Len:25
 Record 2 (server -> client)
  Content type: HANDSHAKE
  Version: TLS1.2
  Length: 1013
  Message type: Certificate
  Message Length: 1009
    Certificate List Len:1006
    Certificate Len:1003
 Record 3 (server -> client)
  Content type: HANDSHAKE
  Version: TLS1.2
  Length: 300
  Message type: ServerKeyExchange
  Message Length: 296
 Record 4 (server -> client)
  Content type: HANDSHAKE
  Version: TLS1.2
  Length: 4
  Message type: ServerHelloDone
  Message Length: 0

Forwarded packet length = 1406

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 = 121
Processing flight 2
 Record 1 (client -> server)
  Content type: HANDSHAKE
  Version: TLS1.2
  Length: 37
  Message type: ClientKeyExchange
  Message Length: 33
 Record 2 (client -> server)
  Content type: CCS
  Version: TLS1.2
  Length: 1
 Record 3 (client -> server)
  Content type: HANDSHAKE
  Version: TLS1.2
  Length: 68
  Message type: Finished
  Message Length: 12

Forwarded packet length = 121

CONNECTION ESTABLISHED
Protocol version: TLSv1.2
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
ECDHE-RSA-AES256-SHA:DHE-RSA-AES256-SHA:Packet length = 270
ECDHE-ECDSA-AES128-SHA:ECDHE-RSA-AES128-SHA:DHE-RSA-AES128-SHA:AES256-GCM-SHA384Processing flight 3
: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)
:AES128-SHA:TLS_EMPTY_RENEGOTIATION_INFO_SCSV
Ciphersuite: ECDHE-RSA-AES128-SHA
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
+SHA224:ECDSA  Version: TLS1.2
+SHA1:RSA  Length: 186+SHA224:RSA
+SHA1:DSA+SHA224:DSA+SHA1:DSA+SHA256:DSA+SHA384:DSA+SHA512
No peer certificate
Supported Elliptic Curve Point Formats: uncompressed:ansiX962_compressed_prime:ansiX962_compressed_char2
Supported Elliptic Groups: X25519:P-256:P-521:P-384
  Message type: NewSessionTicket
  Message Length: 182
 Record 2 (server -> client)
  Content type: CCS
  Version: TLS1.2
  Length: 1
 Record 3 (server -> client)
  Content type: HANDSHAKE
  Version: TLS1.2
  Length: 68
  Message type: Finished
  Message Length: 12

Forwarded packet length = 270

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 1676 bytes and written 422 bytes
Verification error: unable to verify the first certificate
---
New, TLSv1.0, Cipher is ECDHE-RSA-AES128-SHA
Server public key is 2048 bit
Secure Renegotiation IS supported
Compression: NONE
Expansion: NONE
No ALPN negotiated
SSL-Session:
    Protocol  : TLSv1.2
    Cipher    : ECDHE-RSA-AES128-SHA
    Session-ID: 000102030405060708090A0B0C0D0E0F101112131415161718191A1B1C1D1E1F
    Session-ID-ctx: 
    Master-Key: 000102030405060708090A0B0C0D0E0F101112131415161718191A1B1C1D1E1F000102030405060708090A0B0C0D0E0F
    PSK identity: None
    PSK identity hint: None
    SRP username: None
    TLS session ticket lifetime hint: 7200 (seconds)
    TLS session ticket:
    0000 - 01 02 03 04 05 06 07 08-09 0a 0b 0c 0d 0e 0f 10   ................
    0010 - 01 02 03 04 05 06 07 08-09 0a 0b 0c 0d 0e 0f 10   ................
    0020 - 82 48 f7 82 0f 7f 21 bf-f4 19 28 80 63 9f da 52   .H....!...(.c..R
    0030 - 3a 16 a9 85 de 2f 41 96-90 4d f7 f1 b1 11 b8 63   :..../A..M.....c
    0040 - 2d c5 62 f7 e3 da be 90-aa 50 3c 9b e7 ad 41 35   -.b......P<...A5
    0050 - c7 76 8d 18 a6 f7 9a 73-6b 25 4a 90 c7 ca 70 ef   .v.....sk%J...p.
    0060 - 94 de be 7d e8 88 9f 16-57 c3 c6 c5 6c 94 dd c6   ...}....W...l...
    0070 - 18 77 1e ff 26 30 ba 51-f2 dd 37 2e f1 b3 df 0a   .w..&0.Q..7.....
    0080 - 02 db 47 a9 ad eb 1a f0-5d 5e d0 a8 85 ee d0 d2   ..G.....]^......
    0090 - 00 01 02 03 04 05 06 07-08 09 0a 0b 0c 0d 0e 0f   ................
    00a0 - 10 11 12 13 14 15 16 17-18 19 1a 1b 1c 1d 1e 1f   ................

    Start Time: 1515610433
    Timeout   : 7200 (sec)
    Verify return code: 21 (unable to verify the first certificate)
    Extended master secret: yes
---
DONE
Received client packet
Packet length = 57
Processing flight 4
 Record 1 (client -> server)
  Content type: APPLICATION DATA
  Version: TLS1.2
  Length: 52
  [ENCRYPTED APPLICATION DATA]
  [test
]

Forwarded packet length = 57

Received server packet
Packet length = 57
Processing flight 5
 Record 1 (server -> client)
  Content type: APPLICATION DATA
  Version: TLS1.2
  Length: 52
  [ENCRYPTED APPLICATION DATA]
  [tset
]

Forwarded packet length = 57

Connection closed
Waiting for server process to close: 26085
CONNECTION CLOSED
   0 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
   1 session cache misses
   0 session cache timeouts
   0 callback cache hits
   0 cache full overflows (128 allowed)
Waiting for client process to close: 26086
not ok 8 - TLSv1.3 client TLSv1.2 server

#   Failed test 'TLSv1.3 client TLSv1.2 server'
#   at ../test/recipes/70-test_sslsigalgs.t line 119.

%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%

In the pass-ing test, the last forwarded packet is client->server of
type ALERT (but is still length 57 including record header).

-Ben