Bluesky acting a little funny and not understanding set() inprogress

This occurred just now and is holding up the scan because of set() interacting with fccd_fccd1_capture_bgnd. HOwever, this happened a few days ago with the same plan, but for a different device. In the previous case, it was ionout. Last time, this was fixed by quitting bluesky.

This instance also required a re-start of bluesky.

attn: @cmazzoli @wen-hu incase you have the same issue @tacaswell do you see an immediate reason why this would fail for us?

In [277]:  RE(ct_dark(30))

Starting procedure to acquire darks 1.97Hz or 0.507s.

    Current number of images = 400.

    Setting to 30 images.

Returning to intial conditions (pre-count).
        Total images per trigger are NOW:        400                                                                                                
    FCCD FCRIC gain value is NOW:        auto

---------------------------------------------------------------------------
RuntimeError                              Traceback (most recent call last)
~/Users/2017/2017_11_Frano/macros.py in <module>()
----> 1 RE(ct_dark(30))

~/conda_envs/dev/lib/python3.6/site-packages/bluesky/run_engine.py in __call__(self, plan, subs, raise_if_interrupted, **metadata_kw)
    644                     # it (unless it is a canceled error)
    645                     if exc is not None:
--> 646                         raise exc
    647 
    648             if raise_if_interrupted and self._interrupted:

~/conda_envs/dev/lib/python3.6/site-packages/bluesky/run_engine.py in _run(self)
   1084             self.log.error("Run aborted")
   1085             self.log.error("%r", err)
-> 1086             raise err
   1087         finally:
   1088             # Some done_callbacks may still be alive in other threads.

~/conda_envs/dev/lib/python3.6/site-packages/bluesky/run_engine.py in _run(self)
    982                         resp = self._response_stack.pop()
    983                         try:
--> 984                             msg = self._plan_stack[-1].send(resp)
    985                         # We have exhausted the top generator
    986                         except StopIteration:

~/conda_envs/dev/lib/python3.6/site-packages/bluesky/plans.py in __call__(self, plan)
   3338         plan = monitor_during_wrapper(plan, self.monitors)
   3339         plan = fly_during_wrapper(plan, self.flyers)
-> 3340         return (yield from plan)
   3341 
   3342 

~/conda_envs/dev/lib/python3.6/site-packages/bluesky/plans.py in fly_during_wrapper(plan, flyers)
   1482     plan1 = plan_mutator(plan, insert_after_open)
   1483     plan2 = plan_mutator(plan1, insert_before_close)
-> 1484     return (yield from plan2)
   1485 
   1486 

~/conda_envs/dev/lib/python3.6/site-packages/bluesky/plans.py in plan_mutator(plan, msg_proc)
    162                     continue
    163                 else:
--> 164                     raise ex
    165         # if inserting / mutating, put new generator on the stack
    166         # and replace the current msg with the first element from the

~/conda_envs/dev/lib/python3.6/site-packages/bluesky/plans.py in plan_mutator(plan, msg_proc)
    115             ret = result_stack.pop()
    116             try:
--> 117                 msg = plan_stack[-1].send(ret)
    118             except StopIteration as e:
    119                 # discard the exhausted generator

~/conda_envs/dev/lib/python3.6/site-packages/bluesky/plans.py in plan_mutator(plan, msg_proc)
    162                     continue
    163                 else:
--> 164                     raise ex
    165         # if inserting / mutating, put new generator on the stack
    166         # and replace the current msg with the first element from the

~/conda_envs/dev/lib/python3.6/site-packages/bluesky/plans.py in plan_mutator(plan, msg_proc)
    115             ret = result_stack.pop()
    116             try:
--> 117                 msg = plan_stack[-1].send(ret)
    118             except StopIteration as e:
    119                 # discard the exhausted generator

~/conda_envs/dev/lib/python3.6/site-packages/bluesky/plans.py in monitor_during_wrapper(plan, signals)
   1424     plan1 = plan_mutator(plan, insert_after_open)
   1425     plan2 = plan_mutator(plan1, insert_before_close)
