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.

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

Strict checks on device initialization state breaks Hardware Configuration Wizard #384

Open
marktsuchida opened this issue Sep 29, 2023 · 8 comments
Assignees

Comments

@marktsuchida
Copy link
Member

#376 causes errors in the Hardware Configuration Wizard: usually in the form of errors in the log but possibly causing a crash for some devices.

It is quite possible that part of this is due to newly exposed bugs in the HCW (made harder to track due to swallowing of exceptions by the HCW), but I'm creating this issue here to collect information, since the near-term workaround might be to disable the checks.

As far as I am aware, the issue is only with the HCW and does not occur when loading or reloading the configuration outside of the HCW (confirmed with Demo config).

@marktsuchida
Copy link
Member Author

Starting the HCW with the DemoConfig logs errors on State devices Operation not permitted on uninitialized device. This suggests the HCW is querying label information before initialization, which would be a bug (the number of positions would not in general be available until initialization).

log
2023-09-29T11:45:47.133455 tid21224 [dbg,App] [UI] JButton "Next >" clicked in ConfigWizard.
2023-09-29T11:45:47.143588 tid12952 [dbg,Core] Will load device COM1 from SerialManager
2023-09-29T11:45:47.143686 tid12952 [IFO,Core] Did load device COM1 from SerialManager; label = COM1
2023-09-29T11:45:47.143693 tid12952 [dbg,Core] Will load device TCP/IP serial port adapter (1) from TCPIPPort
2023-09-29T11:45:47.143734 tid12952 [IFO,Core] Did load device TCP/IP serial port adapter (1) from TCPIPPort; label = TCP/IP serial port adapter (1)
2023-09-29T11:45:47.143750 tid12952 [dbg,Core] Will load device DHub from DemoCamera
2023-09-29T11:45:47.143762 tid12952 [IFO,Core] Did load device DHub from DemoCamera; label = DHub
2023-09-29T11:45:47.143794 tid12952 [dbg,Core] Will load device DCam from DemoCamera
2023-09-29T11:45:47.143839 tid12952 [IFO,Core] Did load device DCam from DemoCamera; label = Camera
2023-09-29T11:45:47.143845 tid12952 [dbg,Core] Will load device DWheel from DemoCamera
2023-09-29T11:45:47.143854 tid12952 [IFO,Core] Did load device DWheel from DemoCamera; label = Dichroic
2023-09-29T11:45:47.143858 tid12952 [dbg,Core] Will load device DWheel from DemoCamera
2023-09-29T11:45:47.143870 tid12952 [IFO,Core] Did load device DWheel from DemoCamera; label = Emission
2023-09-29T11:45:47.143874 tid12952 [dbg,Core] Will load device DWheel from DemoCamera
2023-09-29T11:45:47.143893 tid12952 [IFO,Core] Did load device DWheel from DemoCamera; label = Excitation
2023-09-29T11:45:47.143897 tid12952 [dbg,Core] Will load device DObjective from DemoCamera
2023-09-29T11:45:47.143905 tid12952 [IFO,Core] Did load device DObjective from DemoCamera; label = Objective
2023-09-29T11:45:47.143910 tid12952 [dbg,Core] Will load device DStage from DemoCamera
2023-09-29T11:45:47.143935 tid12952 [IFO,Core] Did load device DStage from DemoCamera; label = Z
2023-09-29T11:45:47.143939 tid12952 [dbg,Core] Will load device DLightPath from DemoCamera
2023-09-29T11:45:47.143946 tid12952 [IFO,Core] Did load device DLightPath from DemoCamera; label = Path
2023-09-29T11:45:47.143963 tid12952 [dbg,Core] Will load device DXYStage from DemoCamera
2023-09-29T11:45:47.143981 tid12952 [IFO,Core] Did load device DXYStage from DemoCamera; label = XY
2023-09-29T11:45:47.143985 tid12952 [dbg,Core] Will load device DShutter from DemoCamera
2023-09-29T11:45:47.143999 tid12952 [IFO,Core] Did load device DShutter from DemoCamera; label = Shutter
2023-09-29T11:45:47.144003 tid12952 [dbg,Core] Will load device DAutoFocus from DemoCamera
2023-09-29T11:45:47.144009 tid12952 [IFO,Core] Did load device DAutoFocus from DemoCamera; label = Autofocus
2023-09-29T11:45:47.145037 tid12952 [ERR,Core:dev:Dichroic] Operation not permitted on uninitialized device [ Error in device "Dichroic" ]
2023-09-29T11:45:47.145083 tid12952 [ERR,Core:dev:Emission] Operation not permitted on uninitialized device [ Error in device "Emission" ]
2023-09-29T11:45:47.145109 tid12952 [ERR,Core:dev:Excitation] Operation not permitted on uninitialized device [ Error in device "Excitation" ]
2023-09-29T11:45:47.145131 tid12952 [ERR,Core:dev:Objective] Operation not permitted on uninitialized device [ Error in device "Objective" ]
2023-09-29T11:45:47.145164 tid12952 [ERR,Core:dev:Path] Operation not permitted on uninitialized device [ Error in device "Path" ]
2023-09-29T11:45:47.146124 tid12952 [IFO,Core] Will initialize device DHub

