jjerphan/server

## server
Showing logs of joblib-dask-deadlock-test-server-5796bf7779-5pxcz
[2019-05-31 11:50:20,035] [8/MainThread] [INFO] [root] Launching a server
[2019-05-31 11:50:20,771] [9/MainThread] [INFO] [root] Distributed 1.28.0+15.g6ea010b imported
[2019-05-31 11:50:20,772] [9/MainThread] [INFO] [root] Git revision: 6ea010bcf21db7445bd26286966f59a7e75ab390
/usr/local/lib/python3.6/site-packages/bokeh/themes/theme.py:94: YAMLLoadWarning: calling yaml.load() without Loader=... is deprecated, as the default Loader is unsafe. Please read https://msg.pyyaml.org/load for full details.
  json = yaml.load(f)
[2019-05-31 11:50:21,488] [9/MainThread] [INFO] [root] Joblib 0.13.2 imported
[2019-05-31 11:50:21,818] [9/MainThread] [INFO] [root] setup_log() called
[2019-05-31 11:50:21,818] [9/MainThread] [INFO] [root] Installing debugging signal handler
[2019-05-31 11:50:21,819] [9/MainThread] [INFO] [root] Started reproducible example
[2019-05-31 11:50:21,819] [9/MainThread] [INFO] [root] Dask Scheduler: starting on port 8786
[2019-05-31 11:50:21,821] [9/MainThread] [INFO] [root] Dask Scheduler: started on port 8786
[2019-05-31 11:50:21,822] [9/MainThread] [INFO] [root] Creating Dask Client
[2019-05-31 11:50:22,015] [9/MainThread] [INFO] [root] Client.__init__ called from <module>
[2019-05-31 11:50:22,018] [9/MainThread] [DEBUG] [asyncio] Using selector: EpollSelector
[2019-05-31 11:50:22,020] [9/MainThread] [INFO] [root] Client.start called from __init__
[2019-05-31 11:50:22,021] [9/IO loop] [DEBUG] [asyncio] Using selector: EpollSelector
[2019-05-31 11:50:22,025] [9/Thread-1] [INFO] [root] Scheduler.__init__ called from start_dask_scheduler
[2019-05-31 11:50:22,026] [9/Thread-1] [INFO] [root] Scheduler._setup_logging called from __init__
[2019-05-31 11:50:22,028] [9/Thread-1] [DEBUG] [asyncio] Using selector: EpollSelector
[2019-05-31 11:50:22,041] [9/Thread-1] [INFO] [root] Scheduler.start called from start_dask_scheduler
[2019-05-31 11:50:22,042] [9/Thread-1] [INFO] [root] Clear task state
[2019-05-31 11:50:22,046] [9/IO loop] [INFO] [root] Client._start called from wrapper
[2019-05-31 11:50:22,073] [9/Thread-1] [INFO] [root]   Scheduler at:    tcp://10.12.3.241:8786
[2019-05-31 11:50:22,073] [9/Thread-1] [INFO] [root]       bokeh at:                     :8787
[2019-05-31 11:50:22,074] [9/Thread-1] [INFO] [root] Scheduler.finished called from wrapper
[2019-05-31 11:50:22,079] [9/Thread-1] [INFO] [root] Scheduler.add_worker called from wrapper
[2019-05-31 11:50:22,081] [9/Thread-1] [INFO] [root] [2e152f2b-36c8-4f72-a9d2-44c1394f9fdc] Scheduler.check_idle_saturated called from add_worker
[2019-05-31 11:50:22,081] [9/Thread-1] [INFO] [root] [2e152f2b-36c8-4f72-a9d2-44c1394f9fdc] ws  = tcp://10.12.3.240:41261
[2019-05-31 11:50:22,081] [9/Thread-1] [INFO] [root] [2e152f2b-36c8-4f72-a9d2-44c1394f9fdc] occ = 0
[2019-05-31 11:50:22,081] [9/Thread-1] [INFO] [root] [2e152f2b-36c8-4f72-a9d2-44c1394f9fdc] nc  = 8
[2019-05-31 11:50:22,081] [9/Thread-1] [INFO] [root] [2e152f2b-36c8-4f72-a9d2-44c1394f9fdc] p   = 0
[2019-05-31 11:50:22,081] [9/Thread-1] [INFO] [root] [2e152f2b-36c8-4f72-a9d2-44c1394f9fdc] avg = 0.0
[2019-05-31 11:50:22,082] [9/Thread-1] [INFO] [root] [2e152f2b-36c8-4f72-a9d2-44c1394f9fdc] tcp://10.12.3.240:41261 idle ; not saturated
[2019-05-31 11:50:22,082] [9/Thread-1] [INFO] [root] Register tcp://10.12.3.240:41261
[2019-05-31 11:50:22,084] [9/IO loop] [INFO] [root] Client._ensure_connected called from wrapper
[2019-05-31 11:50:22,099] [9/IO loop] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:50:22,105] [9/Thread-1] [INFO] [root] Scheduler.handle_worker called from wrapper
[2019-05-31 11:50:22,105] [9/Thread-1] [INFO] [root] Scheduler.handle_worker: Starting worker compute stream, tcp://10.12.3.240:41261
[2019-05-31 11:50:22,106] [9/Thread-1] [INFO] [root] Server.handle_long_running called from wrapper
[2019-05-31 11:50:22,106] [9/Thread-1] [INFO] [root] Server.handle_long_running arguments
[2019-05-31 11:50:22,107] [9/Thread-1] [INFO] [root] caller_name ; id: 140477619307328 ; type: <class 'str'> ; value: wrapper
[2019-05-31 11:50:22,107] [9/Thread-1] [INFO] [root] every_cycle ; id: 140477187880776 ; type: <class 'list'> ; value: []
[2019-05-31 11:50:22,107] [9/Thread-1] [INFO] [root] extra ; id: 140476407890208 ; type: <class 'dict'> ; value: {'worker': 'tcp://10.12.3.240:41261'}
[2019-05-31 11:50:22,107] [9/Thread-1] [INFO] [root] comm ; id: 140476425546272 ; type: <class 'distributed.comm.tcp.TCP'> ; value: <TCP Scheduler connection to worker local=tcp://10.12.3.241:8786 remote=tcp://10.12.3.240:53376>
[2019-05-31 11:50:22,109] [9/Thread-1] [INFO] [root] Scheduler.__repr__ called from handle_stream
[2019-05-31 11:50:22,109] [9/Thread-1] [INFO] [root] self ; id: 140476527270992 ; type: <class 'distributed.scheduler.Scheduler'> ; value: <Scheduler: "tcp://10.12.3.241:8786" processes: 1 cores: 8>
[2019-05-31 11:50:22,109] [9/Thread-1] [INFO] [root] Server.handle_long_running: Starting established connection
[2019-05-31 11:50:22,109] [9/Thread-1] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:50:22,114] [9/Thread-1] [INFO] [root] Scheduler.add_worker called from wrapper
[2019-05-31 11:50:22,115] [9/Thread-1] [INFO] [root] [51aa8979-dda8-4145-ad96-46cfd1c9d9d0] Scheduler.check_idle_saturated called from add_worker
[2019-05-31 11:50:22,116] [9/Thread-1] [INFO] [root] [51aa8979-dda8-4145-ad96-46cfd1c9d9d0] ws  = tcp://10.12.2.24:39495
[2019-05-31 11:50:22,116] [9/Thread-1] [INFO] [root] [51aa8979-dda8-4145-ad96-46cfd1c9d9d0] occ = 0
[2019-05-31 11:50:22,116] [9/Thread-1] [INFO] [root] [51aa8979-dda8-4145-ad96-46cfd1c9d9d0] nc  = 8
[2019-05-31 11:50:22,116] [9/Thread-1] [INFO] [root] [51aa8979-dda8-4145-ad96-46cfd1c9d9d0] p   = 0
[2019-05-31 11:50:22,116] [9/Thread-1] [INFO] [root] [51aa8979-dda8-4145-ad96-46cfd1c9d9d0] avg = 0.0
[2019-05-31 11:50:22,116] [9/Thread-1] [INFO] [root] [51aa8979-dda8-4145-ad96-46cfd1c9d9d0] tcp://10.12.2.24:39495 idle ; not saturated
[2019-05-31 11:50:22,116] [9/Thread-1] [INFO] [root] Register tcp://10.12.2.24:39495
[2019-05-31 11:50:22,120] [9/Thread-1] [INFO] [root] Scheduler.add_worker called from wrapper
[2019-05-31 11:50:22,121] [9/Thread-1] [INFO] [root] [f3ce8d12-1bf7-4685-a44e-7f5ae733b902] Scheduler.check_idle_saturated called from add_worker
[2019-05-31 11:50:22,121] [9/Thread-1] [INFO] [root] [f3ce8d12-1bf7-4685-a44e-7f5ae733b902] ws  = tcp://10.12.3.242:44061
[2019-05-31 11:50:22,121] [9/Thread-1] [INFO] [root] [f3ce8d12-1bf7-4685-a44e-7f5ae733b902] occ = 0
[2019-05-31 11:50:22,121] [9/Thread-1] [INFO] [root] [f3ce8d12-1bf7-4685-a44e-7f5ae733b902] nc  = 8
[2019-05-31 11:50:22,121] [9/Thread-1] [INFO] [root] [f3ce8d12-1bf7-4685-a44e-7f5ae733b902] p   = 0
[2019-05-31 11:50:22,121] [9/Thread-1] [INFO] [root] [f3ce8d12-1bf7-4685-a44e-7f5ae733b902] avg = 0.0
[2019-05-31 11:50:22,121] [9/Thread-1] [INFO] [root] [f3ce8d12-1bf7-4685-a44e-7f5ae733b902] tcp://10.12.3.242:44061 idle ; not saturated
[2019-05-31 11:50:22,122] [9/Thread-1] [INFO] [root] Register tcp://10.12.3.242:44061
[2019-05-31 11:50:22,131] [9/Thread-1] [INFO] [root] Scheduler.handle_worker called from wrapper
[2019-05-31 11:50:22,131] [9/Thread-1] [INFO] [root] Scheduler.handle_worker: Starting worker compute stream, tcp://10.12.2.24:39495
[2019-05-31 11:50:22,132] [9/Thread-1] [INFO] [root] Server.handle_long_running called from wrapper
[2019-05-31 11:50:22,132] [9/Thread-1] [INFO] [root] Server.handle_long_running arguments
[2019-05-31 11:50:22,132] [9/Thread-1] [INFO] [root] caller_name ; id: 140477619307328 ; type: <class 'str'> ; value: wrapper
[2019-05-31 11:50:22,132] [9/Thread-1] [INFO] [root] every_cycle ; id: 140477187880776 ; type: <class 'list'> ; value: []
[2019-05-31 11:50:22,132] [9/Thread-1] [INFO] [root] extra ; id: 140476408339120 ; type: <class 'dict'> ; value: {'worker': 'tcp://10.12.2.24:39495'}
[2019-05-31 11:50:22,132] [9/Thread-1] [INFO] [root] comm ; id: 140476408277592 ; type: <class 'distributed.comm.tcp.TCP'> ; value: <TCP Scheduler connection to worker local=tcp://10.12.3.241:8786 remote=tcp://10.12.2.24:46126>
[2019-05-31 11:50:22,133] [9/Thread-1] [INFO] [root] Scheduler.__repr__ called from handle_stream
[2019-05-31 11:50:22,133] [9/Thread-1] [INFO] [root] self ; id: 140476527270992 ; type: <class 'distributed.scheduler.Scheduler'> ; value: <Scheduler: "tcp://10.12.3.241:8786" processes: 3 cores: 24>
[2019-05-31 11:50:22,133] [9/Thread-1] [INFO] [root] Server.handle_long_running: Starting established connection
[2019-05-31 11:50:22,134] [9/Thread-1] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:50:22,135] [9/Thread-1] [INFO] [root] Scheduler.handle_worker called from wrapper
[2019-05-31 11:50:22,135] [9/Thread-1] [INFO] [root] Scheduler.handle_worker: Starting worker compute stream, tcp://10.12.3.242:44061
[2019-05-31 11:50:22,135] [9/Thread-1] [INFO] [root] Server.handle_long_running called from wrapper
[2019-05-31 11:50:22,136] [9/Thread-1] [INFO] [root] Server.handle_long_running arguments
[2019-05-31 11:50:22,136] [9/Thread-1] [INFO] [root] caller_name ; id: 140477619307328 ; type: <class 'str'> ; value: wrapper
[2019-05-31 11:50:22,136] [9/Thread-1] [INFO] [root] every_cycle ; id: 140477187880776 ; type: <class 'list'> ; value: []
[2019-05-31 11:50:22,136] [9/Thread-1] [INFO] [root] extra ; id: 140476399284016 ; type: <class 'dict'> ; value: {'worker': 'tcp://10.12.3.242:44061'}
[2019-05-31 11:50:22,136] [9/Thread-1] [INFO] [root] comm ; id: 140476399309768 ; type: <class 'distributed.comm.tcp.TCP'> ; value: <TCP Scheduler connection to worker local=tcp://10.12.3.241:8786 remote=tcp://10.12.3.242:59894>
[2019-05-31 11:50:22,137] [9/Thread-1] [INFO] [root] Scheduler.__repr__ called from handle_stream
[2019-05-31 11:50:22,137] [9/Thread-1] [INFO] [root] self ; id: 140476527270992 ; type: <class 'distributed.scheduler.Scheduler'> ; value: <Scheduler: "tcp://10.12.3.241:8786" processes: 3 cores: 24>
[2019-05-31 11:50:22,137] [9/Thread-1] [INFO] [root] Server.handle_long_running: Starting established connection
[2019-05-31 11:50:22,138] [9/Thread-1] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:50:22,139] [9/Thread-1] [INFO] [root] Scheduler.add_client called from wrapper
[2019-05-31 11:50:22,139] [9/Thread-1] [INFO] [root] Receive client connection: Client-452b0d50-839a-11e9-8009-0a580a0c03f1
[2019-05-31 11:50:22,140] [9/Thread-1] [INFO] [root] Server.handle_long_running called from wrapper
[2019-05-31 11:50:22,140] [9/Thread-1] [INFO] [root] Server.handle_long_running arguments
[2019-05-31 11:50:22,140] [9/Thread-1] [INFO] [root] caller_name ; id: 140477619307328 ; type: <class 'str'> ; value: wrapper
[2019-05-31 11:50:22,141] [9/Thread-1] [INFO] [root] every_cycle ; id: 140477187880776 ; type: <class 'list'> ; value: []
[2019-05-31 11:50:22,141] [9/Thread-1] [INFO] [root] extra ; id: 140476399010368 ; type: <class 'dict'> ; value: {'client': 'Client-452b0d50-839a-11e9-8009-0a580a0c03f1'}
[2019-05-31 11:50:22,141] [9/Thread-1] [INFO] [root] comm ; id: 140476399312232 ; type: <class 'distributed.comm.tcp.TCP'> ; value: <TCP Scheduler->Client local=tcp://10.12.3.241:8786 remote=tcp://10.12.3.241:56874>
[2019-05-31 11:50:22,142] [9/Thread-1] [INFO] [root] Scheduler.__repr__ called from handle_stream
[2019-05-31 11:50:22,142] [9/Thread-1] [INFO] [root] self ; id: 140476527270992 ; type: <class 'distributed.scheduler.Scheduler'> ; value: <Scheduler: "tcp://10.12.3.241:8786" processes: 3 cores: 24>
[2019-05-31 11:50:22,142] [9/Thread-1] [INFO] [root] Server.handle_long_running: Starting established connection
[2019-05-31 11:50:22,142] [9/Thread-1] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:50:22,146] [9/IO loop] [INFO] [root] Client._handle_report called from wrapper
[2019-05-31 11:50:22,146] [9/MainThread] [INFO] [root] Created Dask Client
[2019-05-31 11:50:22,146] [9/MainThread] [INFO] [root] Waiting for Workers to connect
[2019-05-31 11:50:24,152] [9/IO loop] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:50:26,148] [9/IO loop] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:50:27,148] [9/Thread-1] [INFO] [root] Server.handle_long_running: got 1 messages
[2019-05-31 11:50:27,149] [9/Thread-1] [INFO] [root] Server.handle_long_running: message: {'op': 'heartbeat-client'}
[2019-05-31 11:50:27,150] [9/Thread-1] [INFO] [root] Scheduler.__repr__ called from handle_stream
[2019-05-31 11:50:27,150] [9/Thread-1] [INFO] [root] Server.handle_long_running: Using handler <bound method Scheduler.client_heartbeat of <Scheduler: "tcp://10.12.3.241:8786" processes: 3 cores: 24>>
[2019-05-31 11:50:27,150] [9/Thread-1] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:50:28,147] [9/IO loop] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:50:30,148] [9/IO loop] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:50:32,148] [9/IO loop] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:50:32,152] [9/Thread-1] [INFO] [root] Server.handle_long_running: got 1 messages
[2019-05-31 11:50:32,153] [9/Thread-1] [INFO] [root] Server.handle_long_running: message: {'op': 'heartbeat-client'}
[2019-05-31 11:50:32,155] [9/Thread-1] [INFO] [root] Scheduler.__repr__ called from handle_stream
[2019-05-31 11:50:32,155] [9/Thread-1] [INFO] [root] Server.handle_long_running: Using handler <bound method Scheduler.client_heartbeat of <Scheduler: "tcp://10.12.3.241:8786" processes: 3 cores: 24>>
[2019-05-31 11:50:32,155] [9/Thread-1] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:50:32,161] [9/MainThread] [INFO] [joblib.parallel] register_parallel_backend called on ; name: dask ; factory: DaskDistributedBackend
[2019-05-31 11:50:32,161] [9/MainThread] [INFO] [root] Entering Dask Context
[2019-05-31 11:50:32,161] [9/MainThread] [INFO] [joblib.parallel] parallel_backend.__init__ called
[2019-05-31 11:50:32,162] [9/MainThread] [INFO] [joblib.dask] DaskDistributedBackend.__init__ called from __init__
[2019-05-31 11:50:32,163] [9/MainThread] [INFO] [root] Worker.get_client called
[2019-05-31 11:50:32,163] [9/MainThread] [INFO] [root] Worker.get_worker called
[2019-05-31 11:50:32,163] [9/MainThread] [INFO] [root] Entered Dask Context
[2019-05-31 11:50:32,163] [9/MainThread] [INFO] [root] Running GridSearchCV.fit with dask as a parallel back-end
/usr/local/lib64/python3.6/site-packages/sklearn/model_selection/_split.py:2053: FutureWarning: You should specify a value for 'cv' instead of relying on the default value. The default value will change from 3 to 5 in version 0.22.
  warnings.warn(CV_WARNING, FutureWarning)
