search

tempesta-tech / tempesta-test

Test suite for Tempesta FW
11 stars 4 forks source link

Blinking tls.test_tls_cert.TlsCertSelect #302

Closed krizhanovsky closed 2 years ago

krizhanovsky commented 2 years ago

The test may fail or not on the current master as of 8efb2353a2b89a542de4e1783f9913fc32b924a7 and Tempesta FW master 1414cf5c285b6fe4acae09c6d1d6f244250d17eb :

# ./run_tests.py -n tls.test_tls_cert.TlsCertSelect
....
----------------------------------------------------------------------
Running functional tests...
----------------------------------------------------------------------

test_vhost_cert_selection (tls.test_tls_cert.TlsCertSelect) ... /root/tempesta-test/tls/scapy_ssl_tls/ssl_tls_crypto.py:1093: UserWarning: Verification of GCM tag failed: MAC check failed
  warnings.warn("Verification of GCM tag failed: %s" % why)
ok

----------------------------------------------------------------------
Ran 1 test in 4.102s

OK
# ./run_tests.py -n tls
...
----------------------------------------------------------------------
Running functional tests...
----------------------------------------------------------------------

test_bad_request (tls.test_tls_basic.TlsBasic) ... ok
test (tls.test_tls_cert.ECDSA_SHA256_SECP192) ... ok
test (tls.test_tls_cert.ECDSA_SHA384_SECP521) ... ok
test (tls.test_tls_cert.InvalidHash) ... ok
test (tls.test_tls_cert.RSA512_SHA256) ... ok
test_vhost_cert_selection (tls.test_tls_cert.TlsCertSelect) ... /root/tempesta-test/tls/scapy_ssl_tls/ssl_tls_crypto.py:1093: UserWarning: Verification of GCM tag failed: MAC check failed
  warnings.warn("Verification of GCM tag failed: %s" % why)
ERROR
test (tls.test_tls_handshake.TlsCertReconfig) ... ok
test_10byte_transfer (tls.test_tls_handshake.TlsHandshakeTest) ... ok
test_1byte_transfer (tls.test_tls_handshake.TlsHandshakeTest) ... ok
test_9byte_transfer (tls.test_tls_handshake.TlsHandshakeTest) ... ok
test_alert (tls.test_tls_handshake.TlsHandshakeTest) ... ok
test_bad_elliptic_curves (tls.test_tls_handshake.TlsHandshakeTest) ... ok
test_bad_renegotiation_info (tls.test_tls_handshake.TlsHandshakeTest) ... ok
test_bad_sign_algs (tls.test_tls_handshake.TlsHandshakeTest) ... ok
test_close_notify (tls.test_tls_handshake.TlsHandshakeTest) ... ok
test_empty_sni_default (tls.test_tls_handshake.TlsHandshakeTest) ... ok
test_fuzzing (tls.test_tls_handshake.TlsHandshakeTest) ...          18009931 function calls (16048739 primitive calls) in 29.966 seconds

   Ordered by: internal time
   List reduced from 671 to 20 due to restriction <20>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
       81   20.028    0.247   20.028    0.247 {method 'recv' of '_socket.socket' objects}
3216928/3148768    1.296    0.000    1.411    0.000 packet.py:399(__setattr__)
       27    0.714    0.026    0.714    0.026 {method 'poll' of 'select.poll' objects}
98818/33408    0.697    0.000    6.581    0.000 packet.py:135(__init__)
  1811040    0.443    0.000    0.595    0.000 dadict.py:71(iterkeys)
202176/33408    0.389    0.000    6.698    0.000 base_classes.py:256(__call__)
     5280    0.355    0.000    1.354    0.000 mib.py:32(_findroot)
482965/3180    0.294    0.000    0.294    0.000 ec.py:12(egcd)
52724/5364    0.285    0.000    2.352    0.000 packet.py:321(copy)
98818/71218    0.274    0.000    1.490    0.000 packet.py:210(do_init_cached_fields)
  3081675    0.266    0.000    0.266    0.000 {built-in method builtins.isinstance}
  1811401    0.216    0.000    0.216    0.000 {method 'startswith' of 'str' objects}
93230/38550    0.215    0.000    1.920    0.000 packet.py:952(loop)
     5280    0.174    0.000    0.769    0.000 dadict.py:76(keys)
225586/85844    0.145    0.000    2.162    0.000 packet.py:535(copy_field_value)
28257/10082    0.142    0.000    0.236    0.000 packet.py:1119(getlayer)
210974/72512    0.138    0.000    2.303    0.000 packet.py:538(copy_fields_dict)
54076/5004    0.131    0.000    0.196    0.000 packet.py:1092(haslayer)
   103358    0.130    0.000    0.154    0.000 packet.py:1537(__new__)
   212805    0.126    0.000    0.183    0.000 six.py:590(iteritems)

