Diagnose why the ophyd.EpicsMotor support stalls, as reported

Response from current code:

(bsmotor) mintadmin@mint-vm:~/.../eclipse/bstesting$ ./test3.py 10
Loading metadata history from /home/mintadmin/.config/bluesky/bluesky_history.db
ping 1:  0.1 0.1
m1:  92%|██████████████████████████████████████████████████████████████████████████████████       | 0.1845/0.2 [00:00<00:00,  1.51s/degrees]
/home/mintadmin/Apps/anaconda/envs/bsmotor/lib/python3.7/site-packages/tqdm/std.py:484: TqdmWarning: clamping frac to range [0, 1]
pong 1:  -0.1 -0.1                                                                                                                          
ping 2:  0.1 0.1                                                                                                                            
m1: 100%|████████████████████████████████████████████████████████████████████████████████████████████| 0.2/0.2 [00:00<00:00,  3.95s/degrees]

failed in second cycle

The Approach to Use

start putting in logging statements and sort out the timing between the things happening on different threads and at the IOC level.

Since the IOC reports time based on timestamps from the record in the IOC, we need to correlate that with the python timestamps (the time at which the information was received from EPICS by python). New values in some fields of the motor record do not automatically update the record's time stamp, such the .DMOV field. The correlation between EPICS and Python time is very important.

Using ophyd 1.3.3, the ping_pong() plan also stalls. Seems to run a few more cycles but still stalls.

Another diagnostic to test if the problem is a TimeoutError with get() or a status object problem:

import itertools

for i in enumerate(itertools.count()):
    print(i, m1.motor_egu.get())

This process about 1k cycles/s and does not fail after 250,000 iterations (and continuing).

Not the problem.

Worked through this on a conference call with others on the team. Problem was not reproducible by the others on the call. We tried ophyd 1.4.0rc3, 1.3.3, and a custom branch of 1.4.0rc3. With 1.3.3 problem happens after more cycles than 1.4.0rc3 on my VM but not on the others' workstations.

I will try to reproduce on other workstations, especially on a workstation others might be able to access.

Ken Lauer showed an additional low-level diagnostic flag available in the ophyd.EventDispatcher: debug_monitor=False (default). Setting to True when this is called will provide more details and that is the substance of the custom branch mentioned above.

Ken believes the problem is in how ophyd works with PyEpics to handle PV callbacks.

Dan allan suggest that the changes we want from ophyd 1.4 (involving ScalerCH) can be backported, with other changes, to a new release 1.3.4. The master ophyd branch has code that provokes this problem more and should not be used for production work. The master branch is not in a position that it can be released very soon.

@danielballan : I could work around my desire to use ophyd 1.4+ because of changes I made to the ScalerCH class. I could add that modified device to apstools in the interim until a new ophyd can be released. Would that help?

To run my IOC is a docker environment:

cd /tmp
wget https://raw.githubusercontent.com/prjemian/epics-docker/master/n3_synApps/start_xxx.sh
chmod +x start_xxx.sh
./start_xxx.sh sky

then test that IOC

caget sky:UPTIME sky:m1.DESC

Smallest example that reproduces this error: https://github.com/prjemian/bstesting/blob/master/test3.py

(bsmotor) mintadmin@mint-vm:~/.../eclipse/bstesting$ ./test3.py 10
ping 1:  0.1 0.1                                                                                                                            
m1:  93%|██████████████████████████████████████████████████████████████████████████████████▉      | 0.1865/0.2 [00:00<00:00,  1.62s/degrees]
/home/mintadmin/Apps/anaconda/envs/bsmotor/lib/python3.7/site-packages/tqdm/std.py:484: TqdmWarning: clamping frac to range [0, 1]
pong 1:  -0.1 -0.1                                                                                                                          
ping 2:  0.1 0.1                                                                                                                            
m1: 100%|████████████████████████████████████████████████████████████████████████████████████████████| 0.2/0.2 [00:00<00:00,  3.98s/degrees]

Did not reproduce on poof (linux mint system with lots of cores and RAM).

This change:

    ---: print(msg)
    +++: print(msg, os.system("uptime"))

changes things enough that the problem (not solved) takes much longer to appear. Was stalling after 1 or 2 cycles, now stalling after dozens of cycles. Also, configured the development VM for 2 cores (was 1 core).

Even with https://github.com/bluesky/ophyd/pull/787#issuecomment-568203881, still fails quickly on my VM:

./test3.py 1000 2>&1 | tee /tmp/output.log

``` [D 13:08:34.239 ophydobj:187] This is the first instance of OphydObject. name={self.name}, id={id(self)} [D 13:08:34.240 ophydobj:187] This is the first instance of OphydObject. name={self.name}, id={id(self)} [D 13:08:34.241 ophydobj:187] This is the first instance of OphydObject. name={self.name}, id={id(self)} [D 13:08:34.293 epics_motor:237] [ts=2019-12-21 13:07:15.62474] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: False (value=1) [D 13:08:34.363 epics_motor:237] [ts=2019-12-21 13:07:15.62474] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: True (value=0) m1: 50%|███████████████▌ | 0.1/0.2 [00:00<00:00, 2.06s/degrees] [A m1: 85%|█████████████████████████▌ | 0.17/0.2 [00:00<00:00, 1.80s/degrees] [A m1: 100%|███████████████████████████████| 0.2/0.2 [00:00<00:00, 2.04s/degrees] [A[D 13:08:34.863 epics_motor:237] [ts=2019-12-21 13:08:34.86247] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: False (value=1) m1 [Complete.] [A [A2019-12-21 13:08:34.865754 ping 1: 0.1 0.1 [D 13:08:34.869 epics_motor:237] [ts=2019-12-21 13:08:34.86247] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: True (value=0) m1: 45%|█████████████▍ | 0.09/0.2 [00:00<00:00, 2.21s/degrees] [A m1: 85%|█████████████████████████▌ | 0.17/0.2 [00:00<00:00, 1.76s/degrees] [A m1: 100%|███████████████████████████████| 0.2/0.2 [00:00<00:00, 2.00s/degrees] [A[D 13:08:35.366 epics_motor:237] [ts=2019-12-21 13:08:35.36507] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: False (value=1) m1 [Complete.] [A [A2019-12-21 13:08:35.371632 pong 1: -0.1 -0.1 [D 13:08:35.376 epics_motor:237] [ts=2019-12-21 13:08:35.36507] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: True (value=0) m1: 45%|█████████████▍ | 0.09/0.2 [00:00<00:00, 2.15s/degrees] [A m1: 85%|█████████████████████████▌ | 0.17/0.2 [00:00<00:00, 1.74s/degrees] [A m1: 100%|███████████████████████████████| 0.2/0.2 [00:00<00:00, 1.98s/degrees] [A[D 13:08:35.869 epics_motor:237] [ts=2019-12-21 13:08:35.86850] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: False (value=1) m1 [Complete.] [A [A2019-12-21 13:08:35.873292 ping 2: 0.1 0.1 [D 13:08:35.875 epics_motor:237] [ts=2019-12-21 13:08:35.86850] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: True (value=0) m1: 45%|█████████████▍ | 0.09/0.2 [00:00<00:00, 2.24s/degrees] [A m1: 85%|█████████████████████████▌ | 0.17/0.2 [00:00<00:00, 1.76s/degrees] [A m1: 100%|███████████████████████████████| 0.2/0.2 [00:00<00:00, 2.01s/degrees] [A[D 13:08:36.374 epics_motor:237] [ts=2019-12-21 13:08:36.37297] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: False (value=1) m1 [Complete.] [A [A2019-12-21 13:08:36.378595 pong 2: -0.1 -0.1 [D 13:08:36.381 epics_motor:237] [ts=2019-12-21 13:08:36.37297] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: True (value=0) m1: 45%|█████████████▍ | 0.09/0.2 [00:00<00:00, 2.16s/degrees] [A m1: 85%|█████████████████████████▌ | 0.17/0.2 [00:00<00:00, 1.74s/degrees] [A m1: 100%|███████████████████████████████| 0.2/0.2 [00:00<00:00, 1.98s/degrees] [A[D 13:08:36.875 epics_motor:237] [ts=2019-12-21 13:08:36.87488] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: False (value=1) ```

camonitor -tc sky:m1.{DMOV,VAL,RBV} 2>&1 | tee /tmp/camonitor.log

``` sky:m1.DMOV (2019-12-21 13:08:19.861562) 1 sky:m1.VAL (2019-12-21 13:08:19.861627) -0.1 sky:m1.RBV (2019-12-21 13:08:19.861637) -0.1 sky:m1.DMOV (2019-12-21 13:08:34.359826) 0 sky:m1.VAL (2019-12-21 13:08:34.359856) 0.1 sky:m1.RBV (2019-12-21 13:08:34.454223) -0.08 sky:m1.RBV (2019-12-21 13:08:34.560073) 0 sky:m1.RBV (2019-12-21 13:08:34.660193) 0.07 sky:m1.RBV (2019-12-21 13:08:34.762120) 0.1 sky:m1.DMOV (2019-12-21 13:08:34.862665) 1 sky:m1.DMOV (2019-12-21 13:08:34.868328) 0 sky:m1.VAL (2019-12-21 13:08:34.868360) -0.1 sky:m1.RBV (2019-12-21 13:08:34.963311) 0.08 sky:m1.RBV (2019-12-21 13:08:35.064886) 0.01 sky:m1.RBV (2019-12-21 13:08:35.164608) -0.07 sky:m1.RBV (2019-12-21 13:08:35.266161) -0.1 sky:m1.DMOV (2019-12-21 13:08:35.365282) 1 sky:m1.DMOV (2019-12-21 13:08:35.375885) 0 sky:m1.VAL (2019-12-21 13:08:35.375918) 0.1 sky:m1.RBV (2019-12-21 13:08:35.465394) -0.08 sky:m1.RBV (2019-12-21 13:08:35.565870) -0.01 sky:m1.RBV (2019-12-21 13:08:35.666916) 0.07 sky:m1.RBV (2019-12-21 13:08:35.768187) 0.1 sky:m1.DMOV (2019-12-21 13:08:35.868839) 1 sky:m1.DMOV (2019-12-21 13:08:35.875193) 0 sky:m1.VAL (2019-12-21 13:08:35.875250) -0.1 sky:m1.RBV (2019-12-21 13:08:35.971607) 0.08 sky:m1.RBV (2019-12-21 13:08:36.074940) 0.01 sky:m1.RBV (2019-12-21 13:08:36.172844) -0.07 sky:m1.RBV (2019-12-21 13:08:36.274668) -0.1 sky:m1.DMOV (2019-12-21 13:08:36.373254) 1 sky:m1.DMOV (2019-12-21 13:08:36.382170) 0 sky:m1.VAL (2019-12-21 13:08:36.382203) 0.1 sky:m1.RBV (2019-12-21 13:08:36.473451) -0.08 sky:m1.RBV (2019-12-21 13:08:36.574033) -0.01 sky:m1.RBV (2019-12-21 13:08:36.674654) 0.07 sky:m1.RBV (2019-12-21 13:08:36.774913) 0.1 sky:m1.DMOV (2019-12-21 13:08:36.875061) 1 ```

Ran with additional debug and note that stall happens when trying to read the low limit switch value:

[D 13:21:10.849 epics_motor:237] [ts=2019-12-21 13:21:10.84419] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: True (value=0)
[D 13:21:11.397 epics_motor:237] [ts=2019-12-21 13:21:11.39658] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: False (value=1)
[D 13:21:11.397 signal:854] m1_direction_of_travel.get(): set timeout=1.000000
[D 13:21:11.398 signal:854] m1_low_limit_switch.get(): set timeout=1.000000
2019-12-21 13:21:11.399525 ping 14:  0.1 0.1                                   
[D 13:21:11.400 signal:854] m1_motor_egu.get(): set timeout=1.000000
[D 13:21:11.401 epics_motor:237] [ts=2019-12-21 13:21:11.39658] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: True (value=0)
[D 13:21:11.900 epics_motor:237] [ts=2019-12-21 13:21:11.89947] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: False (value=1)
[D 13:21:11.901 signal:854] m1_direction_of_travel.get(): set timeout=1.000000
[D 13:21:11.901 signal:854] m1_low_limit_switch.get(): set timeout=1.000000
2019-12-21 13:21:11.902433 pong 14:  -0.1 -0.1                                 
[D 13:21:11.902 signal:854] m1_motor_egu.get(): set timeout=1.000000
[D 13:21:11.904 epics_motor:237] [ts=2019-12-21 13:21:11.89947] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: True (value=0)
[D 13:21:12.403 epics_motor:237] [ts=2019-12-21 13:21:12.40243] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: False (value=1)
[D 13:21:12.403 signal:854] m1_direction_of_travel.get(): set timeout=1.000000
[D 13:21:12.404 signal:854] m1_low_limit_switch.get(): set timeout=1.000000

Note this comes (13:21:12.404 ) after EPICS has reported the motor is done moving (13:21:12.402612):

sky:m1.VAL                     (2019-12-21 13:21:11.401031) -0.1  
sky:m1.RBV                     (2019-12-21 13:21:11.497524) 0.08  
sky:m1.RBV                     (2019-12-21 13:21:11.598516) 0.01  
sky:m1.RBV                     (2019-12-21 13:21:11.698650) -0.07  
sky:m1.RBV                     (2019-12-21 13:21:11.798784) -0.1  
sky:m1.DMOV                    (2019-12-21 13:21:11.899793) 1  
sky:m1.DMOV                    (2019-12-21 13:21:11.903649) 0  
sky:m1.VAL                     (2019-12-21 13:21:11.903670) 0.1  
sky:m1.RBV                     (2019-12-21 13:21:11.999932) -0.08  
sky:m1.RBV                     (2019-12-21 13:21:12.100720) -0.01  
sky:m1.RBV                     (2019-12-21 13:21:12.201509) 0.07  
sky:m1.RBV                     (2019-12-21 13:21:12.302476) 0.1  
sky:m1.DMOV                    (2019-12-21 13:21:12.402612) 1

Ran several (>5) times, always stalls with m1_low_limit_switch.get(). Something to explore there why that specifically.

This code (https://github.com/bluesky/ophyd/blob/11c5c80e6ff2cd73fd1a9c5b34de46c3007f031f/ophyd/epics_motor.py#L245-L248):

            # Check if we are moving towards the low limit switch
            if self.direction_of_travel.get() == 0:
                if self.low_limit_switch.get() == 1:
                    success = False

added time.time() to debug message:

[D 13:42:27.040 signal:856] m1_direction_of_travel.get(): set timeout=1.000000  (1576957347.040645)
[D 13:42:27.041 signal:856] m1_low_limit_switch.get(): set timeout=1.000000  (1576957347.041287)

0.642 ms time difference between these two calls to get()

Always times out when reading low limit switch value. Might be time for a wireshark.

Always times out after reading limit switch, after call to self._done_moving(). Foud this out by adding more diagnostics to _move_changed().

[D 15:39:53.669 epics_motor:237] [ts=2019-12-21 15:39:53.66901] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: False (value=1)
[D 15:39:53.670 signal:856] m1_direction_of_travel.get(): set timeout=1.000000  (1576964393.670607)
[D 15:39:53.671 signal:856] m1_low_limit_switch.get(): set timeout=1.000000  (1576964393.671289)
[D 15:39:53.672 epics_motor:255] m1._move_changed(): limit switch check success=True
[D 15:39:53.672 epics_motor:276] m1._move_changed(): before _done_moving() success=True  value=1
2019-12-21 15:39:53.673493 ping 8:  0.1 0.1                                                                                                 
[D 15:39:53.674 signal:856] m1_motor_egu.get(): set timeout=1.000000  (1576964393.674592)
[D 15:39:53.677 epics_motor:283] m1._move_changed(): after _done_moving() success=True  value=1
[D 15:39:53.678 epics_motor:237] [ts=2019-12-21 15:39:53.66901] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: True (value=0)
[D 15:39:54.171 epics_motor:237] [ts=2019-12-21 15:39:54.17045] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: False (value=1)
[D 15:39:54.172 signal:856] m1_direction_of_travel.get(): set timeout=1.000000  (1576964394.172128)
[D 15:39:54.173 signal:856] m1_low_limit_switch.get(): set timeout=1.000000  (1576964394.173743)
[D 15:39:54.174 epics_motor:255] m1._move_changed(): limit switch check success=True
[D 15:39:54.175 epics_motor:276] m1._move_changed(): before _done_moving() success=True  value=1
[D 15:39:54.175 epics_motor:283] m1._move_changed(): after _done_moving() success=True  value=1

add more diagnostics to show terms used in call to _run_subs() from _done_moving():

[D 16:26:53.533 signal:856] m1_direction_of_travel.get(): set timeout=1.000000  (1576967213.533783)
[D 16:26:53.537 signal:856] m1_low_limit_switch.get(): set timeout=1.000000  (1576967213.537418)
[D 16:26:53.542 epics_motor:273] m1._move_changed(): before _done_moving() success=True  value=1
[D 16:26:53.543 positioner:203] subscription names: {'_req_done', 'acq_done', 'readback', 'start_moving', 'done_moving'}
[D 16:26:53.544 positioner:204] m1._args_cache[done_moving]=((), {'timestamp': 1576967213.019101, 'value': 1, 'sub_type': 'done_moving', 'obj': EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])})
[D 16:26:53.548 positioner:205] m1._callbacks[done_moving]={}
[D 16:26:53.549 positioner:206] m1._done_moving() sub_type=done_moving value=1
2019-12-21 16:26:53.550177 pong 17:  -0.1 -0.1                                                                                              
[D 16:26:53.551 signal:856] m1_motor_egu.get(): set timeout=1.000000  (1576967213.551482)
[D 16:26:53.556 epics_motor:280] m1._move_changed(): after _done_moving() success=True  value=1
[D 16:26:53.556 epics_motor:237] [ts=2019-12-21 16:26:53.52697] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: True (value=0)
[D 16:26:54.031 epics_motor:237] [ts=2019-12-21 16:26:54.03105] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: False (value=1)
[D 16:26:54.032 signal:856] m1_direction_of_travel.get(): set timeout=1.000000  (1576967214.032564)
[D 16:26:54.033 signal:856] m1_low_limit_switch.get(): set timeout=1.000000  (1576967214.033226)
[D 16:26:54.033 epics_motor:273] m1._move_changed(): before _done_moving() success=True  value=1
[D 16:26:54.034 positioner:203] subscription names: {'_req_done', 'acq_done', 'readback', 'start_moving', 'done_moving'}
[D 16:26:54.034 positioner:204] m1._args_cache[done_moving]=((), {'timestamp': 1576967213.526967, 'value': 1, 'sub_type': 'done_moving', 'obj': EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])})
[D 16:26:54.035 positioner:205] m1._callbacks[done_moving]={}
[D 16:26:54.036 positioner:206] m1._done_moving() sub_type=done_moving value=1
[D 16:26:54.036 epics_motor:280] m1._move_changed(): after _done_moving() success=True  value=1

