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

On Tue, Dec 17, 2019 at 7:37 PM Nir Soffer <nsoffer(a)redhat.com&gt; wrote: > 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. Looks like I have bad luck today with jsonrpc tests, here is another failure of another test: JsonRpcServerTests.testClientNotify https://jenkins.ovirt.org/job/vdsm_standard-check-patch/15981//artifact/c...

> 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, >> JsonRpcInternalError().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 ============================