[openssl-project] update on sporadic test failures
Richard Levitte
levitte at openssl.org
Fri Jan 12 09:40:35 UTC 2018
In message <AM5PR0701MB2657A61AF60A41767572C316E4110 at AM5PR0701MB2657.eurprd07.prod.outlook.com> on Wed, 10 Jan 2018 21:06:43 +0000, Bernd Edlinger <bernd.edlinger at hotmail.de> said:
bernd.edlinger> this time I revert the patch again, and did this command:
bernd.edlinger>
bernd.edlinger> N=0; while make test TESTS=test_sslsigalgs V=1 >test$N.log; do
bernd.edlinger> N=$((N+1)); done; echo count=$N
bernd.edlinger> make[1]: *** [_tests] Error 1
bernd.edlinger> make: *** [tests] Fehler 2
bernd.edlinger> count=352
bernd.edlinger>
bernd.edlinger>
bernd.edlinger> interesting, it happens always after 310-360 iterations.
bernd.edlinger>
bernd.edlinger> attached the last good test and the failed test output.
So I've looked through the logs and played quite a bit with the proxy
code, and I'm thinking that we've found a point where... well I'm not
sure if this qualifies as a race condition, but it seems like we're
kind of cutting the proxy short a little now and then, possibly
because of events we don't check for, possibly because s_client
doesn't always flush...
But let's observe.
The first thing to observe is that we have an idea of a successful
communication, codified at the end of TLSProxy::Message::get_message()
(util/perl/TLSProxy/Message.pm, starting at line 258), that says that
if the proxy sees application data and if we have a session file,
which we selfom do, or if it sees a CloseNotify from the client, the
communication is a success.
With that established, we can have a look at the run of
70-test_sslsigalgs.t, more precisely test 6 "OSS only sigalgs in
TLSv1.3".
This is from test351.log, with commenting:
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
>>> Note the above, we're always sending 'test' as payload through the
>>> client side. It does show up further down
engine "ossltest" set.
Using default temp DH parameters
ACCEPT
engine "ossltest" set.
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 = 265
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: 1515617729
Timeout : 7200 (sec)
Verify return code: 21 (unable to verify the first certificate)
Extended master secret: no
---
DONE
Forwarded packet length = 65
Received client packet
Packet length = 51
Processing flight 3
Record 1 (client -> server)
Content type: APPLICATION DATA
Version: TLS1.2
Length: 22
Inner content type: APPLICATION DATA
[ENCRYPTED APPLICATION DATA]
[test
]
>>> ... and that was the payload showing up!
Record 2 (client -> server)
Content type: APPLICATION DATA
Version: TLS1.2
Length: 19
Inner content type: ALERT
>>> ... and that was the CloseNotify that triggers our success meter
Forwarded packet length = 53
Connection closed
Waiting for server process to close: 10198
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: RSA-PSS+SHA256
No peer certificate
Supported Elliptic Groups: X25519:P-256:P-521:P-384
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: 10199
ok 6 - PSS only sigalgs in TLSv1.3
--------------------
Now, let's have a look at the same test output from test352.log:
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.
Using default temp DH parameters
ACCEPT
engine "ossltest" set.
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 = 265
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
Forwarded packet length = 65
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
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: 1515617730
Timeout : 7200 (sec)
Verify return code: 21 (unable to verify the first certificate)
Extended master secret: no
---
Forwarded packet length = 225
DONE
Received client packet
Packet length = 27
Processing flight 4
Record 1 (client -> server)
Content type: APPLICATION DATA
Version: TLS1.2
Length: 22
Inner content type: APPLICATION DATA
[ENCRYPTED APPLICATION DATA]
[test
]
Forwarded packet length = 28
>>> Same payload comes through... but no CloseNotify alert!!!
Connection closed
Waiting for server process to close: 10698
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: RSA-PSS+SHA256
No peer certificate
Supported Elliptic Groups: X25519:P-256:P-521:P-384
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: 10699
not ok 6 - PSS only sigalgs in TLSv1.3
# Failed test 'PSS only sigalgs in TLSv1.3'
# at ../test/recipes/70-test_sslsigalgs.t line 93.
And voilà, no CloseNotify alert and application data is irrelevant
because we don't use a session file => no success.
So I'm not yet exactly sure what happens here and why s_client
sometimes seems to not send a CloseNotify.
I'm currently looking at s_client.c's do_ssl_shutdown() and libssl's
ssl3_shutdown() to try and figure out what's going on there, but if
someone else (Matt?) has some ideas that can shed a light on this,
that would be great.
Cheers,
Richard
--
Richard Levitte levitte at openssl.org
OpenSSL Project http://www.openssl.org/~levitte/
More information about the openssl-project
mailing list