dont understand reason for new exception that failed script

[ambarb]

@awalter-bnl can you advise on how to track this down?

OOPS!  something bad happened during rixs_one_energy()


...............Cleaning up................


---------------------------------------------------------------------------
RedundantStaging                          Traceback (most recent call last)
~/science_comm/111111_examples.py in <module>
----> 1 RE(lots_of_same())

/opt/conda_envs/collection-2019-2.0-six/lib/python3.6/site-packages/bluesky/run_engine.py in __call__(self, *args, **metadata_kw)
    754                     # it (unless it is a canceled error)
    755                     if exc is not None:
--> 756                         raise exc
    757 
    758             if self._interrupted:

/opt/conda_envs/collection-2019-2.0-six/lib/python3.6/site-packages/bluesky/run_engine.py in _run(self)
   1263             self._reason = str(err)
   1264             self.log.exception("Run aborted")
-> 1265             raise err
   1266         finally:
   1267             # Some done_callbacks may still be alive in other threads.

/opt/conda_envs/collection-2019-2.0-six/lib/python3.6/site-packages/bluesky/run_engine.py in _run(self)
   1128                         try:
   1129                             msg = self._plan_stack[-1].throw(
-> 1130                                 self._exception or resp)
   1131                         except Exception as e:
   1132                             # The current plan did not handle it,

/opt/conda_envs/collection-2019-2.0-six/lib/python3.6/site-packages/bluesky/preprocessors.py in __call__(self, plan)
   1292         plan = monitor_during_wrapper(plan, self.monitors)
   1293         plan = baseline_wrapper(plan, self.baseline)
-> 1294         return (yield from plan)

/opt/conda_envs/collection-2019-2.0-six/lib/python3.6/site-packages/bluesky/preprocessors.py in baseline_wrapper(plan, devices, name)
   1147         return (yield from plan)
   1148     else:
-> 1149         return (yield from plan_mutator(plan, insert_baseline))
   1150 
   1151 

/opt/conda_envs/collection-2019-2.0-six/lib/python3.6/site-packages/bluesky/preprocessors.py in plan_mutator(plan, msg_proc)
     75             # if we have a stashed exception, pass it along
     76             try:
---> 77                 msg = plan_stack[-1].throw(exception)
     78             except StopIteration as e:
     79                 # discard the exhausted generator

/opt/conda_envs/collection-2019-2.0-six/lib/python3.6/site-packages/bluesky/preprocessors.py in monitor_during_wrapper(plan, signals)
    788     plan1 = plan_mutator(plan, insert_after_open)
    789     plan2 = plan_mutator(plan1, insert_before_close)
--> 790     return (yield from plan2)
    791 
    792 

/opt/conda_envs/collection-2019-2.0-six/lib/python3.6/site-packages/bluesky/preprocessors.py in plan_mutator(plan, msg_proc)
     75             # if we have a stashed exception, pass it along
     76             try:
---> 77                 msg = plan_stack[-1].throw(exception)
     78             except StopIteration as e:
     79                 # discard the exhausted generator

/opt/conda_envs/collection-2019-2.0-six/lib/python3.6/site-packages/bluesky/preprocessors.py in plan_mutator(plan, msg_proc)
     75             # if we have a stashed exception, pass it along
     76             try:
---> 77                 msg = plan_stack[-1].throw(exception)
     78             except StopIteration as e:
     79                 # discard the exhausted generator

/opt/conda_envs/collection-2019-2.0-six/lib/python3.6/site-packages/bluesky/preprocessors.py in fly_during_wrapper(plan, flyers)
    846     plan1 = plan_mutator(plan, insert_after_open)
    847     plan2 = plan_mutator(plan1, insert_before_close)
--> 848     return (yield from plan2)
    849 
    850 

/opt/conda_envs/collection-2019-2.0-six/lib/python3.6/site-packages/bluesky/preprocessors.py in plan_mutator(plan, msg_proc)
     75             # if we have a stashed exception, pass it along
     76             try:
---> 77                 msg = plan_stack[-1].throw(exception)
     78             except StopIteration as e:
     79                 # discard the exhausted generator