-> 1426     return (yield from plan2)
   1427 
   1428 

~/conda_envs/dev/lib/python3.6/site-packages/bluesky/plans.py in plan_mutator(plan, msg_proc)
    162                     continue
    163                 else:
--> 164                     raise ex
    165         # if inserting / mutating, put new generator on the stack
    166         # and replace the current msg with the first element from the

~/conda_envs/dev/lib/python3.6/site-packages/bluesky/plans.py in plan_mutator(plan, msg_proc)
    115             ret = result_stack.pop()
    116             try:
--> 117                 msg = plan_stack[-1].send(ret)
    118             except StopIteration as e:
    119                 # discard the exhausted generator

~/conda_envs/dev/lib/python3.6/site-packages/bluesky/plans.py in plan_mutator(plan, msg_proc)
    162                     continue
    163                 else:
--> 164                     raise ex
    165         # if inserting / mutating, put new generator on the stack
    166         # and replace the current msg with the first element from the

~/conda_envs/dev/lib/python3.6/site-packages/bluesky/plans.py in plan_mutator(plan, msg_proc)
    115             ret = result_stack.pop()
    116             try:
--> 117                 msg = plan_stack[-1].send(ret)
    118             except StopIteration as e:
    119                 # discard the exhausted generator

~/conda_envs/dev/lib/python3.6/site-packages/bluesky/plans.py in baseline_wrapper(plan, devices, name)
   1763         return (yield from plan)
   1764     else:
-> 1765         return (yield from plan_mutator(plan, insert_baseline))
   1766 
   1767 

~/conda_envs/dev/lib/python3.6/site-packages/bluesky/plans.py in plan_mutator(plan, msg_proc)
    162                     continue
    163                 else:
--> 164                     raise ex
    165         # if inserting / mutating, put new generator on the stack
    166         # and replace the current msg with the first element from the

~/conda_envs/dev/lib/python3.6/site-packages/bluesky/plans.py in plan_mutator(plan, msg_proc)
    115             ret = result_stack.pop()
    116             try:
--> 117                 msg = plan_stack[-1].send(ret)
    118             except StopIteration as e:
    119                 # discard the exhausted generator

~/Users/2017/2017_11_Frano/macros.py in ct_dark(numim, detectors, gain_std)
     40         yield from bp.mv(inout,'In')
     41         yield from bp.sleep(fccd.cam.acquire_period.value*2.01) # This has to be 2 until we can selectively remove dark images get_fastccd_images()
---> 42         yield from bp.mv(fccd.fccd1.capture_bgnd,1)  # SET TO 1 TO ARM FOR NEXT EVENT so that the FastCCD1 is already bkg subt
     43 
     44         #take darks

~/conda_envs/dev/lib/python3.6/site-packages/bluesky/plans.py in mv(*args)
    464     status_objects = []
    465     for obj, val in partition(2, args):
--> 466         ret = yield Msg('set', obj, val, group=group)
    467         status_objects.append(ret)
    468     yield Msg('wait', None, group=group)

~/conda_envs/dev/lib/python3.6/site-packages/bluesky/plans.py in plan_mutator(plan, msg_proc)
    187         try:
    188             # yield out the 'current message' and collect the return
--> 189             inner_ret = yield msg
    190         except GeneratorExit:
    191             # special case GeneratorExit.  We must clean up all of our plans

~/conda_envs/dev/lib/python3.6/site-packages/bluesky/plans.py in plan_mutator(plan, msg_proc)
    187         try:
    188             # yield out the 'current message' and collect the return
--> 189             inner_ret = yield msg
    190         except GeneratorExit:
    191             # special case GeneratorExit.  We must clean up all of our plans

~/conda_envs/dev/lib/python3.6/site-packages/bluesky/plans.py in plan_mutator(plan, msg_proc)
    187         try:
    188             # yield out the 'current message' and collect the return
