Nir, It looks like we have a race condition where request arrive sooner than subscribe frame:
*16:19:02* 2018-06-27 14:17:54,653 INFO (jsonrpc/0) [jsonrpc.JsonRpcServer] RPC call echo succeeded in 0.01 seconds (__init__:311)*16:19:02* 2018-06-27 14:17:54,661 INFO (Detector thread) [Broker.StompAdapter] Subscribe command received (stompserver:123) Thanks for reporting I will push a patch to fix it. Thanks, Piotr On Wed, Jun 27, 2018 at 5:40 PM, Piotr Kliczewski <[email protected]> wrote: > Ok, I'll take a look. > > śr., 27 cze 2018, 17:36 użytkownik Nir Soffer <[email protected]> > napisał: > >> On Wed, Jun 27, 2018 at 6:13 PM Piotr Kliczewski <[email protected]> >> wrote: >> >>> On Wed, Jun 27, 2018 at 5:01 PM, Nir Soffer <[email protected]> wrote: >>> >>>> This tests used to fail in the past, but since we fixed it or the code >>>> >>>> it never failed. >>>> >>>> >>>> Maybe the slave was overloaded? >>>> >>>> >>> Very possible. Can you paste a link to the job which failed? >>> >> >> Here: https://jenkins.ovirt.org/job/vdsm_master_check- >> patch-el7-x86_64/24130/ >> >> The next build passed. >> >> Maybe we need to solve the flakiness of some tests by running a flaky test >> again, and let the build fail only if a test failed twice. I wonder if >> there is some >> pytest plugin doing this. >> >> >>> >>> >>>> >>>> *14:19:02* >>>> ======================================================================*14:19:02* >>>> ERROR: >>>> >>>> *14:19:02* >>>> ----------------------------------------------------------------------*14:19:02* >>>> Traceback (most recent call last):*14:19:02* File >>>> "/home/jenkins/workspace/vdsm_master_check-patch-el7-x86_64/vdsm/tests/testlib.py", >>>> line 143, in wrapper*14:19:02* return f(self, *args)*14:19:02* File >>>> "/home/jenkins/workspace/vdsm_master_check-patch-el7-x86_64/vdsm/tests/stomp_test.py", >>>> line 95, in test_echo*14:19:02* str(uuid4())),*14:19:02* File >>>> "/home/jenkins/workspace/vdsm_master_check-patch-el7-x86_64/vdsm/lib/yajsonrpc/jsonrpcclient.py", >>>> line 77, in callMethod*14:19:02* raise >>>> exception.JsonRpcNoResponseError(method=methodName)*14:19:02* >>>> JsonRpcNoResponseError: No response for JSON-RPC request: {'method': >>>> 'echo'}*14:19:02* -------------------- >> begin captured logging << >>>> --------------------*14:19:02* 2018-06-27 14:17:54,524 DEBUG (MainThread) >>>> [vds.MultiProtocolAcceptor] Creating socket (host='::1', port=0, >>>> family=10, socketype=1, proto=6) (protocoldetector:225)*14:19:02* >>>> 2018-06-27 14:17:54,526 INFO (MainThread) [vds.MultiProtocolAcceptor] >>>> Listening at ::1:36713 (protocoldetector:183)*14:19:02* 2018-06-27 >>>> 14:17:54,535 DEBUG (MainThread) [Scheduler] Starting scheduler >>>> test.Scheduler (schedule:98)*14:19:02* 2018-06-27 14:17:54,537 DEBUG >>>> (test.Scheduler) [Scheduler] START thread <Thread(test.Scheduler, started >>>> daemon 140562082535168)> (func=<bound method Scheduler._run of >>>> <vdsm.schedule.Scheduler object at 0x7fd74ca00390>>, args=(), kwargs={}) >>>> (concurrent:193)*14:19:02* 2018-06-27 14:17:54,538 DEBUG (test.Scheduler) >>>> [Scheduler] started (schedule:140)*14:19:02* 2018-06-27 14:17:54,546 DEBUG >>>> (JsonRpc (StompReactor)) [root] START thread <Thread(JsonRpc >>>> (StompReactor), started daemon 140562629256960)> (func=<bound method >>>> StompReactor.process_requests of <yajsonrpc.stompserver.StompReactor >>>> object at 0x7fd74ca006d0>>, args=(), kwargs={}) (concurrent:193)*14:19:02* >>>> 2018-06-27 14:17:54,547 DEBUG (MainThread) [Executor] Starting executor >>>> (executor:128)*14:19:02* 2018-06-27 14:17:54,549 DEBUG (MainThread) >>>> [Executor] Starting worker jsonrpc/0 (executor:286)*14:19:02* 2018-06-27 >>>> 14:17:54,553 DEBUG (jsonrpc/0) [Executor] START thread <Thread(jsonrpc/0, >>>> started daemon 140562612471552)> (func=<bound method _Worker._run of >>>> <Worker name=jsonrpc/0 waiting task#=0 at 0x7fd74ca00650>>, args=(), >>>> kwargs={}) (concurrent:193)*14:19:02* 2018-06-27 14:17:54,554 DEBUG >>>> (jsonrpc/0) [Executor] Worker started (executor:298)*14:19:02* 2018-06-27 >>>> 14:17:54,557 DEBUG (MainThread) [Executor] Starting worker jsonrpc/1 >>>> (executor:286)*14:19:02* 2018-06-27 14:17:54,558 DEBUG (MainThread) >>>> [Executor] Starting worker jsonrpc/2 (executor:286)*14:19:02* 2018-06-27 >>>> 14:17:54,559 DEBUG (jsonrpc/2) [Executor] START thread <Thread(jsonrpc/2, >>>> started daemon 140562620864256)> (func=<bound method _Worker._run of >>>> <Worker name=jsonrpc/2 waiting task#=0 at 0x7fd74c9fb350>>, args=(), >>>> kwargs={}) (concurrent:193)*14:19:02* 2018-06-27 14:17:54,560 DEBUG >>>> (jsonrpc/2) [Executor] Worker started (executor:298)*14:19:02* 2018-06-27 >>>> 14:17:54,561 DEBUG (MainThread) [Executor] Starting worker jsonrpc/3 >>>> (executor:286)*14:19:02* 2018-06-27 14:17:54,562 DEBUG (jsonrpc/3) >>>> [Executor] START thread <Thread(jsonrpc/3, started daemon >>>> 140562124498688)> (func=<bound method _Worker._run of <Worker >>>> name=jsonrpc/3 waiting task#=0 at 0x7fd74bc80290>>, args=(), kwargs={}) >>>> (concurrent:193)*14:19:02* 2018-06-27 14:17:54,563 DEBUG (jsonrpc/3) >>>> [Executor] Worker started (executor:298)*14:19:02* 2018-06-27 14:17:54,564 >>>> DEBUG (MainThread) [Executor] Starting worker jsonrpc/4 >>>> (executor:286)*14:19:02* 2018-06-27 14:17:54,565 DEBUG (jsonrpc/4) >>>> [Executor] START thread <Thread(jsonrpc/4, started daemon >>>> 140562116105984)> (func=<bound method _Worker._run of <Worker >>>> name=jsonrpc/4 waiting task#=0 at 0x7fd74bc80790>>, args=(), kwargs={}) >>>> (concurrent:193)*14:19:02* 2018-06-27 14:17:54,566 DEBUG (jsonrpc/4) >>>> [Executor] Worker started (executor:298)*14:19:02* 2018-06-27 14:17:54,568 >>>> DEBUG (jsonrpc/1) [Executor] START thread <Thread(jsonrpc/1, started >>>> daemon 140562132891392)> (func=<bound method _Worker._run of <Worker >>>> name=jsonrpc/1 waiting task#=0 at 0x7fd74c9fb690>>, args=(), kwargs={}) >>>> (concurrent:193)*14:19:02* 2018-06-27 14:17:54,569 DEBUG (jsonrpc/1) >>>> [Executor] Worker started (executor:298)*14:19:02* 2018-06-27 14:17:54,569 >>>> DEBUG (MainThread) [Executor] Starting worker jsonrpc/5 >>>> (executor:286)*14:19:02* 2018-06-27 14:17:54,570 DEBUG (jsonrpc/5) >>>> [Executor] START thread <Thread(jsonrpc/5, started daemon >>>> 140562107713280)> (func=<bound method _Worker._run of <Worker >>>> name=jsonrpc/5 waiting task#=0 at 0x7fd74bc80090>>, args=(), kwargs={}) >>>> (concurrent:193)*14:19:02* 2018-06-27 14:17:54,571 DEBUG (jsonrpc/5) >>>> [Executor] Worker started (executor:298)*14:19:02* 2018-06-27 14:17:54,572 >>>> DEBUG (MainThread) [Executor] Starting worker jsonrpc/6 >>>> (executor:286)*14:19:02* 2018-06-27 14:17:54,580 DEBUG (MainThread) >>>> [Executor] Starting worker jsonrpc/7 (executor:286)*14:19:02* 2018-06-27 >>>> 14:17:54,603 DEBUG (jsonrpc/6) [Executor] START thread <Thread(jsonrpc/6, >>>> started daemon 140562099320576)> (func=<bound method _Worker._run of >>>> <Worker name=jsonrpc/6 waiting task#=0 at 0x7fd74d0dacd0>>, args=(), >>>> kwargs={}) (concurrent:193)*14:19:02* 2018-06-27 14:17:54,604 DEBUG >>>> (jsonrpc/6) [Executor] Worker started (executor:298)*14:19:02* 2018-06-27 >>>> 14:17:54,615 DEBUG (jsonrpc/7) [Executor] START thread <Thread(jsonrpc/7, >>>> started daemon 140562090927872)> (func=<bound method _Worker._run of >>>> <Worker name=jsonrpc/7 waiting task#=0 at 0x7fd74bfe0310>>, args=(), >>>> kwargs={}) (concurrent:193)*14:19:02* 2018-06-27 14:17:54,616 DEBUG >>>> (JsonRpcServer) [root] START thread <Thread(JsonRpcServer, started daemon >>>> 140561730238208)> (func=<bound method JsonRpcServer.serve_requests of >>>> <yajsonrpc.JsonRpcServer object at 0x7fd74ca00690>>, args=(), kwargs={}) >>>> (concurrent:193)*14:19:02* 2018-06-27 14:17:54,618 DEBUG (MainThread) >>>> [vds.MultiProtocolAcceptor] Adding detector >>>> <yajsonrpc.stompserver.StompDetector instance at 0x7fd74c28cc68> >>>> (protocoldetector:210)*14:19:02* 2018-06-27 14:17:54,625 INFO (Detector >>>> thread) [ProtocolDetector.AcceptorImpl] Accepted connection from ::1:52432 >>>> (protocoldetector:61)*14:19:02* 2018-06-27 14:17:54,626 DEBUG (Detector >>>> thread) [ProtocolDetector.Detector] Using required_size=11 >>>> (protocoldetector:89)*14:19:02* 2018-06-27 14:17:54,627 DEBUG (jsonrpc/7) >>>> [Executor] Worker started (executor:298)*14:19:02* 2018-06-27 14:17:54,634 >>>> DEBUG (MainThread) [jsonrpc.AsyncoreClient] Sending response >>>> (stompclient:293)*14:19:02* 2018-06-27 14:17:54,634 DEBUG (Client >>>> ::1:36713) [root] START thread <Thread(Client ::1:36713, started daemon >>>> 140561713452800)> (func=<bound method Reactor.process_requests of >>>> <yajsonrpc.betterAsyncore.Reactor object at 0x7fd74bdb1d90>>, args=(), >>>> kwargs={}) (concurrent:193)*14:19:02* 2018-06-27 14:17:54,641 INFO >>>> (Detector thread) [ProtocolDetector.Detector] Detected protocol stomp from >>>> ::1:52432 (protocoldetector:125)*14:19:02* 2018-06-27 14:17:54,645 INFO >>>> (Detector thread) [Broker.StompAdapter] Processing CONNECT request >>>> (stompserver:94)*14:19:02* 2018-06-27 14:17:54,648 DEBUG (Client >>>> ::1:36713) [yajsonrpc.protocols.stomp.AsyncClient] Stomp connection >>>> established (stompclient:137)*14:19:02* 2018-06-27 14:17:54,651 DEBUG >>>> (jsonrpc/0) [jsonrpc.JsonRpcServer] Calling 'echo' in bridge with [u'Lorem >>>> ipsum dolor sit amet, consectetur adipisicing elit, sed do eiusmod tempor >>>> incididunt ut labore et dolore magna aliqua. Ut enim ad minim veniam, quis >>>> nostrud exercitation ullamco laboris nisi ut aliquip ex ea commodo >>>> consequat. Duis aute irure dolor in reprehenderit in voluptate velit esse >>>> cillum dolore eu fugiat nulla pariatur. Excepteur sint occaecat cupidatat >>>> non proident, sunt in culpa qui officia deserunt mollit anim id est >>>> laborum. Lorem ipsum dolor sit amet, consectetur adipisicing elit, sed do >>>> eiusmod tempor incididunt ut labore et dolore magna aliqua. Ut enim ad >>>> minim veniam, quis nostrud exercitation ullamco laboris nisi ut aliquip ex >>>> ea commodo consequat. Duis aute irure dolor in reprehenderit in voluptate >>>> velit esse cillum dolore eu fugiat nulla pariatur. Excepteur sint occaecat >>>> cupidatat non proident, sunt in culpa qui officia deserunt mollit anim id >>>> est laborum. Lorem ipsum dolor sit amet, consectetur adipisicing elit, sed >>>> do eiusmod tempor incididunt ut labore et dolore magna aliqua. Ut en'] >>>> (__init__:328)*14:19:02* 2018-06-27 14:17:54,652 DEBUG (jsonrpc/0) >>>> [jsonrpc.JsonRpcServer] Return 'echo' in bridge with Lorem ipsum dolor sit >>>> amet, consectetur adipisicing elit, sed do eiusmod tempor incididunt ut >>>> labore et dolore magna aliqua. Ut enim ad minim veniam, quis nostrud >>>> exercitation ullamco laboris nisi ut aliquip ex ea commodo consequat. Duis >>>> aute irure dolor in reprehenderit in voluptate velit esse cillum dolore eu >>>> fugiat nulla pariatur. Excepteur sint occaecat cupidatat non proident, >>>> sunt in culpa qui officia deserunt mollit anim id est laborum. Lorem ipsum >>>> dolor sit amet, consectetur adipisicing elit, sed do eiusmod tempor >>>> incididunt ut labore et dolore magna aliqua. Ut enim ad minim veniam, quis >>>> nostrud exercitation ullamco laboris nisi ut aliquip ex ea commodo >>>> consequat. Duis aute irure dolor in reprehenderit in voluptate velit esse >>>> cillum dolore eu fugiat nulla pariatur. Excepteur sint occaecat cupidatat >>>> non proident, sunt in culpa qui officia deserunt mollit anim id est >>>> laborum. Lorem ipsum dolor sit amet, consectetur adipisicing elit, sed do >>>> eiusmod tempor incididunt ut labore et dolore magna aliqua. Ut en >>>> (__init__:355)*14:19:02* 2018-06-27 14:17:54,653 INFO (jsonrpc/0) >>>> [jsonrpc.JsonRpcServer] RPC call echo succeeded in 0.01 seconds >>>> (__init__:311)*14:19:02* 2018-06-27 14:17:54,661 INFO (Detector thread) >>>> [Broker.StompAdapter] Subscribe command received >>>> (stompserver:123)*14:19:02* 2018-06-27 14:17:54,662 DEBUG (Detector >>>> thread) [protocoldetector.StompDetector] Stomp detected from ('::1', >>>> 52432) (stompserver:412)*14:19:02* 2018-06-27 14:18:09,649 DEBUG >>>> (MainThread) [vds.MultiProtocolAcceptor] Stopping Acceptor >>>> (protocoldetector:214)*14:19:02* 2018-06-27 14:18:09,650 INFO >>>> (MainThread) [jsonrpc.JsonRpcServer] Stopping JsonRPC Server >>>> (__init__:441)*14:19:02* 2018-06-27 14:18:09,651 DEBUG (MainThread) >>>> [Executor] Stopping executor (executor:137)*14:19:02* 2018-06-27 >>>> 14:18:09,652 DEBUG (Client ::1:36713) [root] FINISH thread <Thread(Client >>>> ::1:36713, started daemon 140561713452800)> (concurrent:196)*14:19:02* >>>> 2018-06-27 14:18:09,652 DEBUG (JsonRpcServer) [root] FINISH thread >>>> <Thread(JsonRpcServer, started daemon 140561730238208)> >>>> (concurrent:196)*14:19:02* 2018-06-27 14:18:09,654 DEBUG (JsonRpc >>>> (StompReactor)) [root] FINISH thread <Thread(JsonRpc (StompReactor), >>>> started daemon 140562629256960)> (concurrent:196)*14:19:02* 2018-06-27 >>>> 14:18:09,655 DEBUG (jsonrpc/2) [Executor] Worker stopped >>>> (executor:303)*14:19:02* 2018-06-27 14:18:09,658 DEBUG (jsonrpc/3) >>>> [Executor] Worker stopped (executor:303)*14:19:02* 2018-06-27 14:18:09,659 >>>> DEBUG (jsonrpc/4) [Executor] Worker stopped (executor:303)*14:19:02* >>>> 2018-06-27 14:18:09,660 DEBUG (jsonrpc/1) [Executor] Worker stopped >>>> (executor:303)*14:19:02* 2018-06-27 14:18:09,660 DEBUG (jsonrpc/5) >>>> [Executor] Worker stopped (executor:303)*14:19:02* 2018-06-27 14:18:09,660 >>>> DEBUG (jsonrpc/6) [Executor] Worker stopped (executor:303)*14:19:02* >>>> 2018-06-27 14:18:09,665 DEBUG (jsonrpc/6) [Executor] FINISH thread >>>> <Thread(jsonrpc/6, started daemon 140562099320576)> >>>> (concurrent:196)*14:19:02* 2018-06-27 14:18:09,661 DEBUG (jsonrpc/7) >>>> [Executor] Worker stopped (executor:303)*14:19:02* 2018-06-27 14:18:09,662 >>>> DEBUG (jsonrpc/2) [Executor] FINISH thread <Thread(jsonrpc/2, started >>>> daemon 140562620864256)> (concurrent:196)*14:19:02* 2018-06-27 >>>> 14:18:09,663 DEBUG (jsonrpc/3) [Executor] FINISH thread <Thread(jsonrpc/3, >>>> started daemon 140562124498688)> (concurrent:196)*14:19:02* 2018-06-27 >>>> 14:18:09,663 DEBUG (jsonrpc/1) [Executor] FINISH thread <Thread(jsonrpc/1, >>>> started daemon 140562132891392)> (concurrent:196)*14:19:02* 2018-06-27 >>>> 14:18:09,664 DEBUG (jsonrpc/4) [Executor] FINISH thread <Thread(jsonrpc/4, >>>> started daemon 140562116105984)> (concurrent:196)*14:19:02* 2018-06-27 >>>> 14:18:09,664 DEBUG (jsonrpc/0) [Executor] Worker stopped >>>> (executor:303)*14:19:02* 2018-06-27 14:18:09,665 DEBUG (jsonrpc/5) >>>> [Executor] FINISH thread <Thread(jsonrpc/5, started daemon >>>> 140562107713280)> (concurrent:196)*14:19:02* 2018-06-27 14:18:09,667 DEBUG >>>> (jsonrpc/7) [Executor] FINISH thread <Thread(jsonrpc/7, started daemon >>>> 140562090927872)> (concurrent:196)*14:19:02* 2018-06-27 14:18:09,667 DEBUG >>>> (MainThread) [Executor] Waiting for worker jsonrpc/0 >>>> (executor:290)*14:19:02* 2018-06-27 14:18:09,671 DEBUG (jsonrpc/0) >>>> [Executor] FINISH thread <Thread(jsonrpc/0, started daemon >>>> 140562612471552)> (concurrent:196)*14:19:02* 2018-06-27 14:18:09,673 DEBUG >>>> (MainThread) [Executor] Waiting for worker jsonrpc/1 >>>> (executor:290)*14:19:02* 2018-06-27 14:18:09,674 DEBUG (MainThread) >>>> [Executor] Waiting for worker jsonrpc/6 (executor:290)*14:19:02* >>>> 2018-Coverage.py warning: Module >>>> /home/jenkins/workspace/vdsm_master_check-patch-el7-x86_64/vdsm/vdsm was >>>> never imported. (module-not-imported)*14:19:05* pylint installdeps: >>>> pylint==1.8*14:19:22* pylint installed: The directory >>>> '/home/jenkins/workspace/vdsm_master_check-patch-el7-x86_64/vdsm/.cache/pip/http' >>>> or its parent directory is not owned by the current user and the cache >>>> has been disabled. Please check the permissions and owner of that >>>> directory. If executing pip with sudo, you may want sudo's -H >>>> flag.,astroid==1.6.5,backports.functools-lru-cache==1.5,backports.ssl-match-hostname==3.5.0.1,blivet==0.61.15.69,chardet==2.2.1,configparser==3.5.0,coverage==4.4.1,decorator==3.4.0,enum34==1.1.6,funcsigs==1.0.2,futures==3.2.0,iniparse==0.4,ioprocess==1.1.0,ipaddress==1.0.16,IPy==0.75,isort==4.3.4,kitchen==1.1.1,lazy-object-proxy==1.3.1,libvirt-python==3.9.0,Magic-file-extensions==0.2,mccabe==0.6.1,mock==2.0.0,netaddr==0.7.18,ovirt-imageio-common==1.4.1,pbr==3.1.1,pluggy==0.6.0,policycoreutils-default-encoding==0.1,pthreading==0.1.3,py==1.5.4,pycurl==7.19.0,pygpgme==0.3,pyinotify==0.9.4,pykickstart==1.99.66.18,pyliblzma==0.5.3,pylint==1.8.0,pyparted==3.9,python-augeas==0.5.0,python-dateutil==2.4.2,pyudev==0.15,pyxattr==0.5.1,PyYAML==3.10,requests==2.6.0,sanlock-python==3.6.0,seobject==0.1,sepolicy==1.1,singledispatch==3.4.0.3,six==1.11.0,subprocess32==3.2.6,tox==2.9.1,urlgrabber==3.10,urllib3==1.10.2,virtualenv==16.0.0,WebOb==1.2.3,wrapt==1.10.11,yum-metadata-parser==1.1.4*14:19:22* >>>> pylint runtests: PYTHONHASHSEED='528910716'*14:19:22* pylint runtests: >>>> commands[0] | pylint --errors-only static/usr/share/vdsm/sitecustomize.py >>>> lib/vdsm lib/vdsmclient lib/yajsonrpc*14:19:23* Problem importing module >>>> base.pyc: cannot import name get_node_last_lineno*14:19:24* Problem >>>> importing module base.py: cannot import name >>>> get_node_last_lineno*14:19:34* 06-27 14:18:09,674 DEBUG (MainThread) >>>> [Executor] Waiting for worker jsonrpc/7 (executor:290)*14:19:34* >>>> 2018-06-27 14:18:09,675 DEBUG (MainThread) [Executor] Waiting for worker >>>> jsonrpc/5 (executor:290)*14:19:34* 2018-06-27 14:18:09,675 DEBUG >>>> (MainThread) [Executor] Waiting for worker jsonrpc/2 >>>> (executor:290)*14:19:34* 2018-06-27 14:18:09,676 DEBUG (MainThread) >>>> [Executor] Waiting for worker jsonrpc/3 (executor:290)*14:19:34* >>>> 2018-06-27 14:18:09,676 DEBUG (MainThread) [Executor] Waiting for worker >>>> jsonrpc/4 (executor:290)*14:19:34* 2018-06-27 14:18:09,677 DEBUG >>>> (MainThread) [Scheduler] Stopping scheduler test.Scheduler >>>> (schedule:110)*14:19:34* 2018-06-27 14:18:09,678 DEBUG (test.Scheduler) >>>> [Scheduler] stopped (schedule:143)*14:19:34* 2018-06-27 14:18:09,679 DEBUG >>>> (test.Scheduler) [Scheduler] FINISH thread <Thread(test.Scheduler, started >>>> daemon 140562082535168)> (concurrent:196)*14:19:34* --------------------- >>>> >> end captured logging << --------------------- >>>> >>>> >>>>
_______________________________________________ Devel mailing list -- [email protected] To unsubscribe send an email to [email protected] Privacy Statement: https://www.ovirt.org/site/privacy-policy/ oVirt Code of Conduct: https://www.ovirt.org/community/about/community-guidelines/ List Archives: https://lists.ovirt.org/archives/list/[email protected]/message/ACPGZ4N3ULQ6GJNEGJCYJ6NASDHRYNYL/
