×

INDI Library v2.0.6 is Released (02 Feb 2024)

Bi-monthly release with minor bug fixes and improvements

Scheduled refocus overlapping meridian flip

  • Posts: 37
  • Thank you received: 4
Hi, last night I ran into a weird situation that I don't fully understand. I left a scheduler job running all night long, that involved refocusing each 50 minutes; also, the target crossed the meridian near 4:00 AM. But after the flip, the job didn't capture any images.

In the kstars (3.5.4) log file (see below), it seems that the refocus and the meridian flip overlapped (things start to mess at 03:54:34): focus module was on its first outward movement when the flip started. It also seems to try to resume guiding during the flip a few times, of course failing. Also, the flip was flagged as failed, but then immediately marked as completed. After the flip, the refocus is not retried; it only started a guiding calibration (that didn't complete?). Nothing more until dawn, when shutdown was executed normally. 

Should I open a bug?

Thanks in advance!
Sergio
KStars 3.5.4, INDI 1.9.1 (from PPA)

<code>...
[2021-07-15T03:49:07.973 CEST INFO ][ org.kde.kstars.ekos.capture] - "Capturing 300,000-second O3G image..."
[2021-07-15T03:54:23.334 CEST INFO ][ org.kde.kstars.indi] - MI G2-8300 : "[INFO] Exposure done, downloading image... "
[2021-07-15T03:54:23.650 CEST INFO ][ org.kde.kstars.indi] - MI G2-8300 : "[INFO] Download complete. "
[2021-07-15T03:54:23.657 CEST INFO ][ org.kde.kstars.indi] - "FITS" file saved to "/home/aristarco/datos/NorAmPel_SHO/NorAmPel_SHO/Light/O3G/NorAmPel_SHO_Light_O3G_300_secs_151.fits"
[2021-07-15T03:54:24.296 CEST INFO ][ org.kde.kstars.ekos.capture] - "Download Time: 0.65 s, New Download Time Estimate: 0.84 s."
[2021-07-15T03:54:24.298 CEST INFO ][ org.kde.kstars.ekos.capture] - "Received image 151 out of 200."
[2021-07-15T03:54:24.395 CEST INFO ][ org.kde.kstars.ekos.capture] - Dithering...
[2021-07-15T03:54:24.395 CEST INFO ][ org.kde.kstars.ekos.capture] - "Dithering..."
[2021-07-15T03:54:24.488 CEST INFO ][ org.kde.kstars.ekos.guide] - "Dithering in progress."
[2021-07-15T03:54:24.620 CEST INFO ][ org.kde.kstars.ekos.scheduler] - "Job 'NorAmPel_SHO' 200x300\" O3G sees 151 captures in output folder '/home/aristarco/datos/NorAmPel_SHO/NorAmPel_SHO/Light/O3G'."
[2021-07-15T03:54:24.620 CEST INFO ][ org.kde.kstars.ekos.scheduler] - "Job 'NorAmPel_SHO' 200x300\" O3G requires a dither procedure."
[2021-07-15T03:54:24.622 CEST INFO ][ org.kde.kstars.ekos.scheduler] - "Job 'NorAmPel_SHO' estimated to take 04h 21m 03s to complete."
[2021-07-15T03:54:31.421 CEST INFO ][ org.kde.kstars.ekos.capture] - Dithering succeeded, capture state "Dithering"
[2021-07-15T03:54:31.421 CEST INFO ][ org.kde.kstars.ekos.capture] - "Dithering succeeded."
[2021-07-15T03:54:31.423 CEST INFO ][ org.kde.kstars.ekos.capture] - "Dither complete. Resuming in 3 seconds..."
[2021-07-15T03:54:31.425 CEST INFO ][ org.kde.kstars.ekos.guide] - "Dithering completed successfully."
[2021-07-15T03:54:31.525 CEST INFO ][ org.kde.kstars.ekos.guide] - "Guiding resumed."
[2021-07-15T03:54:34.556 CEST INFO ][ org.kde.kstars.ekos.capture] - "Scheduled refocus starting after 3.285 seconds..."
[2021-07-15T03:54:34.559 CEST INFO ][ org.kde.kstars.ekos.focus] - "Capturing to check HFR..."
[2021-07-15T03:54:34.564 CEST INFO ][ org.kde.kstars.ekos.focus] - "Capturing image..."
[2021-07-15T03:54:42.883 CEST INFO ][ org.kde.kstars.ekos.focus] - "Image received."
[2021-07-15T03:54:42.886 CEST INFO ][ org.kde.kstars.ekos.focus] - "Detecting sources..."
[2021-07-15T03:54:43.018 CEST INFO ][ org.kde.kstars.ekos.focus] - "Detection complete."
[2021-07-15T03:54:43.117 CEST INFO ][ org.kde.kstars.ekos.guide] - "Guiding suspended."
[2021-07-15T03:54:43.119 CEST INFO ][ org.kde.kstars.ekos.focus] - "Focusing outward by 100 steps..."
[2021-07-15T03:54:43.164 CEST INFO ][ org.kde.kstars.indi] - MoonLite : "[INFO] Focuser is moving to position 560 "
[2021-07-15T03:54:52.025 CEST INFO ][ org.kde.kstars.ekos.mount] - "Meridian flip waiting."
[2021-07-15T03:54:52.927 CEST INFO ][ org.kde.kstars.ekos.mount] - Meridian flip: slewing to RA= "20h 55m 40s" DEC= " 43° 55' 20\"" Hour Angle "00h 00m 31s"
[2021-07-15T03:54:52.927 CEST INFO ][ org.kde.kstars.ekos.mount] - "Meridian flip started."
[2021-07-15T03:54:53.122 CEST INFO ][ org.kde.kstars.ekos.guide] - "Guiding resumed."
[2021-07-15T03:54:53.125 CEST INFO ][ org.kde.kstars.ekos.capture] - "Autofocus failed. Aborting exposure..."
[2021-07-15T03:54:53.127 CEST INFO ][ org.kde.kstars.ekos.capture] - "CCD capture aborted"
[2021-07-15T03:54:53.138 CEST INFO ][ org.kde.kstars.ekos.focus] - "Autofocus aborted."
[2021-07-15T03:54:53.236 CEST INFO ][ org.kde.kstars.ekos.guide] - "Mount is moving. Resetting calibration..."
[2021-07-15T03:54:53.238 CEST INFO ][ org.kde.kstars.ekos.guide] - "Calibration is cleared."
[2021-07-15T03:54:53.240 CEST INFO ][ org.kde.kstars.ekos.guide] - "Mount is slewing. Aborting guide..."
[2021-07-15T03:54:53.336 CEST INFO ][ org.kde.kstars.ekos.guide] - "Autoguiding aborted."
[2021-07-15T03:54:53.338 CEST INFO ][ org.kde.kstars.ekos.mount] - "Meridian flip slew started..."
[2021-07-15T03:54:53.341 CEST INFO ][ org.kde.kstars.indi] - MI G2-8300 : "[INFO] Exposure aborted. "
[2021-07-15T03:54:53.435 CEST INFO ][ org.kde.kstars.ekos.scheduler] - "Warning: job 'NorAmPel_SHO' failed to capture target."
[2021-07-15T03:54:53.437 CEST INFO ][ org.kde.kstars.ekos.scheduler] - "Job 'NorAmPel_SHO' is capturing, is restarting its guiding procedure (attempt #1 of 5)."
[2021-07-15T03:54:53.440 CEST INFO ][ org.kde.kstars.ekos.scheduler] - "Starting guiding procedure for NorAmPel_SHO ..."
[2021-07-15T03:54:53.442 CEST INFO ][ org.kde.kstars.indi] - EQMod Mount : "[INFO] Starting Goto RA=20.9279 DE=43.9223 (current RA=20.894 DE=42.9016) "
[2021-07-15T03:54:53.442 CEST INFO ][ org.kde.kstars.indi] - EQMod Mount : "[INFO] GOTO ALign Nearest: delta RA = -0.030205, delta DEC = -0.969358 "
[2021-07-15T03:54:53.443 CEST INFO ][ org.kde.kstars.indi] - EQMod Mount : "[INFO] Aligned Eqmod Goto RA=20.8977 DE=42.9529 (target RA=20.9279 DE=43.9223) "
[2021-07-15T03:54:53.443 CEST INFO ][ org.kde.kstars.indi] - EQMod Mount : "[INFO] Setting Eqmod Goto RA=20.8977 DE=42.9529 (target RA=20.9279 DE=43.9223) "
[2021-07-15T03:54:53.444 CEST INFO ][ org.kde.kstars.indi] - MI G2-8300 : "[INFO] Exposure aborted. "
[2021-07-15T03:54:53.445 CEST INFO ][ org.kde.kstars.ekos.scheduler] - "Warning: job 'NorAmPel_SHO' guiding failed."
[2021-07-15T03:54:53.446 CEST INFO ][ org.kde.kstars.ekos.scheduler] - "Job 'NorAmPel_SHO' is guiding, guiding procedure will be restarted in 5 seconds."
[2021-07-15T03:54:53.448 CEST INFO ][ org.kde.kstars.indi] - EQMod Mount : "[INFO] Slewing mount: RA increment = -4609364, DE increment = 2410125 "
[2021-07-15T03:54:53.573 CEST INFO ][ org.kde.kstars.ekos.guide] - "Calibration is cleared."
[2021-07-15T03:54:53.576 CEST INFO ][ org.kde.kstars.indi] - EQMod Mount : "[INFO] Slewing to RA: 20:55:40 - DEC: 43:55:20 "
[2021-07-15T03:54:55.718 CEST INFO ][ org.kde.kstars.ekos.guide] - "Auto star selected."
[2021-07-15T03:54:55.842 CEST INFO ][ org.kde.kstars.ekos.guide] - "Calibration started."
[2021-07-15T03:54:55.844 CEST INFO ][ org.kde.kstars.ekos.guide] - "RA drifting forward..."
[2021-07-15T03:54:55.849 CEST INFO ][ org.kde.kstars.indi] - EQMod Mount : "[INFO] Start Tracking (Sidereal). "
[2021-07-15T03:54:55.849 CEST INFO ][ org.kde.kstars.indi] - EQMod Mount : "[WARNING] Warning: Invalid parameter -> Can not change rate while motor is running (speedmode differs). "
[2021-07-15T03:54:57.124 CEST WARN ][ org.kde.kstars.ekos.mount] - Meridian flip failed, pier side not changed
[2021-07-15T03:54:57.124 CEST INFO ][ org.kde.kstars.ekos.mount] - "meridian flip failed, retrying in 4 minutes"
[2021-07-15T03:54:57.126 CEST INFO ][ org.kde.kstars.ekos.mount] - "Meridian flip completed."
[2021-07-15T03:54:57.222 CEST INFO ][ org.kde.kstars.ekos.capture] - "Telescope completed the meridian flip."
[2021-07-15T03:54:57.512 CEST INFO ][ org.kde.kstars.indi] - MoonLite : "[INFO] Focuser reached requested position. "
[2021-07-15T03:54:58.522 CEST INFO ][ org.kde.kstars.ekos.scheduler] - "Starting guiding procedure for NorAmPel_SHO ..."
[2021-07-15T03:54:58.525 CEST INFO ][ org.kde.kstars.ekos.guide] - "Calibration is cleared."
[2021-07-15T03:55:00.417 CEST INFO ][ org.kde.kstars.ekos.guide] - "Auto star selected."
[2021-07-15T03:55:00.502 CEST INFO ][ org.kde.kstars.ekos.guide] - "RA drifting reverse..."
[2021-07-15T03:55:39.038 CEST INFO ][ org.kde.kstars.indi] - EQMod Mount : "[INFO] Iterative Goto (1): RA diff = 45.32 arcsecs DE diff = 0.00 arcsecs "
[2021-07-15T03:55:39.039 CEST INFO ][ org.kde.kstars.indi] - EQMod Mount : "[INFO] Iterative goto (1): slew mount to RA increment = 4845, DE increment = 0 "
[2021-07-15T03:55:40.282 CEST INFO ][ org.kde.kstars.indi] - EQMod Mount : "[INFO] Iterative Goto (2): RA diff = 1.14 arcsecs DE diff = 0.00 arcsecs "
[2021-07-15T03:55:40.410 CEST INFO ][ org.kde.kstars.indi] - EQMod Mount : "[INFO] Telescope slew is complete. Tracking TRACK_SIDEREAL... "
[2021-07-15T05:25:13.426 CEST INFO ][ org.kde.kstars.ekos.scheduler] - "Job 'NorAmPel_SHO' is now approaching astronomical twilight rise limit at jue. jul. 15 05:25:11 2021 (0 minutes safety margin), marking idle."
[2021-07-15T05:25:13.479 CEST INFO ][ org.kde.kstars.ekos.scheduler] - "Job 'NorAmPel_SHO' is stopping guiding..."
[2021-07-15T05:25:13.479 CEST INFO ][ org.kde.kstars.ekos.guide] - "Autoguiding aborted."
[2021-07-15T05:25:14.461 CEST INFO ][ org.kde.kstars.ekos.scheduler] - "Job 'NorAmPel_SHO' 200x300\" O3G sees 151 captures in output folder '/home/aristarco/datos/NorAmPel_SHO/NorAmPel_SHO/Light/O3G'."
[2021-07-15T05:25:14.461 CEST INFO ][ org.kde.kstars.ekos.scheduler] - "Job 'NorAmPel_SHO' 200x300\" O3G requires a dither procedure."
[2021-07-15T05:25:14.463 CEST INFO ][ org.kde.kstars.ekos.scheduler] - "Job 'NorAmPel_SHO' estimated to take 04h 21m 03s to complete."
[2021-07-15T05:25:14.464 CEST INFO ][ org.kde.kstars.ekos.scheduler] - Option to sort jobs based on priority and altitude is false
[2021-07-15T05:25:14.522 CEST INFO ][ org.kde.kstars.ekos.scheduler] - "Job 'NorAmPel_SHO' has a total score of -1000 at 15/07 05:25."
[2021-07-15T05:25:14.524 CEST INFO ][ org.kde.kstars.ekos.scheduler] - "Job 'NorAmPel_SHO' has a total score of -1000 at 15/07 05:25."
[2021-07-15T05:25:15.427 CEST INFO ][ org.kde.kstars.ekos.scheduler] - "Job 'NorAmPel_SHO' scheduled for execution at 15/07 23:21. Observatory scheduled for shutdown until next job is ready."
[2021-07-15T05:25:15.431 CEST INFO ][ org.kde.kstars.ekos.scheduler] - Starting shutdown process...
[2021-07-15T05:25:15.431 CEST INFO ][ org.kde.kstars.ekos.scheduler] - "Warming up CCD..."
[2021-07-15T05:25:15.440 CEST INFO ][ org.kde.kstars.ekos.capture] - "Cooler is off"
[2021-07-15T05:25:16.428 CEST INFO ][ org.kde.kstars.ekos.scheduler] - "Parking mount in progress..."
[2021-07-15T05:25:16.596 CEST INFO ][ org.kde.kstars.indi] - EQMod Mount : "[INFO] Parking mount: RA increment = 1662613, DE increment = -1204405 "
[2021-07-15T05:25:16.884 CEST INFO ][ org.kde.kstars.indi] - EQMod Mount : "[INFO] Mount park in progress... "
[2021-07-15T05:25:17.428 CEST INFO ][ org.kde.kstars.ekos.scheduler] - Parking mount in progress...
[2021-07-15T05:25:18.063 CEST INFO ][ org.kde.kstars.ekos.guide] - "Mount is moving. Resetting calibration..."
[2021-07-15T05:25:18.065 CEST INFO ][ org.kde.kstars.ekos.guide] - "Calibration is cleared."
[2021-07-15T05:25:18.427 CEST INFO ][ org.kde.kstars.ekos.scheduler] - Parking mount in progress...
[2021-07-15T05:25:19.427 CEST INFO ][ org.kde.kstars.ekos.scheduler] - Parking mount in progress...
[2021-07-15T05:25:20.428 CEST INFO ][ org.kde.kstars.ekos.scheduler] - Parking mount in progress...
[2021-07-15T05:25:21.427 CEST INFO ][ org.kde.kstars.ekos.scheduler] - Parking mount in progress...
[2021-07-15T05:25:22.427 CEST INFO ][ org.kde.kstars.ekos.scheduler] - Parking mount in progress...
[2021-07-15T05:25:23.428 CEST INFO ][ org.kde.kstars.ekos.scheduler] - Parking mount in progress...
[2021-07-15T05:25:24.427 CEST INFO ][ org.kde.kstars.ekos.scheduler] - Parking mount in progress...
[2021-07-15T05:25:25.428 CEST INFO ][ org.kde.kstars.ekos.scheduler] - Parking mount in progress...
[2021-07-15T05:25:26.427 CEST INFO ][ org.kde.kstars.ekos.scheduler] - Parking mount in progress...
[2021-07-15T05:25:27.427 CEST INFO ][ org.kde.kstars.ekos.scheduler] - Parking mount in progress...
[2021-07-15T05:25:28.427 CEST INFO ][ org.kde.kstars.ekos.scheduler] - Parking mount in progress...
[2021-07-15T05:25:29.428 CEST INFO ][ org.kde.kstars.ekos.scheduler] - Parking mount in progress...
[2021-07-15T05:25:30.427 CEST INFO ][ org.kde.kstars.ekos.scheduler] - Parking mount in progress...
[2021-07-15T05:25:31.428 CEST INFO ][ org.kde.kstars.ekos.scheduler] - Parking mount in progress...
[2021-07-15T05:25:32.428 CEST INFO ][ org.kde.kstars.ekos.scheduler] - Parking mount in progress...
[2021-07-15T05:25:33.427 CEST INFO ][ org.kde.kstars.ekos.scheduler] - Parking mount in progress...
[2021-07-15T05:25:34.029 CEST INFO ][ org.kde.kstars.indi] - EQMod Mount : "[INFO] Mount is parked. "</code>
Last edit: 2 years 8 months ago by Sergio.
2 years 8 months ago #73517

Please Log in or Create an account to join the conversation.

  • Posts: 1185
  • Thank you received: 370
Hi Sergio,
actions overlapping with focusing might lead to problems. I had a similar one where the scheduler changed the target while a re-focus was running. I'll have to take a closer look what happened there.

One thing that suprises me is that guiding seems to restart before slewing has finished. It could explain why this happens:
[2021-07-15T03:54:55.849 CEST INFO ][ org.kde.kstars.indi] - EQMod Mount : "[WARNING] Warning: Invalid parameter -> Can not change rate while motor is running (speedmode differs). "

You do not need to create a bug report. One of my hobbies is the meridian flip handling :-) I'll take a closer look and come back.