--> 189             inner_ret = yield msg
    190         except GeneratorExit:
    191             # special case GeneratorExit.  We must clean up all of our plans

~/conda_envs/dev/lib/python3.6/site-packages/bluesky/plans.py in plan_mutator(plan, msg_proc)
    187         try:
    188             # yield out the 'current message' and collect the return
--> 189             inner_ret = yield msg
    190         except GeneratorExit:
    191             # special case GeneratorExit.  We must clean up all of our plans

~/conda_envs/dev/lib/python3.6/site-packages/bluesky/plans.py in plan_mutator(plan, msg_proc)
    187         try:
    188             # yield out the 'current message' and collect the return
--> 189             inner_ret = yield msg
    190         except GeneratorExit:
    191             # special case GeneratorExit.  We must clean up all of our plans

~/conda_envs/dev/lib/python3.6/site-packages/bluesky/run_engine.py in _run(self)
   1033                         # exceptions (coming in via throw) can be
   1034                         # raised
-> 1035                         response = yield from coro(msg)
   1036                     # special case `CancelledError` and let the outer
   1037                     # exception block deal with it.

~/conda_envs/dev/lib/python3.6/asyncio/coroutines.py in coro(*args, **kw)
    208         @functools.wraps(func)
    209         def coro(*args, **kw):
--> 210             res = func(*args, **kw)
    211             if (base_futures.isfuture(res) or inspect.isgenerator(res) or
    212                 isinstance(res, CoroWrapper)):

~/conda_envs/dev/lib/python3.6/site-packages/bluesky/run_engine.py in _set(self, msg)
   1731         group = kwargs.pop('group', None)
   1732         self._movable_objs_touched.add(msg.obj)
-> 1733         ret = msg.obj.set(*msg.args, **kwargs)
   1734         p_event = asyncio.Event(loop=self.loop)
   1735         pardon_failures = self._pardon_failures

