search

tempesta-tech / tempesta-test

Test suite for Tempesta FW
10 stars 4 forks source link

Deproxy errors on TCP segmentation tests #512

Closed krizhanovsky closed 4 months ago

krizhanovsky commented 10 months ago

Tempesta master as of 4d16c3ee8294817b1bc15994804d17a7d47a4c22 and tempesa-test master as of d56358ea653dbb367624937197ce5e489abf0b00 . Tests config:

[General]
ip = 127.0.0.1
ipv6 = ::1
verbose = 1
workdir = /tmp/host
duration = 10
concurrent_connections = 10
log_file = tests_log.log
stress_threads = 2
stress_large_content_length = 65536
stress_requests_count = 100
stress_mtu = 1500
long_body_size = 500

[Client]
ip = 127.0.0.1
ipv6 = ::1
hostname = localhost
ab = ab
wrk = /root/wrk/wrk
h2load = h2load
tls-perf = /root/tls-perf/tls-perf
workdir = /tmp/client
unavaliable_timeout = 300

[Tempesta]
ip = 127.0.0.1
ipv6 = ::1
hostname = localhost
user = root
port = 22
srcdir = /root/tempesta
workdir = /tmp/tempesta
config = tempesta.conf
unavaliable_timeout = 300

[Server]
ip = 127.0.0.1
ipv6 = ::1
hostname = localhost
user = root
port = 22
nginx = nginx
workdir = /tmp/nginx
resources = /var/www/html/
aliases_interface = ens3
aliases_base_ip = 192.168.100.4
max_workers = 16
keepalive_timeout = 60
keepalive_requests = 100
unavaliable_timeout = 300

TCP segmentation tests fail with deproxy errors:

# ./run_tests.py -T 1 -n tls.test_tls_integrity
Root privileges are required: need access to module loading on localhost.

----------------------------------------------------------------------
Running functional tests...
----------------------------------------------------------------------

test_various_req_resp_sizes (tls.test_tls_integrity.Proxy) ... ok
test_various_req_resp_sizes (tls.test_tls_integrity.ManyClientsH2) ... Exception in thread Thread-2 (run_deproxy_server):
Traceback (most recent call last):
  File "/usr/lib/python3.10/asyncore.py", line 117, in readwrite
    obj.handle_write_event()
  File "/usr/lib/python3.10/asyncore.py", line 446, in handle_write_event
    self.handle_write()
  File "/root/tempesta-test/framework/deproxy_client.py", line 587, in handle_write
    sent = self.socket.send(chunk)
  File "/usr/lib/python3.10/ssl.py", line 1206, in send
    return self._sslobj.write(data)
ssl.SSLEOFError: EOF occurred in violation of protocol (_ssl.c:2426)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/root/tempesta-test/framework/deproxy_manager.py", line 27, in run_deproxy_server
    poll_fun()
  File "/usr/lib/python3.10/asyncore.py", line 195, in poll2
    readwrite(obj, flags)
  File "/usr/lib/python3.10/asyncore.py", line 124, in readwrite
    obj.handle_error()
  File "/root/tempesta-test/helpers/deproxy.py", line 865, in handle_error
    error.bug("\tDeproxy: Client: %s" % v)
  File "/root/tempesta-test/helpers/error.py", line 44, in bug
    raise Error(msg).with_traceback(exc_info[2])
  File "/usr/lib/python3.10/asyncore.py", line 117, in readwrite
    obj.handle_write_event()
  File "/usr/lib/python3.10/asyncore.py", line 446, in handle_write_event
    self.handle_write()
  File "/root/tempesta-test/framework/deproxy_client.py", line 587, in handle_write
    sent = self.socket.send(chunk)
  File "/usr/lib/python3.10/ssl.py", line 1206, in send
    return self._sslobj.write(data)