/opt/conda_envs/collection-2019-2.0-six/lib/python3.6/site-packages/bluesky/preprocessors.py in plan_mutator(plan, msg_proc)
     75             # if we have a stashed exception, pass it along
     76             try:
---> 77                 msg = plan_stack[-1].throw(exception)
     78             except StopIteration as e:
     79                 # discard the exhausted generator

~/science_comm/111111_examples.py in lots_of_same(repeat_block)
      8 
      9     for i in range(0,repeat_block):
---> 10         yield from rixs_one_energy_1(split, total, num_cycles, en, ext_vg, 'testing sclr fail without plot' )
     11         #yield from rixs_one_energy_1(split, total, num_cycles, en, ext_vg, 'testing sclr fail' , False)
     12 

~/science_comm/111111_examples.py in rixs_one_energy_1(split_time, total_exp, cycles, energy, ext_vg, reason, disable_sclr_plt)
     85 
     86     except Exception:
---> 87         print('\n\nOOPS!  something bad happened during rixs_one_energy()')
     88         yield from rixs_cleanup(sclr_set_time)
     89         return fails

~/science_comm/111111_examples.py in rixs_cleanup(sclr_set_time)
     30         print('\n\n...............Cleaning up................\n\n')
     31         yield from sleep(1)
---> 32         yield from pzshutter_disable()
     33         yield from mv(sclr.preset_time,sclr_set_time)
     34         sclr_enable()

~/science_comm/111111_examples.py in pzshutter_disable()
    135     yield from mv(rixscam.cam.acquire_time, rixscam_exp)
    136     yield from mv(pzshutter,'None')
--> 137     yield from snap([rixscam])#, num=1, md = {'reason': 'enable pzshutter'})
    138     yield from mv(rixscam.cam.acquire_time, rixscam_exp_temp)
    139 

~/science_comm/111111_examples.py in snap(dets)
    113 def snap(dets):
    114     for d in dets:
--> 115         yield from bps.stage(d)
    116     for d in dets:
    117         yield from bps.trigger(d, group='snap')