There are no callback functions registered under sub_type="done_moving"

Interesting note (that is not the problem we are working on), the code block mentioned above:

            # Check if we are moving towards the low limit switch
            if self.direction_of_travel.get() == 0:
                if self.low_limit_switch.get() == 1:
                    success = False

always checks the low_limit_switch regardless of whether the move is positive or negative. Expecting self.direction_of_travel.get() == 1 half the time.

A new move starts before the end of _done_moving() in epics_motor. Is that a symptom?

test3 with more diagnostics

``` (bsmotor) mintadmin@mint-vm:~/.../eclipse/bstesting$ ./test3.py 100 2>&1 | tee /tmp/ouput.log [D 16:47:46.809 ophydobj:187] This is the first instance of OphydObject. name={self.name}, id={id(self)} [D 16:47:46.809 ophydobj:187] This is the first instance of OphydObject. name={self.name}, id={id(self)} [D 16:47:46.815 ophydobj:187] This is the first instance of OphydObject. name={self.name}, id={id(self)} [D 16:47:46.905 epics_motor:238] [ts=2019-12-21 16:47:21.29064] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: False (value=1) [D 16:47:46.989 epics_motor:147] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() [D 16:47:46.989 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1576968466.989409) [D 16:47:47.010 epics_motor:238] [ts=2019-12-21 16:47:21.29064] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: True (value=0) [D 16:47:47.502 epics_motor:238] [ts=2019-12-21 16:47:47.50242] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: False (value=1) [D 16:47:47.503 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1576968467.503721) [D 16:47:47.504 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1576968467.504597) [D 16:47:47.505 epics_motor:274] m1._move_changed(): before _done_moving() success=True value=1 [D 16:47:47.505 positioner:202] subscription names: {'acq_done', '_req_done', 'readback', 'done_moving', 'start_moving'} [D 16:47:47.505 positioner:204] m1._callbacks[done_moving]={} [D 16:47:47.505 positioner:205] m1._done_moving() sub_type=done_moving value=1 [D 16:47:47.506 ophydobj:396] sub_type=_req_done callback= 2019-12-21 16:47:47.506710 ping 1: 0.1 0.1 [D 16:47:47.507 epics_motor:147] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() [D 16:47:47.507 ophydobj:396] sub_type=_req_done callback= [D 16:47:47.507 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1576968467.507446) [D 16:47:47.507 epics_motor:281] m1._move_changed(): after _done_moving() success=True value=1 [D 16:47:47.509 epics_motor:238] [ts=2019-12-21 16:47:47.50242] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: True (value=0) [D 16:47:48.005 epics_motor:238] [ts=2019-12-21 16:47:48.00478] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: False (value=1) [D 16:47:48.006 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1576968468.006593) [D 16:47:48.010 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1576968468.010352) [D 16:47:48.011 epics_motor:274] m1._move_changed(): before _done_moving() success=True value=1 [D 16:47:48.011 positioner:202] subscription names: {'acq_done', '_req_done', 'readback', 'done_moving', 'start_moving'} [D 16:47:48.012 positioner:204] m1._callbacks[done_moving]={} [D 16:47:48.012 positioner:205] m1._done_moving() sub_type=done_moving value=1 [D 16:47:48.012 ophydobj:396] sub_type=_req_done callback= 2019-12-21 16:47:48.013085 pong 1: -0.1 -0.1 [D 16:47:48.013 epics_motor:147] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() [D 16:47:48.013 ophydobj:396] sub_type=_req_done callback= [D 16:47:48.013 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1576968468.013911) [D 16:47:48.014 epics_motor:281] m1._move_changed(): after _done_moving() success=True value=1 [D 16:47:48.024 epics_motor:238] [ts=2019-12-21 16:47:48.00478] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: True (value=0) [D 16:47:48.512 epics_motor:238] [ts=2019-12-21 16:47:48.51217] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: False (value=1) [D 16:47:48.513 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1576968468.513581) [D 16:47:48.514 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1576968468.514470) [D 16:47:48.515 epics_motor:274] m1._move_changed(): before _done_moving() success=True value=1 [D 16:47:48.515 positioner:202] subscription names: {'acq_done', '_req_done', 'readback', 'done_moving', 'start_moving'} [D 16:47:48.515 positioner:204] m1._callbacks[done_moving]={} [D 16:47:48.515 positioner:205] m1._done_moving() sub_type=done_moving value=1 [D 16:47:48.515 ophydobj:396] sub_type=_req_done callback= 2019-12-21 16:47:48.516165 ping 2: 0.1 0.1 [D 16:47:48.516 epics_motor:147] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() [D 16:47:48.516 ophydobj:396] sub_type=_req_done callback= [D 16:47:48.516 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1576968468.516900) [D 16:47:48.517 epics_motor:281] m1._move_changed(): after _done_moving() success=True value=1 [D 16:47:48.518 epics_motor:238] [ts=2019-12-21 16:47:48.51217] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: True (value=0) [D 16:47:49.017 epics_motor:238] [ts=2019-12-21 16:47:49.01716] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: False (value=1) [D 16:47:49.018 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1576968469.018490) [D 16:47:49.019 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1576968469.019346) [D 16:47:49.019 epics_motor:274] m1._move_changed(): before _done_moving() success=True value=1 [D 16:47:49.020 positioner:202] subscription names: {'acq_done', '_req_done', 'readback', 'done_moving', 'start_moving'} [D 16:47:49.020 positioner:204] m1._callbacks[done_moving]={} [D 16:47:49.020 positioner:205] m1._done_moving() sub_type=done_moving value=1 [D 16:47:49.020 ophydobj:396] sub_type=_req_done callback= [D 16:47:49.020 epics_motor:281] m1._move_changed(): after _done_moving() success=True value=1 2019-12-21 16:47:49.021011 pong 2: -0.1 -0.1 [D 16:47:49.021 epics_motor:147] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() [D 16:47:49.021 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1576968469.021564) [D 16:47:49.023 epics_motor:238] [ts=2019-12-21 16:47:49.01716] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: True (value=0) [D 16:47:49.518 epics_motor:238] [ts=2019-12-21 16:47:49.51845] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: False (value=1) [D 16:47:49.519 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1576968469.519642) [D 16:47:49.520 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1576968469.520360) [D 16:47:49.520 epics_motor:274] m1._move_changed(): before _done_moving() success=True value=1 [D 16:47:49.520 positioner:202] subscription names: {'acq_done', '_req_done', 'readback', 'done_moving', 'start_moving'} [D 16:47:49.521 positioner:204] m1._callbacks[done_moving]={} [D 16:47:49.521 positioner:205] m1._done_moving() sub_type=done_moving value=1 [D 16:47:49.521 ophydobj:396] sub_type=_req_done callback= [D 16:47:49.521 epics_motor:281] m1._move_changed(): after _done_moving() success=True value=1 2019-12-21 16:47:49.521808 ping 3: 0.1 0.1 [D 16:47:49.522 epics_motor:147] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() [D 16:47:49.522 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1576968469.522450) [D 16:47:49.524 epics_motor:238] [ts=2019-12-21 16:47:49.51845] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: True (value=0) [D 16:47:50.022 epics_motor:238] [ts=2019-12-21 16:47:50.02218] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: False (value=1) [D 16:47:50.023 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1576968470.023397) [D 16:47:50.026 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1576968470.026478) [D 16:47:50.028 epics_motor:274] m1._move_changed(): before _done_moving() success=True value=1 [D 16:47:50.028 positioner:202] subscription names: {'acq_done', '_req_done', 'readback', 'done_moving', 'start_moving'} [D 16:47:50.028 positioner:204] m1._callbacks[done_moving]={} [D 16:47:50.028 positioner:205] m1._done_moving() sub_type=done_moving value=1 [D 16:47:50.028 ophydobj:396] sub_type=_req_done callback= 2019-12-21 16:47:50.028942 pong 3: -0.1 -0.1 [D 16:47:50.029 epics_motor:147] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() [D 16:47:50.029 ophydobj:396] sub_type=_req_done callback= [D 16:47:50.029 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1576968470.029636) [D 16:47:50.029 epics_motor:281] m1._move_changed(): after _done_moving() success=True value=1 [D 16:47:50.034 epics_motor:238] [ts=2019-12-21 16:47:50.02218] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: True (value=0) [D 16:47:50.527 epics_motor:238] [ts=2019-12-21 16:47:50.52641] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: False (value=1) [D 16:47:50.528 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1576968470.528162) [D 16:47:50.529 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1576968470.529377) [D 16:47:50.530 epics_motor:274] m1._move_changed(): before _done_moving() success=True value=1 [D 16:47:50.530 positioner:202] subscription names: {'acq_done', '_req_done', 'readback', 'done_moving', 'start_moving'} [D 16:47:50.530 positioner:204] m1._callbacks[done_moving]={} [D 16:47:50.530 positioner:205] m1._done_moving() sub_type=done_moving value=1 [D 16:47:50.530 ophydobj:396] sub_type=_req_done callback= 2019-12-21 16:47:50.530985 ping 4: 0.1 0.1 [D 16:47:50.531 epics_motor:147] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() [D 16:47:50.531 ophydobj:396] sub_type=_req_done callback= [D 16:47:50.531 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1576968470.531628) [D 16:47:50.531 epics_motor:281] m1._move_changed(): after _done_moving() success=True value=1 [D 16:47:50.533 epics_motor:238] [ts=2019-12-21 16:47:50.52641] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: True (value=0) [D 16:47:51.035 epics_motor:238] [ts=2019-12-21 16:47:51.03428] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: False (value=1) [D 16:47:51.035 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1576968471.035666) [D 16:47:51.036 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1576968471.036453) [D 16:47:51.037 epics_motor:274] m1._move_changed(): before _done_moving() success=True value=1 [D 16:47:51.037 positioner:202] subscription names: {'acq_done', '_req_done', 'readback', 'done_moving', 'start_moving'} [D 16:47:51.037 positioner:204] m1._callbacks[done_moving]={} [D 16:47:51.037 positioner:205] m1._done_moving() sub_type=done_moving value=1 [D 16:47:51.037 ophydobj:396] sub_type=_req_done callback= 2019-12-21 16:47:51.037853 pong 4: -0.1 -0.1 [D 16:47:51.038 epics_motor:147] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() [D 16:47:51.038 ophydobj:396] sub_type=_req_done callback= [D 16:47:51.038 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1576968471.038542) [D 16:47:51.038 epics_motor:281] m1._move_changed(): after _done_moving() success=True value=1 [D 16:47:51.040 epics_motor:238] [ts=2019-12-21 16:47:51.03428] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: True (value=0) [D 16:47:51.545 epics_motor:238] [ts=2019-12-21 16:47:51.54511] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: False (value=1) [D 16:47:51.546 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1576968471.546359) [D 16:47:51.546 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1576968471.546983) [D 16:47:51.547 epics_motor:274] m1._move_changed(): before _done_moving() success=True value=1 [D 16:47:51.547 positioner:202] subscription names: {'acq_done', '_req_done', 'readback', 'done_moving', 'start_moving'} [D 16:47:51.547 positioner:204] m1._callbacks[done_moving]={} [D 16:47:51.547 positioner:205] m1._done_moving() sub_type=done_moving value=1 [D 16:47:51.547 ophydobj:396] sub_type=_req_done callback= [D 16:47:51.547 epics_motor:281] m1._move_changed(): after _done_moving() success=True value=1 2019-12-21 16:47:51.548343 ping 5: 0.1 0.1 [D 16:47:51.548 epics_motor:147] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() [D 16:47:51.548 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1576968471.548877) [D 16:47:51.550 epics_motor:238] [ts=2019-12-21 16:47:51.54511] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: True (value=0) [D 16:47:52.050 epics_motor:238] [ts=2019-12-21 16:47:52.04984] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: False (value=1) [D 16:47:52.051 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1576968472.051146) [D 16:47:52.051 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1576968472.051905) [D 16:47:52.052 epics_motor:274] m1._move_changed(): before _done_moving() success=True value=1 [D 16:47:52.052 positioner:202] subscription names: {'acq_done', '_req_done', 'readback', 'done_moving', 'start_moving'} [D 16:47:52.052 positioner:204] m1._callbacks[done_moving]={} [D 16:47:52.052 positioner:205] m1._done_moving() sub_type=done_moving value=1 [D 16:47:52.053 ophydobj:396] sub_type=_req_done callback= [D 16:47:52.053 epics_motor:281] m1._move_changed(): after _done_moving() success=True value=1 2019-12-21 16:47:52.053899 pong 5: -0.1 -0.1 [D 16:47:52.054 epics_motor:147] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() [D 16:47:52.054 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1576968472.054682) [D 16:47:52.056 epics_motor:238] [ts=2019-12-21 16:47:52.04984] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: True (value=0) [D 16:47:52.556 epics_motor:238] [ts=2019-12-21 16:47:52.55490] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: False (value=1) [D 16:47:52.557 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1576968472.557497) [D 16:47:52.562 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1576968472.562449) [D 16:47:52.566 epics_motor:274] m1._move_changed(): before _done_moving() success=True value=1 [D 16:47:52.566 positioner:202] subscription names: {'acq_done', '_req_done', 'readback', 'done_moving', 'start_moving'} [D 16:47:52.567 positioner:204] m1._callbacks[done_moving]={} [D 16:47:52.567 positioner:205] m1._done_moving() sub_type=done_moving value=1 [D 16:47:52.567 ophydobj:396] sub_type=_req_done callback= [D 16:47:52.567 epics_motor:281] m1._move_changed(): after _done_moving() success=True value=1 2019-12-21 16:47:52.569683 ping 6: 0.1 0.1 [D 16:47:52.570 epics_motor:147] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() [D 16:47:52.570 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1576968472.570439) [D 16:47:52.587 epics_motor:238] [ts=2019-12-21 16:47:52.55490] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: True (value=0) [D 16:47:53.058 epics_motor:238] [ts=2019-12-21 16:47:53.05740] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: False (value=1) [D 16:47:53.064 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1576968473.059397) [D 16:47:53.070 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1576968473.069982) [D 16:47:53.076 epics_motor:274] m1._move_changed(): before _done_moving() success=True value=1 [D 16:47:53.076 positioner:202] subscription names: {'acq_done', '_req_done', 'readback', 'done_moving', 'start_moving'} [D 16:47:53.076 positioner:204] m1._callbacks[done_moving]={} [D 16:47:53.076 positioner:205] m1._done_moving() sub_type=done_moving value=1 [D 16:47:53.077 ophydobj:396] sub_type=_req_done callback= 2019-12-21 16:47:53.078793 pong 6: -0.1 -0.1 [D 16:47:53.080 epics_motor:147] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() [D 16:47:53.081 ophydobj:396] sub_type=_req_done callback= [D 16:47:53.081 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1576968473.081933) [D 16:47:53.082 epics_motor:281] m1._move_changed(): after _done_moving() success=True value=1 [D 16:47:53.086 epics_motor:238] [ts=2019-12-21 16:47:53.05740] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: True (value=0) [D 16:47:53.561 epics_motor:238] [ts=2019-12-21 16:47:53.56011] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: False (value=1) [D 16:47:53.562 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1576968473.562605) [D 16:47:53.564 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1576968473.564286) [D 16:47:53.565 epics_motor:274] m1._move_changed(): before _done_moving() success=True value=1 [D 16:47:53.566 positioner:202] subscription names: {'acq_done', '_req_done', 'readback', 'done_moving', 'start_moving'} [D 16:47:53.566 positioner:204] m1._callbacks[done_moving]={} [D 16:47:53.566 positioner:205] m1._done_moving() sub_type=done_moving value=1 [D 16:47:53.566 ophydobj:396] sub_type=_req_done callback= 2019-12-21 16:47:53.568638 ping 7: 0.1 0.1 [D 16:47:53.569 epics_motor:147] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() [D 16:47:53.569 ophydobj:396] sub_type=_req_done callback= [D 16:47:53.570 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1576968473.570013) [D 16:47:53.570 epics_motor:281] m1._move_changed(): after _done_moving() success=True value=1 [D 16:47:53.576 epics_motor:238] [ts=2019-12-21 16:47:53.56011] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: True (value=0) [D 16:47:54.063 epics_motor:238] [ts=2019-12-21 16:47:54.06255] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: False (value=1) [D 16:47:54.065 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1576968474.065479) [D 16:47:54.067 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1576968474.067404) [D 16:47:54.068 epics_motor:274] m1._move_changed(): before _done_moving() success=True value=1 [D 16:47:54.068 positioner:202] subscription names: {'acq_done', '_req_done', 'readback', 'done_moving', 'start_moving'} [D 16:47:54.068 positioner:204] m1._callbacks[done_moving]={} [D 16:47:54.068 positioner:205] m1._done_moving() sub_type=done_moving value=1 [D 16:47:54.069 ophydobj:396] sub_type=_req_done callback= [D 16:47:54.069 epics_motor:281] m1._move_changed(): after _done_moving() success=True value=1 2019-12-21 16:47:54.071454 pong 7: -0.1 -0.1 [D 16:47:54.072 epics_motor:147] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() [D 16:47:54.073 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1576968474.073360) [D 16:47:54.076 epics_motor:238] [ts=2019-12-21 16:47:54.06255] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: True (value=0) [D 16:47:54.567 epics_motor:238] [ts=2019-12-21 16:47:54.56657] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: False (value=1) [D 16:47:54.568 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1576968474.568682) [D 16:47:54.569 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1576968474.569432) [D 16:47:54.570 epics_motor:274] m1._move_changed(): before _done_moving() success=True value=1 [D 16:47:54.570 positioner:202] subscription names: {'acq_done', '_req_done', 'readback', 'done_moving', 'start_moving'} [D 16:47:54.570 positioner:204] m1._callbacks[done_moving]={} [D 16:47:54.570 positioner:205] m1._done_moving() sub_type=done_moving value=1 [D 16:47:54.570 ophydobj:396] sub_type=_req_done callback= 2019-12-21 16:47:54.571302 ping 8: 0.1 0.1 [D 16:47:54.571 epics_motor:147] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() [D 16:47:54.572 ophydobj:396] sub_type=_req_done callback= [D 16:47:54.572 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1576968474.572248) [D 16:47:54.572 epics_motor:281] m1._move_changed(): after _done_moving() success=True value=1 [D 16:47:54.577 epics_motor:238] [ts=2019-12-21 16:47:54.56657] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: True (value=0) [D 16:47:55.079 epics_motor:238] [ts=2019-12-21 16:47:55.07831] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: False (value=1) [D 16:47:55.079 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1576968475.079806) [D 16:47:55.080 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1576968475.080416) [D 16:47:55.081 epics_motor:274] m1._move_changed(): before _done_moving() success=True value=1 [D 16:47:55.081 positioner:202] subscription names: {'acq_done', '_req_done', 'readback', 'done_moving', 'start_moving'} [D 16:47:55.081 positioner:204] m1._callbacks[done_moving]={} [D 16:47:55.081 positioner:205] m1._done_moving() sub_type=done_moving value=1 [D 16:47:55.081 ophydobj:396] sub_type=_req_done callback= [D 16:47:55.081 epics_motor:281] m1._move_changed(): after _done_moving() success=True value=1 2019-12-21 16:47:55.082123 pong 8: -0.1 -0.1 [D 16:47:55.082 epics_motor:147] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() [D 16:47:55.082 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1576968475.082803) [D 16:47:55.084 epics_motor:238] [ts=2019-12-21 16:47:55.07831] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: True (value=0) [D 16:47:55.582 epics_motor:238] [ts=2019-12-21 16:47:55.58166] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: False (value=1) [D 16:47:55.582 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1576968475.582916) [D 16:47:55.583 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1576968475.583675) [D 16:47:55.584 epics_motor:274] m1._move_changed(): before _done_moving() success=True value=1 [D 16:47:55.584 positioner:202] subscription names: {'acq_done', '_req_done', 'readback', 'done_moving', 'start_moving'} [D 16:47:55.584 positioner:204] m1._callbacks[done_moving]={} [D 16:47:55.584 positioner:205] m1._done_moving() sub_type=done_moving value=1 [D 16:47:55.584 ophydobj:396] sub_type=_req_done callback= [D 16:47:55.585 epics_motor:281] m1._move_changed(): after _done_moving() success=True value=1 2019-12-21 16:47:55.585787 ping 9: 0.1 0.1 [D 16:47:55.586 epics_motor:147] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() [D 16:47:55.586 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1576968475.586465) [D 16:47:55.588 epics_motor:238] [ts=2019-12-21 16:47:55.58166] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: True (value=0) [D 16:47:56.085 epics_motor:238] [ts=2019-12-21 16:47:56.08470] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: False (value=1) [D 16:47:56.086 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1576968476.086002) [D 16:47:56.086 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1576968476.086677) [D 16:47:56.087 epics_motor:274] m1._move_changed(): before _done_moving() success=True value=1 [D 16:47:56.087 positioner:202] subscription names: {'acq_done', '_req_done', 'readback', 'done_moving', 'start_moving'} [D 16:47:56.087 positioner:204] m1._callbacks[done_moving]={} [D 16:47:56.087 positioner:205] m1._done_moving() sub_type=done_moving value=1 [D 16:47:56.087 ophydobj:396] sub_type=_req_done callback= [D 16:47:56.087 epics_motor:281] m1._move_changed(): after _done_moving() success=True value=1 2019-12-21 16:47:56.088183 pong 9: -0.1 -0.1 [D 16:47:56.088 epics_motor:147] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() [D 16:47:56.088 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1576968476.088784) [D 16:47:56.090 epics_motor:238] [ts=2019-12-21 16:47:56.08470] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: True (value=0) [D 16:47:56.603 epics_motor:238] [ts=2019-12-21 16:47:56.60291] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: False (value=1) [D 16:47:56.604 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1576968476.604367) [D 16:47:56.605 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1576968476.605009) [D 16:47:56.605 epics_motor:274] m1._move_changed(): before _done_moving() success=True value=1 [D 16:47:56.605 positioner:202] subscription names: {'acq_done', '_req_done', 'readback', 'done_moving', 'start_moving'} [D 16:47:56.605 positioner:204] m1._callbacks[done_moving]={} [D 16:47:56.606 positioner:205] m1._done_moving() sub_type=done_moving value=1 [D 16:47:56.606 ophydobj:396] sub_type=_req_done callback= 2019-12-21 16:47:56.606921 ping 10: 0.1 0.1 [D 16:47:56.607 epics_motor:147] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() [D 16:47:56.607 ophydobj:396] sub_type=_req_done callback= [D 16:47:56.607 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1576968476.607533) [D 16:47:56.607 epics_motor:281] m1._move_changed(): after _done_moving() success=True value=1 [D 16:47:56.609 epics_motor:238] [ts=2019-12-21 16:47:56.60291] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: True (value=0) [D 16:47:57.107 epics_motor:238] [ts=2019-12-21 16:47:57.10649] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: False (value=1) [D 16:47:57.108 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1576968477.108055) [D 16:47:57.108 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1576968477.108739) [D 16:47:57.109 epics_motor:274] m1._move_changed(): before _done_moving() success=True value=1 [D 16:47:57.109 positioner:202] subscription names: {'acq_done', '_req_done', 'readback', 'done_moving', 'start_moving'} [D 16:47:57.109 positioner:204] m1._callbacks[done_moving]={} [D 16:47:57.109 positioner:205] m1._done_moving() sub_type=done_moving value=1 [D 16:47:57.109 ophydobj:396] sub_type=_req_done callback= [D 16:47:57.110 epics_motor:281] m1._move_changed(): after _done_moving() success=True value=1 2019-12-21 16:47:57.111378 pong 10: -0.1 -0.1 [D 16:47:57.112 epics_motor:147] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() [D 16:47:57.112 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1576968477.112927) [D 16:47:57.114 epics_motor:238] [ts=2019-12-21 16:47:57.10649] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: True (value=0) [D 16:47:57.611 epics_motor:238] [ts=2019-12-21 16:47:57.61005] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: False (value=1) [D 16:47:57.612 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1576968477.612051) [D 16:47:57.612 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1576968477.612812) [D 16:47:57.613 epics_motor:274] m1._move_changed(): before _done_moving() success=True value=1 [D 16:47:57.613 positioner:202] subscription names: {'acq_done', '_req_done', 'readback', 'done_moving', 'start_moving'} [D 16:47:57.613 positioner:204] m1._callbacks[done_moving]={} [D 16:47:57.613 positioner:205] m1._done_moving() sub_type=done_moving value=1 [D 16:47:57.613 ophydobj:396] sub_type=_req_done callback= 2019-12-21 16:47:57.614519 ping 11: 0.1 0.1 [D 16:47:57.614 epics_motor:147] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() [D 16:47:57.615 ophydobj:396] sub_type=_req_done callback= [D 16:47:57.615 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1576968477.615320) [D 16:47:57.615 epics_motor:281] m1._move_changed(): after _done_moving() success=True value=1 [D 16:47:57.617 epics_motor:238] [ts=2019-12-21 16:47:57.61005] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: True (value=0) [D 16:47:58.113 epics_motor:238] [ts=2019-12-21 16:47:58.11322] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: False (value=1) [D 16:47:58.114 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1576968478.114547) [D 16:47:58.115 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1576968478.115098) [D 16:47:58.115 epics_motor:274] m1._move_changed(): before _done_moving() success=True value=1 [D 16:47:58.115 positioner:202] subscription names: {'acq_done', '_req_done', 'readback', 'done_moving', 'start_moving'} [D 16:47:58.115 positioner:204] m1._callbacks[done_moving]={} [D 16:47:58.115 positioner:205] m1._done_moving() sub_type=done_moving value=1 [D 16:47:58.116 ophydobj:396] sub_type=_req_done callback= [D 16:47:58.116 epics_motor:281] m1._move_changed(): after _done_moving() success=True value=1 2019-12-21 16:47:58.116982 pong 11: -0.1 -0.1 [D 16:47:58.117 epics_motor:147] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() [D 16:47:58.117 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1576968478.117604) [D 16:47:58.119 epics_motor:238] [ts=2019-12-21 16:47:58.11322] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: True (value=0) [D 16:47:58.618 epics_motor:238] [ts=2019-12-21 16:47:58.61803] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: False (value=1) [D 16:47:58.619 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1576968478.619332) [D 16:47:58.620 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1576968478.620002) [D 16:47:58.620 epics_motor:274] m1._move_changed(): before _done_moving() success=True value=1 [D 16:47:58.620 positioner:202] subscription names: {'acq_done', '_req_done', 'readback', 'done_moving', 'start_moving'} [D 16:47:58.620 positioner:204] m1._callbacks[done_moving]={} [D 16:47:58.620 positioner:205] m1._done_moving() sub_type=done_moving value=1 [D 16:47:58.620 ophydobj:396] sub_type=_req_done callback= [D 16:47:58.621 epics_motor:281] m1._move_changed(): after _done_moving() success=True value=1 2019-12-21 16:47:58.621494 ping 12: 0.1 0.1 [D 16:47:58.621 epics_motor:147] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() [D 16:47:58.622 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1576968478.622052) [D 16:47:58.623 epics_motor:238] [ts=2019-12-21 16:47:58.61803] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: True (value=0) [D 16:47:59.125 epics_motor:238] [ts=2019-12-21 16:47:59.12491] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: False (value=1) [D 16:47:59.127 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1576968479.127142) [D 16:47:59.128 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1576968479.127981) [D 16:47:59.128 epics_motor:274] m1._move_changed(): before _done_moving() success=True value=1 [D 16:47:59.128 positioner:202] subscription names: {'acq_done', '_req_done', 'readback', 'done_moving', 'start_moving'} [D 16:47:59.128 positioner:204] m1._callbacks[done_moving]={} [D 16:47:59.129 positioner:205] m1._done_moving() sub_type=done_moving value=1 [D 16:47:59.129 ophydobj:396] sub_type=_req_done callback= 2019-12-21 16:47:59.129710 pong 12: -0.1 -0.1 [D 16:47:59.130 epics_motor:147] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() [D 16:47:59.130 ophydobj:396] sub_type=_req_done callback= [D 16:47:59.130 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1576968479.130431) [D 16:47:59.130 epics_motor:281] m1._move_changed(): after _done_moving() success=True value=1 [D 16:47:59.132 epics_motor:238] [ts=2019-12-21 16:47:59.12491] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: True (value=0) [D 16:47:59.634 epics_motor:238] [ts=2019-12-21 16:47:59.63166] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: False (value=1) [D 16:47:59.639 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1576968479.639293) [D 16:47:59.641 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1576968479.641255) [D 16:47:59.644 epics_motor:274] m1._move_changed(): before _done_moving() success=True value=1 [D 16:47:59.645 positioner:202] subscription names: {'acq_done', '_req_done', 'readback', 'done_moving', 'start_moving'} [D 16:47:59.645 positioner:204] m1._callbacks[done_moving]={} [D 16:47:59.645 positioner:205] m1._done_moving() sub_type=done_moving value=1 [D 16:47:59.646 ophydobj:396] sub_type=_req_done callback= 2019-12-21 16:47:59.647560 ping 13: 0.1 0.1 [D 16:47:59.648 epics_motor:147] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() [D 16:47:59.648 ophydobj:396] sub_type=_req_done callback= [D 16:47:59.648 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1576968479.648751) [D 16:47:59.651 epics_motor:281] m1._move_changed(): after _done_moving() success=True value=1 [D 16:47:59.651 epics_motor:238] [ts=2019-12-21 16:47:59.63166] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: True (value=0) [D 16:48:00.136 epics_motor:238] [ts=2019-12-21 16:48:00.13588] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: False (value=1) [D 16:48:00.138 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1576968480.138070) [D 16:48:00.139 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1576968480.139444) [D 16:48:00.140 epics_motor:274] m1._move_changed(): before _done_moving() success=True value=1 [D 16:48:00.140 positioner:202] subscription names: {'acq_done', '_req_done', 'readback', 'done_moving', 'start_moving'} [D 16:48:00.140 positioner:204] m1._callbacks[done_moving]={} [D 16:48:00.141 positioner:205] m1._done_moving() sub_type=done_moving value=1 [D 16:48:00.141 epics_motor:281] m1._move_changed(): after _done_moving() success=True value=1 ```

