Open bernd-edlinger opened 2 years ago
paulidale
commented
2 years ago Does make test TESTS=test_sslapi V=1 OPENSSL_TEST_RAND_ORDER=1652172508 reproduce this?
If so, it's a test ordering problem which likely means something isn't cleaning up properly.
bernd-edlinger
commented
2 years ago Oh, that's funny. today it reproduces every time. Your proposed test order or without always FAIL:
$ make test TESTS=test_sslapi V=1 OPENSSL_TEST_RAND_ORDER=1652172508
make depend && make _tests
make[1]: Entering directory '/home/ed/OPCToolboxV5/Source/Core/OpenSSL/openssl'
make[1]: Leaving directory '/home/ed/OPCToolboxV5/Source/Core/OpenSSL/openssl'
make[1]: Entering directory '/home/ed/OPCToolboxV5/Source/Core/OpenSSL/openssl'
( SRCTOP=. \
BLDTOP=. \
PERL="/usr/bin/perl" \
FIPSKEY="f4556650ac31d35461610bac4ed81b1a181b2d8a43ea2854cbae22ca74560813" \
EXE_EXT= \
/usr/bin/perl ./test/run_tests.pl test_sslapi )
00-prep_fipsmodule_cnf.t ..
# The results of this test will end up in test-runs/prep_fipsmodule
1..0 # SKIP FIPS module config file only supported in a fips build
skipped: FIPS module config file only supported in a fips build
Files=1, Tests=0, 0 wallclock secs ( 0.01 usr 0.01 sys + 0.16 cusr 0.01 csys = 0.19 CPU)
Result: NOTESTS
90-test_sslapi.t ..
# The results of this test will end up in test-runs/test_sslapi
1..1
# Subtest: ../../test/sslapitest
1..84
ok 1 - test_set_verify_cert_store_ssl
# Subtest: test_dh_auto
1..7
ok 1 - iteration 5
ok 2 - iteration 3
ok 3 - iteration 1
ok 4 - iteration 6
ok 5 - iteration 4
ok 6 - iteration 2
ok 7 - iteration 7
ok 2 - test_dh_auto
# INFO: @ test/helpers/ssltestlib.c:975
# SSL_accept() failed -1, 1
# 80329382B97F0000:error:0A0000BF:SSL routines:tls_setup_handshake:no protocols available:ssl/statem/statem_lib.c:104:
# INFO: @ test/helpers/ssltestlib.c:957
# SSL_connect() failed -1, 1
# 80329382B97F0000:error:0A00042E:SSL routines:ssl3_read_bytes:tlsv1 alert protocol version:ssl/record/rec_layer_s3.c:1584:SSL alert number 70
# INFO: @ test/helpers/ssltestlib.c:975
# SSL_accept() failed -1, 1
# 80329382B97F0000:error:0A0000BF:SSL routines:tls_setup_handshake:no protocols available:ssl/statem/statem_lib.c:104:
# INFO: @ test/helpers/ssltestlib.c:957
# SSL_connect() failed -1, 1
# 80329382B97F0000:error:0A00042E:SSL routines:ssl3_read_bytes:tlsv1 alert protocol version:ssl/record/rec_layer_s3.c:1584:SSL alert number 70
ok 3 - test_session_wo_ca_names
# Subtest: test_ssl_pending
1..2
ok 8 - iteration 1
ok 9 - iteration 2
ok 4 - test_ssl_pending
# Subtest: test_set_sigalgs
1..28
ok 10 - iteration 13
ok 11 - iteration 26
ok 12 - iteration 11
ok 13 - iteration 24
ok 14 - iteration 9
ok 15 - iteration 22
ok 16 - iteration 7
# INFO: @ test/helpers/ssltestlib.c:975
# SSL_accept() failed -1, 1
# 80329382B97F0000:error:0A0000C1:SSL routines:tls_post_process_client_hello:no shared cipher:ssl/statem/statem_srvr.c:2220:
# INFO: @ test/helpers/ssltestlib.c:957
# SSL_connect() failed -1, 1
# 80329382B97F0000:error:0A000410:SSL routines:ssl3_read_bytes:ssl/tls alert handshake failure:ssl/record/rec_layer_s3.c:1584:SSL alert number 40
ok 17 - iteration 20
ok 18 - iteration 5
ok 19 - iteration 18
# INFO: @ test/helpers/ssltestlib.c:975
# SSL_accept() failed -1, 1
# 80329382B97F0000:error:0A0000C1:SSL routines:tls_post_process_client_hello:no shared cipher:ssl/statem/statem_srvr.c:2220:
# INFO: @ test/helpers/ssltestlib.c:957
# SSL_connect() failed -1, 1
# 80329382B97F0000:error:0A000410:SSL routines:ssl3_read_bytes:ssl/tls alert handshake failure:ssl/record/rec_layer_s3.c:1584:SSL alert number 40
ok 20 - iteration 3
ok 21 - iteration 16
ok 22 - iteration 1
ok 23 - iteration 14
ok 24 - iteration 27
ok 25 - iteration 12
ok 26 - iteration 25
ok 27 - iteration 10
ok 28 - iteration 23
ok 29 - iteration 8
ok 30 - iteration 21
# INFO: @ test/helpers/ssltestlib.c:975
# SSL_accept() failed -1, 1
# 80329382B97F0000:error:0A0000C1:SSL routines:tls_post_process_client_hello:no shared cipher:ssl/statem/statem_srvr.c:2220:
# INFO: @ test/helpers/ssltestlib.c:957
# SSL_connect() failed -1, 1
# 80329382B97F0000:error:0A000410:SSL routines:ssl3_read_bytes:ssl/tls alert handshake failure:ssl/record/rec_layer_s3.c:1584:SSL alert number 40
ok 31 - iteration 6
ok 32 - iteration 19
ok 33 - iteration 4
# INFO: @ test/helpers/ssltestlib.c:975
# SSL_accept() failed -1, 1
# 80329382B97F0000:error:0A0000C1:SSL routines:tls_post_process_client_hello:no shared cipher:ssl/statem/statem_srvr.c:2220:
# INFO: @ test/helpers/ssltestlib.c:957
# SSL_connect() failed -1, 1
# 80329382B97F0000:error:0A000410:SSL routines:ssl3_read_bytes:ssl/tls alert handshake failure:ssl/record/rec_layer_s3.c:1584:SSL alert number 40
ok 34 - iteration 17
ok 35 - iteration 2
ok 36 - iteration 15
ok 37 - iteration 28
ok 5 - test_set_sigalgs
ok 6 - test_inherit_verify_param
ok 7 - test_keylog
# INFO: @ test/helpers/ssltestlib.c:975
# SSL_accept() failed -1, 1
# 80329382B97F0000:error:0A0000BF:SSL routines:tls_setup_handshake:no protocols available:ssl/statem/statem_lib.c:104:
# INFO: @ test/helpers/ssltestlib.c:957
# SSL_connect() failed -1, 1
# 80329382B97F0000:error:0A00042E:SSL routines:ssl3_read_bytes:tlsv1 alert protocol version:ssl/record/rec_layer_s3.c:1584:SSL alert number 70
# INFO: @ test/helpers/ssltestlib.c:975
# SSL_accept() failed -1, 1
# 80329382B97F0000:error:0A0000BF:SSL routines:tls_setup_handshake:no protocols available:ssl/statem/statem_lib.c:104:
# INFO: @ test/helpers/ssltestlib.c:957
# SSL_connect() failed -1, 1
# 80329382B97F0000:error:0A00042E:SSL routines:ssl3_read_bytes:tlsv1 alert protocol version:ssl/record/rec_layer_s3.c:1584:SSL alert number 70
ok 8 - test_session_with_only_ext_cache
# Subtest: test_ktls
1..24
ok 38 - iteration 13
ok 39 - iteration 2
# ERROR: (bool) 'ping_pong_query(clientssl, serverssl) == true' failed @ test/sslapitest.c:1271
# false
# 80329382B97F0000:error:0A000119:SSL routines:ssl3_get_record:decryption failed or bad record mac:ssl/record/ssl3_record.c:224:
# 80329382B97F0000:error:0A000197:SSL routines:SSL_shutdown:shutdown while in init:ssl/ssl_lib.c:2245:
# OPENSSL_TEST_RAND_ORDER=1652172508
not ok 40 - iteration 15
ok 41 - iteration 4
ok 42 - iteration 17
ok 43 - iteration 6
# SKIP: @ test/sslapitest.c:1265
# KTLS not supported for TLS 1.3 cipher TLS_AES_128_CCM_SHA256
ok 44 - iteration 19 # skipped
ok 45 - iteration 8
ok 46 - iteration 21
ok 47 - iteration 10
# ERROR: (bool) 'ping_pong_query(clientssl, serverssl) == true' failed @ test/sslapitest.c:1271
# false
# 80329382B97F0000:error:0A000119:SSL routines:ssl3_get_record:decryption failed or bad record mac:ssl/record/ssl3_record.c:224:
# 80329382B97F0000:error:0A000197:SSL routines:SSL_shutdown:shutdown while in init:ssl/ssl_lib.c:2245:
# OPENSSL_TEST_RAND_ORDER=1652172508
not ok 48 - iteration 23
ok 49 - iteration 12
ok 50 - iteration 1
# ERROR: (bool) 'ping_pong_query(clientssl, serverssl) == true' failed @ test/sslapitest.c:1271
# false
# 80329382B97F0000:error:0A000119:SSL routines:ssl3_get_record:decryption failed or bad record mac:ssl/record/ssl3_record.c:224:
# 80329382B97F0000:error:0A000197:SSL routines:SSL_shutdown:shutdown while in init:ssl/ssl_lib.c:2245:
# OPENSSL_TEST_RAND_ORDER=1652172508
not ok 51 - iteration 14
ok 52 - iteration 3
# ERROR: (bool) 'ping_pong_query(clientssl, serverssl) == true' failed @ test/sslapitest.c:1271
# false
# 80329382B97F0000:error:0A000119:SSL routines:ssl3_get_record:decryption failed or bad record mac:ssl/record/ssl3_record.c:224:
# 80329382B97F0000:error:0A000197:SSL routines:SSL_shutdown:shutdown while in init:ssl/ssl_lib.c:2245:
# OPENSSL_TEST_RAND_ORDER=1652172508
not ok 53 - iteration 16
ok 54 - iteration 5
# SKIP: @ test/sslapitest.c:1265
# KTLS not supported for TLS 1.3 cipher TLS_AES_128_CCM_SHA256
ok 55 - iteration 18 # skipped
ok 56 - iteration 7
# SKIP: @ test/sslapitest.c:1265
# KTLS not supported for TLS 1.3 cipher TLS_AES_128_CCM_SHA256
ok 57 - iteration 20 # skipped
ok 58 - iteration 9
# ERROR: (bool) 'ping_pong_query(clientssl, serverssl) == true' failed @ test/sslapitest.c:1271
# false
# 80329382B97F0000:error:0A000119:SSL routines:ssl3_get_record:decryption failed or bad record mac:ssl/record/ssl3_record.c:224:
# 80329382B97F0000:error:0A000197:SSL routines:SSL_shutdown:shutdown while in init:ssl/ssl_lib.c:2245:
# OPENSSL_TEST_RAND_ORDER=1652172508
not ok 59 - iteration 22
ok 60 - iteration 11
# ERROR: (bool) 'ping_pong_query(clientssl, serverssl) == true' failed @ test/sslapitest.c:1271
# false
# 80329382B97F0000:error:0A000119:SSL routines:ssl3_get_record:decryption failed or bad record mac:ssl/record/ssl3_record.c:224:
# 80329382B97F0000:error:0A000197:SSL routines:SSL_shutdown:shutdown while in init:ssl/ssl_lib.c:2245:
# OPENSSL_TEST_RAND_ORDER=1652172508
not ok 61 - iteration 24
# OPENSSL_TEST_RAND_ORDER=1652172508
not ok 9 - test_ktls
# Subtest: test_serverinfo
1..8
ok 62 - iteration 5
ok 63 - iteration 2
ok 64 - iteration 7
ok 65 - iteration 4
ok 66 - iteration 1
ok 67 - iteration 6
ok 68 - iteration 3
ok 69 - iteration 8
ok 10 - test_serverinfo
# Subtest: test_tls13_ciphersuite
1..4
ok 70 - iteration 3
ok 71 - iteration 2
ok 72 - iteration 1
ok 73 - iteration 4
ok 11 - test_tls13_ciphersuite
# Subtest: test_ca_names
1..3
ok 74 - iteration 1
ok 75 - iteration 2
ok 76 - iteration 3
ok 12 - test_ca_names
# Subtest: test_early_data_read_write
1..3
ok 77 - iteration 2
ok 78 - iteration 1
ok 79 - iteration 3
ok 13 - test_early_data_read_write
ok 14 - test_pha_key_update
ok 15 - test_large_message_dtls
# Subtest: test_negotiated_group
1..40
ok 80 - iteration 3
ok 81 - iteration 6
ok 82 - iteration 9
ok 83 - iteration 12
ok 84 - iteration 15
ok 85 - iteration 18
ok 86 - iteration 21
ok 87 - iteration 24
ok 88 - iteration 27
ok 89 - iteration 30
ok 90 - iteration 33
ok 91 - iteration 36
ok 92 - iteration 39
ok 93 - iteration 2
ok 94 - iteration 5
ok 95 - iteration 8
ok 96 - iteration 11
ok 97 - iteration 14
ok 98 - iteration 17
ok 99 - iteration 20
ok 100 - iteration 23
ok 101 - iteration 26
ok 102 - iteration 29
ok 103 - iteration 32
ok 104 - iteration 35
ok 105 - iteration 38
ok 106 - iteration 1
ok 107 - iteration 4
ok 108 - iteration 7
ok 109 - iteration 10
ok 110 - iteration 13
ok 111 - iteration 16
ok 112 - iteration 19
ok 113 - iteration 22
ok 114 - iteration 25
ok 115 - iteration 28
ok 116 - iteration 31
ok 117 - iteration 34
ok 118 - iteration 37
ok 119 - iteration 40
ok 16 - test_negotiated_group
# Subtest: test_ssl_set_bio
1..89
ok 120 - iteration 25
ok 121 - iteration 50
ok 122 - iteration 75
ok 123 - iteration 11
ok 124 - iteration 36
ok 125 - iteration 61
# INFO: @ test/helpers/ssltestlib.c:975
# SSL_accept() failed -1, 1
# 80329382B97F0000:error:0A000102:SSL routines:tls_early_post_process_client_hello:unsupported protocol:ssl/statem/statem_srvr.c:1657:
# INFO: @ test/helpers/ssltestlib.c:957
# SSL_connect() failed -1, 1
# 80329382B97F0000:error:0A00042E:SSL routines:ssl3_read_bytes:tlsv1 alert protocol version:ssl/record/rec_layer_s3.c:1584:SSL alert number 70
ok 126 - iteration 86
ok 127 - iteration 22
ok 128 - iteration 47
ok 129 - iteration 72
ok 130 - iteration 8
ok 131 - iteration 33
ok 132 - iteration 58
ok 133 - iteration 83
ok 134 - iteration 19
ok 135 - iteration 44
ok 136 - iteration 69
ok 137 - iteration 5
ok 138 - iteration 30
ok 139 - iteration 55
ok 140 - iteration 80
ok 141 - iteration 16
ok 142 - iteration 41
ok 143 - iteration 66
ok 144 - iteration 2
ok 145 - iteration 27
ok 146 - iteration 52
ok 147 - iteration 77
ok 148 - iteration 13
ok 149 - iteration 38
ok 150 - iteration 63
# INFO: @ test/helpers/ssltestlib.c:975
# SSL_accept() failed -1, 1
# 80329382B97F0000:error:0A000102:SSL routines:tls_early_post_process_client_hello:unsupported protocol:ssl/statem/statem_srvr.c:1657:
# INFO: @ test/helpers/ssltestlib.c:957
# SSL_connect() failed -1, 1
# 80329382B97F0000:error:0A00042E:SSL routines:ssl3_read_bytes:tlsv1 alert protocol version:ssl/record/rec_layer_s3.c:1584:SSL alert number 70
ok 151 - iteration 88
ok 152 - iteration 24
ok 153 - iteration 49
ok 154 - iteration 74
ok 155 - iteration 10
ok 156 - iteration 35
ok 157 - iteration 60
ok 158 - iteration 85
ok 159 - iteration 21
ok 160 - iteration 46
ok 161 - iteration 71
ok 162 - iteration 7
ok 163 - iteration 32
ok 164 - iteration 57
ok 165 - iteration 82
ok 166 - iteration 18
ok 167 - iteration 43
ok 168 - iteration 68
ok 169 - iteration 4
ok 170 - iteration 29
ok 171 - iteration 54
ok 172 - iteration 79
ok 173 - iteration 15
ok 174 - iteration 40
ok 175 - iteration 65
ok 176 - iteration 1
ok 177 - iteration 26
ok 178 - iteration 51
ok 179 - iteration 76
ok 180 - iteration 12
ok 181 - iteration 37
ok 182 - iteration 62
# INFO: @ test/helpers/ssltestlib.c:975
# SSL_accept() failed -1, 1
# 80329382B97F0000:error:0A000102:SSL routines:tls_early_post_process_client_hello:unsupported protocol:ssl/statem/statem_srvr.c:1657:
# INFO: @ test/helpers/ssltestlib.c:957
# SSL_connect() failed -1, 1
# 80329382B97F0000:error:0A00042E:SSL routines:ssl3_read_bytes:tlsv1 alert protocol version:ssl/record/rec_layer_s3.c:1584:SSL alert number 70
ok 183 - iteration 87
ok 184 - iteration 23
ok 185 - iteration 48
ok 186 - iteration 73
ok 187 - iteration 9
ok 188 - iteration 34
ok 189 - iteration 59
ok 190 - iteration 84
ok 191 - iteration 20
ok 192 - iteration 45
ok 193 - iteration 70
ok 194 - iteration 6
ok 195 - iteration 31
ok 196 - iteration 56
ok 197 - iteration 81
ok 198 - iteration 17
ok 199 - iteration 42
ok 200 - iteration 67
ok 201 - iteration 3
ok 202 - iteration 28
ok 203 - iteration 53
ok 204 - iteration 78
ok 205 - iteration 14
ok 206 - iteration 39
ok 207 - iteration 64
# INFO: @ test/helpers/ssltestlib.c:975
# SSL_accept() failed -1, 1
# 80329382B97F0000:error:0A000102:SSL routines:tls_early_post_process_client_hello:unsupported protocol:ssl/statem/statem_srvr.c:1657:
# INFO: @ test/helpers/ssltestlib.c:957
# SSL_connect() failed -1, 1
# 80329382B97F0000:error:0A00042E:SSL routines:ssl3_read_bytes:tlsv1 alert protocol version:ssl/record/rec_layer_s3.c:1584:SSL alert number 70
ok 208 - iteration 89
ok 17 - test_ssl_set_bio
ok 18 - test_ssl_bio_change_rbio
# Subtest: test_ticket_lifetime
1..2
ok 209 - iteration 1
ok 210 - iteration 2
ok 19 - test_ticket_lifetime
ok 20 - test_cleanse_plaintext
# Subtest: test_early_data_skip_abort
1..3
ok 211 - iteration 1
ok 212 - iteration 2
ok 213 - iteration 3
ok 21 - test_early_data_skip_abort
# Subtest: test_client_cert_cb
1..2
ok 214 - iteration 1
ok 215 - iteration 2
ok 22 - test_client_cert_cb
# Subtest: test_ticket_callbacks
1..16
ok 216 - iteration 7
ok 217 - iteration 14
ok 218 - iteration 5
ok 219 - iteration 12
ok 220 - iteration 3
ok 221 - iteration 10
ok 222 - iteration 1
ok 223 - iteration 8
ok 224 - iteration 15
ok 225 - iteration 6
ok 226 - iteration 13
ok 227 - iteration 4
ok 228 - iteration 11
ok 229 - iteration 2
ok 230 - iteration 9
ok 231 - iteration 16
ok 23 - test_ticket_callbacks
ok 24 - test_ccs_change_cipher
# Subtest: test_key_update_local_in_read
1..2
ok 232 - iteration 1
ok 233 - iteration 2
ok 25 - test_key_update_local_in_read
ok 26 - test_ssl_dup
# Subtest: test_session_timeout
1..1
ok 234 - iteration 1
ok 27 - test_session_timeout
# INFO: @ test/helpers/ssltestlib.c:975
# SSL_accept() failed -1, 1
# 80329382B97F0000:error:0A0000E2:SSL routines:tls_handle_status_request:clienthello tlsext:ssl/statem/statem_srvr.c:2095:
# INFO: @ test/helpers/ssltestlib.c:957
# SSL_connect() failed -1, 1
# 80329382B97F0000:error:0A000438:SSL routines:ssl3_read_bytes:tlsv1 alert internal error:ssl/record/rec_layer_s3.c:1584:SSL alert number 80
ok 28 - test_tlsext_status_type
# Subtest: test_export_key_mat_early
1..3
ok 235 - iteration 1
ok 236 - iteration 2
ok 237 - iteration 3
ok 29 - test_export_key_mat_early
# Subtest: test_early_data_replay
1..2
ok 238 - iteration 1
ok 239 - iteration 2
ok 30 - test_early_data_replay
# INFO: @ test/helpers/ssltestlib.c:975
# SSL_accept() failed -1, 11
ok 31 - test_client_hello_cb
ok 32 - test_sni_tls13
ok 33 - test_key_update
ok 34 - test_keylog_no_master_key
# Subtest: test_early_data_not_expected
1..3
ok 240 - iteration 2
ok 241 - iteration 1
ok 242 - iteration 3
ok 35 - test_early_data_not_expected
ok 36 - test_ssl_bio_pop_ssl_bio
# Subtest: test_export_key_mat
1..6
ok 243 - iteration 5
ok 244 - iteration 4
ok 245 - iteration 3
ok 246 - iteration 2
ok 247 - iteration 1
ok 248 - iteration 6
ok 37 - test_export_key_mat
# Subtest: test_shutdown
1..7
ok 249 - iteration 1
ok 250 - iteration 2
ok 251 - iteration 3
ok 252 - iteration 4
ok 253 - iteration 5
ok 254 - iteration 6
ok 255 - iteration 7
ok 38 - test_shutdown
# Subtest: test_key_update_local_in_write
1..2
ok 256 - iteration 1
ok 257 - iteration 2
ok 39 - test_key_update_local_in_write
# Subtest: test_extra_tickets
1..6
ok 258 - iteration 5
ok 259 - iteration 4
ok 260 - iteration 3
ok 261 - iteration 2
ok 262 - iteration 1
ok 263 - iteration 6
ok 40 - test_extra_tickets
# Subtest: test_multiblock_write
1..4
# SKIP: @ test/sslapitest.c:8432
# Multiblock cipher is not available for AES256-SHA
ok 264 - iteration 3
# SKIP: @ test/sslapitest.c:8432
# Multiblock cipher is not available for AES128-SHA256
ok 265 - iteration 2
# SKIP: @ test/sslapitest.c:8432
# Multiblock cipher is not available for AES128-SHA
ok 266 - iteration 1
# SKIP: @ test/sslapitest.c:8432
# Multiblock cipher is not available for AES256-SHA256
ok 267 - iteration 4
ok 41 - test_multiblock_write
# Subtest: test_early_data_skip
1..3
ok 268 - iteration 2
ok 269 - iteration 1
ok 270 - iteration 3
ok 42 - test_early_data_skip
ok 43 - test_large_message_tls
# INFO: @ test/helpers/ssltestlib.c:975
# SSL_accept() failed -1, 1
# 80329382B97F0000:error:0A0000BF:SSL routines:tls_setup_handshake:no protocols available:ssl/statem/statem_lib.c:104:
# INFO: @ test/helpers/ssltestlib.c:957
# SSL_connect() failed -1, 1
# 80329382B97F0000:error:0A00042E:SSL routines:ssl3_read_bytes:tlsv1 alert protocol version:ssl/record/rec_layer_s3.c:1584:SSL alert number 70
# INFO: @ test/helpers/ssltestlib.c:975
# SSL_accept() failed -1, 1
# 80329382B97F0000:error:0A0000BF:SSL routines:tls_setup_handshake:no protocols available:ssl/statem/statem_lib.c:104:
# INFO: @ test/helpers/ssltestlib.c:957
# SSL_connect() failed -1, 1
# 80329382B97F0000:error:0A00042E:SSL routines:ssl3_read_bytes:tlsv1 alert protocol version:ssl/record/rec_layer_s3.c:1584:SSL alert number 70
ok 44 - test_session_with_only_int_cache
ok 45 - test_no_ems
# Subtest: test_early_data_skip_hrr
1..3
ok 271 - iteration 1
ok 272 - iteration 2
ok 273 - iteration 3
ok 46 - test_early_data_skip_hrr
# Subtest: test_tls13_psk
1..4
ok 274 - iteration 3
ok 275 - iteration 2
ok 276 - iteration 1
ok 277 - iteration 4
ok 47 - test_tls13_psk
ok 48 - test_stateless
# Subtest: test_early_data_tls1_2
1..3
ok 278 - iteration 2
ok 279 - iteration 1
ok 280 - iteration 3
ok 49 - test_early_data_tls1_2
# INFO: @ test/helpers/ssltestlib.c:975
# SSL_accept() failed -1, 1
# 80329382B97F0000:error:0A0000BF:SSL routines:tls_setup_handshake:no protocols available:ssl/statem/statem_lib.c:104:
# INFO: @ test/helpers/ssltestlib.c:957
# SSL_connect() failed -1, 1
# 80329382B97F0000:error:0A00042E:SSL routines:ssl3_read_bytes:tlsv1 alert protocol version:ssl/record/rec_layer_s3.c:1584:SSL alert number 70
# INFO: @ test/helpers/ssltestlib.c:975
# SSL_accept() failed -1, 1
# 80329382B97F0000:error:0A0000BF:SSL routines:tls_setup_handshake:no protocols available:ssl/statem/statem_lib.c:104:
# INFO: @ test/helpers/ssltestlib.c:957
# SSL_connect() failed -1, 1
# 80329382B97F0000:error:0A00042E:SSL routines:ssl3_read_bytes:tlsv1 alert protocol version:ssl/record/rec_layer_s3.c:1584:SSL alert number 70
ok 50 - test_session_with_both_cache
# Subtest: test_early_data_skip_hrr_fail
1..3
ok 281 - iteration 2
ok 282 - iteration 1
ok 283 - iteration 3
ok 51 - test_early_data_skip_hrr_fail
# Subtest: test_ssl_clear
1..2
ok 284 - iteration 1
ok 285 - iteration 2
ok 52 - test_ssl_clear
ok 53 - test_ssl_bio_change_wbio
ok 54 - test_set_alpn
ok 55 - test_ssl_build_cert_chain
# Subtest: test_srp
1..6
ok 286 - iteration 1
# INFO: @ test/helpers/ssltestlib.c:975
# SSL_accept() failed -1, 1
# 80329382B97F0000:error:0A000119:SSL routines:ssl3_get_record:decryption failed or bad record mac:ssl/record/ssl3_record.c:568:
# INFO: @ test/helpers/ssltestlib.c:957
# SSL_connect() failed -1, 1
# 80329382B97F0000:error:0A0003FC:SSL routines:ssl3_read_bytes:ssl/tls alert bad record mac:ssl/record/rec_layer_s3.c:1584:SSL alert number 20
ok 287 - iteration 2
ok 288 - iteration 3
# INFO: @ test/helpers/ssltestlib.c:975
# SSL_accept() failed -1, 1
# 80329382B97F0000:error:0A000119:SSL routines:ssl3_get_record:decryption failed or bad record mac:ssl/record/ssl3_record.c:568:
# INFO: @ test/helpers/ssltestlib.c:957
# SSL_connect() failed -1, 1
# 80329382B97F0000:error:0A0003FC:SSL routines:ssl3_read_bytes:ssl/tls alert bad record mac:ssl/record/rec_layer_s3.c:1584:SSL alert number 20
ok 289 - iteration 4
ok 290 - iteration 5
# INFO: @ test/helpers/ssltestlib.c:975
# SSL_accept() failed -1, 1
# 80329382B97F0000:error:0A000119:SSL routines:ssl3_get_record:decryption failed or bad record mac:ssl/record/ssl3_record.c:568:
# INFO: @ test/helpers/ssltestlib.c:957
# SSL_connect() failed -1, 1
# 80329382B97F0000:error:0A0003FC:SSL routines:ssl3_read_bytes:ssl/tls alert bad record mac:ssl/record/rec_layer_s3.c:1584:SSL alert number 20
ok 291 - iteration 6
ok 56 - test_srp
# Subtest: test_max_fragment_len_ext
1..4
ok 292 - iteration 1
ok 293 - iteration 2
ok 294 - iteration 3
ok 295 - iteration 4
ok 57 - test_max_fragment_len_ext
# Subtest: test_pluggable_group
1..2
ok 296 - iteration 1
ok 297 - iteration 2
ok 58 - test_pluggable_group
ok 59 - test_ssl_ctx_build_cert_chain
# Subtest: test_info_callback
1..6
ok 298 - iteration 1
ok 299 - iteration 2
ok 300 - iteration 3
ok 301 - iteration 4
ok 302 - iteration 5
ok 303 - iteration 6
ok 60 - test_info_callback
ok 61 - test_psk_tickets
ok 62 - test_set_verify_cert_store_ssl_ctx
# Subtest: test_sigalgs_available
1..6
ok 304 - iteration 1
ok 305 - iteration 2
ok 306 - iteration 3
ok 307 - iteration 4
ok 308 - iteration 5
ok 309 - iteration 6
ok 63 - test_sigalgs_available
# Subtest: test_stateless_tickets
1..3
ok 310 - iteration 2
ok 311 - iteration 1
ok 312 - iteration 3
ok 64 - test_stateless_tickets
# Subtest: test_servername
1..10
ok 313 - iteration 3
ok 314 - iteration 6
ok 315 - iteration 9
ok 316 - iteration 2
ok 317 - iteration 5
ok 318 - iteration 8
ok 319 - iteration 1
ok 320 - iteration 4
ok 321 - iteration 7
ok 322 - iteration 10
ok 65 - test_servername
# Subtest: test_early_data_not_sent
1..3
ok 323 - iteration 1
ok 324 - iteration 2
ok 325 - iteration 3
ok 66 - test_early_data_not_sent
# Subtest: test_cert_cb
1..6
# INFO: @ test/helpers/ssltestlib.c:975
# SSL_accept() failed -1, 1
# 80329382B97F0000:error:0A000179:SSL routines:tls_post_process_client_hello:cert cb error:ssl/statem/statem_srvr.c:2204:
# INFO: @ test/helpers/ssltestlib.c:957
# SSL_connect() failed -1, 1
# 80329382B97F0000:error:0A000438:SSL routines:ssl3_read_bytes:tlsv1 alert internal error:ssl/record/rec_layer_s3.c:1584:SSL alert number 80
# INFO: @ test/helpers/ssltestlib.c:975
# SSL_accept() failed -1, 1
# 80329382B97F0000:error:0A000179:SSL routines:tls_post_process_client_hello:cert cb error:ssl/statem/statem_srvr.c:2204:
# INFO: @ test/helpers/ssltestlib.c:957
# SSL_connect() failed -1, 1
# 80329382B97F0000:error:0A000438:SSL routines:ssl3_read_bytes:tlsv1 alert internal error:ssl/record/rec_layer_s3.c:1584:SSL alert number 80
ok 326 - iteration 1
ok 327 - iteration 2
ok 328 - iteration 3
ok 329 - iteration 4
# INFO: @ test/helpers/ssltestlib.c:975
# SSL_accept() failed -1, 1
# 80329382B97F0000:error:0A0000C1:SSL routines:tls_post_process_client_hello:no shared cipher:ssl/statem/statem_srvr.c:2220:
# INFO: @ test/helpers/ssltestlib.c:957
# SSL_connect() failed -1, 1
# 80329382B97F0000:error:0A000410:SSL routines:ssl3_read_bytes:ssl/tls alert handshake failure:ssl/record/rec_layer_s3.c:1584:SSL alert number 40
# INFO: @ test/helpers/ssltestlib.c:975
# SSL_accept() failed -1, 1
# 80329382B97F0000:error:0A000076:SSL routines:tls_choose_sigalg:no suitable signature algorithm:ssl/t1_lib.c:3275:
# INFO: @ test/helpers/ssltestlib.c:957
# SSL_connect() failed -1, 1
# 80329382B97F0000:error:0A000410:SSL routines:ssl3_read_bytes:ssl/tls alert handshake failure:ssl/record/rec_layer_s3.c:1584:SSL alert number 40
ok 330 - iteration 5
# INFO: @ test/helpers/ssltestlib.c:975
# SSL_accept() failed -1, 1
# 80329382B97F0000:error:0A0000C1:SSL routines:tls_post_process_client_hello:no shared cipher:ssl/statem/statem_srvr.c:2220:
# INFO: @ test/helpers/ssltestlib.c:957
# SSL_connect() failed -1, 1
# 80329382B97F0000:error:0A000410:SSL routines:ssl3_read_bytes:ssl/tls alert handshake failure:ssl/record/rec_layer_s3.c:1584:SSL alert number 40
# INFO: @ test/helpers/ssltestlib.c:975
# SSL_accept() failed -1, 1
# 80329382B97F0000:error:0A000076:SSL routines:tls_choose_sigalg:no suitable signature algorithm:ssl/t1_lib.c:3275:
# INFO: @ test/helpers/ssltestlib.c:957
# SSL_connect() failed -1, 1
# 80329382B97F0000:error:0A000410:SSL routines:ssl3_read_bytes:ssl/tls alert handshake failure:ssl/record/rec_layer_s3.c:1584:SSL alert number 40
ok 331 - iteration 6
ok 67 - test_cert_cb
# Subtest: test_ktls_sendfile
1..6
ok 332 - iteration 1
ok 333 - iteration 2
ok 334 - iteration 3
ok 335 - iteration 4
# SKIP: @ test/sslapitest.c:1356
# Failed to enable KTLS for TLS 1.3 cipher TLS_AES_128_CCM_SHA256
ok 336 - iteration 5 # skipped
ok 337 - iteration 6
ok 68 - test_ktls_sendfile
# Subtest: test_ssl_get_shared_ciphers
1..6
ok 338 - iteration 5
ok 339 - iteration 4
ok 340 - iteration 3
ok 341 - iteration 2
ok 342 - iteration 1
ok 343 - iteration 6
ok 69 - test_ssl_get_shared_ciphers
# INFO: @ test/helpers/ssltestlib.c:957
# SSL_connect() failed -1, 12
ok 70 - test_client_cert_verify_cb
# Subtest: test_early_data_psk_with_all_ciphers
1..5
ok 344 - iteration 4
ok 345 - iteration 3
ok 346 - iteration 2
ok 347 - iteration 1
ok 348 - iteration 5
ok 71 - test_early_data_psk_with_all_ciphers
# Subtest: test_incorrect_shutdown
1..2
ok 349 - iteration 1
ok 350 - iteration 2
ok 72 - test_incorrect_shutdown
# Subtest: test_early_data_psk
1..8
ok 351 - iteration 5
ok 352 - iteration 2
ok 353 - iteration 7
ok 354 - iteration 4
ok 355 - iteration 1
ok 356 - iteration 6
ok 357 - iteration 3
ok 358 - iteration 8
ok 73 - test_early_data_psk
# Subtest: test_stateful_tickets
1..3
ok 359 - iteration 1
ok 360 - iteration 2
ok 361 - iteration 3
ok 74 - test_stateful_tickets
# Subtest: test_key_update_peer_in_read
1..2
ok 362 - iteration 1
ok 363 - iteration 2
ok 75 - test_key_update_peer_in_read
ok 76 - test_ssl_bio_pop_next_bio
ok 77 - test_large_message_tls_read_ahead
# Subtest: test_key_update_peer_in_write
1..2
ok 364 - iteration 1
ok 365 - iteration 2
ok 78 - test_key_update_peer_in_write
# INFO: @ test/helpers/ssltestlib.c:957
# SSL_connect() failed -1, 1
ok 79 - test_ciphersuite_change
ok 80 - test_load_dhfile
# Subtest: test_key_exchange
1..14
ok 366 - iteration 11
ok 367 - iteration 8
ok 368 - iteration 5
ok 369 - iteration 2
ok 370 - iteration 13
ok 371 - iteration 10
ok 372 - iteration 7
ok 373 - iteration 4
ok 374 - iteration 1
ok 375 - iteration 12
ok 376 - iteration 9
ok 377 - iteration 6
ok 378 - iteration 3
ok 379 - iteration 14
ok 81 - test_key_exchange
# Subtest: test_set_tmp_dh
1..11
# INFO: @ test/helpers/ssltestlib.c:975
# SSL_accept() failed -1, 1
# 80329382B97F0000:error:0A0000C1:SSL routines:tls_post_process_client_hello:no shared cipher:ssl/statem/statem_srvr.c:2220:
# INFO: @ test/helpers/ssltestlib.c:957
# SSL_connect() failed -1, 1
# 80329382B97F0000:error:0A000410:SSL routines:ssl3_read_bytes:ssl/tls alert handshake failure:ssl/record/rec_layer_s3.c:1584:SSL alert number 40
ok 380 - iteration 2
ok 381 - iteration 4
ok 382 - iteration 6
ok 383 - iteration 8
ok 384 - iteration 10
# INFO: @ test/helpers/ssltestlib.c:975
# SSL_accept() failed -1, 1
# 80329382B97F0000:error:0A0000C1:SSL routines:tls_post_process_client_hello:no shared cipher:ssl/statem/statem_srvr.c:2220:
# INFO: @ test/helpers/ssltestlib.c:957
# SSL_connect() failed -1, 1
# 80329382B97F0000:error:0A000410:SSL routines:ssl3_read_bytes:ssl/tls alert handshake failure:ssl/record/rec_layer_s3.c:1584:SSL alert number 40
ok 385 - iteration 1
# INFO: @ test/helpers/ssltestlib.c:975
# SSL_accept() failed -1, 1
# 80329382B97F0000:error:0A0000C1:SSL routines:tls_post_process_client_hello:no shared cipher:ssl/statem/statem_srvr.c:2220:
# INFO: @ test/helpers/ssltestlib.c:957
# SSL_connect() failed -1, 1
# 80329382B97F0000:error:0A000410:SSL routines:ssl3_read_bytes:ssl/tls alert handshake failure:ssl/record/rec_layer_s3.c:1584:SSL alert number 40
ok 386 - iteration 3
ok 387 - iteration 5
ok 388 - iteration 7
ok 389 - iteration 9
ok 390 - iteration 11
ok 82 - test_set_tmp_dh
# Subtest: test_set_ciphersuite
1..10
ok 391 - iteration 9
ok 392 - iteration 8
ok 393 - iteration 7
ok 394 - iteration 6
ok 395 - iteration 5
ok 396 - iteration 4
ok 397 - iteration 3
ok 398 - iteration 2
ok 399 - iteration 1
ok 400 - iteration 10
ok 83 - test_set_ciphersuite
# Subtest: test_custom_exts
1..6
ok 401 - iteration 1
ok 402 - iteration 2
ok 403 - iteration 3
ok 404 - iteration 4
ok 405 - iteration 5
ok 406 - iteration 6
ok 84 - test_custom_exts
../../util/wrap.pl ../../test/sslapitest ../../test/certs ../../test/recipes/90-test_sslapi_data/passwd.txt /tmp/nGQ_xzlC3E default ../../test/default.cnf ../../test/recipes/90-test_sslapi_data/dhparams.pem => 1
not ok 1 - running sslapitest
# Failed test 'running sslapitest'
# at test/recipes/90-test_sslapi.t line 32.
# Looks like you failed 1 test of 1.
Dubious, test returned 1 (wstat 256, 0x100)
Failed 1/1 subtests
Test Summary Report
-------------------
90-test_sslapi.t (Wstat: 256 Tests: 1 Failed: 1)
Failed test: 1
Non-zero exit status: 1
Files=1, Tests=1, 12 wallclock secs ( 0.05 usr 0.00 sys + 11.23 cusr 0.04 csys = 11.32 CPU)
Result: FAIL
make[1]: *** [Makefile:3292: run_tests] Error 1
make[1]: Leaving directory '/home/ed/OPCToolboxV5/Source/Core/OpenSSL/openssl'
make: *** [Makefile:3288: tests] Error 2I tried to reproduce this with the openssl-3.0 branch, yesterday, but that did work, but maybe it left the kernel module in an undefined state? I have not re-booted or unloaded the kernel module so far.
bernd-edlinger
commented
2 years ago Wow, ran "make test" once and that fixed it... Now again as before.
bernd-edlinger
commented
2 years ago Cannot reproduce this any more, but saw a similar thing with this test:
$ CTLOG_FILE=test/ct/log_list.cnf ./util/shlib_wrap.sh test/ssl_old_test -s_cert apps/server.pem -ipv6 -server_ktls -client_ktls -bytes 1000000000
Doing handshakes=1 bytes=1000000000
ERROR in SERVER
TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, 2048 bits RSA, temp key: 253 bits X25519, digest=SHA256but that is also not reproducible.
bernd-edlinger
commented
2 years ago I was able to reproduce that again, and used the opportunity to try different combinations, in the ssl_old_test command:
$ CTLOG_FILE=test/ct/log_list.cnf ./util/shlib_wrap.sh test/ssl_old_test -s_cert apps/server.pem -ipv6 -server_ktls -client_ktls -bytes 1000000000 -tls1_2
Doing handshakes=1 bytes=1000000000
ERROR in SERVER
TLSv1.2, cipher TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384, 2048 bits RSA, temp key: 253 bits X25519, digest=SHA256
$ CTLOG_FILE=test/ct/log_list.cnf ./util/shlib_wrap.sh test/ssl_old_test -s_cert apps/server.pem -ipv6 -server_ktls -client_ktls -bytes 1000000000 -tls1_2
Doing handshakes=1 bytes=1000000000
ERROR in SERVER
TLSv1.2, cipher TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384, 2048 bits RSA, temp key: 253 bits X25519, digest=SHA256
$ CTLOG_FILE=test/ct/log_list.cnf ./util/shlib_wrap.sh test/ssl_old_test -s_cert apps/server.pem -ipv6 -server_ktls -client_ktls -bytes 1000000000
Doing handshakes=1 bytes=1000000000
ERROR in SERVER
TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, 2048 bits RSA, temp key: 253 bits X25519, digest=SHA256
$ CTLOG_FILE=test/ct/log_list.cnf ./util/shlib_wrap.sh test/ssl_old_test -s_cert apps/server.pem -ipv6 -server_ktls -bytes 1000000000
Doing handshakes=1 bytes=1000000000
ERROR in SERVER
407754FE627F0000:error:0A000119:SSL routines:ssl3_get_record:decryption failed or bad record mac:ssl/record/ssl3_record.c:224:
TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, 2048 bits RSA, temp key: 253 bits X25519, digest=SHA256
$ CTLOG_FILE=test/ct/log_list.cnf ./util/shlib_wrap.sh test/ssl_old_test -s_cert apps/server.pem -ipv6 -client_ktls -bytes 1000000000
Doing handshakes=1 bytes=1000000000
TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, 2048 bits RSA, temp key: 253 bits X25519, digest=SHA256
$ CTLOG_FILE=test/ct/log_list.cnf ./util/shlib_wrap.sh test/ssl_old_test -s_cert apps/server.pem -ipv6 -server_ktls -bytes 1000000000
Doing handshakes=1 bytes=1000000000
ERROR in SERVER
TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, 2048 bits RSA, temp key: 253 bits X25519, digest=SHA256
$ CTLOG_FILE=test/ct/log_list.cnf ./util/shlib_wrap.sh test/ssl_old_test -s_cert apps/server.pem -ipv6 -server_ktls -bytes 1000000000 -tls1_2
Doing handshakes=1 bytes=1000000000
ERROR in SERVER
TLSv1.2, cipher TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384, 2048 bits RSA, temp key: 253 bits X25519, digest=SHA256
$ CTLOG_FILE=test/ct/log_list.cnf ./util/shlib_wrap.sh test/ssl_old_test -s_cert apps/server.pem -ipv6 -client_ktls -bytes 1000000000 -tls1_2
Doing handshakes=1 bytes=1000000000
TLSv1.2, cipher TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384, 2048 bits RSA, temp key: 253 bits X25519, digest=SHA256
$ CTLOG_FILE=test/ct/log_list.cnf ./util/shlib_wrap.sh test/ssl_old_test -s_cert apps/server.pem -ipv6 -server_ktls -bytes 1000000000 -tls1_2
Doing handshakes=1 bytes=1000000000
ERROR in SERVER
TLSv1.2, cipher TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384, 2048 bits RSA, temp key: 253 bits X25519, digest=SHA256
$ CTLOG_FILE=test/ct/log_list.cnf ./util/shlib_wrap.sh strace -o trace.txt -f test/ssl_old_test -s_cert apps/server.pem -ipv6 -server_ktls -bytes 1000000000 -tls1_2
Doing handshakes=1 bytes=1000000000
TLSv1.2, cipher TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384, 2048 bits RSA, temp key: 253 bits X25519, digest=SHA256
$ CTLOG_FILE=test/ct/log_list.cnf ./util/shlib_wrap.sh test/ssl_old_test -s_cert apps/server.pem -ipv6 -server_ktls -bytes 1000000000 -tls1_2
Doing handshakes=1 bytes=1000000000
ERROR in SERVER
TLSv1.2, cipher TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384, 2048 bits RSA, temp key: 253 bits X25519, digest=SHA256
$ CTLOG_FILE=test/ct/log_list.cnf ./util/shlib_wrap.sh strace -o trace1.txt -f test/ssl_old_test -s_cert apps/server.pem -ipv6 -server_ktls -bytes 1000000000 -tls1_2
Doing handshakes=1 bytes=1000000000
TLSv1.2, cipher TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384, 2048 bits RSA, temp key: 253 bits X25519, digest=SHA256
$ CTLOG_FILE=test/ct/log_list.cnf ./util/shlib_wrap.sh test/ssl_old_test -s_cert apps/server.pem -ipv6 -server_ktls -bytes 1000000000 -tls1_2
Doing handshakes=1 bytes=1000000000
TLSv1.2, cipher TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384, 2048 bits RSA, temp key: 253 bits X25519, digest=SHA256
ed@mw-ed:~/OPCToolboxV5/Source/Core/OpenSSL/openssl$ CTLOG_FILE=test/ct/log_list.cnf ./util/shlib_wrap.sh test/ssl_old_test -s_cert apps/server.pem -ipv6 -server_ktls -bytes 1000000000
Doing handshakes=1 bytes=1000000000
TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, 2048 bits RSA, temp key: 253 bits X25519, digest=SHA256EDIT: I think there is always an something in the error stack, when the SSL_read fails, and it is always from the O/S errno==EBADMSG. and all ERROR in SERVER w/o "decryption failed or bad record mac" above were from SSL_write. Maybe it would be interesting to find out the errno from the O/S function there.
bernd-edlinger
commented
2 years ago So to summarize it there is also a problem with tls1_2 and not only with tls1_3 as the sslapi test indicated before. The problem goes away when the -server_ktls is not used, and is unrelated to -client_ktls. Unfortunately the problem does not reproduce when strace is intercepting the calls. The "ERROR in SERVER" can be printed either from an error in the SSL_read or in SSL_write. The error queue was empty when this happened. When I modified the ssl_old_test.c to add information if it is a read or a write error, and rebuilt the ssl_old_test, the error went away...
bernd-edlinger
commented
2 years ago I did this mod:
diff --git a/test/ssl_old_test.c b/test/ssl_old_test.c
index 1e4058f19f..22bc4c78bd 100644
--- a/test/ssl_old_test.c
+++ b/test/ssl_old_test.c
@@ -2039,7 +2039,7 @@ int doit_localhost(SSL *s_ssl, SSL *c_ssl, int family, long count,
r = BIO_write(c_ssl_bio, cbuf, i);
if (r < 0) {
if (!BIO_should_retry(c_ssl_bio)) {
- fprintf(stderr, "ERROR in CLIENT\n");
+ fprintf(stderr, "ERROR in CLIENT (write)\n");
err_in_client = 1;
goto err;
}
@@ -2065,7 +2065,7 @@ int doit_localhost(SSL *s_ssl, SSL *c_ssl, int family, long count,
r = BIO_read(c_ssl_bio, cbuf, sizeof(cbuf));
if (r < 0) {
if (!BIO_should_retry(c_ssl_bio)) {
- fprintf(stderr, "ERROR in CLIENT\n");
+ fprintf(stderr, "ERROR in CLIENT (read)\n");
err_in_client = 1;
goto err;
}
@@ -2118,7 +2118,7 @@ int doit_localhost(SSL *s_ssl, SSL *c_ssl, int family, long count,
r = BIO_write(s_ssl_bio, sbuf, i);
if (r < 0) {
if (!BIO_should_retry(s_ssl_bio)) {
- fprintf(stderr, "ERROR in SERVER\n");
+ fprintf(stderr, "ERROR in SERVER (write)\n");
err_in_server = 1;
goto err;
}
@@ -2139,7 +2139,7 @@ int doit_localhost(SSL *s_ssl, SSL *c_ssl, int family, long count,
r = BIO_read(s_ssl_bio, sbuf, sizeof(sbuf));
if (r < 0) {
if (!BIO_should_retry(s_ssl_bio)) {
- fprintf(stderr, "ERROR in SERVER\n");
+ fprintf(stderr, "ERROR in SERVER (read)\n");
err_in_server = 1;
goto err;
}... and was lucky to reproduce again:
$ CTLOG_FILE=test/ct/log_list.cnf ./util/shlib_wrap.sh test/ssl_old_test -s_cert apps/server.pem -ipv6 -server_ktls -client_ktls -bytes 1000000000
Doing handshakes=1 bytes=1000000000
ERROR in SERVER (read)
402765763B7F0000:error:0A000119:SSL routines:ssl3_get_record:decryption failed or bad record mac:ssl/record/ssl3_record.c:224:
TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, 2048 bits RSA, temp key: 253 bits X25519, digest=SHA256
$ CTLOG_FILE=test/ct/log_list.cnf ./util/shlib_wrap.sh test/ssl_old_test -s_cert apps/server.pem -ipv6 -server_ktls -bytes 1000000000
Doing handshakes=1 bytes=1000000000
ERROR in SERVER (read)
4077A105E27F0000:error:0A000119:SSL routines:ssl3_get_record:decryption failed or bad record mac:ssl/record/ssl3_record.c:224:
TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, 2048 bits RSA, temp key: 253 bits X25519, digest=SHA256
$ CTLOG_FILE=test/ct/log_list.cnf ./util/shlib_wrap.sh test/ssl_old_test -s_cert apps/server.pem -ipv6 -server_ktls -bytes 1000000000 -tls1_2
Doing handshakes=1 bytes=1000000000
ERROR in SERVER (write)
TLSv1.2, cipher TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384, 2048 bits RSA, temp key: 253 bits X25519, digest=SHA256
$ CTLOG_FILE=test/ct/log_list.cnf ./util/shlib_wrap.sh test/ssl_old_test -s_cert apps/server.pem -ipv4 -server_ktls -bytes 1000000000
Doing handshakes=1 bytes=1000000000
ERROR in SERVER (write)
TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, 2048 bits RSA, temp key: 253 bits X25519, digest=SHA256
$ CTLOG_FILE=test/ct/log_list.cnf ./util/shlib_wrap.sh test/ssl_old_test -s_cert apps/server.pem -ipv4 -server_ktls -bytes 1000000000
Doing handshakes=1 bytes=1000000000
ERROR in SERVER (write)
TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, 2048 bits RSA, temp key: 253 bits X25519, digest=SHA256
$ CTLOG_FILE=test/ct/log_list.cnf ./util/shlib_wrap.sh test/ssl_old_test -s_cert apps/server.pem -ipv4 -server_ktls -bytes 1000000000 -tls1_2
Doing handshakes=1 bytes=1000000000
ERROR in SERVER (write)
TLSv1.2, cipher TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384, 2048 bits RSA, temp key: 253 bits X25519, digest=SHA256Interestingly this time the bad record mac error is happening, that was previously only seen in the clientapi test. And ipv4 is not working either, but the error is in the write when using ipv4, not the read function.
bernd-edlinger
commented
2 years ago Magic: the test_sslapi does only use IPv4, never IPv6.
bernd-edlinger
commented
2 years ago Okay, I've been able to get a strace output from both failure modes: Here's the error from SSL_read:
write(5, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8192) = 8192
recvmsg(5, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=80432968}) = 0
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=80440318}) = 0
write(4, "\27\3\3 \21\215KD\247\37\313\177^\313v\2\255E\334\374\200\324\300\fP\6\7\251\244\6\352["..., 8214) = 8214
read(4, 0x564e5ac80fa3, 5) = -1 EAGAIN (Resource temporarily unavailable)
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=80479525}) = 0
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=80486202}) = 0
write(5, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8192) = 8192
recvmsg(5, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=80527972}) = 0
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=80536176}) = 0
write(4, "\27\3\3 \21\252\32z\232@\277y\231\207p\r\333\377x@\236\315\204\202\277~\316\301\357\260\33\376"..., 8214) = 8214
read(4, 0x564e5ac80fa3, 5) = -1 EAGAIN (Resource temporarily unavailable)
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=80573913}) = 0
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=80581965}) = 0
write(5, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8192) = 8192
recvmsg(5, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=80618274}) = 0
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=80625895}) = 0
write(4, "\27\3\3 \21f~ea\312\331\326Fu\315D{\277GM\301gX{\255\224\272\321\354\204G\325"..., 8214) = 8214
read(4, 0x564e5ac80fa3, 5) = -1 EAGAIN (Resource temporarily unavailable)
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=80661200}) = 0
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=80670104}) = 0
write(5, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8192) = 8192
recvmsg(5, {msg_namelen=0}, 0) = -1 EBADMSG (Bad message)
sendmsg(5, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\2\24", iov_len=2}], msg_iovlen=1, msg_control=[{cmsg_len=17, cmsg_level=SOL_TLS, cmsg_type=0x1}], msg_controllen=17, msg_flags=0}, 0) = -1 EBADMSG (Bad message)
write(2, "ERROR in SERVER (read)\n", 23) = 23
write(2, "4037F0EE737F0000:error:0A000119:"..., 127) = 127
write(1, "TLSv1.3, cipher TLSv1.3 TLS_AES_"..., 104) = 104
close(5) = 0
shutdown(4, SHUT_RDWR) = -1 ENOTCONN (Transport endpoint is not connected)
close(4) = 0
exit_group(1) = ?
+++ exited with 1 +++And the error from SSL_write turns out to be also EBADMSG:
write(4, "\27\3\3 \21k\262\344\26\310{\"\370\4e\332\220X\323\36\311\v\24\25~\"0U\26V\370\250"..., 8214) = 8214
read(4, "\27\3\3 \21", 5) = 5
read(4, "B\262H\3308\315\251\255(\262f\23\177\331\335\346y\204\333\346\224\336C(JD\2\301\330\314\223\332"..., 8209) = 8209
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=861534147}) = 0
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=861543110}) = 0
write(5, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8192) = 8192
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=861577984}) = 0
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=861586721}) = 0
write(4, "\27\3\3 \21_\266\321\25p\355\365[\1\207\t\347\254\246\316\377\264\346\354\4\48\26\247\212A\273"..., 8214) = 8214
read(4, "\27\3\3 \21", 5) = 5
read(4, "QuG\n\350\321O\34\32\237\235\35Y\317!\270F\20\221\303f\3\201\17?\303G\323\34=I-"..., 8209) = 8209
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=861643711}) = 0
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=861652115}) = 0
write(5, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8192) = 8192
recvmsg(5, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., iov_len=16688}], msg_iovlen=1, msg_control=[{cmsg_len=17, cmsg_level=SOL_TLS, cmsg_type=0x2}], msg_controllen=24, msg_flags=MSG_CTRUNC|MSG_EOR}, 0) = 13952
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=861725371}) = 0
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=861732036}) = 0
write(4, "\27\3\3 \21\207b\316\311\217\325\225)\367\350O\362L\332\16\206\265|\331&7\25\342\263n\350\200"..., 8214) = 8214
read(4, "\27\3\3 \21", 5) = 5
read(4, "Tm2#\367\236\306lGU\272s\rh\335\341n\236\4{eB\314\330\0320-I\312\nP\201"..., 8209) = 8209
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=861783473}) = 0
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=861794037}) = 0
write(5, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8192) = -1 EBADMSG (Bad message)
write(2, "ERROR in SERVER (write)\n", 24) = 24
write(1, "TLSv1.3, cipher TLSv1.3 TLS_AES_"..., 104) = 104
close(5) = 0
shutdown(4, SHUT_RDWR) = -1 ENOTCONN (Transport endpoint is not connected)
close(4) = 0
exit_group(1) = ?
+++ exited with 1 +++Hmm, it is also reproducible with openssl-3.0.3, but only with TLS1.2, that means probably that the RX handling of the server_ktls is likely broken, and in the 3.0 branch the RX path is only enabled with TLS1.2. It's a mystery why the client_ktls is never affected.
bernd-edlinger
commented
2 years ago Empirically I found this would be a possible fix:
diff --git a/ssl/t1_enc.c b/ssl/t1_enc.c
index 900ba14fbd..4d8fbf63c9 100644
--- a/ssl/t1_enc.c
+++ b/ssl/t1_enc.c
@@ -414,6 +414,9 @@ int tls1_change_cipher_state(SSL *s, int which)
goto err;
}
+ if (which & SSL3_CC_READ && s->server)
+ goto skip_ktls;
+
/* All future data will get encrypted by ktls. Flush the BIO or skip ktls */
if (which & SSL3_CC_WRITE) {
if (BIO_flush(bio) <= 0)
diff --git a/ssl/tls13_enc.c b/ssl/tls13_enc.c
index a14cbb1785..8e0923ab57 100644
--- a/ssl/tls13_enc.c
+++ b/ssl/tls13_enc.c
@@ -715,6 +715,9 @@ int tls13_change_cipher_state(SSL *s, int which)
goto err;
}
+ if (which & SSL3_CC_READ && s->server)
+ goto skip_ktls;
+
/* All future data will get encrypted by ktls. Flush the BIO or skip ktls */
if (which & SSL3_CC_WRITE) {
if (BIO_flush(bio) <= 0)I forgot to mention one thing about the machine, where this was observed, that may or may not have to do with the ktls failure: In the kernel traces is never anything when the ktls failure occurs, but when the machine starts up I have found this:
[ 25.377961] vboxdrv: loading out-of-tree module taints kernel.
[ 25.378375] vboxdrv: module verification failed: signature and/or required key missing - tainting kernel
[ 25.394895] vboxdrv: Found 8 processor cores
[ 25.411874] vboxdrv: TSC mode is Invariant, tentative frequency 3599979862 Hz
[ 25.411876] vboxdrv: Successfully loaded version 6.1.32_Ubuntu r149290 (interface 0x00320000)So the kernel is "tainted".
The VirtualBox is installed from ubuntu 20.4 as all the other stuff, I use it to run a Windows VM. It was not active when this initially happened, but the likelihood that the ssl_old_test runs into this error is higher when a VM is starting, or maybe only running, and it is less likely to observe the failure when no VM is running.
bernd-edlinger
commented
2 years ago I've reproduced the failure on another machine, where the same O/S is running but the kernel is not tainted.
However, the failure is not restricted to the server side as I initially thought, based on the preliminary test results. That was just a different bug #18318 that prevented the ssl_old_test to properly enable the client KTLS.
t8m
commented
2 years ago Could perhaps @pasis @bsdjhb @ueno look at this?
bsdjhb
commented
2 years ago EBADMSG means that the kernel failed a record due to one of its internal checks (header validation, MAC mismatch, etc.). I don’t know if Linux provides counters or logs for the specific error checks it performs, but I would start with checking that (perhaps adding new counters or traces in a local kernel patch while reproducing). I have never seen sporadic failures myself, but I work on KTLS on FreeBSD and this might very well be an OS-specific issue if the kernel is failing a valid record incorrectly.
While testing my RFC 8449 patch #18248 with KTLS enabled system I became aware of a sporadic test failure, that turns out to be also there without my patch. I've been able to reproduce with master ecb1ed1b0e5aea5b71e8a98e95b6f9f022d61c89
./config enable-ktlsI useLinux version 5.4.0-109-lowlatency (buildd@ubuntu) (gcc version 9.4.0 (Ubuntu 9.4.0-1ubuntu1~20.04.1)) #123-Ubuntu SMP PREEMPT Fri Apr 8 09:52:18 UTC 2022I see the following test failure in
make test TESTS=test_sslapi V=1but not easily reproducible:It does only happen very rarely, and so far only immedeatly after the full buitd. It is always in the TLS1.3 tests with TLS_AES_128_GCM_SHA256 and TLS_AES_256_GCM_SHA384.