/opt/conda_envs/collection-2019-2.0-six/lib/python3.6/site-packages/bluesky/plan_stubs.py in stage(obj)
    584     :func:`bluesky.plan_stubs.unstage`
    585     """
--> 586     return (yield Msg('stage', obj))
    587 
    588 

/opt/conda_envs/collection-2019-2.0-six/lib/python3.6/site-packages/bluesky/preprocessors.py in plan_mutator(plan, msg_proc)
    192         try:
    193             # yield out the 'current message' and collect the return
--> 194             inner_ret = yield msg
    195         except GeneratorExit:
    196             # special case GeneratorExit.  We must clean up all of our plans

/opt/conda_envs/collection-2019-2.0-six/lib/python3.6/site-packages/bluesky/preprocessors.py in plan_mutator(plan, msg_proc)
    192         try:
    193             # yield out the 'current message' and collect the return
--> 194             inner_ret = yield msg
    195         except GeneratorExit:
    196             # special case GeneratorExit.  We must clean up all of our plans

/opt/conda_envs/collection-2019-2.0-six/lib/python3.6/site-packages/bluesky/preprocessors.py in plan_mutator(plan, msg_proc)
    192         try:
    193             # yield out the 'current message' and collect the return
--> 194             inner_ret = yield msg
    195         except GeneratorExit:
    196             # special case GeneratorExit.  We must clean up all of our plans

/opt/conda_envs/collection-2019-2.0-six/lib/python3.6/site-packages/bluesky/preprocessors.py in plan_mutator(plan, msg_proc)
    192         try:
    193             # yield out the 'current message' and collect the return
--> 194             inner_ret = yield msg
    195         except GeneratorExit:
    196             # special case GeneratorExit.  We must clean up all of our plans

/opt/conda_envs/collection-2019-2.0-six/lib/python3.6/site-packages/bluesky/preprocessors.py in plan_mutator(plan, msg_proc)
    192         try:
    193             # yield out the 'current message' and collect the return
--> 194             inner_ret = yield msg
    195         except GeneratorExit:
    196             # special case GeneratorExit.  We must clean up all of our plans

/opt/conda_envs/collection-2019-2.0-six/lib/python3.6/site-packages/bluesky/run_engine.py in _run(self)
   1209                         # exceptions (coming in via throw) can be
   1210                         # raised
-> 1211                         new_response = yield from coro(msg)
   1212 
   1213                     # special case `CancelledError` and let the outer

/opt/conda_envs/collection-2019-2.0-six/lib/python3.6/site-packages/bluesky/run_engine.py in _stage(self, msg)
   2215         if not hasattr(obj, 'stage'):
   2216             return []
-> 2217         result = obj.stage()
   2218         self._staged.add(obj)  # add first in case of failure below
   2219         yield from self._reset_checkpoint_state_coro()

/opt/conda_envs/collection-2019-2.0-six/lib/python3.6/site-packages/ophyd/areadetector/trigger_mixins.py in stage(self)
    119     def stage(self):
    120         self._acquisition_signal.subscribe(self._acquire_changed)
--> 121         super().stage()
    122 
    123     def unstage(self):

/opt/conda_envs/collection-2019-2.0-six/lib/python3.6/site-packages/ophyd/areadetector/base.py in stage(self, *args, **kwargs)
    156 
    157     def stage(self, *args, **kwargs):
--> 158         ret = super().stage(*args, **kwargs)
    159         try:
    160             self.validate_asyn_ports()

/opt/conda_envs/collection-2019-2.0-six/lib/python3.6/site-packages/ophyd/device.py in stage(self)
    569                                    "Maybe the most recent unstaging "
    570                                    "encountered an error before finishing. "
--> 571                                    "Try unstaging again.".format(self))
    572         self.log.debug("Staging %s", self.name)
    573         self._staged = Staged.partially

RedundantStaging: Device RIXSCam(prefix='XF:02ID1-ES{RIXSCam}:', name='rixscam', read_attrs=['xip', 'xip.count_possible_event', 'xip.count_above_threshold', 'xip.count_below_threshold', 'xip.count_neighbours', 'xip.count_event_2x2', 'xip.count_event_3x3', 'hdf5', 'hdf2'], configuration_attrs=['cam', 'cam.acquire_period', 'cam.acquire_time', 'cam.num_images', 'cam.temperature', 'cam.temperature_actual', 'cam.trigger_mode', 'centroid_enable', 'xip', 'xip.configuration_names', 'xip.port_name', 'xip.asyn_pipeline_config', 'xip.blocking_callbacks', 'xip.enable', 'xip.nd_array_port', 'xip.plugin_type', 'xip.algorithm', 'xip.output_mode', 'xip.bkgd_update_mode', 'xip.bkgd_value', 'xip.sum_3x3_threshold_min', 'xip.sum_3x3_threshold_max', 'xip.hist_start', 'xip.hist_bin_width', 'xip.hist_bin_count', 'xip.source_region', 'xip.dim0_region_start', 'xip.dim0_region_size', 'xip.dim1_region_start', 'xip.dim1_region_size', 'xip.x_expansion_factor', 'xip.y_expansion_factor', 'xip.centroid_correction', 'xip.beamline_energy', 'xip.isolinear_correction', 'xip.isolinear_coefficient_x2_1', 'xip.isolinear_coefficient_x1_1', 'xip.isolinear_coefficient_x0_1', 'xip.isolinear_coefficient_x2_2', 'xip.isolinear_coefficient_x1_2', 'xip.isolinear_coefficient_x0_2', 'xip.isolinear_threshold', 'hdf5', 'hdf5.configuration_names', 'hdf5.port_name', 'hdf5.asyn_pipeline_config', 'hdf5.blocking_callbacks', 'hdf5.enable', 'hdf5.nd_array_port', 'hdf5.plugin_type', 'hdf5.auto_increment', 'hdf5.auto_save', 'hdf5.file_format', 'hdf5.file_name', 'hdf5.file_path', 'hdf5.file_path_exists', 'hdf5.file_template', 'hdf5.file_write_mode', 'hdf5.full_file_name', 'hdf5.num_capture', 'hdf5.boundary_align', 'hdf5.boundary_threshold', 'hdf5.compression', 'hdf5.data_bits_offset', 'hdf5.extra_dim_name', 'hdf5.extra_dim_size', 'hdf5.io_speed', 'hdf5.num_col_chunks', 'hdf5.num_data_bits', 'hdf5.num_extra_dims', 'hdf5.num_frames_chunks', 'hdf5.num_frames_flush', 'hdf5.num_row_chunks', 'hdf5.run_time', 'hdf5.szip_num_pixels', 'hdf5.store_attr', 'hdf5.store_perform', 'hdf5.zlevel', 'hdf2', 'hdf2.configuration_names', 'hdf2.port_name', 'hdf2.asyn_pipeline_config', 'hdf2.blocking_callbacks', 'hdf2.enable', 'hdf2.nd_array_port', 'hdf2.plugin_type', 'hdf2.auto_increment', 'hdf2.auto_save', 'hdf2.file_format', 'hdf2.file_name', 'hdf2.file_path', 'hdf2.file_path_exists', 'hdf2.file_template', 'hdf2.file_write_mode', 'hdf2.full_file_name', 'hdf2.num_capture', 'hdf2.boundary_align', 'hdf2.boundary_threshold', 'hdf2.compression', 'hdf2.data_bits_offset', 'hdf2.extra_dim_name', 'hdf2.extra_dim_size', 'hdf2.io_speed', 'hdf2.num_col_chunks', 'hdf2.num_data_bits', 'hdf2.num_extra_dims', 'hdf2.num_frames_chunks', 'hdf2.num_frames_flush', 'hdf2.num_row_chunks', 'hdf2.run_time', 'hdf2.szip_num_pixels', 'hdf2.store_attr', 'hdf2.store_perform', 'hdf2.zlevel', 'set_node', 'sensor_region_xsize', 'sensor_region_ysize', 'sensor_region_xstart', 'sensor_region_ystart', 'sensor_binning_x', 'sensor_binning_y', 'ccd1_hv', 'ccd2_hv']) has been partially staged. Maybe the most recent unstaging encountered an error before finishing. Try unstaging again.

In [17]: fails                                                                                                                          
Out[17]: []

In [18]:                                                                                                                                

[awalter-bnl]

Hi @ambarb,
Can you place a link here to the code for the rixs_one_energy scan? It appears to be in a local directory called ~/science_comm/111111_examples.py but that does not appear to be on git so I would need to look at that to diagnose properly.

In the meantime, the traceback indicates to me that the 'snap' plan from line 137 in the above file (which performs some staging on line 115 in the above mentioned file) is being called while the rixscam was still staged from a previous part of the plan. I can think of four reasons this could happen:

1. The one_rixs_energy plan was started when the previous plan did not clean up after itself, possibly due to a ctrl-c followed by RE.halt(). This means that this must be the first 'stage' of the rixscam in the plan.
2. For some reason in the one_rixs_energy plan it is possible to bypass the section that unstages the rixscam but continue through the plan to the yield from snap([rixscam]) section.
3. one_energy_rixscam is written in a way that snap([rixscam]) is called prior to the actual unstage call, which means this pln would never work.
4. There is a deeper issue which means that we call unstage but that this is not being succesfully completed, but the RunEngine continues on regardless.

I can narrow this down further once I can see the actual code in the plan.

[ambarb]

@awalter-bnl Thanks for the useful comments. We can rule out the first option as it happened at midnight (late Sunday/early Monday).

I will send you the plans not on git. snap([rixscam]) may be in the profile that is on git. We have launched the same 2+ day scan to see if it happens again or we run free of errors. For this instance, it happened at the very end of the plan - all requested data was collected.

I will get back to you tomorrow after lunch.

[mrakitin]

@awalter-bnl, @ambarb, we worked with @pelliciari yesterday to push the science_comm directory to GitHub -- https://github.com/NSLS-II-SIX/science_commissioning. Also, a related issue was reported via #24 as well. Andrew's points make sense. I think we encountered a weird timeout, and the snap plan didn't finalize itself cleanly. I asked @tacaswell to confirm my guess in that issue.