[2019-05-31 11:50:32,164] [9/MainThread] [INFO] [joblib.parallel] Parallel.__init__ called
[2019-05-31 11:50:32,164] [9/MainThread] [INFO] [joblib.parallel] Parallel.__enter__ called
[2019-05-31 11:50:32,164] [9/MainThread] [INFO] [joblib.parallel] Parallel._initialize_backend called
[2019-05-31 11:50:32,165] [9/MainThread] [INFO] [joblib.dask] DaskDistributedBackend.configure called from _initialize_backend
[2019-05-31 11:50:32,166] [9/MainThread] [INFO] [joblib.dask] DaskDistributedBackend.effective_n_jobs called from configure
[2019-05-31 11:50:32,173] [9/MainThread] [INFO] [joblib.parallel] Parallel.__call__ called
[2019-05-31 11:50:32,174] [9/MainThread] [INFO] [joblib.dask] DaskDistributedBackend.effective_n_jobs called from _effective_n_jobs
[2019-05-31 11:50:32,181] [9/MainThread] [INFO] [joblib.parallel] Parallel._print called
[2019-05-31 11:50:32,181] [9/MainThread] [INFO] [joblib.parallel] [Parallel(n_jobs=-1)]: Using backend DaskDistributedBackend with 24 concurrent workers.