ok
test_long_sni (tls.test_tls_handshake.TlsHandshakeTest) ... ok
test_many_ciphers (tls.test_tls_handshake.TlsHandshakeTest) ... ok
test_regression_1 (tls.test_tls_handshake.TlsHandshakeTest) ... ok
test_tls12_synthetic (tls.test_tls_handshake.TlsHandshakeTest) ... ok
test (tls.test_tls_handshake.TlsMissingDefaultKey) ... ok
test_empty_sni_default (tls.test_tls_handshake.TlsVhostHandshakeTest) ... ok
test_vhost_sni (tls.test_tls_handshake.TlsVhostHandshakeTest) ... ok
test_auto_port_mismatch (tls.test_tls_limits.TLSMatchHostSni) ... ok
test_host_sni_bypass_check (tls.test_tls_limits.TLSMatchHostSni) ... ok
test_port_mismatch (tls.test_tls_limits.TLSMatchHostSni) ... ok
test (tls.test_tls_tickets.StandardTlsClient) ... ok
test_invalid_ticket (tls.test_tls_tickets.TlsTicketTest) ... ok
test_no_ticket_support (tls.test_tls_tickets.TlsTicketTest) ... ok
test (tls.test_tls_tickets.TlsVhostConfusion) ... ok
test (tls.test_tls_tickets.TlsVhostConfusionDfltCerts) ... ok
test (tls.test_tls_tickets.TlsVhostConfusionDfltCertsWithUnknown) ... ok

======================================================================
ERROR: test_vhost_cert_selection (tls.test_tls_cert.TlsCertSelect)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/root/tempesta-test/framework/tester.py", line 340, in tearDown
    raise Exception("%s happened during test on Tempesta" % err)
Exception: WARNING happened during test on Tempesta

----------------------------------------------------------------------
Ran 33 tests in 175.375s

FAILED (errors=1)
# ./run_tests.py -n tls.test_tls_cert.TlsCertSelect
...
----------------------------------------------------------------------
Running functional tests...
----------------------------------------------------------------------

test_vhost_cert_selection (tls.test_tls_cert.TlsCertSelect) ... /root/tempesta-test/tls/scapy_ssl_tls/ssl_tls_crypto.py:1093: UserWarning: Verification of GCM tag failed: MAC check failed
  warnings.warn("Verification of GCM tag failed: %s" % why)
ERROR

======================================================================
ERROR: test_vhost_cert_selection (tls.test_tls_cert.TlsCertSelect)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/root/tempesta-test/framework/tester.py", line 340, in tearDown
    raise Exception("%s happened during test on Tempesta" % err)
Exception: WARNING happened during test on Tempesta

----------------------------------------------------------------------
Ran 1 test in 4.775s

FAILED (errors=1)
krizhanovsky commented 2 years ago

Just checked that the issue is still here:

# ./run_tests.py -n tls.test_tls_cert.TlsCertSelect
...
----------------------------------------------------------------------
Running functional tests...
----------------------------------------------------------------------

test_vhost_cert_selection (tls.test_tls_cert.TlsCertSelect) ... /root/tempesta-test/tls/scapy_ssl_tls/ssl_tls_crypto.py:1093: UserWarning: Verification of GCM tag failed: MAC check failed
  warnings.warn("Verification of GCM tag failed: %s" % why)
ok

----------------------------------------------------------------------
Ran 1 test in 4.833s

OK
# ./run_tests.py -n tls.test_tls_cert.TlsCertSelect
.....
----------------------------------------------------------------------
Running functional tests...
----------------------------------------------------------------------

test_vhost_cert_selection (tls.test_tls_cert.TlsCertSelect) ... /root/tempesta-test/tls/scapy_ssl_tls/ssl_tls_crypto.py:1093: UserWarning: Verification of GCM tag failed: MAC check failed
  warnings.warn("Verification of GCM tag failed: %s" % why)
ERROR

======================================================================
ERROR: test_vhost_cert_selection (tls.test_tls_cert.TlsCertSelect)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/root/tempesta-test/framework/tester.py", line 340, in tearDown
    raise Exception("%s happened during test on Tempesta" % err)
Exception: WARNING happened during test on Tempesta

----------------------------------------------------------------------
Ran 1 test in 4.463s

FAILED (errors=1)

Versions of the tests and Tempesta:

# cd ~/tempesta-test && git log|head -1
commit f09b12988cb65be26e438bda428dc9b2246d7ded
# cd ~/tempesta && git log|head -1
commit b54724134d28102e75ea2a5399598fd19fecba89
# pip list
Package                Version
---------------------- -------------
appdirs                1.4.4
attrs                  21.2.0
Automat                20.2.0
awscli                 1.25.18
Babel                  2.8.0
backcall               0.2.0
bcrypt                 3.2.0
beautifulsoup4         4.10.0
beniget                0.4.1
blinker                1.4
boto                   2.49.0
botocore               1.27.18
Brotli                 1.0.9
certifi                2020.6.20
chardet                4.0.0
click                  8.0.3
cloud-init             22.2
colorama               0.4.4
command-not-found      0.3
configobj              5.0.6
constantly             15.1.0
cryptography           3.4.8
cycler                 0.11.0
dbus-python            1.2.18
decorator              4.4.2
distro                 1.7.0
distro-info            1.1build1
docutils               0.16
fonttools              4.29.1
fs                     2.4.12
future                 0.18.2
gast                   0.5.2
gyp                    0.1
h2                     4.1.0
hpack                  4.0.0
html5lib               1.1
httplib2               0.20.2
hyperframe             6.0.1
hyperlink              21.0.0
idna                   3.3
importlib-metadata     4.6.4
incremental            21.3.0
ipython                7.31.1
jedi                   0.18.0
jeepney                0.7.1
Jinja2                 3.0.3
jmespath               1.0.1
jsonpatch              1.32
jsonpointer            2.0
jsonschema             3.2.0
keyring                23.5.0
kiwisolver             1.3.2
launchpadlib           1.10.16
lazr.restfulclient     0.14.4
lazr.uri               1.0.6
lxml                   4.8.0
lz4                    3.1.3+dfsg
MarkupSafe             2.0.1
matplotlib             3.5.1
matplotlib-inline      0.1.3
more-itertools         8.10.0
mpmath                 0.0.0
netifaces              0.11.0
numpy                  1.21.5
oauthlib               3.2.0
olefile                0.46
packaging              21.3
paramiko               2.9.3
parso                  0.8.1
pexpect                4.8.0
pickleshare            0.7.5
Pillow                 9.0.1
pip                    22.0.2
ply                    3.11
prompt-toolkit         3.0.28
ptyprocess             0.7.0
pyasn1                 0.4.8
pyasn1-modules         0.2.1
pycryptodome           3.15.0
pycryptodomex          3.15.0
Pygments               2.11.2
PyGObject              3.42.0
PyHamcrest             2.0.2
PyJWT                  2.3.0
pymacaroons            0.13.0
PyNaCl                 1.5.0
pyOpenSSL              21.0.0
pyparsing              2.4.7
pyrsistent             0.18.1
pyserial               3.5
python-apt             2.3.0+ubuntu2
python-dateutil        2.8.1
python-debian          0.1.43ubuntu1
pythran                0.10.0
pytz                   2022.1
PyYAML                 5.4.1
requests               2.25.1
roman                  3.3
rsa                    4.7.2
s3transfer             0.6.0
scapy                  2.4.4
scipy                  1.8.0
SCons                  4.0.1
SecretStorage          3.3.1
service-identity       18.1.0
setuptools             59.6.0
six                    1.16.0
sos                    4.3
soupsieve              2.3.1
ssh-import-id          5.11
subprocess32           3.5.4
sympy                  1.9
systemd-python         234
tinyec                 0.4.0
traitlets              5.1.1
Twisted                22.1.0
ubuntu-advantage-tools 27.9
ufoLib2                0.13.1
ufw                    0.36.1
unattended-upgrades    0.1
unicodedata2           14.0.0
urllib3                1.26.5
wadllib                1.3.6
wcwidth                0.2.5
webencodings           0.5.1
websockets             10.3
wheel                  0.37.1
wrk                    0.3.2
zipp                   1.0.0
zope.interface         5.4.0
krizhanovsky commented 2 years ago

I made one for unsuccessful test run, i.e. in total there were 1 first successful run followed by 2 unsuccessful. I noticed that there were 2 call traces in big integer arithmetics, so I suppose the problem is on the Tempesta TLS side. See the attached fill serial console log serial-ubuntu.txt

This is ttls_mpi_shift_l() call at https://github.com/tempesta-tech/tempesta/blob/master/tls/bignum.c#L988

krizhanovsky commented 2 years ago

I ran the fix from https://github.com/tempesta-tech/tempesta/pull/1694 20 times for the test and didn't notice a failure.

b3b commented 2 years ago

Warning on tls.test_tls_cert.TlsCertSelect occurs for some of generated certificates. https://github.com/tempesta-tech/tempesta/issues/1683 has example of a certificate causing a warning.

pale-emperor commented 2 years ago

On latest master branches of tempesta-fw and tempesta-test this test fail in all runs - i disable it with issue

krizhanovsky commented 2 years ago

The issue is fixed in https://github.com/tempesta-tech/tempesta/pull/1694