helpers.error.Error:    Deproxy: Client: EOF occurred in violation of protocol (_ssl.c:2426) (SSLEOFError: EOF occurred in violation of protocol (_ssl.c:2426))

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3.10/threading.py", line 1016, in _bootstrap_inner
    self.run()
  File "/usr/lib/python3.10/threading.py", line 953, in run
    self._target(*self._args, **self._kwargs)
  File "/root/tempesta-test/framework/deproxy_manager.py", line 34, in run_deproxy_server
    error.bug(f"\n\tDeproxy: Manager:")
  File "/root/tempesta-test/helpers/error.py", line 44, in bug
    raise Error(msg).with_traceback(exc_info[2])
  File "/root/tempesta-test/framework/deproxy_manager.py", line 27, in run_deproxy_server
    poll_fun()
  File "/usr/lib/python3.10/asyncore.py", line 195, in poll2
    readwrite(obj, flags)
  File "/usr/lib/python3.10/asyncore.py", line 124, in readwrite
    obj.handle_error()
  File "/root/tempesta-test/helpers/deproxy.py", line 865, in handle_error
    error.bug("\tDeproxy: Client: %s" % v)
  File "/root/tempesta-test/helpers/error.py", line 44, in bug
    raise Error(msg).with_traceback(exc_info[2])
  File "/usr/lib/python3.10/asyncore.py", line 117, in readwrite
    obj.handle_write_event()
  File "/usr/lib/python3.10/asyncore.py", line 446, in handle_write_event
    self.handle_write()
  File "/root/tempesta-test/framework/deproxy_client.py", line 587, in handle_write
    sent = self.socket.send(chunk)
  File "/usr/lib/python3.10/ssl.py", line 1206, in send
    return self._sslobj.write(data)
helpers.error.Error: 
    Deproxy: Manager: (Error:   Deproxy: Client: EOF occurred in violation of protocol (_ssl.c:2426) (SSLEOFError: EOF occurred in violation of protocol (_ssl.c:2426)))
FAIL
test_various_req_resp_sizes (tls.test_tls_integrity.ManyClients) ... Exception in thread Thread-3 (run_deproxy_server):
Traceback (most recent call last):
  File "/usr/lib/python3.10/asyncore.py", line 117, in readwrite
    obj.handle_write_event()
  File "/usr/lib/python3.10/asyncore.py", line 446, in handle_write_event
    self.handle_write()
  File "/root/tempesta-test/framework/deproxy_server.py", line 100, in handle_write
    sent = self.socket.send(resp[:segment_size])
BlockingIOError: [Errno 11] Resource temporarily unavailable

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/root/tempesta-test/framework/deproxy_manager.py", line 27, in run_deproxy_server
    poll_fun()
  File "/usr/lib/python3.10/asyncore.py", line 195, in poll2
    readwrite(obj, flags)
  File "/usr/lib/python3.10/asyncore.py", line 124, in readwrite
    obj.handle_error()
  File "/root/tempesta-test/framework/deproxy_server.py", line 43, in handle_error
    error.bug("\tDeproxy: SrvConnection: %s" % v)
  File "/root/tempesta-test/helpers/error.py", line 44, in bug
    raise Error(msg).with_traceback(exc_info[2])
  File "/usr/lib/python3.10/asyncore.py", line 117, in readwrite
    obj.handle_write_event()
  File "/usr/lib/python3.10/asyncore.py", line 446, in handle_write_event
    self.handle_write()
  File "/root/tempesta-test/framework/deproxy_server.py", line 100, in handle_write
    sent = self.socket.send(resp[:segment_size])
helpers.error.Error:    Deproxy: SrvConnection: [Errno 11] Resource temporarily unavailable (BlockingIOError: [Errno 11] Resource temporarily unavailable)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3.10/threading.py", line 1016, in _bootstrap_inner
    self.run()
  File "/usr/lib/python3.10/threading.py", line 953, in run
    self._target(*self._args, **self._kwargs)
  File "/root/tempesta-test/framework/deproxy_manager.py", line 34, in run_deproxy_server
    error.bug(f"\n\tDeproxy: Manager:")
  File "/root/tempesta-test/helpers/error.py", line 44, in bug
    raise Error(msg).with_traceback(exc_info[2])
  File "/root/tempesta-test/framework/deproxy_manager.py", line 27, in run_deproxy_server
    poll_fun()
  File "/usr/lib/python3.10/asyncore.py", line 195, in poll2
    readwrite(obj, flags)
  File "/usr/lib/python3.10/asyncore.py", line 124, in readwrite
    obj.handle_error()
  File "/root/tempesta-test/framework/deproxy_server.py", line 43, in handle_error
    error.bug("\tDeproxy: SrvConnection: %s" % v)
  File "/root/tempesta-test/helpers/error.py", line 44, in bug
    raise Error(msg).with_traceback(exc_info[2])
  File "/usr/lib/python3.10/asyncore.py", line 117, in readwrite
    obj.handle_write_event()
  File "/usr/lib/python3.10/asyncore.py", line 446, in handle_write_event
    self.handle_write()
  File "/root/tempesta-test/framework/deproxy_server.py", line 100, in handle_write
    sent = self.socket.send(resp[:segment_size])