[2019-05-31 11:50:32,182] [9/MainThread] [INFO] [joblib.dask] DaskDistributedBackend.start_call called from __call__
[2019-05-31 11:50:32,182] [9/MainThread] [INFO] [joblib.parallel] Parallel.__call__: iterator created
[2019-05-31 11:50:32,182] [9/MainThread] [INFO] [joblib.parallel] <generator object BaseSearchCV.fit.<locals>.evaluate_candidates.<locals>.<genexpr> at 0x7fc3344c5d00>
[2019-05-31 11:50:32,182] [9/MainThread] [INFO] [joblib.parallel] Parallel.dispatch_one_batch called from __call__
[2019-05-31 11:50:32,182] [9/MainThread] [INFO] [joblib.parallel] Parallel.dispatch_one_batch: took the lock
[2019-05-31 11:50:32,183] [9/MainThread] [INFO] [joblib.dask] DaskDistributedBackend.get_nested_backend called from dispatch_one_batch
[2019-05-31 11:50:32,183] [9/MainThread] [INFO] [joblib.dask] DaskDistributedBackend.__init__ called from get_nested_backend
[2019-05-31 11:50:32,183] [9/MainThread] [INFO] [joblib.parallel] BatchedCalls.__init__ called
[2019-05-31 11:50:32,184] [9/MainThread] [INFO] [joblib.parallel] delayed called
[2019-05-31 11:50:32,184] [9/MainThread] [INFO] [joblib.parallel] BatchedCalls.__init__ : wraps 1 objects
[2019-05-31 11:50:32,184] [9/MainThread] [INFO] [joblib.parallel] BatchedCalls.__init__: pickle cache: {}
[2019-05-31 11:50:32,184] [9/MainThread] [INFO] [joblib.parallel] Parallel.dispatch: calling self._dispatch
[2019-05-31 11:50:32,184] [9/MainThread] [INFO] [joblib.parallel] Parallel._dispatch called from dispatch_one_batch
[2019-05-31 11:50:32,185] [9/MainThread] [INFO] [joblib.parallel] BatchCompletionCallBack.__init__ called
[2019-05-31 11:50:32,185] [9/MainThread] [INFO] [joblib.parallel] Parallel._dispatch: taking the lock
[2019-05-31 11:50:32,185] [9/MainThread] [INFO] [joblib.parallel] Parallel._dispatch: took the lock
[2019-05-31 11:50:32,185] [9/MainThread] [INFO] [joblib.parallel] Parallel._dispatch: submitting job of id 0 to back-end of size 1
[2019-05-31 11:50:32,185] [9/MainThread] [INFO] [joblib.dask] DaskDistributedBackend.apply_async called from _dispatch
[2019-05-31 11:50:32,185] [9/MainThread] [INFO] [joblib.dask] DaskDistributedBackend._to_func_args called from apply_async
[2019-05-31 11:50:32,186] [9/MainThread] [INFO] [joblib.dask] DaskDistributedBackend._to_func_args: Looping on func.items of len=1
[2019-05-31 11:50:32,186] [9/MainThread] [INFO] [joblib.dask] f: <function _fit_and_score at 0x7fc33e84c598>
[2019-05-31 11:50:32,186] [9/MainThread] [INFO] [joblib.dask] DaskDistributedBackend._to_func_args.maybe_to_future: scatter to Client
[2019-05-31 11:50:32,186] [9/MainThread] [INFO] [root] Client.scatter called from maybe_to_futures
[2019-05-31 11:50:32,189] [9/IO loop] [INFO] [root] Client._scatter called from wrapper
[2019-05-31 11:50:32,190] [9/IO loop] [INFO] [root] Worker.get_worker called
[2019-05-31 11:50:32,198] [9/Thread-1] [INFO] [root] Scheduler.scatter called from wrapper
[2019-05-31 11:50:32,359] [9/Thread-1] [INFO] [root] Scheduler.update_data called from scatter
[2019-05-31 11:50:32,360] [9/Thread-1] [INFO] [root] Scheduler.report called from update_data
[2019-05-31 11:50:32,361] [9/Thread-1] [INFO] [root] Scheduler.report_on_key called from client_desires_keys
[2019-05-31 11:50:32,362] [9/Thread-1] [INFO] [root] Scheduler.report called from report_on_key
[2019-05-31 11:50:32,366] [9/MainThread] [INFO] [joblib.dask] DaskDistributedBackend._to_func_args.maybe_to_future: scatter to Client
[2019-05-31 11:50:32,367] [9/MainThread] [INFO] [root] Client.scatter called from maybe_to_futures
[2019-05-31 11:50:32,369] [9/IO loop] [INFO] [root] Client._scatter called from wrapper
[2019-05-31 11:50:32,370] [9/IO loop] [INFO] [root] Worker.get_worker called
[2019-05-31 11:50:32,373] [9/Thread-1] [INFO] [root] Scheduler.scatter called from wrapper
[2019-05-31 11:50:32,378] [9/Thread-1] [INFO] [root] Scheduler.update_data called from scatter
[2019-05-31 11:50:32,379] [9/Thread-1] [INFO] [root] Scheduler.report called from update_data
[2019-05-31 11:50:32,379] [9/Thread-1] [INFO] [root] Scheduler.report_on_key called from client_desires_keys
[2019-05-31 11:50:32,380] [9/Thread-1] [INFO] [root] Scheduler.report called from report_on_key
[2019-05-31 11:50:32,384] [9/MainThread] [INFO] [joblib.dask] DaskDistributedBackend._to_func_args.maybe_to_future: scatter to Client
[2019-05-31 11:50:32,385] [9/MainThread] [INFO] [root] Client.scatter called from maybe_to_futures
[2019-05-31 11:50:32,387] [9/IO loop] [INFO] [root] Client._scatter called from wrapper
[2019-05-31 11:50:32,387] [9/IO loop] [INFO] [root] Worker.get_worker called
[2019-05-31 11:50:32,391] [9/Thread-1] [INFO] [root] Scheduler.scatter called from wrapper
[2019-05-31 11:50:32,397] [9/Thread-1] [INFO] [root] Scheduler.update_data called from scatter
[2019-05-31 11:50:32,399] [9/Thread-1] [INFO] [root] Scheduler.report called from update_data
[2019-05-31 11:50:32,399] [9/Thread-1] [INFO] [root] Scheduler.report_on_key called from client_desires_keys
[2019-05-31 11:50:32,400] [9/Thread-1] [INFO] [root] Scheduler.report called from report_on_key
[2019-05-31 11:50:32,405] [9/MainThread] [INFO] [joblib.dask] DaskDistributedBackend._to_func_args.maybe_to_future: scatter to Client
[2019-05-31 11:50:32,405] [9/MainThread] [INFO] [root] Client.scatter called from maybe_to_futures
[2019-05-31 11:50:32,407] [9/IO loop] [INFO] [root] Client._scatter called from wrapper
[2019-05-31 11:50:32,408] [9/IO loop] [INFO] [root] Worker.get_worker called
[2019-05-31 11:50:32,411] [9/Thread-1] [INFO] [root] Scheduler.scatter called from wrapper
[2019-05-31 11:50:32,417] [9/Thread-1] [INFO] [root] Scheduler.update_data called from scatter
[2019-05-31 11:50:32,418] [9/Thread-1] [INFO] [root] Scheduler.report called from update_data
[2019-05-31 11:50:32,419] [9/Thread-1] [INFO] [root] Scheduler.report_on_key called from client_desires_keys
[2019-05-31 11:50:32,420] [9/Thread-1] [INFO] [root] Scheduler.report called from report_on_key
[2019-05-31 11:50:32,423] [9/MainThread] [INFO] [joblib.dask] DaskDistributedBackend._to_func_args: appending tasks done
[2019-05-31 11:50:32,424] [9/MainThread] [INFO] [joblib.dask] Batch.__init__ called from _to_func_args
[2019-05-31 11:50:32,424] [9/MainThread] [INFO] [joblib.dask] DaskDistributedBackend.apply_async: Submitting to Client
[2019-05-31 11:50:32,425] [9/MainThread] [INFO] [root] Client.submit called from apply_async
[2019-05-31 11:50:32,426] [9/MainThread] [INFO] [root] Client._graph_to_futures called from submit
[2019-05-31 11:50:32,426] [9/MainThread] [INFO] [joblib.dask] Batch.__reduce__ called
[2019-05-31 11:50:32,427] [9/MainThread] [INFO] [root] Client._send_to_scheduler called from _graph_to_futures
[2019-05-31 11:50:32,427] [9/MainThread] [INFO] [joblib.dask] DaskDistributedBackend.apply_async: Done submitting to the Client
[2019-05-31 11:50:32,428] [9/MainThread] [INFO] [joblib.dask] DaskDistributedBackend.apply_async: Added future to tasks
[2019-05-31 11:50:32,428] [9/MainThread] [INFO] [joblib.dask] <Future: status: pending, key: _fit_and_score-batch-dd498349a1d8484d97152230e388f65f>
[2019-05-31 11:50:32,429] [9/IO loop] [INFO] [root] Client._send_to_scheduler_safe called from null_wrapper
[2019-05-31 11:50:32,429] [9/MainThread] [INFO] [joblib.dask] DaskDistributedBackend.apply_async: Returning future
[2019-05-31 11:50:32,430] [9/MainThread] [INFO] [joblib.dask] <Future: status: pending, key: _fit_and_score-batch-dd498349a1d8484d97152230e388f65f>
[2019-05-31 11:50:32,430] [9/MainThread] [INFO] [joblib.parallel] Parallel._dispatch: job of id 0 inserted to back-end
[2019-05-31 11:50:32,430] [9/MainThread] [INFO] [joblib.parallel] Parallel._dispatch: leaving the lock
[2019-05-31 11:50:32,430] [9/MainThread] [INFO] [joblib.parallel] Parallel._dispatch: left the lock
[2019-05-31 11:50:32,430] [9/MainThread] [INFO] [joblib.parallel] Parallel.dispatch_one_batch: leaving the lock after self._dispatch
[2019-05-31 11:50:32,430] [9/MainThread] [INFO] [joblib.parallel] Parallel.dispatch_one_batch: left the lock
[2019-05-31 11:50:32,430] [9/MainThread] [INFO] [joblib.parallel] Parallel.__call__ dispatched initial batch
[2019-05-31 11:50:32,431] [9/IO loop] [INFO] [joblib.dask] DaskDistributedBackend.apply_async: Executing callback_wrapper ; called from wrapper
[2019-05-31 11:50:32,432] [9/MainThread] [INFO] [joblib.parallel] Parallel.dispatch_one_batch called from __call__
[2019-05-31 11:50:32,433] [9/MainThread] [INFO] [joblib.parallel] Parallel.dispatch_one_batch: took the lock
[2019-05-31 11:50:32,435] [9/Thread-1] [INFO] [root] Server.handle_long_running: got 1 messages
[2019-05-31 11:50:32,435] [9/Thread-1] [INFO] [root] Server.handle_long_running: message: {'op': 'update-graph', 'tasks': {'_fit_and_score-batch-dd498349a1d8484d97152230e388f65f': {'function': b'\x80\x04\x95\x03\x03\x00\x00\x00\x00\x00\x00\x8c\x0cjoblib._dask\x94\x8c\x05Batch\x94\x93\x94]\x94\x8c#sklearn.model_selection._validation\x94\x8c\x0e_fit_and_score\x94\x93\x94]\x94(\x8c\x11sklearn.tree.tree\x94\x8c\x15DecisionTreeRegressor\x94\x93\x94)\x81\x94}\x94(\x8c\tcriterion\x94\x8c\x03mse\x94\x8c\x08splitter\x94\x8c\x04best\x94\x8c\tmax_depth\x94N\x8c\x11min_samples_split\x94K\x02\x8c\x10min_samples_leaf\x94K\x01\x8c\x18min_weight_fraction_leaf\x94G\x00\x00\x00\x00\x00\x00\x00\x00\x8c\x0cmax_features\x94N\x8c\x0crandom_state\x94N\x8c\x0emax_leaf_nodes\x94N\x8c\x15min_impurity_decrease\x94G\x00\x00\x00\x00\x00\x00\x00\x00\x8c\x12min_impurity_split\x94N\x8c\x0cclass_weight\x94N\x8c\x07presort\x94\x89\x8c\x10_sklearn_version\x94\x8c\x060.20.3\x94ub\x8c\x11distributed.utils\x94\x8c\nitemgetter\x94\x93\x94K\x00\x85\x94R\x94h K\x01\x85\x94R\x94e}\x94(\x8c\x05train\x94h K\x02\x85\x94R\x94\x8c\x04test\x94h K\x03\x85\x94R\x94\x8c\nparameters\x94}\x94(h\x11K\nh\x13K\x01h\x12K\x02u\x8c\x06scorer\x94}\x94\x8c\x05score\x94\x8c\x16sklearn.metrics.scorer\x94\x8c\x13_passthrough_scorer\x94\x93\x94s\x8c\nfit_params\x94}\x94\x8c\x12return_train_score\x94\x8c\x04warn\x94\x8c\x15return_n_test_samples\x94\x88\x8c\x0creturn_times\x94\x88\x8c\x11return_parameters\x94\x89\x8c\x0berror_score\x94\x8c\x11raise-deprecating\x94\x8c\x07verbose\x94K\x00u\x87\x94a\x85\x94R\x94.', 'args': b'\x80\x04\x95\xb0\x00\x00\x00\x00\x00\x00\x00(\x8c(ndarray-fb4f174bb1e813722d61df6188b5f028\x94\x8c(ndarray-0e249125e0dbd98c1c526e3c9b0b3395\x94\x8c(ndarray-c65639aba94c107b0729630e1e2b6118\x94\x8c(ndarray-88ba704ce4c44b71d81a35cec23b06b5\x94t\x94.'}}, 'dependencies': {'_fit_and_score-batch-dd498349a1d8484d97152230e388f65f': ('ndarray-0e249125e0dbd98c1c526e3c9b0b3395', 'ndarray-c65639aba94c107b0729630e1e2b6118', 'ndarray-fb4f174bb1e813722d61df6188b5f028', 'ndarray-88ba704ce4c44b71d81a35cec23b06b5')}, 'keys': ('_fit_and_score-batch-dd498349a1d8484d97152230e388f65f',), 'restrictions': {}, 'loose_restrictions': (), 'priority': {'_fit_and_score-batch-dd498349a1d8484d97152230e388f65f': 0}, 'user_priority': 0, 'resources': None, 'submitting_task': None, 'retries': None, 'fifo_timeout': '100ms', 'actors': False}
[2019-05-31 11:50:32,436] [9/Thread-1] [INFO] [root] Scheduler.__repr__ called from handle_stream
[2019-05-31 11:50:32,437] [9/Thread-1] [INFO] [root] Server.handle_long_running: Using handler <bound method Scheduler.update_graph of <Scheduler: "tcp://10.12.3.241:8786" processes: 3 cores: 24>>
[2019-05-31 11:50:32,438] [9/MainThread] [INFO] [joblib.dask] DaskDistributedBackend.get_nested_backend called from dispatch_one_batch
[2019-05-31 11:50:32,440] [9/MainThread] [INFO] [joblib.dask] DaskDistributedBackend.__init__ called from get_nested_backend
[2019-05-31 11:50:32,440] [9/MainThread] [INFO] [joblib.parallel] BatchedCalls.__init__ called
[2019-05-31 11:50:32,441] [9/MainThread] [INFO] [joblib.parallel] delayed called
[2019-05-31 11:50:32,441] [9/MainThread] [INFO] [joblib.parallel] BatchedCalls.__init__ : wraps 1 objects
[2019-05-31 11:50:32,441] [9/MainThread] [INFO] [joblib.parallel] BatchedCalls.__init__: pickle cache: {}
[2019-05-31 11:50:32,441] [9/MainThread] [INFO] [joblib.parallel] Parallel.dispatch: calling self._dispatch
[2019-05-31 11:50:32,442] [9/Thread-1] [INFO] [root] Scheduler.update_graph called from handle_stream
[2019-05-31 11:50:32,443] [9/MainThread] [INFO] [joblib.parallel] Parallel._dispatch called from dispatch_one_batch
[2019-05-31 11:50:32,443] [9/MainThread] [INFO] [joblib.parallel] BatchCompletionCallBack.__init__ called
[2019-05-31 11:50:32,444] [9/MainThread] [INFO] [joblib.parallel] Parallel._dispatch: taking the lock
[2019-05-31 11:50:32,444] [9/MainThread] [INFO] [joblib.parallel] Parallel._dispatch: took the lock
[2019-05-31 11:50:32,444] [9/MainThread] [INFO] [joblib.parallel] Parallel._dispatch: submitting job of id 1 to back-end of size 1
[2019-05-31 11:50:32,446] [9/Thread-1] [INFO] [root] Scheduler.transitions called from update_graph
[2019-05-31 11:50:32,447] [9/MainThread] [INFO] [joblib.dask] DaskDistributedBackend.apply_async called from _dispatch
[2019-05-31 11:50:32,448] [9/MainThread] [INFO] [joblib.dask] DaskDistributedBackend._to_func_args called from apply_async
[2019-05-31 11:50:32,449] [9/Thread-1] [INFO] [root] Scheduler.decide_worker called from transition_waiting_processing
[2019-05-31 11:50:32,450] [9/MainThread] [INFO] [joblib.dask] DaskDistributedBackend._to_func_args: Looping on func.items of len=1
[2019-05-31 11:50:32,450] [9/MainThread] [INFO] [joblib.dask] f: <function _fit_and_score at 0x7fc33e84c598>
[2019-05-31 11:50:32,451] [9/MainThread] [INFO] [joblib.dask] DaskDistributedBackend._to_func_args.maybe_to_future: scatter to Client
[2019-05-31 11:50:32,453] [9/Thread-1] [INFO] [root] Scheduler.valid_workers called from decide_worker
[2019-05-31 11:50:32,455] [9/Thread-1] [INFO] [root] Scheduler.decide_worker called from decide_worker
[2019-05-31 11:50:32,456] [9/Thread-1] [INFO] [root] Scheduler.consumre_resources called from transition_waiting_processing
[2019-05-31 11:50:32,457] [9/Thread-1] [INFO] [root] [711f3377-8adf-4162-82e1-e0704b52c5d9] Scheduler.check_idle_saturated called from transition_waiting_processing
[2019-05-31 11:50:32,457] [9/Thread-1] [INFO] [root] [711f3377-8adf-4162-82e1-e0704b52c5d9] ws  = tcp://10.12.2.24:39495
[2019-05-31 11:50:32,457] [9/Thread-1] [INFO] [root] [711f3377-8adf-4162-82e1-e0704b52c5d9] occ = 0.5
[2019-05-31 11:50:32,457] [9/Thread-1] [INFO] [root] [711f3377-8adf-4162-82e1-e0704b52c5d9] nc  = 8
[2019-05-31 11:50:32,457] [9/Thread-1] [INFO] [root] [711f3377-8adf-4162-82e1-e0704b52c5d9] p   = 1
[2019-05-31 11:50:32,458] [9/Thread-1] [INFO] [root] [711f3377-8adf-4162-82e1-e0704b52c5d9] avg = 0.020833333333333332
[2019-05-31 11:50:32,458] [9/Thread-1] [INFO] [root] [711f3377-8adf-4162-82e1-e0704b52c5d9] tcp://10.12.2.24:39495 idle ; not saturated
[2019-05-31 11:50:32,459] [9/Thread-1] [INFO] [root] Scheduler.send_task_to_worker called from transition_waiting_processing
[2019-05-31 11:50:32,460] [9/MainThread] [INFO] [root] Client.scatter called from maybe_to_futures
[2019-05-31 11:50:32,465] [9/Thread-1] [INFO] [root] Scheduler.worker_send called from send_task_to_worker
[2019-05-31 11:50:32,468] [9/IO loop] [INFO] [root] Client._scatter called from wrapper
[2019-05-31 11:50:32,469] [9/IO loop] [INFO] [root] Worker.get_worker called
[2019-05-31 11:50:32,471] [9/Thread-1] [INFO] [root] Scheduler.report_on_key called from update_graph
[2019-05-31 11:50:32,473] [9/Thread-1] [INFO] [root] Scheduler.report called from report_on_key
[2019-05-31 11:50:32,474] [9/Thread-1] [INFO] [root] Scheduler.report_on_key called from update_graph
[2019-05-31 11:50:32,474] [9/Thread-1] [INFO] [root] Scheduler.report called from report_on_key
[2019-05-31 11:50:32,475] [9/Thread-1] [INFO] [root] Scheduler.report_on_key called from update_graph
[2019-05-31 11:50:32,476] [9/Thread-1] [INFO] [root] Scheduler.report called from report_on_key
[2019-05-31 11:50:32,476] [9/Thread-1] [INFO] [root] Scheduler.report_on_key called from update_graph
[2019-05-31 11:50:32,477] [9/Thread-1] [INFO] [root] Scheduler.report called from report_on_key
[2019-05-31 11:50:32,477] [9/Thread-1] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:50:32,480] [9/Thread-1] [INFO] [root] Scheduler.scatter called from wrapper
[2019-05-31 11:50:32,603] [9/Thread-1] [INFO] [root] [82843896-094f-4e4c-976d-f9fa00b1d58f] Scheduler.check_idle_saturated called from _reevaluate_occupancy_worker
[2019-05-31 11:50:32,604] [9/Thread-1] [INFO] [root] [82843896-094f-4e4c-976d-f9fa00b1d58f] ws  = tcp://10.12.2.24:39495
[2019-05-31 11:50:32,604] [9/Thread-1] [INFO] [root] [82843896-094f-4e4c-976d-f9fa00b1d58f] occ = 0.5
[2019-05-31 11:50:32,604] [9/Thread-1] [INFO] [root] [82843896-094f-4e4c-976d-f9fa00b1d58f] nc  = 8
[2019-05-31 11:50:32,604] [9/Thread-1] [INFO] [root] [82843896-094f-4e4c-976d-f9fa00b1d58f] p   = 1
[2019-05-31 11:50:32,604] [9/Thread-1] [INFO] [root] [82843896-094f-4e4c-976d-f9fa00b1d58f] avg = 0.020833333333333332
[2019-05-31 11:50:32,604] [9/Thread-1] [INFO] [root] [82843896-094f-4e4c-976d-f9fa00b1d58f] tcp://10.12.2.24:39495 idle ; not saturated
[2019-05-31 11:50:32,706] [9/Thread-1] [INFO] [root] [ada24442-9a56-41f7-adb4-24c5ce25c37a] Scheduler.check_idle_saturated called from _reevaluate_occupancy_worker
[2019-05-31 11:50:32,706] [9/Thread-1] [INFO] [root] [ada24442-9a56-41f7-adb4-24c5ce25c37a] ws  = tcp://10.12.2.24:39495
[2019-05-31 11:50:32,706] [9/Thread-1] [INFO] [root] [ada24442-9a56-41f7-adb4-24c5ce25c37a] occ = 0.5
[2019-05-31 11:50:32,706] [9/Thread-1] [INFO] [root] [ada24442-9a56-41f7-adb4-24c5ce25c37a] nc  = 8
[2019-05-31 11:50:32,706] [9/Thread-1] [INFO] [root] [ada24442-9a56-41f7-adb4-24c5ce25c37a] p   = 1
[2019-05-31 11:50:32,706] [9/Thread-1] [INFO] [root] [ada24442-9a56-41f7-adb4-24c5ce25c37a] avg = 0.020833333333333332
[2019-05-31 11:50:32,706] [9/Thread-1] [INFO] [root] [ada24442-9a56-41f7-adb4-24c5ce25c37a] tcp://10.12.2.24:39495 idle ; not saturated
[2019-05-31 11:50:32,809] [9/Thread-1] [INFO] [root] [cca289ea-d72c-4ea5-8e64-e640dfc90cb0] Scheduler.check_idle_saturated called from _reevaluate_occupancy_worker
[2019-05-31 11:50:32,809] [9/Thread-1] [INFO] [root] [cca289ea-d72c-4ea5-8e64-e640dfc90cb0] ws  = tcp://10.12.2.24:39495
[2019-05-31 11:50:32,809] [9/Thread-1] [INFO] [root] [cca289ea-d72c-4ea5-8e64-e640dfc90cb0] occ = 0.5
[2019-05-31 11:50:32,809] [9/Thread-1] [INFO] [root] [cca289ea-d72c-4ea5-8e64-e640dfc90cb0] nc  = 8
[2019-05-31 11:50:32,810] [9/Thread-1] [INFO] [root] [cca289ea-d72c-4ea5-8e64-e640dfc90cb0] p   = 1
[2019-05-31 11:50:32,810] [9/Thread-1] [INFO] [root] [cca289ea-d72c-4ea5-8e64-e640dfc90cb0] avg = 0.020833333333333332
[2019-05-31 11:50:32,810] [9/Thread-1] [INFO] [root] [cca289ea-d72c-4ea5-8e64-e640dfc90cb0] tcp://10.12.2.24:39495 idle ; not saturated
[2019-05-31 11:50:32,913] [9/Thread-1] [INFO] [root] [8d91efc3-d4a2-4b03-8226-fe4cb5b3f025] Scheduler.check_idle_saturated called from _reevaluate_occupancy_worker
[2019-05-31 11:50:32,913] [9/Thread-1] [INFO] [root] [8d91efc3-d4a2-4b03-8226-fe4cb5b3f025] ws  = tcp://10.12.2.24:39495
[2019-05-31 11:50:32,913] [9/Thread-1] [INFO] [root] [8d91efc3-d4a2-4b03-8226-fe4cb5b3f025] occ = 0.5
[2019-05-31 11:50:32,913] [9/Thread-1] [INFO] [root] [8d91efc3-d4a2-4b03-8226-fe4cb5b3f025] nc  = 8
[2019-05-31 11:50:32,913] [9/Thread-1] [INFO] [root] [8d91efc3-d4a2-4b03-8226-fe4cb5b3f025] p   = 1
[2019-05-31 11:50:32,913] [9/Thread-1] [INFO] [root] [8d91efc3-d4a2-4b03-8226-fe4cb5b3f025] avg = 0.020833333333333332
[2019-05-31 11:50:32,913] [9/Thread-1] [INFO] [root] [8d91efc3-d4a2-4b03-8226-fe4cb5b3f025] tcp://10.12.2.24:39495 idle ; not saturated
[2019-05-31 11:50:32,945] [9/Thread-1] [INFO] [root] Scheduler.update_data called from scatter
[2019-05-31 11:50:32,946] [9/Thread-1] [INFO] [root] Scheduler.report called from update_data
[2019-05-31 11:50:32,947] [9/Thread-1] [INFO] [root] Scheduler.report_on_key called from client_desires_keys
[2019-05-31 11:50:32,948] [9/Thread-1] [INFO] [root] Scheduler.report called from report_on_key
[2019-05-31 11:50:32,953] [9/MainThread] [INFO] [joblib.dask] DaskDistributedBackend._to_func_args.maybe_to_future: scatter to Client
[2019-05-31 11:50:32,954] [9/MainThread] [INFO] [root] Client.scatter called from maybe_to_futures
[2019-05-31 11:50:32,956] [9/IO loop] [INFO] [root] Client._scatter called from wrapper
[2019-05-31 11:50:32,957] [9/IO loop] [INFO] [root] Worker.get_worker called
[2019-05-31 11:50:32,960] [9/Thread-1] [INFO] [root] Scheduler.scatter called from wrapper
[2019-05-31 11:50:32,970] [9/Thread-1] [INFO] [root] Scheduler.update_data called from scatter
[2019-05-31 11:50:32,971] [9/Thread-1] [INFO] [root] Scheduler.report called from update_data
[2019-05-31 11:50:32,972] [9/Thread-1] [INFO] [root] Scheduler.report_on_key called from client_desires_keys
[2019-05-31 11:50:32,973] [9/Thread-1] [INFO] [root] Scheduler.report called from report_on_key
[2019-05-31 11:50:32,980] [9/MainThread] [INFO] [joblib.dask] DaskDistributedBackend._to_func_args: appending tasks done
[2019-05-31 11:50:32,983] [9/MainThread] [INFO] [joblib.dask] Batch.__init__ called from _to_func_args
[2019-05-31 11:50:32,983] [9/MainThread] [INFO] [joblib.dask] DaskDistributedBackend.apply_async: Submitting to Client
[2019-05-31 11:50:32,985] [9/Thread-1] [INFO] [root] Scheduler.add_client called from wrapper
[2019-05-31 11:50:32,985] [9/Thread-1] [INFO] [root] Receive client connection: Client-worker-4bb02946-839a-11e9-800a-0a580a0c0218
[2019-05-31 11:50:32,986] [9/MainThread] [INFO] [root] Client.submit called from apply_async
[2019-05-31 11:50:32,989] [9/MainThread] [INFO] [root] Client._graph_to_futures called from submit
[2019-05-31 11:50:32,989] [9/MainThread] [INFO] [joblib.dask] Batch.__reduce__ called
[2019-05-31 11:50:32,990] [9/Thread-1] [INFO] [root] Server.handle_long_running called from wrapper
[2019-05-31 11:50:32,990] [9/Thread-1] [INFO] [root] Server.handle_long_running arguments
[2019-05-31 11:50:32,991] [9/Thread-1] [INFO] [root] caller_name ; id: 140477619307328 ; type: <class 'str'> ; value: wrapper
[2019-05-31 11:50:32,991] [9/Thread-1] [INFO] [root] every_cycle ; id: 140477187880776 ; type: <class 'list'> ; value: []
[2019-05-31 11:50:32,991] [9/Thread-1] [INFO] [root] extra ; id: 140476372263056 ; type: <class 'dict'> ; value: {'client': 'Client-worker-4bb02946-839a-11e9-800a-0a580a0c0218'}
[2019-05-31 11:50:32,991] [9/Thread-1] [INFO] [root] comm ; id: 140476372687280 ; type: <class 'distributed.comm.tcp.TCP'> ; value: <TCP Scheduler->Client local=tcp://10.12.3.241:8786 remote=tcp://10.12.2.24:46160>
[2019-05-31 11:50:32,993] [9/MainThread] [INFO] [root] Client._send_to_scheduler called from _graph_to_futures
[2019-05-31 11:50:32,993] [9/MainThread] [INFO] [joblib.dask] DaskDistributedBackend.apply_async: Done submitting to the Client
[2019-05-31 11:50:32,993] [9/MainThread] [INFO] [joblib.dask] DaskDistributedBackend.apply_async: Added future to tasks
[2019-05-31 11:50:32,994] [9/MainThread] [INFO] [joblib.dask] <Future: status: pending, key: _fit_and_score-batch-8fd23376feca4ad3816bb4ff43023ca9>
[2019-05-31 11:50:32,994] [9/MainThread] [INFO] [joblib.dask] DaskDistributedBackend.apply_async: Returning future
[2019-05-31 11:50:32,994] [9/MainThread] [INFO] [joblib.dask] <Future: status: pending, key: _fit_and_score-batch-8fd23376feca4ad3816bb4ff43023ca9>
[2019-05-31 11:50:32,994] [9/MainThread] [INFO] [joblib.parallel] Parallel._dispatch: job of id 1 inserted to back-end
[2019-05-31 11:50:32,995] [9/MainThread] [INFO] [joblib.parallel] Parallel._dispatch: leaving the lock
[2019-05-31 11:50:32,995] [9/MainThread] [INFO] [joblib.parallel] Parallel._dispatch: left the lock
[2019-05-31 11:50:32,996] [9/MainThread] [INFO] [joblib.parallel] Parallel.dispatch_one_batch: leaving the lock after self._dispatch
[2019-05-31 11:50:32,996] [9/MainThread] [INFO] [joblib.parallel] Parallel.dispatch_one_batch: left the lock
[2019-05-31 11:50:32,996] [9/MainThread] [INFO] [joblib.parallel] Parallel.__call__ dispatched one batch
[2019-05-31 11:50:32,998] [9/Thread-1] [INFO] [root] Scheduler.__repr__ called from handle_stream
[2019-05-31 11:50:32,998] [9/Thread-1] [INFO] [root] self ; id: 140476527270992 ; type: <class 'distributed.scheduler.Scheduler'> ; value: <Scheduler: "tcp://10.12.3.241:8786" processes: 3 cores: 24>
[2019-05-31 11:50:32,998] [9/Thread-1] [INFO] [root] Server.handle_long_running: Starting established connection
[2019-05-31 11:50:32,998] [9/Thread-1] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:50:33,001] [9/MainThread] [INFO] [joblib.parallel] Parallel.dispatch_one_batch called from __call__
[2019-05-31 11:50:33,001] [9/MainThread] [INFO] [joblib.parallel] Parallel.dispatch_one_batch: took the lock
[2019-05-31 11:50:33,003] [9/IO loop] [INFO] [root] Client._send_to_scheduler_safe called from null_wrapper
[2019-05-31 11:50:33,005] [9/MainThread] [INFO] [joblib.dask] DaskDistributedBackend.get_nested_backend called from dispatch_one_batch
[2019-05-31 11:50:33,007] [9/IO loop] [INFO] [joblib.dask] DaskDistributedBackend.apply_async: Executing callback_wrapper ; called from wrapper
[2019-05-31 11:50:33,009] [9/Thread-1] [INFO] [root] Server.handle_long_running: got 1 messages
[2019-05-31 11:50:33,009] [9/Thread-1] [INFO] [root] Server.handle_long_running: message: {'op': 'update-graph', 'tasks': {'_fit_and_score-batch-8fd23376feca4ad3816bb4ff43023ca9': {'function': b'\x80\x04\x95\x03\x03\x00\x00\x00\x00\x00\x00\x8c\x0cjoblib._dask\x94\x8c\x05Batch\x94\x93\x94]\x94\x8c#sklearn.model_selection._validation\x94\x8c\x0e_fit_and_score\x94\x93\x94]\x94(\x8c\x11sklearn.tree.tree\x94\x8c\x15DecisionTreeRegressor\x94\x93\x94)\x81\x94}\x94(\x8c\tcriterion\x94\x8c\x03mse\x94\x8c\x08splitter\x94\x8c\x04best\x94\x8c\tmax_depth\x94N\x8c\x11min_samples_split\x94K\x02\x8c\x10min_samples_leaf\x94K\x01\x8c\x18min_weight_fraction_leaf\x94G\x00\x00\x00\x00\x00\x00\x00\x00\x8c\x0cmax_features\x94N\x8c\x0crandom_state\x94N\x8c\x0emax_leaf_nodes\x94N\x8c\x15min_impurity_decrease\x94G\x00\x00\x00\x00\x00\x00\x00\x00\x8c\x12min_impurity_split\x94N\x8c\x0cclass_weight\x94N\x8c\x07presort\x94\x89\x8c\x10_sklearn_version\x94\x8c\x060.20.3\x94ub\x8c\x11distributed.utils\x94\x8c\nitemgetter\x94\x93\x94K\x00\x85\x94R\x94h K\x01\x85\x94R\x94e}\x94(\x8c\x05train\x94h K\x02\x85\x94R\x94\x8c\x04test\x94h K\x03\x85\x94R\x94\x8c\nparameters\x94}\x94(h\x11K\nh\x13K\x01h\x12K\x02u\x8c\x06scorer\x94}\x94\x8c\x05score\x94\x8c\x16sklearn.metrics.scorer\x94\x8c\x13_passthrough_scorer\x94\x93\x94s\x8c\nfit_params\x94}\x94\x8c\x12return_train_score\x94\x8c\x04warn\x94\x8c\x15return_n_test_samples\x94\x88\x8c\x0creturn_times\x94\x88\x8c\x11return_parameters\x94\x89\x8c\x0berror_score\x94\x8c\x11raise-deprecating\x94\x8c\x07verbose\x94K\x00u\x87\x94a\x85\x94R\x94.', 'args': b'\x80\x04\x95\xb0\x00\x00\x00\x00\x00\x00\x00(\x8c(ndarray-fb4f174bb1e813722d61df6188b5f028\x94\x8c(ndarray-0e249125e0dbd98c1c526e3c9b0b3395\x94\x8c(ndarray-8b4383c9662f67a96fc16c9a5b3c048c\x94\x8c(ndarray-dfc19c3740a5958674f7a9e697457720\x94t\x94.'}}, 'dependencies': {'_fit_and_score-batch-8fd23376feca4ad3816bb4ff43023ca9': ('ndarray-0e249125e0dbd98c1c526e3c9b0b3395', 'ndarray-8b4383c9662f67a96fc16c9a5b3c048c', 'ndarray-fb4f174bb1e813722d61df6188b5f028', 'ndarray-dfc19c3740a5958674f7a9e697457720')}, 'keys': ('_fit_and_score-batch-8fd23376feca4ad3816bb4ff43023ca9',), 'restrictions': {}, 'loose_restrictions': (), 'priority': {'_fit_and_score-batch-8fd23376feca4ad3816bb4ff43023ca9': 0}, 'user_priority': 0, 'resources': None, 'submitting_task': None, 'retries': None, 'fifo_timeout': '100ms', 'actors': False}
[2019-05-31 11:50:33,011] [9/MainThread] [INFO] [joblib.dask] DaskDistributedBackend.__init__ called from get_nested_backend
[2019-05-31 11:50:33,011] [9/MainThread] [INFO] [joblib.parallel] BatchedCalls.__init__ called
[2019-05-31 11:50:33,011] [9/MainThread] [INFO] [joblib.parallel] delayed called
[2019-05-31 11:50:33,012] [9/MainThread] [INFO] [joblib.parallel] BatchedCalls.__init__ : wraps 1 objects
[2019-05-31 11:50:33,012] [9/MainThread] [INFO] [joblib.parallel] BatchedCalls.__init__: pickle cache: {}
[2019-05-31 11:50:33,012] [9/MainThread] [INFO] [joblib.parallel] Parallel.dispatch: calling self._dispatch
[2019-05-31 11:50:33,014] [9/MainThread] [INFO] [joblib.parallel] Parallel._dispatch called from dispatch_one_batch
[2019-05-31 11:50:33,014] [9/MainThread] [INFO] [joblib.parallel] BatchCompletionCallBack.__init__ called
[2019-05-31 11:50:33,014] [9/MainThread] [INFO] [joblib.parallel] Parallel._dispatch: taking the lock
[2019-05-31 11:50:33,014] [9/MainThread] [INFO] [joblib.parallel] Parallel._dispatch: took the lock
[2019-05-31 11:50:33,014] [9/MainThread] [INFO] [joblib.parallel] Parallel._dispatch: submitting job of id 2 to back-end of size 1
[2019-05-31 11:50:33,015] [9/Thread-1] [INFO] [root] Scheduler.__repr__ called from handle_stream
[2019-05-31 11:50:33,015] [9/Thread-1] [INFO] [root] Server.handle_long_running: Using handler <bound method Scheduler.update_graph of <Scheduler: "tcp://10.12.3.241:8786" processes: 3 cores: 24>>
[2019-05-31 11:50:33,017] [9/MainThread] [INFO] [joblib.dask] DaskDistributedBackend.apply_async called from _dispatch
[2019-05-31 11:50:33,019] [9/MainThread] [INFO] [joblib.dask] DaskDistributedBackend._to_func_args called from apply_async
[2019-05-31 11:50:33,020] [9/MainThread] [INFO] [joblib.dask] DaskDistributedBackend._to_func_args: Looping on func.items of len=1
[2019-05-31 11:50:33,020] [9/MainThread] [INFO] [joblib.dask] f: <function _fit_and_score at 0x7fc33e84c598>
[2019-05-31 11:50:33,020] [9/MainThread] [INFO] [joblib.dask] DaskDistributedBackend._to_func_args.maybe_to_future: scatter to Client
[2019-05-31 11:50:33,022] [9/Thread-1] [INFO] [root] Scheduler.update_graph called from handle_stream
[2019-05-31 11:50:33,024] [9/Thread-1] [INFO] [root] Scheduler.transitions called from update_graph
[2019-05-31 11:50:33,025] [9/MainThread] [INFO] [root] Client.scatter called from maybe_to_futures
[2019-05-31 11:50:33,029] [9/Thread-1] [INFO] [root] Scheduler.decide_worker called from transition_waiting_processing
[2019-05-31 11:50:33,034] [9/IO loop] [INFO] [root] Client._scatter called from wrapper
[2019-05-31 11:50:33,035] [9/IO loop] [INFO] [root] Worker.get_worker called
[2019-05-31 11:50:33,035] [9/Thread-1] [INFO] [root] Scheduler.valid_workers called from decide_worker
[2019-05-31 11:50:33,039] [9/Thread-1] [INFO] [root] Scheduler.decide_worker called from decide_worker
[2019-05-31 11:50:33,040] [9/Thread-1] [INFO] [root] Scheduler.consumre_resources called from transition_waiting_processing
[2019-05-31 11:50:33,041] [9/Thread-1] [INFO] [root] [393f691e-cc29-40bb-8227-786415bb09a2] Scheduler.check_idle_saturated called from transition_waiting_processing
[2019-05-31 11:50:33,041] [9/Thread-1] [INFO] [root] [393f691e-cc29-40bb-8227-786415bb09a2] ws  = tcp://10.12.2.24:39495
[2019-05-31 11:50:33,041] [9/Thread-1] [INFO] [root] [393f691e-cc29-40bb-8227-786415bb09a2] occ = 1.0
[2019-05-31 11:50:33,041] [9/Thread-1] [INFO] [root] [393f691e-cc29-40bb-8227-786415bb09a2] nc  = 8
[2019-05-31 11:50:33,041] [9/Thread-1] [INFO] [root] [393f691e-cc29-40bb-8227-786415bb09a2] p   = 2
[2019-05-31 11:50:33,042] [9/Thread-1] [INFO] [root] [393f691e-cc29-40bb-8227-786415bb09a2] avg = 0.041666666666666664
[2019-05-31 11:50:33,042] [9/Thread-1] [INFO] [root] [393f691e-cc29-40bb-8227-786415bb09a2] tcp://10.12.2.24:39495 idle ; not saturated
[2019-05-31 11:50:33,042] [9/Thread-1] [INFO] [root] Scheduler.send_task_to_worker called from transition_waiting_processing
[2019-05-31 11:50:33,043] [9/Thread-1] [INFO] [root] Scheduler.worker_send called from send_task_to_worker
[2019-05-31 11:50:33,044] [9/Thread-1] [INFO] [root] Scheduler.report_on_key called from update_graph
[2019-05-31 11:50:33,045] [9/Thread-1] [INFO] [root] Scheduler.report called from report_on_key
[2019-05-31 11:50:33,045] [9/Thread-1] [INFO] [root] Scheduler.report_on_key called from update_graph
[2019-05-31 11:50:33,046] [9/Thread-1] [INFO] [root] Scheduler.report called from report_on_key
[2019-05-31 11:50:33,047] [9/Thread-1] [INFO] [root] Scheduler.report_on_key called from update_graph
[2019-05-31 11:50:33,047] [9/Thread-1] [INFO] [root] Scheduler.report called from report_on_key
[2019-05-31 11:50:33,049] [9/Thread-1] [INFO] [root] Scheduler.report_on_key called from update_graph
[2019-05-31 11:50:33,049] [9/Thread-1] [INFO] [root] Scheduler.report called from report_on_key
[2019-05-31 11:50:33,049] [9/Thread-1] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:50:33,053] [9/Thread-1] [INFO] [root] Scheduler.scatter called from wrapper
[2019-05-31 11:50:33,054] [9/Thread-1] [INFO] [root] Server.handle_long_running: got 1 messages
[2019-05-31 11:50:33,054] [9/Thread-1] [INFO] [root] Server.handle_long_running: message: {'op': 'task-finished', 'status': 'OK', 'key': '_fit_and_score-batch-dd498349a1d8484d97152230e388f65f', 'nbytes': 764, 'thread': 140227596941056, 'type': b'\x80\x04\x95\x15\x00\x00\x00\x00\x00\x00\x00\x8c\x08builtins\x94\x8c\x04list\x94\x93\x94.', 'typename': 'builtins.list', 'startstops': (('deserialize', 1559303432.4844885, 1559303432.9343007), ('compute', 1559303432.9367857, 1559303433.039962))}
[2019-05-31 11:50:33,055] [9/Thread-1] [INFO] [root] Scheduler.__repr__ called from handle_stream
[2019-05-31 11:50:33,055] [9/Thread-1] [INFO] [root] Server.handle_long_running: Using handler <bound method Scheduler.handle_task_finished of <Scheduler: "tcp://10.12.3.241:8786" processes: 3 cores: 24>>
[2019-05-31 11:50:33,056] [9/Thread-1] [INFO] [root] Scheduler.handle_task_finished called from handle_stream
[2019-05-31 11:50:33,057] [9/Thread-1] [INFO] [root] Scheduler._remove_from_processing called from transition_processing_memory
[2019-05-31 11:50:33,057] [9/Thread-1] [INFO] [root] [838db46f-6b64-46d2-8f6e-278cee431319] Scheduler.check_idle_saturated called from _remove_from_processing
[2019-05-31 11:50:33,058] [9/Thread-1] [INFO] [root] [838db46f-6b64-46d2-8f6e-278cee431319] ws  = tcp://10.12.2.24:39495
[2019-05-31 11:50:33,058] [9/Thread-1] [INFO] [root] [838db46f-6b64-46d2-8f6e-278cee431319] occ = 0.10317635536193848
[2019-05-31 11:50:33,058] [9/Thread-1] [INFO] [root] [838db46f-6b64-46d2-8f6e-278cee431319] nc  = 8
[2019-05-31 11:50:33,058] [9/Thread-1] [INFO] [root] [838db46f-6b64-46d2-8f6e-278cee431319] p   = 1
[2019-05-31 11:50:33,058] [9/Thread-1] [INFO] [root] [838db46f-6b64-46d2-8f6e-278cee431319] avg = 0.0042990148067474365
[2019-05-31 11:50:33,058] [9/Thread-1] [INFO] [root] [838db46f-6b64-46d2-8f6e-278cee431319] tcp://10.12.2.24:39495 idle ; not saturated
[2019-05-31 11:50:33,059] [9/Thread-1] [INFO] [root] Scheduler.release_resources called from _remove_from_processing
[2019-05-31 11:50:33,060] [9/Thread-1] [INFO] [root] Scheduler._add_to_memory called from transition_processing_memory
[2019-05-31 11:50:33,061] [9/Thread-1] [INFO] [root] Scheduler.report called from _add_to_memory
[2019-05-31 11:50:33,062] [9/Thread-1] [INFO] [root] Scheduler.transitions called from handle_task_finished
[2019-05-31 11:50:33,062] [9/Thread-1] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:50:33,068] [9/IO loop] [INFO] [joblib.parallel] BatchCompletionCallBack.__call__ called
[2019-05-31 11:50:33,068] [9/IO loop] [INFO] [joblib.parallel] BatchCompletionCallBack.__call__: calling parallel._backend.batch_completed
[2019-05-31 11:50:33,069] [9/IO loop] [INFO] [joblib.parallel] BatchCompletionCallBack.__call__: calling parallel.print_progress
[2019-05-31 11:50:33,069] [9/IO loop] [INFO] [joblib.parallel] Parallel.print_progress called
[2019-05-31 11:50:33,069] [9/IO loop] [INFO] [joblib.parallel] BatchCompletionCallBack.__call__: taking the lock
[2019-05-31 11:50:33,072] [9/Thread-1] [INFO] [root] Scheduler.update_data called from scatter
[2019-05-31 11:50:33,073] [9/Thread-1] [INFO] [root] Scheduler.report called from update_data
[2019-05-31 11:50:33,074] [9/Thread-1] [INFO] [root] Scheduler.report_on_key called from client_desires_keys
[2019-05-31 11:50:33,075] [9/Thread-1] [INFO] [root] Scheduler.report called from report_on_key
[2019-05-31 11:50:33,108] [9/Thread-1] [INFO] [root] Server.handle_long_running: got 1 messages
[2019-05-31 11:50:33,109] [9/Thread-1] [INFO] [root] Server.handle_long_running: message: {'op': 'task-finished', 'status': 'OK', 'key': '_fit_and_score-batch-8fd23376feca4ad3816bb4ff43023ca9', 'nbytes': 764, 'thread': 140227587499776, 'type': b'\x80\x04\x95\x15\x00\x00\x00\x00\x00\x00\x00\x8c\x08builtins\x94\x8c\x04list\x94\x93\x94.', 'typename': 'builtins.list', 'startstops': (('compute', 1559303433.0698767, 1559303433.1075315),)}
[2019-05-31 11:50:33,109] [9/Thread-1] [INFO] [root] Scheduler.__repr__ called from handle_stream
[2019-05-31 11:50:33,110] [9/Thread-1] [INFO] [root] Server.handle_long_running: Using handler <bound method Scheduler.handle_task_finished of <Scheduler: "tcp://10.12.3.241:8786" processes: 3 cores: 24>>
[2019-05-31 11:50:33,111] [9/Thread-1] [INFO] [root] Scheduler.handle_task_finished called from handle_stream
[2019-05-31 11:50:33,112] [9/Thread-1] [INFO] [root] Scheduler._remove_from_processing called from transition_processing_memory
[2019-05-31 11:50:33,113] [9/Thread-1] [INFO] [root] [82706d7d-9fa8-4bad-80d2-77399c44d5f5] Scheduler.check_idle_saturated called from _remove_from_processing
[2019-05-31 11:50:33,113] [9/Thread-1] [INFO] [root] [82706d7d-9fa8-4bad-80d2-77399c44d5f5] ws  = tcp://10.12.2.24:39495
[2019-05-31 11:50:33,113] [9/Thread-1] [INFO] [root] [82706d7d-9fa8-4bad-80d2-77399c44d5f5] occ = 0
[2019-05-31 11:50:33,113] [9/Thread-1] [INFO] [root] [82706d7d-9fa8-4bad-80d2-77399c44d5f5] nc  = 8
[2019-05-31 11:50:33,113] [9/Thread-1] [INFO] [root] [82706d7d-9fa8-4bad-80d2-77399c44d5f5] p   = 0
[2019-05-31 11:50:33,113] [9/Thread-1] [INFO] [root] [82706d7d-9fa8-4bad-80d2-77399c44d5f5] avg = 0.0
[2019-05-31 11:50:33,113] [9/Thread-1] [INFO] [root] [82706d7d-9fa8-4bad-80d2-77399c44d5f5] tcp://10.12.2.24:39495 idle ; not saturated
[2019-05-31 11:50:33,114] [9/Thread-1] [INFO] [root] Scheduler.release_resources called from _remove_from_processing
[2019-05-31 11:50:33,114] [9/Thread-1] [INFO] [root] Scheduler._add_to_memory called from transition_processing_memory
[2019-05-31 11:50:33,115] [9/Thread-1] [INFO] [root] Scheduler.report called from _add_to_memory
[2019-05-31 11:50:33,116] [9/Thread-1] [INFO] [root] Scheduler.transitions called from handle_task_finished
[2019-05-31 11:50:33,116] [9/Thread-1] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:50:38,006] [9/Thread-1] [INFO] [root] Server.handle_long_running: got 1 messages
[2019-05-31 11:50:38,006] [9/Thread-1] [INFO] [root] Server.handle_long_running: message: {'op': 'heartbeat-client'}
[2019-05-31 11:50:38,007] [9/Thread-1] [INFO] [root] Scheduler.__repr__ called from handle_stream
[2019-05-31 11:50:38,008] [9/Thread-1] [INFO] [root] Server.handle_long_running: Using handler <bound method Scheduler.client_heartbeat of <Scheduler: "tcp://10.12.3.241:8786" processes: 3 cores: 24>>
[2019-05-31 11:50:38,008] [9/Thread-1] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:50:43,008] [9/Thread-1] [INFO] [root] Server.handle_long_running: got 1 messages
[2019-05-31 11:50:43,009] [9/Thread-1] [INFO] [root] Server.handle_long_running: message: {'op': 'heartbeat-client'}
[2019-05-31 11:50:43,010] [9/Thread-1] [INFO] [root] Scheduler.__repr__ called from handle_stream
[2019-05-31 11:50:43,011] [9/Thread-1] [INFO] [root] Server.handle_long_running: Using handler <bound method Scheduler.client_heartbeat of <Scheduler: "tcp://10.12.3.241:8786" processes: 3 cores: 24>>
[2019-05-31 11:50:43,011] [9/Thread-1] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:50:48,006] [9/Thread-1] [INFO] [root] Server.handle_long_running: got 1 messages
[2019-05-31 11:50:48,007] [9/Thread-1] [INFO] [root] Server.handle_long_running: message: {'op': 'heartbeat-client'}
[2019-05-31 11:50:48,008] [9/Thread-1] [INFO] [root] Scheduler.__repr__ called from handle_stream
[2019-05-31 11:50:48,008] [9/Thread-1] [INFO] [root] Server.handle_long_running: Using handler <bound method Scheduler.client_heartbeat of <Scheduler: "tcp://10.12.3.241:8786" processes: 3 cores: 24>>
[2019-05-31 11:50:48,008] [9/Thread-1] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:50:53,010] [9/Thread-1] [INFO] [root] Server.handle_long_running: got 1 messages
[2019-05-31 11:50:53,010] [9/Thread-1] [INFO] [root] Server.handle_long_running: message: {'op': 'heartbeat-client'}
[2019-05-31 11:50:53,012] [9/Thread-1] [INFO] [root] Scheduler.__repr__ called from handle_stream
[2019-05-31 11:50:53,012] [9/Thread-1] [INFO] [root] Server.handle_long_running: Using handler <bound method Scheduler.client_heartbeat of <Scheduler: "tcp://10.12.3.241:8786" processes: 3 cores: 24>>
[2019-05-31 11:50:53,012] [9/Thread-1] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:50:58,006] [9/Thread-1] [INFO] [root] Server.handle_long_running: got 1 messages
[2019-05-31 11:50:58,006] [9/Thread-1] [INFO] [root] Server.handle_long_running: message: {'op': 'heartbeat-client'}
[2019-05-31 11:50:58,007] [9/Thread-1] [INFO] [root] Scheduler.__repr__ called from handle_stream
[2019-05-31 11:50:58,007] [9/Thread-1] [INFO] [root] Server.handle_long_running: Using handler <bound method Scheduler.client_heartbeat of <Scheduler: "tcp://10.12.3.241:8786" processes: 3 cores: 24>>
[2019-05-31 11:50:58,007] [9/Thread-1] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:51:03,010] [9/Thread-1] [INFO] [root] Server.handle_long_running: got 1 messages
[2019-05-31 11:51:03,010] [9/Thread-1] [INFO] [root] Server.handle_long_running: message: {'op': 'heartbeat-client'}
[2019-05-31 11:51:03,011] [9/Thread-1] [INFO] [root] Scheduler.__repr__ called from handle_stream
[2019-05-31 11:51:03,012] [9/Thread-1] [INFO] [root] Server.handle_long_running: Using handler <bound method Scheduler.client_heartbeat of <Scheduler: "tcp://10.12.3.241:8786" processes: 3 cores: 24>>
[2019-05-31 11:51:03,012] [9/Thread-1] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:51:08,006] [9/Thread-1] [INFO] [root] Server.handle_long_running: got 1 messages
[2019-05-31 11:51:08,006] [9/Thread-1] [INFO] [root] Server.handle_long_running: message: {'op': 'heartbeat-client'}
[2019-05-31 11:51:08,007] [9/Thread-1] [INFO] [root] Scheduler.__repr__ called from handle_stream
[2019-05-31 11:51:08,007] [9/Thread-1] [INFO] [root] Server.handle_long_running: Using handler <bound method Scheduler.client_heartbeat of <Scheduler: "tcp://10.12.3.241:8786" processes: 3 cores: 24>>
[2019-05-31 11:51:08,008] [9/Thread-1] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:51:13,008] [9/Thread-1] [INFO] [root] Server.handle_long_running: got 1 messages
[2019-05-31 11:51:13,009] [9/Thread-1] [INFO] [root] Server.handle_long_running: message: {'op': 'heartbeat-client'}
[2019-05-31 11:51:13,010] [9/Thread-1] [INFO] [root] Scheduler.__repr__ called from handle_stream
[2019-05-31 11:51:13,010] [9/Thread-1] [INFO] [root] Server.handle_long_running: Using handler <bound method Scheduler.client_heartbeat of <Scheduler: "tcp://10.12.3.241:8786" processes: 3 cores: 24>>
[2019-05-31 11:51:13,010] [9/Thread-1] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:51:18,007] [9/Thread-1] [INFO] [root] Server.handle_long_running: got 1 messages
[2019-05-31 11:51:18,007] [9/Thread-1] [INFO] [root] Server.handle_long_running: message: {'op': 'heartbeat-client'}
[2019-05-31 11:51:18,008] [9/Thread-1] [INFO] [root] Scheduler.__repr__ called from handle_stream
[2019-05-31 11:51:18,008] [9/Thread-1] [INFO] [root] Server.handle_long_running: Using handler <bound method Scheduler.client_heartbeat of <Scheduler: "tcp://10.12.3.241:8786" processes: 3 cores: 24>>
[2019-05-31 11:51:18,008] [9/Thread-1] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:51:23,009] [9/Thread-1] [INFO] [root] Server.handle_long_running: got 1 messages
[2019-05-31 11:51:23,009] [9/Thread-1] [INFO] [root] Server.handle_long_running: message: {'op': 'heartbeat-client'}
[2019-05-31 11:51:23,011] [9/Thread-1] [INFO] [root] Scheduler.__repr__ called from handle_stream
[2019-05-31 11:51:23,011] [9/Thread-1] [INFO] [root] Server.handle_long_running: Using handler <bound method Scheduler.client_heartbeat of <Scheduler: "tcp://10.12.3.241:8786" processes: 3 cores: 24>>
[2019-05-31 11:51:23,011] [9/Thread-1] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:51:28,006] [9/Thread-1] [INFO] [root] Server.handle_long_running: got 1 messages
[2019-05-31 11:51:28,006] [9/Thread-1] [INFO] [root] Server.handle_long_running: message: {'op': 'heartbeat-client'}
[2019-05-31 11:51:28,007] [9/Thread-1] [INFO] [root] Scheduler.__repr__ called from handle_stream
[2019-05-31 11:51:28,007] [9/Thread-1] [INFO] [root] Server.handle_long_running: Using handler <bound method Scheduler.client_heartbeat of <Scheduler: "tcp://10.12.3.241:8786" processes: 3 cores: 24>>
[2019-05-31 11:51:28,007] [9/Thread-1] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:51:33,009] [9/Thread-1] [INFO] [root] Server.handle_long_running: got 1 messages
[2019-05-31 11:51:33,009] [9/Thread-1] [INFO] [root] Server.handle_long_running: message: {'op': 'heartbeat-client'}
[2019-05-31 11:51:33,010] [9/Thread-1] [INFO] [root] Scheduler.__repr__ called from handle_stream
[2019-05-31 11:51:33,011] [9/Thread-1] [INFO] [root] Server.handle_long_running: Using handler <bound method Scheduler.client_heartbeat of <Scheduler: "tcp://10.12.3.241:8786" processes: 3 cores: 24>>
[2019-05-31 11:51:33,011] [9/Thread-1] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:51:38,008] [9/Thread-1] [INFO] [root] Server.handle_long_running: got 1 messages
[2019-05-31 11:51:38,008] [9/Thread-1] [INFO] [root] Server.handle_long_running: message: {'op': 'heartbeat-client'}
[2019-05-31 11:51:38,009] [9/Thread-1] [INFO] [root] Scheduler.__repr__ called from handle_stream
[2019-05-31 11:51:38,009] [9/Thread-1] [INFO] [root] Server.handle_long_running: Using handler <bound method Scheduler.client_heartbeat of <Scheduler: "tcp://10.12.3.241:8786" processes: 3 cores: 24>>
[2019-05-31 11:51:38,009] [9/Thread-1] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:51:43,008] [9/Thread-1] [INFO] [root] Server.handle_long_running: got 1 messages
[2019-05-31 11:51:43,009] [9/Thread-1] [INFO] [root] Server.handle_long_running: message: {'op': 'heartbeat-client'}
[2019-05-31 11:51:43,010] [9/Thread-1] [INFO] [root] Scheduler.__repr__ called from handle_stream
[2019-05-31 11:51:43,010] [9/Thread-1] [INFO] [root] Server.handle_long_running: Using handler <bound method Scheduler.client_heartbeat of <Scheduler: "tcp://10.12.3.241:8786" processes: 3 cores: 24>>
[2019-05-31 11:51:43,010] [9/Thread-1] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:51:48,007] [9/Thread-1] [INFO] [root] Server.handle_long_running: got 1 messages
[2019-05-31 11:51:48,007] [9/Thread-1] [INFO] [root] Server.handle_long_running: message: {'op': 'heartbeat-client'}
[2019-05-31 11:51:48,008] [9/Thread-1] [INFO] [root] Scheduler.__repr__ called from handle_stream
[2019-05-31 11:51:48,008] [9/Thread-1] [INFO] [root] Server.handle_long_running: Using handler <bound method Scheduler.client_heartbeat of <Scheduler: "tcp://10.12.3.241:8786" processes: 3 cores: 24>>
[2019-05-31 11:51:48,008] [9/Thread-1] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:51:53,010] [9/Thread-1] [INFO] [root] Server.handle_long_running: got 1 messages
[2019-05-31 11:51:53,011] [9/Thread-1] [INFO] [root] Server.handle_long_running: message: {'op': 'heartbeat-client'}
[2019-05-31 11:51:53,012] [9/Thread-1] [INFO] [root] Scheduler.__repr__ called from handle_stream
[2019-05-31 11:51:53,012] [9/Thread-1] [INFO] [root] Server.handle_long_running: Using handler <bound method Scheduler.client_heartbeat of <Scheduler: "tcp://10.12.3.241:8786" processes: 3 cores: 24>>
[2019-05-31 11:51:53,012] [9/Thread-1] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:51:58,006] [9/Thread-1] [INFO] [root] Server.handle_long_running: got 1 messages
[2019-05-31 11:51:58,006] [9/Thread-1] [INFO] [root] Server.handle_long_running: message: {'op': 'heartbeat-client'}
[2019-05-31 11:51:58,007] [9/Thread-1] [INFO] [root] Scheduler.__repr__ called from handle_stream
[2019-05-31 11:51:58,007] [9/Thread-1] [INFO] [root] Server.handle_long_running: Using handler <bound method Scheduler.client_heartbeat of <Scheduler: "tcp://10.12.3.241:8786" processes: 3 cores: 24>>
[2019-05-31 11:51:58,007] [9/Thread-1] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:52:03,009] [9/Thread-1] [INFO] [root] Server.handle_long_running: got 1 messages
[2019-05-31 11:52:03,009] [9/Thread-1] [INFO] [root] Server.handle_long_running: message: {'op': 'heartbeat-client'}
[2019-05-31 11:52:03,010] [9/Thread-1] [INFO] [root] Scheduler.__repr__ called from handle_stream
[2019-05-31 11:52:03,011] [9/Thread-1] [INFO] [root] Server.handle_long_running: Using handler <bound method Scheduler.client_heartbeat of <Scheduler: "tcp://10.12.3.241:8786" processes: 3 cores: 24>>
[2019-05-31 11:52:03,011] [9/Thread-1] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:52:08,006] [9/Thread-1] [INFO] [root] Server.handle_long_running: got 1 messages
[2019-05-31 11:52:08,006] [9/Thread-1] [INFO] [root] Server.handle_long_running: message: {'op': 'heartbeat-client'}
[2019-05-31 11:52:08,007] [9/Thread-1] [INFO] [root] Scheduler.__repr__ called from handle_stream
[2019-05-31 11:52:08,007] [9/Thread-1] [INFO] [root] Server.handle_long_running: Using handler <bound method Scheduler.client_heartbeat of <Scheduler: "tcp://10.12.3.241:8786" processes: 3 cores: 24>>
[2019-05-31 11:52:08,007] [9/Thread-1] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:52:13,009] [9/Thread-1] [INFO] [root] Server.handle_long_running: got 1 messages
[2019-05-31 11:52:13,009] [9/Thread-1] [INFO] [root] Server.handle_long_running: message: {'op': 'heartbeat-client'}
[2019-05-31 11:52:13,010] [9/Thread-1] [INFO] [root] Scheduler.__repr__ called from handle_stream
[2019-05-31 11:52:13,010] [9/Thread-1] [INFO] [root] Server.handle_long_running: Using handler <bound method Scheduler.client_heartbeat of <Scheduler: "tcp://10.12.3.241:8786" processes: 3 cores: 24>>
[2019-05-31 11:52:13,011] [9/Thread-1] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:52:18,006] [9/Thread-1] [INFO] [root] Server.handle_long_running: got 1 messages
[2019-05-31 11:52:18,006] [9/Thread-1] [INFO] [root] Server.handle_long_running: message: {'op': 'heartbeat-client'}
[2019-05-31 11:52:18,007] [9/Thread-1] [INFO] [root] Scheduler.__repr__ called from handle_stream
[2019-05-31 11:52:18,007] [9/Thread-1] [INFO] [root] Server.handle_long_running: Using handler <bound method Scheduler.client_heartbeat of <Scheduler: "tcp://10.12.3.241:8786" processes: 3 cores: 24>>
[2019-05-31 11:52:18,007] [9/Thread-1] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:52:23,009] [9/Thread-1] [INFO] [root] Server.handle_long_running: got 1 messages
[2019-05-31 11:52:23,010] [9/Thread-1] [INFO] [root] Server.handle_long_running: message: {'op': 'heartbeat-client'}
[2019-05-31 11:52:23,011] [9/Thread-1] [INFO] [root] Scheduler.__repr__ called from handle_stream
[2019-05-31 11:52:23,011] [9/Thread-1] [INFO] [root] Server.handle_long_running: Using handler <bound method Scheduler.client_heartbeat of <Scheduler: "tcp://10.12.3.241:8786" processes: 3 cores: 24>>
[2019-05-31 11:52:23,011] [9/Thread-1] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:52:28,007] [9/Thread-1] [INFO] [root] Server.handle_long_running: got 1 messages
[2019-05-31 11:52:28,007] [9/Thread-1] [INFO] [root] Server.handle_long_running: message: {'op': 'heartbeat-client'}
[2019-05-31 11:52:28,008] [9/Thread-1] [INFO] [root] Scheduler.__repr__ called from handle_stream
[2019-05-31 11:52:28,008] [9/Thread-1] [INFO] [root] Server.handle_long_running: Using handler <bound method Scheduler.client_heartbeat of <Scheduler: "tcp://10.12.3.241:8786" processes: 3 cores: 24>>
[2019-05-31 11:52:28,008] [9/Thread-1] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:52:33,009] [9/Thread-1] [INFO] [root] Server.handle_long_running: got 1 messages
[2019-05-31 11:52:33,010] [9/Thread-1] [INFO] [root] Server.handle_long_running: message: {'op': 'heartbeat-client'}
[2019-05-31 11:52:33,011] [9/Thread-1] [INFO] [root] Scheduler.__repr__ called from handle_stream
[2019-05-31 11:52:33,011] [9/Thread-1] [INFO] [root] Server.handle_long_running: Using handler <bound method Scheduler.client_heartbeat of <Scheduler: "tcp://10.12.3.241:8786" processes: 3 cores: 24>>
[2019-05-31 11:52:33,011] [9/Thread-1] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:52:38,006] [9/Thread-1] [INFO] [root] Server.handle_long_running: got 1 messages
[2019-05-31 11:52:38,007] [9/Thread-1] [INFO] [root] Server.handle_long_running: message: {'op': 'heartbeat-client'}
[2019-05-31 11:52:38,008] [9/Thread-1] [INFO] [root] Scheduler.__repr__ called from handle_stream
[2019-05-31 11:52:38,008] [9/Thread-1] [INFO] [root] Server.handle_long_running: Using handler <bound method Scheduler.client_heartbeat of <Scheduler: "tcp://10.12.3.241:8786" processes: 3 cores: 24>>
[2019-05-31 11:52:38,008] [9/Thread-1] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:52:43,010] [9/Thread-1] [INFO] [root] Server.handle_long_running: got 1 messages
[2019-05-31 11:52:43,010] [9/Thread-1] [INFO] [root] Server.handle_long_running: message: {'op': 'heartbeat-client'}
[2019-05-31 11:52:43,011] [9/Thread-1] [INFO] [root] Scheduler.__repr__ called from handle_stream
[2019-05-31 11:52:43,012] [9/Thread-1] [INFO] [root] Server.handle_long_running: Using handler <bound method Scheduler.client_heartbeat of <Scheduler: "tcp://10.12.3.241:8786" processes: 3 cores: 24>>
[2019-05-31 11:52:43,012] [9/Thread-1] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:52:48,007] [9/Thread-1] [INFO] [root] Server.handle_long_running: got 1 messages
[2019-05-31 11:52:48,007] [9/Thread-1] [INFO] [root] Server.handle_long_running: message: {'op': 'heartbeat-client'}
[2019-05-31 11:52:48,008] [9/Thread-1] [INFO] [root] Scheduler.__repr__ called from handle_stream
[2019-05-31 11:52:48,008] [9/Thread-1] [INFO] [root] Server.handle_long_running: Using handler <bound method Scheduler.client_heartbeat of <Scheduler: "tcp://10.12.3.241:8786" processes: 3 cores: 24>>
[2019-05-31 11:52:48,008] [9/Thread-1] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:52:53,008] [9/Thread-1] [INFO] [root] Server.handle_long_running: got 1 messages
[2019-05-31 11:52:53,009] [9/Thread-1] [INFO] [root] Server.handle_long_running: message: {'op': 'heartbeat-client'}
[2019-05-31 11:52:53,010] [9/Thread-1] [INFO] [root] Scheduler.__repr__ called from handle_stream
[2019-05-31 11:52:53,010] [9/Thread-1] [INFO] [root] Server.handle_long_running: Using handler <bound method Scheduler.client_heartbeat of <Scheduler: "tcp://10.12.3.241:8786" processes: 3 cores: 24>>
[2019-05-31 11:52:53,010] [9/Thread-1] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:52:58,006] [9/Thread-1] [INFO] [root] Server.handle_long_running: got 1 messages
[2019-05-31 11:52:58,007] [9/Thread-1] [INFO] [root] Server.handle_long_running: message: {'op': 'heartbeat-client'}
[2019-05-31 11:52:58,007] [9/Thread-1] [INFO] [root] Scheduler.__repr__ called from handle_stream
[2019-05-31 11:52:58,008] [9/Thread-1] [INFO] [root] Server.handle_long_running: Using handler <bound method Scheduler.client_heartbeat of <Scheduler: "tcp://10.12.3.241:8786" processes: 3 cores: 24>>
[2019-05-31 11:52:58,008] [9/Thread-1] [INFO] [root] Server.handle_long_running: still not closed

