Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

nabs test suite fails with bluesky=v1.11.0 #73

Open
ZLLentz opened this issue Jun 19, 2023 · 2 comments
Open

nabs test suite fails with bluesky=v1.11.0 #73

ZLLentz opened this issue Jun 19, 2023 · 2 comments

Comments

@ZLLentz
Copy link
Member

ZLLentz commented Jun 19, 2023

Tag details: https://github.com/bluesky/bluesky/releases/tag/v1.11.0
Some test suite excerpts from the "big integration test" at https://github.com/pcdshub/pcds-envs/actions/runs/5307584975

1 test failure relating to extra elog posts:

2023-06-19T04:19:26.5207980Z ______________________________ test_elog_callback ______________________________
2023-06-19T04:19:26.5208497Z 
2023-06-19T04:19:26.5208886Z RE = <bluesky.run_engine.RunEngine object at 0x7fd97ceb24f0>
2023-06-19T04:19:26.5210077Z hw = namespace(motor=SynAxis(prefix='', name='motor', read_attrs=['readback', 'setpoint'], configuration_attrs=['velocity',...ted', read_attrs=['softpos', 'noop', 'noop.readback', 'noop.setpoint'], configuration_attrs=['noop'], concurrent=True))
2023-06-19T04:19:26.5210742Z elog = <nabs.tests.conftest.elog.<locals>.MockELog object at 0x7fd979d837f0>
2023-06-19T04:19:26.5211223Z ipython = <nabs.tests.conftest.ipython.<locals>.MockIPython object at 0x7fd979d83f70>
2023-06-19T04:19:26.5211511Z 
2023-06-19T04:19:26.5211955Z     def test_elog_callback(RE, hw, elog, ipython):
2023-06-19T04:19:26.5212290Z         elogc = ELogPoster(elog, ipython)
2023-06-19T04:19:26.5212579Z         elogc.enable_run_posts = True
2023-06-19T04:19:26.5212835Z     
2023-06-19T04:19:26.5213079Z         elog_uid = RE.subscribe(elogc)
2023-06-19T04:19:26.5213312Z     
2023-06-19T04:19:26.5213652Z         ipython.user_ns["In"].append(
2023-06-19T04:19:26.5213949Z             "RE(bp.scan([hw.det], hw.motor, 0, 1, num=10))"
2023-06-19T04:19:26.5214190Z         )
2023-06-19T04:19:26.5214457Z         RE(bp.scan([hw.det], hw.motor, 0, 1, num=10))
2023-06-19T04:19:26.5214698Z     
2023-06-19T04:19:26.5214943Z         assert len(elog.posts) == 2  # start and table posts
2023-06-19T04:19:26.5215540Z         assert 'plan_info' in elog.posts[0][1]['tags']
2023-06-19T04:19:26.5215948Z         assert 'RE' in elog.posts[0][1]['tags']
2023-06-19T04:19:26.5216198Z     
2023-06-19T04:19:26.5216441Z         ipython.user_ns["In"].append(
2023-06-19T04:19:26.5216891Z             "RE(bp.scan([hw.det], hw.motor, 0, 1, num=10), post=False)"
2023-06-19T04:19:26.5217156Z         )
2023-06-19T04:19:26.5217405Z         RE(bp.scan([hw.det], hw.motor, 0, 1, num=10), post=False)
2023-06-19T04:19:26.5217738Z         assert len(elog.posts) == 2  # confirm no new entries
2023-06-19T04:19:26.5217996Z     
2023-06-19T04:19:26.5218207Z         elog.enable_run_posts = False
2023-06-19T04:19:26.5218477Z         ipython.user_ns["In"].append(
2023-06-19T04:19:26.5218766Z             "RE(bp.scan([hw.det], hw.motor, 0, 1, num=10))"
2023-06-19T04:19:26.5219172Z         )
2023-06-19T04:19:26.5219436Z         RE(bp.scan([hw.det], hw.motor, 0, 1, num=10))
2023-06-19T04:19:26.5219772Z         assert len(elog.posts) == 2  # confirm no new entries
2023-06-19T04:19:26.5220028Z     
2023-06-19T04:19:26.5220381Z         # Test override of elog default
2023-06-19T04:19:26.5220709Z         last_cmd = "RE(bp.scan([hw.det], hw.motor, 10, 0, num=10), post=True)"
2023-06-19T04:19:26.5221245Z         ipython.user_ns["In"].append(last_cmd)
2023-06-19T04:19:26.5221585Z         RE(bp.scan([hw.det], hw.motor, 10, 0, num=10), post=True)
2023-06-19T04:19:26.5221889Z         assert len(elog.posts) == 4
2023-06-19T04:19:26.5222280Z         assert elog.posts[-2][0][0] == last_cmd
2023-06-19T04:19:26.5222533Z     
2023-06-19T04:19:26.5222781Z         # test behavior when no table is generated
2023-06-19T04:19:26.5223102Z         last_cmd = "RE(bp.count([]), post=True)"
2023-06-19T04:19:26.5223418Z         ipython.user_ns["In"].append(last_cmd)
2023-06-19T04:19:26.5223706Z         RE(bp.count([]), post=True)
2023-06-19T04:19:26.5224045Z >       assert len(elog.posts) == 5  # empty table should not be posted
2023-06-19T04:19:26.5224394Z E       AssertionError: assert 6 == 5
2023-06-19T04:19:26.5225306Z E        +  where 6 = len([(('RE(bp.scan([hw.det], hw.motor, 0, 1, num=10))',), {'tags': ['plan_info', 'RE']}), (('<!DOCTYPE html>\n<html>\n<hea...>\n  </thead>\n  <tbody>\n  </tbody>\n</table></body> </html>',), {'tags': ['run_table', 'RE'], 'title': 'run_table'})])
2023-06-19T04:19:26.5226690Z E        +    where [(('RE(bp.scan([hw.det], hw.motor, 0, 1, num=10))',), {'tags': ['plan_info', 'RE']}), (('<!DOCTYPE html>\n<html>\n<hea...>\n  </thead>\n  <tbody>\n  </tbody>\n</table></body> </html>',), {'tags': ['run_table', 'RE'], 'title': 'run_table'})] = <nabs.tests.conftest.elog.<locals>.MockELog object at 0x7fd979d837f0>.posts

13 failures relating to daq wrapper:

2023-06-19T04:19:26.5705919Z ________________________ test_daq_step_scan_run_events _________________________
2023-06-19T04:19:26.5705931Z 
2023-06-19T04:19:26.5706115Z RE = <bluesky.run_engine.RunEngine object at 0x7fd94c1d1910>
2023-06-19T04:19:26.5706823Z hw = namespace(motor=SynAxis(prefix='', name='motor', read_attrs=['readback', 'setpoint'], configuration_attrs=['velocity',...ted', read_attrs=['softpos', 'noop', 'noop.readback', 'noop.setpoint'], configuration_attrs=['noop'], concurrent=True))
2023-06-19T04:19:26.5706979Z daq_step_scan = <function scan at 0x7fd94bf9fc10>
2023-06-19T04:19:26.5706987Z 
2023-06-19T04:19:26.5707143Z     def test_daq_step_scan_run_events(RE, hw, daq_step_scan):
2023-06-19T04:19:26.5707230Z         """
2023-06-19T04:19:26.5707485Z         Actually run a scan and make sure it doesn't error out.
2023-06-19T04:19:26.5707572Z         """
2023-06-19T04:19:26.5707759Z >       RE(daq_step_scan([hw.det], hw.motor, 0, 10, 11, events=10, record=False,
2023-06-19T04:19:26.5707876Z                          use_l3t=True))
2023-06-19T04:19:26.5708038Z 
2023-06-19T04:19:26.5708182Z nabs/tests/test_preprocessors.py:88: 
2023-06-19T04:19:26.5708314Z _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
2023-06-19T04:19:26.5708697Z /home/runner/miniconda/envs/pcds-test/lib/python3.9/site-packages/bluesky/run_engine.py:899: in __call__
2023-06-19T04:19:26.5708863Z     plan_return = self._resume_task(init_func=_build_task)
2023-06-19T04:19:26.5709261Z /home/runner/miniconda/envs/pcds-test/lib/python3.9/site-packages/bluesky/run_engine.py:1038: in _resume_task
2023-06-19T04:19:26.5709352Z     raise exc
2023-06-19T04:19:26.5709726Z /home/runner/miniconda/envs/pcds-test/lib/python3.9/site-packages/bluesky/run_engine.py:1668: in _run
2023-06-19T04:19:26.5709816Z     raise err
2023-06-19T04:19:26.5710178Z /home/runner/miniconda/envs/pcds-test/lib/python3.9/site-packages/bluesky/run_engine.py:1528: in _run
2023-06-19T04:19:26.5710390Z     msg = self._plan_stack[-1].send(resp)
2023-06-19T04:19:26.5710519Z nabs/preprocessors.py:227: in inner
2023-06-19T04:19:26.5710703Z     return (yield from daq_step_scan_wrapper(plan(*args, **kwargs),
2023-06-19T04:19:26.5710866Z nabs/preprocessors.py:194: in daq_step_scan_wrapper
2023-06-19T04:19:26.5710993Z     return (yield from daq_step_plan())
2023-06-19T04:19:26.5711389Z /home/runner/miniconda/envs/pcds-test/lib/python3.9/site-packages/bluesky/utils/__init__.py:1202: in dec_inner
2023-06-19T04:19:26.5711503Z     return (yield from plan)
2023-06-19T04:19:26.5711915Z /home/runner/miniconda/envs/pcds-test/lib/python3.9/site-packages/bluesky/preprocessors.py:954: in stage_wrapper
2023-06-19T04:19:26.5712089Z     return (yield from finalize_wrapper(inner(), unstage_devices()))
2023-06-19T04:19:26.5712504Z /home/runner/miniconda/envs/pcds-test/lib/python3.9/site-packages/bluesky/preprocessors.py:511: in finalize_wrapper
2023-06-19T04:19:26.5712721Z     ret = yield from plan
2023-06-19T04:19:26.5713122Z /home/runner/miniconda/envs/pcds-test/lib/python3.9/site-packages/bluesky/preprocessors.py:952: in inner
2023-06-19T04:19:26.5713234Z     return (yield from plan)
2023-06-19T04:19:26.5713385Z nabs/preprocessors.py:192: in daq_step_plan
2023-06-19T04:19:26.5713557Z     return (yield from bpp.plan_mutator(plan, daq_mutator))
2023-06-19T04:19:26.5713966Z /home/runner/miniconda/envs/pcds-test/lib/python3.9/site-packages/bluesky/preprocessors.py:172: in plan_mutator
2023-06-19T04:19:26.5714041Z     raise ex
2023-06-19T04:19:26.5714447Z /home/runner/miniconda/envs/pcds-test/lib/python3.9/site-packages/bluesky/preprocessors.py:125: in plan_mutator
2023-06-19T04:19:26.5714631Z     msg = plan_stack[-1].send(ret)
2023-06-19T04:19:26.5714997Z /home/runner/miniconda/envs/pcds-test/lib/python3.9/site-packages/bluesky/plans.py:1118: in scan
2023-06-19T04:19:26.5715156Z     return (yield from scan_nd(detectors, full_cycler,
2023-06-19T04:19:26.5715525Z /home/runner/miniconda/envs/pcds-test/lib/python3.9/site-packages/bluesky/plans.py:1013: in scan_nd
2023-06-19T04:19:26.5715665Z     return (yield from inner_scan_nd())
2023-06-19T04:19:26.5716055Z /home/runner/miniconda/envs/pcds-test/lib/python3.9/site-packages/bluesky/utils/__init__.py:1202: in dec_inner
2023-06-19T04:19:26.5716151Z     return (yield from plan)
2023-06-19T04:19:26.5716558Z /home/runner/miniconda/envs/pcds-test/lib/python3.9/site-packages/bluesky/preprocessors.py:954: in stage_wrapper
2023-06-19T04:19:26.5716742Z     return (yield from finalize_wrapper(inner(), unstage_devices()))
2023-06-19T04:19:26.5717158Z /home/runner/miniconda/envs/pcds-test/lib/python3.9/site-packages/bluesky/preprocessors.py:511: in finalize_wrapper
2023-06-19T04:19:26.5717265Z     ret = yield from plan
2023-06-19T04:19:26.5717656Z /home/runner/miniconda/envs/pcds-test/lib/python3.9/site-packages/bluesky/preprocessors.py:952: in inner
2023-06-19T04:19:26.5717767Z     return (yield from plan)
2023-06-19T04:19:26.5718155Z /home/runner/miniconda/envs/pcds-test/lib/python3.9/site-packages/bluesky/utils/__init__.py:1202: in dec_inner
2023-06-19T04:19:26.5718363Z     return (yield from plan)
2023-06-19T04:19:26.5718944Z /home/runner/miniconda/envs/pcds-test/lib/python3.9/site-packages/bluesky/preprocessors.py:327: in run_wrapper
2023-06-19T04:19:26.5719192Z     yield from contingency_wrapper(plan,
2023-06-19T04:19:26.5746375Z /home/runner/miniconda/envs/pcds-test/lib/python3.9/site-packages/bluesky/preprocessors.py:577: in contingency_wrapper
2023-06-19T04:19:26.5746538Z     ret = yield from plan
2023-06-19T04:19:26.5747041Z /home/runner/miniconda/envs/pcds-test/lib/python3.9/site-packages/bluesky/plans.py:1011: in inner_scan_nd
2023-06-19T04:19:26.5747205Z     yield from per_step(detectors, step, pos_cache)
2023-06-19T04:19:26.5747603Z /home/runner/miniconda/envs/pcds-test/lib/python3.9/site-packages/bluesky/plan_stubs.py:1270: in one_nd_step
2023-06-19T04:19:26.5747761Z     yield from take_reading(list(detectors) + list(motors))
2023-06-19T04:19:26.5748179Z /home/runner/miniconda/envs/pcds-test/lib/python3.9/site-packages/bluesky/plan_stubs.py:1064: in trigger_and_read
2023-06-19T04:19:26.5748373Z     return (yield from rewindable_wrapper(inner_trigger_and_read(),
2023-06-19T04:19:26.5748807Z /home/runner/miniconda/envs/pcds-test/lib/python3.9/site-packages/bluesky/preprocessors.py:695: in rewindable_wrapper
2023-06-19T04:19:26.5748921Z     return (yield from plan)
2023-06-19T04:19:26.5749348Z /home/runner/miniconda/envs/pcds-test/lib/python3.9/site-packages/bluesky/plan_stubs.py:1056: in inner_trigger_and_read
2023-06-19T04:19:26.5749485Z     ret = yield from contingency_wrapper(
2023-06-19T04:19:26.5749914Z /home/runner/miniconda/envs/pcds-test/lib/python3.9/site-packages/bluesky/preprocessors.py:591: in contingency_wrapper
2023-06-19T04:19:26.5750011Z     yield from else_plan()
2023-06-19T04:19:26.5750414Z /home/runner/miniconda/envs/pcds-test/lib/python3.9/site-packages/bluesky/plan_stubs.py:1050: in standard_path
2023-06-19T04:19:26.5750780Z     yield from save()
2023-06-19T04:19:26.5751163Z /home/runner/miniconda/envs/pcds-test/lib/python3.9/site-packages/bluesky/plan_stubs.py:85: in save
2023-06-19T04:19:26.5751342Z     return (yield Msg('save'))
2023-06-19T04:19:26.5751749Z /home/runner/miniconda/envs/pcds-test/lib/python3.9/site-packages/bluesky/preprocessors.py:197: in plan_mutator
2023-06-19T04:19:26.5751852Z     inner_ret = yield msg
2023-06-19T04:19:26.5752228Z /home/runner/miniconda/envs/pcds-test/lib/python3.9/site-packages/bluesky/run_engine.py:1588: in _run
2023-06-19T04:19:26.5752338Z     new_response = await coro(msg)
2023-06-19T04:19:26.5752711Z /home/runner/miniconda/envs/pcds-test/lib/python3.9/site-packages/bluesky/run_engine.py:1964: in _save
2023-06-19T04:19:26.5752828Z     await current_run.save(msg)
2023-06-19T04:19:26.5752967Z _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
2023-06-19T04:19:26.5752978Z 
2023-06-19T04:19:26.5753177Z self = <bluesky.bundlers.RunBundler object at 0x7fd94c1f2d90>
2023-06-19T04:19:26.5753425Z msg = Msg('save', obj=None, args=(), kwargs={}, run=None)
2023-06-19T04:19:26.5753433Z 
2023-06-19T04:19:26.5753553Z     async def save(self, msg):
2023-06-19T04:19:26.5753710Z         """Save the event that is currently being bundled
2023-06-19T04:19:26.5753775Z     
2023-06-19T04:19:26.5753977Z         Create and emit an Event document containing the data read from devices
2023-06-19T04:19:26.5754169Z         in self._objs_read. Emit any Resource and Datum documents cached by
2023-06-19T04:19:26.5754365Z         those devices before emitting the Event document. If this is the first
2023-06-19T04:19:26.5754556Z         Event of its stream then create and emit the Event Descriptor document
2023-06-19T04:19:26.5754725Z         before emitting Resource, Datum, and Event documents.
2023-06-19T04:19:26.5754804Z     
2023-06-19T04:19:26.5754932Z         Expected message object is::
2023-06-19T04:19:26.5755011Z     
2023-06-19T04:19:26.5755159Z             Msg('save')
2023-06-19T04:19:26.5755250Z         """
2023-06-19T04:19:26.5755364Z         if not self.bundling:
2023-06-19T04:19:26.5755649Z             raise IllegalMessageSequence(
2023-06-19T04:19:26.5755885Z                 "A 'create' message must be sent, to "
2023-06-19T04:19:26.5756017Z                 "open an event bundle, before that "
2023-06-19T04:19:26.5756233Z                 "bundle can be saved with 'save'."
2023-06-19T04:19:26.5756319Z             )
2023-06-19T04:19:26.5756398Z     
2023-06-19T04:19:26.5756704Z         # Short-circuit if nothing has been read. (Do not create empty Events.)
2023-06-19T04:19:26.5756814Z         if not self._objs_read:
2023-06-19T04:19:26.5756931Z             self.bundling = False
2023-06-19T04:19:26.5757033Z             self._bundle_name = None
2023-06-19T04:19:26.5757121Z             return
2023-06-19T04:19:26.5757304Z         # The Event Descriptor is uniquely defined by the set of objects
2023-06-19T04:19:26.5757426Z         # read in this Event grouping.
2023-06-19T04:19:26.5757573Z         objs_read = frozenset(self._objs_read)
2023-06-19T04:19:26.5757652Z     
2023-06-19T04:19:26.5757764Z         # Event Descriptor key
2023-06-19T04:19:26.5757873Z         desc_key = self._bundle_name
2023-06-19T04:19:26.5757953Z     
2023-06-19T04:19:26.5758129Z         # This is a separate check because it can be reset on resume.
2023-06-19T04:19:26.5758241Z         seq_num_key = desc_key
2023-06-19T04:19:26.5758392Z         if seq_num_key not in self._sequence_counters:
2023-06-19T04:19:26.5758497Z             counter = count(1)
2023-06-19T04:19:26.5758646Z             counter_copy1, counter_copy2 = tee(counter)
2023-06-19T04:19:26.5758798Z             self._sequence_counters[seq_num_key] = counter_copy1
2023-06-19T04:19:26.5758973Z             self._teed_sequence_counters[seq_num_key] = counter_copy2
2023-06-19T04:19:26.5759084Z         self.bundling = False
2023-06-19T04:19:26.5759197Z         self._bundle_name = None
2023-06-19T04:19:26.5759276Z     
2023-06-19T04:19:26.5759477Z         d_objs, descriptor_doc = self._descriptors.get(desc_key, (None, None))
2023-06-19T04:19:26.5759741Z         # we do not have the descriptor cached, make it
2023-06-19T04:19:26.5759845Z         if descriptor_doc is None:
2023-06-19T04:19:26.5760232Z             descriptor_doc = await self._prepare_stream(desc_key, objs_read)
2023-06-19T04:19:26.5760358Z         # do have the descriptor cached
2023-06-19T04:19:26.5760469Z         elif d_objs != objs_read:
2023-06-19T04:19:26.5760581Z >           raise RuntimeError(
2023-06-19T04:19:26.5760738Z                 "Mismatched objects read, expected {!s}, "
2023-06-19T04:19:26.5760878Z                 "got {!s}".format(d_objs, objs_read)
2023-06-19T04:19:26.5760947Z             )
2023-06-19T04:19:26.5762603Z E           RuntimeError: Mismatched objects read, expected frozenset({SynAxis(prefix='', name='motor', read_attrs=['readback', 'setpoint'], configuration_attrs=['velocity', 'acceleration']), SynGauss(prefix='', name='det', read_attrs=['val'], configuration_attrs=['Imax', 'center', 'sigma', 'noise', 'noise_multiplier'])}), got frozenset({SynAxis(prefix='', name='motor', read_attrs=['readback', 'setpoint'], configuration_attrs=['velocity', 'acceleration']), SynGauss(prefix='', name='det', read_attrs=['val'], configuration_attrs=['Imax', 'center', 'sigma', 'noise', 'noise_multiplier']), <pcdsdaq.daq.original.Daq object at 0x7fd94bf9a2e0>})
2023-06-19T04:19:26.5762636Z 
2023-06-19T04:19:26.5763033Z /home/runner/miniconda/envs/pcds-test/lib/python3.9/site-packages/bluesky/bundlers.py:473: RuntimeError
@ZLLentz
Copy link
Member Author

ZLLentz commented Jun 19, 2023 •
edited
Loading

I think the source of these is the differing behavior with predeclaring streams, which is new but is not automatic and is added on a per-plan basis:
https://github.com/bluesky/bluesky/blob/e38b2dab394300fff1cc02fbc5bd2fba23cbfdc1/bluesky/plans.py#L1009
https://github.com/bluesky/bluesky/blob/e38b2dab394300fff1cc02fbc5bd2fba23cbfdc1/bluesky/plan_stubs.py#L47
https://github.com/bluesky/bluesky/blob/e38b2dab394300fff1cc02fbc5bd2fba23cbfdc1/bluesky/run_engine.py#L1830-L1852

For the elog failure, we're probably getting extra posts from the stream declaration. I think for this one we need to carefully examine the new behavior and see if it is wrong or if it is just different. (It could also be something else entirely, of course)

For the daq wrapper, here are some first pass options, though I don't fully understand the issue yet:

  • manipulate plans that use this wrapper into not predeclaring streams
  • extend the mutator to understand declare_stream and declare it properly
  • make the mutator less brittle to upstream changes (and make it less complicated) (minor refactor?)

@ZLLentz
Copy link
Member Author

ZLLentz commented Jun 19, 2023 •
edited
Loading

After thinking for 3 whole minutes, option 2 makes the most sense to me:

extend the mutator to understand declare_stream and declare it properly

declare_stream message comes in -> mutator adds the daq to it if it wasn't present

Maybe that's all that is needed here

@klauer klauer mentioned this issue Jul 24, 2023
Merged
3 tasks
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@ZLLentz