helpers.error.Error: 
    Deproxy: Manager: (Error:   Deproxy: SrvConnection: [Errno 11] Resource temporarily unavailable (BlockingIOError: [Errno 11] Resource temporarily unavailable))
FAIL
test7 (tls.test_tls_integrity.CloseConnection) ... ok
test6 (tls.test_tls_integrity.CloseConnection) ... ok
test5 (tls.test_tls_integrity.CloseConnection) ... ok
test4 (tls.test_tls_integrity.CloseConnection) ... ok
test3 (tls.test_tls_integrity.CloseConnection) ... ok
test2 (tls.test_tls_integrity.CloseConnection) ... ok
test1 (tls.test_tls_integrity.CloseConnection) ... ok

======================================================================
FAIL: test_various_req_resp_sizes (tls.test_tls_integrity.ManyClientsH2)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/root/tempesta-test/tls/test_tls_integrity.py", line 251, in test_various_req_resp_sizes
    self.common_check(65536, 65536)
  File "/root/tempesta-test/tls/test_tls_integrity.py", line 320, in common_check
    self.assertTrue(
AssertionError: False is not true : Cannot process request (len=65536) or response (len=65536)

======================================================================
FAIL: test_various_req_resp_sizes (tls.test_tls_integrity.ManyClients)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/root/tempesta-test/tls/test_tls_integrity.py", line 251, in test_various_req_resp_sizes
    self.common_check(65536, 65536)
  File "/root/tempesta-test/tls/test_tls_integrity.py", line 320, in common_check
    self.assertTrue(
AssertionError: False is not true : Cannot process request (len=65536) or response (len=65536)

----------------------------------------------------------------------
Ran 10 tests in 42.098s

FAILED (failures=2)

Full log with verbose = 6 (unpack it with tar --xz -xf tests_log.log.tar.xz.txt) tests_log.log.tar.xz.txt

krizhanovsky commented 10 months ago 
# 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             23.2.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.1+ubuntu0.1
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.1
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.4.0+ubuntu2
python-dateutil        2.8.1
python-debian          0.1.43+ubuntu1.1
python-magic           0.4.24
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.5.6
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 8001
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 10 months ago

Call trace from CI

test_various_req_resp_sizes (tls.test_tls_integrity.ManyClients) ... Exception in thread Thread-11:
Traceback (most recent call last):
  File "/usr/lib/python3.8/asyncore.py", line 110, in readwrite
    obj.handle_write_event()
  File "/usr/lib/python3.8/asyncore.py", line 439, in handle_write_event
    self.handle_write()
  File "/home/jenkins/workspace/_PR_tempesta_PR-1972/tempesta-test/framework/deproxy_server.py", line 100, in handle_write
    sent = self.socket.send(resp[:segment_size])
BlockingIOError: [Errno 11] Resource temporarily unavailable

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/jenkins/workspace/_PR_tempesta_PR-1972/tempesta-test/framework/deproxy_manager.py", line 27, in run_deproxy_server
    poll_fun()
  File "/usr/lib/python3.8/asyncore.py", line 188, in poll2
    readwrite(obj, flags)
  File "/usr/lib/python3.8/asyncore.py", line 117, in readwrite
    obj.handle_error()
  File "/home/jenkins/workspace/_PR_tempesta_PR-1972/tempesta-test/framework/deproxy_server.py", line 43, in handle_error
    error.bug("\tDeproxy: SrvConnection: %s" % v)
  File "/home/jenkins/workspace/_PR_tempesta_PR-1972/tempesta-test/helpers/error.py", line 44, in bug
    raise Error(msg).with_traceback(exc_info[2])
  File "/usr/lib/python3.8/asyncore.py", line 110, in readwrite
    obj.handle_write_event()
  File "/usr/lib/python3.8/asyncore.py", line 439, in handle_write_event
    self.handle_write()
  File "/home/jenkins/workspace/_PR_tempesta_PR-1972/tempesta-test/framework/deproxy_server.py", line 100, in handle_write
    sent = self.socket.send(resp[:segment_size])
helpers.error.Error:    Deproxy: SrvConnection: [Errno 11] Resource temporarily unavailable (BlockingIOError: [Errno 11] Resource temporarily unavailable)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3.8/threading.py", line 932, in _bootstrap_inner
    self.run()
  File "/usr/lib/python3.8/threading.py", line 870, in run
    self._target(*self._args, **self._kwargs)
  File "/home/jenkins/workspace/_PR_tempesta_PR-1972/tempesta-test/framework/deproxy_manager.py", line 34, in run_deproxy_server
    error.bug(f"\n\tDeproxy: Manager:")
  File "/home/jenkins/workspace/_PR_tempesta_PR-1972/tempesta-test/helpers/error.py", line 44, in bug
    raise Error(msg).with_traceback(exc_info[2])
  File "/home/jenkins/workspace/_PR_tempesta_PR-1972/tempesta-test/framework/deproxy_manager.py", line 27, in run_deproxy_server
    poll_fun()
  File "/usr/lib/python3.8/asyncore.py", line 188, in poll2
    readwrite(obj, flags)
  File "/usr/lib/python3.8/asyncore.py", line 117, in readwrite
    obj.handle_error()
  File "/home/jenkins/workspace/_PR_tempesta_PR-1972/tempesta-test/framework/deproxy_server.py", line 43, in handle_error
    error.bug("\tDeproxy: SrvConnection: %s" % v)
  File "/home/jenkins/workspace/_PR_tempesta_PR-1972/tempesta-test/helpers/error.py", line 44, in bug
    raise Error(msg).with_traceback(exc_info[2])
  File "/usr/lib/python3.8/asyncore.py", line 110, in readwrite
    obj.handle_write_event()
  File "/usr/lib/python3.8/asyncore.py", line 439, in handle_write_event
    self.handle_write()
  File "/home/jenkins/workspace/_PR_tempesta_PR-1972/tempesta-test/framework/deproxy_server.py", line 100, in handle_write
    sent = self.socket.send(resp[:segment_size])
helpers.error.Error: 
    Deproxy: Manager: (Error:   Deproxy: SrvConnection: [Errno 11] Resource temporarily unavailable (BlockingIOError: [Errno 11] Resource temporarily unavailable))
FAIL
krizhanovsky commented 10 months ago

My initial test case was run inside a VM with 4GB RAM and I saw OOM in dmesg. When I reran it in a VM with 8GB RAM, the test is successful:

./run_tests.py -T 1 -n tls.test_tls_integrity
Root privileges are required: need access to module loading on localhost.

----------------------------------------------------------------------
Running functional tests...
----------------------------------------------------------------------

test_various_req_resp_sizes (tls.test_tls_integrity.Proxy) ... ok
test_various_req_resp_sizes (tls.test_tls_integrity.ManyClientsH2) ... ok
test_various_req_resp_sizes (tls.test_tls_integrity.ManyClients) ... ok
test7 (tls.test_tls_integrity.CloseConnection) ... ok
test6 (tls.test_tls_integrity.CloseConnection) ... ok
test5 (tls.test_tls_integrity.CloseConnection) ... ok
test4 (tls.test_tls_integrity.CloseConnection) ... ok
test3 (tls.test_tls_integrity.CloseConnection) ... ok
test2 (tls.test_tls_integrity.CloseConnection) ... ok
test1 (tls.test_tls_integrity.CloseConnection) ... ok

----------------------------------------------------------------------
Ran 10 tests in 44.240s

OK
EvgeniiMekhanik commented 4 months ago

This tests fails because of out of memory. I think these tests should be fixed after 498 in tempesta will be implemented.