Results of three runs of test5.py using only PyEpics (no ophyd or bluesky)

test 1

``` 2019-12-22 13:12:40.338661: pong 16312: -0.1 0.1 2019-12-22 13:12:40.338813: ping 16313: 0.1 0.1 CA.Client.Exception............................................... Warning: "Virtual circuit unresponsive" Context: "ioc8idi1.xray.aps.anl.gov:5064" Source File: ../tcpiiu.cpp line 920 Current Time: Sun Dec 22 2019 13:12:40.338869244 .................................................................. Traceback (most recent call last): File "./test5.py", line 56, in ping_pong(pv, .1, -.1, delay_s=DELAY_S) File "./test5.py", line 48, in ping_pong move(signal, f"pong {i+1}", v2, delay_s) File "./test5.py", line 37, in move signal.put(dest, timeout=TIMEOUT) File "/home/beams/8IDIUSER/.conda/envs/bluesky/lib/python3.7/site-packages/epics/pv.py", line 48, in wrapped return func(self, *args, **kwargs) File "/home/beams/8IDIUSER/.conda/envs/bluesky/lib/python3.7/site-packages/epics/pv.py", line 652, in put callback_data=callback_data) File "/home/beams/8IDIUSER/.conda/envs/bluesky/lib/python3.7/site-packages/epics/ca.py", line 549, in wrapper name(chid), timeout)) epics.ca.ChannelAccessException: put() timed out waiting '8idi:Reg200' to connect (1 seconds) ```

test 2

``` 2019-12-22 13:14:14.894821: pong 13950: -0.1 0.1 2019-12-22 13:14:14.895069: ping 13951: 0.1 0.1 2019-12-22 13:14:14.895316: pong 13951: -0.1 0.1 CA.Client.Exception............................................... Warning: "Virtual circuit unresponsive" Context: "ioc8idi1.xray.aps.anl.gov:5064" Source File: ../tcpiiu.cpp line 920 Current Time: Sun Dec 22 2019 13:14:14.895332228 .................................................................. date Traceback (most recent call last): File "./test5.py", line 56, in ping_pong(pv, .1, -.1, delay_s=DELAY_S) File "./test5.py", line 47, in ping_pong move(signal, f"ping {i+1}", v1, delay_s) File "./test5.py", line 40, in move raise TimeoutError("timeout") TimeoutError: timeout ```

