On Sat, Jan 19, 2019 at 11:15 PM Nir Soffer <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 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)