## w1
Showing logs of joblib-dask-deadlock-test-worker-774b9f6565-9gf7v
[2019-05-31 11:50:20,965] [9/MainThread] [INFO] [root] Launching a worker
[2019-05-31 11:50:21,581] [10/MainThread] [INFO] [root] Distributed 1.28.0+15.g6ea010b imported
[2019-05-31 11:50:21,581] [10/MainThread] [INFO] [root] Git revision: 6ea010bcf21db7445bd26286966f59a7e75ab390
[2019-05-31 11:50:21,583] [10/MainThread] [INFO] [root] setup_log() called
[2019-05-31 11:50:21,583] [10/MainThread] [INFO] [root] Installing debugging signal handler
[2019-05-31 11:50:21,583] [10/MainThread] [INFO] [root] Worker.__init__ called
[2019-05-31 11:50:21,583] [10/MainThread] [INFO] [root] Worker._setup_logging called
[2019-05-31 11:50:21,594] [10/MainThread] [INFO] [root] Launching Dask Worker via Python API
[2019-05-31 11:50:21,594] [10/MainThread] [INFO] [root] Python      version:
[2019-05-31 11:50:21,594] [10/MainThread] [INFO] [root] 3.6.8 (default, Apr 25 2019, 21:02:35)
[GCC 4.8.5 20150623 (Red Hat 4.8.5-36)]
[2019-05-31 11:50:21,594] [10/MainThread] [INFO] [root] Dask        version: 1.2.2
[2019-05-31 11:50:21,594] [10/MainThread] [INFO] [root] Distributed version: 1.28.0+15.g6ea010b
[2019-05-31 11:50:21,594] [10/MainThread] [INFO] [root] Worker.start called
[2019-05-31 11:50:21,595] [10/MainThread] [INFO] [root] Launching Worker Watchdog Thread
[2019-05-31 11:50:21,596] [10/MainThread] [INFO] [root] Worker._start called
[2019-05-31 11:50:21,599] [10/MainThread] [INFO] [root]       Start worker at:     tcp://10.12.2.24:39495
[2019-05-31 11:50:21,599] [10/MainThread] [INFO] [root]          Listening to: tcp://joblib-dask-deadlock-test-server:39495
[2019-05-31 11:50:21,599] [10/MainThread] [INFO] [root] Waiting to connect to: tcp://joblib-dask-deadlock-test-server:8786
[2019-05-31 11:50:21,599] [10/MainThread] [INFO] [root] -------------------------------------------------
[2019-05-31 11:50:21,600] [10/MainThread] [INFO] [root]               Threads:                          8
[2019-05-31 11:50:21,600] [10/MainThread] [INFO] [root]                Memory:                   31.62 GB
[2019-05-31 11:50:21,600] [10/MainThread] [INFO] [root]       Local Directory: /home/test_user/dask-worker-space/worker-qrqqs0ih
[2019-05-31 11:50:21,600] [10/MainThread] [INFO] [root] Worker._register_with_scheduler called
[2019-05-31 11:50:21,600] [10/MainThread] [INFO] [root] -------------------------------------------------
[2019-05-31 11:50:22,126] [10/MainThread] [INFO] [root]         Registered to: tcp://joblib-dask-deadlock-test-server:8786
[2019-05-31 11:50:22,126] [10/MainThread] [INFO] [root] -------------------------------------------------
[2019-05-31 11:50:22,127] [10/MainThread] [INFO] [root] Worker.handle_scheduler called
[2019-05-31 11:50:22,155] [10/MainThread] [INFO] [root] Server.handle_long_running called from wrapper
[2019-05-31 11:50:22,155] [10/MainThread] [INFO] [root] Server.handle_long_running arguments
[2019-05-31 11:50:22,155] [10/MainThread] [INFO] [root] caller_name ; id: 140228949628496 ; type: <class 'str'> ; value: wrapper
[2019-05-31 11:50:22,155] [10/MainThread] [INFO] [root] Worker.__repr__ called
[2019-05-31 11:50:22,155] [10/MainThread] [INFO] [root] Worker.__repr__ called
[2019-05-31 11:50:22,155] [10/MainThread] [INFO] [root] every_cycle ; id: 140228815578056 ; type: <class 'list'> ; value: [<bound method Worker.ensure_communicating of <Worker: tcp://10.12.2.24:39495, running, stored: 0, running: 0/8, ready: 0, comm: 0, waiting: 0>>, <bound method Worker.ensure_computing of <Worker: tcp://10.12.2.24:39495, running, stored: 0, running: 0/8, ready: 0, comm: 0, waiting: 0>>]
[2019-05-31 11:50:22,155] [10/MainThread] [INFO] [root] extra ; id: 140228816359928 ; type: <class 'dict'> ; value: {}
[2019-05-31 11:50:22,155] [10/MainThread] [INFO] [root] comm ; id: 140228815980808 ; type: <class 'distributed.comm.tcp.TCP'> ; value: <TCP Worker->Scheduler local=tcp://10.12.2.24:46126 remote=tcp://joblib-dask-deadlock-test-server:8786>
[2019-05-31 11:50:22,156] [10/MainThread] [INFO] [root] Worker.__repr__ called
[2019-05-31 11:50:22,156] [10/MainThread] [INFO] [root] self ; id: 140228848669304 ; type: <class 'distributed.worker.Worker'> ; value: <Worker: tcp://10.12.2.24:39495, running, stored: 0, running: 0/8, ready: 0, comm: 0, waiting: 0>
[2019-05-31 11:50:22,156] [10/MainThread] [INFO] [root] Server.handle_long_running: Starting established connection
[2019-05-31 11:50:22,156] [10/MainThread] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:50:26,598] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:50:31,604] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:50:32,355] [10/MainThread] [INFO] [root] Worker.update_data called
[2019-05-31 11:50:32,375] [10/MainThread] [INFO] [root] Worker.update_data called
[2019-05-31 11:50:32,394] [10/MainThread] [INFO] [root] Worker.update_data called
[2019-05-31 11:50:32,414] [10/MainThread] [INFO] [root] Worker.update_data called
[2019-05-31 11:50:32,483] [10/MainThread] [INFO] [root] Server.handle_long_running: got 1 messages
[2019-05-31 11:50:32,484] [10/MainThread] [INFO] [root] Server.handle_long_running: message: {'op': 'compute-task', 'key': '_fit_and_score-batch-dd498349a1d8484d97152230e388f65f', 'priority': (0, 1, 0), 'duration': 0.5, 'who_has': {'ndarray-fb4f174bb1e813722d61df6188b5f028': ('tcp://10.12.2.24:39495',), 'ndarray-88ba704ce4c44b71d81a35cec23b06b5': ('tcp://10.12.2.24:39495',), 'ndarray-c65639aba94c107b0729630e1e2b6118': ('tcp://10.12.2.24:39495',), 'ndarray-0e249125e0dbd98c1c526e3c9b0b3395': ('tcp://10.12.2.24:39495',)}, 'nbytes': {'ndarray-fb4f174bb1e813722d61df6188b5f028': 431024, 'ndarray-88ba704ce4c44b71d81a35cec23b06b5': 13064, 'ndarray-c65639aba94c107b0729630e1e2b6118': 26120, 'ndarray-0e249125e0dbd98c1c526e3c9b0b3395': 39184}, 'function': b'\x80\x04\x95\x03\x03\x00\x00\x00\x00\x00\x00\x8c\x0cjoblib._dask\x94\x8c\x05Batch\x94\x93\x94]\x94\x8c#sklearn.model_selection._validation\x94\x8c\x0e_fit_and_score\x94\x93\x94]\x94(\x8c\x11sklearn.tree.tree\x94\x8c\x15DecisionTreeRegressor\x94\x93\x94)\x81\x94}\x94(\x8c\tcriterion\x94\x8c\x03mse\x94\x8c\x08splitter\x94\x8c\x04best\x94\x8c\tmax_depth\x94N\x8c\x11min_samples_split\x94K\x02\x8c\x10min_samples_leaf\x94K\x01\x8c\x18min_weight_fraction_leaf\x94G\x00\x00\x00\x00\x00\x00\x00\x00\x8c\x0cmax_features\x94N\x8c\x0crandom_state\x94N\x8c\x0emax_leaf_nodes\x94N\x8c\x15min_impurity_decrease\x94G\x00\x00\x00\x00\x00\x00\x00\x00\x8c\x12min_impurity_split\x94N\x8c\x0cclass_weight\x94N\x8c\x07presort\x94\x89\x8c\x10_sklearn_version\x94\x8c\x060.20.3\x94ub\x8c\x11distributed.utils\x94\x8c\nitemgetter\x94\x93\x94K\x00\x85\x94R\x94h K\x01\x85\x94R\x94e}\x94(\x8c\x05train\x94h K\x02\x85\x94R\x94\x8c\x04test\x94h K\x03\x85\x94R\x94\x8c\nparameters\x94}\x94(h\x11K\nh\x13K\x01h\x12K\x02u\x8c\x06scorer\x94}\x94\x8c\x05score\x94\x8c\x16sklearn.metrics.scorer\x94\x8c\x13_passthrough_scorer\x94\x93\x94s\x8c\nfit_params\x94}\x94\x8c\x12return_train_score\x94\x8c\x04warn\x94\x8c\x15return_n_test_samples\x94\x88\x8c\x0creturn_times\x94\x88\x8c\x11return_parameters\x94\x89\x8c\x0berror_score\x94\x8c\x11raise-deprecating\x94\x8c\x07verbose\x94K\x00u\x87\x94a\x85\x94R\x94.', 'args': b'\x80\x04\x95\xb0\x00\x00\x00\x00\x00\x00\x00(\x8c(ndarray-fb4f174bb1e813722d61df6188b5f028\x94\x8c(ndarray-0e249125e0dbd98c1c526e3c9b0b3395\x94\x8c(ndarray-c65639aba94c107b0729630e1e2b6118\x94\x8c(ndarray-88ba704ce4c44b71d81a35cec23b06b5\x94t\x94.'}
[2019-05-31 11:50:32,484] [10/MainThread] [INFO] [root] Worker.__repr__ called
[2019-05-31 11:50:32,484] [10/MainThread] [INFO] [root] Server.handle_long_running: Using handler <bound method Worker.add_task of <Worker: tcp://10.12.2.24:39495, running, stored: 4, running: 0/8, ready: 0, comm: 0, waiting: 0>>
[2019-05-31 11:50:32,484] [10/MainThread] [INFO] [root] Worker.add_task called
[2019-05-31 11:50:32,484] [10/MainThread] [INFO] [root] Worker._deserialize called
[2019-05-31 11:50:32,525] [10/MainThread] [INFO] [root] Joblib 0.13.2 imported
[2019-05-31 11:50:32,934] [10/MainThread] [INFO] [joblib.dask] Batch.__init__ called from loads
[2019-05-31 11:50:32,934] [10/MainThread] [INFO] [root] Worker.__repr__ called
[2019-05-31 11:50:32,934] [10/MainThread] [INFO] [root] Server.handle_long_running: func: <bound method Worker.ensure_communicating of <Worker: tcp://10.12.2.24:39495, running, stored: 4, running: 0/8, ready: 1, comm: 0, waiting: 0>>
[2019-05-31 11:50:32,934] [10/MainThread] [INFO] [root] Worker.__repr__ called
[2019-05-31 11:50:32,934] [10/MainThread] [INFO] [root] Server.handle_long_running: func: <bound method Worker.ensure_computing of <Worker: tcp://10.12.2.24:39495, running, stored: 4, running: 0/8, ready: 1, comm: 0, waiting: 0>>
[2019-05-31 11:50:32,934] [10/MainThread] [INFO] [root] Worker.ensure_computing called
[2019-05-31 11:50:32,934] [10/MainThread] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:50:32,935] [10/MainThread] [INFO] [root] Worker.execute called
[2019-05-31 11:50:32,935] [10/MainThread] [INFO] [root] Worker.executor_submit called
[2019-05-31 11:50:32,941] [10/MainThread] [INFO] [root] Worker.update_data called
[2019-05-31 11:50:32,944] [10/Dask-Worker-Threads'-10-2] [INFO] [joblib.dask] Batch.__call__ called from apply_function
[2019-05-31 11:50:32,944] [10/Dask-Worker-Threads'-10-2] [INFO] [joblib.parallel] parallel_backend.__init__ called
[2019-05-31 11:50:32,944] [10/Dask-Worker-Threads'-10-2] [INFO] [root] _register_dask called
[2019-05-31 11:50:32,944] [10/Dask-Worker-Threads'-10-2] [INFO] [joblib.parallel] register_parallel_backend called on ; name: dask ; factory: DaskDistributedBackend
[2019-05-31 11:50:32,946] [10/Dask-Worker-Threads'-10-2] [INFO] [joblib.dask] DaskDistributedBackend.__init__ called from __init__
[2019-05-31 11:50:32,946] [10/Dask-Worker-Threads'-10-2] [INFO] [root] Worker.get_client called
[2019-05-31 11:50:32,946] [10/Dask-Worker-Threads'-10-2] [INFO] [root] Worker.get_worker called
[2019-05-31 11:50:32,946] [10/Dask-Worker-Threads'-10-2] [INFO] [root] Worker._get_client called
[2019-05-31 11:50:32,946] [10/Dask-Worker-Threads'-10-2] [DEBUG] [asyncio] Using selector: EpollSelector
[2019-05-31 11:50:32,954] [10/Dask-Worker-Threads'-10-2] [INFO] [root] Client.__init__ called from _get_client
[2019-05-31 11:50:32,956] [10/Dask-Worker-Threads'-10-2] [INFO] [root] Client.start called from __init__
[2019-05-31 11:50:32,957] [10/IO loop] [DEBUG] [asyncio] Using selector: EpollSelector
[2019-05-31 11:50:32,963] [10/MainThread] [INFO] [root] Client._start called from wrapper
[2019-05-31 11:50:32,965] [10/MainThread] [INFO] [root] Client._ensure_connected called from wrapper
[2019-05-31 11:50:32,967] [10/MainThread] [INFO] [root] Worker.update_data called
[2019-05-31 11:50:32,971] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:50:33,004] [10/MainThread] [INFO] [root] Client._handle_report called from wrapper
[2019-05-31 11:50:33,005] [10/Dask-Worker-Threads'-10-2] [INFO] [joblib.dask] Batch.__call__: executing <function _fit_and_score at 0x7f8949aa7510>
[2019-05-31 11:50:33,038] [10/Dask-Worker-Threads'-10-2] [INFO] [joblib.dask] Batch.__call__: done executing <function _fit_and_score at 0x7f8949aa7510>
[2019-05-31 11:50:33,039] [10/Dask-Worker-Threads'-10-2] [INFO] [joblib.dask] Batch.__call__: done
[2019-05-31 11:50:33,040] [10/MainThread] [INFO] [root] Worker.ensure_computing called
[2019-05-31 11:50:33,064] [10/MainThread] [INFO] [root] Server.handle_long_running: got 1 messages
[2019-05-31 11:50:33,064] [10/MainThread] [INFO] [root] Server.handle_long_running: message: {'op': 'compute-task', 'key': '_fit_and_score-batch-8fd23376feca4ad3816bb4ff43023ca9', 'priority': (0, 2, 0), 'duration': 0.5, 'who_has': {'ndarray-fb4f174bb1e813722d61df6188b5f028': ('tcp://10.12.2.24:39495',), 'ndarray-dfc19c3740a5958674f7a9e697457720': ('tcp://10.12.2.24:39495',), 'ndarray-8b4383c9662f67a96fc16c9a5b3c048c': ('tcp://10.12.2.24:39495',), 'ndarray-0e249125e0dbd98c1c526e3c9b0b3395': ('tcp://10.12.2.24:39495',)}, 'nbytes': {'ndarray-fb4f174bb1e813722d61df6188b5f028': 431024, 'ndarray-dfc19c3740a5958674f7a9e697457720': 13064, 'ndarray-8b4383c9662f67a96fc16c9a5b3c048c': 26120, 'ndarray-0e249125e0dbd98c1c526e3c9b0b3395': 39184}, 'function': b'\x80\x04\x95\x03\x03\x00\x00\x00\x00\x00\x00\x8c\x0cjoblib._dask\x94\x8c\x05Batch\x94\x93\x94]\x94\x8c#sklearn.model_selection._validation\x94\x8c\x0e_fit_and_score\x94\x93\x94]\x94(\x8c\x11sklearn.tree.tree\x94\x8c\x15DecisionTreeRegressor\x94\x93\x94)\x81\x94}\x94(\x8c\tcriterion\x94\x8c\x03mse\x94\x8c\x08splitter\x94\x8c\x04best\x94\x8c\tmax_depth\x94N\x8c\x11min_samples_split\x94K\x02\x8c\x10min_samples_leaf\x94K\x01\x8c\x18min_weight_fraction_leaf\x94G\x00\x00\x00\x00\x00\x00\x00\x00\x8c\x0cmax_features\x94N\x8c\x0crandom_state\x94N\x8c\x0emax_leaf_nodes\x94N\x8c\x15min_impurity_decrease\x94G\x00\x00\x00\x00\x00\x00\x00\x00\x8c\x12min_impurity_split\x94N\x8c\x0cclass_weight\x94N\x8c\x07presort\x94\x89\x8c\x10_sklearn_version\x94\x8c\x060.20.3\x94ub\x8c\x11distributed.utils\x94\x8c\nitemgetter\x94\x93\x94K\x00\x85\x94R\x94h K\x01\x85\x94R\x94e}\x94(\x8c\x05train\x94h K\x02\x85\x94R\x94\x8c\x04test\x94h K\x03\x85\x94R\x94\x8c\nparameters\x94}\x94(h\x11K\nh\x13K\x01h\x12K\x02u\x8c\x06scorer\x94}\x94\x8c\x05score\x94\x8c\x16sklearn.metrics.scorer\x94\x8c\x13_passthrough_scorer\x94\x93\x94s\x8c\nfit_params\x94}\x94\x8c\x12return_train_score\x94\x8c\x04warn\x94\x8c\x15return_n_test_samples\x94\x88\x8c\x0creturn_times\x94\x88\x8c\x11return_parameters\x94\x89\x8c\x0berror_score\x94\x8c\x11raise-deprecating\x94\x8c\x07verbose\x94K\x00u\x87\x94a\x85\x94R\x94.', 'args': b'\x80\x04\x95\xb0\x00\x00\x00\x00\x00\x00\x00(\x8c(ndarray-fb4f174bb1e813722d61df6188b5f028\x94\x8c(ndarray-0e249125e0dbd98c1c526e3c9b0b3395\x94\x8c(ndarray-8b4383c9662f67a96fc16c9a5b3c048c\x94\x8c(ndarray-dfc19c3740a5958674f7a9e697457720\x94t\x94.'}
[2019-05-31 11:50:33,064] [10/MainThread] [INFO] [root] Worker.__repr__ called
[2019-05-31 11:50:33,065] [10/MainThread] [INFO] [root] Server.handle_long_running: Using handler <bound method Worker.add_task of <Worker: tcp://10.12.2.24:39495, running, stored: 7, running: 0/8, ready: 0, comm: 0, waiting: 0>>
[2019-05-31 11:50:33,065] [10/MainThread] [INFO] [root] Worker.add_task called
[2019-05-31 11:50:33,065] [10/MainThread] [INFO] [root] Worker._deserialize called
[2019-05-31 11:50:33,066] [10/MainThread] [INFO] [joblib.dask] Batch.__init__ called from loads
[2019-05-31 11:50:33,066] [10/MainThread] [INFO] [root] Worker.__repr__ called
[2019-05-31 11:50:33,066] [10/MainThread] [INFO] [root] Server.handle_long_running: func: <bound method Worker.ensure_communicating of <Worker: tcp://10.12.2.24:39495, running, stored: 7, running: 0/8, ready: 1, comm: 0, waiting: 0>>
[2019-05-31 11:50:33,066] [10/MainThread] [INFO] [root] Worker.__repr__ called
[2019-05-31 11:50:33,066] [10/MainThread] [INFO] [root] Server.handle_long_running: func: <bound method Worker.ensure_computing of <Worker: tcp://10.12.2.24:39495, running, stored: 7, running: 0/8, ready: 1, comm: 0, waiting: 0>>
[2019-05-31 11:50:33,066] [10/MainThread] [INFO] [root] Worker.ensure_computing called
[2019-05-31 11:50:33,066] [10/MainThread] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:50:33,067] [10/MainThread] [INFO] [root] Worker.execute called
[2019-05-31 11:50:33,068] [10/MainThread] [INFO] [root] Worker.executor_submit called
[2019-05-31 11:50:33,069] [10/MainThread] [INFO] [root] Worker.update_data called
[2019-05-31 11:50:33,070] [10/Dask-Worker-Threads'-10-3] [INFO] [joblib.dask] Batch.__call__ called from apply_function
[2019-05-31 11:50:33,070] [10/Dask-Worker-Threads'-10-3] [INFO] [joblib.parallel] parallel_backend.__init__ called
[2019-05-31 11:50:33,072] [10/Dask-Worker-Threads'-10-3] [INFO] [joblib.dask] DaskDistributedBackend.__init__ called from __init__
[2019-05-31 11:50:33,072] [10/Dask-Worker-Threads'-10-3] [INFO] [root] Worker.get_client called
[2019-05-31 11:50:33,072] [10/Dask-Worker-Threads'-10-3] [INFO] [root] Worker.get_worker called
[2019-05-31 11:50:33,072] [10/Dask-Worker-Threads'-10-3] [INFO] [root] Worker._get_client called
[2019-05-31 11:50:33,072] [10/Dask-Worker-Threads'-10-3] [INFO] [joblib.dask] Batch.__call__: executing <function _fit_and_score at 0x7f8949aa7510>
[2019-05-31 11:50:33,105] [10/Dask-Worker-Threads'-10-3] [INFO] [joblib.dask] Batch.__call__: done executing <function _fit_and_score at 0x7f8949aa7510>
[2019-05-31 11:50:33,106] [10/Dask-Worker-Threads'-10-3] [INFO] [joblib.dask] Batch.__call__: done
[2019-05-31 11:50:33,106] [10/MainThread] [INFO] [root] Worker.ensure_computing called
[2019-05-31 11:50:35,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:50:36,609] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:50:37,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:50:39,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:50:41,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:50:41,614] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:50:43,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:50:45,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:50:46,618] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:50:47,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:50:49,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:50:51,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:50:51,624] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:50:53,006] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:50:55,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:50:56,628] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:50:57,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:50:59,004] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:51:01,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:51:01,632] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:51:03,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:51:05,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:51:06,636] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:51:07,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:51:09,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:51:11,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:51:11,641] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:51:13,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:51:15,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:51:16,647] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:51:17,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:51:19,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:51:21,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:51:21,652] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:51:23,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:51:25,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:51:26,659] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:51:27,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:51:29,004] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:51:31,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:51:31,665] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:51:33,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:51:35,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:51:36,670] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:51:37,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:51:39,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:51:41,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:51:41,671] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:51:43,004] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:51:45,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:51:46,676] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:51:47,006] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:51:49,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:51:51,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:51:51,678] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:51:53,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:51:55,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:51:56,683] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:51:57,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:51:59,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:52:01,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:52:01,689] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:52:03,004] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:52:05,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:52:06,694] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:52:07,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:52:09,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:52:11,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:52:11,699] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:52:13,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:52:15,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:52:16,704] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:52:17,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:52:19,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:52:21,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:52:21,710] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:52:23,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:52:25,004] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:52:26,715] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:52:27,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:52:29,004] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:52:31,004] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:52:31,721] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:52:33,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:52:35,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:52:36,726] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:52:37,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:52:39,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:52:41,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:52:41,729] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:52:43,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:52:45,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:52:46,733] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:52:47,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:52:49,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:52:51,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:52:51,735] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:52:53,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:52:55,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:52:56,741] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:52:57,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:52:59,006] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:53:01,004] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper
[2019-05-31 11:53:01,746] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:53:03,005] [10/MainThread] [INFO] [root] Client._update_scheduler_info called from wrapper

