Writing this issue for posterity/to capture some strange behaviour observed earlier in the year. NB I haven't seen this happen again since.
Pocs completed a 54/54 exposure block for a compound field and proceeded to to run a coarse focusing block. The coarse focusing block finished and then the main pocs logs indicated pocs moved to the scheduling state and started a new observation block for the same compound field. After about 15 minutes a timeout error was raised and pocs transitioned to the scheduling state again, selecting the same compound field and this time successfully started taking exposures without timeouts.
The logs from jetson08 seem to indicate that instead of moving to a compound field observation, it instead initiated a fine focus (this is what should happen), completed it and then remained in an inactive state until receive a new observation from the pocs control computer instance.
Control computer pocs instance logs:
I 06-22 13:32:32.593 Taking observation <bound method AbstractObservation.__name__ of <huntsman.pocs.scheduler.observation.base.CompoundObservation object at 0x7fca81f14610>>: <bound method AbstractField.__name__ of <huntsman.pocs.scheduler.field.CompoundField object at 0x7fca81f121c0>>: Centaurus-A: exptime=300.0 s, filter=r_band for CameraGroup with 8 cameras.
I 06-22 13:37:48.188 Observation status: {'current_exp': 52, 'exp_set_size': 54}
I 06-22 13:37:48.474 Taking observation <bound method AbstractObservation.__name__ of <huntsman.pocs.scheduler.observation.base.CompoundObservation object at 0x7fca81f14610>>: <bound method AbstractField.__name__ of <huntsman.pocs.scheduler.field.CompoundField object at 0x7fca81f121c0>>: Centaurus-A: exptime=300.0 s, filter=r_band for CameraGroup with 8 cameras.
I 06-22 13:43:05.050 Observation status: {'current_exp': 53, 'exp_set_size': 54}
I 06-22 13:43:05.286 Taking observation <bound method AbstractObservation.__name__ of <huntsman.pocs.scheduler.observation.base.CompoundObservation object at 0x7fca81f14610>>: <bound method AbstractField.__name__ of <huntsman.pocs.scheduler.field.CompoundField object at 0x7fca81f121c0>>: Centaurus-A: exptime=300.0 s, filter=r_band for CameraGroup with 8 cameras.
I 06-22 13:48:20.724 Observation status: {'current_exp': 54, 'exp_set_size': 54}
S 06-22 13:48:20.726 Unit says: Finished with the observing state. The next state is scheduling.
S 06-22 13:48:20.727 Finished with observing
I 06-22 13:48:20.772 Run loop: 'observing' -> 'scheduling'
I 06-22 13:48:21.110 Going to 'scheduling'
S 06-22 13:48:21.336 Unit says: Opening the dome before entering the scheduling state.
S 06-22 13:48:21.340 Unit says: Entering scheduling state from the observing state.
I 06-22 13:48:22.166 coarse focus required because of time difference.
S 06-22 13:48:22.168 Unit says: Scheduled coarse focusing
S 06-22 13:48:22.170 Unit says: Finished with the scheduling state. The next state is coarse_focusing.
S 06-22 13:48:22.172 Finished with scheduling
I 06-22 13:48:22.215 Run loop: 'scheduling' -> 'coarse_focusing'
I 06-22 13:48:22.581 Going to 'coarse_focusing'
S 06-22 13:48:22.819 Unit says: Opening the dome before entering the coarse_focusing state.
S 06-22 13:48:22.823 Unit says: Entering coarse_focusing state from the scheduling state.
S 06-22 13:48:23.523 Unit says: Setting up location
S 06-22 13:48:23.565 Unit says: Coarse focus coordinates: <SkyCoord (ICRS): (ra, dec) in deg
(289.05004132, -39.28002345)>
S 06-22 13:48:23.569 Unit says: I'm slewing over to the coordinates for coarse focus.
I 06-22 13:48:34.171 Slewing to target coordinates: ('19h16m12.00991592s', '-39d16m48.0844295s')
S 06-22 13:49:32.565 Unit says: I'm at the coordinates for coarse focus.
S 06-22 13:49:32.569 Unit says: Starting coarse focus on all cameras.
S 06-22 13:55:02.965 Unit says: Finished with the coarse_focusing state. The next state is scheduling.
S 06-22 13:55:02.967 Finished with coarse_focusing
I 06-22 13:55:03.006 Run loop: 'coarse_focusing' -> 'scheduling'
I 06-22 13:55:03.332 Going to 'scheduling'
S 06-22 13:55:03.552 Unit says: Opening the dome before entering the scheduling state.
S 06-22 13:55:03.555 Unit says: Entering scheduling state from the coarse_focusing state.
I 06-22 13:55:05.690 Checking Constraint: Altitude
I 06-22 13:55:05.926 Checking Constraint: Moon Avoidance
I 06-22 13:55:06.030 Checking Constraint: Sun Avoidance
I 06-22 13:55:06.659 Best observation: Centaurus-A-target Score: 1393.97
I 06-22 13:55:06.662 Setting new observation to <bound method AbstractObservation.__name__ of <huntsman.pocs.scheduler.observation.base.CompoundObservation object at 0x7fca81f10490>>: <bound method AbstractField.__name__ of <huntsman.pocs.scheduler.field.CompoundField object at 0x7fca7185acd0>>: Centaurus-A: exptime=300.0 s, filter=r_band
I 06-22 13:55:06.665 Observation: <bound method AbstractObservation.__name__ of <huntsman.pocs.scheduler.observation.base.CompoundObservation object at 0x7fca81f10490>>: <bound method AbstractField.__name__ of <huntsman.pocs.scheduler.field.CompoundField object at 0x7fca7185acd0>>: Centaurus-A: exptime=300.0 s, filter=r_band
S 06-22 13:55:06.669 Unit says: Scheduled observation: Centaurus-A-target
S 06-22 13:55:06.672 Unit says: Finished with the scheduling state. The next state is observing.
S 06-22 13:55:06.679 Finished with scheduling
I 06-22 13:55:06.746 Run loop: 'scheduling' -> 'observing'
I 06-22 13:55:07.138 Going to 'observing'
S 06-22 13:55:07.448 Unit says: Opening the dome before entering the observing state.
S 06-22 13:55:07.459 Unit says: Entering observing state from the scheduling state.
S 06-22 13:55:08.374 Unit says: I'm exploring the universe!
I 06-22 13:55:09.228 Starting observation block for <bound method AbstractObservation.__name__ of <huntsman.pocs.scheduler.observation.base.CompoundObservation object at 0x7fca81f10490>>: <bound method AbstractField.__name__ of <huntsman.pocs.scheduler.field.CompoundField object at 0x7fca7185acd0>>: Centaurus-A: exptime=300.0 s, filter=r_band
I 06-22 13:55:09.505 Slewing to target coordinates for <bound method AbstractObservation.__name__ of <huntsman.pocs.scheduler.observation.base.CompoundObservation object at 0x7fca81f10490>>: <bound method AbstractField.__name__ of <huntsman.pocs.scheduler.field.CompoundField object at 0x7fca7185acd0>>: Centaurus-A: exptime=300.0 s, filter=r_band.
I 06-22 13:55:20.164 Slewing to target coordinates: ('13h25m27.6s', '-43d01m09s')
E 06-22 14:11:35.185 Timeout: Timeout waiting for 8 events after 900.03 seconds
E 06-22 14:11:35.482 Exception while taking observation block for <bound method AbstractObservation.__name__ of <huntsman.pocs.scheduler.observation.base.CompoundObservation object at 0x7fca81f10490>>: <bound method AbstractField.__name__ of <huntsman.pocs.scheduler.field.CompoundField object at 0x7fca7185acd0>>: Centaurus-A: exptime=300.0 s, filter=r_band: Timeout('Timeout waiting for 8 events after 900.03 seconds')
S 06-22 14:11:35.484 Unit says: Finished with the observing state. The next state is scheduling.
S 06-22 14:11:35.487 Finished with observing
I 06-22 14:11:35.529 Run loop: 'observing' -> 'scheduling'
I 06-22 14:11:35.865 Going to 'scheduling'
S 06-22 14:11:36.097 Unit says: Opening the dome before entering the scheduling state.
S 06-22 14:11:36.101 Unit says: Entering scheduling state from the observing state.
I 06-22 14:11:38.105 Checking Constraint: Altitude
I 06-22 14:11:38.283 Checking Constraint: Moon Avoidance
I 06-22 14:11:38.378 Checking Constraint: Sun Avoidance
I 06-22 14:11:38.963 Best observation: Centaurus-A-target Score: 1394.18
I 06-22 14:11:38.965 Setting new observation to <bound method AbstractObservation.__name__ of <huntsman.pocs.scheduler.observation.base.CompoundObservation object at 0x7fca72ca4430>>: <bound method AbstractField.__name__ of <huntsman.pocs.scheduler.field.CompoundField object at 0x7fca71864b50>>: Centaurus-A: exptime=300.0 s, filter=r_band
I 06-22 14:11:38.970 Observation: <bound method AbstractObservation.__name__ of <huntsman.pocs.scheduler.observation.base.CompoundObservation object at 0x7fca72ca4430>>: <bound method AbstractField.__name__ of <huntsman.pocs.scheduler.field.CompoundField object at 0x7fca71864b50>>: Centaurus-A: exptime=300.0 s, filter=r_band
S 06-22 14:11:38.973 Unit says: Scheduled observation: Centaurus-A-target
S 06-22 14:11:38.976 Unit says: Finished with the scheduling state. The next state is observing.
S 06-22 14:11:38.978 Finished with scheduling
I 06-22 14:11:39.017 Run loop: 'scheduling' -> 'observing'
I 06-22 14:11:39.391 Going to 'observing'
S 06-22 14:11:39.635 Unit says: Opening the dome before entering the observing state.
S 06-22 14:11:39.638 Unit says: Entering observing state from the scheduling state.
S 06-22 14:11:40.347 Unit says: I'm exploring the universe!
I 06-22 14:11:40.964 Starting observation block for <bound method AbstractObservation.__name__ of <huntsman.pocs.scheduler.observation.base.CompoundObservation object at 0x7fca72ca4430>>: <bound method AbstractField.__name__ of <huntsman.pocs.scheduler.field.CompoundField object at 0x7fca71864b50>>: Centaurus-A: exptime=300.0 s, filter=r_band
I 06-22 14:11:41.187 Slewing to target coordinates for <bound method AbstractObservation.__name__ of <huntsman.pocs.scheduler.observation.base.CompoundObservation object at 0x7fca72ca4430>>: <bound method AbstractField.__name__ of <huntsman.pocs.scheduler.field.CompoundField object at 0x7fca71864b50>>: Centaurus-A: exptime=300.0 s, filter=r_band.
I 06-22 14:11:51.844 Slewing to target coordinates: ('13h25m27.6s', '-43d01m09s')
I 06-22 14:18:16.986 Taking observation <bound method AbstractObservation.__name__ of <huntsman.pocs.scheduler.observation.base.CompoundObservation object at 0x7fca72ca4430>>: <bound method AbstractField.__name__ of <huntsman.pocs.scheduler.field.CompoundField object at 0x7fca71864b50>>: Centaurus-A: exptime=300.0 s, filter=r_band for CameraGroup with 8 cameras.
I 06-22 14:23:32.691 Observation status: {'current_exp': 1, 'exp_set_size': 54}
I 06-22 14:23:32.931 Taking observation <bound method AbstractObservation.__name__ of <huntsman.pocs.scheduler.observation.base.CompoundObservation object at 0x7fca72ca4430>>: <bound method AbstractField.__name__ of <huntsman.pocs.scheduler.field.CompoundField object at 0x7fca71864b50>>: Centaurus-A: exptime=300.0 s, filter=r_band for CameraGroup with 8 cameras.
I 06-22 14:28:49.275 Observation status: {'current_exp': 2, 'exp_set_size': 54}
I 06-22 14:28:49.505 Taking observation <bound method AbstractObservation.__name__ of <huntsman.pocs.scheduler.observation.base.CompoundObservation object at 0x7fca72ca4430>>: <bound method AbstractField.__name__ of <huntsman.pocs.scheduler.field.CompoundField object at 0x7fca71864b50>>: Centaurus-A: exptime=300.0 s, filter=r_band for CameraGroup with 8 cameras.
Corresponding logs for jetson08 for relevant period, there is just a large gap between 14:11:57 and the previosu log at 14:00:59.... did the jetsons not receive the observation command? Somehow it initiated a fine focus without the control computer pocs logs mentioning fine focus?
W 06-22 13:56:28.573 No focus offset found for blank filter.
I 06-22 13:56:28.581 Moving ZWO Filter Wheel (10) [Camera: 192.168.80.208] to position 1 (blank)
I 06-22 13:56:42.482 Autofocus status on Birger Focuser (13280) on /dev/ttyUSB0: {'is_finished': False, 'completed_positions': 0, 'total_positions': 13}
I 06-22 13:56:50.814 Moving ZWO Filter Wheel (10) [Camera: 192.168.80.208] to position 4 (r_band)
I 06-22 13:57:05.351 Autofocus status on Birger Focuser (13280) on /dev/ttyUSB0: {'is_finished': False, 'completed_positions': 1, 'total_positions': 13}
I 06-22 13:57:24.535 Autofocus status on Birger Focuser (13280) on /dev/ttyUSB0: {'is_finished': False, 'completed_positions': 2, 'total_positions': 13}
I 06-22 13:57:43.591 Autofocus status on Birger Focuser (13280) on /dev/ttyUSB0: {'is_finished': False, 'completed_positions': 3, 'total_positions': 13}
I 06-22 13:58:02.525 Autofocus status on Birger Focuser (13280) on /dev/ttyUSB0: {'is_finished': False, 'completed_positions': 4, 'total_positions': 13}
I 06-22 13:58:21.459 Autofocus status on Birger Focuser (13280) on /dev/ttyUSB0: {'is_finished': False, 'completed_positions': 5, 'total_positions': 13}
I 06-22 13:58:40.415 Autofocus status on Birger Focuser (13280) on /dev/ttyUSB0: {'is_finished': False, 'completed_positions': 6, 'total_positions': 13}
I 06-22 13:58:59.494 Autofocus status on Birger Focuser (13280) on /dev/ttyUSB0: {'is_finished': False, 'completed_positions': 7, 'total_positions': 13}
I 06-22 13:59:18.463 Autofocus status on Birger Focuser (13280) on /dev/ttyUSB0: {'is_finished': False, 'completed_positions': 8, 'total_positions': 13}
I 06-22 13:59:37.419 Autofocus status on Birger Focuser (13280) on /dev/ttyUSB0: {'is_finished': False, 'completed_positions': 9, 'total_positions': 13}
I 06-22 13:59:56.368 Autofocus status on Birger Focuser (13280) on /dev/ttyUSB0: {'is_finished': False, 'completed_positions': 10, 'total_positions': 13}
I 06-22 14:00:15.323 Autofocus status on Birger Focuser (13280) on /dev/ttyUSB0: {'is_finished': False, 'completed_positions': 11, 'total_positions': 13}
I 06-22 14:00:34.380 Autofocus status on Birger Focuser (13280) on /dev/ttyUSB0: {'is_finished': False, 'completed_positions': 12, 'total_positions': 13}
I 06-22 14:00:53.324 Calculating focus metrics for <huntsman.pocs.utils.focus.AutofocusSequence object at 0x7f933f1ac0>.
I 06-22 14:00:55.790 Best focus position for Birger Focuser (13280) on /dev/ttyUSB0: 22289
I 06-22 14:00:59.983 Writing focus plot for Birger Focuser (13280) on /dev/ttyUSB0 to /huntsman/images/focus/11360f0405080900/20220622T135626/fine-focus-11360f0405080900.png.
I 06-22 14:11:57.211 Moving filterwheel to r_band for autofocusing on Birger Focuser (13280) on /dev/ttyUSB0.
I 06-22 14:12:03.559 Taking dark frame before autofocus on Birger Focuser (13280) on /dev/ttyUSB0.
W 06-22 14:12:03.567 No focus offset found for blank filter.
I 06-22 14:12:03.571 Moving ZWO Filter Wheel (10) [Camera: 192.168.80.208] to position 1 (blank)
I 06-22 14:12:17.350 Autofocus status on Birger Focuser (13280) on /dev/ttyUSB0: {'is_finished': False, 'completed_positions': 0, 'total_positions': 13}
I 06-22 14:12:25.674 Moving ZWO Filter Wheel (10) [Camera: 192.168.80.208] to position 4 (r_band)
Writing this issue for posterity/to capture some strange behaviour observed earlier in the year. NB I haven't seen this happen again since.
Pocs completed a 54/54 exposure block for a compound field and proceeded to to run a coarse focusing block. The coarse focusing block finished and then the main pocs logs indicated pocs moved to the scheduling state and started a new observation block for the same compound field. After about 15 minutes a timeout error was raised and pocs transitioned to the scheduling state again, selecting the same compound field and this time successfully started taking exposures without timeouts.
The logs from jetson08 seem to indicate that instead of moving to a compound field observation, it instead initiated a fine focus (this is what should happen), completed it and then remained in an inactive state until receive a new observation from the pocs control computer instance.
Control computer pocs instance logs:
Corresponding logs for jetson08 for relevant period, there is just a large gap between 14:11:57 and the previosu log at 14:00:59.... did the jetsons not receive the observation command? Somehow it initiated a fine focus without the control computer pocs logs mentioning fine focus?