4:15 p.m.
Recently this test cause too many random failures. I guess this is
the known issue with handling SUBSCRIBE in protocol detector.
I posted https://gerrit.ovirt.org/c/97099/
To mark it as broken until we have time to dig deeper
======================================================================
FAIL: test_detect_slow_client_concurrency(True)
(protocoldetector_test.AcceptorTests)
----------------------------------------------------------------------
Traceback (most recent call last):
File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/testlib.py",
line 142, in wrapper
return f(self, *args)
File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/protocoldetector_test.py",
line 167, in test_detect_slow_client_concurrency
self.check_concurrently(self.check_slow_client, use_ssl)
File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/protocoldetector_test.py",
line 266, in check_concurrently
self.assertTrue(all(done))
AssertionError: False is not true
-------------------- >> begin captured logging << --------------------
2019-01-19 20:47:16,021 DEBUG (MainThread) [vds.MultiProtocolAcceptor]
Creating socket (host='127.0.0.1', port=0, family=2, socketype=1,
proto=6) (protocoldetector:225)
2019-01-19 20:47:16,022 INFO (MainThread) [vds.MultiProtocolAcceptor]
Listening at 127.0.0.1:46009 (protocoldetector:183)
2019-01-19 20:47:16,023 DEBUG (MainThread) [vds.MultiProtocolAcceptor]
Adding detector <protocoldetector_test.Echo object at 0x7f1bb77f8dd0>
(protocoldetector:210)
2019-01-19 20:47:16,024 DEBUG (MainThread) [vds.MultiProtocolAcceptor]
Adding detector <protocoldetector_test.Uppercase object at
0x7f1bb77f8c90> (protocoldetector:210)
2019-01-19 20:47:16,031 INFO (Thread-61)
[ProtocolDetector.AcceptorImpl] Accepted connection from
127.0.0.1:51950 (protocoldetector:61)
2019-01-19 20:47:16,047 INFO (Thread-61)
[ProtocolDetector.AcceptorImpl] Accepted connection from
127.0.0.1:51952 (protocoldetector:61)
2019-01-19 20:47:16,048 INFO (Thread-61)
[ProtocolDetector.AcceptorImpl] Accepted connection from
127.0.0.1:51954 (protocoldetector:61)
2019-01-19 20:47:16,065 INFO (Thread-61)
[ProtocolDetector.AcceptorImpl] Accepted connection from
127.0.0.1:51956 (protocoldetector:61)
2019-01-19 20:47:16,068 INFO (Thread-61)
[ProtocolDetector.AcceptorImpl] Accepted connection from
127.0.0.1:51958 (protocoldetector:61)
2019-01-19 20:47:16,069 DEBUG (Thread-61) [ProtocolDetector.Detector]
Using required_size=9 (protocoldetector:89)
2019-01-19 20:47:16,097 DEBUG (Thread-61) [ProtocolDetector.Detector]
Using required_size=9 (protocoldetector:89)
2019-01-19 20:47:16,099 DEBUG (Thread-61) [ProtocolDetector.Detector]
Using required_size=9 (protocoldetector:89)
2019-01-19 20:47:16,107 DEBUG (Thread-61) [ProtocolDetector.Detector]
Using required_size=9 (protocoldetector:89)
2019-01-19 20:47:16,109 DEBUG (Thread-61) [ProtocolDetector.Detector]
Using required_size=9 (protocoldetector:89)
2019-01-19 20:47:16,574 INFO (Thread-61) [ProtocolDetector.Detector]
Detected protocol echo from 127.0.0.1:51950 (protocoldetector:125)
2019-01-19 20:47:17,570 DEBUG (Thread-61) [ProtocolDetector.Detector]
Timed out while waiting for data (protocoldetector:94)
2019-01-19 20:47:17,571 DEBUG (Thread-61) [ProtocolDetector.Detector]
Timed out while waiting for data (protocoldetector:94)
2019-01-19 20:47:17,576 DEBUG (Thread-61) [ProtocolDetector.Detector]
Timed out while waiting for data (protocoldetector:94)
2019-01-19 20:47:17,578 DEBUG (Thread-61) [ProtocolDetector.Detector]
Timed out while waiting for data (protocoldetector:94)
--------------------- >> end captured logging << ---------------------
6:56 p.m.
On Sat, Jan 19, 2019 at 11:15 PM Nir Soffer <nsoffer(a)redhat.com> wrote:
Recently this test cause too many random failures. I guess this is
the known issue with handling SUBSCRIBE in protocol detector.
I posted https://gerrit.ovirt.org/c/97099/
To mark it as broken until we have time to dig deeper
======================================================================
FAIL: test_detect_slow_client_concurrency(True) (protocoldetector_test.AcceptorTests)
----------------------------------------------------------------------
Traceback (most recent call last):
File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/testlib.py", line
142, in wrapper
return f(self, *args)
File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/protocoldetector_test.py",
line 167, in test_detect_slow_client_concurrency
self.check_concurrently(self.check_slow_client, use_ssl)
File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/protocoldetector_test.py",
line 266, in check_concurrently
self.assertTrue(all(done))
AssertionError: False is not true
-------------------- >> begin captured logging << --------------------
2019-01-19 20:47:16,021 DEBUG (MainThread) [vds.MultiProtocolAcceptor] Creating socket
(host='127.0.0.1', port=0, family=2, socketype=1, proto=6) (protocoldetector:225)
2019-01-19 20:47:16,022 INFO (MainThread) [vds.MultiProtocolAcceptor] Listening at
127.0.0.1:46009 (protocoldetector:183)
2019-01-19 20:47:16,023 DEBUG (MainThread) [vds.MultiProtocolAcceptor] Adding detector
<protocoldetector_test.Echo object at 0x7f1bb77f8dd0> (protocoldetector:210)
2019-01-19 20:47:16,024 DEBUG (MainThread) [vds.MultiProtocolAcceptor] Adding detector
<protocoldetector_test.Uppercase object at 0x7f1bb77f8c90> (protocoldetector:210)
2019-01-19 20:47:16,031 INFO (Thread-61) [ProtocolDetector.AcceptorImpl] Accepted
connection from 127.0.0.1:51950 (protocoldetector:61)
2019-01-19 20:47:16,047 INFO (Thread-61) [ProtocolDetector.AcceptorImpl] Accepted
connection from 127.0.0.1:51952 (protocoldetector:61)
2019-01-19 20:47:16,048 INFO (Thread-61) [ProtocolDetector.AcceptorImpl] Accepted
connection from 127.0.0.1:51954 (protocoldetector:61)
2019-01-19 20:47:16,065 INFO (Thread-61) [ProtocolDetector.AcceptorImpl] Accepted
connection from 127.0.0.1:51956 (protocoldetector:61)
2019-01-19 20:47:16,068 INFO (Thread-61) [ProtocolDetector.AcceptorImpl] Accepted
connection from 127.0.0.1:51958 (protocoldetector:61)
2019-01-19 20:47:16,069 DEBUG (Thread-61) [ProtocolDetector.Detector] Using
required_size=9 (protocoldetector:89)
2019-01-19 20:47:16,097 DEBUG (Thread-61) [ProtocolDetector.Detector] Using
required_size=9 (protocoldetector:89)
2019-01-19 20:47:16,099 DEBUG (Thread-61) [ProtocolDetector.Detector] Using
required_size=9 (protocoldetector:89)
2019-01-19 20:47:16,107 DEBUG (Thread-61) [ProtocolDetector.Detector] Using
required_size=9 (protocoldetector:89)
2019-01-19 20:47:16,109 DEBUG (Thread-61) [ProtocolDetector.Detector] Using
required_size=9 (protocoldetector:89)
2019-01-19 20:47:16,574 INFO (Thread-61) [ProtocolDetector.Detector] Detected protocol
echo from 127.0.0.1:51950 (protocoldetector:125)
2019-01-19 20:47:17,570 DEBUG (Thread-61) [ProtocolDetector.Detector] Timed out while
waiting for data (protocoldetector:94)
2019-01-19 20:47:17,571 DEBUG (Thread-61) [ProtocolDetector.Detector] Timed out while
waiting for data (protocoldetector:94)
2019-01-19 20:47:17,576 DEBUG (Thread-61) [ProtocolDetector.Detector] Timed out while
waiting for data (protocoldetector:94)
2019-01-19 20:47:17,578 DEBUG (Thread-61) [ProtocolDetector.Detector] Timed out while
waiting for data (protocoldetector:94)
--------------------- >> end captured logging << ---------------------
Another flaky test - we marked the other test in this class as broken on ci
recently. This test fail randomly from time to time.
======================================================================
ERROR: test_event(False) (stomp_test.StompTests)
----------------------------------------------------------------------
Traceback (most recent call last):
File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/testlib.py",
line 142, in wrapper
return f(self, *args)
File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/stomp_test.py",
line 118, in test_event
client.callMethod("event", [], str(uuid4()))
File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/lib/yajsonrpc/jsonrpcclient.py",
line 78, in callMethod
raise exception.JsonRpcNoResponseError(method=methodName)
JsonRpcNoResponseError: No response for JSON-RPC request: {'method':
'event'}
-------------------- >> begin captured logging << --------------------
2019-01-21 23:41:32,132 DEBUG (MainThread) [vds.MultiProtocolAcceptor]
Creating socket (host='::1', port=0, family=10, socketype=1, proto=6)
(protocoldetector:225)
2019-01-21 23:41:32,133 INFO (MainThread) [vds.MultiProtocolAcceptor]
Listening at ::1:46303 (protocoldetector:183)
2019-01-21 23:41:32,134 DEBUG (MainThread) [Scheduler] Starting
scheduler test.Scheduler (schedule:98)
2019-01-21 23:41:32,135 DEBUG (test.Scheduler) [Scheduler] START
thread <Thread(test.Scheduler, started daemon 140162734585600)>
(func=<bound method Scheduler._run of <vdsm.schedule.Scheduler object
at 0x7f7a2c156e10>>, args=(), kwargs={}) (concurrent:193)
2019-01-21 23:41:32,138 DEBUG (test.Scheduler) [Scheduler] started
(schedule:140)
2019-01-21 23:41:32,139 DEBUG (JsonRpc (StompReactor)) [root] START
thread <Thread(JsonRpc (StompReactor), started daemon
140162271528704)> (func=<bound method StompReactor.process_requests of
<yajsonrpc.stompserver.StompReactor object at 0x7f7a2c177950>>,
args=(), kwargs={}) (concurrent:193)
2019-01-21 23:41:32,139 DEBUG (MainThread) [Executor] Starting
executor (executor:128)
2019-01-21 23:41:32,141 DEBUG (MainThread) [Executor] Starting worker
jsonrpc/0 (executor:286)
2019-01-21 23:41:32,142 DEBUG (MainThread) [Executor] Starting worker
jsonrpc/1 (executor:286)
2019-01-21 23:41:32,143 DEBUG (jsonrpc/1) [Executor] START thread
<Thread(jsonrpc/1, started daemon 140162288314112)> (func=<bound
method _Worker._run of <Worker name=jsonrpc/1 waiting task#=0 at
0x7f7a2c177510>>, args=(), kwargs={}) (concurrent:193)
2019-01-21 23:41:32,144 DEBUG (MainThread) [Executor] Starting worker
jsonrpc/2 (executor:286)
2019-01-21 23:41:32,144 DEBUG (jsonrpc/0) [Executor] START thread
<Thread(jsonrpc/0, started daemon 140162263136000)> (func=<bound
method _Worker._run of <Worker name=jsonrpc/0 waiting task#=0 at
0x7f7a2c177d50>>, args=(), kwargs={}) (concurrent:193)
2019-01-21 23:41:32,145 DEBUG (jsonrpc/1) [Executor] Worker started
(executor:298)
2019-01-21 23:41:32,147 DEBUG (MainThread) [Executor] Starting worker
jsonrpc/3 (executor:286)
2019-01-21 23:41:32,148 DEBUG (jsonrpc/2) [Executor] START thread
<Thread(jsonrpc/2, started daemon 140162751371008)> (func=<bound
method _Worker._run of <Worker name=jsonrpc/2 waiting task#=0 at
0x7f7a2c177ad0>>, args=(), kwargs={}) (concurrent:193)
2019-01-21 23:41:32,149 DEBUG (jsonrpc/0) [Executor] Worker started
(executor:298)
2019-01-21 23:41:32,153 DEBUG (jsonrpc/2) [Executor] Worker started
(executor:298)
2019-01-21 23:41:32,154 DEBUG (MainThread) [Executor] Starting worker
jsonrpc/4 (executor:286)
2019-01-21 23:41:32,155 DEBUG (jsonrpc/3) [Executor] START thread
<Thread(jsonrpc/3, started daemon 140162742978304)> (func=<bound
method _Worker._run of <Worker name=jsonrpc/3 waiting task#=0 at
0x7f7a2c112e10>>, args=(), kwargs={}) (concurrent:193)
2019-01-21 23:41:32,158 DEBUG (jsonrpc/3) [Executor] Worker started
(executor:298)
2019-01-21 23:41:32,159 DEBUG (MainThread) [Executor] Starting worker
jsonrpc/5 (executor:286)
2019-01-21 23:41:32,160 DEBUG (jsonrpc/4) [Executor] START thread
<Thread(jsonrpc/4, started daemon 140162296706816)> (func=<bound
method _Worker._run of <Worker name=jsonrpc/4 waiting task#=0 at
0x7f7a2c112d50>>, args=(), kwargs={}) (concurrent:193)
2019-01-21 23:41:32,161 DEBUG (jsonrpc/4) [Executor] Worker started
(executor:298)
2019-01-21 23:41:32,163 DEBUG (MainThread) [Executor] Starting worker
jsonrpc/6 (executor:286)
2019-01-21 23:41:32,164 DEBUG (jsonrpc/5) [Executor] START thread
<Thread(jsonrpc/5, started daemon 140162279921408)> (func=<bound
method _Worker._run of <Worker name=jsonrpc/5 waiting task#=0 at
0x7f7a2c112810>>, args=(), kwargs={}) (concurrent:193)
2019-01-21 23:41:32,166 DEBUG (jsonrpc/6) [Executor] START thread
<Thread(jsonrpc/6, started daemon 140162254743296)> (func=<bound
method _Worker._run of <Worker name=jsonrpc/6 waiting task#=0 at
0x7f7a2c1924d0>>, args=(), kwargs={}) (concurrent:193)
2019-01-21 23:41:32,166 DEBUG (MainThread) [Executor] Starting worker
jsonrpc/7 (executor:286)
2019-01-21 23:41:32,167 DEBUG (jsonrpc/5) [Executor] Worker started
(executor:298)
2019-01-21 23:41:32,169 DEBUG (jsonrpc/6) [Executor] Worker started
(executor:298)
2019-01-21 23:41:32,172 DEBUG (jsonrpc/7) [Executor] START thread
<Thread(jsonrpc/7, started daemon 140162246350592)> (func=<bound
method _Worker._run of <Worker name=jsonrpc/7 waiting task#=0 at
0x7f7a2c1921d0>>, args=(), kwargs={}) (concurrent:193)
2019-01-21 23:41:32,173 DEBUG (MainThread) [vds.MultiProtocolAcceptor]
Adding detector <yajsonrpc.stompserver.StompDetector instance at
0x7f7a13fa7050> (protocoldetector:210)
2019-01-21 23:41:32,173 DEBUG (JsonRpcServer) [root] START thread
<Thread(JsonRpcServer, started daemon 140162164061952)> (func=<bound
method JsonRpcServer.serve_requests of <yajsonrpc.JsonRpcServer object
at 0x7f7a2c177bd0>>, args=(), kwargs={}) (concurrent:193)
2019-01-21 23:41:32,174 DEBUG (jsonrpc/7) [Executor] Worker started
(executor:298)
2019-01-21 23:41:32,181 INFO (Detector thread)
[ProtocolDetector.AcceptorImpl] Accepted connection from ::1:43660
(protocoldetector:61)
2019-01-21 23:41:32,185 DEBUG (MainThread) [jsonrpc.AsyncoreClient]
Sending response (stompclient:294)
2019-01-21 23:41:32,185 DEBUG (Detector thread)
[ProtocolDetector.Detector] Using required_size=11
(protocoldetector:89)
2019-01-21 23:41:32,187 DEBUG (Client ::1:46303) [root] START thread
<Thread(Client ::1:46303, started daemon 140162147276544)>
(func=<bound method Reactor.process_requests of
<yajsonrpc.betterAsyncore.Reactor object at 0x7f7a2c156610>>, args=(),
kwargs={}) (concurrent:193)
2019-01-21 23:41:32,189 INFO (Detector thread)
[ProtocolDetector.Detector] Detected protocol stomp from ::1:43660
(protocoldetector:125)
2019-01-21 23:41:32,192 INFO (Detector thread) [Broker.StompAdapter]
Processing CONNECT request (stompserver:95)
2019-01-21 23:41:32,195 INFO (JsonRpc (StompReactor))
[Broker.StompAdapter] Subscribe command received (stompserver:124)
2019-01-21 23:41:32,196 INFO (JsonRpc (StompReactor))
[Broker.StompAdapter] Subscribe command received (stompserver:124)
2019-01-21 23:41:32,197 ERROR (Detector thread) [vds.dispatcher]
uncaptured python exception, closing channel
<yajsonrpc.betterAsyncore.Dispatcher ('::1', 43660, 0, 0) at
0x7f7a13fdaab8> (<type 'exceptions.AttributeError'>:'NoneType'
object
has no attribute 'command'
[/usr/lib64/python2.7/asyncore.py|readwrite|108]
[/usr/lib64/python2.7/asyncore.py|handle_read_event|449]
[/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|412]
[/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|635]
[/usr/lib64/python2.7/asyncore.py|handle_read_event|449]
[/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|415]
[/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/lib/yajsonrpc/stompserver.py|handle_frame|269])
(betterAsyncore:179)
2019-01-21 23:41:32,199 DEBUG (Client ::1:46303)
[yajsonrpc.protocols.stomp.AsyncClient] Stomp connection established
(stompclient:138)
2019-01-21 23:41:32,200 WARNING (Detector thread) [vds.dispatcher]
unhandled close event (betterAsyncore:179)
2019-01-21 23:41:32,207 DEBUG (jsonrpc/1) [jsonrpc.JsonRpcServer]
Calling 'event' in bridge with [] (__init__:329)
2019-01-21 23:41:32,208 DEBUG (jsonrpc/1) [jsonrpc.Notification]
Sending event {"params": {"content": true, "notify_time":
23083358880}, "jsonrpc": "2.0", "method":
"vdsm.event"} (__init__:181)
2019-01-21 23:41:32,210 DEBUG (jsonrpc/1) [jsonrpc.JsonRpcServer]
Return 'event' in bridge with True (__init__:356)
2019-01-21 23:41:32,210 INFO (jsonrpc/1) [jsonrpc.JsonRpcServer] RPC
call event succeeded in 0.00 seconds (__init__:312)
2019-01-21 23:41:34,207 DEBUG (Client ::1:46303)
[yajsonrpc.protocols.stomp.AsyncClient] Timeout occurred, trying to
reconnect (stompclient:128)
2019-01-21 23:41:34,209 INFO (Detector thread)
[ProtocolDetector.AcceptorImpl] Accepted connection from ::1:43662
(protocoldetector:61)
2019-01-21 23:41:34,211 DEBUG (Detector thread)
[ProtocolDetector.Detector] Using required_size=11
(protocoldetector:89)
2019-01-21 23:41:44,222 DEBUG (Detector thread)
[ProtocolDetector.Detector] Timed out while waiting for data
(protocoldetector:94)
2019-01-21 23:41:44,223 DEBUG (Client ::1:46303)
[stomp.AsyncDispatcher] managed to connect successfully. (stomp:388)
2019-01-21 23:41:46,227 DEBUG (Client ::1:46303)
[yajsonrpc.protocols.stomp.AsyncClient] Timeout occurred, trying to
reconnect (stompclient:128)
2019-01-21 23:41:46,230 INFO (Detector thread)
[ProtocolDetector.AcceptorImpl] Accepted connection from ::1:43664
(protocoldetector:61)
2019-01-21 23:41:46,230 DEBUG (Detector thread)
[ProtocolDetector.Detector] Using required_size=11
(protocoldetector:89)
2019-01-21 23:41:46,232 DEBUG (Client ::1:46303)
[stomp.AsyncDispatcher] managed to connect successfully. (stomp:388)
2019-01-21 23:41:46,233 INFO (Detector thread)
[ProtocolDetector.Detector] Detected protocol stomp from ::1:43664
(protocoldetector:125)
2019-01-21 23:41:46,235 INFO (Detector thread) [Broker.StompAdapter]
Processing CONNECT request (stompserver:95)
2019-01-21 23:41:46,236 DEBUG (Detector thread)
[protocoldetector.StompDetector] Stomp detected from ('::1', 43664)
(stompserver:413)
2019-01-21 23:41:46,240 INFO (JsonRpc (StompReactor))
[Broker.StompAdapter] Subscribe command received (stompserver:124)
2019-01-21 23:41:46,242 DEBUG (Client ::1:46303)
[yajsonrpc.protocols.stomp.AsyncClient] Stomp connection established
(stompclient:138)
2019-01-21 23:41:46,281 INFO (JsonRpc (StompReactor))
[Broker.StompAdapter] Subscribe command received (stompserver:124)
2019-01-21 23:41:47,200 WARNING (MainThread)
[yajsonrpc.protocols.stomp.AsyncClient] No subscription with
2a926ebd-35f9-47ce-9fb2-bec2823734f0 id (stompclient:211)
2019-01-21 23:41:47,201 WARNING (MainThread)
[yajsonrpc.protocols.stomp.AsyncClient] No subscription with
b33e3bb3-1f1f-49c2-9ec2-073ec9f4fb33 id (stompclient:211)
2019-01-21 23:41:47,202 DEBUG (MainThread) [vds.MultiProtocolAcceptor]
Stopping Acceptor (protocoldetector:214)
2019-01-21 23:41:47,202 INFO (MainThread) [jsonrpc.JsonRCoverage.py
warning: Module
/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/vdsm was never
imported. (module-not-imported)
pcServer] Stopping JsonRPC Server (__init__:442)
2019-01-21 23:41:47,203 DEBUG (JsonRpcServer) [root] FINISH thread
<Thread(JsonRpcServer, started daemon 140162164061952)>
(concurrent:196)
2019-01-21 23:41:47,204 DEBUG (MainThread) [Executor] Stopping
executor (executor:137)
2019-01-21 23:41:47,204 DEBUG (Client ::1:46303) [root] FINISH thread
<Thread(Client ::1:46303, started daemon 140162147276544)>
(concurrent:196)
2019-01-21 23:41:47,206 DEBUG (jsonrpc/0) [Executor] Worker stopped
(executor:303)
2019-01-21 23:41:47,207 DEBUG (jsonrpc/2) [Executor] Worker stopped
(executor:303)
2019-01-21 23:41:47,208 DEBUG (jsonrpc/3) [Executor] Worker stopped
(executor:303)
2019-01-21 23:41:47,209 DEBUG (jsonrpc/4) [Executor] Worker stopped
(executor:303)
2019-01-21 23:41:47,209 DEBUG (jsonrpc/5) [Executor] Worker stopped
(executor:303)
2019-01-21 23:41:47,210 DEBUG (JsonRpc (StompReactor)) [root] FINISH
thread <Thread(JsonRpc (StompReactor), started daemon
140162271528704)> (concurrent:196)
2019-01-21 23:41:47,211 DEBUG (jsonrpc/6) [Executor] Worker stopped
(executor:303)
2019-01-21 23:41:47,212 DEBUG (jsonrpc/0) [Executor] FINISH thread
<Thread(jsonrpc/0, started daemon 140162263136000)> (concurrent:196)
2019-01-21 23:41:47,212 DEBUG (jsonrpc/2) [Executor] FINISH thread
<Thread(jsonrpc/2, started daemon 140162751371008)> (concurrent:196)
2019-01-21 23:41:47,212 DEBUG (jsonrpc/3) [Executor] FINISH thread
<Thread(jsonrpc/3, started daemon 140162742978304)> (concurrent:196)
2019-01-21 23:41:47,212 DEBUG (MainThread) [Executor] Waiting for
worker jsonrpc/5 (executor:290)
2019-01-21 23:41:47,212 DEBUG (jsonrpc/1) [Executor] Worker stopped
(executor:303)
2019-01-21 23:41:47,216 DEBUG (jsonrpc/1) [Executor] FINISH thread
<Thread(jsonrpc/1, started daemon 140162288314112)> (concurrent:196)
2019-01-21 23:41:47,213 DEBUG (jsonrpc/4) [Executor] FINISH thread
<Thread(jsonrpc/4, started daemon 140162296706816)> (concurrent:196)
2019-01-21 23:41:47,214 DEBUG (jsonrpc/7) [Executor] Worker stopped
(executor:303)
2019-01-21 23:41:47,214 DEBUG (jsonrpc/5) [Executor] FINISH thread
<Thread(jsonrpc/5, started daemon 140162279921408)> (concurrent:196)
2019-01-21 23:41:47,215 DEBUG (jsonrpc/6) [Executor] FINISH thread
<Thread(jsonrpc/6, started daemon 140162254743296)> (concurrent:196)
2019-01-21 23:41:47,217 DEBUG (jsonrpc/7) [Executor] FINISH thread
<Thread(jsonrpc/7, started daemon 140162246350592)> (concurrent:196)
2019-01-21 23:41:47,218 DEBUG (MainThread) [Executor] Waiting for
worker jsonrpc/3 (executor:290)
2019-01-21 23:41:47,219 DEBUG (MainThread) [Executor] Waiting for
worker jsonrpc/2 (executor:290)
2019-01-21 23:41:47,220 DEBUG (MainThread) [Executor] Waiting for
worker jsonrpc/6 (executor:290)
2019-01-21 23:41:47,220 DEBUG (MainThread) [Executor] Waiting for
worker jsonrpc/1 (executor:290)
2019-01-21 23:41:47,220 DEBUG (MainThread) [Executor] Waiting for
worker jsonrpc/4 (executor:290)
2019-01-21 23:41:47,221 DEBUG (MainThread) [Executor] Waiting for
worker jsonrpc/7 (executor:290)
2019-01-21 23:41:47,221 DEBUG (MainThread) [Executor] Waiting for
worker jsonrpc/0 (executor:290)
2019-01-21 23:41:47,221 DEBUG (MainThread) [Scheduler] Stopping
scheduler test.Scheduler (schedule:110)
2019-01-21 23:41:47,222 DEBUG (test.Scheduler) [Scheduler] stopped
(schedule:143)
2019-01-21 23:41:47,222 DEBUG (test.Scheduler) [Scheduler] FINISH
thread <Thread(test.Scheduler, started daemon 140162734585600)>
(concurrent:196)
6:57 p.m.
On Tue, Jan 22, 2019 at 1:56 AM Nir Soffer <nsoffer(a)redhat.com> wrote:
On Sat, Jan 19, 2019 at 11:15 PM Nir Soffer
<nsoffer(a)redhat.com> wrote:
> Recently this test cause too many random failures. I guess this is
> the known issue with handling SUBSCRIBE in protocol detector.
> I posted https://gerrit.ovirt.org/c/97099/
> To mark it as broken until we have time to dig deeper
>
> ======================================================================
>
> FAIL: test_detect_slow_client_concurrency(True)
(protocoldetector_test.AcceptorTests)
> ----------------------------------------------------------------------
> Traceback (most recent call last):
> File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/testlib.py", line
142, in wrapper
> return f(self, *args)
> File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/protocoldetector_test.py",
line 167, in test_detect_slow_client_concurrency
> self.check_concurrently(self.check_slow_client, use_ssl)
> File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/protocoldetector_test.py",
line 266, in check_concurrently
> self.assertTrue(all(done))
> AssertionError: False is not true
> -------------------- >> begin captured logging << --------------------
> 2019-01-19 20:47:16,021 DEBUG (MainThread) [vds.MultiProtocolAcceptor] Creating
socket (host='127.0.0.1', port=0, family=2, socketype=1, proto=6)
(protocoldetector:225)
> 2019-01-19 20:47:16,022 INFO (MainThread) [vds.MultiProtocolAcceptor] Listening at
127.0.0.1:46009 (protocoldetector:183)
> 2019-01-19 20:47:16,023 DEBUG (MainThread) [vds.MultiProtocolAcceptor] Adding
detector <protocoldetector_test.Echo object at 0x7f1bb77f8dd0>
(protocoldetector:210)
> 2019-01-19 20:47:16,024 DEBUG (MainThread) [vds.MultiProtocolAcceptor] Adding
detector <protocoldetector_test.Uppercase object at 0x7f1bb77f8c90>
(protocoldetector:210)
> 2019-01-19 20:47:16,031 INFO (Thread-61) [ProtocolDetector.AcceptorImpl] Accepted
connection from 127.0.0.1:51950 (protocoldetector:61)
> 2019-01-19 20:47:16,047 INFO (Thread-61) [ProtocolDetector.AcceptorImpl] Accepted
connection from 127.0.0.1:51952 (protocoldetector:61)
> 2019-01-19 20:47:16,048 INFO (Thread-61) [ProtocolDetector.AcceptorImpl] Accepted
connection from 127.0.0.1:51954 (protocoldetector:61)
> 2019-01-19 20:47:16,065 INFO (Thread-61) [ProtocolDetector.AcceptorImpl] Accepted
connection from 127.0.0.1:51956 (protocoldetector:61)
> 2019-01-19 20:47:16,068 INFO (Thread-61) [ProtocolDetector.AcceptorImpl] Accepted
connection from 127.0.0.1:51958 (protocoldetector:61)
> 2019-01-19 20:47:16,069 DEBUG (Thread-61) [ProtocolDetector.Detector] Using
required_size=9 (protocoldetector:89)
> 2019-01-19 20:47:16,097 DEBUG (Thread-61) [ProtocolDetector.Detector] Using
required_size=9 (protocoldetector:89)
> 2019-01-19 20:47:16,099 DEBUG (Thread-61) [ProtocolDetector.Detector] Using
required_size=9 (protocoldetector:89)
> 2019-01-19 20:47:16,107 DEBUG (Thread-61) [ProtocolDetector.Detector] Using
required_size=9 (protocoldetector:89)
> 2019-01-19 20:47:16,109 DEBUG (Thread-61) [ProtocolDetector.Detector] Using
required_size=9 (protocoldetector:89)
> 2019-01-19 20:47:16,574 INFO (Thread-61) [ProtocolDetector.Detector] Detected
protocol echo from 127.0.0.1:51950 (protocoldetector:125)
> 2019-01-19 20:47:17,570 DEBUG (Thread-61) [ProtocolDetector.Detector] Timed out while
waiting for data (protocoldetector:94)
> 2019-01-19 20:47:17,571 DEBUG (Thread-61) [ProtocolDetector.Detector] Timed out while
waiting for data (protocoldetector:94)
> 2019-01-19 20:47:17,576 DEBUG (Thread-61) [ProtocolDetector.Detector] Timed out while
waiting for data (protocoldetector:94)
> 2019-01-19 20:47:17,578 DEBUG (Thread-61) [ProtocolDetector.Detector] Timed out while
waiting for data (protocoldetector:94)
> --------------------- >> end captured logging << ---------------------
>
>
Another flaky test - we marked the other test in this class as broken on ci
recently. This test fail randomly from time to time.
Failed this build:
https://jenkins.ovirt.org/job/vdsm_standard-check-patch/2158//artifact/ch...
======================================================================
ERROR: test_event(False) (stomp_test.StompTests)
----------------------------------------------------------------------
Traceback (most recent call last):
File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/testlib.py", line
142, in wrapper
return f(self, *args)
File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/stomp_test.py",
line 118, in test_event
client.callMethod("event", [], str(uuid4()))
File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/lib/yajsonrpc/jsonrpcclient.py",
line 78, in callMethod
raise exception.JsonRpcNoResponseError(method=methodName)
JsonRpcNoResponseError: No response for JSON-RPC request: {'method':
'event'}
-------------------- >> begin captured logging << --------------------
2019-01-21 23:41:32,132 DEBUG (MainThread) [vds.MultiProtocolAcceptor] Creating socket
(host='::1', port=0, family=10, socketype=1, proto=6) (protocoldetector:225)
2019-01-21 23:41:32,133 INFO (MainThread) [vds.MultiProtocolAcceptor] Listening at
::1:46303 (protocoldetector:183)
2019-01-21 23:41:32,134 DEBUG (MainThread) [Scheduler] Starting scheduler test.Scheduler
(schedule:98)
2019-01-21 23:41:32,135 DEBUG (test.Scheduler) [Scheduler] START thread
<Thread(test.Scheduler, started daemon 140162734585600)> (func=<bound method
Scheduler._run of <vdsm.schedule.Scheduler object at 0x7f7a2c156e10>>, args=(),
kwargs={}) (concurrent:193)
2019-01-21 23:41:32,138 DEBUG (test.Scheduler) [Scheduler] started (schedule:140)
2019-01-21 23:41:32,139 DEBUG (JsonRpc (StompReactor)) [root] START thread
<Thread(JsonRpc (StompReactor), started daemon 140162271528704)> (func=<bound
method StompReactor.process_requests of <yajsonrpc.stompserver.StompReactor object at
0x7f7a2c177950>>, args=(), kwargs={}) (concurrent:193)
2019-01-21 23:41:32,139 DEBUG (MainThread) [Executor] Starting executor (executor:128)
2019-01-21 23:41:32,141 DEBUG (MainThread) [Executor] Starting worker jsonrpc/0
(executor:286)
2019-01-21 23:41:32,142 DEBUG (MainThread) [Executor] Starting worker jsonrpc/1
(executor:286)
2019-01-21 23:41:32,143 DEBUG (jsonrpc/1) [Executor] START thread <Thread(jsonrpc/1,
started daemon 140162288314112)> (func=<bound method _Worker._run of <Worker
name=jsonrpc/1 waiting task#=0 at 0x7f7a2c177510>>, args=(), kwargs={})
(concurrent:193)
2019-01-21 23:41:32,144 DEBUG (MainThread) [Executor] Starting worker jsonrpc/2
(executor:286)
2019-01-21 23:41:32,144 DEBUG (jsonrpc/0) [Executor] START thread <Thread(jsonrpc/0,
started daemon 140162263136000)> (func=<bound method _Worker._run of <Worker
name=jsonrpc/0 waiting task#=0 at 0x7f7a2c177d50>>, args=(), kwargs={})
(concurrent:193)
2019-01-21 23:41:32,145 DEBUG (jsonrpc/1) [Executor] Worker started (executor:298)
2019-01-21 23:41:32,147 DEBUG (MainThread) [Executor] Starting worker jsonrpc/3
(executor:286)
2019-01-21 23:41:32,148 DEBUG (jsonrpc/2) [Executor] START thread <Thread(jsonrpc/2,
started daemon 140162751371008)> (func=<bound method _Worker._run of <Worker
name=jsonrpc/2 waiting task#=0 at 0x7f7a2c177ad0>>, args=(), kwargs={})
(concurrent:193)
2019-01-21 23:41:32,149 DEBUG (jsonrpc/0) [Executor] Worker started (executor:298)
2019-01-21 23:41:32,153 DEBUG (jsonrpc/2) [Executor] Worker started (executor:298)
2019-01-21 23:41:32,154 DEBUG (MainThread) [Executor] Starting worker jsonrpc/4
(executor:286)
2019-01-21 23:41:32,155 DEBUG (jsonrpc/3) [Executor] START thread <Thread(jsonrpc/3,
started daemon 140162742978304)> (func=<bound method _Worker._run of <Worker
name=jsonrpc/3 waiting task#=0 at 0x7f7a2c112e10>>, args=(), kwargs={})
(concurrent:193)
2019-01-21 23:41:32,158 DEBUG (jsonrpc/3) [Executor] Worker started (executor:298)
2019-01-21 23:41:32,159 DEBUG (MainThread) [Executor] Starting worker jsonrpc/5
(executor:286)
2019-01-21 23:41:32,160 DEBUG (jsonrpc/4) [Executor] START thread <Thread(jsonrpc/4,
started daemon 140162296706816)> (func=<bound method _Worker._run of <Worker
name=jsonrpc/4 waiting task#=0 at 0x7f7a2c112d50>>, args=(), kwargs={})
(concurrent:193)
2019-01-21 23:41:32,161 DEBUG (jsonrpc/4) [Executor] Worker started (executor:298)
2019-01-21 23:41:32,163 DEBUG (MainThread) [Executor] Starting worker jsonrpc/6
(executor:286)
2019-01-21 23:41:32,164 DEBUG (jsonrpc/5) [Executor] START thread <Thread(jsonrpc/5,
started daemon 140162279921408)> (func=<bound method _Worker._run of <Worker
name=jsonrpc/5 waiting task#=0 at 0x7f7a2c112810>>, args=(), kwargs={})
(concurrent:193)
2019-01-21 23:41:32,166 DEBUG (jsonrpc/6) [Executor] START thread <Thread(jsonrpc/6,
started daemon 140162254743296)> (func=<bound method _Worker._run of <Worker
name=jsonrpc/6 waiting task#=0 at 0x7f7a2c1924d0>>, args=(), kwargs={})
(concurrent:193)
2019-01-21 23:41:32,166 DEBUG (MainThread) [Executor] Starting worker jsonrpc/7
(executor:286)
2019-01-21 23:41:32,167 DEBUG (jsonrpc/5) [Executor] Worker started (executor:298)
2019-01-21 23:41:32,169 DEBUG (jsonrpc/6) [Executor] Worker started (executor:298)
2019-01-21 23:41:32,172 DEBUG (jsonrpc/7) [Executor] START thread <Thread(jsonrpc/7,
started daemon 140162246350592)> (func=<bound method _Worker._run of <Worker
name=jsonrpc/7 waiting task#=0 at 0x7f7a2c1921d0>>, args=(), kwargs={})
(concurrent:193)
2019-01-21 23:41:32,173 DEBUG (MainThread) [vds.MultiProtocolAcceptor] Adding detector
<yajsonrpc.stompserver.StompDetector instance at 0x7f7a13fa7050>
(protocoldetector:210)
2019-01-21 23:41:32,173 DEBUG (JsonRpcServer) [root] START thread
<Thread(JsonRpcServer, started daemon 140162164061952)> (func=<bound method
JsonRpcServer.serve_requests of <yajsonrpc.JsonRpcServer object at
0x7f7a2c177bd0>>, args=(), kwargs={}) (concurrent:193)
2019-01-21 23:41:32,174 DEBUG (jsonrpc/7) [Executor] Worker started (executor:298)
2019-01-21 23:41:32,181 INFO (Detector thread) [ProtocolDetector.AcceptorImpl] Accepted
connection from ::1:43660 (protocoldetector:61)
2019-01-21 23:41:32,185 DEBUG (MainThread) [jsonrpc.AsyncoreClient] Sending response
(stompclient:294)
2019-01-21 23:41:32,185 DEBUG (Detector thread) [ProtocolDetector.Detector] Using
required_size=11 (protocoldetector:89)
2019-01-21 23:41:32,187 DEBUG (Client ::1:46303) [root] START thread <Thread(Client
::1:46303, started daemon 140162147276544)> (func=<bound method
Reactor.process_requests of <yajsonrpc.betterAsyncore.Reactor object at
0x7f7a2c156610>>, args=(), kwargs={}) (concurrent:193)
2019-01-21 23:41:32,189 INFO (Detector thread) [ProtocolDetector.Detector] Detected
protocol stomp from ::1:43660 (protocoldetector:125)
2019-01-21 23:41:32,192 INFO (Detector thread) [Broker.StompAdapter] Processing CONNECT
request (stompserver:95)
2019-01-21 23:41:32,195 INFO (JsonRpc (StompReactor)) [Broker.StompAdapter] Subscribe
command received (stompserver:124)
2019-01-21 23:41:32,196 INFO (JsonRpc (StompReactor)) [Broker.StompAdapter] Subscribe
command received (stompserver:124)
2019-01-21 23:41:32,197 ERROR (Detector thread) [vds.dispatcher] uncaptured python
exception, closing channel <yajsonrpc.betterAsyncore.Dispatcher ('::1', 43660,
0, 0) at 0x7f7a13fdaab8> (<type
'exceptions.AttributeError'>:'NoneType' object has no attribute
'command' [/usr/lib64/python2.7/asyncore.py|readwrite|108]
[/usr/lib64/python2.7/asyncore.py|handle_read_event|449]
[/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|412]
[/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|635]
[/usr/lib64/python2.7/asyncore.py|handle_read_event|449]
[/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|415]
[/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/lib/yajsonrpc/stompserver.py|handle_frame|269])
(betterAsyncore:179)
2019-01-21 23:41:32,199 DEBUG (Client ::1:46303) [yajsonrpc.protocols.stomp.AsyncClient]
Stomp connection established (stompclient:138)
2019-01-21 23:41:32,200 WARNING (Detector thread) [vds.dispatcher] unhandled close event
(betterAsyncore:179)
2019-01-21 23:41:32,207 DEBUG (jsonrpc/1) [jsonrpc.JsonRpcServer] Calling 'event'
in bridge with [] (__init__:329)
2019-01-21 23:41:32,208 DEBUG (jsonrpc/1) [jsonrpc.Notification] Sending event
{"params": {"content": true, "notify_time": 23083358880},
"jsonrpc": "2.0", "method": "vdsm.event"}
(__init__:181)
2019-01-21 23:41:32,210 DEBUG (jsonrpc/1) [jsonrpc.JsonRpcServer] Return 'event'
in bridge with True (__init__:356)
2019-01-21 23:41:32,210 INFO (jsonrpc/1) [jsonrpc.JsonRpcServer] RPC call event
succeeded in 0.00 seconds (__init__:312)
2019-01-21 23:41:34,207 DEBUG (Client ::1:46303) [yajsonrpc.protocols.stomp.AsyncClient]
Timeout occurred, trying to reconnect (stompclient:128)
2019-01-21 23:41:34,209 INFO (Detector thread) [ProtocolDetector.AcceptorImpl] Accepted
connection from ::1:43662 (protocoldetector:61)
2019-01-21 23:41:34,211 DEBUG (Detector thread) [ProtocolDetector.Detector] Using
required_size=11 (protocoldetector:89)
2019-01-21 23:41:44,222 DEBUG (Detector thread) [ProtocolDetector.Detector] Timed out
while waiting for data (protocoldetector:94)
2019-01-21 23:41:44,223 DEBUG (Client ::1:46303) [stomp.AsyncDispatcher] managed to
connect successfully. (stomp:388)
2019-01-21 23:41:46,227 DEBUG (Client ::1:46303) [yajsonrpc.protocols.stomp.AsyncClient]
Timeout occurred, trying to reconnect (stompclient:128)
2019-01-21 23:41:46,230 INFO (Detector thread) [ProtocolDetector.AcceptorImpl] Accepted
connection from ::1:43664 (protocoldetector:61)
2019-01-21 23:41:46,230 DEBUG (Detector thread) [ProtocolDetector.Detector] Using
required_size=11 (protocoldetector:89)
2019-01-21 23:41:46,232 DEBUG (Client ::1:46303) [stomp.AsyncDispatcher] managed to
connect successfully. (stomp:388)
2019-01-21 23:41:46,233 INFO (Detector thread) [ProtocolDetector.Detector] Detected
protocol stomp from ::1:43664 (protocoldetector:125)
2019-01-21 23:41:46,235 INFO (Detector thread) [Broker.StompAdapter] Processing CONNECT
request (stompserver:95)
2019-01-21 23:41:46,236 DEBUG (Detector thread) [protocoldetector.StompDetector] Stomp
detected from ('::1', 43664) (stompserver:413)
2019-01-21 23:41:46,240 INFO (JsonRpc (StompReactor)) [Broker.StompAdapter] Subscribe
command received (stompserver:124)
2019-01-21 23:41:46,242 DEBUG (Client ::1:46303) [yajsonrpc.protocols.stomp.AsyncClient]
Stomp connection established (stompclient:138)
2019-01-21 23:41:46,281 INFO (JsonRpc (StompReactor)) [Broker.StompAdapter] Subscribe
command received (stompserver:124)
2019-01-21 23:41:47,200 WARNING (MainThread) [yajsonrpc.protocols.stomp.AsyncClient] No
subscription with 2a926ebd-35f9-47ce-9fb2-bec2823734f0 id (stompclient:211)
2019-01-21 23:41:47,201 WARNING (MainThread) [yajsonrpc.protocols.stomp.AsyncClient] No
subscription with b33e3bb3-1f1f-49c2-9ec2-073ec9f4fb33 id (stompclient:211)
2019-01-21 23:41:47,202 DEBUG (MainThread) [vds.MultiProtocolAcceptor] Stopping Acceptor
(protocoldetector:214)
2019-01-21 23:41:47,202 INFO (MainThread) [jsonrpc.JsonRCoverage.py warning: Module
/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/vdsm was never imported.
(module-not-imported)
pcServer] Stopping JsonRPC Server (__init__:442)
2019-01-21 23:41:47,203 DEBUG (JsonRpcServer) [root] FINISH thread
<Thread(JsonRpcServer, started daemon 140162164061952)> (concurrent:196)
2019-01-21 23:41:47,204 DEBUG (MainThread) [Executor] Stopping executor (executor:137)
2019-01-21 23:41:47,204 DEBUG (Client ::1:46303) [root] FINISH thread <Thread(Client
::1:46303, started daemon 140162147276544)> (concurrent:196)
2019-01-21 23:41:47,206 DEBUG (jsonrpc/0) [Executor] Worker stopped (executor:303)
2019-01-21 23:41:47,207 DEBUG (jsonrpc/2) [Executor] Worker stopped (executor:303)
2019-01-21 23:41:47,208 DEBUG (jsonrpc/3) [Executor] Worker stopped (executor:303)
2019-01-21 23:41:47,209 DEBUG (jsonrpc/4) [Executor] Worker stopped (executor:303)
2019-01-21 23:41:47,209 DEBUG (jsonrpc/5) [Executor] Worker stopped (executor:303)
2019-01-21 23:41:47,210 DEBUG (JsonRpc (StompReactor)) [root] FINISH thread
<Thread(JsonRpc (StompReactor), started daemon 140162271528704)> (concurrent:196)
2019-01-21 23:41:47,211 DEBUG (jsonrpc/6) [Executor] Worker stopped (executor:303)
2019-01-21 23:41:47,212 DEBUG (jsonrpc/0) [Executor] FINISH thread <Thread(jsonrpc/0,
started daemon 140162263136000)> (concurrent:196)
2019-01-21 23:41:47,212 DEBUG (jsonrpc/2) [Executor] FINISH thread <Thread(jsonrpc/2,
started daemon 140162751371008)> (concurrent:196)
2019-01-21 23:41:47,212 DEBUG (jsonrpc/3) [Executor] FINISH thread <Thread(jsonrpc/3,
started daemon 140162742978304)> (concurrent:196)
2019-01-21 23:41:47,212 DEBUG (MainThread) [Executor] Waiting for worker jsonrpc/5
(executor:290)
2019-01-21 23:41:47,212 DEBUG (jsonrpc/1) [Executor] Worker stopped (executor:303)
2019-01-21 23:41:47,216 DEBUG (jsonrpc/1) [Executor] FINISH thread <Thread(jsonrpc/1,
started daemon 140162288314112)> (concurrent:196)
2019-01-21 23:41:47,213 DEBUG (jsonrpc/4) [Executor] FINISH thread <Thread(jsonrpc/4,
started daemon 140162296706816)> (concurrent:196)
2019-01-21 23:41:47,214 DEBUG (jsonrpc/7) [Executor] Worker stopped (executor:303)
2019-01-21 23:41:47,214 DEBUG (jsonrpc/5) [Executor] FINISH thread <Thread(jsonrpc/5,
started daemon 140162279921408)> (concurrent:196)
2019-01-21 23:41:47,215 DEBUG (jsonrpc/6) [Executor] FINISH thread <Thread(jsonrpc/6,
started daemon 140162254743296)> (concurrent:196)
2019-01-21 23:41:47,217 DEBUG (jsonrpc/7) [Executor] FINISH thread <Thread(jsonrpc/7,
started daemon 140162246350592)> (concurrent:196)
2019-01-21 23:41:47,218 DEBUG (MainThread) [Executor] Waiting for worker jsonrpc/3
(executor:290)
2019-01-21 23:41:47,219 DEBUG (MainThread) [Executor] Waiting for worker jsonrpc/2
(executor:290)
2019-01-21 23:41:47,220 DEBUG (MainThread) [Executor] Waiting for worker jsonrpc/6
(executor:290)
2019-01-21 23:41:47,220 DEBUG (MainThread) [Executor] Waiting for worker jsonrpc/1
(executor:290)
2019-01-21 23:41:47,220 DEBUG (MainThread) [Executor] Waiting for worker jsonrpc/4
(executor:290)
2019-01-21 23:41:47,221 DEBUG (MainThread) [Executor] Waiting for worker jsonrpc/7
(executor:290)
2019-01-21 23:41:47,221 DEBUG (MainThread) [Executor] Waiting for worker jsonrpc/0
(executor:290)
2019-01-21 23:41:47,221 DEBUG (MainThread) [Scheduler] Stopping scheduler test.Scheduler
(schedule:110)
2019-01-21 23:41:47,222 DEBUG (test.Scheduler) [Scheduler] stopped (schedule:143)
2019-01-21 23:41:47,222 DEBUG (test.Scheduler) [Scheduler] FINISH thread
<Thread(test.Scheduler, started daemon 140162734585600)> (concurrent:196)
4:15 a.m.
Hi,
I don't have time to look into this right now, but I will definitely do
so after coming back from FOSDEM.
Regards, Marcin
On 1/22/19 12:57 AM, Nir Soffer wrote:
On Tue, Jan 22, 2019 at 1:56 AM Nir Soffer <nsoffer(a)redhat.com
<mailto:nsoffer@redhat.com>> wrote:
On Sat, Jan 19, 2019 at 11:15 PM Nir Soffer <nsoffer(a)redhat.com
<mailto:nsoffer@redhat.com>> wrote:
Recently this test cause too many random failures. I guess
this is the known issue with handling SUBSCRIBE in protocol
detector. I posted https://gerrit.ovirt.org/c/97099/ To mark
it as broken until we have time to dig deeper
======================================================================
FAIL: test_detect_slow_client_concurrency(True)
(protocoldetector_test.AcceptorTests)
----------------------------------------------------------------------
Traceback (most recent call last):
File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/testlib.py", line
142, in wrapper
return f(self, *args)
File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/protocoldetector_test.py",
line 167, in test_detect_slow_client_concurrency
self.check_concurrently(self.check_slow_client, use_ssl)
File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/protocoldetector_test.py",
line 266, in check_concurrently
self.assertTrue(all(done))
AssertionError: False is not true
-------------------- >> begin captured logging <<
--------------------
2019-01-19 20:47:16,021 DEBUG (MainThread) [vds.MultiProtocolAcceptor] Creating
socket (host='127.0.0.1', port=0, family=2, socketype=1, proto=6)
(protocoldetector:225)
2019-01-19 20:47:16,022 INFO (MainThread) [vds.MultiProtocolAcceptor] Listening
at127.0.0.1:46009 <http://127.0.0.1:46009> (protocoldetector:183)
2019-01-19 20:47:16,023 DEBUG (MainThread) [vds.MultiProtocolAcceptor] Adding
detector <protocoldetector_test.Echo object at 0x7f1bb77f8dd0>
(protocoldetector:210)
2019-01-19 20:47:16,024 DEBUG (MainThread) [vds.MultiProtocolAcceptor] Adding
detector <protocoldetector_test.Uppercase object at 0x7f1bb77f8c90>
(protocoldetector:210)
2019-01-19 20:47:16,031 INFO (Thread-61) [ProtocolDetector.AcceptorImpl]
Accepted connection from127.0.0.1:51950 <http://127.0.0.1:51950>
(protocoldetector:61)
2019-01-19 20:47:16,047 INFO (Thread-61) [ProtocolDetector.AcceptorImpl]
Accepted connection from127.0.0.1:51952 <http://127.0.0.1:51952>
(protocoldetector:61)
2019-01-19 20:47:16,048 INFO (Thread-61) [ProtocolDetector.AcceptorImpl]
Accepted connection from127.0.0.1:51954 <http://127.0.0.1:51954>
(protocoldetector:61)
2019-01-19 20:47:16,065 INFO (Thread-61) [ProtocolDetector.AcceptorImpl]
Accepted connection from127.0.0.1:51956 <http://127.0.0.1:51956>
(protocoldetector:61)
2019-01-19 20:47:16,068 INFO (Thread-61) [ProtocolDetector.AcceptorImpl]
Accepted connection from127.0.0.1:51958 <http://127.0.0.1:51958>
(protocoldetector:61)
2019-01-19 20:47:16,069 DEBUG (Thread-61) [ProtocolDetector.Detector] Using
required_size=9 (protocoldetector:89)
2019-01-19 20:47:16,097 DEBUG (Thread-61) [ProtocolDetector.Detector] Using
required_size=9 (protocoldetector:89)
2019-01-19 20:47:16,099 DEBUG (Thread-61) [ProtocolDetector.Detector] Using
required_size=9 (protocoldetector:89)
2019-01-19 20:47:16,107 DEBUG (Thread-61) [ProtocolDetector.Detector] Using
required_size=9 (protocoldetector:89)
2019-01-19 20:47:16,109 DEBUG (Thread-61) [ProtocolDetector.Detector] Using
required_size=9 (protocoldetector:89)
2019-01-19 20:47:16,574 INFO (Thread-61) [ProtocolDetector.Detector] Detected
protocol echo from127.0.0.1:51950 <http://127.0.0.1:51950> (protocoldetector:125)
2019-01-19 20:47:17,570 DEBUG (Thread-61) [ProtocolDetector.Detector] Timed out
while waiting for data (protocoldetector:94)
2019-01-19 20:47:17,571 DEBUG (Thread-61) [ProtocolDetector.Detector] Timed out
while waiting for data (protocoldetector:94)
2019-01-19 20:47:17,576 DEBUG (Thread-61) [ProtocolDetector.Detector] Timed out
while waiting for data (protocoldetector:94)
2019-01-19 20:47:17,578 DEBUG (Thread-61) [ProtocolDetector.Detector] Timed out
while waiting for data (protocoldetector:94)
--------------------- >> end captured logging <<
---------------------
Another flaky test - we marked the other test in this class as
broken on ci
recently. This test fail randomly from time to time.
Failed this build:
https://jenkins.ovirt.org/job/vdsm_standard-check-patch/2158//artifact/ch...
======================================================================
ERROR: test_event(False) (stomp_test.StompTests)
----------------------------------------------------------------------
Traceback (most recent call last):
File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/testlib.py", line
142, in wrapper
return f(self, *args)
File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/stomp_test.py",
line 118, in test_event
client.callMethod("event", [], str(uuid4()))
File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/lib/yajsonrpc/jsonrpcclient.py",
line 78, in callMethod
raise exception.JsonRpcNoResponseError(method=methodName)
JsonRpcNoResponseError: No response for JSON-RPC request: {'method':
'event'}
-------------------- >> begin captured logging << --------------------
2019-01-21 23:41:32,132 DEBUG (MainThread) [vds.MultiProtocolAcceptor] Creating
socket (host='::1', port=0, family=10, socketype=1, proto=6)
(protocoldetector:225)
2019-01-21 23:41:32,133 INFO (MainThread) [vds.MultiProtocolAcceptor] Listening at
::1:46303 (protocoldetector:183)
2019-01-21 23:41:32,134 DEBUG (MainThread) [Scheduler] Starting scheduler
test.Scheduler (schedule:98)
2019-01-21 23:41:32,135 DEBUG (test.Scheduler) [Scheduler] START thread
<Thread(test.Scheduler, started daemon 140162734585600)> (func=<bound method
Scheduler._run of <vdsm.schedule.Scheduler object at 0x7f7a2c156e10>>, args=(),
kwargs={}) (concurrent:193)
2019-01-21 23:41:32,138 DEBUG (test.Scheduler) [Scheduler] started (schedule:140)
2019-01-21 23:41:32,139 DEBUG (JsonRpc (StompReactor)) [root] START thread
<Thread(JsonRpc (StompReactor), started daemon 140162271528704)> (func=<bound
method StompReactor.process_requests of <yajsonrpc.stompserver.StompReactor object at
0x7f7a2c177950>>, args=(), kwargs={}) (concurrent:193)
2019-01-21 23:41:32,139 DEBUG (MainThread) [Executor] Starting executor
(executor:128)
2019-01-21 23:41:32,141 DEBUG (MainThread) [Executor] Starting worker jsonrpc/0
(executor:286)
2019-01-21 23:41:32,142 DEBUG (MainThread) [Executor] Starting worker jsonrpc/1
(executor:286)
2019-01-21 23:41:32,143 DEBUG (jsonrpc/1) [Executor] START thread
<Thread(jsonrpc/1, started daemon 140162288314112)> (func=<bound method
_Worker._run of <Worker name=jsonrpc/1 waiting task#=0 at 0x7f7a2c177510>>,
args=(), kwargs={}) (concurrent:193)
2019-01-21 23:41:32,144 DEBUG (MainThread) [Executor] Starting worker jsonrpc/2
(executor:286)
2019-01-21 23:41:32,144 DEBUG (jsonrpc/0) [Executor] START thread
<Thread(jsonrpc/0, started daemon 140162263136000)> (func=<bound method
_Worker._run of <Worker name=jsonrpc/0 waiting task#=0 at 0x7f7a2c177d50>>,
args=(), kwargs={}) (concurrent:193)
2019-01-21 23:41:32,145 DEBUG (jsonrpc/1) [Executor] Worker started (executor:298)
2019-01-21 23:41:32,147 DEBUG (MainThread) [Executor] Starting worker jsonrpc/3
(executor:286)
2019-01-21 23:41:32,148 DEBUG (jsonrpc/2) [Executor] START thread
<Thread(jsonrpc/2, started daemon 140162751371008)> (func=<bound method
_Worker._run of <Worker name=jsonrpc/2 waiting task#=0 at 0x7f7a2c177ad0>>,
args=(), kwargs={}) (concurrent:193)
2019-01-21 23:41:32,149 DEBUG (jsonrpc/0) [Executor] Worker started (executor:298)
2019-01-21 23:41:32,153 DEBUG (jsonrpc/2) [Executor] Worker started (executor:298)
2019-01-21 23:41:32,154 DEBUG (MainThread) [Executor] Starting worker jsonrpc/4
(executor:286)
2019-01-21 23:41:32,155 DEBUG (jsonrpc/3) [Executor] START thread
<Thread(jsonrpc/3, started daemon 140162742978304)> (func=<bound method
_Worker._run of <Worker name=jsonrpc/3 waiting task#=0 at 0x7f7a2c112e10>>,
args=(), kwargs={}) (concurrent:193)
2019-01-21 23:41:32,158 DEBUG (jsonrpc/3) [Executor] Worker started (executor:298)
2019-01-21 23:41:32,159 DEBUG (MainThread) [Executor] Starting worker jsonrpc/5
(executor:286)
2019-01-21 23:41:32,160 DEBUG (jsonrpc/4) [Executor] START thread
<Thread(jsonrpc/4, started daemon 140162296706816)> (func=<bound method
_Worker._run of <Worker name=jsonrpc/4 waiting task#=0 at 0x7f7a2c112d50>>,
args=(), kwargs={}) (concurrent:193)
2019-01-21 23:41:32,161 DEBUG (jsonrpc/4) [Executor] Worker started (executor:298)
2019-01-21 23:41:32,163 DEBUG (MainThread) [Executor] Starting worker jsonrpc/6
(executor:286)
2019-01-21 23:41:32,164 DEBUG (jsonrpc/5) [Executor] START thread
<Thread(jsonrpc/5, started daemon 140162279921408)> (func=<bound method
_Worker._run of <Worker name=jsonrpc/5 waiting task#=0 at 0x7f7a2c112810>>,
args=(), kwargs={}) (concurrent:193)
2019-01-21 23:41:32,166 DEBUG (jsonrpc/6) [Executor] START thread
<Thread(jsonrpc/6, started daemon 140162254743296)> (func=<bound method
_Worker._run of <Worker name=jsonrpc/6 waiting task#=0 at 0x7f7a2c1924d0>>,
args=(), kwargs={}) (concurrent:193)
2019-01-21 23:41:32,166 DEBUG (MainThread) [Executor] Starting worker jsonrpc/7
(executor:286)
2019-01-21 23:41:32,167 DEBUG (jsonrpc/5) [Executor] Worker started (executor:298)
2019-01-21 23:41:32,169 DEBUG (jsonrpc/6) [Executor] Worker started (executor:298)
2019-01-21 23:41:32,172 DEBUG (jsonrpc/7) [Executor] START thread
<Thread(jsonrpc/7, started daemon 140162246350592)> (func=<bound method
_Worker._run of <Worker name=jsonrpc/7 waiting task#=0 at 0x7f7a2c1921d0>>,
args=(), kwargs={}) (concurrent:193)
2019-01-21 23:41:32,173 DEBUG (MainThread) [vds.MultiProtocolAcceptor] Adding
detector <yajsonrpc.stompserver.StompDetector instance at 0x7f7a13fa7050>
(protocoldetector:210)
2019-01-21 23:41:32,173 DEBUG (JsonRpcServer) [root] START thread
<Thread(JsonRpcServer, started daemon 140162164061952)> (func=<bound method
JsonRpcServer.serve_requests of <yajsonrpc.JsonRpcServer object at
0x7f7a2c177bd0>>, args=(), kwargs={}) (concurrent:193)
2019-01-21 23:41:32,174 DEBUG (jsonrpc/7) [Executor] Worker started (executor:298)
2019-01-21 23:41:32,181 INFO (Detector thread) [ProtocolDetector.AcceptorImpl]
Accepted connection from ::1:43660 (protocoldetector:61)
2019-01-21 23:41:32,185 DEBUG (MainThread) [jsonrpc.AsyncoreClient] Sending response
(stompclient:294)
2019-01-21 23:41:32,185 DEBUG (Detector thread) [ProtocolDetector.Detector] Using
required_size=11 (protocoldetector:89)
2019-01-21 23:41:32,187 DEBUG (Client ::1:46303) [root] START thread
<Thread(Client ::1:46303, started daemon 140162147276544)> (func=<bound method
Reactor.process_requests of <yajsonrpc.betterAsyncore.Reactor object at
0x7f7a2c156610>>, args=(), kwargs={}) (concurrent:193)
2019-01-21 23:41:32,189 INFO (Detector thread) [ProtocolDetector.Detector] Detected
protocol stomp from ::1:43660 (protocoldetector:125)
2019-01-21 23:41:32,192 INFO (Detector thread) [Broker.StompAdapter] Processing
CONNECT request (stompserver:95)
2019-01-21 23:41:32,195 INFO (JsonRpc (StompReactor)) [Broker.StompAdapter]
Subscribe command received (stompserver:124)
2019-01-21 23:41:32,196 INFO (JsonRpc (StompReactor)) [Broker.StompAdapter]
Subscribe command received (stompserver:124)
2019-01-21 23:41:32,197 ERROR (Detector thread) [vds.dispatcher] uncaptured python
exception, closing channel <yajsonrpc.betterAsyncore.Dispatcher ('::1', 43660,
0, 0) at 0x7f7a13fdaab8> (<type
'exceptions.AttributeError'>:'NoneType' object has no attribute
'command' [/usr/lib64/python2.7/asyncore.py|readwrite|108]
[/usr/lib64/python2.7/asyncore.py|handle_read_event|449]
[/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|412]
[/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|635]
[/usr/lib64/python2.7/asyncore.py|handle_read_event|449]
[/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|415]
[/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/lib/yajsonrpc/stompserver.py|handle_frame|269])
(betterAsyncore:179)
2019-01-21 23:41:32,199 DEBUG (Client ::1:46303)
[yajsonrpc.protocols.stomp.AsyncClient] Stomp connection established (stompclient:138)
2019-01-21 23:41:32,200 WARNING (Detector thread) [vds.dispatcher] unhandled close
event (betterAsyncore:179)
2019-01-21 23:41:32,207 DEBUG (jsonrpc/1) [jsonrpc.JsonRpcServer] Calling
'event' in bridge with [] (__init__:329)
2019-01-21 23:41:32,208 DEBUG (jsonrpc/1) [jsonrpc.Notification] Sending event
{"params": {"content": true, "notify_time": 23083358880},
"jsonrpc": "2.0", "method": "vdsm.event"}
(__init__:181)
2019-01-21 23:41:32,210 DEBUG (jsonrpc/1) [jsonrpc.JsonRpcServer] Return
'event' in bridge with True (__init__:356)
2019-01-21 23:41:32,210 INFO (jsonrpc/1) [jsonrpc.JsonRpcServer] RPC call event
succeeded in 0.00 seconds (__init__:312)
2019-01-21 23:41:34,207 DEBUG (Client ::1:46303)
[yajsonrpc.protocols.stomp.AsyncClient] Timeout occurred, trying to reconnect
(stompclient:128)
2019-01-21 23:41:34,209 INFO (Detector thread) [ProtocolDetector.AcceptorImpl]
Accepted connection from ::1:43662 (protocoldetector:61)
2019-01-21 23:41:34,211 DEBUG (Detector thread) [ProtocolDetector.Detector] Using
required_size=11 (protocoldetector:89)
2019-01-21 23:41:44,222 DEBUG (Detector thread) [ProtocolDetector.Detector] Timed out
while waiting for data (protocoldetector:94)
2019-01-21 23:41:44,223 DEBUG (Client ::1:46303) [stomp.AsyncDispatcher] managed to
connect successfully. (stomp:388)
2019-01-21 23:41:46,227 DEBUG (Client ::1:46303)
[yajsonrpc.protocols.stomp.AsyncClient] Timeout occurred, trying to reconnect
(stompclient:128)
2019-01-21 23:41:46,230 INFO (Detector thread) [ProtocolDetector.AcceptorImpl]
Accepted connection from ::1:43664 (protocoldetector:61)
2019-01-21 23:41:46,230 DEBUG (Detector thread) [ProtocolDetector.Detector] Using
required_size=11 (protocoldetector:89)
2019-01-21 23:41:46,232 DEBUG (Client ::1:46303) [stomp.AsyncDispatcher] managed to
connect successfully. (stomp:388)
2019-01-21 23:41:46,233 INFO (Detector thread) [ProtocolDetector.Detector] Detected
protocol stomp from ::1:43664 (protocoldetector:125)
2019-01-21 23:41:46,235 INFO (Detector thread) [Broker.StompAdapter] Processing
CONNECT request (stompserver:95)
2019-01-21 23:41:46,236 DEBUG (Detector thread) [protocoldetector.StompDetector]
Stomp detected from ('::1', 43664) (stompserver:413)
2019-01-21 23:41:46,240 INFO (JsonRpc (StompReactor)) [Broker.StompAdapter]
Subscribe command received (stompserver:124)
2019-01-21 23:41:46,242 DEBUG (Client ::1:46303)
[yajsonrpc.protocols.stomp.AsyncClient] Stomp connection established (stompclient:138)
2019-01-21 23:41:46,281 INFO (JsonRpc (StompReactor)) [Broker.StompAdapter]
Subscribe command received (stompserver:124)
2019-01-21 23:41:47,200 WARNING (MainThread) [yajsonrpc.protocols.stomp.AsyncClient]
No subscription with 2a926ebd-35f9-47ce-9fb2-bec2823734f0 id (stompclient:211)
2019-01-21 23:41:47,201 WARNING (MainThread) [yajsonrpc.protocols.stomp.AsyncClient]
No subscription with b33e3bb3-1f1f-49c2-9ec2-073ec9f4fb33 id (stompclient:211)
2019-01-21 23:41:47,202 DEBUG (MainThread) [vds.MultiProtocolAcceptor] Stopping
Acceptor (protocoldetector:214)
2019-01-21 23:41:47,202 INFO (MainThread) [jsonrpc.JsonRCoverage.py
<http://jsonrpc.JsonRCoverage.py> warning: Module
/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/vdsm was never imported.
(module-not-imported)
pcServer] Stopping JsonRPC Server (__init__:442)
2019-01-21 23:41:47,203 DEBUG (JsonRpcServer) [root] FINISH thread
<Thread(JsonRpcServer, started daemon 140162164061952)> (concurrent:196)
2019-01-21 23:41:47,204 DEBUG (MainThread) [Executor] Stopping executor
(executor:137)
2019-01-21 23:41:47,204 DEBUG (Client ::1:46303) [root] FINISH thread
<Thread(Client ::1:46303, started daemon 140162147276544)> (concurrent:196)
2019-01-21 23:41:47,206 DEBUG (jsonrpc/0) [Executor] Worker stopped (executor:303)
2019-01-21 23:41:47,207 DEBUG (jsonrpc/2) [Executor] Worker stopped (executor:303)
2019-01-21 23:41:47,208 DEBUG (jsonrpc/3) [Executor] Worker stopped (executor:303)
2019-01-21 23:41:47,209 DEBUG (jsonrpc/4) [Executor] Worker stopped (executor:303)
2019-01-21 23:41:47,209 DEBUG (jsonrpc/5) [Executor] Worker stopped (executor:303)
2019-01-21 23:41:47,210 DEBUG (JsonRpc (StompReactor)) [root] FINISH thread
<Thread(JsonRpc (StompReactor), started daemon 140162271528704)> (concurrent:196)
2019-01-21 23:41:47,211 DEBUG (jsonrpc/6) [Executor] Worker stopped (executor:303)
2019-01-21 23:41:47,212 DEBUG (jsonrpc/0) [Executor] FINISH thread
<Thread(jsonrpc/0, started daemon 140162263136000)> (concurrent:196)
2019-01-21 23:41:47,212 DEBUG (jsonrpc/2) [Executor] FINISH thread
<Thread(jsonrpc/2, started daemon 140162751371008)> (concurrent:196)
2019-01-21 23:41:47,212 DEBUG (jsonrpc/3) [Executor] FINISH thread
<Thread(jsonrpc/3, started daemon 140162742978304)> (concurrent:196)
2019-01-21 23:41:47,212 DEBUG (MainThread) [Executor] Waiting for worker jsonrpc/5
(executor:290)
2019-01-21 23:41:47,212 DEBUG (jsonrpc/1) [Executor] Worker stopped (executor:303)
2019-01-21 23:41:47,216 DEBUG (jsonrpc/1) [Executor] FINISH thread
<Thread(jsonrpc/1, started daemon 140162288314112)> (concurrent:196)
2019-01-21 23:41:47,213 DEBUG (jsonrpc/4) [Executor] FINISH thread
<Thread(jsonrpc/4, started daemon 140162296706816)> (concurrent:196)
2019-01-21 23:41:47,214 DEBUG (jsonrpc/7) [Executor] Worker stopped (executor:303)
2019-01-21 23:41:47,214 DEBUG (jsonrpc/5) [Executor] FINISH thread
<Thread(jsonrpc/5, started daemon 140162279921408)> (concurrent:196)
2019-01-21 23:41:47,215 DEBUG (jsonrpc/6) [Executor] FINISH thread
<Thread(jsonrpc/6, started daemon 140162254743296)> (concurrent:196)
2019-01-21 23:41:47,217 DEBUG (jsonrpc/7) [Executor] FINISH thread
<Thread(jsonrpc/7, started daemon 140162246350592)> (concurrent:196)
2019-01-21 23:41:47,218 DEBUG (MainThread) [Executor] Waiting for worker jsonrpc/3
(executor:290)
2019-01-21 23:41:47,219 DEBUG (MainThread) [Executor] Waiting for worker jsonrpc/2
(executor:290)
2019-01-21 23:41:47,220 DEBUG (MainThread) [Executor] Waiting for worker jsonrpc/6
(executor:290)
2019-01-21 23:41:47,220 DEBUG (MainThread) [Executor] Waiting for worker jsonrpc/1
(executor:290)
2019-01-21 23:41:47,220 DEBUG (MainThread) [Executor] Waiting for worker jsonrpc/4
(executor:290)
2019-01-21 23:41:47,221 DEBUG (MainThread) [Executor] Waiting for worker jsonrpc/7
(executor:290)
2019-01-21 23:41:47,221 DEBUG (MainThread) [Executor] Waiting for worker jsonrpc/0
(executor:290)
2019-01-21 23:41:47,221 DEBUG (MainThread) [Scheduler] Stopping scheduler
test.Scheduler (schedule:110)
2019-01-21 23:41:47,222 DEBUG (test.Scheduler) [Scheduler] stopped (schedule:143)
2019-01-21 23:41:47,222 DEBUG (test.Scheduler) [Scheduler] FINISH thread
<Thread(test.Scheduler, started daemon 140162734585600)> (concurrent:196)
8:41 a.m.
On Wed, Jan 23, 2019 at 11:15 AM Marcin Sobczyk <msobczyk(a)redhat.com> wrote:
Hi,
I don't have time to look into this right now, but I will definitely do so
after coming back from FOSDEM.
Great.
We will mark this tests as broken_on_ci on Jenkins for now.
I think the issue for this and other failures is the race we have when
handling
STOMP CONNECT and SUBSCRIBE, see these patches trying to fix this on
the client side:
https://gerrit.ovirt.org/c/95899
Regards, Marcin
On 1/22/19 12:57 AM, Nir Soffer wrote:
On Tue, Jan 22, 2019 at 1:56 AM Nir Soffer <nsoffer(a)redhat.com> wrote:
> On Sat, Jan 19, 2019 at 11:15 PM Nir Soffer <nsoffer(a)redhat.com> wrote:
>
>> Recently this test cause too many random failures. I guess this is
>> the known issue with handling SUBSCRIBE in protocol detector.
>> I posted https://gerrit.ovirt.org/c/97099/
>> To mark it as broken until we have time to dig deeper
>>
>> ======================================================================
>>
>> FAIL: test_detect_slow_client_concurrency(True)
(protocoldetector_test.AcceptorTests)
>> ----------------------------------------------------------------------
>> Traceback (most recent call last):
>> File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/testlib.py", line
142, in wrapper
>> return f(self, *args)
>> File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/protocoldetector_test.py",
line 167, in test_detect_slow_client_concurrency
>> self.check_concurrently(self.check_slow_client, use_ssl)
>> File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/protocoldetector_test.py",
line 266, in check_concurrently
>> self.assertTrue(all(done))
>> AssertionError: False is not true
>> -------------------- >> begin captured logging <<
--------------------
>> 2019-01-19 20:47:16,021 DEBUG (MainThread) [vds.MultiProtocolAcceptor] Creating
socket (host='127.0.0.1', port=0, family=2, socketype=1, proto=6)
(protocoldetector:225)
>> 2019-01-19 20:47:16,022 INFO (MainThread) [vds.MultiProtocolAcceptor] Listening
at 127.0.0.1:46009 (protocoldetector:183)
>> 2019-01-19 20:47:16,023 DEBUG (MainThread) [vds.MultiProtocolAcceptor] Adding
detector <protocoldetector_test.Echo object at 0x7f1bb77f8dd0>
(protocoldetector:210)
>> 2019-01-19 20:47:16,024 DEBUG (MainThread) [vds.MultiProtocolAcceptor] Adding
detector <protocoldetector_test.Uppercase object at 0x7f1bb77f8c90>
(protocoldetector:210)
>> 2019-01-19 20:47:16,031 INFO (Thread-61) [ProtocolDetector.AcceptorImpl]
Accepted connection from 127.0.0.1:51950 (protocoldetector:61)
>> 2019-01-19 20:47:16,047 INFO (Thread-61) [ProtocolDetector.AcceptorImpl]
Accepted connection from 127.0.0.1:51952 (protocoldetector:61)
>> 2019-01-19 20:47:16,048 INFO (Thread-61) [ProtocolDetector.AcceptorImpl]
Accepted connection from 127.0.0.1:51954 (protocoldetector:61)
>> 2019-01-19 20:47:16,065 INFO (Thread-61) [ProtocolDetector.AcceptorImpl]
Accepted connection from 127.0.0.1:51956 (protocoldetector:61)
>> 2019-01-19 20:47:16,068 INFO (Thread-61) [ProtocolDetector.AcceptorImpl]
Accepted connection from 127.0.0.1:51958 (protocoldetector:61)
>> 2019-01-19 20:47:16,069 DEBUG (Thread-61) [ProtocolDetector.Detector] Using
required_size=9 (protocoldetector:89)
>> 2019-01-19 20:47:16,097 DEBUG (Thread-61) [ProtocolDetector.Detector] Using
required_size=9 (protocoldetector:89)
>> 2019-01-19 20:47:16,099 DEBUG (Thread-61) [ProtocolDetector.Detector] Using
required_size=9 (protocoldetector:89)
>> 2019-01-19 20:47:16,107 DEBUG (Thread-61) [ProtocolDetector.Detector] Using
required_size=9 (protocoldetector:89)
>> 2019-01-19 20:47:16,109 DEBUG (Thread-61) [ProtocolDetector.Detector] Using
required_size=9 (protocoldetector:89)
>> 2019-01-19 20:47:16,574 INFO (Thread-61) [ProtocolDetector.Detector] Detected
protocol echo from 127.0.0.1:51950 (protocoldetector:125)
>> 2019-01-19 20:47:17,570 DEBUG (Thread-61) [ProtocolDetector.Detector] Timed out
while waiting for data (protocoldetector:94)
>> 2019-01-19 20:47:17,571 DEBUG (Thread-61) [ProtocolDetector.Detector] Timed out
while waiting for data (protocoldetector:94)
>> 2019-01-19 20:47:17,576 DEBUG (Thread-61) [ProtocolDetector.Detector] Timed out
while waiting for data (protocoldetector:94)
>> 2019-01-19 20:47:17,578 DEBUG (Thread-61) [ProtocolDetector.Detector] Timed out
while waiting for data (protocoldetector:94)
>> --------------------- >> end captured logging <<
---------------------
>>
>>
> Another flaky test - we marked the other test in this class as broken on
> ci
> recently. This test fail randomly from time to time.
>
Failed this build:
https://jenkins.ovirt.org/job/vdsm_standard-check-patch/2158//artifact/ch...
>
> ======================================================================
> ERROR: test_event(False) (stomp_test.StompTests)
> ----------------------------------------------------------------------
> Traceback (most recent call last):
> File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/testlib.py", line
142, in wrapper
> return f(self, *args)
> File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/stomp_test.py",
line 118, in test_event
> client.callMethod("event", [], str(uuid4()))
> File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/lib/yajsonrpc/jsonrpcclient.py",
line 78, in callMethod
> raise exception.JsonRpcNoResponseError(method=methodName)
> JsonRpcNoResponseError: No response for JSON-RPC request: {'method':
'event'}
> -------------------- >> begin captured logging << --------------------
> 2019-01-21 23:41:32,132 DEBUG (MainThread) [vds.MultiProtocolAcceptor] Creating
socket (host='::1', port=0, family=10, socketype=1, proto=6)
(protocoldetector:225)
> 2019-01-21 23:41:32,133 INFO (MainThread) [vds.MultiProtocolAcceptor] Listening at
::1:46303 (protocoldetector:183)
> 2019-01-21 23:41:32,134 DEBUG (MainThread) [Scheduler] Starting scheduler
test.Scheduler (schedule:98)
> 2019-01-21 23:41:32,135 DEBUG (test.Scheduler) [Scheduler] START thread
<Thread(test.Scheduler, started daemon 140162734585600)> (func=<bound method
Scheduler._run of <vdsm.schedule.Scheduler object at 0x7f7a2c156e10>>, args=(),
kwargs={}) (concurrent:193)
> 2019-01-21 23:41:32,138 DEBUG (test.Scheduler) [Scheduler] started (schedule:140)
> 2019-01-21 23:41:32,139 DEBUG (JsonRpc (StompReactor)) [root] START thread
<Thread(JsonRpc (StompReactor), started daemon 140162271528704)> (func=<bound
method StompReactor.process_requests of <yajsonrpc.stompserver.StompReactor object at
0x7f7a2c177950>>, args=(), kwargs={}) (concurrent:193)
> 2019-01-21 23:41:32,139 DEBUG (MainThread) [Executor] Starting executor
(executor:128)
> 2019-01-21 23:41:32,141 DEBUG (MainThread) [Executor] Starting worker jsonrpc/0
(executor:286)
> 2019-01-21 23:41:32,142 DEBUG (MainThread) [Executor] Starting worker jsonrpc/1
(executor:286)
> 2019-01-21 23:41:32,143 DEBUG (jsonrpc/1) [Executor] START thread
<Thread(jsonrpc/1, started daemon 140162288314112)> (func=<bound method
_Worker._run of <Worker name=jsonrpc/1 waiting task#=0 at 0x7f7a2c177510>>,
args=(), kwargs={}) (concurrent:193)
> 2019-01-21 23:41:32,144 DEBUG (MainThread) [Executor] Starting worker jsonrpc/2
(executor:286)
> 2019-01-21 23:41:32,144 DEBUG (jsonrpc/0) [Executor] START thread
<Thread(jsonrpc/0, started daemon 140162263136000)> (func=<bound method
_Worker._run of <Worker name=jsonrpc/0 waiting task#=0 at 0x7f7a2c177d50>>,
args=(), kwargs={}) (concurrent:193)
> 2019-01-21 23:41:32,145 DEBUG (jsonrpc/1) [Executor] Worker started (executor:298)
> 2019-01-21 23:41:32,147 DEBUG (MainThread) [Executor] Starting worker jsonrpc/3
(executor:286)
> 2019-01-21 23:41:32,148 DEBUG (jsonrpc/2) [Executor] START thread
<Thread(jsonrpc/2, started daemon 140162751371008)> (func=<bound method
_Worker._run of <Worker name=jsonrpc/2 waiting task#=0 at 0x7f7a2c177ad0>>,
args=(), kwargs={}) (concurrent:193)
> 2019-01-21 23:41:32,149 DEBUG (jsonrpc/0) [Executor] Worker started (executor:298)
> 2019-01-21 23:41:32,153 DEBUG (jsonrpc/2) [Executor] Worker started (executor:298)
> 2019-01-21 23:41:32,154 DEBUG (MainThread) [Executor] Starting worker jsonrpc/4
(executor:286)
> 2019-01-21 23:41:32,155 DEBUG (jsonrpc/3) [Executor] START thread
<Thread(jsonrpc/3, started daemon 140162742978304)> (func=<bound method
_Worker._run of <Worker name=jsonrpc/3 waiting task#=0 at 0x7f7a2c112e10>>,
args=(), kwargs={}) (concurrent:193)
> 2019-01-21 23:41:32,158 DEBUG (jsonrpc/3) [Executor] Worker started (executor:298)
> 2019-01-21 23:41:32,159 DEBUG (MainThread) [Executor] Starting worker jsonrpc/5
(executor:286)
> 2019-01-21 23:41:32,160 DEBUG (jsonrpc/4) [Executor] START thread
<Thread(jsonrpc/4, started daemon 140162296706816)> (func=<bound method
_Worker._run of <Worker name=jsonrpc/4 waiting task#=0 at 0x7f7a2c112d50>>,
args=(), kwargs={}) (concurrent:193)
> 2019-01-21 23:41:32,161 DEBUG (jsonrpc/4) [Executor] Worker started (executor:298)
> 2019-01-21 23:41:32,163 DEBUG (MainThread) [Executor] Starting worker jsonrpc/6
(executor:286)
> 2019-01-21 23:41:32,164 DEBUG (jsonrpc/5) [Executor] START thread
<Thread(jsonrpc/5, started daemon 140162279921408)> (func=<bound method
_Worker._run of <Worker name=jsonrpc/5 waiting task#=0 at 0x7f7a2c112810>>,
args=(), kwargs={}) (concurrent:193)
> 2019-01-21 23:41:32,166 DEBUG (jsonrpc/6) [Executor] START thread
<Thread(jsonrpc/6, started daemon 140162254743296)> (func=<bound method
_Worker._run of <Worker name=jsonrpc/6 waiting task#=0 at 0x7f7a2c1924d0>>,
args=(), kwargs={}) (concurrent:193)
> 2019-01-21 23:41:32,166 DEBUG (MainThread) [Executor] Starting worker jsonrpc/7
(executor:286)
> 2019-01-21 23:41:32,167 DEBUG (jsonrpc/5) [Executor] Worker started (executor:298)
> 2019-01-21 23:41:32,169 DEBUG (jsonrpc/6) [Executor] Worker started (executor:298)
> 2019-01-21 23:41:32,172 DEBUG (jsonrpc/7) [Executor] START thread
<Thread(jsonrpc/7, started daemon 140162246350592)> (func=<bound method
_Worker._run of <Worker name=jsonrpc/7 waiting task#=0 at 0x7f7a2c1921d0>>,
args=(), kwargs={}) (concurrent:193)
> 2019-01-21 23:41:32,173 DEBUG (MainThread) [vds.MultiProtocolAcceptor] Adding
detector <yajsonrpc.stompserver.StompDetector instance at 0x7f7a13fa7050>
(protocoldetector:210)
> 2019-01-21 23:41:32,173 DEBUG (JsonRpcServer) [root] START thread
<Thread(JsonRpcServer, started daemon 140162164061952)> (func=<bound method
JsonRpcServer.serve_requests of <yajsonrpc.JsonRpcServer object at
0x7f7a2c177bd0>>, args=(), kwargs={}) (concurrent:193)
> 2019-01-21 23:41:32,174 DEBUG (jsonrpc/7) [Executor] Worker started (executor:298)
> 2019-01-21 23:41:32,181 INFO (Detector thread) [ProtocolDetector.AcceptorImpl]
Accepted connection from ::1:43660 (protocoldetector:61)
> 2019-01-21 23:41:32,185 DEBUG (MainThread) [jsonrpc.AsyncoreClient] Sending response
(stompclient:294)
> 2019-01-21 23:41:32,185 DEBUG (Detector thread) [ProtocolDetector.Detector] Using
required_size=11 (protocoldetector:89)
> 2019-01-21 23:41:32,187 DEBUG (Client ::1:46303) [root] START thread
<Thread(Client ::1:46303, started daemon 140162147276544)> (func=<bound method
Reactor.process_requests of <yajsonrpc.betterAsyncore.Reactor object at
0x7f7a2c156610>>, args=(), kwargs={}) (concurrent:193)
> 2019-01-21 23:41:32,189 INFO (Detector thread) [ProtocolDetector.Detector] Detected
protocol stomp from ::1:43660 (protocoldetector:125)
> 2019-01-21 23:41:32,192 INFO (Detector thread) [Broker.StompAdapter] Processing
CONNECT request (stompserver:95)
> 2019-01-21 23:41:32,195 INFO (JsonRpc (StompReactor)) [Broker.StompAdapter]
Subscribe command received (stompserver:124)
> 2019-01-21 23:41:32,196 INFO (JsonRpc (StompReactor)) [Broker.StompAdapter]
Subscribe command received (stompserver:124)
> 2019-01-21 23:41:32,197 ERROR (Detector thread) [vds.dispatcher] uncaptured python
exception, closing channel <yajsonrpc.betterAsyncore.Dispatcher ('::1', 43660,
0, 0) at 0x7f7a13fdaab8> (<type
'exceptions.AttributeError'>:'NoneType' object has no attribute
'command' [/usr/lib64/python2.7/asyncore.py|readwrite|108]
[/usr/lib64/python2.7/asyncore.py|handle_read_event|449]
[/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|412]
[/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|635]
[/usr/lib64/python2.7/asyncore.py|handle_read_event|449]
[/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|415]
[/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/lib/yajsonrpc/stompserver.py|handle_frame|269])
(betterAsyncore:179)
> 2019-01-21 23:41:32,199 DEBUG (Client ::1:46303)
[yajsonrpc.protocols.stomp.AsyncClient] Stomp connection established (stompclient:138)
> 2019-01-21 23:41:32,200 WARNING (Detector thread) [vds.dispatcher] unhandled close
event (betterAsyncore:179)
> 2019-01-21 23:41:32,207 DEBUG (jsonrpc/1) [jsonrpc.JsonRpcServer] Calling
'event' in bridge with [] (__init__:329)
> 2019-01-21 23:41:32,208 DEBUG (jsonrpc/1) [jsonrpc.Notification] Sending event
{"params": {"content": true, "notify_time": 23083358880},
"jsonrpc": "2.0", "method": "vdsm.event"}
(__init__:181)
> 2019-01-21 23:41:32,210 DEBUG (jsonrpc/1) [jsonrpc.JsonRpcServer] Return
'event' in bridge with True (__init__:356)
> 2019-01-21 23:41:32,210 INFO (jsonrpc/1) [jsonrpc.JsonRpcServer] RPC call event
succeeded in 0.00 seconds (__init__:312)
> 2019-01-21 23:41:34,207 DEBUG (Client ::1:46303)
[yajsonrpc.protocols.stomp.AsyncClient] Timeout occurred, trying to reconnect
(stompclient:128)
> 2019-01-21 23:41:34,209 INFO (Detector thread) [ProtocolDetector.AcceptorImpl]
Accepted connection from ::1:43662 (protocoldetector:61)
> 2019-01-21 23:41:34,211 DEBUG (Detector thread) [ProtocolDetector.Detector] Using
required_size=11 (protocoldetector:89)
> 2019-01-21 23:41:44,222 DEBUG (Detector thread) [ProtocolDetector.Detector] Timed out
while waiting for data (protocoldetector:94)
> 2019-01-21 23:41:44,223 DEBUG (Client ::1:46303) [stomp.AsyncDispatcher] managed to
connect successfully. (stomp:388)
> 2019-01-21 23:41:46,227 DEBUG (Client ::1:46303)
[yajsonrpc.protocols.stomp.AsyncClient] Timeout occurred, trying to reconnect
(stompclient:128)
> 2019-01-21 23:41:46,230 INFO (Detector thread) [ProtocolDetector.AcceptorImpl]
Accepted connection from ::1:43664 (protocoldetector:61)
> 2019-01-21 23:41:46,230 DEBUG (Detector thread) [ProtocolDetector.Detector] Using
required_size=11 (protocoldetector:89)
> 2019-01-21 23:41:46,232 DEBUG (Client ::1:46303) [stomp.AsyncDispatcher] managed to
connect successfully. (stomp:388)
> 2019-01-21 23:41:46,233 INFO (Detector thread) [ProtocolDetector.Detector] Detected
protocol stomp from ::1:43664 (protocoldetector:125)
> 2019-01-21 23:41:46,235 INFO (Detector thread) [Broker.StompAdapter] Processing
CONNECT request (stompserver:95)
> 2019-01-21 23:41:46,236 DEBUG (Detector thread) [protocoldetector.StompDetector]
Stomp detected from ('::1', 43664) (stompserver:413)
> 2019-01-21 23:41:46,240 INFO (JsonRpc (StompReactor)) [Broker.StompAdapter]
Subscribe command received (stompserver:124)
> 2019-01-21 23:41:46,242 DEBUG (Client ::1:46303)
[yajsonrpc.protocols.stomp.AsyncClient] Stomp connection established (stompclient:138)
> 2019-01-21 23:41:46,281 INFO (JsonRpc (StompReactor)) [Broker.StompAdapter]
Subscribe command received (stompserver:124)
> 2019-01-21 23:41:47,200 WARNING (MainThread) [yajsonrpc.protocols.stomp.AsyncClient]
No subscription with 2a926ebd-35f9-47ce-9fb2-bec2823734f0 id (stompclient:211)
> 2019-01-21 23:41:47,201 WARNING (MainThread) [yajsonrpc.protocols.stomp.AsyncClient]
No subscription with b33e3bb3-1f1f-49c2-9ec2-073ec9f4fb33 id (stompclient:211)
> 2019-01-21 23:41:47,202 DEBUG (MainThread) [vds.MultiProtocolAcceptor] Stopping
Acceptor (protocoldetector:214)
> 2019-01-21 23:41:47,202 INFO (MainThread) [jsonrpc.JsonRCoverage.py warning: Module
/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/vdsm was never imported.
(module-not-imported)
> pcServer] Stopping JsonRPC Server (__init__:442)
> 2019-01-21 23:41:47,203 DEBUG (JsonRpcServer) [root] FINISH thread
<Thread(JsonRpcServer, started daemon 140162164061952)> (concurrent:196)
> 2019-01-21 23:41:47,204 DEBUG (MainThread) [Executor] Stopping executor
(executor:137)
> 2019-01-21 23:41:47,204 DEBUG (Client ::1:46303) [root] FINISH thread
<Thread(Client ::1:46303, started daemon 140162147276544)> (concurrent:196)
> 2019-01-21 23:41:47,206 DEBUG (jsonrpc/0) [Executor] Worker stopped (executor:303)
> 2019-01-21 23:41:47,207 DEBUG (jsonrpc/2) [Executor] Worker stopped (executor:303)
> 2019-01-21 23:41:47,208 DEBUG (jsonrpc/3) [Executor] Worker stopped (executor:303)
> 2019-01-21 23:41:47,209 DEBUG (jsonrpc/4) [Executor] Worker stopped (executor:303)
> 2019-01-21 23:41:47,209 DEBUG (jsonrpc/5) [Executor] Worker stopped (executor:303)
> 2019-01-21 23:41:47,210 DEBUG (JsonRpc (StompReactor)) [root] FINISH thread
<Thread(JsonRpc (StompReactor), started daemon 140162271528704)> (concurrent:196)
> 2019-01-21 23:41:47,211 DEBUG (jsonrpc/6) [Executor] Worker stopped (executor:303)
> 2019-01-21 23:41:47,212 DEBUG (jsonrpc/0) [Executor] FINISH thread
<Thread(jsonrpc/0, started daemon 140162263136000)> (concurrent:196)
> 2019-01-21 23:41:47,212 DEBUG (jsonrpc/2) [Executor] FINISH thread
<Thread(jsonrpc/2, started daemon 140162751371008)> (concurrent:196)
> 2019-01-21 23:41:47,212 DEBUG (jsonrpc/3) [Executor] FINISH thread
<Thread(jsonrpc/3, started daemon 140162742978304)> (concurrent:196)
> 2019-01-21 23:41:47,212 DEBUG (MainThread) [Executor] Waiting for worker jsonrpc/5
(executor:290)
> 2019-01-21 23:41:47,212 DEBUG (jsonrpc/1) [Executor] Worker stopped (executor:303)
> 2019-01-21 23:41:47,216 DEBUG (jsonrpc/1) [Executor] FINISH thread
<Thread(jsonrpc/1, started daemon 140162288314112)> (concurrent:196)
> 2019-01-21 23:41:47,213 DEBUG (jsonrpc/4) [Executor] FINISH thread
<Thread(jsonrpc/4, started daemon 140162296706816)> (concurrent:196)
> 2019-01-21 23:41:47,214 DEBUG (jsonrpc/7) [Executor] Worker stopped (executor:303)
> 2019-01-21 23:41:47,214 DEBUG (jsonrpc/5) [Executor] FINISH thread
<Thread(jsonrpc/5, started daemon 140162279921408)> (concurrent:196)
> 2019-01-21 23:41:47,215 DEBUG (jsonrpc/6) [Executor] FINISH thread
<Thread(jsonrpc/6, started daemon 140162254743296)> (concurrent:196)
> 2019-01-21 23:41:47,217 DEBUG (jsonrpc/7) [Executor] FINISH thread
<Thread(jsonrpc/7, started daemon 140162246350592)> (concurrent:196)
> 2019-01-21 23:41:47,218 DEBUG (MainThread) [Executor] Waiting for worker jsonrpc/3
(executor:290)
> 2019-01-21 23:41:47,219 DEBUG (MainThread) [Executor] Waiting for worker jsonrpc/2
(executor:290)
> 2019-01-21 23:41:47,220 DEBUG (MainThread) [Executor] Waiting for worker jsonrpc/6
(executor:290)
> 2019-01-21 23:41:47,220 DEBUG (MainThread) [Executor] Waiting for worker jsonrpc/1
(executor:290)
> 2019-01-21 23:41:47,220 DEBUG (MainThread) [Executor] Waiting for worker jsonrpc/4
(executor:290)
> 2019-01-21 23:41:47,221 DEBUG (MainThread) [Executor] Waiting for worker jsonrpc/7
(executor:290)
> 2019-01-21 23:41:47,221 DEBUG (MainThread) [Executor] Waiting for worker jsonrpc/0
(executor:290)
> 2019-01-21 23:41:47,221 DEBUG (MainThread) [Scheduler] Stopping scheduler
test.Scheduler (schedule:110)
> 2019-01-21 23:41:47,222 DEBUG (test.Scheduler) [Scheduler] stopped (schedule:143)
> 2019-01-21 23:41:47,222 DEBUG (test.Scheduler) [Scheduler] FINISH thread
<Thread(test.Scheduler, started daemon 140162734585600)> (concurrent:196)
>
>
>
3:02 p.m.
Another failure today:
FAIL: test_event(False) (stomp_test.StompTests)
----------------------------------------------------------------------
Traceback (most recent call last):
File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/testlib.py",
line 142, in wrapper
return f(self, *args)
File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/stomp_test.py",
line 123, in test_event
self.fail("Event queue timed out.")
AssertionError: Event queue timed out.
https://jenkins.ovirt.org/job/vdsm_standard-check-patch/2501//artifact/ch...
On Wed, Jan 23, 2019 at 3:41 PM Nir Soffer <nsoffer(a)redhat.com> wrote:
On Wed, Jan 23, 2019 at 11:15 AM Marcin Sobczyk
<msobczyk(a)redhat.com>
wrote:
> Hi,
>
> I don't have time to look into this right now, but I will definitely do
> so after coming back from FOSDEM.
>
Great.
We will mark this tests as broken_on_ci on Jenkins for now.
I think the issue for this and other failures is the race we have when
handling
STOMP CONNECT and SUBSCRIBE, see these patches trying to fix this on
the client side:
https://gerrit.ovirt.org/c/95899
> Regards, Marcin
> On 1/22/19 12:57 AM, Nir Soffer wrote:
>
> On Tue, Jan 22, 2019 at 1:56 AM Nir Soffer <nsoffer(a)redhat.com> wrote:
>
>> On Sat, Jan 19, 2019 at 11:15 PM Nir Soffer <nsoffer(a)redhat.com> wrote:
>>
>>> Recently this test cause too many random failures. I guess this is
>>> the known issue with handling SUBSCRIBE in protocol detector.
>>> I posted https://gerrit.ovirt.org/c/97099/
>>> To mark it as broken until we have time to dig deeper
>>>
>>> ======================================================================
>>>
>>> FAIL: test_detect_slow_client_concurrency(True)
(protocoldetector_test.AcceptorTests)
>>> ----------------------------------------------------------------------
>>> Traceback (most recent call last):
>>> File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/testlib.py", line
142, in wrapper
>>> return f(self, *args)
>>> File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/protocoldetector_test.py",
line 167, in test_detect_slow_client_concurrency
>>> self.check_concurrently(self.check_slow_client, use_ssl)
>>> File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/protocoldetector_test.py",
line 266, in check_concurrently
>>> self.assertTrue(all(done))
>>> AssertionError: False is not true
>>> -------------------- >> begin captured logging <<
--------------------
>>> 2019-01-19 20:47:16,021 DEBUG (MainThread) [vds.MultiProtocolAcceptor]
Creating socket (host='127.0.0.1', port=0, family=2, socketype=1, proto=6)
(protocoldetector:225)
>>> 2019-01-19 20:47:16,022 INFO (MainThread) [vds.MultiProtocolAcceptor]
Listening at 127.0.0.1:46009 (protocoldetector:183)
>>> 2019-01-19 20:47:16,023 DEBUG (MainThread) [vds.MultiProtocolAcceptor] Adding
detector <protocoldetector_test.Echo object at 0x7f1bb77f8dd0>
(protocoldetector:210)
>>> 2019-01-19 20:47:16,024 DEBUG (MainThread) [vds.MultiProtocolAcceptor] Adding
detector <protocoldetector_test.Uppercase object at 0x7f1bb77f8c90>
(protocoldetector:210)
>>> 2019-01-19 20:47:16,031 INFO (Thread-61) [ProtocolDetector.AcceptorImpl]
Accepted connection from 127.0.0.1:51950 (protocoldetector:61)
>>> 2019-01-19 20:47:16,047 INFO (Thread-61) [ProtocolDetector.AcceptorImpl]
Accepted connection from 127.0.0.1:51952 (protocoldetector:61)
>>> 2019-01-19 20:47:16,048 INFO (Thread-61) [ProtocolDetector.AcceptorImpl]
Accepted connection from 127.0.0.1:51954 (protocoldetector:61)
>>> 2019-01-19 20:47:16,065 INFO (Thread-61) [ProtocolDetector.AcceptorImpl]
Accepted connection from 127.0.0.1:51956 (protocoldetector:61)
>>> 2019-01-19 20:47:16,068 INFO (Thread-61) [ProtocolDetector.AcceptorImpl]
Accepted connection from 127.0.0.1:51958 (protocoldetector:61)
>>> 2019-01-19 20:47:16,069 DEBUG (Thread-61) [ProtocolDetector.Detector] Using
required_size=9 (protocoldetector:89)
>>> 2019-01-19 20:47:16,097 DEBUG (Thread-61) [ProtocolDetector.Detector] Using
required_size=9 (protocoldetector:89)
>>> 2019-01-19 20:47:16,099 DEBUG (Thread-61) [ProtocolDetector.Detector] Using
required_size=9 (protocoldetector:89)
>>> 2019-01-19 20:47:16,107 DEBUG (Thread-61) [ProtocolDetector.Detector] Using
required_size=9 (protocoldetector:89)
>>> 2019-01-19 20:47:16,109 DEBUG (Thread-61) [ProtocolDetector.Detector] Using
required_size=9 (protocoldetector:89)
>>> 2019-01-19 20:47:16,574 INFO (Thread-61) [ProtocolDetector.Detector]
Detected protocol echo from 127.0.0.1:51950 (protocoldetector:125)
>>> 2019-01-19 20:47:17,570 DEBUG (Thread-61) [ProtocolDetector.Detector] Timed
out while waiting for data (protocoldetector:94)
>>> 2019-01-19 20:47:17,571 DEBUG (Thread-61) [ProtocolDetector.Detector] Timed
out while waiting for data (protocoldetector:94)
>>> 2019-01-19 20:47:17,576 DEBUG (Thread-61) [ProtocolDetector.Detector] Timed
out while waiting for data (protocoldetector:94)
>>> 2019-01-19 20:47:17,578 DEBUG (Thread-61) [ProtocolDetector.Detector] Timed
out while waiting for data (protocoldetector:94)
>>> --------------------- >> end captured logging <<
---------------------
>>>
>>>
>> Another flaky test - we marked the other test in this class as broken on
>> ci
>> recently. This test fail randomly from time to time.
>>
>
> Failed this build:
>
>
https://jenkins.ovirt.org/job/vdsm_standard-check-patch/2158//artifact/ch...
>
>
>
>>
>> ======================================================================
>> ERROR: test_event(False) (stomp_test.StompTests)
>> ----------------------------------------------------------------------
>> Traceback (most recent call last):
>> File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/testlib.py", line
142, in wrapper
>> return f(self, *args)
>> File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/stomp_test.py",
line 118, in test_event
>> client.callMethod("event", [], str(uuid4()))
>> File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/lib/yajsonrpc/jsonrpcclient.py",
line 78, in callMethod
>> raise exception.JsonRpcNoResponseError(method=methodName)
>> JsonRpcNoResponseError: No response for JSON-RPC request: {'method':
'event'}
>> -------------------- >> begin captured logging <<
--------------------
>> 2019-01-21 23:41:32,132 DEBUG (MainThread) [vds.MultiProtocolAcceptor] Creating
socket (host='::1', port=0, family=10, socketype=1, proto=6)
(protocoldetector:225)
>> 2019-01-21 23:41:32,133 INFO (MainThread) [vds.MultiProtocolAcceptor] Listening
at ::1:46303 (protocoldetector:183)
>> 2019-01-21 23:41:32,134 DEBUG (MainThread) [Scheduler] Starting scheduler
test.Scheduler (schedule:98)
>> 2019-01-21 23:41:32,135 DEBUG (test.Scheduler) [Scheduler] START thread
<Thread(test.Scheduler, started daemon 140162734585600)> (func=<bound method
Scheduler._run of <vdsm.schedule.Scheduler object at 0x7f7a2c156e10>>, args=(),
kwargs={}) (concurrent:193)
>> 2019-01-21 23:41:32,138 DEBUG (test.Scheduler) [Scheduler] started
(schedule:140)
>> 2019-01-21 23:41:32,139 DEBUG (JsonRpc (StompReactor)) [root] START thread
<Thread(JsonRpc (StompReactor), started daemon 140162271528704)> (func=<bound
method StompReactor.process_requests of <yajsonrpc.stompserver.StompReactor object at
0x7f7a2c177950>>, args=(), kwargs={}) (concurrent:193)
>> 2019-01-21 23:41:32,139 DEBUG (MainThread) [Executor] Starting executor
(executor:128)
>> 2019-01-21 23:41:32,141 DEBUG (MainThread) [Executor] Starting worker jsonrpc/0
(executor:286)
>> 2019-01-21 23:41:32,142 DEBUG (MainThread) [Executor] Starting worker jsonrpc/1
(executor:286)
>> 2019-01-21 23:41:32,143 DEBUG (jsonrpc/1) [Executor] START thread
<Thread(jsonrpc/1, started daemon 140162288314112)> (func=<bound method
_Worker._run of <Worker name=jsonrpc/1 waiting task#=0 at 0x7f7a2c177510>>,
args=(), kwargs={}) (concurrent:193)
>> 2019-01-21 23:41:32,144 DEBUG (MainThread) [Executor] Starting worker jsonrpc/2
(executor:286)
>> 2019-01-21 23:41:32,144 DEBUG (jsonrpc/0) [Executor] START thread
<Thread(jsonrpc/0, started daemon 140162263136000)> (func=<bound method
_Worker._run of <Worker name=jsonrpc/0 waiting task#=0 at 0x7f7a2c177d50>>,
args=(), kwargs={}) (concurrent:193)
>> 2019-01-21 23:41:32,145 DEBUG (jsonrpc/1) [Executor] Worker started
(executor:298)
>> 2019-01-21 23:41:32,147 DEBUG (MainThread) [Executor] Starting worker jsonrpc/3
(executor:286)
>> 2019-01-21 23:41:32,148 DEBUG (jsonrpc/2) [Executor] START thread
<Thread(jsonrpc/2, started daemon 140162751371008)> (func=<bound method
_Worker._run of <Worker name=jsonrpc/2 waiting task#=0 at 0x7f7a2c177ad0>>,
args=(), kwargs={}) (concurrent:193)
>> 2019-01-21 23:41:32,149 DEBUG (jsonrpc/0) [Executor] Worker started
(executor:298)
>> 2019-01-21 23:41:32,153 DEBUG (jsonrpc/2) [Executor] Worker started
(executor:298)
>> 2019-01-21 23:41:32,154 DEBUG (MainThread) [Executor] Starting worker jsonrpc/4
(executor:286)
>> 2019-01-21 23:41:32,155 DEBUG (jsonrpc/3) [Executor] START thread
<Thread(jsonrpc/3, started daemon 140162742978304)> (func=<bound method
_Worker._run of <Worker name=jsonrpc/3 waiting task#=0 at 0x7f7a2c112e10>>,
args=(), kwargs={}) (concurrent:193)
>> 2019-01-21 23:41:32,158 DEBUG (jsonrpc/3) [Executor] Worker started
(executor:298)
>> 2019-01-21 23:41:32,159 DEBUG (MainThread) [Executor] Starting worker jsonrpc/5
(executor:286)
>> 2019-01-21 23:41:32,160 DEBUG (jsonrpc/4) [Executor] START thread
<Thread(jsonrpc/4, started daemon 140162296706816)> (func=<bound method
_Worker._run of <Worker name=jsonrpc/4 waiting task#=0 at 0x7f7a2c112d50>>,
args=(), kwargs={}) (concurrent:193)
>> 2019-01-21 23:41:32,161 DEBUG (jsonrpc/4) [Executor] Worker started
(executor:298)
>> 2019-01-21 23:41:32,163 DEBUG (MainThread) [Executor] Starting worker jsonrpc/6
(executor:286)
>> 2019-01-21 23:41:32,164 DEBUG (jsonrpc/5) [Executor] START thread
<Thread(jsonrpc/5, started daemon 140162279921408)> (func=<bound method
_Worker._run of <Worker name=jsonrpc/5 waiting task#=0 at 0x7f7a2c112810>>,
args=(), kwargs={}) (concurrent:193)
>> 2019-01-21 23:41:32,166 DEBUG (jsonrpc/6) [Executor] START thread
<Thread(jsonrpc/6, started daemon 140162254743296)> (func=<bound method
_Worker._run of <Worker name=jsonrpc/6 waiting task#=0 at 0x7f7a2c1924d0>>,
args=(), kwargs={}) (concurrent:193)
>> 2019-01-21 23:41:32,166 DEBUG (MainThread) [Executor] Starting worker jsonrpc/7
(executor:286)
>> 2019-01-21 23:41:32,167 DEBUG (jsonrpc/5) [Executor] Worker started
(executor:298)
>> 2019-01-21 23:41:32,169 DEBUG (jsonrpc/6) [Executor] Worker started
(executor:298)
>> 2019-01-21 23:41:32,172 DEBUG (jsonrpc/7) [Executor] START thread
<Thread(jsonrpc/7, started daemon 140162246350592)> (func=<bound method
_Worker._run of <Worker name=jsonrpc/7 waiting task#=0 at 0x7f7a2c1921d0>>,
args=(), kwargs={}) (concurrent:193)
>> 2019-01-21 23:41:32,173 DEBUG (MainThread) [vds.MultiProtocolAcceptor] Adding
detector <yajsonrpc.stompserver.StompDetector instance at 0x7f7a13fa7050>
(protocoldetector:210)
>> 2019-01-21 23:41:32,173 DEBUG (JsonRpcServer) [root] START thread
<Thread(JsonRpcServer, started daemon 140162164061952)> (func=<bound method
JsonRpcServer.serve_requests of <yajsonrpc.JsonRpcServer object at
0x7f7a2c177bd0>>, args=(), kwargs={}) (concurrent:193)
>> 2019-01-21 23:41:32,174 DEBUG (jsonrpc/7) [Executor] Worker started
(executor:298)
>> 2019-01-21 23:41:32,181 INFO (Detector thread) [ProtocolDetector.AcceptorImpl]
Accepted connection from ::1:43660 (protocoldetector:61)
>> 2019-01-21 23:41:32,185 DEBUG (MainThread) [jsonrpc.AsyncoreClient] Sending
response (stompclient:294)
>> 2019-01-21 23:41:32,185 DEBUG (Detector thread) [ProtocolDetector.Detector] Using
required_size=11 (protocoldetector:89)
>> 2019-01-21 23:41:32,187 DEBUG (Client ::1:46303) [root] START thread
<Thread(Client ::1:46303, started daemon 140162147276544)> (func=<bound method
Reactor.process_requests of <yajsonrpc.betterAsyncore.Reactor object at
0x7f7a2c156610>>, args=(), kwargs={}) (concurrent:193)
>> 2019-01-21 23:41:32,189 INFO (Detector thread) [ProtocolDetector.Detector]
Detected protocol stomp from ::1:43660 (protocoldetector:125)
>> 2019-01-21 23:41:32,192 INFO (Detector thread) [Broker.StompAdapter] Processing
CONNECT request (stompserver:95)
>> 2019-01-21 23:41:32,195 INFO (JsonRpc (StompReactor)) [Broker.StompAdapter]
Subscribe command received (stompserver:124)
>> 2019-01-21 23:41:32,196 INFO (JsonRpc (StompReactor)) [Broker.StompAdapter]
Subscribe command received (stompserver:124)
>> 2019-01-21 23:41:32,197 ERROR (Detector thread) [vds.dispatcher] uncaptured
python exception, closing channel <yajsonrpc.betterAsyncore.Dispatcher ('::1',
43660, 0, 0) at 0x7f7a13fdaab8> (<type
'exceptions.AttributeError'>:'NoneType' object has no attribute
'command' [/usr/lib64/python2.7/asyncore.py|readwrite|108]
[/usr/lib64/python2.7/asyncore.py|handle_read_event|449]
[/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|412]
[/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|635]
[/usr/lib64/python2.7/asyncore.py|handle_read_event|449]
[/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|415]
[/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/lib/yajsonrpc/stompserver.py|handle_frame|269])
(betterAsyncore:179)
>> 2019-01-21 23:41:32,199 DEBUG (Client ::1:46303)
[yajsonrpc.protocols.stomp.AsyncClient] Stomp connection established (stompclient:138)
>> 2019-01-21 23:41:32,200 WARNING (Detector thread) [vds.dispatcher] unhandled
close event (betterAsyncore:179)
>> 2019-01-21 23:41:32,207 DEBUG (jsonrpc/1) [jsonrpc.JsonRpcServer] Calling
'event' in bridge with [] (__init__:329)
>> 2019-01-21 23:41:32,208 DEBUG (jsonrpc/1) [jsonrpc.Notification] Sending event
{"params": {"content": true, "notify_time": 23083358880},
"jsonrpc": "2.0", "method": "vdsm.event"}
(__init__:181)
>> 2019-01-21 23:41:32,210 DEBUG (jsonrpc/1) [jsonrpc.JsonRpcServer] Return
'event' in bridge with True (__init__:356)
>> 2019-01-21 23:41:32,210 INFO (jsonrpc/1) [jsonrpc.JsonRpcServer] RPC call event
succeeded in 0.00 seconds (__init__:312)
>> 2019-01-21 23:41:34,207 DEBUG (Client ::1:46303)
[yajsonrpc.protocols.stomp.AsyncClient] Timeout occurred, trying to reconnect
(stompclient:128)
>> 2019-01-21 23:41:34,209 INFO (Detector thread) [ProtocolDetector.AcceptorImpl]
Accepted connection from ::1:43662 (protocoldetector:61)
>> 2019-01-21 23:41:34,211 DEBUG (Detector thread) [ProtocolDetector.Detector] Using
required_size=11 (protocoldetector:89)
>> 2019-01-21 23:41:44,222 DEBUG (Detector thread) [ProtocolDetector.Detector] Timed
out while waiting for data (protocoldetector:94)
>> 2019-01-21 23:41:44,223 DEBUG (Client ::1:46303) [stomp.AsyncDispatcher] managed
to connect successfully. (stomp:388)
>> 2019-01-21 23:41:46,227 DEBUG (Client ::1:46303)
[yajsonrpc.protocols.stomp.AsyncClient] Timeout occurred, trying to reconnect
(stompclient:128)
>> 2019-01-21 23:41:46,230 INFO (Detector thread) [ProtocolDetector.AcceptorImpl]
Accepted connection from ::1:43664 (protocoldetector:61)
>> 2019-01-21 23:41:46,230 DEBUG (Detector thread) [ProtocolDetector.Detector] Using
required_size=11 (protocoldetector:89)
>> 2019-01-21 23:41:46,232 DEBUG (Client ::1:46303) [stomp.AsyncDispatcher] managed
to connect successfully. (stomp:388)
>> 2019-01-21 23:41:46,233 INFO (Detector thread) [ProtocolDetector.Detector]
Detected protocol stomp from ::1:43664 (protocoldetector:125)
>> 2019-01-21 23:41:46,235 INFO (Detector thread) [Broker.StompAdapter] Processing
CONNECT request (stompserver:95)
>> 2019-01-21 23:41:46,236 DEBUG (Detector thread) [protocoldetector.StompDetector]
Stomp detected from ('::1', 43664) (stompserver:413)
>> 2019-01-21 23:41:46,240 INFO (JsonRpc (StompReactor)) [Broker.StompAdapter]
Subscribe command received (stompserver:124)
>> 2019-01-21 23:41:46,242 DEBUG (Client ::1:46303)
[yajsonrpc.protocols.stomp.AsyncClient] Stomp connection established (stompclient:138)
>> 2019-01-21 23:41:46,281 INFO (JsonRpc (StompReactor)) [Broker.StompAdapter]
Subscribe command received (stompserver:124)
>> 2019-01-21 23:41:47,200 WARNING (MainThread)
[yajsonrpc.protocols.stomp.AsyncClient] No subscription with
2a926ebd-35f9-47ce-9fb2-bec2823734f0 id (stompclient:211)
>> 2019-01-21 23:41:47,201 WARNING (MainThread)
[yajsonrpc.protocols.stomp.AsyncClient] No subscription with
b33e3bb3-1f1f-49c2-9ec2-073ec9f4fb33 id (stompclient:211)
>> 2019-01-21 23:41:47,202 DEBUG (MainThread) [vds.MultiProtocolAcceptor] Stopping
Acceptor (protocoldetector:214)
>> 2019-01-21 23:41:47,202 INFO (MainThread) [jsonrpc.JsonRCoverage.py warning:
Module /home/jenkins/workspace/vdsm_standard-check-patch/vdsm/vdsm was never imported.
(module-not-imported)
>> pcServer] Stopping JsonRPC Server (__init__:442)
>> 2019-01-21 23:41:47,203 DEBUG (JsonRpcServer) [root] FINISH thread
<Thread(JsonRpcServer, started daemon 140162164061952)> (concurrent:196)
>> 2019-01-21 23:41:47,204 DEBUG (MainThread) [Executor] Stopping executor
(executor:137)
>> 2019-01-21 23:41:47,204 DEBUG (Client ::1:46303) [root] FINISH thread
<Thread(Client ::1:46303, started daemon 140162147276544)> (concurrent:196)
>> 2019-01-21 23:41:47,206 DEBUG (jsonrpc/0) [Executor] Worker stopped
(executor:303)
>> 2019-01-21 23:41:47,207 DEBUG (jsonrpc/2) [Executor] Worker stopped
(executor:303)
>> 2019-01-21 23:41:47,208 DEBUG (jsonrpc/3) [Executor] Worker stopped
(executor:303)
>> 2019-01-21 23:41:47,209 DEBUG (jsonrpc/4) [Executor] Worker stopped
(executor:303)
>> 2019-01-21 23:41:47,209 DEBUG (jsonrpc/5) [Executor] Worker stopped
(executor:303)
>> 2019-01-21 23:41:47,210 DEBUG (JsonRpc (StompReactor)) [root] FINISH thread
<Thread(JsonRpc (StompReactor), started daemon 140162271528704)> (concurrent:196)
>> 2019-01-21 23:41:47,211 DEBUG (jsonrpc/6) [Executor] Worker stopped
(executor:303)
>> 2019-01-21 23:41:47,212 DEBUG (jsonrpc/0) [Executor] FINISH thread
<Thread(jsonrpc/0, started daemon 140162263136000)> (concurrent:196)
>> 2019-01-21 23:41:47,212 DEBUG (jsonrpc/2) [Executor] FINISH thread
<Thread(jsonrpc/2, started daemon 140162751371008)> (concurrent:196)
>> 2019-01-21 23:41:47,212 DEBUG (jsonrpc/3) [Executor] FINISH thread
<Thread(jsonrpc/3, started daemon 140162742978304)> (concurrent:196)
>> 2019-01-21 23:41:47,212 DEBUG (MainThread) [Executor] Waiting for worker
jsonrpc/5 (executor:290)
>> 2019-01-21 23:41:47,212 DEBUG (jsonrpc/1) [Executor] Worker stopped
(executor:303)
>> 2019-01-21 23:41:47,216 DEBUG (jsonrpc/1) [Executor] FINISH thread
<Thread(jsonrpc/1, started daemon 140162288314112)> (concurrent:196)
>> 2019-01-21 23:41:47,213 DEBUG (jsonrpc/4) [Executor] FINISH thread
<Thread(jsonrpc/4, started daemon 140162296706816)> (concurrent:196)
>> 2019-01-21 23:41:47,214 DEBUG (jsonrpc/7) [Executor] Worker stopped
(executor:303)
>> 2019-01-21 23:41:47,214 DEBUG (jsonrpc/5) [Executor] FINISH thread
<Thread(jsonrpc/5, started daemon 140162279921408)> (concurrent:196)
>> 2019-01-21 23:41:47,215 DEBUG (jsonrpc/6) [Executor] FINISH thread
<Thread(jsonrpc/6, started daemon 140162254743296)> (concurrent:196)
>> 2019-01-21 23:41:47,217 DEBUG (jsonrpc/7) [Executor] FINISH thread
<Thread(jsonrpc/7, started daemon 140162246350592)> (concurrent:196)
>> 2019-01-21 23:41:47,218 DEBUG (MainThread) [Executor] Waiting for worker
jsonrpc/3 (executor:290)
>> 2019-01-21 23:41:47,219 DEBUG (MainThread) [Executor] Waiting for worker
jsonrpc/2 (executor:290)
>> 2019-01-21 23:41:47,220 DEBUG (MainThread) [Executor] Waiting for worker
jsonrpc/6 (executor:290)
>> 2019-01-21 23:41:47,220 DEBUG (MainThread) [Executor] Waiting for worker
jsonrpc/1 (executor:290)
>> 2019-01-21 23:41:47,220 DEBUG (MainThread) [Executor] Waiting for worker
jsonrpc/4 (executor:290)
>> 2019-01-21 23:41:47,221 DEBUG (MainThread) [Executor] Waiting for worker
jsonrpc/7 (executor:290)
>> 2019-01-21 23:41:47,221 DEBUG (MainThread) [Executor] Waiting for worker
jsonrpc/0 (executor:290)
>> 2019-01-21 23:41:47,221 DEBUG (MainThread) [Scheduler] Stopping scheduler
test.Scheduler (schedule:110)
>> 2019-01-21 23:41:47,222 DEBUG (test.Scheduler) [Scheduler] stopped
(schedule:143)
>> 2019-01-21 23:41:47,222 DEBUG (test.Scheduler) [Scheduler] FINISH thread
<Thread(test.Scheduler, started daemon 140162734585600)> (concurrent:196)
>>
>>
>>
9:39 a.m.
On Mon, Feb 4, 2019 at 10:02 PM Nir Soffer <nsoffer(a)redhat.com> wrote:
Another failure today:
FAIL: test_event(False) (stomp_test.StompTests)
----------------------------------------------------------------------
Traceback (most recent call last):
File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/testlib.py", line
142, in wrapper
return f(self, *args)
File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/stomp_test.py",
line 123, in test_event
self.fail("Event queue timed out.")
AssertionError: Event queue timed out.
https://jenkins.ovirt.org/job/vdsm_standard-check-patch/2501//artifact/ch...
Another random failure of similar test:
======================================================================
FAIL: test_reject_very_slow_client_concurrency(False)
(protocoldetector_test.AcceptorTests)
----------------------------------------------------------------------
Traceback (most recent call last):
File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/testlib.py",
line 142, in wrapper
return f(self, *args)
File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/protocoldetector_test.py",
line 178, in test_reject_very_slow_client_concurrency
self.check_concurrently(self.check_very_slow_client, use_ssl)
File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/protocoldetector_test.py",
line 267, in check_concurrently
self.assertTrue(all(done))
AssertionError: False is not true
-------------------- >> begin captured logging << --------------------
2019-02-05 10:10:06,902 DEBUG (MainThread) [vds.MultiProtocolAcceptor]
Creating socket (host='127.0.0.1', port=0, family=2, socketype=1,
proto=6) (protocoldetector:225)
2019-02-05 10:10:06,904 INFO (MainThread) [vds.MultiProtocolAcceptor]
Listening at 127.0.0.1:37755 (protocoldetector:183)
2019-02-05 10:10:06,904 DEBUG (MainThread) [vds.MultiProtocolAcceptor]
Adding detector <protocoldetector_test.Echo object at 0x7f91d53d65d0>
(protocoldetector:210)
2019-02-05 10:10:06,905 DEBUG (MainThread) [vds.MultiProtocolAcceptor]
Adding detector <protocoldetector_test.Uppercase object at
0x7f91d53d62d0> (protocoldetector:210)
2019-02-05 10:10:06,910 INFO (Thread-93)
[ProtocolDetector.AcceptorImpl] Accepted connection from
127.0.0.1:38802 (protocoldetector:61)
2019-02-05 10:10:06,911 DEBUG (Thread-93) [ProtocolDetector.Detector]
Using required_size=9 (protocoldetector:89)
2019-02-05 10:10:06,912 INFO (Thread-93)
[ProtocolDetector.AcceptorImpl] Accepted connection from
127.0.0.1:38800 (protocoldetector:61)
2019-02-05 10:10:06,913 DEBUG (Thread-93) [ProtocolDetector.Detector]
Using required_size=9 (protocoldetector:89)
2019-02-05 10:10:06,915 INFO (Thread-93)
[ProtocolDetector.AcceptorImpl] Accepted connection from
127.0.0.1:38804 (protocoldetector:61)
2019-02-05 10:10:06,919 DEBUG (Thread-93) [ProtocolDetector.Detector]
Using required_size=9 (protocoldetector:89)
2019-02-05 10:10:06,920 INFO (Thread-93)
[ProtocolDetector.AcceptorImpl] Accepted connection from
127.0.0.1:38806 (protocoldetector:61)
2019-02-05 10:10:06,921 DEBUG (Thread-93) [ProtocolDetector.Detector]
Using required_size=9 (protocoldetector:89)
2019-02-05 10:10:06,922 INFO (Thread-93)
[ProtocolDetector.AcceptorImpl] Accepted connection from
127.0.0.1:38808 (protocoldetector:61)
2019-02-05 10:10:06,923 DEBUG (Thread-93) [ProtocolDetector.Detector]
Using required_size=9 (protocoldetector:89)
2019-02-05 10:10:07,916 DEBUG (Thread-93) [ProtocolDetector.Detector]
Timed out while waiting for data (protocoldetector:94)
--------------------- >> end captured logging << ---------------------
https://jenkins.ovirt.org/job/vdsm_standard-check-patch/2598//artifact/ch...
On Wed, Jan 23, 2019 at 3:41 PM Nir Soffer <nsoffer(a)redhat.com> wrote:
> On Wed, Jan 23, 2019 at 11:15 AM Marcin Sobczyk <msobczyk(a)redhat.com>
> wrote:
>
>> Hi,
>>
>> I don't have time to look into this right now, but I will definitely do
>> so after coming back from FOSDEM.
>>
> Great.
>
> We will mark this tests as broken_on_ci on Jenkins for now.
>
> I think the issue for this and other failures is the race we have when
> handling
> STOMP CONNECT and SUBSCRIBE, see these patches trying to fix this on
> the client side:
> https://gerrit.ovirt.org/c/95899
>
>
>> Regards, Marcin
>> On 1/22/19 12:57 AM, Nir Soffer wrote:
>>
>> On Tue, Jan 22, 2019 at 1:56 AM Nir Soffer <nsoffer(a)redhat.com> wrote:
>>
>>> On Sat, Jan 19, 2019 at 11:15 PM Nir Soffer <nsoffer(a)redhat.com>
wrote:
>>>
>>>> Recently this test cause too many random failures. I guess this is
>>>> the known issue with handling SUBSCRIBE in protocol detector.
>>>> I posted https://gerrit.ovirt.org/c/97099/
>>>> To mark it as broken until we have time to dig deeper
>>>>
>>>> ======================================================================
>>>>
>>>> FAIL: test_detect_slow_client_concurrency(True)
(protocoldetector_test.AcceptorTests)
>>>> ----------------------------------------------------------------------
>>>> Traceback (most recent call last):
>>>> File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/testlib.py", line
142, in wrapper
>>>> return f(self, *args)
>>>> File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/protocoldetector_test.py",
line 167, in test_detect_slow_client_concurrency
>>>> self.check_concurrently(self.check_slow_client, use_ssl)
>>>> File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/protocoldetector_test.py",
line 266, in check_concurrently
>>>> self.assertTrue(all(done))
>>>> AssertionError: False is not true
>>>> -------------------- >> begin captured logging <<
--------------------
>>>> 2019-01-19 20:47:16,021 DEBUG (MainThread) [vds.MultiProtocolAcceptor]
Creating socket (host='127.0.0.1', port=0, family=2, socketype=1, proto=6)
(protocoldetector:225)
>>>> 2019-01-19 20:47:16,022 INFO (MainThread) [vds.MultiProtocolAcceptor]
Listening at 127.0.0.1:46009 (protocoldetector:183)
>>>> 2019-01-19 20:47:16,023 DEBUG (MainThread) [vds.MultiProtocolAcceptor]
Adding detector <protocoldetector_test.Echo object at 0x7f1bb77f8dd0>
(protocoldetector:210)
>>>> 2019-01-19 20:47:16,024 DEBUG (MainThread) [vds.MultiProtocolAcceptor]
Adding detector <protocoldetector_test.Uppercase object at 0x7f1bb77f8c90>
(protocoldetector:210)
>>>> 2019-01-19 20:47:16,031 INFO (Thread-61) [ProtocolDetector.AcceptorImpl]
Accepted connection from 127.0.0.1:51950 (protocoldetector:61)
>>>> 2019-01-19 20:47:16,047 INFO (Thread-61) [ProtocolDetector.AcceptorImpl]
Accepted connection from 127.0.0.1:51952 (protocoldetector:61)
>>>> 2019-01-19 20:47:16,048 INFO (Thread-61) [ProtocolDetector.AcceptorImpl]
Accepted connection from 127.0.0.1:51954 (protocoldetector:61)
>>>> 2019-01-19 20:47:16,065 INFO (Thread-61) [ProtocolDetector.AcceptorImpl]
Accepted connection from 127.0.0.1:51956 (protocoldetector:61)
>>>> 2019-01-19 20:47:16,068 INFO (Thread-61) [ProtocolDetector.AcceptorImpl]
Accepted connection from 127.0.0.1:51958 (protocoldetector:61)
>>>> 2019-01-19 20:47:16,069 DEBUG (Thread-61) [ProtocolDetector.Detector]
Using required_size=9 (protocoldetector:89)
>>>> 2019-01-19 20:47:16,097 DEBUG (Thread-61) [ProtocolDetector.Detector]
Using required_size=9 (protocoldetector:89)
>>>> 2019-01-19 20:47:16,099 DEBUG (Thread-61) [ProtocolDetector.Detector]
Using required_size=9 (protocoldetector:89)
>>>> 2019-01-19 20:47:16,107 DEBUG (Thread-61) [ProtocolDetector.Detector]
Using required_size=9 (protocoldetector:89)
>>>> 2019-01-19 20:47:16,109 DEBUG (Thread-61) [ProtocolDetector.Detector]
Using required_size=9 (protocoldetector:89)
>>>> 2019-01-19 20:47:16,574 INFO (Thread-61) [ProtocolDetector.Detector]
Detected protocol echo from 127.0.0.1:51950 (protocoldetector:125)
>>>> 2019-01-19 20:47:17,570 DEBUG (Thread-61) [ProtocolDetector.Detector]
Timed out while waiting for data (protocoldetector:94)
>>>> 2019-01-19 20:47:17,571 DEBUG (Thread-61) [ProtocolDetector.Detector]
Timed out while waiting for data (protocoldetector:94)
>>>> 2019-01-19 20:47:17,576 DEBUG (Thread-61) [ProtocolDetector.Detector]
Timed out while waiting for data (protocoldetector:94)
>>>> 2019-01-19 20:47:17,578 DEBUG (Thread-61) [ProtocolDetector.Detector]
Timed out while waiting for data (protocoldetector:94)
>>>> --------------------- >> end captured logging <<
---------------------
>>>>
>>>>
>>> Another flaky test - we marked the other test in this class as broken
>>> on ci
>>> recently. This test fail randomly from time to time.
>>>
>>
>> Failed this build:
>>
>>
https://jenkins.ovirt.org/job/vdsm_standard-check-patch/2158//artifact/ch...
>>
>>
>>
>>>
>>> ======================================================================
>>> ERROR: test_event(False) (stomp_test.StompTests)
>>> ----------------------------------------------------------------------
>>> Traceback (most recent call last):
>>> File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/testlib.py", line
142, in wrapper
>>> return f(self, *args)
>>> File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/stomp_test.py",
line 118, in test_event
>>> client.callMethod("event", [], str(uuid4()))
>>> File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/lib/yajsonrpc/jsonrpcclient.py",
line 78, in callMethod
>>> raise exception.JsonRpcNoResponseError(method=methodName)
>>> JsonRpcNoResponseError: No response for JSON-RPC request: {'method':
'event'}
>>> -------------------- >> begin captured logging <<
--------------------
>>> 2019-01-21 23:41:32,132 DEBUG (MainThread) [vds.MultiProtocolAcceptor]
Creating socket (host='::1', port=0, family=10, socketype=1, proto=6)
(protocoldetector:225)
>>> 2019-01-21 23:41:32,133 INFO (MainThread) [vds.MultiProtocolAcceptor]
Listening at ::1:46303 (protocoldetector:183)
>>> 2019-01-21 23:41:32,134 DEBUG (MainThread) [Scheduler] Starting scheduler
test.Scheduler (schedule:98)
>>> 2019-01-21 23:41:32,135 DEBUG (test.Scheduler) [Scheduler] START thread
<Thread(test.Scheduler, started daemon 140162734585600)> (func=<bound method
Scheduler._run of <vdsm.schedule.Scheduler object at 0x7f7a2c156e10>>, args=(),
kwargs={}) (concurrent:193)
>>> 2019-01-21 23:41:32,138 DEBUG (test.Scheduler) [Scheduler] started
(schedule:140)
>>> 2019-01-21 23:41:32,139 DEBUG (JsonRpc (StompReactor)) [root] START thread
<Thread(JsonRpc (StompReactor), started daemon 140162271528704)> (func=<bound
method StompReactor.process_requests of <yajsonrpc.stompserver.StompReactor object at
0x7f7a2c177950>>, args=(), kwargs={}) (concurrent:193)
>>> 2019-01-21 23:41:32,139 DEBUG (MainThread) [Executor] Starting executor
(executor:128)
>>> 2019-01-21 23:41:32,141 DEBUG (MainThread) [Executor] Starting worker
jsonrpc/0 (executor:286)
>>> 2019-01-21 23:41:32,142 DEBUG (MainThread) [Executor] Starting worker
jsonrpc/1 (executor:286)
>>> 2019-01-21 23:41:32,143 DEBUG (jsonrpc/1) [Executor] START thread
<Thread(jsonrpc/1, started daemon 140162288314112)> (func=<bound method
_Worker._run of <Worker name=jsonrpc/1 waiting task#=0 at 0x7f7a2c177510>>,
args=(), kwargs={}) (concurrent:193)
>>> 2019-01-21 23:41:32,144 DEBUG (MainThread) [Executor] Starting worker
jsonrpc/2 (executor:286)
>>> 2019-01-21 23:41:32,144 DEBUG (jsonrpc/0) [Executor] START thread
<Thread(jsonrpc/0, started daemon 140162263136000)> (func=<bound method
_Worker._run of <Worker name=jsonrpc/0 waiting task#=0 at 0x7f7a2c177d50>>,
args=(), kwargs={}) (concurrent:193)
>>> 2019-01-21 23:41:32,145 DEBUG (jsonrpc/1) [Executor] Worker started
(executor:298)
>>> 2019-01-21 23:41:32,147 DEBUG (MainThread) [Executor] Starting worker
jsonrpc/3 (executor:286)
>>> 2019-01-21 23:41:32,148 DEBUG (jsonrpc/2) [Executor] START thread
<Thread(jsonrpc/2, started daemon 140162751371008)> (func=<bound method
_Worker._run of <Worker name=jsonrpc/2 waiting task#=0 at 0x7f7a2c177ad0>>,
args=(), kwargs={}) (concurrent:193)
>>> 2019-01-21 23:41:32,149 DEBUG (jsonrpc/0) [Executor] Worker started
(executor:298)
>>> 2019-01-21 23:41:32,153 DEBUG (jsonrpc/2) [Executor] Worker started
(executor:298)
>>> 2019-01-21 23:41:32,154 DEBUG (MainThread) [Executor] Starting worker
jsonrpc/4 (executor:286)
>>> 2019-01-21 23:41:32,155 DEBUG (jsonrpc/3) [Executor] START thread
<Thread(jsonrpc/3, started daemon 140162742978304)> (func=<bound method
_Worker._run of <Worker name=jsonrpc/3 waiting task#=0 at 0x7f7a2c112e10>>,
args=(), kwargs={}) (concurrent:193)
>>> 2019-01-21 23:41:32,158 DEBUG (jsonrpc/3) [Executor] Worker started
(executor:298)
>>> 2019-01-21 23:41:32,159 DEBUG (MainThread) [Executor] Starting worker
jsonrpc/5 (executor:286)
>>> 2019-01-21 23:41:32,160 DEBUG (jsonrpc/4) [Executor] START thread
<Thread(jsonrpc/4, started daemon 140162296706816)> (func=<bound method
_Worker._run of <Worker name=jsonrpc/4 waiting task#=0 at 0x7f7a2c112d50>>,
args=(), kwargs={}) (concurrent:193)
>>> 2019-01-21 23:41:32,161 DEBUG (jsonrpc/4) [Executor] Worker started
(executor:298)
>>> 2019-01-21 23:41:32,163 DEBUG (MainThread) [Executor] Starting worker
jsonrpc/6 (executor:286)
>>> 2019-01-21 23:41:32,164 DEBUG (jsonrpc/5) [Executor] START thread
<Thread(jsonrpc/5, started daemon 140162279921408)> (func=<bound method
_Worker._run of <Worker name=jsonrpc/5 waiting task#=0 at 0x7f7a2c112810>>,
args=(), kwargs={}) (concurrent:193)
>>> 2019-01-21 23:41:32,166 DEBUG (jsonrpc/6) [Executor] START thread
<Thread(jsonrpc/6, started daemon 140162254743296)> (func=<bound method
_Worker._run of <Worker name=jsonrpc/6 waiting task#=0 at 0x7f7a2c1924d0>>,
args=(), kwargs={}) (concurrent:193)
>>> 2019-01-21 23:41:32,166 DEBUG (MainThread) [Executor] Starting worker
jsonrpc/7 (executor:286)
>>> 2019-01-21 23:41:32,167 DEBUG (jsonrpc/5) [Executor] Worker started
(executor:298)
>>> 2019-01-21 23:41:32,169 DEBUG (jsonrpc/6) [Executor] Worker started
(executor:298)
>>> 2019-01-21 23:41:32,172 DEBUG (jsonrpc/7) [Executor] START thread
<Thread(jsonrpc/7, started daemon 140162246350592)> (func=<bound method
_Worker._run of <Worker name=jsonrpc/7 waiting task#=0 at 0x7f7a2c1921d0>>,
args=(), kwargs={}) (concurrent:193)
>>> 2019-01-21 23:41:32,173 DEBUG (MainThread) [vds.MultiProtocolAcceptor] Adding
detector <yajsonrpc.stompserver.StompDetector instance at 0x7f7a13fa7050>
(protocoldetector:210)
>>> 2019-01-21 23:41:32,173 DEBUG (JsonRpcServer) [root] START thread
<Thread(JsonRpcServer, started daemon 140162164061952)> (func=<bound method
JsonRpcServer.serve_requests of <yajsonrpc.JsonRpcServer object at
0x7f7a2c177bd0>>, args=(), kwargs={}) (concurrent:193)
>>> 2019-01-21 23:41:32,174 DEBUG (jsonrpc/7) [Executor] Worker started
(executor:298)
>>> 2019-01-21 23:41:32,181 INFO (Detector thread)
[ProtocolDetector.AcceptorImpl] Accepted connection from ::1:43660 (protocoldetector:61)
>>> 2019-01-21 23:41:32,185 DEBUG (MainThread) [jsonrpc.AsyncoreClient] Sending
response (stompclient:294)
>>> 2019-01-21 23:41:32,185 DEBUG (Detector thread) [ProtocolDetector.Detector]
Using required_size=11 (protocoldetector:89)
>>> 2019-01-21 23:41:32,187 DEBUG (Client ::1:46303) [root] START thread
<Thread(Client ::1:46303, started daemon 140162147276544)> (func=<bound method
Reactor.process_requests of <yajsonrpc.betterAsyncore.Reactor object at
0x7f7a2c156610>>, args=(), kwargs={}) (concurrent:193)
>>> 2019-01-21 23:41:32,189 INFO (Detector thread) [ProtocolDetector.Detector]
Detected protocol stomp from ::1:43660 (protocoldetector:125)
>>> 2019-01-21 23:41:32,192 INFO (Detector thread) [Broker.StompAdapter]
Processing CONNECT request (stompserver:95)
>>> 2019-01-21 23:41:32,195 INFO (JsonRpc (StompReactor)) [Broker.StompAdapter]
Subscribe command received (stompserver:124)
>>> 2019-01-21 23:41:32,196 INFO (JsonRpc (StompReactor)) [Broker.StompAdapter]
Subscribe command received (stompserver:124)
>>> 2019-01-21 23:41:32,197 ERROR (Detector thread) [vds.dispatcher] uncaptured
python exception, closing channel <yajsonrpc.betterAsyncore.Dispatcher ('::1',
43660, 0, 0) at 0x7f7a13fdaab8> (<type
'exceptions.AttributeError'>:'NoneType' object has no attribute
'command' [/usr/lib64/python2.7/asyncore.py|readwrite|108]
[/usr/lib64/python2.7/asyncore.py|handle_read_event|449]
[/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|412]
[/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|635]
[/usr/lib64/python2.7/asyncore.py|handle_read_event|449]
[/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|415]
[/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/lib/yajsonrpc/stompserver.py|handle_frame|269])
(betterAsyncore:179)
>>> 2019-01-21 23:41:32,199 DEBUG (Client ::1:46303)
[yajsonrpc.protocols.stomp.AsyncClient] Stomp connection established (stompclient:138)
>>> 2019-01-21 23:41:32,200 WARNING (Detector thread) [vds.dispatcher] unhandled
close event (betterAsyncore:179)
>>> 2019-01-21 23:41:32,207 DEBUG (jsonrpc/1) [jsonrpc.JsonRpcServer] Calling
'event' in bridge with [] (__init__:329)
>>> 2019-01-21 23:41:32,208 DEBUG (jsonrpc/1) [jsonrpc.Notification] Sending
event {"params": {"content": true, "notify_time":
23083358880}, "jsonrpc": "2.0", "method":
"vdsm.event"} (__init__:181)
>>> 2019-01-21 23:41:32,210 DEBUG (jsonrpc/1) [jsonrpc.JsonRpcServer] Return
'event' in bridge with True (__init__:356)
>>> 2019-01-21 23:41:32,210 INFO (jsonrpc/1) [jsonrpc.JsonRpcServer] RPC call
event succeeded in 0.00 seconds (__init__:312)
>>> 2019-01-21 23:41:34,207 DEBUG (Client ::1:46303)
[yajsonrpc.protocols.stomp.AsyncClient] Timeout occurred, trying to reconnect
(stompclient:128)
>>> 2019-01-21 23:41:34,209 INFO (Detector thread)
[ProtocolDetector.AcceptorImpl] Accepted connection from ::1:43662 (protocoldetector:61)
>>> 2019-01-21 23:41:34,211 DEBUG (Detector thread) [ProtocolDetector.Detector]
Using required_size=11 (protocoldetector:89)
>>> 2019-01-21 23:41:44,222 DEBUG (Detector thread) [ProtocolDetector.Detector]
Timed out while waiting for data (protocoldetector:94)
>>> 2019-01-21 23:41:44,223 DEBUG (Client ::1:46303) [stomp.AsyncDispatcher]
managed to connect successfully. (stomp:388)
>>> 2019-01-21 23:41:46,227 DEBUG (Client ::1:46303)
[yajsonrpc.protocols.stomp.AsyncClient] Timeout occurred, trying to reconnect
(stompclient:128)
>>> 2019-01-21 23:41:46,230 INFO (Detector thread)
[ProtocolDetector.AcceptorImpl] Accepted connection from ::1:43664 (protocoldetector:61)
>>> 2019-01-21 23:41:46,230 DEBUG (Detector thread) [ProtocolDetector.Detector]
Using required_size=11 (protocoldetector:89)
>>> 2019-01-21 23:41:46,232 DEBUG (Client ::1:46303) [stomp.AsyncDispatcher]
managed to connect successfully. (stomp:388)
>>> 2019-01-21 23:41:46,233 INFO (Detector thread) [ProtocolDetector.Detector]
Detected protocol stomp from ::1:43664 (protocoldetector:125)
>>> 2019-01-21 23:41:46,235 INFO (Detector thread) [Broker.StompAdapter]
Processing CONNECT request (stompserver:95)
>>> 2019-01-21 23:41:46,236 DEBUG (Detector thread)
[protocoldetector.StompDetector] Stomp detected from ('::1', 43664)
(stompserver:413)
>>> 2019-01-21 23:41:46,240 INFO (JsonRpc (StompReactor)) [Broker.StompAdapter]
Subscribe command received (stompserver:124)
>>> 2019-01-21 23:41:46,242 DEBUG (Client ::1:46303)
[yajsonrpc.protocols.stomp.AsyncClient] Stomp connection established (stompclient:138)
>>> 2019-01-21 23:41:46,281 INFO (JsonRpc (StompReactor)) [Broker.StompAdapter]
Subscribe command received (stompserver:124)
>>> 2019-01-21 23:41:47,200 WARNING (MainThread)
[yajsonrpc.protocols.stomp.AsyncClient] No subscription with
2a926ebd-35f9-47ce-9fb2-bec2823734f0 id (stompclient:211)
>>> 2019-01-21 23:41:47,201 WARNING (MainThread)
[yajsonrpc.protocols.stomp.AsyncClient] No subscription with
b33e3bb3-1f1f-49c2-9ec2-073ec9f4fb33 id (stompclient:211)
>>> 2019-01-21 23:41:47,202 DEBUG (MainThread) [vds.MultiProtocolAcceptor]
Stopping Acceptor (protocoldetector:214)
>>> 2019-01-21 23:41:47,202 INFO (MainThread) [jsonrpc.JsonRCoverage.py warning:
Module /home/jenkins/workspace/vdsm_standard-check-patch/vdsm/vdsm was never imported.
(module-not-imported)
>>> pcServer] Stopping JsonRPC Server (__init__:442)
>>> 2019-01-21 23:41:47,203 DEBUG (JsonRpcServer) [root] FINISH thread
<Thread(JsonRpcServer, started daemon 140162164061952)> (concurrent:196)
>>> 2019-01-21 23:41:47,204 DEBUG (MainThread) [Executor] Stopping executor
(executor:137)
>>> 2019-01-21 23:41:47,204 DEBUG (Client ::1:46303) [root] FINISH thread
<Thread(Client ::1:46303, started daemon 140162147276544)> (concurrent:196)
>>> 2019-01-21 23:41:47,206 DEBUG (jsonrpc/0) [Executor] Worker stopped
(executor:303)
>>> 2019-01-21 23:41:47,207 DEBUG (jsonrpc/2) [Executor] Worker stopped
(executor:303)
>>> 2019-01-21 23:41:47,208 DEBUG (jsonrpc/3) [Executor] Worker stopped
(executor:303)
>>> 2019-01-21 23:41:47,209 DEBUG (jsonrpc/4) [Executor] Worker stopped
(executor:303)
>>> 2019-01-21 23:41:47,209 DEBUG (jsonrpc/5) [Executor] Worker stopped
(executor:303)
>>> 2019-01-21 23:41:47,210 DEBUG (JsonRpc (StompReactor)) [root] FINISH thread
<Thread(JsonRpc (StompReactor), started daemon 140162271528704)> (concurrent:196)
>>> 2019-01-21 23:41:47,211 DEBUG (jsonrpc/6) [Executor] Worker stopped
(executor:303)
>>> 2019-01-21 23:41:47,212 DEBUG (jsonrpc/0) [Executor] FINISH thread
<Thread(jsonrpc/0, started daemon 140162263136000)> (concurrent:196)
>>> 2019-01-21 23:41:47,212 DEBUG (jsonrpc/2) [Executor] FINISH thread
<Thread(jsonrpc/2, started daemon 140162751371008)> (concurrent:196)
>>> 2019-01-21 23:41:47,212 DEBUG (jsonrpc/3) [Executor] FINISH thread
<Thread(jsonrpc/3, started daemon 140162742978304)> (concurrent:196)
>>> 2019-01-21 23:41:47,212 DEBUG (MainThread) [Executor] Waiting for worker
jsonrpc/5 (executor:290)
>>> 2019-01-21 23:41:47,212 DEBUG (jsonrpc/1) [Executor] Worker stopped
(executor:303)
>>> 2019-01-21 23:41:47,216 DEBUG (jsonrpc/1) [Executor] FINISH thread
<Thread(jsonrpc/1, started daemon 140162288314112)> (concurrent:196)
>>> 2019-01-21 23:41:47,213 DEBUG (jsonrpc/4) [Executor] FINISH thread
<Thread(jsonrpc/4, started daemon 140162296706816)> (concurrent:196)
>>> 2019-01-21 23:41:47,214 DEBUG (jsonrpc/7) [Executor] Worker stopped
(executor:303)
>>> 2019-01-21 23:41:47,214 DEBUG (jsonrpc/5) [Executor] FINISH thread
<Thread(jsonrpc/5, started daemon 140162279921408)> (concurrent:196)
>>> 2019-01-21 23:41:47,215 DEBUG (jsonrpc/6) [Executor] FINISH thread
<Thread(jsonrpc/6, started daemon 140162254743296)> (concurrent:196)
>>> 2019-01-21 23:41:47,217 DEBUG (jsonrpc/7) [Executor] FINISH thread
<Thread(jsonrpc/7, started daemon 140162246350592)> (concurrent:196)
>>> 2019-01-21 23:41:47,218 DEBUG (MainThread) [Executor] Waiting for worker
jsonrpc/3 (executor:290)
>>> 2019-01-21 23:41:47,219 DEBUG (MainThread) [Executor] Waiting for worker
jsonrpc/2 (executor:290)
>>> 2019-01-21 23:41:47,220 DEBUG (MainThread) [Executor] Waiting for worker
jsonrpc/6 (executor:290)
>>> 2019-01-21 23:41:47,220 DEBUG (MainThread) [Executor] Waiting for worker
jsonrpc/1 (executor:290)
>>> 2019-01-21 23:41:47,220 DEBUG (MainThread) [Executor] Waiting for worker
jsonrpc/4 (executor:290)
>>> 2019-01-21 23:41:47,221 DEBUG (MainThread) [Executor] Waiting for worker
jsonrpc/7 (executor:290)
>>> 2019-01-21 23:41:47,221 DEBUG (MainThread) [Executor] Waiting for worker
jsonrpc/0 (executor:290)
>>> 2019-01-21 23:41:47,221 DEBUG (MainThread) [Scheduler] Stopping scheduler
test.Scheduler (schedule:110)
>>> 2019-01-21 23:41:47,222 DEBUG (test.Scheduler) [Scheduler] stopped
(schedule:143)
>>> 2019-01-21 23:41:47,222 DEBUG (test.Scheduler) [Scheduler] FINISH thread
<Thread(test.Scheduler, started daemon 140162734585600)> (concurrent:196)
>>>
>>>
>>>
12:23 p.m.
On Tue, Feb 5, 2019 at 4:39 PM Nir Soffer <nsoffer(a)redhat.com> wrote:
On Mon, Feb 4, 2019 at 10:02 PM Nir Soffer <nsoffer(a)redhat.com>
wrote:
> Another failure today:
>
> FAIL: test_event(False) (stomp_test.StompTests)
> ----------------------------------------------------------------------
> Traceback (most recent call last):
> File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/testlib.py", line
142, in wrapper
> return f(self, *args)
> File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/stomp_test.py",
line 123, in test_event
> self.fail("Event queue timed out.")
> AssertionError: Event queue timed out.
>
>
>
https://jenkins.ovirt.org/job/vdsm_standard-check-patch/2501//artifact/ch...
>
>
Another random failure of similar test:
======================================================================
FAIL: test_reject_very_slow_client_concurrency(False)
(protocoldetector_test.AcceptorTests)
----------------------------------------------------------------------
Traceback (most recent call last):
File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/testlib.py", line
142, in wrapper
return f(self, *args)
File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/protocoldetector_test.py",
line 178, in test_reject_very_slow_client_concurrency
self.check_concurrently(self.check_very_slow_client, use_ssl)
File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/protocoldetector_test.py",
line 267, in check_concurrently
self.assertTrue(all(done))
AssertionError: False is not true
-------------------- >> begin captured logging << --------------------
2019-02-05 10:10:06,902 DEBUG (MainThread) [vds.MultiProtocolAcceptor] Creating socket
(host='127.0.0.1', port=0, family=2, socketype=1, proto=6) (protocoldetector:225)
2019-02-05 10:10:06,904 INFO (MainThread) [vds.MultiProtocolAcceptor] Listening at
127.0.0.1:37755 (protocoldetector:183)
2019-02-05 10:10:06,904 DEBUG (MainThread) [vds.MultiProtocolAcceptor] Adding detector
<protocoldetector_test.Echo object at 0x7f91d53d65d0> (protocoldetector:210)
2019-02-05 10:10:06,905 DEBUG (MainThread) [vds.MultiProtocolAcceptor] Adding detector
<protocoldetector_test.Uppercase object at 0x7f91d53d62d0> (protocoldetector:210)
2019-02-05 10:10:06,910 INFO (Thread-93) [ProtocolDetector.AcceptorImpl] Accepted
connection from 127.0.0.1:38802 (protocoldetector:61)
2019-02-05 10:10:06,911 DEBUG (Thread-93) [ProtocolDetector.Detector] Using
required_size=9 (protocoldetector:89)
2019-02-05 10:10:06,912 INFO (Thread-93) [ProtocolDetector.AcceptorImpl] Accepted
connection from 127.0.0.1:38800 (protocoldetector:61)
2019-02-05 10:10:06,913 DEBUG (Thread-93) [ProtocolDetector.Detector] Using
required_size=9 (protocoldetector:89)
2019-02-05 10:10:06,915 INFO (Thread-93) [ProtocolDetector.AcceptorImpl] Accepted
connection from 127.0.0.1:38804 (protocoldetector:61)
2019-02-05 10:10:06,919 DEBUG (Thread-93) [ProtocolDetector.Detector] Using
required_size=9 (protocoldetector:89)
2019-02-05 10:10:06,920 INFO (Thread-93) [ProtocolDetector.AcceptorImpl] Accepted
connection from 127.0.0.1:38806 (protocoldetector:61)
2019-02-05 10:10:06,921 DEBUG (Thread-93) [ProtocolDetector.Detector] Using
required_size=9 (protocoldetector:89)
2019-02-05 10:10:06,922 INFO (Thread-93) [ProtocolDetector.AcceptorImpl] Accepted
connection from 127.0.0.1:38808 (protocoldetector:61)
2019-02-05 10:10:06,923 DEBUG (Thread-93) [ProtocolDetector.Detector] Using
required_size=9 (protocoldetector:89)
2019-02-05 10:10:07,916 DEBUG (Thread-93) [ProtocolDetector.Detector] Timed out while
waiting for data (protocoldetector:94)
--------------------- >> end captured logging << ---------------------
https://jenkins.ovirt.org/job/vdsm_standard-check-patch/2598//artifact/ch...
Another failure today:
======================================================================
FAIL: test_event(False) (stomp_test.StompTests)
----------------------------------------------------------------------
Traceback (most recent call last):
File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/testlib.py",
line 142, in wrapper
return f(self, *args)
File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/stomp_test.py",
line 123, in test_event
self.fail("Event queue timed out.")
AssertionError: Event queue timed out.
-------------------- >> begin captured logging << --------------------
2019-02-17 17:06:43,303 DEBUG (MainThread) [vds.MultiProtocolAcceptor]
Creating socket (host='::1', port=0, family=10, socketype=1, proto=6)
(protocoldetector:225)
2019-02-17 17:06:43,304 INFO (MainThread) [vds.MultiProtocolAcceptor]
Listening at ::1:45177 (protocoldetector:183)
2019-02-17 17:06:43,305 DEBUG (MainThread) [Scheduler] Starting
scheduler test.Scheduler (schedule:98)
2019-02-17 17:06:43,306 DEBUG (test.Scheduler) [Scheduler] START
thread <Thread(test.Scheduler, started daemon 139805153421056)>
(func=<bound method Scheduler._run of <vdsm.schedule.Scheduler object
at 0x7f26ee2e23d0>>, args=(), kwargs={}) (concurrent:193)
2019-02-17 17:06:43,310 DEBUG (test.Scheduler) [Scheduler] started
(schedule:140)
2019-02-17 17:06:43,311 DEBUG (MainThread) [Executor] Starting
executor (executor:128)
2019-02-17 17:06:43,313 DEBUG (MainThread) [Executor] Starting worker
jsonrpc/0 (executor:286)
2019-02-17 17:06:43,311 DEBUG (JsonRpc (StompReactor)) [root] START
thread <Thread(JsonRpc (StompReactor), started daemon
139804935186176)> (func=<bound method StompReactor.process_requests of
<yajsonrpc.stompserver.StompReactor object at 0x7f26ee2e2410>>,
args=(), kwargs={}) (concurrent:193)
2019-02-17 17:06:43,315 DEBUG (MainThread) [Executor] Starting worker
jsonrpc/1 (executor:286)
2019-02-17 17:06:43,318 DEBUG (MainThread) [Executor] Starting worker
jsonrpc/2 (executor:286)
2019-02-17 17:06:43,315 DEBUG (jsonrpc/0) [Executor] START thread
<Thread(jsonrpc/0, started daemon 139804943578880)> (func=<bound
method _Worker._run of <Worker name=jsonrpc/0 waiting task#=0 at
0x7f26ee2ae6d0>>, args=(), kwargs={}) (concurrent:193)
2019-02-17 17:06:43,320 DEBUG (jsonrpc/1) [Executor] START thread
<Thread(jsonrpc/1, started daemon 139805161813760)> (func=<bound
method _Worker._run of <Worker name=jsonrpc/1 waiting task#=0 at
0x7f26ee2ae0d0>>, args=(), kwargs={}) (concurrent:193)
2019-02-17 17:06:43,322 DEBUG (MainThread) [Executor] Starting worker
jsonrpc/3 (executor:286)
2019-02-17 17:06:43,321 DEBUG (jsonrpc/0) [Executor] Worker started
(executor:298)
2019-02-17 17:06:43,324 DEBUG (jsonrpc/1) [Executor] Worker started
(executor:298)
2019-02-17 17:06:43,323 DEBUG (jsonrpc/2) [Executor] START thread
<Thread(jsonrpc/2, started daemon 139805898135296)> (func=<bound
method _Worker._run of <Worker name=jsonrpc/2 waiting task#=0 at
0x7f26ee2ae290>>, args=(), kwargs={}) (concurrent:193)
2019-02-17 17:06:43,327 DEBUG (MainThread) [Executor] Starting worker
jsonrpc/4 (executor:286)
2019-02-17 17:06:43,329 DEBUG (jsonrpc/2) [Executor] Worker started
(executor:298)
2019-02-17 17:06:43,330 DEBUG (jsonrpc/3) [Executor] START thread
<Thread(jsonrpc/3, started daemon 139805774083840)> (func=<bound
method _Worker._run of <Worker name=jsonrpc/3 waiting task#=0 at
0x7f26ee2aed50>>, args=(), kwargs={}) (concurrent:193)
2019-02-17 17:06:43,334 DEBUG (MainThread) [Executor] Starting worker
jsonrpc/5 (executor:286)
2019-02-17 17:06:43,334 DEBUG (jsonrpc/3) [Executor] Worker started
(executor:298)
2019-02-17 17:06:43,339 DEBUG (MainThread) [Executor] Starting worker
jsonrpc/6 (executor:286)
2019-02-17 17:06:43,336 DEBUG (jsonrpc/4) [Executor] START thread
<Thread(jsonrpc/4, started daemon 139805765691136)> (func=<bound
method _Worker._run of <Worker name=jsonrpc/4 waiting task#=0 at
0x7f26ee2ae9d0>>, args=(), kwargs={}) (concurrent:193)
2019-02-17 17:06:43,339 DEBUG (jsonrpc/5) [Executor] START thread
<Thread(jsonrpc/5, started daemon 139805178599168)> (func=<bound
method _Worker._run of <Worker name=jsonrpc/5 waiting task#=0 at
0x7f26ee134690>>, args=(), kwargs={}) (concurrent:193)
2019-02-17 17:06:43,345 DEBUG (MainThread) [Executor] Starting worker
jsonrpc/7 (executor:286)
2019-02-17 17:06:43,346 DEBUG (jsonrpc/5) [Executor] Worker started
(executor:298)
2019-02-17 17:06:43,348 DEBUG (jsonrpc/6) [Executor] START thread
<Thread(jsonrpc/6, started daemon 139805170206464)> (func=<bound
method _Worker._run of <Worker name=jsonrpc/6 waiting task#=0 at
0x7f26ee2c9b50>>, args=(), kwargs={}) (concurrent:193)
2019-02-17 17:06:43,350 DEBUG (jsonrpc/4) [Executor] Worker started
(executor:298)
2019-02-17 17:06:43,354 DEBUG (jsonrpc/6) [Executor] Worker started
(executor:298)
2019-02-17 17:06:43,355 DEBUG (MainThread) [vds.MultiProtocolAcceptor]
Adding detector <yajsonrpc.stompserver.StompDetector instance at
0x7f26ee2b6098> (protocoldetector:210)
2019-02-17 17:06:43,352 DEBUG (jsonrpc/7) [Executor] START thread
<Thread(jsonrpc/7, started daemon 139804926793472)> (func=<bound
method _Worker._run of <Worker name=jsonrpc/7 waiting task#=0 at
0x7f26ee34ec50>>, args=(), kwargs={}) (concurrent:193)
2019-02-17 17:06:43,355 DEBUG (JsonRpcServer) [root] START thread
<Thread(JsonRpcServer, started daemon 139804918400768)> (func=<bound
method JsonRpcServer.serve_requests of <yajsonrpc.JsonRpcServer object
at 0x7f26ee2e2550>>, args=(), kwargs={}) (concurrent:193)
2019-02-17 17:06:43,359 DEBUG (jsonrpc/7) [Executor] Worker started
(executor:298)
2019-02-17 17:06:43,367 DEBUG (MainThread) [jsonrpc.AsyncoreClient]
Sending response (stompclient:294)
2019-02-17 17:06:43,365 INFO (Detector thread)
[ProtocolDetector.AcceptorImpl] Accepted connection from ::1:56880
(protocoldetector:61)
2019-02-17 17:06:43,369 DEBUG (Client ::1:45177) [root] START thread
<Thread(Client ::1:45177, started daemon 139804901615360)>
(func=<bound method Reactor.process_requests of
<yajsonrpc.betterAsyncore.Reactor object at 0x7f26ee2e22d0>>, args=(),
kwargs={}) (concurrent:193)
2019-02-17 17:06:43,371 DEBUG (Detector thread)
[ProtocolDetector.Detector] Using required_size=11
(protocoldetector:89)
2019-02-17 17:06:43,375 INFO (Detector thread)
[ProtocolDetector.Detector] Detected protocol stomp from ::1:56880
(protocoldetector:125)
2019-02-17 17:06:43,379 INFO (Detector thread) [Broker.StompAdapter]
Processing CONNECT request (stompserver:95)
2019-02-17 17:06:43,381 DEBUG (Client ::1:45177)
[yajsonrpc.protocols.stomp.AsyncClient] Stomp connection established
(stompclient:138)
2019-02-17 17:06:43,382 INFO (Detector thread) [Broker.StompAdapter]
Subscribe command received (stompserver:124)
2019-02-17 17:06:43,391 DEBUG (jsonrpc/0) [jsonrpc.JsonRpcServer]
Calling 'event' in bridge with [] (__init__:329)
2019-02-17 17:06:43,388 INFO (Detector thread) [Broker.StompAdapter]
Subscribe command received (stompserver:124)
2019-02-17 17:06:43,393 DEBUG (jsonrpc/0) [jsonrpc.Notification]
Sending event {"params": {"content": true, "notify_time":
5417247890},
"jsonrpc": "2.0", "method": "vdsm.event"}
(__init__:181)
2019-02-17 17:06:43,397 DEBUG (jsonrpc/0) [jsonrpc.JsonRpcServer]
Return 'event' in bridge with True (__init__:356)
2019-02-17 17:06:43,399 DEBUG (Client ::1:45177)
[jsonrpc.JsonRpcClient] No event queue is registered for received
event, ignoring. Event: {u'jsonrpc': u'2.0', u'params':
{u'content':
True, u'notify_time': 5417247890}, u'method': u'vdsm.event'}
(jsonrpcclient:244)
2019-02-17 17:06:43,401 INFO (jsonrpc/0) [jsonrpc.JsonRpcServer] RPC
call event succeeded in 0.01 seconds (__init__:312)
2019-02-17 17:06:43,402 DEBUG (Detector thread)
[protocoldetector.StompDetector] Stomp detected from ('::1', 56880)
(stompserver:413)
2019-02-17 17:06:43,440 DEBUG (Client ::1:45177)
[stomp.AsyncDispatcher] Communication error occurred. (stomp:421)
2019-02-17 17:06:45,445 DEBUG (Client ::1:45177)
[yajsonrpc.protocols.stomp.AsyncClient] Timeout occurred, trying to
reconnect (stompclient:128)
2019-02-17 17:06:45,448 INFO (Detector thread)
[ProtocolDetector.AcceptorImpl] Accepted connection from ::1:56882
(protocoldetector:61)
2019-02-17 17:06:45,449 DEBUG (Detector thread)
[ProtocolDetector.Detector] Using required_size=11
(protocoldetector:89)
2019-02-17 17:06:55,461 DEBUG (Detector thread)
[ProtocolDetector.Detector] Timed out while waiting for data
(protocoldetector:94)
2019-02-17 17:06:55,464 DEBUG (Client ::1:45177)
[stomp.AsyncDispatcher] managed to connect successfully. (stomp:388)
2019-02-17 17:06:57,473 DEBUG (Client ::1:45177)
[yajsonrpc.protocols.stomp.AsyncClient] Timeout occurred, trying to
reconnect (stompclient:128)
2019-02-17 17:06:57,475 DEBUG (Client ::1:45177)
[stomp.AsyncDispatcher] managed to connect successfully. (stomp:388)
2019-02-17 17:06:57,475 INFO (Detector thread)
[ProtocolDetector.AcceptorImpl] Accepted connection from ::1:56884
(protocoldetector:61)
2019-02-17 17:06:57,477 DEBUG (Detector thread)
[ProtocolDetector.Detector] Using required_size=11
(protocoldetector:89)
2019-02-17 17:06:57,478 INFO (Detector thread)
[ProtocolDetector.Detector] Detected protocol stomp from ::1:56884
(protocoldetector:125)
2019-02-17 17:06:57,479 INFO (Detector thread) [Broker.StompAdapter]
Processing CONNECT request (stompserver:95)
2019-02-17 17:06:57,480 INFO (Detector thread) [Broker.StompAdapter]
Subscribe command received (stompserver:124)
2019-02-17 17:06:57,481 DEBUG (Client ::1:45177)
[yajsonrpc.protocols.stomp.AsyncClient] Stomp connection established
(stompclient:138)
2019-02-17 17:06:57,482 INFO (Detector thread) [Broker.StompAdapter]
Subscribe command received (stompserver:124)
2019-02-17 17:06:57,483 DEBUG (Detector thread)
[protocoldetector.StompDetector] Stomp detected from ('::1', 56884)
(stompserver:413)
2019-02-17 17:06:58,441 WARNING (MainThread)
[yajsonrpc.protocols.stomp.AsyncClient] No subscription with
e3cbbadc-5e2e-46d5-9653-83c30f2b01f6 id (stompclient:211)
2019-02-17 17:06:58,442 WARNING (MainThread)
[yajsonrpc.protocols.stomp.AsyncClient] No subscription with
1835133c-868d-4ea8-8869-36f3c5c380f1 id (stompclient:211)
2019-02-17 17:06:58,443 DEBUG (MainThread) [vds.MultiProtocolAcceptor]
Stopping Acceptor (protocoldetector:214)
2019-02-17 17:06:58,444 DEBUG (Client ::1:45177) [root] FINISH thread
<Thread(Client ::1:45177, started daemon 139804901615360)>
(concurrent:196)
2019-02-17 17:06:58,445 INFO (MainThread) [jsonrpc.JsonRpcServer]
Stopping JsonRPC Server (__init__:442)
2019-02-17 17:06:58,446 DEBUG (MainThread) [Executor] Stopping
executor (executor:137)
2019-02-17 17:06:58,447 DEBUG (JsonRpcServer) [root] FINISH thread
<Thread(JsonRpcServer, started daemon 139804918400768)>
(concurrent:196)
2019-02-17 17:06:58,448 DEBUG (jsonrpc/3) [Executor] Worker stopped
(executor:303)
2019-02-17 17:06:58,450 DEBUG (JsonRpc (StompReactor)) [root] FINISH
thread <Thread(JsonRpc (StompReactor), started daemon
139804935186176)> (concurrent:196)
2019-02-17 17:06:58,450 DEBUG (jsonrpc/5) [Executor] Worker stopped
(executor:303)
2019-02-17 17:06:58,451 DEBUG (jsonrpc/2) [Executor] Worker stopped
(executor:303)
2019-02-17 17:06:58,447 DEBUG (jsonrpc/1) [Executor] Worker stopped
(executor:303)
2019-02-17 17:06:58,451 DEBUG (jsonrpc/4) [Executor] Worker stopped
(executor:303)
2019-02-17 17:06:58,452 DEBUG (jsonrpc/6) [Executor] Worker stopped
(executor:303)
2019-02-17 17:06:58,452 DEBUG (jsonrpc/7) [Executor] Worker stopped
(executor:303)
2019-02-17 17:06:58,453 DEBUG (jsonrpc/0) [Executor] Worker stopped
(executor:303)
2019-02-17 17:06:58,453 DEBUG (MainThread) [Executor] Waiting for
worker jsonrpc/7 (executor:290)
2019-02-17 17:06:58,455 DEBUG (jsonrpc/2) [Executor] FINISH thread
<Thread(jsonrpc/2, started daemon 139805898135296)> (concurrent:196)
2019-02-17 17:06:58,454 DEBUG (jsonrpc/3) [Executor] FINISH thread
<Thread(jsonrpc/3, started daemon 139805774083840)> (concurrent:196)
2019-02-17 17:06:58,454 DEBUG (jsonrpc/5) [Executor] FINISH thread
<Thread(jsonrpc/5, started daemon 139805178599168)> (concurrent:196)
2019-02-17 17:06:58,455 DEBUG (jsonrpc/1) [Executor] FINISH thread
<Thread(jsonrpc/1, started daemon 139805161813760)> (concurrent:196)
2019-02-17 17:06:58,455 DEBUG (jsonrpc/4) [Executor] FINISH thread
<Thread(jsCoverage.py warning: Module
/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/vdsm was never
imported. (module-not-imported)
onrpc/4, started daemon 139805765691136)> (concurrent:196)
2019-02-17 17:06:58,456 DEBUG (jsonrpc/6) [Executor] FINISH thread
<Thread(jsonrpc/6, started daemon 139805170206464)> (concurrent:196)
2019-02-17 17:06:58,456 DEBUG (jsonrpc/0) [Executor] FINISH thread
<Thread(jsonrpc/0, started daemon 139804943578880)> (concurrent:196)
2019-02-17 17:06:58,456 DEBUG (jsonrpc/7) [Executor] FINISH thread
<Thread(jsonrpc/7, started daemon 139804926793472)> (concurrent:196)
2019-02-17 17:06:58,459 DEBUG (MainThread) [Executor] Waiting for
worker jsonrpc/2 (executor:290)
2019-02-17 17:06:58,459 DEBUG (MainThread) [Executor] Waiting for
worker jsonrpc/0 (executor:290)
2019-02-17 17:06:58,460 DEBUG (MainThread) [Executor] Waiting for
worker jsonrpc/1 (executor:290)
2019-02-17 17:06:58,460 DEBUG (MainThread) [Executor] Waiting for
worker jsonrpc/3 (executor:290)
2019-02-17 17:06:58,460 DEBUG (MainThread) [Executor] Waiting for
worker jsonrpc/5 (executor:290)
2019-02-17 17:06:58,461 DEBUG (MainThread) [Executor] Waiting for
worker jsonrpc/4 (executor:290)
2019-02-17 17:06:58,461 DEBUG (MainThread) [Executor] Waiting for
worker jsonrpc/6 (executor:290)
2019-02-17 17:06:58,461 DEBUG (MainThread) [Scheduler] Stopping
scheduler test.Scheduler (schedule:110)
--------------------- >> end captured logging << ---------------------
https://jenkins.ovirt.org/blue/rest/organizations/jenkins/pipelines/vdsm_...
>
> On Wed, Jan 23, 2019 at 3:41 PM Nir Soffer <nsoffer(a)redhat.com> wrote:
>
>> On Wed, Jan 23, 2019 at 11:15 AM Marcin Sobczyk <msobczyk(a)redhat.com>
>> wrote:
>>
>>> Hi,
>>>
>>> I don't have time to look into this right now, but I will definitely do
>>> so after coming back from FOSDEM.
>>>
>> Great.
>>
>> We will mark this tests as broken_on_ci on Jenkins for now.
>>
>> I think the issue for this and other failures is the race we have when
>> handling
>> STOMP CONNECT and SUBSCRIBE, see these patches trying to fix this on
>> the client side:
>> https://gerrit.ovirt.org/c/95899
>>
>>
>>> Regards, Marcin
>>> On 1/22/19 12:57 AM, Nir Soffer wrote:
>>>
>>> On Tue, Jan 22, 2019 at 1:56 AM Nir Soffer <nsoffer(a)redhat.com> wrote:
>>>
>>>> On Sat, Jan 19, 2019 at 11:15 PM Nir Soffer <nsoffer(a)redhat.com>
>>>> wrote:
>>>>
>>>>> Recently this test cause too many random failures. I guess this is
>>>>> the known issue with handling SUBSCRIBE in protocol detector.
>>>>> I posted https://gerrit.ovirt.org/c/97099/
>>>>> To mark it as broken until we have time to dig deeper
>>>>>
>>>>>
======================================================================
>>>>>
>>>>> FAIL: test_detect_slow_client_concurrency(True)
(protocoldetector_test.AcceptorTests)
>>>>>
----------------------------------------------------------------------
>>>>> Traceback (most recent call last):
>>>>> File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/testlib.py", line
142, in wrapper
>>>>> return f(self, *args)
>>>>> File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/protocoldetector_test.py",
line 167, in test_detect_slow_client_concurrency
>>>>> self.check_concurrently(self.check_slow_client, use_ssl)
>>>>> File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/protocoldetector_test.py",
line 266, in check_concurrently
>>>>> self.assertTrue(all(done))
>>>>> AssertionError: False is not true
>>>>> -------------------- >> begin captured logging <<
--------------------
>>>>> 2019-01-19 20:47:16,021 DEBUG (MainThread)
[vds.MultiProtocolAcceptor] Creating socket (host='127.0.0.1', port=0, family=2,
socketype=1, proto=6) (protocoldetector:225)
>>>>> 2019-01-19 20:47:16,022 INFO (MainThread)
[vds.MultiProtocolAcceptor] Listening at 127.0.0.1:46009 (protocoldetector:183)
>>>>> 2019-01-19 20:47:16,023 DEBUG (MainThread)
[vds.MultiProtocolAcceptor] Adding detector <protocoldetector_test.Echo object at
0x7f1bb77f8dd0> (protocoldetector:210)
>>>>> 2019-01-19 20:47:16,024 DEBUG (MainThread)
[vds.MultiProtocolAcceptor] Adding detector <protocoldetector_test.Uppercase object at
0x7f1bb77f8c90> (protocoldetector:210)
>>>>> 2019-01-19 20:47:16,031 INFO (Thread-61)
[ProtocolDetector.AcceptorImpl] Accepted connection from 127.0.0.1:51950
(protocoldetector:61)
>>>>> 2019-01-19 20:47:16,047 INFO (Thread-61)
[ProtocolDetector.AcceptorImpl] Accepted connection from 127.0.0.1:51952
(protocoldetector:61)
>>>>> 2019-01-19 20:47:16,048 INFO (Thread-61)
[ProtocolDetector.AcceptorImpl] Accepted connection from 127.0.0.1:51954
(protocoldetector:61)
>>>>> 2019-01-19 20:47:16,065 INFO (Thread-61)
[ProtocolDetector.AcceptorImpl] Accepted connection from 127.0.0.1:51956
(protocoldetector:61)
>>>>> 2019-01-19 20:47:16,068 INFO (Thread-61)
[ProtocolDetector.AcceptorImpl] Accepted connection from 127.0.0.1:51958
(protocoldetector:61)
>>>>> 2019-01-19 20:47:16,069 DEBUG (Thread-61) [ProtocolDetector.Detector]
Using required_size=9 (protocoldetector:89)
>>>>> 2019-01-19 20:47:16,097 DEBUG (Thread-61) [ProtocolDetector.Detector]
Using required_size=9 (protocoldetector:89)
>>>>> 2019-01-19 20:47:16,099 DEBUG (Thread-61) [ProtocolDetector.Detector]
Using required_size=9 (protocoldetector:89)
>>>>> 2019-01-19 20:47:16,107 DEBUG (Thread-61) [ProtocolDetector.Detector]
Using required_size=9 (protocoldetector:89)
>>>>> 2019-01-19 20:47:16,109 DEBUG (Thread-61) [ProtocolDetector.Detector]
Using required_size=9 (protocoldetector:89)
>>>>> 2019-01-19 20:47:16,574 INFO (Thread-61) [ProtocolDetector.Detector]
Detected protocol echo from 127.0.0.1:51950 (protocoldetector:125)
>>>>> 2019-01-19 20:47:17,570 DEBUG (Thread-61) [ProtocolDetector.Detector]
Timed out while waiting for data (protocoldetector:94)
>>>>> 2019-01-19 20:47:17,571 DEBUG (Thread-61) [ProtocolDetector.Detector]
Timed out while waiting for data (protocoldetector:94)
>>>>> 2019-01-19 20:47:17,576 DEBUG (Thread-61) [ProtocolDetector.Detector]
Timed out while waiting for data (protocoldetector:94)
>>>>> 2019-01-19 20:47:17,578 DEBUG (Thread-61) [ProtocolDetector.Detector]
Timed out while waiting for data (protocoldetector:94)
>>>>> --------------------- >> end captured logging <<
---------------------
>>>>>
>>>>>
>>>> Another flaky test - we marked the other test in this class as broken
>>>> on ci
>>>> recently. This test fail randomly from time to time.
>>>>
>>>
>>> Failed this build:
>>>
>>>
https://jenkins.ovirt.org/job/vdsm_standard-check-patch/2158//artifact/ch...
>>>
>>>
>>>
>>>>
>>>> ======================================================================
>>>> ERROR: test_event(False) (stomp_test.StompTests)
>>>> ----------------------------------------------------------------------
>>>> Traceback (most recent call last):
>>>> File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/testlib.py", line
142, in wrapper
>>>> return f(self, *args)
>>>> File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/tests/stomp_test.py",
line 118, in test_event
>>>> client.callMethod("event", [], str(uuid4()))
>>>> File
"/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/lib/yajsonrpc/jsonrpcclient.py",
line 78, in callMethod
>>>> raise exception.JsonRpcNoResponseError(method=methodName)
>>>> JsonRpcNoResponseError: No response for JSON-RPC request:
{'method': 'event'}
>>>> -------------------- >> begin captured logging <<
--------------------
>>>> 2019-01-21 23:41:32,132 DEBUG (MainThread) [vds.MultiProtocolAcceptor]
Creating socket (host='::1', port=0, family=10, socketype=1, proto=6)
(protocoldetector:225)
>>>> 2019-01-21 23:41:32,133 INFO (MainThread) [vds.MultiProtocolAcceptor]
Listening at ::1:46303 (protocoldetector:183)
>>>> 2019-01-21 23:41:32,134 DEBUG (MainThread) [Scheduler] Starting scheduler
test.Scheduler (schedule:98)
>>>> 2019-01-21 23:41:32,135 DEBUG (test.Scheduler) [Scheduler] START thread
<Thread(test.Scheduler, started daemon 140162734585600)> (func=<bound method
Scheduler._run of <vdsm.schedule.Scheduler object at 0x7f7a2c156e10>>, args=(),
kwargs={}) (concurrent:193)
>>>> 2019-01-21 23:41:32,138 DEBUG (test.Scheduler) [Scheduler] started
(schedule:140)
>>>> 2019-01-21 23:41:32,139 DEBUG (JsonRpc (StompReactor)) [root] START
thread <Thread(JsonRpc (StompReactor), started daemon 140162271528704)>
(func=<bound method StompReactor.process_requests of
<yajsonrpc.stompserver.StompReactor object at 0x7f7a2c177950>>, args=(),
kwargs={}) (concurrent:193)
>>>> 2019-01-21 23:41:32,139 DEBUG (MainThread) [Executor] Starting executor
(executor:128)
>>>> 2019-01-21 23:41:32,141 DEBUG (MainThread) [Executor] Starting worker
jsonrpc/0 (executor:286)
>>>> 2019-01-21 23:41:32,142 DEBUG (MainThread) [Executor] Starting worker
jsonrpc/1 (executor:286)
>>>> 2019-01-21 23:41:32,143 DEBUG (jsonrpc/1) [Executor] START thread
<Thread(jsonrpc/1, started daemon 140162288314112)> (func=<bound method
_Worker._run of <Worker name=jsonrpc/1 waiting task#=0 at 0x7f7a2c177510>>,
args=(), kwargs={}) (concurrent:193)
>>>> 2019-01-21 23:41:32,144 DEBUG (MainThread) [Executor] Starting worker
jsonrpc/2 (executor:286)
>>>> 2019-01-21 23:41:32,144 DEBUG (jsonrpc/0) [Executor] START thread
<Thread(jsonrpc/0, started daemon 140162263136000)> (func=<bound method
_Worker._run of <Worker name=jsonrpc/0 waiting task#=0 at 0x7f7a2c177d50>>,
args=(), kwargs={}) (concurrent:193)
>>>> 2019-01-21 23:41:32,145 DEBUG (jsonrpc/1) [Executor] Worker started
(executor:298)
>>>> 2019-01-21 23:41:32,147 DEBUG (MainThread) [Executor] Starting worker
jsonrpc/3 (executor:286)
>>>> 2019-01-21 23:41:32,148 DEBUG (jsonrpc/2) [Executor] START thread
<Thread(jsonrpc/2, started daemon 140162751371008)> (func=<bound method
_Worker._run of <Worker name=jsonrpc/2 waiting task#=0 at 0x7f7a2c177ad0>>,
args=(), kwargs={}) (concurrent:193)
>>>> 2019-01-21 23:41:32,149 DEBUG (jsonrpc/0) [Executor] Worker started
(executor:298)
>>>> 2019-01-21 23:41:32,153 DEBUG (jsonrpc/2) [Executor] Worker started
(executor:298)
>>>> 2019-01-21 23:41:32,154 DEBUG (MainThread) [Executor] Starting worker
jsonrpc/4 (executor:286)
>>>> 2019-01-21 23:41:32,155 DEBUG (jsonrpc/3) [Executor] START thread
<Thread(jsonrpc/3, started daemon 140162742978304)> (func=<bound method
_Worker._run of <Worker name=jsonrpc/3 waiting task#=0 at 0x7f7a2c112e10>>,
args=(), kwargs={}) (concurrent:193)
>>>> 2019-01-21 23:41:32,158 DEBUG (jsonrpc/3) [Executor] Worker started
(executor:298)
>>>> 2019-01-21 23:41:32,159 DEBUG (MainThread) [Executor] Starting worker
jsonrpc/5 (executor:286)
>>>> 2019-01-21 23:41:32,160 DEBUG (jsonrpc/4) [Executor] START thread
<Thread(jsonrpc/4, started daemon 140162296706816)> (func=<bound method
_Worker._run of <Worker name=jsonrpc/4 waiting task#=0 at 0x7f7a2c112d50>>,
args=(), kwargs={}) (concurrent:193)
>>>> 2019-01-21 23:41:32,161 DEBUG (jsonrpc/4) [Executor] Worker started
(executor:298)
>>>> 2019-01-21 23:41:32,163 DEBUG (MainThread) [Executor] Starting worker
jsonrpc/6 (executor:286)
>>>> 2019-01-21 23:41:32,164 DEBUG (jsonrpc/5) [Executor] START thread
<Thread(jsonrpc/5, started daemon 140162279921408)> (func=<bound method
_Worker._run of <Worker name=jsonrpc/5 waiting task#=0 at 0x7f7a2c112810>>,
args=(), kwargs={}) (concurrent:193)
>>>> 2019-01-21 23:41:32,166 DEBUG (jsonrpc/6) [Executor] START thread
<Thread(jsonrpc/6, started daemon 140162254743296)> (func=<bound method
_Worker._run of <Worker name=jsonrpc/6 waiting task#=0 at 0x7f7a2c1924d0>>,
args=(), kwargs={}) (concurrent:193)
>>>> 2019-01-21 23:41:32,166 DEBUG (MainThread) [Executor] Starting worker
jsonrpc/7 (executor:286)
>>>> 2019-01-21 23:41:32,167 DEBUG (jsonrpc/5) [Executor] Worker started
(executor:298)
>>>> 2019-01-21 23:41:32,169 DEBUG (jsonrpc/6) [Executor] Worker started
(executor:298)
>>>> 2019-01-21 23:41:32,172 DEBUG (jsonrpc/7) [Executor] START thread
<Thread(jsonrpc/7, started daemon 140162246350592)> (func=<bound method
_Worker._run of <Worker name=jsonrpc/7 waiting task#=0 at 0x7f7a2c1921d0>>,
args=(), kwargs={}) (concurrent:193)
>>>> 2019-01-21 23:41:32,173 DEBUG (MainThread) [vds.MultiProtocolAcceptor]
Adding detector <yajsonrpc.stompserver.StompDetector instance at 0x7f7a13fa7050>
(protocoldetector:210)
>>>> 2019-01-21 23:41:32,173 DEBUG (JsonRpcServer) [root] START thread
<Thread(JsonRpcServer, started daemon 140162164061952)> (func=<bound method
JsonRpcServer.serve_requests of <yajsonrpc.JsonRpcServer object at
0x7f7a2c177bd0>>, args=(), kwargs={}) (concurrent:193)
>>>> 2019-01-21 23:41:32,174 DEBUG (jsonrpc/7) [Executor] Worker started
(executor:298)
>>>> 2019-01-21 23:41:32,181 INFO (Detector thread)
[ProtocolDetector.AcceptorImpl] Accepted connection from ::1:43660 (protocoldetector:61)
>>>> 2019-01-21 23:41:32,185 DEBUG (MainThread) [jsonrpc.AsyncoreClient]
Sending response (stompclient:294)
>>>> 2019-01-21 23:41:32,185 DEBUG (Detector thread)
[ProtocolDetector.Detector] Using required_size=11 (protocoldetector:89)
>>>> 2019-01-21 23:41:32,187 DEBUG (Client ::1:46303) [root] START thread
<Thread(Client ::1:46303, started daemon 140162147276544)> (func=<bound method
Reactor.process_requests of <yajsonrpc.betterAsyncore.Reactor object at
0x7f7a2c156610>>, args=(), kwargs={}) (concurrent:193)
>>>> 2019-01-21 23:41:32,189 INFO (Detector thread)
[ProtocolDetector.Detector] Detected protocol stomp from ::1:43660 (protocoldetector:125)
>>>> 2019-01-21 23:41:32,192 INFO (Detector thread) [Broker.StompAdapter]
Processing CONNECT request (stompserver:95)
>>>> 2019-01-21 23:41:32,195 INFO (JsonRpc (StompReactor))
[Broker.StompAdapter] Subscribe command received (stompserver:124)
>>>> 2019-01-21 23:41:32,196 INFO (JsonRpc (StompReactor))
[Broker.StompAdapter] Subscribe command received (stompserver:124)
>>>> 2019-01-21 23:41:32,197 ERROR (Detector thread) [vds.dispatcher]
uncaptured python exception, closing channel <yajsonrpc.betterAsyncore.Dispatcher
('::1', 43660, 0, 0) at 0x7f7a13fdaab8> (<type
'exceptions.AttributeError'>:'NoneType' object has no attribute
'command' [/usr/lib64/python2.7/asyncore.py|readwrite|108]
[/usr/lib64/python2.7/asyncore.py|handle_read_event|449]
[/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|412]
[/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|635]
[/usr/lib64/python2.7/asyncore.py|handle_read_event|449]
[/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|415]
[/home/jenkins/workspace/vdsm_standard-check-patch/vdsm/lib/yajsonrpc/stompserver.py|handle_frame|269])
(betterAsyncore:179)
>>>> 2019-01-21 23:41:32,199 DEBUG (Client ::1:46303)
[yajsonrpc.protocols.stomp.AsyncClient] Stomp connection established (stompclient:138)
>>>> 2019-01-21 23:41:32,200 WARNING (Detector thread) [vds.dispatcher]
unhandled close event (betterAsyncore:179)
>>>> 2019-01-21 23:41:32,207 DEBUG (jsonrpc/1) [jsonrpc.JsonRpcServer] Calling
'event' in bridge with [] (__init__:329)
>>>> 2019-01-21 23:41:32,208 DEBUG (jsonrpc/1) [jsonrpc.Notification] Sending
event {"params": {"content": true, "notify_time":
23083358880}, "jsonrpc": "2.0", "method":
"vdsm.event"} (__init__:181)
>>>> 2019-01-21 23:41:32,210 DEBUG (jsonrpc/1) [jsonrpc.JsonRpcServer] Return
'event' in bridge with True (__init__:356)
>>>> 2019-01-21 23:41:32,210 INFO (jsonrpc/1) [jsonrpc.JsonRpcServer] RPC
call event succeeded in 0.00 seconds (__init__:312)
>>>> 2019-01-21 23:41:34,207 DEBUG (Client ::1:46303)
[yajsonrpc.protocols.stomp.AsyncClient] Timeout occurred, trying to reconnect
(stompclient:128)
>>>> 2019-01-21 23:41:34,209 INFO (Detector thread)
[ProtocolDetector.AcceptorImpl] Accepted connection from ::1:43662 (protocoldetector:61)
>>>> 2019-01-21 23:41:34,211 DEBUG (Detector thread)
[ProtocolDetector.Detector] Using required_size=11 (protocoldetector:89)
>>>> 2019-01-21 23:41:44,222 DEBUG (Detector thread)
[ProtocolDetector.Detector] Timed out while waiting for data (protocoldetector:94)
>>>> 2019-01-21 23:41:44,223 DEBUG (Client ::1:46303) [stomp.AsyncDispatcher]
managed to connect successfully. (stomp:388)
>>>> 2019-01-21 23:41:46,227 DEBUG (Client ::1:46303)
[yajsonrpc.protocols.stomp.AsyncClient] Timeout occurred, trying to reconnect
(stompclient:128)
>>>> 2019-01-21 23:41:46,230 INFO (Detector thread)
[ProtocolDetector.AcceptorImpl] Accepted connection from ::1:43664 (protocoldetector:61)
>>>> 2019-01-21 23:41:46,230 DEBUG (Detector thread)
[ProtocolDetector.Detector] Using required_size=11 (protocoldetector:89)
>>>> 2019-01-21 23:41:46,232 DEBUG (Client ::1:46303) [stomp.AsyncDispatcher]
managed to connect successfully. (stomp:388)
>>>> 2019-01-21 23:41:46,233 INFO (Detector thread)
[ProtocolDetector.Detector] Detected protocol stomp from ::1:43664 (protocoldetector:125)
>>>> 2019-01-21 23:41:46,235 INFO (Detector thread) [Broker.StompAdapter]
Processing CONNECT request (stompserver:95)
>>>> 2019-01-21 23:41:46,236 DEBUG (Detector thread)
[protocoldetector.StompDetector] Stomp detected from ('::1', 43664)
(stompserver:413)
>>>> 2019-01-21 23:41:46,240 INFO (JsonRpc (StompReactor))
[Broker.StompAdapter] Subscribe command received (stompserver:124)
>>>> 2019-01-21 23:41:46,242 DEBUG (Client ::1:46303)
[yajsonrpc.protocols.stomp.AsyncClient] Stomp connection established (stompclient:138)
>>>> 2019-01-21 23:41:46,281 INFO (JsonRpc (StompReactor))
[Broker.StompAdapter] Subscribe command received (stompserver:124)
>>>> 2019-01-21 23:41:47,200 WARNING (MainThread)
[yajsonrpc.protocols.stomp.AsyncClient] No subscription with
2a926ebd-35f9-47ce-9fb2-bec2823734f0 id (stompclient:211)
>>>> 2019-01-21 23:41:47,201 WARNING (MainThread)
[yajsonrpc.protocols.stomp.AsyncClient] No subscription with
b33e3bb3-1f1f-49c2-9ec2-073ec9f4fb33 id (stompclient:211)
>>>> 2019-01-21 23:41:47,202 DEBUG (MainThread) [vds.MultiProtocolAcceptor]
Stopping Acceptor (protocoldetector:214)
>>>> 2019-01-21 23:41:47,202 INFO (MainThread) [jsonrpc.JsonRCoverage.py
warning: Module /home/jenkins/workspace/vdsm_standard-check-patch/vdsm/vdsm was never
imported. (module-not-imported)
>>>> pcServer] Stopping JsonRPC Server (__init__:442)
>>>> 2019-01-21 23:41:47,203 DEBUG (JsonRpcServer) [root] FINISH thread
<Thread(JsonRpcServer, started daemon 140162164061952)> (concurrent:196)
>>>> 2019-01-21 23:41:47,204 DEBUG (MainThread) [Executor] Stopping executor
(executor:137)
>>>> 2019-01-21 23:41:47,204 DEBUG (Client ::1:46303) [root] FINISH thread
<Thread(Client ::1:46303, started daemon 140162147276544)> (concurrent:196)
>>>> 2019-01-21 23:41:47,206 DEBUG (jsonrpc/0) [Executor] Worker stopped
(executor:303)
>>>> 2019-01-21 23:41:47,207 DEBUG (jsonrpc/2) [Executor] Worker stopped
(executor:303)
>>>> 2019-01-21 23:41:47,208 DEBUG (jsonrpc/3) [Executor] Worker stopped
(executor:303)
>>>> 2019-01-21 23:41:47,209 DEBUG (jsonrpc/4) [Executor] Worker stopped
(executor:303)
>>>> 2019-01-21 23:41:47,209 DEBUG (jsonrpc/5) [Executor] Worker stopped
(executor:303)
>>>> 2019-01-21 23:41:47,210 DEBUG (JsonRpc (StompReactor)) [root] FINISH
thread <Thread(JsonRpc (StompReactor), started daemon 140162271528704)>
(concurrent:196)
>>>> 2019-01-21 23:41:47,211 DEBUG (jsonrpc/6) [Executor] Worker stopped
(executor:303)
>>>> 2019-01-21 23:41:47,212 DEBUG (jsonrpc/0) [Executor] FINISH thread
<Thread(jsonrpc/0, started daemon 140162263136000)> (concurrent:196)
>>>> 2019-01-21 23:41:47,212 DEBUG (jsonrpc/2) [Executor] FINISH thread
<Thread(jsonrpc/2, started daemon 140162751371008)> (concurrent:196)
>>>> 2019-01-21 23:41:47,212 DEBUG (jsonrpc/3) [Executor] FINISH thread
<Thread(jsonrpc/3, started daemon 140162742978304)> (concurrent:196)
>>>> 2019-01-21 23:41:47,212 DEBUG (MainThread) [Executor] Waiting for worker
jsonrpc/5 (executor:290)
>>>> 2019-01-21 23:41:47,212 DEBUG (jsonrpc/1) [Executor] Worker stopped
(executor:303)
>>>> 2019-01-21 23:41:47,216 DEBUG (jsonrpc/1) [Executor] FINISH thread
<Thread(jsonrpc/1, started daemon 140162288314112)> (concurrent:196)
>>>> 2019-01-21 23:41:47,213 DEBUG (jsonrpc/4) [Executor] FINISH thread
<Thread(jsonrpc/4, started daemon 140162296706816)> (concurrent:196)
>>>> 2019-01-21 23:41:47,214 DEBUG (jsonrpc/7) [Executor] Worker stopped
(executor:303)
>>>> 2019-01-21 23:41:47,214 DEBUG (jsonrpc/5) [Executor] FINISH thread
<Thread(jsonrpc/5, started daemon 140162279921408)> (concurrent:196)
>>>> 2019-01-21 23:41:47,215 DEBUG (jsonrpc/6) [Executor] FINISH thread
<Thread(jsonrpc/6, started daemon 140162254743296)> (concurrent:196)
>>>> 2019-01-21 23:41:47,217 DEBUG (jsonrpc/7) [Executor] FINISH thread
<Thread(jsonrpc/7, started daemon 140162246350592)> (concurrent:196)
>>>> 2019-01-21 23:41:47,218 DEBUG (MainThread) [Executor] Waiting for worker
jsonrpc/3 (executor:290)
>>>> 2019-01-21 23:41:47,219 DEBUG (MainThread) [Executor] Waiting for worker
jsonrpc/2 (executor:290)
>>>> 2019-01-21 23:41:47,220 DEBUG (MainThread) [Executor] Waiting for worker
jsonrpc/6 (executor:290)
>>>> 2019-01-21 23:41:47,220 DEBUG (MainThread) [Executor] Waiting for worker
jsonrpc/1 (executor:290)
>>>> 2019-01-21 23:41:47,220 DEBUG (MainThread) [Executor] Waiting for worker
jsonrpc/4 (executor:290)
>>>> 2019-01-21 23:41:47,221 DEBUG (MainThread) [Executor] Waiting for worker
jsonrpc/7 (executor:290)
>>>> 2019-01-21 23:41:47,221 DEBUG (MainThread) [Executor] Waiting for worker
jsonrpc/0 (executor:290)
>>>> 2019-01-21 23:41:47,221 DEBUG (MainThread) [Scheduler] Stopping scheduler
test.Scheduler (schedule:110)
>>>> 2019-01-21 23:41:47,222 DEBUG (test.Scheduler) [Scheduler] stopped
(schedule:143)
>>>> 2019-01-21 23:41:47,222 DEBUG (test.Scheduler) [Scheduler] FINISH thread
<Thread(test.Scheduler, started daemon 140162734585600)> (concurrent:196)
>>>>
>>>>
>>>>
2138
days inactive
2167
days old
7 comments
2 participants
participants (2)
-
Marcin Sobczyk -
Nir Soffer