## w2
Showing logs of joblib-dask-deadlock-test-worker-774b9f6565-bl4j6
[2019-05-31 11:50:20,017] [10/MainThread] [INFO] [root] Launching a worker
[2019-05-31 11:50:20,638] [11/MainThread] [INFO] [root] Distributed 1.28.0+15.g6ea010b imported
[2019-05-31 11:50:20,638] [11/MainThread] [INFO] [root] Git revision: 6ea010bcf21db7445bd26286966f59a7e75ab390
[2019-05-31 11:50:20,640] [11/MainThread] [INFO] [root] setup_log() called
[2019-05-31 11:50:20,640] [11/MainThread] [INFO] [root] Installing debugging signal handler
[2019-05-31 11:50:20,640] [11/MainThread] [INFO] [root] Worker.__init__ called
[2019-05-31 11:50:20,641] [11/MainThread] [INFO] [root] Worker._setup_logging called
[2019-05-31 11:50:20,651] [11/MainThread] [INFO] [root] Launching Dask Worker via Python API
[2019-05-31 11:50:20,652] [11/MainThread] [INFO] [root] Python      version:
[2019-05-31 11:50:20,652] [11/MainThread] [INFO] [root] 3.6.8 (default, Apr 25 2019, 21:02:35)
[GCC 4.8.5 20150623 (Red Hat 4.8.5-36)]
[2019-05-31 11:50:20,652] [11/MainThread] [INFO] [root] Dask        version: 1.2.2
[2019-05-31 11:50:20,652] [11/MainThread] [INFO] [root] Distributed version: 1.28.0+15.g6ea010b
[2019-05-31 11:50:20,652] [11/MainThread] [INFO] [root] Worker.start called
[2019-05-31 11:50:20,652] [11/MainThread] [INFO] [root] Launching Worker Watchdog Thread
[2019-05-31 11:50:20,653] [11/MainThread] [INFO] [root] Worker._start called
[2019-05-31 11:50:20,657] [11/MainThread] [INFO] [root]       Start worker at:    tcp://10.12.3.242:44061
[2019-05-31 11:50:20,658] [11/MainThread] [INFO] [root]          Listening to: tcp://joblib-dask-deadlock-test-server:44061
[2019-05-31 11:50:20,658] [11/MainThread] [INFO] [root] Waiting to connect to: tcp://joblib-dask-deadlock-test-server:8786
[2019-05-31 11:50:20,658] [11/MainThread] [INFO] [root] -------------------------------------------------
[2019-05-31 11:50:20,658] [11/MainThread] [INFO] [root]               Threads:                          8
[2019-05-31 11:50:20,658] [11/MainThread] [INFO] [root]                Memory:                   31.62 GB
[2019-05-31 11:50:20,658] [11/MainThread] [INFO] [root]       Local Directory: /home/test_user/dask-worker-space/worker-k4ya39ls
[2019-05-31 11:50:20,659] [11/MainThread] [INFO] [root] Worker._register_with_scheduler called
[2019-05-31 11:50:20,659] [11/MainThread] [INFO] [root] -------------------------------------------------
[2019-05-31 11:50:22,126] [11/MainThread] [INFO] [root]         Registered to: tcp://joblib-dask-deadlock-test-server:8786
[2019-05-31 11:50:22,126] [11/MainThread] [INFO] [root] -------------------------------------------------
[2019-05-31 11:50:22,127] [11/MainThread] [INFO] [root] Worker.handle_scheduler called
[2019-05-31 11:50:22,155] [11/MainThread] [INFO] [root] Server.handle_long_running called from wrapper
[2019-05-31 11:50:22,155] [11/MainThread] [INFO] [root] Server.handle_long_running arguments
[2019-05-31 11:50:22,155] [11/MainThread] [INFO] [root] caller_name ; id: 139694188459600 ; type: <class 'str'> ; value: wrapper
[2019-05-31 11:50:22,155] [11/MainThread] [INFO] [root] Worker.__repr__ called
[2019-05-31 11:50:22,155] [11/MainThread] [INFO] [root] Worker.__repr__ called
[2019-05-31 11:50:22,156] [11/MainThread] [INFO] [root] every_cycle ; id: 139694047536136 ; type: <class 'list'> ; value: [<bound method Worker.ensure_communicating of <Worker: tcp://10.12.3.242:44061, running, stored: 0, running: 0/8, ready: 0, comm: 0, waiting: 0>>, <bound method Worker.ensure_computing of <Worker: tcp://10.12.3.242:44061, running, stored: 0, running: 0/8, ready: 0, comm: 0, waiting: 0>>]
[2019-05-31 11:50:22,156] [11/MainThread] [INFO] [root] extra ; id: 139694055109400 ; type: <class 'dict'> ; value: {}
[2019-05-31 11:50:22,156] [11/MainThread] [INFO] [root] comm ; id: 139694053835048 ; type: <class 'distributed.comm.tcp.TCP'> ; value: <TCP Worker->Scheduler local=tcp://10.12.3.242:59894 remote=tcp://joblib-dask-deadlock-test-server:8786>
[2019-05-31 11:50:22,156] [11/MainThread] [INFO] [root] Worker.__repr__ called
[2019-05-31 11:50:22,156] [11/MainThread] [INFO] [root] self ; id: 139694087500072 ; type: <class 'distributed.worker.Worker'> ; value: <Worker: tcp://10.12.3.242:44061, running, stored: 0, running: 0/8, ready: 0, comm: 0, waiting: 0>
[2019-05-31 11:50:22,156] [11/MainThread] [INFO] [root] Server.handle_long_running: Starting established connection
[2019-05-31 11:50:22,156] [11/MainThread] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:50:25,658] [11/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:50:30,664] [11/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:50:35,669] [11/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:50:40,674] [11/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:50:45,680] [11/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:50:50,685] [11/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:50:55,691] [11/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:51:00,696] [11/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:51:05,698] [11/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:51:10,701] [11/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:51:15,706] [11/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:51:20,711] [11/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:51:25,716] [11/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:51:30,721] [11/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:51:35,725] [11/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:51:40,730] [11/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:51:45,736] [11/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:51:50,737] [11/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:51:55,738] [11/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:52:00,743] [11/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:52:05,746] [11/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:52:10,750] [11/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:52:15,755] [11/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:52:20,756] [11/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:52:25,762] [11/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:52:30,767] [11/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:52:35,772] [11/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:52:40,773] [11/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:52:45,774] [11/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:52:50,777] [11/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:52:55,782] [11/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:53:00,788] [11/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:53:05,793] [11/Thread-1] [INFO] [root] Dask Worker status : running