test 3

``` 2019-12-22 13:15:41.740184: pong 17766: -0.1 0.1 2019-12-22 13:15:41.740339: ping 17767: 0.1 0.1 2019-12-22 13:15:41.740493: pong 17767: -0.1 0.1 2019-12-22 13:15:41.740647: ping 17768: 0.1 0.1 CA.Client.Exception............................................... Warning: "Virtual circuit unresponsive" Context: "ioc8idi1.xray.aps.anl.gov:5064" Source File: ../tcpiiu.cpp line 920 Current Time: Sun Dec 22 2019 13:15:42.498961135 Traceback (most recent call last): .................................................................. File "./test5.py", line 56, in ping_pong(pv, .1, -.1, delay_s=DELAY_S) File "./test5.py", line 48, in ping_pong move(signal, f"pong {i+1}", v2, delay_s) File "./test5.py", line 37, in move signal.put(dest, timeout=TIMEOUT) File "/home/beams/8IDIUSER/.conda/envs/bluesky/lib/python3.7/site-packages/epics/pv.py", line 48, in wrapped return func(self, *args, **kwargs) File "/home/beams/8IDIUSER/.conda/envs/bluesky/lib/python3.7/site-packages/epics/pv.py", line 652, in put callback_data=callback_data) File "/home/beams/8IDIUSER/.conda/envs/bluesky/lib/python3.7/site-packages/epics/ca.py", line 551, in wrapper return fcn(*args, **kwds) File "/home/beams/8IDIUSER/.conda/envs/bluesky/lib/python3.7/site-packages/epics/ca.py", line 1653, in put PySEVCHK('put', ret) File "/home/beams/8IDIUSER/.conda/envs/bluesky/lib/python3.7/site-packages/epics/ca.py", line 596, in PySEVCHK raise CASeverityException(func_name, message(status)) epics.ca.CASeverityException: put returned 'Virtual circuit disconnect' Sun Dec 22 13:15:42 CST 2019 ```

Always, a timeout immediately after libca message Virtual circuit unresponsive:


CA.Client.Exception...............................................
    Warning: "Virtual circuit unresponsive"
    Context: "ioc8idi1.xray.aps.anl.gov:5064"
    Source File: ../tcpiiu.cpp line 920
    Current Time: Sun Dec 22 2019 13:15:42.498961135