Thanks for reporting it.
Wolfgang
The following user(s) said Thank You: Sergio, Peter Sütterlin
2 years 8 months ago #73701

Please Log in or Create an account to join the conversation.

  • Posts: 37
  • Thank you received: 4
Thanks so much, Wolfgang! These border cases seem difficult to catch, good to know that the MF expert is here!
2 years 8 months ago #73706

Please Log in or Create an account to join the conversation.

  • Posts: 1185
  • Thank you received: 370
Hi Sergio,
it took me a while to drill it down, but now I have a test case that shows the problem. When a meridian flip happens while focusing, focusing is aborted - that's fine. But then, the problem begins. An aborted re-focus triggers capture to abort - this at least is wrong if the aborted focusing was triggered by a meridian flip.

So after the meridian flip has completed, capture does not continue. If the scheduler is running and error recovery is selected, the scheduler will restart the capture sequence. If not, capture remains terminated after the meridian flip.

In your case it is even more difficult, since it looks like the scheduler tries to the restart the job while the meridian flip is still running.

Wolfgang
The following user(s) said Thank You: Jasem Mutlaq, Sergio
2 years 8 months ago #73923

Please Log in or Create an account to join the conversation.

  • Posts: 37
  • Thank you received: 4
Thanks Wolfgang!
The code is overwhelming to me but I had a look at it. Capture triggers refocus (after expiring the configuring time limit), which first check focus, then suspends guiding (as configured), and then initiates the focuser motion. But why focusing fails? Is it because it cannot find stars in the captured image (this would be incoordination between the modules, as the mount is slewing) or because the flipping operation somehow signals focus module to abort (I can't find something like this in the code) ?
2 years 8 months ago #73936

Please Log in or Create an account to join the conversation.

  • Posts: 1185
  • Thank you received: 370
The capture module indirectly triggers the focuser to abort. The connection is via the event meridianFlipStarted() in Capture that triggers Focuser::abort(). The connection is configured inside the manager, that translates the capture event into a focuser signal.
The following user(s) said Thank You: Sergio
Last edit: 2 years 8 months ago by Wolfgang Reissenberger.
2 years 8 months ago #73937

Please Log in or Create an account to join the conversation.

  • Posts: 37
  • Thank you received: 4
Thanks! I completely missed that...

Any thoughts for the solution?

I understand that delaying the focusing operation after the flip is desirable, but doing so by 'aborting and retrying' after the flip seems difficult to manage by the state machine as it should distinguish it from a true focusing failure.

Maybe don't initiate the focusing if it will overlap with a flip? Not trivial as we don't know how long focusing will take, also not sure how difficult is to implement this 'look ahead'.

Or maybe just don't accept the flip while focusing is running? This deviates from the ideal, but maybe its easier to implement?

Thanks so much for your involvement, Wolfgang!
2 years 8 months ago #73938

Please Log in or Create an account to join the conversation.

  • Posts: 1185
  • Thank you received: 370
I'm already working on a merge request  !MR371  to fix this. The current approach is to interrupt focusing when a meridian flip is necessary - a MF should have priority since if it comes too late the scope might hit the pole. As soon as the flip is completed, focusing should be restarted similar as we do it for guiding etc. I'm slightly optimistic that this is already the case.

The current problem is that a flip aborts focusing (OK) and this leads to capture abort (not OK).

If the scheduler is running, it becomes even more complicated, since an aborted capture might immediately lead to restarting alignment and guiding, which could itself interfere with the meridian flip.

I'm currently working on test cases to reliably reproducing the situation and then try to fix it.
The following user(s) said Thank You: Sergio
2 years 8 months ago #73939

Please Log in or Create an account to join the conversation.

  • Posts: 37
  • Thank you received: 4
Thanks so much for the detailed explanation. Hope you can fix it without too much work
2 years 8 months ago #73940

Please Log in or Create an account to join the conversation.

  • Posts: 225
  • Thank you received: 16
I've also experienced the issue in my setup. Just an idea... but when there is an issue with auto focusing, rather than aborting capture... why don't you just return to the original focus setting and continue as before?

Thanks!

Ron
2 years 8 months ago #73943

Please Log in or Create an account to join the conversation.

  • Posts: 1185
  • Thank you received: 370
That's exactly the idea I'm working on. Aborting focus should move the focuser to the last known focus position. And capture will be modified such that an abort event of the focuser will not abort capturing if itself triggered a re-focus.
2 years 8 months ago #73944

Please Log in or Create an account to join the conversation.

  • Posts: 6
  • Thank you received: 1
I had the same problem. Focus aborted by the meridian flip, which in turn then aborted the capture sequence.
In addition to just ABORTING the focus, couldn't the meridian flip schedule a re-focus after the flip is finished?

I'm afraid, just resuming the old focus position will not be sufficient in my case, as driving to absolute positions is very unreliable for me. It would be perfect, if auto-focus would just start after the flip. And even in that case, It would really depend on the current focus position being not too far off (after the aborted focus attempt).

Steffen
2 years 8 months ago #73963

Please Log in or Create an account to join the conversation.

Time to create page: 1.204 seconds