~/conda_envs/dev/lib/python3.6/site-packages/ophyd/signal.py in set(self, value, timeout, settle_time)
    929         '''
    930         if not self._put_complete:
--> 931             return super().set(value, timeout=timeout, settle_time=settle_time)
    932 
    933         # using put completion:

~/conda_envs/dev/lib/python3.6/site-packages/ophyd/signal.py in set(self, value, timeout, settle_time)
    181 
    182         if self._set_thread is not None:
--> 183             raise RuntimeError('Another set() call is still in progress')
    184 
    185         st = Status(self)

RuntimeError: Another set() call is still in progress

Debug Uncovers:

In [278]: %debug
ERROR:asyncio:Task was destroyed but it is pending!
task: <Task pending coro=<Event.wait() done, defined at /home/xf23id1/conda_envs/dev/lib/python3.6/asyncio/locks.py:257> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4a7fa7318>()]> cb=[_wait.<locals>._on_completion() at /home/xf23id1/conda_envs/dev/lib/python3.6/asyncio/tasks.py:380]>
> /home/xf23id1/conda_envs/dev/lib/python3.6/site-packages/ophyd/signal.py(183)set()
    181 
    182         if self._set_thread is not None:
--> 183             raise RuntimeError('Another set() call is still in progress')
    184 
    185         st = Status(self)

ipdb> self
EpicsSignalWithRBV(read_pv='XF:23ID1-ES{FCCD}FastCCD1:CaptureBgnd_RBV', name='fccd_fccd1_capture_bgnd', parent='fccd_fccd1', value=0, timestamp=1510366132.812116, pv_kw={}, auto_monitor=False, string=False, write_pv='XF:23ID1-ES{FCCD}FastCCD1:CaptureBgnd', limits=False, put_complete=False)
ipdb>

Current definition of ct_dark()

def ct_dark(numim=None,detectors=[fccd], gain_std=0):
    """Collect dark images for fccd and add metadata tag for dark and gain. The pre-count shutter & gain states preserved.

    Parameters
    -----------
    numim: int
        Number of images to be measured.

    detectors: list
        List of detectors to be recorded.
        Default = [fccd]

    gain_std: int
        List of detectors to be recorded.
        Default = 0   (which is 'Auto' or x8, the most sensitive gain)

    Returns
    -----------
    """
    try: 
        #TODO figureout kwargs and self to mkae up to line 44 a single definition
        oldnumim = fccd.cam.num_images.value

        #Printing info
        print('\nStarting procedure to acquire darks {:3.3}Hz or {:3.3f}s.\n'.format(1/fccd.cam.acquire_time.value,fccd.cam.acquire_time.value))
        print('\tCurrent number of images = {}.\n'.format(fccd.cam.num_images.value)) 

        yield from bp.sleep(.3)

        if numim != None:
            print('\tSetting to {} images.\n'.format(numim))
            yield from abs_set(fccd.cam.num_images,numim,wait=True)

        dark_shutter_state = inout.status.value
        dark_sh_dict ={'Inserted':'In', 'Not Inserted':'Out'}
        gain_state = fccd.cam.fcric_gain.value
        gain_bit_dict = {0:'auto',1:'x2',2:'x1'}

        yield from bp.mv(inout,'In')
        yield from bp.sleep(fccd.cam.acquire_period.value*2.01) # This has to be 2 until we can selectively remove dark images get_fastccd_images()
        yield from bp.mv(fccd.fccd1.capture_bgnd,1)  # SET TO 1 TO ARM FOR NEXT EVENT so that the FastCCD1 is already bkg subt

        #take darks
        yield from _ct_dark(detectors,gain_std,gain_bit_dict)

        #Putting things back
        yield from _ct_dark_cleanup(oldnumim,gain_bit_dict,gain_state,dark_sh_dict, dark_shutter_state)

    except Exception:
        yield from _ct_dark_cleanup(oldnumim,gain_bit_dict,gain_state,dark_sh_dict, dark_shutter_state)
        raise
    except KeyboardInterrupt:
        yield from _ct_dark_cleanup(oldnumim,gain_bit_dict,gain_state,dark_sh_dict, dark_shutter_state)
        raise

def _ct_dark(detectors,gain_bit_input, gain_bit_dict):
    yield from bp.mv(fccd.cam.fcric_gain, gain_bit_input)
    #if _gain_bit_input != 0:
    #    yield from bp.sleep(fccd.cam.acquire_period.value*2.01) # This has to be 2 until we can selectively remove dark images get_fastccd_images()
    print('\n\nGain bit set to {} for a gain value of {}\n'.format(gain_bit_input,gain_bit_dict.get(gain_bit_input)))

    #TODO use md csxtools dark correction
    yield from count(detectors, md={'fccd': {'image':'dark', 'gain': gain_bit_dict.get(gain_bit_input)}})  

    ## Commented this out because we should be using the md
    #olog('ScanNo {} Darks at for {}Hz or {}s with most sensitive gain ({},Auto)'.format(db[-1].start['scan_id'],1/fccd.cam.acquire_time.value,fccd.cam.acquire_time.value,fccd.cam.fcric_gain.value))    

def _ct_dark_cleanup(oldnumim,gain_bit_dict,gain_state,dark_sh_dict,dark_shutter_state):
    print('\nReturning to intial conditions (pre-count).')
    yield from abs_set(fccd.cam.num_images,oldnumim,wait=True)

    yield from bp.mv(fccd.cam.fcric_gain, gain_state)
    yield from bp.mv(inout,dark_sh_dict.get(dark_shutter_state))
    yield from bp.sleep(fccd.cam.acquire_period.value)

    print('\tTotal images per trigger are NOW:\t {}'.format(fccd.cam.num_images.setpoint))
    print('\tFCCD FCRIC gain value is NOW:\t\t {}\n\n'.format(gain_bit_dict.get(fccd.cam.fcric_gain.value)))

NSLS-II-CSX / issues

Bluesky acting a little funny and not understanding set() inprogress #10

Debug Uncovers:

Current definition of ct_dark()