Traceback (most recent call last):
..................................................................```

Ran test5.py for 1,000,000 cycles on my VM with no failures. PV provided on softIoc instance running on same VM.

(bsmotor) mintadmin@mint-vm:~/.../eclipse/bstesting$ ./test5.py 1000000
epics 3.4.0
2019-12-22 15:57:48.950378: ping 1:  0.1 -0.1
2019-12-22 15:57:48.950767: pong 1:  -0.1 0.1
2019-12-22 15:57:48.951215: ping 2:  0.1 -0.1
2019-12-22 15:57:48.952207: pong 2:  -0.1 -0.1
2019-12-22 15:57:48.952706: ping 3:  0.1 0.1
2019-12-22 15:57:48.953070: pong 3:  -0.1 0.1
2019-12-22 15:57:48.953633: ping 4:  0.1 0.1
2019-12-22 15:57:48.954159: pong 4:  -0.1 -0.1
2019-12-22 15:57:48.954668: ping 5:  0.1 0.1
2019-12-22 15:57:48.955031: pong 5:  -0.1 0.1
2019-12-22 15:57:48.955573: ping 6:  0.1 0.1
2019-12-22 15:57:48.956034: pong 6:  -0.1 -0.1
2019-12-22 15:57:48.956481: ping 7:  0.1 0.1
2019-12-22 15:57:48.956896: pong 7:  -0.1 -0.1
2019-12-22 15:57:48.957282: ping 8:  0.1 0.1
2019-12-22 15:57:48.957620: pong 8:  -0.1 0.1
2019-12-22 15:57:48.958126: ping 9:  0.1 0.1
2019-12-22 15:57:48.958453: pong 9:  -0.1 0.1
2019-12-22 15:57:48.958905: ping 10:  0.1 0.1
2019-12-22 15:57:48.959230: pong 10:  -0.1 0.1
2019-12-22 15:57:48.959669: ping 11:  0.1 0.1
2019-12-22 15:57:48.960122: pong 11:  -0.1 -0.1
2019-12-22 15:57:48.960381: ping 12:  0.1 -0.1
2019-12-22 15:57:48.960693: pong 12:  -0.1 -0.1
2019-12-22 15:57:48.960935: ping 13:  0.1 -0.1
2019-12-22 15:57:48.961178: pong 13:  -0.1 -0.1
...
2019-12-22 16:23:18.318355: pong 999998:  -0.1 0.1
2019-12-22 16:23:18.319552: ping 999999:  0.1 0.1
2019-12-22 16:23:18.320142: pong 999999:  -0.1 0.1
2019-12-22 16:23:18.320930: ping 1000000:  0.1 -0.1
2019-12-22 16:23:18.322037: pong 1000000:  -0.1 0.1
epics 3.4.0

But look at pong 10, it does not always get where it should. The put() call needs a put_complete=True kwarg.

test5 needs to wait for value to change before proceeding

repeat that test of 1,000,000 cycles

(bsmotor) mintadmin@mint-vm:~/.../eclipse/bstesting$ ./test5.py 1000000
epics 3.4.0
2019-12-22 16:56:05.937325: ping 1:  0.1 0.1
2019-12-22 16:56:05.942816: pong 1:  -0.1 -0.1
2019-12-22 16:56:05.944701: ping 2:  0.1 0.1
2019-12-22 16:56:05.946704: pong 2:  -0.1 -0.1
2019-12-22 16:56:05.955874: ping 3:  0.1 0.1
2019-12-22 16:56:05.960147: pong 3:  -0.1 -0.1
2019-12-22 16:56:05.962536: ping 4:  0.1 0.1
2019-12-22 16:56:05.965209: pong 4:  -0.1 -0.1
2019-12-22 16:56:05.967652: ping 5:  0.1 0.1
2019-12-22 16:56:05.971338: pong 5:  -0.1 -0.1
2019-12-22 16:56:05.979995: ping 6:  0.1 0.1
2019-12-22 16:56:05.982191: pong 6:  -0.1 -0.1
...
2019-12-22 17:56:31.868671: pong 467836:  -0.1 -0.1
2019-12-22 17:56:31.874254: ping 467837:  0.1 0.1
2019-12-22 17:56:31.878496: pong 467837:  -0.1 -0.1
2019-12-22 17:56:31.891101: ping 467838:  0.1 0.1
2019-12-22 17:56:31.898704: pong 467838:  -0.1 -0.1
2019-12-22 17:56:31.900661: ping 467839:  0.1 0.1
2019-12-22 17:56:31.909032: pong 467839:  -0.1 -0.1
...
2019-12-22 18:15:16.877233: pong 999997:  -0.1 -0.1
2019-12-22 18:15:16.877650: ping 999998:  0.1 0.1
2019-12-22 18:15:16.878054: pong 999998:  -0.1 -0.1
2019-12-22 18:15:16.878481: ping 999999:  0.1 0.1
2019-12-22 18:15:16.878882: pong 999999:  -0.1 -0.1
2019-12-22 18:15:16.879302: ping 1000000:  0.1 0.1
2019-12-22 18:15:16.879706: pong 1000000:  -0.1 -0.1
epics 3.4.0

~7.8 ms per cycle

Set up a test on a different system.

Run softIoc -d 8idi.db on workstation opp.
Run test4.py (put a float number) on workstation poof.

No timeout failures observed.

Run IOC sky on workstation opp (in docker container as iocsky)
Run test3.py 1000 (move EPICS motor) on workstation poof.

No motor stall or timeout failures seen in two runs of 1000 cycles each.

Note that after _done_moving() message comes just before status message is finished which comes before the end of move print().

[D 22:09:51.001 epics_motor:147] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move()
[D 22:09:51.001 signal:856] m1_motor_egu.get(): set timeout=1.000000  (1577074191.001521)
[D 22:09:51.003 epics_motor:238] [ts=2019-12-22 22:09:50.99722] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: True (value=0)
[D 22:09:51.497 epics_motor:238] [ts=2019-12-22 22:09:51.49782] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: False (value=1)
[D 22:09:51.497 signal:856] m1_direction_of_travel.get(): set timeout=1.000000  (1577074191.497805)
[D 22:09:51.498 signal:856] m1_low_limit_switch.get(): set timeout=1.000000  (1577074191.498800)
[D 22:09:51.499 epics_motor:274] m1._move_changed(): before _done_moving() success=True  value=1
[D 22:09:51.499 positioner:202] subscription names: {'acq_done', 'readback', '_req_done', 'done_moving', 'start_moving'}
[D 22:09:51.499 positioner:204] m1._callbacks[done_moving]={}
[D 22:09:51.500 positioner:205] m1._done_moving() sub_type=done_moving value=1
[D 22:09:51.500 ophydobj:396] sub_type=_req_done callback=<function StatusBase._finished at 0x7f283d019320>
[D 22:09:51.500 epics_motor:281] m1._move_changed(): after _done_moving() success=True  value=1                                                                           
2019-12-22 22:09:51.501274 ping 930:  0.1 0.1                                                                                                                             
[D 22:09:51.501 epics_motor:147] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move()
[D 22:09:51.502 signal:856] m1_motor_egu.get(): set timeout=1.000000  (1577074191.502176)
[D 22:09:51.504 epics_motor:238] [ts=2019-12-22 22:09:51.49782] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: True (value=0)
[D 22:09:51.997 epics_motor:238] [ts=2019-12-22 22:09:51.99839] EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu']) moving: False (value=1)
[D 22:09:51.998 signal:856] m1_direction_of_travel.get(): set timeout=1.000000  (1577074191.998382)
[D 22:09:51.999 signal:856] m1_low_limit_switch.get(): set timeout=1.000000  (1577074191.999388)
[D 22:09:52.000 epics_motor:274] m1._move_changed(): before _done_moving() success=True  value=1
[D 22:09:52.000 positioner:202] subscription names: {'acq_done', 'readback', '_req_done', 'done_moving', 'start_moving'}
[D 22:09:52.000 positioner:204] m1._callbacks[done_moving]={}
[D 22:09:52.000 positioner:205] m1._done_moving() sub_type=done_moving value=1
[D 22:09:52.000 ophydobj:396] sub_type=_req_done callback=<function StatusBase._finished at 0x7f283d007290>
[D 22:09:52.001 epics_motor:281] m1._move_changed(): after _done_moving() success=True  value=1                                                                           
2019-12-22 22:09:52.001889 pong 930:  -0.1 -0.1                                                                                                                           
[D 22:09:52.002 epics_motor:147] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move()

Something is unusual on the VM when compared with other systems. This is the case to investigate with wireshark.

Definitely, this must be the symptom: the status message _finished() method should be called before the move is declared done. In the VM, this happens after the next move has started.

Wireshark v2.6 did not recognize the pre-compiled EPICS ca dissector from KEK. Hrmph. It was built for wireshark 1.10.2 a decade ago.

https://www-linac.kek.jp/cont/epics/wireshark/ca-1.0.3/linux-x86_64/ca.so

Try newer support: https://github.com/mdavidsaver/cashark

wget https://raw.githubusercontent.com/mdavidsaver/cashark/master/ca.lua

Only the file ca.lua is needed. Then start wireshark with

wireshark -X lua_script:/path/to/ca.lua

more success - the plugin is recognized

but the plugin has limited usefulness, it does not seem to interpret the various TCP messages, just the UDP search request. Using a filter for packets between CLIENT_IP and IOC_IP is effective:

(ip.src == CLIENT_IP && ip.dst == IOC_IP) || (ip.src == IOC_IP && ip.dst == CLIENT_IP)

Without richer analytical tools, the wireshark investigation is a rabbit hole. In both VM and non-VM cases, the motor .DMOV field goes to 1 before the status object is done. In the VM, the stall is always observed after the .DMOV field foes to 1, yet it is not clear the status object's _finished() method has been called.

The TimeoutError is not being detected on the VM, when testing for the motor stall. Focus on the motor stall problem in the VM as it points to either a problem with the VM of some issue in ophyd status objects to be resolved. Curious this is only seen in the VM.

Better to investigate what is happening with the life-cycle of the status objects in the VM case (where the next move starts before the logging reports the status object is done) and the non-VM case (where the status object is done before the next move starts, as expected).

Continuing to add diagnostic logging statements to identify what happens at the time of stalling (on the VM system). Added UUID to each status object for diagnostic purposes.

most recent console result from test3.py

``` [D 12:46:09.348 ophydobj:187] This is the first instance of OphydObject. name=m1, id=140235712277968 [D 12:46:09.349 ophydobj:187] This is the first instance of OphydObject. name=m1_user_readback, id=140235712325904 [D 12:46:09.350 ophydobj:187] This is the first instance of OphydObject. name=m1_user_setpoint, id=140235712327440 [D 12:46:09.390 epics_motor:239] [ts=2019-12-26 12:46:06.67488] m1 moving: False (value=1) [D 12:46:09.406 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1577385969.406899) [D 12:46:09.407 positioner:190] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=111bcb23-ce0c-4953-ab65-6c92d2e06c5f [D 12:46:09.407 epics_motor:150] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=111bcb23-ce0c-4953-ab65-6c92d2e06c5f [D 12:46:09.413 epics_motor:239] [ts=2019-12-26 12:46:06.67488] m1 moving: True (value=0) m1: 45%|█████████████▍ | 0.09/0.2 [00:00<00:00, 1.73s/degrees] [A m1: 85%|█████████████████████████▌ | 0.17/0.2 [00:00<00:00, 1.51s/degrees] [A m1: 100%|███████████████████████████████| 0.2/0.2 [00:00<00:00, 1.79s/degrees] [A[D 12:46:09.866 epics_motor:239] [ts=2019-12-26 12:46:09.86602] m1 moving: False (value=1) [D 12:46:09.867 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1577385969.867009) [D 12:46:09.867 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1577385969.867735) [D 12:46:09.868 epics_motor:275] m1._move_changed(): before _done_moving() success=True value=1 [D 12:46:09.868 positioner:205] m1._callbacks[done_moving]={} [D 12:46:09.868 positioner:206] m1._done_moving() sub_type=done_moving value=1 [D 12:46:09.868 ophydobj:396] sub_type=_req_done callback= [D 12:46:09.869 status:142] >>>>>>>>>>>>>>>>>>>>: status 111bcb23-ce0c-4953-ab65-6c92d2e06c5f._finished(): done=False success=True, kwargs={'timestamp': 1577385969.866021, 'sub_type': '_req_done', 'obj': EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])} [D 12:46:09.870 status:111] >>>>>>>>>>>>>>>>>>>>: status 111bcb23-ce0c-4953-ab65-6c92d2e06c5f._settle_then_run_callbacks(): MoveStatus(done=False, pos=m1, elapsed=0.5, success=False, settle_time=0.0) m1 [Complete.] [A [A2019-12-26 12:46:09.870931 ping 1: 0.1 0.1 [D 12:46:09.871 ophydobj:396] sub_type=_req_done callback= [D 12:46:09.871 status:142] >>>>>>>>>>>>>>>>>>>>: status 111bcb23-ce0c-4953-ab65-6c92d2e06c5f._finished(): done=True success=False, kwargs={'sub_type': '_req_done', 'obj': EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])} [D 12:46:09.872 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1577385969.872612) [D 12:46:09.873 status:123] --------------------: status 111bcb23-ce0c-4953-ab65-6c92d2e06c5f._settle_then_run_callbacks(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0) [D 12:46:09.873 status:155] --------------------: status 111bcb23-ce0c-4953-ab65-6c92d2e06c5f._finished(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0) [D 12:46:09.873 epics_motor:282] m1._move_changed(): after _done_moving() success=True value=1 [D 12:46:09.873 positioner:190] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=a19e614f-cfa8-4265-aabc-96d3480bc951 [D 12:46:09.874 epics_motor:150] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=a19e614f-cfa8-4265-aabc-96d3480bc951 [D 12:46:09.875 epics_motor:239] [ts=2019-12-26 12:46:09.86602] m1 moving: True (value=0) m1: 45%|█████████████▍ | 0.09/0.2 [00:00<00:00, 2.18s/degrees] [A m1: 85%|█████████████████████████▌ | 0.17/0.2 [00:00<00:00, 1.75s/degrees] [A m1: 100%|███████████████████████████████| 0.2/0.2 [00:00<00:00, 1.99s/degrees] [A[D 12:46:10.371 epics_motor:239] [ts=2019-12-26 12:46:10.37063] m1 moving: False (value=1) [D 12:46:10.371 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1577385970.371326) [D 12:46:10.371 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1577385970.371890) [D 12:46:10.372 epics_motor:275] m1._move_changed(): before _done_moving() success=True value=1 [D 12:46:10.372 positioner:205] m1._callbacks[done_moving]={} [D 12:46:10.372 positioner:206] m1._done_moving() sub_type=done_moving value=1 [D 12:46:10.372 ophydobj:396] sub_type=_req_done callback= [D 12:46:10.372 status:142] >>>>>>>>>>>>>>>>>>>>: status a19e614f-cfa8-4265-aabc-96d3480bc951._finished(): done=False success=True, kwargs={'timestamp': 1577385970.370631, 'sub_type': '_req_done', 'obj': EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])} [D 12:46:10.373 status:111] >>>>>>>>>>>>>>>>>>>>: status a19e614f-cfa8-4265-aabc-96d3480bc951._settle_then_run_callbacks(): MoveStatus(done=False, pos=m1, elapsed=0.5, success=False, settle_time=0.0) m1 [Complete.] [A[D 12:46:10.373 status:123] --------------------: status a19e614f-cfa8-4265-aabc-96d3480bc951._settle_then_run_callbacks(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0) [D 12:46:10.373 status:155] --------------------: status a19e614f-cfa8-4265-aabc-96d3480bc951._finished(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0) [D 12:46:10.373 epics_motor:282] m1._move_changed(): after _done_moving() success=True value=1 [A2019-12-26 12:46:10.373807 pong 1: -0.1 -0.1 [D 12:46:10.374 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1577385970.374330) [D 12:46:10.374 positioner:190] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=906453ce-43ba-40da-a78d-7edaf5ec315b [D 12:46:10.374 epics_motor:150] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=906453ce-43ba-40da-a78d-7edaf5ec315b [D 12:46:10.375 epics_motor:239] [ts=2019-12-26 12:46:10.37063] m1 moving: True (value=0) m1: 45%|█████████████▍ | 0.09/0.2 [00:00<00:00, 2.22s/degrees] [A m1: 85%|█████████████████████████▌ | 0.17/0.2 [00:00<00:00, 1.76s/degrees] [A m1: 100%|███████████████████████████████| 0.2/0.2 [00:00<00:00, 2.00s/degrees] [A[D 12:46:10.874 epics_motor:239] [ts=2019-12-26 12:46:10.87371] m1 moving: False (value=1) [D 12:46:10.874 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1577385970.874891) [D 12:46:10.875 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1577385970.875717) [D 12:46:10.876 epics_motor:275] m1._move_changed(): before _done_moving() success=True value=1 [D 12:46:10.876 positioner:205] m1._callbacks[done_moving]={} [D 12:46:10.876 positioner:206] m1._done_moving() sub_type=done_moving value=1 [D 12:46:10.876 ophydobj:396] sub_type=_req_done callback= [D 12:46:10.876 status:142] >>>>>>>>>>>>>>>>>>>>: status 906453ce-43ba-40da-a78d-7edaf5ec315b._finished(): done=False success=True, kwargs={'timestamp': 1577385970.873707, 'sub_type': '_req_done', 'obj': EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])} [D 12:46:10.877 status:111] >>>>>>>>>>>>>>>>>>>>: status 906453ce-43ba-40da-a78d-7edaf5ec315b._settle_then_run_callbacks(): MoveStatus(done=False, pos=m1, elapsed=0.5, success=False, settle_time=0.0) m1 [Complete.] [A[D 12:46:10.878 status:123] --------------------: status 906453ce-43ba-40da-a78d-7edaf5ec315b._settle_then_run_callbacks(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0) [D 12:46:10.878 status:155] --------------------: status 906453ce-43ba-40da-a78d-7edaf5ec315b._finished(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0) [D 12:46:10.878 epics_motor:282] m1._move_changed(): after _done_moving() success=True value=1 [A2019-12-26 12:46:10.879123 ping 2: 0.1 0.1 [D 12:46:10.879 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1577385970.879842) [D 12:46:10.880 positioner:190] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=bf4501e4-8c92-446d-96e6-50f05f82392d [D 12:46:10.881 epics_motor:150] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=bf4501e4-8c92-446d-96e6-50f05f82392d [D 12:46:10.882 epics_motor:239] [ts=2019-12-26 12:46:10.87371] m1 moving: True (value=0) m1: 45%|█████████████▍ | 0.09/0.2 [00:00<00:00, 2.18s/degrees] [A m1: 85%|█████████████████████████▌ | 0.17/0.2 [00:00<00:00, 1.75s/degrees] [A m1: 100%|███████████████████████████████| 0.2/0.2 [00:00<00:00, 1.98s/degrees] [A[D 12:46:11.377 epics_motor:239] [ts=2019-12-26 12:46:11.37660] m1 moving: False (value=1) [D 12:46:11.377 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1577385971.377818) [D 12:46:11.379 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1577385971.379077) [D 12:46:11.379 epics_motor:275] m1._move_changed(): before _done_moving() success=True value=1 [D 12:46:11.379 positioner:205] m1._callbacks[done_moving]={} [D 12:46:11.380 positioner:206] m1._done_moving() sub_type=done_moving value=1 [D 12:46:11.380 ophydobj:396] sub_type=_req_done callback= [D 12:46:11.380 status:142] >>>>>>>>>>>>>>>>>>>>: status bf4501e4-8c92-446d-96e6-50f05f82392d._finished(): done=False success=True, kwargs={'timestamp': 1577385971.3766, 'sub_type': '_req_done', 'obj': EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])} [D 12:46:11.381 status:111] >>>>>>>>>>>>>>>>>>>>: status bf4501e4-8c92-446d-96e6-50f05f82392d._settle_then_run_callbacks(): MoveStatus(done=False, pos=m1, elapsed=0.5, success=False, settle_time=0.0) m1 [Complete.] [A[D 12:46:11.381 status:123] --------------------: status bf4501e4-8c92-446d-96e6-50f05f82392d._settle_then_run_callbacks(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0) [D 12:46:11.381 status:155] --------------------: status bf4501e4-8c92-446d-96e6-50f05f82392d._finished(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0) [D 12:46:11.381 epics_motor:282] m1._move_changed(): after _done_moving() success=True value=1 [A2019-12-26 12:46:11.383216 pong 2: -0.1 -0.1 [D 12:46:11.384 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1577385971.384072) [D 12:46:11.385 positioner:190] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=12daee7e-b839-476d-8b70-d08adb0ed480 [D 12:46:11.385 epics_motor:150] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=12daee7e-b839-476d-8b70-d08adb0ed480 [D 12:46:11.387 epics_motor:239] [ts=2019-12-26 12:46:11.37660] m1 moving: True (value=0) m1: 50%|███████████████▌ | 0.1/0.2 [00:00<00:00, 1.99s/degrees] [A m1: 85%|█████████████████████████▌ | 0.17/0.2 [00:00<00:00, 1.77s/degrees] [A m1: 100%|███████████████████████████████| 0.2/0.2 [00:00<00:00, 2.01s/degrees] [A[D 12:46:11.885 epics_motor:239] [ts=2019-12-26 12:46:11.88453] m1 moving: False (value=1) [D 12:46:11.885 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1577385971.885823) [D 12:46:11.886 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1577385971.886834) [D 12:46:11.887 epics_motor:275] m1._move_changed(): before _done_moving() success=True value=1 [D 12:46:11.887 positioner:205] m1._callbacks[done_moving]={} [D 12:46:11.888 positioner:206] m1._done_moving() sub_type=done_moving value=1 [D 12:46:11.888 ophydobj:396] sub_type=_req_done callback= [D 12:46:11.888 status:142] >>>>>>>>>>>>>>>>>>>>: status 12daee7e-b839-476d-8b70-d08adb0ed480._finished(): done=False success=True, kwargs={'timestamp': 1577385971.884526, 'sub_type': '_req_done', 'obj': EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])} [D 12:46:11.889 status:111] >>>>>>>>>>>>>>>>>>>>: status 12daee7e-b839-476d-8b70-d08adb0ed480._settle_then_run_callbacks(): MoveStatus(done=False, pos=m1, elapsed=0.5, success=False, settle_time=0.0) m1 [Complete.] [A[D 12:46:11.890 status:123] --------------------: status 12daee7e-b839-476d-8b70-d08adb0ed480._settle_then_run_callbacks(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0) [D 12:46:11.890 status:155] --------------------: status 12daee7e-b839-476d-8b70-d08adb0ed480._finished(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0) [D 12:46:11.890 epics_motor:282] m1._move_changed(): after _done_moving() success=True value=1 [A2019-12-26 12:46:11.891451 ping 3: 0.1 0.1 [D 12:46:11.892 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1577385971.892478) [D 12:46:11.893 positioner:190] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=5b031f99-4ca0-4dc3-841f-c4f76687e805 [D 12:46:11.893 epics_motor:150] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=5b031f99-4ca0-4dc3-841f-c4f76687e805 [D 12:46:11.895 epics_motor:239] [ts=2019-12-26 12:46:11.88453] m1 moving: True (value=0) m1: 45%|█████████████▍ | 0.09/0.2 [00:00<00:00, 2.16s/degrees] [A m1: 85%|█████████████████████████▌ | 0.17/0.2 [00:00<00:00, 1.73s/degrees] [A m1: 100%|███████████████████████████████| 0.2/0.2 [00:00<00:00, 1.97s/degrees] [A[D 12:46:12.387 epics_motor:239] [ts=2019-12-26 12:46:12.38690] m1 moving: False (value=1) [D 12:46:12.387 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1577385972.387963) [D 12:46:12.388 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1577385972.388649) [D 12:46:12.389 epics_motor:275] m1._move_changed(): before _done_moving() success=True value=1 [D 12:46:12.389 positioner:205] m1._callbacks[done_moving]={} [D 12:46:12.389 positioner:206] m1._done_moving() sub_type=done_moving value=1 [D 12:46:12.389 ophydobj:396] sub_type=_req_done callback= [D 12:46:12.389 status:142] >>>>>>>>>>>>>>>>>>>>: status 5b031f99-4ca0-4dc3-841f-c4f76687e805._finished(): done=False success=True, kwargs={'timestamp': 1577385972.386896, 'sub_type': '_req_done', 'obj': EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])} [D 12:46:12.390 status:111] >>>>>>>>>>>>>>>>>>>>: status 5b031f99-4ca0-4dc3-841f-c4f76687e805._settle_then_run_callbacks(): MoveStatus(done=False, pos=m1, elapsed=0.5, success=False, settle_time=0.0) m1 [Complete.] [A[D 12:46:12.391 status:123] --------------------: status 5b031f99-4ca0-4dc3-841f-c4f76687e805._settle_then_run_callbacks(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0) [D 12:46:12.391 status:155] --------------------: status 5b031f99-4ca0-4dc3-841f-c4f76687e805._finished(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0) [D 12:46:12.391 epics_motor:282] m1._move_changed(): after _done_moving() success=True value=1 [A2019-12-26 12:46:12.392120 pong 3: -0.1 -0.1 [D 12:46:12.392 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1577385972.392817) [D 12:46:12.393 positioner:190] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=3a0076d9-3f5e-4710-b9d3-a5cc1b5577ed [D 12:46:12.393 epics_motor:150] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=3a0076d9-3f5e-4710-b9d3-a5cc1b5577ed [D 12:46:12.395 epics_motor:239] [ts=2019-12-26 12:46:12.38690] m1 moving: True (value=0) m1: 45%|█████████████▍ | 0.09/0.2 [00:00<00:00, 2.18s/degrees] [A m1: 85%|█████████████████████████▌ | 0.17/0.2 [00:00<00:00, 1.75s/degrees] [A m1: 100%|███████████████████████████████| 0.2/0.2 [00:00<00:00, 1.98s/degrees] [A[D 12:46:12.896 epics_motor:239] [ts=2019-12-26 12:46:12.89622] m1 moving: False (value=1) [D 12:46:12.896 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1577385972.896912) [D 12:46:12.897 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1577385972.897650) [D 12:46:12.898 epics_motor:275] m1._move_changed(): before _done_moving() success=True value=1 [D 12:46:12.898 positioner:205] m1._callbacks[done_moving]={} [D 12:46:12.898 positioner:206] m1._done_moving() sub_type=done_moving value=1 [D 12:46:12.898 ophydobj:396] sub_type=_req_done callback= [D 12:46:12.898 status:142] >>>>>>>>>>>>>>>>>>>>: status 3a0076d9-3f5e-4710-b9d3-a5cc1b5577ed._finished(): done=False success=True, kwargs={'timestamp': 1577385972.896218, 'sub_type': '_req_done', 'obj': EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])} [D 12:46:12.899 status:111] >>>>>>>>>>>>>>>>>>>>: status 3a0076d9-3f5e-4710-b9d3-a5cc1b5577ed._settle_then_run_callbacks(): MoveStatus(done=False, pos=m1, elapsed=0.5, success=False, settle_time=0.0) m1 [Complete.] [A[D 12:46:12.899 status:123] --------------------: status 3a0076d9-3f5e-4710-b9d3-a5cc1b5577ed._settle_then_run_callbacks(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0) [D 12:46:12.899 status:155] --------------------: status 3a0076d9-3f5e-4710-b9d3-a5cc1b5577ed._finished(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0) [D 12:46:12.899 epics_motor:282] m1._move_changed(): after _done_moving() success=True value=1 [A2019-12-26 12:46:12.900196 ping 4: 0.1 0.1 [D 12:46:12.900 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1577385972.900820) [D 12:46:12.901 positioner:190] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=313d0555-77af-4da9-ba9e-3995abdc1a45 [D 12:46:12.901 epics_motor:150] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=313d0555-77af-4da9-ba9e-3995abdc1a45 [D 12:46:12.902 epics_motor:239] [ts=2019-12-26 12:46:12.89622] m1 moving: True (value=0) m1: 10%|██▉ | 0.02/0.2 [00:00<00:00, 4.94s/degrees] [A m1: 50%|███████████████▌ | 0.1/0.2 [00:00<00:00, 2.07s/degrees] [A m1: 90%|██████████████████████████▉ | 0.18/0.2 [00:00<00:00, 1.74s/degrees] [A m1: 100%|███████████████████████████████| 0.2/0.2 [00:00<00:00, 2.08s/degrees] [A[D 12:46:13.416 epics_motor:239] [ts=2019-12-26 12:46:13.41525] m1 moving: False (value=1) [D 12:46:13.416 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1577385973.416384) [D 12:46:13.417 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1577385973.417179) [D 12:46:13.418 epics_motor:275] m1._move_changed(): before _done_moving() success=True value=1 [D 12:46:13.418 positioner:205] m1._callbacks[done_moving]={} [D 12:46:13.418 positioner:206] m1._done_moving() sub_type=done_moving value=1 [D 12:46:13.418 ophydobj:396] sub_type=_req_done callback= [D 12:46:13.418 status:142] >>>>>>>>>>>>>>>>>>>>: status 313d0555-77af-4da9-ba9e-3995abdc1a45._finished(): done=False success=True, kwargs={'timestamp': 1577385973.415252, 'sub_type': '_req_done', 'obj': EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])} [D 12:46:13.419 status:111] >>>>>>>>>>>>>>>>>>>>: status 313d0555-77af-4da9-ba9e-3995abdc1a45._settle_then_run_callbacks(): MoveStatus(done=False, pos=m1, elapsed=0.5, success=False, settle_time=0.0) m1 [Complete.] [A [A2019-12-26 12:46:13.420253 pong 4: -0.1 -0.1 [D 12:46:13.420 ophydobj:396] sub_type=_req_done callback= [D 12:46:13.420 status:142] >>>>>>>>>>>>>>>>>>>>: status 313d0555-77af-4da9-ba9e-3995abdc1a45._finished(): done=True success=False, kwargs={'sub_type': '_req_done', 'obj': EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])} [D 12:46:13.421 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1577385973.421673) [D 12:46:13.422 status:123] --------------------: status 313d0555-77af-4da9-ba9e-3995abdc1a45._settle_then_run_callbacks(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0) [D 12:46:13.422 status:155] --------------------: status 313d0555-77af-4da9-ba9e-3995abdc1a45._finished(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0) [D 12:46:13.422 positioner:190] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=9543515b-eb57-4814-a97f-c069c477ce0b [D 12:46:13.423 epics_motor:150] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=9543515b-eb57-4814-a97f-c069c477ce0b [D 12:46:13.422 epics_motor:282] m1._move_changed(): after _done_moving() success=True value=1 [D 12:46:13.424 epics_motor:239] [ts=2019-12-26 12:46:13.41525] m1 moving: True (value=0) m1: 45%|█████████████▍ | 0.09/0.2 [00:00<00:00, 2.17s/degrees] [A m1: 85%|█████████████████████████▌ | 0.17/0.2 [00:00<00:00, 1.75s/degrees] [A m1: 100%|███████████████████████████████| 0.2/0.2 [00:00<00:00, 2.00s/degrees] [A[D 12:46:13.921 epics_motor:239] [ts=2019-12-26 12:46:13.92074] m1 moving: False (value=1) [D 12:46:13.921 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1577385973.921706) [D 12:46:13.922 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1577385973.922659) [D 12:46:13.923 epics_motor:275] m1._move_changed(): before _done_moving() success=True value=1 [D 12:46:13.923 positioner:205] m1._callbacks[done_moving]={} [D 12:46:13.923 positioner:206] m1._done_moving() sub_type=done_moving value=1 [D 12:46:13.923 ophydobj:396] sub_type=_req_done callback= [D 12:46:13.923 status:142] >>>>>>>>>>>>>>>>>>>>: status 9543515b-eb57-4814-a97f-c069c477ce0b._finished(): done=False success=True, kwargs={'timestamp': 1577385973.920737, 'sub_type': '_req_done', 'obj': EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])} [D 12:46:13.924 status:111] >>>>>>>>>>>>>>>>>>>>: status 9543515b-eb57-4814-a97f-c069c477ce0b._settle_then_run_callbacks(): MoveStatus(done=False, pos=m1, elapsed=0.5, success=False, settle_time=0.0) m1 [Complete.] [A [A2019-12-26 12:46:13.925828 ping 5: 0.1 0.1 [D 12:46:13.926 ophydobj:396] sub_type=_req_done callback= [D 12:46:13.926 status:142] >>>>>>>>>>>>>>>>>>>>: status 9543515b-eb57-4814-a97f-c069c477ce0b._finished(): done=True success=False, kwargs={'sub_type': '_req_done', 'obj': EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])} [D 12:46:13.927 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1577385973.927442) [D 12:46:13.927 status:123] --------------------: status 9543515b-eb57-4814-a97f-c069c477ce0b._settle_then_run_callbacks(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0) [D 12:46:13.928 positioner:190] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=42951f5e-355a-425d-8f73-04b51fceef1f [D 12:46:13.928 epics_motor:150] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=42951f5e-355a-425d-8f73-04b51fceef1f [D 12:46:13.928 status:155] --------------------: status 9543515b-eb57-4814-a97f-c069c477ce0b._finished(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0) [D 12:46:13.930 epics_motor:282] m1._move_changed(): after _done_moving() success=True value=1 [D 12:46:13.930 epics_motor:239] [ts=2019-12-26 12:46:13.92074] m1 moving: True (value=0) m1: 45%|█████████████▍ | 0.09/0.2 [00:00<00:00, 2.19s/degrees] [A m1: 85%|█████████████████████████▌ | 0.17/0.2 [00:00<00:00, 1.75s/degrees] [A m1: 100%|███████████████████████████████| 0.2/0.2 [00:00<00:00, 1.99s/degrees] [A[D 12:46:14.426 epics_motor:239] [ts=2019-12-26 12:46:14.42614] m1 moving: False (value=1) [D 12:46:14.427 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1577385974.427164) [D 12:46:14.429 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1577385974.429182) [D 12:46:14.430 epics_motor:275] m1._move_changed(): before _done_moving() success=True value=1 [D 12:46:14.430 positioner:205] m1._callbacks[done_moving]={} [D 12:46:14.430 positioner:206] m1._done_moving() sub_type=done_moving value=1 [D 12:46:14.430 epics_motor:282] m1._move_changed(): after _done_moving() success=True value=1 ```

On the VM, when it moves properly (no stall), from just before to just after call to _done_moving():

[D 12:46:09.868 epics_motor:275] m1._move_changed(): before _done_moving() success=True  value=1
[D 12:46:09.868 positioner:205] m1._callbacks[done_moving]={}
[D 12:46:09.868 positioner:206] m1._done_moving() sub_type=done_moving value=1
[D 12:46:09.868 ophydobj:396] sub_type=_req_done callback=<function StatusBase._finished at 0x7f8b2b3f6290>
[D 12:46:09.869 status:142] >>>>>>>>>>>>>>>>>>>>: status 111bcb23-ce0c-4953-ab65-6c92d2e06c5f._finished(): done=False success=True, kwargs={'timestamp': 1577385969.866021, 'sub_type': '_req_done', 'obj': EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])}
[D 12:46:09.870 status:111] >>>>>>>>>>>>>>>>>>>>: status 111bcb23-ce0c-4953-ab65-6c92d2e06c5f._settle_then_run_callbacks(): MoveStatus(done=False, pos=m1, elapsed=0.5, success=False, settle_time=0.0)

m1 [Complete.]                                                                 
[A

[A2019-12-26 12:46:09.870931 ping 1:  0.1 0.1
[D 12:46:09.871 ophydobj:396] sub_type=_req_done callback=<function StatusBase._finished at 0x7f8b2b3f6290>
[D 12:46:09.871 status:142] >>>>>>>>>>>>>>>>>>>>: status 111bcb23-ce0c-4953-ab65-6c92d2e06c5f._finished(): done=True success=False, kwargs={'sub_type': '_req_done', 'obj': EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])}
[D 12:46:09.872 signal:856] m1_motor_egu.get(): set timeout=1.000000  (1577385969.872612)
[D 12:46:09.873 status:123] --------------------: status 111bcb23-ce0c-4953-ab65-6c92d2e06c5f._settle_then_run_callbacks(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0)
[D 12:46:09.873 status:155] --------------------: status 111bcb23-ce0c-4953-ab65-6c92d2e06c5f._finished(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0)
[D 12:46:09.873 epics_motor:282] m1._move_changed(): after _done_moving() success=True  value=1

When it stalls, from just before to just after call to _done_moving():

[D 12:46:14.430 epics_motor:275] m1._move_changed(): before _done_moving() success=True  value=1
[D 12:46:14.430 positioner:205] m1._callbacks[done_moving]={}
[D 12:46:14.430 positioner:206] m1._done_moving() sub_type=done_moving value=1
[D 12:46:14.430 epics_motor:282] m1._move_changed(): after _done_moving() success=True  value=1

When the motor moves smoothly, and the status object is marked done=True so the plan continues to the next message, this chunk of code (in StatusBase._finished() ) is still running: https://github.com/bluesky/ophyd/blob/f7177f015066ed778f196af82ec700f0c59d50c2/ophyd/status.py#L139-L145

    if success and self.settle_time > 0:
        # delay gratification until the settle time is up
        self._settle_thread = threading.Thread(
            target=self._settle_then_run_callbacks, daemon=True,
            kwargs=dict(success=success),
        )
        self._settle_thread.start()

Alternatively (to https://github.com/prjemian/bstesting/issues/1#issuecomment-569116845 above), when the motor moves on the non-VM workstation and does not stall:

[D 13:46:54.956 epics_motor:275] m1._move_changed(): before _done_moving() success=True  value=1
[D 13:46:54.956 positioner:205] m1._callbacks[done_moving]={}
[D 13:46:54.956 positioner:206] m1._done_moving() sub_type=done_moving value=1
[D 13:46:54.956 ophydobj:396] sub_type=_req_done callback=<function StatusBase._finished at 0x7f7eccd305f0>
[D 13:46:54.956 status:142] >>>>>>>>>>>>>>>>>>>>: status ed9995c3-db5c-48ee-9c47-d38988088ab6._finished(): done=False success=True, kwargs={'timestamp': 1577389614.956807, 'sub_type': '_req_done', 'obj': EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])}
[D 13:46:54.957 status:111] >>>>>>>>>>>>>>>>>>>>: status ed9995c3-db5c-48ee-9c47-d38988088ab6._settle_then_run_callbacks(): MoveStatus(done=False, pos=m1, elapsed=0.5, success=False, settle_time=0.0)

m1 [Complete.]                                                                 
[A[D 13:46:54.957 status:123] --------------------: status ed9995c3-db5c-48ee-9c47-d38988088ab6._settle_then_run_callbacks(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0)
[D 13:46:54.957 status:155] --------------------: status ed9995c3-db5c-48ee-9c47-d38988088ab6._finished(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0)
[D 13:46:54.957 epics_motor:282] m1._move_changed(): after _done_moving() success=True  value=1

[A2019-12-26 13:46:54.958325 ping 3:  0.1 0.1

What code controls this ordering? Message handling the RunEngine?

Adding message handling diagnostic to RunEngine instance:

def msg_watcher(msg):
    print("!"*10, f"Msg({msg})")

RE = bluesky.RunEngine({})
RE.msg_hook=msg_watcher

and this console output (when it stalls on the VM):

console showing RE message in progress

``` [D 14:14:08.612 ophydobj:187] This is the first instance of OphydObject. name=m1, id=140598013913872 [D 14:14:08.613 ophydobj:187] This is the first instance of OphydObject. name=m1_user_readback, id=140598013965136 [D 14:14:08.614 ophydobj:187] This is the first instance of OphydObject. name=m1_user_setpoint, id=140598013966672 [D 14:14:08.649 epics_motor:239] [ts=2019-12-26 14:14:05.61723] m1 moving: False (value=1) !!!!!!!!!! Msg(checkpoint[None]: (None), (), {}) !!!!!!!!!! Msg(set[None]: (EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])), (0.1,), {'group': '1d12c297-59f5-4306-8601-1de8e1d25592'}) [D 14:14:08.674 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1577391248.674679) [D 14:14:08.680 positioner:190] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=9f80f6e8-6965-4b2b-81c9-4752203c640e [D 14:14:08.680 epics_motor:150] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=9f80f6e8-6965-4b2b-81c9-4752203c640e !!!!!!!!!! Msg(wait[None]: (None), (), {'group': '1d12c297-59f5-4306-8601-1de8e1d25592'}) [D 14:14:08.682 epics_motor:239] [ts=2019-12-26 14:14:05.61723] m1 moving: True (value=0) [D 14:14:08.683 epics_motor:239] [ts=2019-12-26 14:14:08.68067] m1 moving: False (value=1) [D 14:14:08.683 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1577391248.683437) [D 14:14:08.684 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1577391248.684723) [D 14:14:08.686 epics_motor:275] m1._move_changed(): before _done_moving() success=True value=1 [D 14:14:08.686 positioner:205] m1._callbacks[done_moving]={} [D 14:14:08.686 positioner:206] m1._done_moving() sub_type=done_moving value=1 [D 14:14:08.686 ophydobj:396] sub_type=_req_done callback= [D 14:14:08.686 status:142] >>>>>>>>>>>>>>>>>>>>: status 9f80f6e8-6965-4b2b-81c9-4752203c640e._finished(): done=False success=True, kwargs={'timestamp': 1577391248.680674, 'sub_type': '_req_done', 'obj': EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])} [D 14:14:08.687 status:111] >>>>>>>>>>>>>>>>>>>>: status 9f80f6e8-6965-4b2b-81c9-4752203c640e._settle_then_run_callbacks(): MoveStatus(done=False, pos=m1, elapsed=0.0, success=False, settle_time=0.0) [D 14:14:08.687 status:123] --------------------: status 9f80f6e8-6965-4b2b-81c9-4752203c640e._settle_then_run_callbacks(): MoveStatus(done=True, pos=m1, elapsed=0.0, success=True, settle_time=0.0) [D 14:14:08.687 status:155] --------------------: status 9f80f6e8-6965-4b2b-81c9-4752203c640e._finished(): MoveStatus(done=True, pos=m1, elapsed=0.0, success=True, settle_time=0.0) [D 14:14:08.687 epics_motor:282] m1._move_changed(): after _done_moving() success=True value=1 2019-12-26 14:14:08.688516 ping 1: 0.1 0.1 !!!!!!!!!! Msg(sleep[None]: (None), (1e-06,), {}) !!!!!!!!!! Msg(checkpoint[None]: (None), (), {}) !!!!!!!!!! Msg(set[None]: (EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])), (-0.1,), {'group': '85797dfc-8fac-45a5-98d2-99c2362d0fde'}) [D 14:14:08.689 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1577391248.689665) [D 14:14:08.690 positioner:190] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=f8ee07b9-370a-4b93-956a-55e076c8e5a2 [D 14:14:08.690 epics_motor:150] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=f8ee07b9-370a-4b93-956a-55e076c8e5a2 !!!!!!!!!! Msg(wait[None]: (None), (), {'group': '85797dfc-8fac-45a5-98d2-99c2362d0fde'}) [D 14:14:08.691 epics_motor:239] [ts=2019-12-26 14:14:08.68067] m1 moving: True (value=0) m1: 45%|█████████████▍ | 0.09/0.2 [00:00<00:00, 1.89s/degrees] [A m1: 85%|█████████████████████████▌ | 0.17/0.2 [00:00<00:00, 1.63s/degrees] [A m1: 100%|███████████████████████████████| 0.2/0.2 [00:00<00:00, 1.89s/degrees] [A[D 14:14:09.168 epics_motor:239] [ts=2019-12-26 14:14:09.16808] m1 moving: False (value=1) [D 14:14:09.168 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1577391249.168965) [D 14:14:09.169 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1577391249.169559) [D 14:14:09.170 epics_motor:275] m1._move_changed(): before _done_moving() success=True value=1 [D 14:14:09.170 positioner:205] m1._callbacks[done_moving]={} [D 14:14:09.170 positioner:206] m1._done_moving() sub_type=done_moving value=1 [D 14:14:09.170 ophydobj:396] sub_type=_req_done callback= [D 14:14:09.170 status:142] >>>>>>>>>>>>>>>>>>>>: status f8ee07b9-370a-4b93-956a-55e076c8e5a2._finished(): done=False success=True, kwargs={'timestamp': 1577391249.168082, 'sub_type': '_req_done', 'obj': EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])} [D 14:14:09.170 status:111] >>>>>>>>>>>>>>>>>>>>: status f8ee07b9-370a-4b93-956a-55e076c8e5a2._settle_then_run_callbacks(): MoveStatus(done=False, pos=m1, elapsed=0.5, success=False, settle_time=0.0) m1 [Complete.] [A[D 14:14:09.171 status:123] --------------------: status f8ee07b9-370a-4b93-956a-55e076c8e5a2._settle_then_run_callbacks(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0) [A2019-12-26 14:14:09.171575 pong 1: -0.1 -0.1 !!!!!!!!!! Msg(sleep[None]: (None), (1e-06,), {}) !!!!!!!!!! Msg(checkpoint[None]: (None), (), {}) !!!!!!!!!! Msg(set[None]: (EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])), (0.1,), {'group': 'e9b79c35-91f5-4490-b8b6-bdf11791f312'}) [D 14:14:09.172 ophydobj:396] sub_type=_req_done callback= [D 14:14:09.172 status:142] >>>>>>>>>>>>>>>>>>>>: status f8ee07b9-370a-4b93-956a-55e076c8e5a2._finished(): done=True success=False, kwargs={'sub_type': '_req_done', 'obj': EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])} [D 14:14:09.172 status:155] --------------------: status f8ee07b9-370a-4b93-956a-55e076c8e5a2._finished(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0) [D 14:14:09.173 epics_motor:282] m1._move_changed(): after _done_moving() success=True value=1 [D 14:14:09.173 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1577391249.173503) [D 14:14:09.174 positioner:190] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=6283b287-2750-4faa-ad95-d060ad994a35 [D 14:14:09.174 epics_motor:150] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=6283b287-2750-4faa-ad95-d060ad994a35 !!!!!!!!!! Msg(wait[None]: (None), (), {'group': 'e9b79c35-91f5-4490-b8b6-bdf11791f312'}) [D 14:14:09.175 epics_motor:239] [ts=2019-12-26 14:14:09.16808] m1 moving: True (value=0) m1: 45%|█████████████▍ | 0.09/0.2 [00:00<00:00, 2.18s/degrees] [A m1: 85%|█████████████████████████▌ | 0.17/0.2 [00:00<00:00, 1.77s/degrees] [A m1: 100%|███████████████████████████████| 0.2/0.2 [00:00<00:00, 2.01s/degrees] [A[D 14:14:09.680 epics_motor:239] [ts=2019-12-26 14:14:09.67944] m1 moving: False (value=1) [D 14:14:09.681 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1577391249.681144) [D 14:14:09.682 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1577391249.682659) [D 14:14:09.684 epics_motor:275] m1._move_changed(): before _done_moving() success=True value=1 [D 14:14:09.684 positioner:205] m1._callbacks[done_moving]={} [D 14:14:09.684 positioner:206] m1._done_moving() sub_type=done_moving value=1 [D 14:14:09.685 ophydobj:396] sub_type=_req_done callback= [D 14:14:09.685 status:142] >>>>>>>>>>>>>>>>>>>>: status 6283b287-2750-4faa-ad95-d060ad994a35._finished(): done=False success=True, kwargs={'timestamp': 1577391249.679437, 'sub_type': '_req_done', 'obj': EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])} [D 14:14:09.686 status:111] >>>>>>>>>>>>>>>>>>>>: status 6283b287-2750-4faa-ad95-d060ad994a35._settle_then_run_callbacks(): MoveStatus(done=False, pos=m1, elapsed=0.5, success=False, settle_time=0.0) m1 [Complete.] [A[D 14:14:09.687 status:123] --------------------: status 6283b287-2750-4faa-ad95-d060ad994a35._settle_then_run_callbacks(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0) [D 14:14:09.687 status:155] --------------------: status 6283b287-2750-4faa-ad95-d060ad994a35._finished(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0) [D 14:14:09.688 epics_motor:282] m1._move_changed(): after _done_moving() success=True value=1 [A2019-12-26 14:14:09.689073 ping 2: 0.1 0.1 !!!!!!!!!! Msg(sleep[None]: (None), (1e-06,), {}) !!!!!!!!!! Msg(checkpoint[None]: (None), (), {}) !!!!!!!!!! Msg(set[None]: (EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])), (-0.1,), {'group': 'dd1e1f71-56be-435d-ae05-4e1ecb0f3f36'}) [D 14:14:09.691 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1577391249.691470) [D 14:14:09.693 positioner:190] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=12d68f61-2014-4add-80f7-c2556d82d6de [D 14:14:09.693 epics_motor:150] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=12d68f61-2014-4add-80f7-c2556d82d6de [D 14:14:09.695 epics_motor:239] [ts=2019-12-26 14:14:09.67944] m1 moving: True (value=0) !!!!!!!!!! Msg(wait[None]: (None), (), {'group': 'dd1e1f71-56be-435d-ae05-4e1ecb0f3f36'}) m1: 50%|███████████████▌ | 0.1/0.2 [00:00<00:00, 2.00s/degrees] [A m1: 85%|█████████████████████████▌ | 0.17/0.2 [00:00<00:00, 1.78s/degrees] [A m1: 100%|███████████████████████████████| 0.2/0.2 [00:00<00:00, 2.02s/degrees] [A[D 14:14:10.196 epics_motor:239] [ts=2019-12-26 14:14:10.19593] m1 moving: False (value=1) [D 14:14:10.197 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1577391250.197021) [D 14:14:10.197 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1577391250.197828) [D 14:14:10.198 epics_motor:275] m1._move_changed(): before _done_moving() success=True value=1 [D 14:14:10.198 positioner:205] m1._callbacks[done_moving]={} [D 14:14:10.198 positioner:206] m1._done_moving() sub_type=done_moving value=1 [D 14:14:10.198 ophydobj:396] sub_type=_req_done callback= [D 14:14:10.198 status:142] >>>>>>>>>>>>>>>>>>>>: status 12d68f61-2014-4add-80f7-c2556d82d6de._finished(): done=False success=True, kwargs={'timestamp': 1577391250.195931, 'sub_type': '_req_done', 'obj': EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])} [D 14:14:10.199 status:111] >>>>>>>>>>>>>>>>>>>>: status 12d68f61-2014-4add-80f7-c2556d82d6de._settle_then_run_callbacks(): MoveStatus(done=False, pos=m1, elapsed=0.5, success=False, settle_time=0.0) m1 [Complete.] [A[D 14:14:10.199 status:123] --------------------: status 12d68f61-2014-4add-80f7-c2556d82d6de._settle_then_run_callbacks(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0) [A2019-12-26 14:14:10.199962 pong 2: -0.1 -0.1 !!!!!!!!!! Msg(sleep[None]: (None), (1e-06,), {}) !!!!!!!!!! Msg(checkpoint[None]: (None), (), {}) !!!!!!!!!! Msg(set[None]: (EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])), (0.1,), {'group': '1bca7916-8bf5-4a67-a0a2-d0c25e8358e1'}) [D 14:14:10.201 ophydobj:396] sub_type=_req_done callback= [D 14:14:10.201 status:142] >>>>>>>>>>>>>>>>>>>>: status 12d68f61-2014-4add-80f7-c2556d82d6de._finished(): done=True success=False, kwargs={'sub_type': '_req_done', 'obj': EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])} [D 14:14:10.201 status:155] --------------------: status 12d68f61-2014-4add-80f7-c2556d82d6de._finished(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0) [D 14:14:10.202 epics_motor:282] m1._move_changed(): after _done_moving() success=True value=1 [D 14:14:10.201 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1577391250.201912) [D 14:14:10.203 positioner:190] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=858be5cb-f157-4452-b3ec-e1c33f9f423f [D 14:14:10.203 epics_motor:150] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=858be5cb-f157-4452-b3ec-e1c33f9f423f !!!!!!!!!! Msg(wait[None]: (None), (), {'group': '1bca7916-8bf5-4a67-a0a2-d0c25e8358e1'}) [D 14:14:10.204 epics_motor:239] [ts=2019-12-26 14:14:10.19593] m1 moving: True (value=0) m1: 45%|█████████████▍ | 0.09/0.2 [00:00<00:00, 2.18s/degrees] [A m1: 85%|█████████████████████████▌ | 0.17/0.2 [00:00<00:00, 1.78s/degrees] [A m1: 100%|███████████████████████████████| 0.2/0.2 [00:00<00:00, 2.03s/degrees] [A[D 14:14:10.709 epics_motor:239] [ts=2019-12-26 14:14:10.70846] m1 moving: False (value=1) [D 14:14:10.709 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1577391250.709665) [D 14:14:10.710 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1577391250.710760) [D 14:14:10.711 epics_motor:275] m1._move_changed(): before _done_moving() success=True value=1 [D 14:14:10.712 positioner:205] m1._callbacks[done_moving]={} [D 14:14:10.712 positioner:206] m1._done_moving() sub_type=done_moving value=1 [D 14:14:10.712 ophydobj:396] sub_type=_req_done callback= [D 14:14:10.712 status:142] >>>>>>>>>>>>>>>>>>>>: status 858be5cb-f157-4452-b3ec-e1c33f9f423f._finished(): done=False success=True, kwargs={'timestamp': 1577391250.708456, 'sub_type': '_req_done', 'obj': EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])} [D 14:14:10.713 status:111] >>>>>>>>>>>>>>>>>>>>: status 858be5cb-f157-4452-b3ec-e1c33f9f423f._settle_then_run_callbacks(): MoveStatus(done=False, pos=m1, elapsed=0.5, success=False, settle_time=0.0) m1 [Complete.] [A[D 14:14:10.714 status:123] --------------------: status 858be5cb-f157-4452-b3ec-e1c33f9f423f._settle_then_run_callbacks(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0) [D 14:14:10.714 status:155] --------------------: status 858be5cb-f157-4452-b3ec-e1c33f9f423f._finished(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0) [D 14:14:10.714 epics_motor:282] m1._move_changed(): after _done_moving() success=True value=1 [A2019-12-26 14:14:10.719330 ping 3: 0.1 0.1 !!!!!!!!!! Msg(sleep[None]: (None), (1e-06,), {}) !!!!!!!!!! Msg(checkpoint[None]: (None), (), {}) !!!!!!!!!! Msg(set[None]: (EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])), (-0.1,), {'group': '9a69ccd6-e2e0-4190-a638-be47dcf331e9'}) [D 14:14:10.721 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1577391250.721231) [D 14:14:10.722 positioner:190] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=9b836522-5442-4f0f-81af-084a006d2597 [D 14:14:10.723 epics_motor:150] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=9b836522-5442-4f0f-81af-084a006d2597 !!!!!!!!!! Msg(wait[None]: (None), (), {'group': '9a69ccd6-e2e0-4190-a638-be47dcf331e9'}) [D 14:14:10.724 epics_motor:239] [ts=2019-12-26 14:14:10.70846] m1 moving: True (value=0) m1: 50%|███████████████▌ | 0.1/0.2 [00:00<00:00, 1.95s/degrees] [A m1: 85%|█████████████████████████▌ | 0.17/0.2 [00:00<00:00, 1.73s/degrees] [A m1: 100%|███████████████████████████████| 0.2/0.2 [00:00<00:00, 1.97s/degrees] [A[D 14:14:11.216 epics_motor:239] [ts=2019-12-26 14:14:11.21625] m1 moving: False (value=1) [D 14:14:11.217 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1577391251.217115) [D 14:14:11.217 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1577391251.217957) [D 14:14:11.218 epics_motor:275] m1._move_changed(): before _done_moving() success=True value=1 [D 14:14:11.218 positioner:205] m1._callbacks[done_moving]={} [D 14:14:11.218 positioner:206] m1._done_moving() sub_type=done_moving value=1 [D 14:14:11.218 ophydobj:396] sub_type=_req_done callback= [D 14:14:11.218 status:142] >>>>>>>>>>>>>>>>>>>>: status 9b836522-5442-4f0f-81af-084a006d2597._finished(): done=False success=True, kwargs={'timestamp': 1577391251.21625, 'sub_type': '_req_done', 'obj': EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])} [D 14:14:11.219 status:111] >>>>>>>>>>>>>>>>>>>>: status 9b836522-5442-4f0f-81af-084a006d2597._settle_then_run_callbacks(): MoveStatus(done=False, pos=m1, elapsed=0.5, success=False, settle_time=0.0) m1 [Complete.] [A[D 14:14:11.219 status:123] --------------------: status 9b836522-5442-4f0f-81af-084a006d2597._settle_then_run_callbacks(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0) [A2019-12-26 14:14:11.220281 pong 3: -0.1 -0.1 !!!!!!!!!! Msg(sleep[None]: (None), (1e-06,), {}) !!!!!!!!!! Msg(checkpoint[None]: (None), (), {}) !!!!!!!!!! Msg(set[None]: (EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])), (0.1,), {'group': 'd5c71795-d0e0-4b8c-a707-26d123d613e9'}) [D 14:14:11.221 ophydobj:396] sub_type=_req_done callback= [D 14:14:11.221 status:142] >>>>>>>>>>>>>>>>>>>>: status 9b836522-5442-4f0f-81af-084a006d2597._finished(): done=True success=False, kwargs={'sub_type': '_req_done', 'obj': EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])} [D 14:14:11.221 status:155] --------------------: status 9b836522-5442-4f0f-81af-084a006d2597._finished(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0) [D 14:14:11.222 epics_motor:282] m1._move_changed(): after _done_moving() success=True value=1 [D 14:14:11.222 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1577391251.222092) [D 14:14:11.222 positioner:190] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=e7cc83c2-eb78-43c6-9b1c-967e0e7ce1bb [D 14:14:11.223 epics_motor:150] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=e7cc83c2-eb78-43c6-9b1c-967e0e7ce1bb !!!!!!!!!! Msg(wait[None]: (None), (), {'group': 'd5c71795-d0e0-4b8c-a707-26d123d613e9'}) [D 14:14:11.224 epics_motor:239] [ts=2019-12-26 14:14:11.21625] m1 moving: True (value=0) m1: 45%|█████████████▍ | 0.09/0.2 [00:00<00:00, 2.19s/degrees] [A m1: 85%|█████████████████████████▌ | 0.17/0.2 [00:00<00:00, 1.75s/degrees] [A m1: 100%|███████████████████████████████| 0.2/0.2 [00:00<00:00, 1.99s/degrees] [A[D 14:14:11.727 epics_motor:239] [ts=2019-12-26 14:14:11.72249] m1 moving: False (value=1) [D 14:14:11.727 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1577391251.727590) [D 14:14:11.728 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1577391251.728358) [D 14:14:11.729 epics_motor:275] m1._move_changed(): before _done_moving() success=True value=1 [D 14:14:11.729 positioner:205] m1._callbacks[done_moving]={} [D 14:14:11.729 positioner:206] m1._done_moving() sub_type=done_moving value=1 [D 14:14:11.729 ophydobj:396] sub_type=_req_done callback= [D 14:14:11.729 status:142] >>>>>>>>>>>>>>>>>>>>: status e7cc83c2-eb78-43c6-9b1c-967e0e7ce1bb._finished(): done=False success=True, kwargs={'timestamp': 1577391251.722488, 'sub_type': '_req_done', 'obj': EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])} [D 14:14:11.729 status:111] >>>>>>>>>>>>>>>>>>>>: status e7cc83c2-eb78-43c6-9b1c-967e0e7ce1bb._settle_then_run_callbacks(): MoveStatus(done=False, pos=m1, elapsed=0.5, success=False, settle_time=0.0) m1 [Complete.] [A[D 14:14:11.730 status:123] --------------------: status e7cc83c2-eb78-43c6-9b1c-967e0e7ce1bb._settle_then_run_callbacks(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0) [A2019-12-26 14:14:11.730723 ping 4: 0.1 0.1 !!!!!!!!!! Msg(sleep[None]: (None), (1e-06,), {}) !!!!!!!!!! Msg(checkpoint[None]: (None), (), {}) !!!!!!!!!! Msg(set[None]: (EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])), (-0.1,), {'group': '77ccb1eb-e4be-475d-aa63-6228c0faaed7'}) [D 14:14:11.731 ophydobj:396] sub_type=_req_done callback= [D 14:14:11.732 status:142] >>>>>>>>>>>>>>>>>>>>: status e7cc83c2-eb78-43c6-9b1c-967e0e7ce1bb._finished(): done=True success=False, kwargs={'sub_type': '_req_done', 'obj': EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])} [D 14:14:11.731 status:155] --------------------: status e7cc83c2-eb78-43c6-9b1c-967e0e7ce1bb._finished(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0) [D 14:14:11.733 epics_motor:282] m1._move_changed(): after _done_moving() success=True value=1 [D 14:14:11.732 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1577391251.732770) [D 14:14:11.737 positioner:190] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=0e301c62-aa02-480f-b689-1538d5d53e23 [D 14:14:11.737 epics_motor:150] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=0e301c62-aa02-480f-b689-1538d5d53e23 !!!!!!!!!! Msg(wait[None]: (None), (), {'group': '77ccb1eb-e4be-475d-aa63-6228c0faaed7'}) [D 14:14:11.749 epics_motor:239] [ts=2019-12-26 14:14:11.72249] m1 moving: True (value=0) m1: 50%|███████████████▌ | 0.1/0.2 [00:00<00:00, 2.00s/degrees] [A m1: 85%|█████████████████████████▌ | 0.17/0.2 [00:00<00:00, 1.78s/degrees] [A m1: 100%|███████████████████████████████| 0.2/0.2 [00:00<00:00, 2.01s/degrees] [A[D 14:14:12.238 epics_motor:239] [ts=2019-12-26 14:14:12.23702] m1 moving: False (value=1) [D 14:14:12.238 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1577391252.238217) [D 14:14:12.239 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1577391252.239010) [D 14:14:12.239 epics_motor:275] m1._move_changed(): before _done_moving() success=True value=1 [D 14:14:12.239 positioner:205] m1._callbacks[done_moving]={} [D 14:14:12.239 positioner:206] m1._done_moving() sub_type=done_moving value=1 [D 14:14:12.239 ophydobj:396] sub_type=_req_done callback= [D 14:14:12.239 status:142] >>>>>>>>>>>>>>>>>>>>: status 0e301c62-aa02-480f-b689-1538d5d53e23._finished(): done=False success=True, kwargs={'timestamp': 1577391252.237022, 'sub_type': '_req_done', 'obj': EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])} [D 14:14:12.240 status:111] >>>>>>>>>>>>>>>>>>>>: status 0e301c62-aa02-480f-b689-1538d5d53e23._settle_then_run_callbacks(): MoveStatus(done=False, pos=m1, elapsed=0.5, success=False, settle_time=0.0) m1 [Complete.] [A[D 14:14:12.240 status:123] --------------------: status 0e301c62-aa02-480f-b689-1538d5d53e23._settle_then_run_callbacks(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0) [A2019-12-26 14:14:12.241513 pong 4: -0.1 -0.1 !!!!!!!!!! Msg(sleep[None]: (None), (1e-06,), {}) !!!!!!!!!! Msg(checkpoint[None]: (None), (), {}) !!!!!!!!!! Msg(set[None]: (EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])), (0.1,), {'group': '6b0ba96e-cade-477d-baca-58de8dd56a3f'}) [D 14:14:12.242 ophydobj:396] sub_type=_req_done callback= [D 14:14:12.243 status:142] >>>>>>>>>>>>>>>>>>>>: status 0e301c62-aa02-480f-b689-1538d5d53e23._finished(): done=True success=False, kwargs={'sub_type': '_req_done', 'obj': EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])} [D 14:14:12.242 status:155] --------------------: status 0e301c62-aa02-480f-b689-1538d5d53e23._finished(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0) [D 14:14:12.244 epics_motor:282] m1._move_changed(): after _done_moving() success=True value=1 [D 14:14:12.244 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1577391252.244058) [D 14:14:12.245 positioner:190] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=912571ef-f9f4-439b-bb0b-59e42037b2be [D 14:14:12.245 epics_motor:150] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=912571ef-f9f4-439b-bb0b-59e42037b2be !!!!!!!!!! Msg(wait[None]: (None), (), {'group': '6b0ba96e-cade-477d-baca-58de8dd56a3f'}) [D 14:14:12.246 epics_motor:239] [ts=2019-12-26 14:14:12.23702] m1 moving: True (value=0) m1: 50%|███████████████▌ | 0.1/0.2 [00:00<00:00, 2.07s/degrees] [A m1: 85%|█████████████████████████▌ | 0.17/0.2 [00:00<00:00, 1.81s/degrees] [A m1: 100%|███████████████████████████████| 0.2/0.2 [00:00<00:00, 2.05s/degrees] [A[D 14:14:12.754 epics_motor:239] [ts=2019-12-26 14:14:12.75283] m1 moving: False (value=1) [D 14:14:12.754 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1577391252.754232) [D 14:14:12.755 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1577391252.755086) [D 14:14:12.755 epics_motor:275] m1._move_changed(): before _done_moving() success=True value=1 [D 14:14:12.755 positioner:205] m1._callbacks[done_moving]={} [D 14:14:12.755 positioner:206] m1._done_moving() sub_type=done_moving value=1 [D 14:14:12.756 ophydobj:396] sub_type=_req_done callback= [D 14:14:12.756 status:142] >>>>>>>>>>>>>>>>>>>>: status 912571ef-f9f4-439b-bb0b-59e42037b2be._finished(): done=False success=True, kwargs={'timestamp': 1577391252.752826, 'sub_type': '_req_done', 'obj': EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])} [D 14:14:12.756 status:111] >>>>>>>>>>>>>>>>>>>>: status 912571ef-f9f4-439b-bb0b-59e42037b2be._settle_then_run_callbacks(): MoveStatus(done=False, pos=m1, elapsed=0.5, success=False, settle_time=0.0) m1 [Complete.] [A[D 14:14:12.757 status:123] --------------------: status 912571ef-f9f4-439b-bb0b-59e42037b2be._settle_then_run_callbacks(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0) [D 14:14:12.757 status:155] --------------------: status 912571ef-f9f4-439b-bb0b-59e42037b2be._finished(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0) [D 14:14:12.757 epics_motor:282] m1._move_changed(): after _done_moving() success=True value=1 [A2019-12-26 14:14:12.758110 ping 5: 0.1 0.1 !!!!!!!!!! Msg(sleep[None]: (None), (1e-06,), {}) !!!!!!!!!! Msg(checkpoint[None]: (None), (), {}) !!!!!!!!!! Msg(set[None]: (EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])), (-0.1,), {'group': '2913fc61-83b3-4072-b5e1-23a423a7b308'}) [D 14:14:12.759 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1577391252.759506) [D 14:14:12.760 positioner:190] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=604c6ad4-cd58-41e2-8e23-e2b32889fcd6 [D 14:14:12.760 epics_motor:150] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=604c6ad4-cd58-41e2-8e23-e2b32889fcd6 !!!!!!!!!! Msg(wait[None]: (None), (), {'group': '2913fc61-83b3-4072-b5e1-23a423a7b308'}) [D 14:14:12.762 epics_motor:239] [ts=2019-12-26 14:14:12.75283] m1 moving: True (value=0) m1: 45%|█████████████▍ | 0.09/0.2 [00:00<00:00, 2.20s/degrees] [A m1: 85%|█████████████████████████▌ | 0.17/0.2 [00:00<00:00, 1.77s/degrees] [A m1: 100%|███████████████████████████████| 0.2/0.2 [00:00<00:00, 2.04s/degrees] [A[D 14:14:13.271 epics_motor:239] [ts=2019-12-26 14:14:13.27089] m1 moving: False (value=1) [D 14:14:13.272 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1577391253.272081) [D 14:14:13.273 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1577391253.273035) [D 14:14:13.273 epics_motor:275] m1._move_changed(): before _done_moving() success=True value=1 [D 14:14:13.274 positioner:205] m1._callbacks[done_moving]={} [D 14:14:13.274 positioner:206] m1._done_moving() sub_type=done_moving value=1 [D 14:14:13.274 ophydobj:396] sub_type=_req_done callback= [D 14:14:13.274 status:142] >>>>>>>>>>>>>>>>>>>>: status 604c6ad4-cd58-41e2-8e23-e2b32889fcd6._finished(): done=False success=True, kwargs={'timestamp': 1577391253.27089, 'sub_type': '_req_done', 'obj': EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])} [D 14:14:13.275 status:111] >>>>>>>>>>>>>>>>>>>>: status 604c6ad4-cd58-41e2-8e23-e2b32889fcd6._settle_then_run_callbacks(): MoveStatus(done=False, pos=m1, elapsed=0.5, success=False, settle_time=0.0) m1 [Complete.] [A [A2019-12-26 14:14:13.276067 pong 5: -0.1 -0.1 !!!!!!!!!! Msg(sleep[None]: (None), (1e-06,), {}) !!!!!!!!!! Msg(checkpoint[None]: (None), (), {}) !!!!!!!!!! Msg(set[None]: (EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])), (0.1,), {'group': 'a42fff37-5403-4f1b-8c1f-bd4c608b8741'}) [D 14:14:13.277 ophydobj:396] sub_type=_req_done callback= [D 14:14:13.277 status:142] >>>>>>>>>>>>>>>>>>>>: status 604c6ad4-cd58-41e2-8e23-e2b32889fcd6._finished(): done=True success=False, kwargs={'sub_type': '_req_done', 'obj': EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])} [D 14:14:13.278 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1577391253.278392) [D 14:14:13.278 status:123] --------------------: status 604c6ad4-cd58-41e2-8e23-e2b32889fcd6._settle_then_run_callbacks(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0) [D 14:14:13.279 status:155] --------------------: status 604c6ad4-cd58-41e2-8e23-e2b32889fcd6._finished(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0) [D 14:14:13.279 epics_motor:282] m1._move_changed(): after _done_moving() success=True value=1 [D 14:14:13.279 positioner:190] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=6903e08e-f6aa-4885-9a1b-8c861188cf07 [D 14:14:13.280 epics_motor:150] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=6903e08e-f6aa-4885-9a1b-8c861188cf07 !!!!!!!!!! Msg(wait[None]: (None), (), {'group': 'a42fff37-5403-4f1b-8c1f-bd4c608b8741'}) [D 14:14:13.281 epics_motor:239] [ts=2019-12-26 14:14:13.27089] m1 moving: True (value=0) m1: 45%|█████████████▍ | 0.09/0.2 [00:00<00:00, 2.17s/degrees] [A m1: 85%|█████████████████████████▌ | 0.17/0.2 [00:00<00:00, 1.74s/degrees] [A m1: 100%|███████████████████████████████| 0.2/0.2 [00:00<00:00, 1.98s/degrees] [A[D 14:14:13.774 epics_motor:239] [ts=2019-12-26 14:14:13.77437] m1 moving: False (value=1) [D 14:14:13.775 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1577391253.775046) [D 14:14:13.775 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1577391253.775692) [D 14:14:13.776 epics_motor:275] m1._move_changed(): before _done_moving() success=True value=1 [D 14:14:13.776 positioner:205] m1._callbacks[done_moving]={} [D 14:14:13.776 positioner:206] m1._done_moving() sub_type=done_moving value=1 [D 14:14:13.776 ophydobj:396] sub_type=_req_done callback= [D 14:14:13.776 status:142] >>>>>>>>>>>>>>>>>>>>: status 6903e08e-f6aa-4885-9a1b-8c861188cf07._finished(): done=False success=True, kwargs={'timestamp': 1577391253.774374, 'sub_type': '_req_done', 'obj': EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])} [D 14:14:13.777 status:111] >>>>>>>>>>>>>>>>>>>>: status 6903e08e-f6aa-4885-9a1b-8c861188cf07._settle_then_run_callbacks(): MoveStatus(done=False, pos=m1, elapsed=0.5, success=False, settle_time=0.0) m1 [Complete.] [A[D 14:14:13.777 status:123] --------------------: status 6903e08e-f6aa-4885-9a1b-8c861188cf07._settle_then_run_callbacks(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0) [D 14:14:13.777 status:155] --------------------: status 6903e08e-f6aa-4885-9a1b-8c861188cf07._finished(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0) [D 14:14:13.777 epics_motor:282] m1._move_changed(): after _done_moving() success=True value=1 [A2019-12-26 14:14:13.777797 ping 6: 0.1 0.1 !!!!!!!!!! Msg(sleep[None]: (None), (1e-06,), {}) !!!!!!!!!! Msg(checkpoint[None]: (None), (), {}) !!!!!!!!!! Msg(set[None]: (EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])), (-0.1,), {'group': 'ab88967f-2e35-4caa-a9b5-fdfe5f36b6b6'}) [D 14:14:13.778 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1577391253.778673) [D 14:14:13.779 positioner:190] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=b25438db-2b9f-42d1-a774-8345c49d4378 [D 14:14:13.779 epics_motor:150] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=b25438db-2b9f-42d1-a774-8345c49d4378 !!!!!!!!!! Msg(wait[None]: (None), (), {'group': 'ab88967f-2e35-4caa-a9b5-fdfe5f36b6b6'}) [D 14:14:13.780 epics_motor:239] [ts=2019-12-26 14:14:13.77437] m1 moving: True (value=0) m1: 45%|█████████████▍ | 0.09/0.2 [00:00<00:00, 2.22s/degrees] [A m1: 85%|█████████████████████████▌ | 0.17/0.2 [00:00<00:00, 1.77s/degrees] [A m1: 100%|███████████████████████████████| 0.2/0.2 [00:00<00:00, 2.02s/degrees] [A[D 14:14:14.282 epics_motor:239] [ts=2019-12-26 14:14:14.28169] m1 moving: False (value=1) [D 14:14:14.282 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1577391254.282890) [D 14:14:14.283 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1577391254.283859) [D 14:14:14.285 epics_motor:275] m1._move_changed(): before _done_moving() success=True value=1 [D 14:14:14.285 positioner:205] m1._callbacks[done_moving]={} [D 14:14:14.285 positioner:206] m1._done_moving() sub_type=done_moving value=1 [D 14:14:14.285 ophydobj:396] sub_type=_req_done callback= [D 14:14:14.285 status:142] >>>>>>>>>>>>>>>>>>>>: status b25438db-2b9f-42d1-a774-8345c49d4378._finished(): done=False success=True, kwargs={'timestamp': 1577391254.281694, 'sub_type': '_req_done', 'obj': EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])} [D 14:14:14.286 status:111] >>>>>>>>>>>>>>>>>>>>: status b25438db-2b9f-42d1-a774-8345c49d4378._settle_then_run_callbacks(): MoveStatus(done=False, pos=m1, elapsed=0.5, success=False, settle_time=0.0) m1 [Complete.] [A [A2019-12-26 14:14:14.287166 pong 6: -0.1 -0.1 !!!!!!!!!! Msg(sleep[None]: (None), (1e-06,), {}) !!!!!!!!!! Msg(checkpoint[None]: (None), (), {}) !!!!!!!!!! Msg(set[None]: (EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])), (0.1,), {'group': '269972aa-6487-45a7-a06d-92b908372dda'}) [D 14:14:14.288 ophydobj:396] sub_type=_req_done callback= [D 14:14:14.288 status:142] >>>>>>>>>>>>>>>>>>>>: status b25438db-2b9f-42d1-a774-8345c49d4378._finished(): done=True success=False, kwargs={'sub_type': '_req_done', 'obj': EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])} [D 14:14:14.289 signal:856] m1_motor_egu.get(): set timeout=1.000000 (1577391254.289408) [D 14:14:14.289 status:123] --------------------: status b25438db-2b9f-42d1-a774-8345c49d4378._settle_then_run_callbacks(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0) [D 14:14:14.290 positioner:190] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=c3457e24-8356-473d-8d9e-0fac9f0132ef [D 14:14:14.290 epics_motor:150] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move() uuid=c3457e24-8356-473d-8d9e-0fac9f0132ef !!!!!!!!!! Msg(wait[None]: (None), (), {'group': '269972aa-6487-45a7-a06d-92b908372dda'}) [D 14:14:14.290 status:155] --------------------: status b25438db-2b9f-42d1-a774-8345c49d4378._finished(): MoveStatus(done=True, pos=m1, elapsed=0.5, success=True, settle_time=0.0) [D 14:14:14.291 epics_motor:282] m1._move_changed(): after _done_moving() success=True value=1 [D 14:14:14.292 epics_motor:239] [ts=2019-12-26 14:14:14.28169] m1 moving: True (value=0) m1: 45%|█████████████▍ | 0.09/0.2 [00:00<00:00, 2.16s/degrees] [A m1: 85%|█████████████████████████▌ | 0.17/0.2 [00:00<00:00, 1.73s/degrees] [A m1: 100%|███████████████████████████████| 0.2/0.2 [00:00<00:00, 1.97s/degrees] [A[D 14:14:14.784 epics_motor:239] [ts=2019-12-26 14:14:14.78388] m1 moving: False (value=1) [D 14:14:14.784 signal:856] m1_direction_of_travel.get(): set timeout=1.000000 (1577391254.784668) [D 14:14:14.785 signal:856] m1_low_limit_switch.get(): set timeout=1.000000 (1577391254.785385) [D 14:14:14.785 epics_motor:275] m1._move_changed(): before _done_moving() success=True value=1 [D 14:14:14.785 positioner:205] m1._callbacks[done_moving]={} [D 14:14:14.785 positioner:206] m1._done_moving() sub_type=done_moving value=1 [D 14:14:14.786 epics_motor:282] m1._move_changed(): after _done_moving() success=True value=1 ```

It's waiting on the latest motor move to complete. Here is the Msg sequence:

!!!!!!!!!! Msg(checkpoint[None]: (None), (), {})
!!!!!!!!!! Msg(set[None]: (EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])), (0.1,), {'group': 'a42fff37-5403-4f1b-8c1f-bd4c608b8741'})
!!!!!!!!!! Msg(wait[None]: (None), (), {'group': 'a42fff37-5403-4f1b-8c1f-bd4c608b8741'})
!!!!!!!!!! Msg(sleep[None]: (None), (1e-06,), {})
!!!!!!!!!! Msg(checkpoint[None]: (None), (), {})
!!!!!!!!!! Msg(set[None]: (EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])), (-0.1,), {'group': 'ab88967f-2e35-4caa-a9b5-fdfe5f36b6b6'})
!!!!!!!!!! Msg(wait[None]: (None), (), {'group': 'ab88967f-2e35-4caa-a9b5-fdfe5f36b6b6'})
!!!!!!!!!! Msg(sleep[None]: (None), (1e-06,), {})
!!!!!!!!!! Msg(checkpoint[None]: (None), (), {})
!!!!!!!!!! Msg(set[None]: (EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])), (0.1,), {'group': '269972aa-6487-45a7-a06d-92b908372dda'})
!!!!!!!!!! Msg(wait[None]: (None), (), {'group': '269972aa-6487-45a7-a06d-92b908372dda'})

Alternatively, skip the msg_hook and get the default logging by setting the level on the RE logger (cannot just getLogger("bluesky.run_engine") since each RE instance has its own logger):

RE = bluesky.RunEngine({})
RE.log.setLevel(logging.DEBUG)

So, RE is processing the wait message, waiting on group=b059ffa8... to be done. That's not going to happen because just after the set message was processed for group=b059ffa8..., the previous move (group=77708b8b...) status object (uuid=abfea6ab...) had its _finished() method queued for execution:

[D 14:41:44.731 run_engine:1376] set[None]: (EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])), (0.1,), {'group': 'b059ffa8-06dd-4a49-937d-73456bd417f1'}
[D 14:41:44.733 ophydobj:396] sub_type=_req_done callback=<function StatusBase._finished at 0x7fa87e6f9ef0>
[D 14:41:44.733 status:142] >>>>>>>>>>>>>>>>>>>>: status abfea6ab-041a-4303-8656-22d1f5b1ddb4._finished(): done=True success=False, kwargs={'sub_type': '_req_done', 'obj': EpicsMotor(prefix='sky:m1', name='m1', settle_time=0.0, timeout=None, read_attrs=['user_readback', 'user_setpoint'], configuration_attrs=['user_offset', 'user_offset_dir', 'velocity', 'acceleration', 'motor_egu'])}
[D 14:41:44.734 signal:856] m1_motor_egu.get(): set timeout=1.000000  (1577392904.734127)
[D 14:41:44.735 positioner:190] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move()  uuid=19034f49-5a92-4922-9a88-13b4c5cdc78c
[D 14:41:44.735 epics_motor:150] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>: m1.move()  uuid=19034f49-5a92-4922-9a88-13b4c5cdc78c
[D 14:41:44.735 status:123] --------------------: status abfea6ab-041a-4303-8656-22d1f5b1ddb4._settle_then_run_callbacks(): MoveStatus(done=True, pos=m1, elapsed=0.2, success=True, settle_time=0.0)
[D 14:41:44.742 run_engine:1376] wait[None]: (None), (), {'group': 'b059ffa8-06dd-4a49-937d-73456bd417f1'}
[D 14:41:44.736 status:155] --------------------: status abfea6ab-041a-4303-8656-22d1f5b1ddb4._finished(): MoveStatus(done=True, pos=m1, elapsed=0.2, success=True, settle_time=0.0)

@klauer, @tacaswell: Why does RE finish the previous move (why does it exit from the wait message of group=77708b8b...) before the callbacks from the status object are returned?

It's waiting at this line in bluesky.run_engine.py: await asyncio.wait(futs, loop=self.loop, **msg.kwargs)

I'm sure wishing I had a timeout available.

Experimenting further by increasing the sleep time in the ping_pong plan shows that 100 cycles can be executed repeatedly on the VM without motor stall. Test with logging both ON and OFF. Minimum (empirical) sleep time for no stalls is ca. 2 ms.

Testing with sleep shorter, such as 0.2 ms results in occasional stall.

When the motor moves smoothly, and the status object is marked done=True so the plan continues to the next message, this chunk of code (in StatusBase._finished() ) is still running: https://github.com/bluesky/ophyd/blob/f7177f015066ed778f196af82ec700f0c59d50c2/ophyd/status.py#L139-L145
    if success and self.settle_time > 0:
        # delay gratification until the settle time is up
        self._settle_thread = threading.Thread(
            target=self._settle_then_run_callbacks, daemon=True,
            kwargs=dict(success=success),
        )
        self._settle_thread.start()

Note, not this code since in our case, settle_time =0. _finished() just calls self._settle_then_run_callbacks(success=success) directly.

Did some status object not get included in the group?

Reverted all the diagnostics added to an ophyd PR to help track this down.

prjemian / bstesting

ophyd.EpicsMotor stalls sometimes. Why? #1

The Approach to Use