[ovirt-devel] Flaky jsonrpc test? looks like timeout

I had this failure today, that looks like a timeout, based on the test duration: 18.16s call tests/lib/yajsonrpc/jsonrpcserver_test.py::JsonRpcServerTests::testMethodBadParameters(True) Looking at the log it smells like the known race when connecting to server. Also we see: - ERROR vds.dispatcher:betterAsyncore.py:179 uncaptured python exception, closing channel Should never happen, means we did not handle exceptions in some handler. - WARNING vds.dispatcher:betterAsyncore.py:179 unhandled write event Should not happen, means that we did not implement handle_write() in some dispatcher. See logs below. Nir --- Build log: https://jenkins.ovirt.org/job/vdsm_standard-check-patch/15978//artifact/c... Error: =================================== FAILURES =================================== _______________ JsonRpcServerTests.testMethodBadParameters(True) _______________ self = <jsonrpcserver_test.JsonRpcServerTests testMethod=testMethodBadParameters(True)> use_ssl = True @permutations(USE_SSL) def testMethodBadParameters(self, use_ssl): # Without a schema the server returns an internal error ssl_ctx = self.ssl_ctx if use_ssl else None bridge = _DummyBridge() with constructClient(self.log, bridge, ssl_ctx) as clientFactory: with self._client(clientFactory) as client: with self.assertRaises(JsonRpcErrorBase) as cm: self._callTimeout(client, "echo", [], CALL_ID) self.assertEqual(cm.exception.code, E AssertionError: -32605 != -32603 lib/yajsonrpc/jsonrpcserver_test.py:209: AssertionError ------------------------------ Captured log call ------------------------------- WARNING vds.dispatcher:betterAsyncore.py:179 unhandled write event ERROR vds.dispatcher:betterAsyncore.py:179 uncaptured python exception, closing channel <yajsonrpc.betterAsyncore.Dispatcher ('::1', 40156, 0, 0) at 0x7f842cd7d7f0> (<class 'ValueError'>:'b'ept-version:1.2'' contains illegal character ':' [/usr/lib64/python3.6/asyncore.py|readwrite|108] [/usr/lib64/python3.6/asyncore.py|handle_read_event|423] [/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/lib/yajsonrpc/betterAsyncore.py|handle_read|71] [/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/lib/yajsonrpc/betterAsyncore.py|_delegate_call|168] [/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/lib/vdsm/protocoldetector.py|handle_read|129] [/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/lib/yajsonrpc/stompserver.py|handle_socket|413] [/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/lib/vdsm/rpc/bindingjsonrpc.py|add_socket|54] [/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/lib/yajsonrpc/stompserver.py|createListener|379] [/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/lib/yajsonrpc/stompserver.py|StompListener|345] [/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/lib/yajsonrpc/betterAsyncore.py|__init__|47] [/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/lib/yajsonrpc/betterAsyncore.py|switch_implementation|86] [/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/lib/yajsonrpc/stompserver.py|init|363] [/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/lib/vdsm/rpc/bindingjsonrpc.py|_onAccept|57] [/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/lib/yajsonrpc/stomp.py|set_message_handler|645] [/usr/lib64/python3.6/asyncore.py|handle_read_event|423] [/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/lib/yajsonrpc/betterAsyncore.py|handle_read|71] [/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/lib/yajsonrpc/betterAsyncore.py|_delegate_call|168] [/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/lib/yajsonrpc/stomp.py|handle_read|421] [/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/lib/yajsonrpc/stomp.py|parse|323] [/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/lib/yajsonrpc/stomp.py|_parse_command|245] [/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/lib/yajsonrpc/stomp.py|decode_value|167]) WARNING vds.dispatcher:betterAsyncore.py:179 unhandled close event =============================== warnings summary =============================== /home/jenkins/workspace/vdsm_standard-check-patch/vdsm/.tox/lib/lib/python3.6/site-packages/_pytest/mark/structures.py:334 /home/jenkins/workspace/vdsm_standard-check-patch/vdsm/.tox/lib/lib/python3.6/site-packages/_pytest/mark/structures.py:334: PytestUnknownMarkWarning: Unknown pytest.mark.stress - is this a typo? You can register custom marks to avoid this warning - for details, see https://docs.pytest.org/en/latest/mark.html PytestUnknownMarkWarning, /home/jenkins/workspace/vdsm_standard-check-patch/vdsm/.tox/lib/lib/python3.6/site-packages/_pytest/mark/structures.py:334 /home/jenkins/workspace/vdsm_standard-check-patch/vdsm/.tox/lib/lib/python3.6/site-packages/_pytest/mark/structures.py:334: PytestUnknownMarkWarning: Unknown pytest.mark.slow - is this a typo? You can register custom marks to avoid this warning - for details, see https://docs.pytest.org/en/latest/mark.html PytestUnknownMarkWarning, /home/jenkins/workspace/vdsm_standard-check-patch/vdsm/lib/vdsm/network/models.py:442 /home/jenkins/workspace/vdsm_standard-check-patch/vdsm/lib/vdsm/network/models.py:442: DeprecationWarning: invalid escape sequence \D nicsRexp = re.compile("^(\D*)(\d*)(.*)$") /home/jenkins/workspace/vdsm_standard-check-patch/vdsm/lib/vdsm/network/link/validator.py:38 /home/jenkins/workspace/vdsm_standard-check-patch/vdsm/lib/vdsm/network/link/validator.py:38: DeprecationWarning: invalid escape sequence \w bond for bond in bonds if not re.match('^bond\w+$', bond) /home/jenkins/workspace/vdsm_standard-check-patch/vdsm/lib/vdsm/network/link/validator.py:44 /home/jenkins/workspace/vdsm_standard-check-patch/vdsm/lib/vdsm/network/link/validator.py:44: DeprecationWarning: invalid escape sequence \w and not re.match('^bond\w+$', net_attrs['bonding']) /home/jenkins/workspace/vdsm_standard-check-patch/vdsm/lib/vdsm/v2v.py:78 /home/jenkins/workspace/vdsm_standard-check-patch/vdsm/lib/vdsm/v2v.py:78: DeprecationWarning: invalid escape sequence \d _SSH_AUTH_RE = b'(SSH_AUTH_SOCK)=([^;]+).*;\nSSH_AGENT_PID=(\d+)' /home/jenkins/workspace/vdsm_standard-check-patch/vdsm/lib/vdsm/v2v.py:1420 /home/jenkins/workspace/vdsm_standard-check-patch/vdsm/lib/vdsm/v2v.py:1420: DeprecationWarning: invalid escape sequence \^ '(?P<m2_base>[0-9]+){sp}\^{sp}(?P<m2_exp>{exp}))'.format( /home/jenkins/workspace/vdsm_standard-check-patch/vdsm/.tox/lib/lib/python3.6/site-packages/_pytest/mark/structures.py:334 /home/jenkins/workspace/vdsm_standard-check-patch/vdsm/.tox/lib/lib/python3.6/site-packages/_pytest/mark/structures.py:334: PytestUnknownMarkWarning: Unknown pytest.mark.xpass - is this a typo? You can register custom marks to avoid this warning - for details, see https://docs.pytest.org/en/latest/mark.html PytestUnknownMarkWarning, -- Docs: https://docs.pytest.org/en/latest/warnings.html ----------- coverage: platform linux, python 3.6.8-final-0 ----------- Coverage HTML written to dir htmlcov-lib ========================== slowest 10 test durations =========================== 18.16s call tests/lib/yajsonrpc/jsonrpcserver_test.py::JsonRpcServerTests::testMethodBadParameters(True) 2.92s call tests/lib/protocoldetector_test.py::AcceptorTests::test_reject_very_slow_client_concurrency(False) 2.86s call tests/lib/protocoldetector_test.py::AcceptorTests::test_reject_very_slow_client(True) 2.76s call tests/lib/protocoldetector_test.py::AcceptorTests::test_reject_very_slow_client_concurrency(True) 2.63s call tests/lib/protocoldetector_test.py::AcceptorTests::test_reject_very_slow_client(False) 1.28s call tests/pywatch_test.py::TestPyWatch::test_timeout_backtrace 0.89s call tests/pywatch_test.py::TestPyWatch::test_kill_grandkids 0.89s call tests/lib/protocoldetector_test.py::AcceptorTests::test_detect_slow_client_concurrency(True) 0.88s call tests/pywatch_test.py::TestPyWatch::test_timeout_output 0.80s call tests/lib/protocoldetector_test.py::AcceptorTests::test_detect_slow_client(False) =========================== short test summary info ============================