## w3
Showing logs of joblib-dask-deadlock-test-worker-774b9f6565-nhlq2
[2019-05-31 11:50:19,991] [9/MainThread] [INFO] [root] Launching a worker
[2019-05-31 11:50:20,620] [10/MainThread] [INFO] [root] Distributed 1.28.0+15.g6ea010b imported
[2019-05-31 11:50:20,620] [10/MainThread] [INFO] [root] Git revision: 6ea010bcf21db7445bd26286966f59a7e75ab390
[2019-05-31 11:50:20,622] [10/MainThread] [INFO] [root] setup_log() called
[2019-05-31 11:50:20,622] [10/MainThread] [INFO] [root] Installing debugging signal handler
[2019-05-31 11:50:20,622] [10/MainThread] [INFO] [root] Worker.__init__ called
[2019-05-31 11:50:20,623] [10/MainThread] [INFO] [root] Worker._setup_logging called
[2019-05-31 11:50:20,634] [10/MainThread] [INFO] [root] Launching Dask Worker via Python API
[2019-05-31 11:50:20,635] [10/MainThread] [INFO] [root] Python      version:
[2019-05-31 11:50:20,635] [10/MainThread] [INFO] [root] 3.6.8 (default, Apr 25 2019, 21:02:35)
[GCC 4.8.5 20150623 (Red Hat 4.8.5-36)]
[2019-05-31 11:50:20,635] [10/MainThread] [INFO] [root] Dask        version: 1.2.2
[2019-05-31 11:50:20,635] [10/MainThread] [INFO] [root] Distributed version: 1.28.0+15.g6ea010b
[2019-05-31 11:50:20,635] [10/MainThread] [INFO] [root] Worker.start called
[2019-05-31 11:50:20,635] [10/MainThread] [INFO] [root] Launching Worker Watchdog Thread
[2019-05-31 11:50:20,637] [10/MainThread] [INFO] [root] Worker._start called
[2019-05-31 11:50:20,641] [10/MainThread] [INFO] [root]       Start worker at:    tcp://10.12.3.240:41261
[2019-05-31 11:50:20,642] [10/MainThread] [INFO] [root]          Listening to: tcp://joblib-dask-deadlock-test-server:41261
[2019-05-31 11:50:20,642] [10/MainThread] [INFO] [root] Waiting to connect to: tcp://joblib-dask-deadlock-test-server:8786
[2019-05-31 11:50:20,642] [10/MainThread] [INFO] [root] -------------------------------------------------
[2019-05-31 11:50:20,642] [10/MainThread] [INFO] [root]               Threads:                          8
[2019-05-31 11:50:20,643] [10/MainThread] [INFO] [root]                Memory:                   31.62 GB
[2019-05-31 11:50:20,643] [10/MainThread] [INFO] [root]       Local Directory: /home/test_user/dask-worker-space/worker-9nlq2z6a
[2019-05-31 11:50:20,643] [10/MainThread] [INFO] [root] Worker._register_with_scheduler called
[2019-05-31 11:50:20,643] [10/MainThread] [INFO] [root] -------------------------------------------------
[2019-05-31 11:50:22,094] [10/MainThread] [INFO] [root]         Registered to: tcp://joblib-dask-deadlock-test-server:8786
[2019-05-31 11:50:22,094] [10/MainThread] [INFO] [root] -------------------------------------------------
[2019-05-31 11:50:22,094] [10/MainThread] [INFO] [root] Worker.handle_scheduler called
[2019-05-31 11:50:22,124] [10/MainThread] [INFO] [root] Server.handle_long_running called from wrapper
[2019-05-31 11:50:22,124] [10/MainThread] [INFO] [root] Server.handle_long_running arguments
[2019-05-31 11:50:22,124] [10/MainThread] [INFO] [root] caller_name ; id: 140490935346768 ; type: <class 'str'> ; value: wrapper
[2019-05-31 11:50:22,124] [10/MainThread] [INFO] [root] Worker.__repr__ called
[2019-05-31 11:50:22,125] [10/MainThread] [INFO] [root] Worker.__repr__ called
[2019-05-31 11:50:22,125] [10/MainThread] [INFO] [root] every_cycle ; id: 140490801284936 ; type: <class 'list'> ; value: [<bound method Worker.ensure_communicating of <Worker: tcp://10.12.3.240:41261, running, stored: 0, running: 0/8, ready: 0, comm: 0, waiting: 0>>, <bound method Worker.ensure_computing of <Worker: tcp://10.12.3.240:41261, running, stored: 0, running: 0/8, ready: 0, comm: 0, waiting: 0>>]
[2019-05-31 11:50:22,125] [10/MainThread] [INFO] [root] extra ; id: 140490795704112 ; type: <class 'dict'> ; value: {}
[2019-05-31 11:50:22,125] [10/MainThread] [INFO] [root] comm ; id: 140490801355072 ; type: <class 'distributed.comm.tcp.TCP'> ; value: <TCP Worker->Scheduler local=tcp://10.12.3.240:53376 remote=tcp://joblib-dask-deadlock-test-server:8786>
[2019-05-31 11:50:22,125] [10/MainThread] [INFO] [root] Worker.__repr__ called
[2019-05-31 11:50:22,125] [10/MainThread] [INFO] [root] self ; id: 140490834395656 ; type: <class 'distributed.worker.Worker'> ; value: <Worker: tcp://10.12.3.240:41261, running, stored: 0, running: 0/8, ready: 0, comm: 0, waiting: 0>
[2019-05-31 11:50:22,125] [10/MainThread] [INFO] [root] Server.handle_long_running: Starting established connection
[2019-05-31 11:50:22,125] [10/MainThread] [INFO] [root] Server.handle_long_running: still not closed
[2019-05-31 11:50:25,641] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:50:30,646] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:50:35,651] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:50:40,656] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:50:45,657] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:50:50,658] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:50:55,663] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:51:00,669] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:51:05,672] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:51:10,678] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:51:15,683] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:51:20,688] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:51:25,693] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:51:30,698] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:51:35,703] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:51:40,708] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:51:45,713] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:51:50,717] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:51:55,722] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:52:00,727] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:52:05,732] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:52:10,734] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:52:15,738] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:52:20,743] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:52:25,745] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:52:30,750] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:52:35,756] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:52:40,761] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:52:45,766] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:52:50,767] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:52:55,772] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:53:00,777] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:53:05,783] [10/Thread-1] [INFO] [root] Dask Worker status : running
[2019-05-31 11:53:10,788] [10/Thread-1] [INFO] [root] Dask Worker status : running
	Showing logs of joblib-dask-deadlock-test-worker-774b9f6565-bl4j6
	[2019-05-31 11:50:20,017] [10/MainThread] [INFO] [root] Launching a worker
	[2019-05-31 11:50:20,638] [11/MainThread] [INFO] [root] Distributed 1.28.0+15.g6ea010b imported
	[2019-05-31 11:50:20,638] [11/MainThread] [INFO] [root] Git revision: 6ea010bcf21db7445bd26286966f59a7e75ab390
	[2019-05-31 11:50:20,640] [11/MainThread] [INFO] [root] setup_log() called
	[2019-05-31 11:50:20,640] [11/MainThread] [INFO] [root] Installing debugging signal handler
	[2019-05-31 11:50:20,640] [11/MainThread] [INFO] [root] Worker.__init__ called
	[2019-05-31 11:50:20,641] [11/MainThread] [INFO] [root] Worker._setup_logging called
	[2019-05-31 11:50:20,651] [11/MainThread] [INFO] [root] Launching Dask Worker via Python API
	[2019-05-31 11:50:20,652] [11/MainThread] [INFO] [root] Python version:
	[2019-05-31 11:50:20,652] [11/MainThread] [INFO] [root] 3.6.8 (default, Apr 25 2019, 21:02:35)
	[GCC 4.8.5 20150623 (Red Hat 4.8.5-36)]
	[2019-05-31 11:50:20,652] [11/MainThread] [INFO] [root] Dask version: 1.2.2
	[2019-05-31 11:50:20,652] [11/MainThread] [INFO] [root] Distributed version: 1.28.0+15.g6ea010b
	[2019-05-31 11:50:20,652] [11/MainThread] [INFO] [root] Worker.start called
	[2019-05-31 11:50:20,652] [11/MainThread] [INFO] [root] Launching Worker Watchdog Thread
	[2019-05-31 11:50:20,653] [11/MainThread] [INFO] [root] Worker._start called
	[2019-05-31 11:50:20,657] [11/MainThread] [INFO] [root] Start worker at: tcp://10.12.3.242:44061
	[2019-05-31 11:50:20,658] [11/MainThread] [INFO] [root] Listening to: tcp://joblib-dask-deadlock-test-server:44061
	[2019-05-31 11:50:20,658] [11/MainThread] [INFO] [root] Waiting to connect to: tcp://joblib-dask-deadlock-test-server:8786
	[2019-05-31 11:50:20,658] [11/MainThread] [INFO] [root] -------------------------------------------------
	[2019-05-31 11:50:20,658] [11/MainThread] [INFO] [root] Threads: 8
	[2019-05-31 11:50:20,658] [11/MainThread] [INFO] [root] Memory: 31.62 GB
	[2019-05-31 11:50:20,658] [11/MainThread] [INFO] [root] Local Directory: /home/test_user/dask-worker-space/worker-k4ya39ls
	[2019-05-31 11:50:20,659] [11/MainThread] [INFO] [root] Worker._register_with_scheduler called
	[2019-05-31 11:50:20,659] [11/MainThread] [INFO] [root] -------------------------------------------------
	[2019-05-31 11:50:22,126] [11/MainThread] [INFO] [root] Registered to: tcp://joblib-dask-deadlock-test-server:8786
	[2019-05-31 11:50:22,126] [11/MainThread] [INFO] [root] -------------------------------------------------
	[2019-05-31 11:50:22,127] [11/MainThread] [INFO] [root] Worker.handle_scheduler called
	[2019-05-31 11:50:22,155] [11/MainThread] [INFO] [root] Server.handle_long_running called from wrapper
	[2019-05-31 11:50:22,155] [11/MainThread] [INFO] [root] Server.handle_long_running arguments
	[2019-05-31 11:50:22,155] [11/MainThread] [INFO] [root] caller_name ; id: 139694188459600 ; type: <class 'str'> ; value: wrapper
	[2019-05-31 11:50:22,155] [11/MainThread] [INFO] [root] Worker.__repr__ called
	[2019-05-31 11:50:22,155] [11/MainThread] [INFO] [root] Worker.__repr__ called
	[2019-05-31 11:50:22,156] [11/MainThread] [INFO] [root] every_cycle ; id: 139694047536136 ; type: <class 'list'> ; value: [<bound method Worker.ensure_communicating of <Worker: tcp://10.12.3.242:44061, running, stored: 0, running: 0/8, ready: 0, comm: 0, waiting: 0>>, <bound method Worker.ensure_computing of <Worker: tcp://10.12.3.242:44061, running, stored: 0, running: 0/8, ready: 0, comm: 0, waiting: 0>>]
	[2019-05-31 11:50:22,156] [11/MainThread] [INFO] [root] extra ; id: 139694055109400 ; type: <class 'dict'> ; value: {}
	[2019-05-31 11:50:22,156] [11/MainThread] [INFO] [root] comm ; id: 139694053835048 ; type: <class 'distributed.comm.tcp.TCP'> ; value: <TCP Worker->Scheduler local=tcp://10.12.3.242:59894 remote=tcp://joblib-dask-deadlock-test-server:8786>
	[2019-05-31 11:50:22,156] [11/MainThread] [INFO] [root] Worker.__repr__ called
	[2019-05-31 11:50:22,156] [11/MainThread] [INFO] [root] self ; id: 139694087500072 ; type: <class 'distributed.worker.Worker'> ; value: <Worker: tcp://10.12.3.242:44061, running, stored: 0, running: 0/8, ready: 0, comm: 0, waiting: 0>
	[2019-05-31 11:50:22,156] [11/MainThread] [INFO] [root] Server.handle_long_running: Starting established connection
	[2019-05-31 11:50:22,156] [11/MainThread] [INFO] [root] Server.handle_long_running: still not closed
	[2019-05-31 11:50:25,658] [11/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:50:30,664] [11/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:50:35,669] [11/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:50:40,674] [11/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:50:45,680] [11/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:50:50,685] [11/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:50:55,691] [11/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:51:00,696] [11/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:51:05,698] [11/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:51:10,701] [11/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:51:15,706] [11/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:51:20,711] [11/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:51:25,716] [11/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:51:30,721] [11/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:51:35,725] [11/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:51:40,730] [11/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:51:45,736] [11/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:51:50,737] [11/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:51:55,738] [11/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:52:00,743] [11/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:52:05,746] [11/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:52:10,750] [11/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:52:15,755] [11/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:52:20,756] [11/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:52:25,762] [11/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:52:30,767] [11/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:52:35,772] [11/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:52:40,773] [11/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:52:45,774] [11/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:52:50,777] [11/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:52:55,782] [11/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:53:00,788] [11/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:53:05,793] [11/Thread-1] [INFO] [root] Dask Worker status : running
	Showing logs of joblib-dask-deadlock-test-worker-774b9f6565-nhlq2
	[2019-05-31 11:50:19,991] [9/MainThread] [INFO] [root] Launching a worker
	[2019-05-31 11:50:20,620] [10/MainThread] [INFO] [root] Distributed 1.28.0+15.g6ea010b imported
	[2019-05-31 11:50:20,620] [10/MainThread] [INFO] [root] Git revision: 6ea010bcf21db7445bd26286966f59a7e75ab390
	[2019-05-31 11:50:20,622] [10/MainThread] [INFO] [root] setup_log() called
	[2019-05-31 11:50:20,622] [10/MainThread] [INFO] [root] Installing debugging signal handler
	[2019-05-31 11:50:20,622] [10/MainThread] [INFO] [root] Worker.__init__ called
	[2019-05-31 11:50:20,623] [10/MainThread] [INFO] [root] Worker._setup_logging called
	[2019-05-31 11:50:20,634] [10/MainThread] [INFO] [root] Launching Dask Worker via Python API
	[2019-05-31 11:50:20,635] [10/MainThread] [INFO] [root] Python version:
	[2019-05-31 11:50:20,635] [10/MainThread] [INFO] [root] 3.6.8 (default, Apr 25 2019, 21:02:35)
	[GCC 4.8.5 20150623 (Red Hat 4.8.5-36)]
	[2019-05-31 11:50:20,635] [10/MainThread] [INFO] [root] Dask version: 1.2.2
	[2019-05-31 11:50:20,635] [10/MainThread] [INFO] [root] Distributed version: 1.28.0+15.g6ea010b
	[2019-05-31 11:50:20,635] [10/MainThread] [INFO] [root] Worker.start called
	[2019-05-31 11:50:20,635] [10/MainThread] [INFO] [root] Launching Worker Watchdog Thread
	[2019-05-31 11:50:20,637] [10/MainThread] [INFO] [root] Worker._start called
	[2019-05-31 11:50:20,641] [10/MainThread] [INFO] [root] Start worker at: tcp://10.12.3.240:41261
	[2019-05-31 11:50:20,642] [10/MainThread] [INFO] [root] Listening to: tcp://joblib-dask-deadlock-test-server:41261
	[2019-05-31 11:50:20,642] [10/MainThread] [INFO] [root] Waiting to connect to: tcp://joblib-dask-deadlock-test-server:8786
	[2019-05-31 11:50:20,642] [10/MainThread] [INFO] [root] -------------------------------------------------
	[2019-05-31 11:50:20,642] [10/MainThread] [INFO] [root] Threads: 8
	[2019-05-31 11:50:20,643] [10/MainThread] [INFO] [root] Memory: 31.62 GB
	[2019-05-31 11:50:20,643] [10/MainThread] [INFO] [root] Local Directory: /home/test_user/dask-worker-space/worker-9nlq2z6a
	[2019-05-31 11:50:20,643] [10/MainThread] [INFO] [root] Worker._register_with_scheduler called
	[2019-05-31 11:50:20,643] [10/MainThread] [INFO] [root] -------------------------------------------------
	[2019-05-31 11:50:22,094] [10/MainThread] [INFO] [root] Registered to: tcp://joblib-dask-deadlock-test-server:8786
	[2019-05-31 11:50:22,094] [10/MainThread] [INFO] [root] -------------------------------------------------
	[2019-05-31 11:50:22,094] [10/MainThread] [INFO] [root] Worker.handle_scheduler called
	[2019-05-31 11:50:22,124] [10/MainThread] [INFO] [root] Server.handle_long_running called from wrapper
	[2019-05-31 11:50:22,124] [10/MainThread] [INFO] [root] Server.handle_long_running arguments
	[2019-05-31 11:50:22,124] [10/MainThread] [INFO] [root] caller_name ; id: 140490935346768 ; type: <class 'str'> ; value: wrapper
	[2019-05-31 11:50:22,124] [10/MainThread] [INFO] [root] Worker.__repr__ called
	[2019-05-31 11:50:22,125] [10/MainThread] [INFO] [root] Worker.__repr__ called
	[2019-05-31 11:50:22,125] [10/MainThread] [INFO] [root] every_cycle ; id: 140490801284936 ; type: <class 'list'> ; value: [<bound method Worker.ensure_communicating of <Worker: tcp://10.12.3.240:41261, running, stored: 0, running: 0/8, ready: 0, comm: 0, waiting: 0>>, <bound method Worker.ensure_computing of <Worker: tcp://10.12.3.240:41261, running, stored: 0, running: 0/8, ready: 0, comm: 0, waiting: 0>>]
	[2019-05-31 11:50:22,125] [10/MainThread] [INFO] [root] extra ; id: 140490795704112 ; type: <class 'dict'> ; value: {}
	[2019-05-31 11:50:22,125] [10/MainThread] [INFO] [root] comm ; id: 140490801355072 ; type: <class 'distributed.comm.tcp.TCP'> ; value: <TCP Worker->Scheduler local=tcp://10.12.3.240:53376 remote=tcp://joblib-dask-deadlock-test-server:8786>
	[2019-05-31 11:50:22,125] [10/MainThread] [INFO] [root] Worker.__repr__ called
	[2019-05-31 11:50:22,125] [10/MainThread] [INFO] [root] self ; id: 140490834395656 ; type: <class 'distributed.worker.Worker'> ; value: <Worker: tcp://10.12.3.240:41261, running, stored: 0, running: 0/8, ready: 0, comm: 0, waiting: 0>
	[2019-05-31 11:50:22,125] [10/MainThread] [INFO] [root] Server.handle_long_running: Starting established connection
	[2019-05-31 11:50:22,125] [10/MainThread] [INFO] [root] Server.handle_long_running: still not closed
	[2019-05-31 11:50:25,641] [10/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:50:30,646] [10/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:50:35,651] [10/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:50:40,656] [10/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:50:45,657] [10/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:50:50,658] [10/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:50:55,663] [10/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:51:00,669] [10/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:51:05,672] [10/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:51:10,678] [10/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:51:15,683] [10/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:51:20,688] [10/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:51:25,693] [10/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:51:30,698] [10/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:51:35,703] [10/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:51:40,708] [10/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:51:45,713] [10/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:51:50,717] [10/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:51:55,722] [10/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:52:00,727] [10/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:52:05,732] [10/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:52:10,734] [10/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:52:15,738] [10/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:52:20,743] [10/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:52:25,745] [10/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:52:30,750] [10/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:52:35,756] [10/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:52:40,761] [10/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:52:45,766] [10/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:52:50,767] [10/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:52:55,772] [10/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:53:00,777] [10/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:53:05,783] [10/Thread-1] [INFO] [root] Dask Worker status : running
	[2019-05-31 11:53:10,788] [10/Thread-1] [INFO] [root] Dask Worker status : running