Actions on the Labels page do not appear to trigger an error.

Adding a new State device (e.g. DemoCamera's DWheel) logs the same error.

log
2023-09-29T11:51:25.236579 tid21224 [dbg,Core] Will load device DHub from DemoCamera
2023-09-29T11:51:25.236632 tid21224 [IFO,Core] Did load device DHub from DemoCamera; label = DHub
2023-09-29T11:51:37.916737 tid21224 [IFO,Core] Will initialize device DHub
2023-09-29T11:51:37.916745 tid21224 [IFO,Core] Did initialize device DHub
2023-09-29T11:51:43.949071 tid21224 [dbg,App] [UI] Table clicked in PeripheralSetupDlg.
2023-09-29T11:51:44.509169 tid21224 [dbg,App] [UI] Table clicked in PeripheralSetupDlg.
2023-09-29T11:51:51.953999 tid21224 [dbg,Core] Will load device DCam from DemoCamera
2023-09-29T11:51:51.954040 tid21224 [IFO,Core] Did load device DCam from DemoCamera; label = DCam
2023-09-29T11:51:54.444103 tid21224 [dbg,Core:dev:DCam] Will set property "MaximumExposureMs" to "10000.0000"
2023-09-29T11:51:54.444116 tid21224 [dbg,Core:dev:DCam] Did set property "MaximumExposureMs" to "10000.0000"
2023-09-29T11:51:54.444251 tid21224 [IFO,Core] Will initialize device DCam
2023-09-29T11:51:54.444273 tid21224 [dbg,dev:DCam] Setting Allowed Binning settings
2023-09-29T11:51:54.444383 tid21224 [dbg,dev:DCam] Reading property ScanMode
2023-09-29T11:51:54.444398 tid21224 [IFO,Core] Did initialize device DCam
2023-09-29T11:51:54.444958 tid21224 [dbg,dev:DCam] Reading property ScanMode
2023-09-29T11:51:54.451193 tid21224 [dbg,Core] Will load device DWheel from DemoCamera
2023-09-29T11:51:54.451223 tid21224 [IFO,Core] Did load device DWheel from DemoCamera; label = DWheel
2023-09-29T11:51:54.451263 tid21224 [ERR,Core:dev:DWheel] Operation not permitted on uninitialized device [ Error in device "DWheel" ]
2023-09-29T11:51:54.451294 tid21224 [IFO,Core] Will initialize device DWheel
2023-09-29T11:51:54.451320 tid21224 [IFO,Core] Did initialize device DWheel

It also appears that every time a pre-init property of a State device is edited, the error is logged. Need to confirm what is being called in this case.


Canceling the HCW after configuring a serial device (successfully or unsuccessfully) logs the error. This comes from waiting for COM devices as part of a call to waitForSystem().

  • We probably need waitForSystem() to skip uninitialized devices, which makes sense.
  • The error does not occur if the config file was successfully saved.
  • This indicates that the HCW fails to unload serial ports (including those that didn't get used). This is not strictly a bug in itself, but could be a source of history-dependent behavior that is hard to troubleshoot.
log
2023-09-29T13:05:47.482307 tid27644 [dbg,Core] Waiting for device COM1...
2023-09-29T13:05:47.482317 tid27644 [ERR,Core:dev:COM1] Operation not permitted on uninitialized device [ Error in device "COM1" ]
2023-09-29T13:05:47.507003 tid27644 [IFO,App] Failed to load hardware configuration
                                    [       ] java.lang.Exception: Operation not permitted on uninitialized device [ Error in device "COM1" ] in Thread[Thread-64,6,main]
                                    [       ]   at mmcorej.MMCoreJJNI.CMMCore_waitForSystem(Native Method)
                                    [       ]   at mmcorej.CMMCore.waitForSystem(CMMCore.java:608)
                                    [       ]   at org.micromanager.internal.MMStudio.loadSystemConfiguration(MMStudio.java:880)
                                    [       ]   at org.micromanager.internal.MMStudio.setSysConfigFile(MMStudio.java:551)
                                    [       ]   at org.micromanager.internal.menus.ConfigMenu.runHardwareWizard(ConfigMenu.java:149)
                                    [       ]   at java.lang.Thread.run(Thread.java:748)

There appears to be a case where the error is triggered via unloadAllDevices() but I cannot reproduce it.


I also encountered multiple issues with HCW behavior that may or may not be related to this issue (it's hard to tell because this issue potentially causes the HCW's data model to go out of sync with CMMCore's).

Given the complexity, I think the best course of action is to disable throwing exceptions for now and replace it with logging the error. That way, we can test the HCW without affecting its behavior until we are reasonably confident that it no longer violates the rules. Then we can re-enable the exceptions.

I will create (and merge) a PR to that effect later today.

@marktsuchida marktsuchida self-assigned this Sep 29, 2023
@nicost
Copy link
Member

nicost commented Sep 29, 2023

Thanks Mark! Happy to help testing on this end.

@marktsuchida
Copy link
Member Author

The throwing of exceptions has been removed in #385 (in favor of logging a message when continuing with an unsafe operation).

Leaving this issue open until I create individual issues for things that need fixing before re-enabling the exceptions.

@marktsuchida
Copy link
Member Author

Path forward:

  • Make it configurable whether strict checks are enabled or not (default to off)
  • Fix hcwizard code
  • Plan on enabling checks by default in a future major version of MMCore (but no rush)

@tlambert03
Copy link
Contributor

I think I might be seeing a related issue here in pymmcore_plus's microscope model (also used for the hardware config wizard there). And it has to do with directly getting/setting `core.getProperty('Core', 'Initialize'). Here's a minimal reproducer. I recognize that I'm directly accessing some very low level stuff here, but there appears to be an inconsistency in the reporting of the core initialization state in any case:

In [1]: core = CMMCorePlus()

# in a new instance, we can get/set Initialize
In [2]: core.getProperty('Core', 'Initialize')
Out[2]: '0'

In [3]: core.setProperty('Core', 'Initialize', '1')

In [4]: core.getProperty('Core', 'Initialize')
Out[4]: '1'

In [5]: core.setProperty('Core', 'Initialize', '0')

In [6]: core.loadDevice('Camera', 'DemoCamera', 'DCam')

# but after we initialize a single (non-core) device ...
In [7]: core.initializeDevice('Camera')

# getProperty says core is uninitialized ...
In [8]: core.getProperty('Core', 'Initialize')
Out[8]: '0'

# but setting it manually to '1' causes already initialized error
In [9]: core.setProperty('Core', 'Initialize', '1')
---------------------------------------------------------------------------
RuntimeError                              Traceback (most recent call last)
Cell In[9], line 1
----> 1 core.setProperty('Core', 'Initialize', '1')

File ~/mambaforge/envs/pymmcore-plus/lib/python3.11/site-packages/wrapt/decorators.py:470, in synchronized.<locals>._synchronized(wrapped, instance, args, kwargs)
    464 @decorator
    465 def _synchronized(wrapped, instance, args, kwargs):
    466     # Execute the wrapped function while the original supplied
    467     # lock is held.
    469     with lock:
--> 470         return wrapped(*args, **kwargs)

File ~/dev/self/pymmcore-plus/src/pymmcore_plus/core/_mmcore_plus.py:254, in CMMCorePlus.setProperty(self, label, propName, propValue)
    245 """Set property named `propName` on device `label` to `propValue`.
    246
    247 **Why Override?**  In `MMCore`, the calling of the `onPropertyChanged`
   (...)
    251 and the property Value has actually changed.
    252 """
    253 with self._property_change_emission_ensured(label, (propName,)):
--> 254     super().setProperty(label, propName, propValue)

RuntimeError: Device already initialized (or initialization already attempted)

It's also (understandably) not possible to query the core's device initialization state:

In [10]: core.getDeviceInitializationState('Core')
---------------------------------------------------------------------------
RuntimeError                              Traceback (most recent call last)
Cell In[10], line 1
----> 1 core.getDeviceInitializationState('Core')

RuntimeError: No device with label "Core"

@marktsuchida, is this related to the issues seen in MMStudio? Or unrelated?

I'll also note that this is easy for me to workaround in pymmcore-plus, so no urgency on my part

@tlambert03
Copy link
Contributor

also worth noting... that call to core.setProperty('Core', 'Initialize', '1') did actually succeed, even though it raised an exception:

In [1]: core = CMMCorePlus()

In [2]: core.getProperty('Core', 'Initialize')
Out[2]: '0'

In [3]: core.loadDevice('Camera', 'DemoCamera', 'DCam')

In [4]: core.initializeDevice('Camera')

In [5]: core.getProperty('Core', 'Initialize')
Out[5]: '0'

In [6]: core.setProperty('Core', 'Initialize', '1')
---------------------------------------------------------------------------
RuntimeError                              Traceback (most recent call last)
Cell In[6], line 1
----> 1 core.setProperty('Core', 'Initialize', '1')

RuntimeError: Device already initialized (or initialization already attempted)

In [7]: core.getProperty('Core', 'Initialize')
Out[7]: '1'  # value has been changed

@marktsuchida
Copy link
Member Author

Yeah, Core needs to be special-cased and I totally forgot that. Will fix, thanks for the report.

Some day I'll get Core to be more properly wrapped as a (virtual) device, but right now it's handled in an ad-hoc manner with conditionals scattered all over the place.

@marktsuchida
Copy link
Member Author

In addition, it turns out that serial devices need to be able to set serial port settings, at least in the case of implementing DetectDevice() (need to see if there are any other cases). So we also need to relax the check for setting pre-init properties after initialization. See https://forum.image.sc/t/mm-serialmanager-cannot-set-pre-init-property-after-initialization/88264

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants