×

INDI Library v2.0.7 is Released (01 Apr 2024)

Bi-monthly release with minor bug fixes and improvements

Re:first capture after meridian flip fails

  • Posts: 969
  • Thank you received: 94
Source build from git.

Hi everyone
An annoying 'sometimes happens' situation which needs manual intervention.
The first capture after the flip counts down but never reaches zero; it never downloads. This unfortunately means that meridian flips must be attended.

The workaround is simply to abort the capture whereupon the capture is recovered, but it means YOU have to do it:(
This happened at the first flip of the schedule at around 21:18

Any help most gratefully received.

Log: drive.google.com/open?id=17At3AA8WeSHJHslGkayci8r2SUimdPnO
4 years 2 months ago #49525

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

  • Posts: 1221
  • Thank you received: 565
Steve,

I have seen a similar (though probably slightly different) issue. I did look at your log and couldn't quite figure out what was going on, though there are some clues. I added a little logging to the source which might help us figure things out. If you 'git pull' you would get the software with the extra logging. So, please do that, and then, should this ever happen again, please add the new log to this thread.

Thanks,
Hy
The following user(s) said Thank You: alacant
4 years 2 months ago #49646

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

  • Posts: 969
  • Thank you received: 94
Hi Hy
OK, thanks. Can't ATM:
www.indilib.org/forum/ekos/6487-latest-git-build-error.html

Will pull again when fixed.
Steve
4 years 2 months ago #49657

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

  • Posts: 1221
  • Thank you received: 565
Although that build error should be fixed, you should be able to get around it with just, eg, make -j6 kstars
4 years 2 months ago #49669

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

  • Posts: 1029
  • Thank you received: 301
Side note first, Capture will abort exposure by itself when the post-flip exposure doesn't finish 180 seconds after its expected duration.
I don't see why the flip shouldn't be left unattended, but I can understand these few minutes are wasted (or maybe not, because the frame is actually stored in the APN sdcard).

From the log, the post-flip capture is started and finished at 21:24:38, but the Capture module doesn't react at that point.
The Capture module procedure is then aborted at 21:26:18, though there's nothing to abort really except the procedure itself.

This is my analysis of the log, I marked three FIXMEs that require attention (well the second is quite minor):
- 21:18:41 // Guide aborted guiding, but it seems PHD2 aborts because the mount is slewing, not because it was told to abort (FIXME)[/li]
- 21:21:25 // Capture restarts Guide, though proper log is missing (FIXME)[/li]
- 21:26:18 // Then the INDI driver more or less successfully applies the abort request (FIXME)[/li]
// Dithering before the last capture before flip
[2020-02-14T21:14:42.168 CET DEBG ][   org.kde.kstars.ekos.capture] - Guiding state changed from "Dithering" to "Dithering successful"
[2020-02-14T21:14:42.168 CET INFO ][   org.kde.kstars.ekos.capture] - Dithering succeeded, capture state "Dithering"
[2020-02-14T21:14:42.168 CET INFO ][   org.kde.kstars.ekos.capture] - "Dither complete. Resuming capture in 14 seconds..."
[2020-02-14T21:14:42.169 CET INFO ][     org.kde.kstars.ekos.guide] - "Dithering completed successfully."
[2020-02-14T21:14:42.170 CET DEBG ][   org.kde.kstars.ekos.capture] - Guiding state changed from "Dithering successful" to "Guiding"
[2020-02-14T21:14:42.170 CET INFO ][     org.kde.kstars.ekos.guide] - "Guiding resumed."
 
// Last capture before flip time
[2020-02-14T21:14:55.829 CET INFO ][   org.kde.kstars.ekos.capture] - "Capturing 180,000-second  image..."
[2020-02-14T21:14:55.873 CET INFO ][           org.kde.kstars.indi] - Canon DSLR EOS 700D :  "[INFO] Starting 180 seconds exposure. "
 
// Last capture before flip time, done
[2020-02-14T21:18:01.068 CET DEBG ][           org.kde.kstars.indi] - Canon DSLR EOS 700D : "[DEBUG] Upload complete "
[2020-02-14T21:18:03.272 CET INFO ][   org.kde.kstars.ekos.capture] - "Download Time: 2.20 s, New Download Time Estimate: 2.23 s."
[2020-02-14T21:18:03.278 CET INFO ][           org.kde.kstars.fits] - Loading FITS file  "/home/steve/astro/M_37/Light/M_37_Light_017.fits"
[2020-02-14T21:18:03.278 CET INFO ][   org.kde.kstars.ekos.capture] - "Received image 17 out of 40."
[2020-02-14T21:18:03.279 CET INFO ][   org.kde.kstars.ekos.capture] - Dithering...
[2020-02-14T21:18:03.280 CET DEBG ][   org.kde.kstars.ekos.capture] - Guiding state changed from "Guiding" to "Dithering"
[2020-02-14T21:18:03.280 CET INFO ][     org.kde.kstars.ekos.guide] - "Dithering in progress."
 
// While waiting for dithering to complete, Mount says we should flip
[2020-02-14T21:18:15.332 CET DEBG ][   org.kde.kstars.ekos.capture] - meridianFlipStatusChanged:  1
[2020-02-14T21:18:15.333 CET DEBG ][   org.kde.kstars.ekos.capture] - setMeridianFlipStage:  1
 
// Dithering complete, Guide resumes guiding, but actually Mount wants Capture to flip
[2020-02-14T21:18:27.134 CET DEBG ][   org.kde.kstars.ekos.capture] - Guiding state changed from "Dithering" to "Dithering successful"
[2020-02-14T21:18:27.134 CET INFO ][   org.kde.kstars.ekos.capture] - Dithering succeeded, capture state "Dithering"
[2020-02-14T21:18:27.134 CET INFO ][   org.kde.kstars.ekos.capture] - "Dither complete. Resuming capture in 14 seconds..."
[2020-02-14T21:18:27.135 CET INFO ][     org.kde.kstars.ekos.guide] - "Dithering completed successfully."
[2020-02-14T21:18:27.136 CET DEBG ][   org.kde.kstars.ekos.capture] - Guiding state changed from "Dithering successful" to "Guiding"
[2020-02-14T21:18:27.136 CET INFO ][     org.kde.kstars.ekos.guide] - "Guiding resumed."
 
// Capture agrees to flip
[2020-02-14T21:18:40.827 CET DEBG ][   org.kde.kstars.ekos.capture] - setMeridianFlipStage:  2
[2020-02-14T21:18:41.333 CET INFO ][     org.kde.kstars.ekos.mount] - Meridian flip: slewing to RA= "05h 53m 36s" DEC= " 32° 33' 24\""
[2020-02-14T21:18:41.333 CET DEBG ][   org.kde.kstars.ekos.capture] - meridianFlipStatusChanged:  4
[2020-02-14T21:18:41.333 CET DEBG ][   org.kde.kstars.ekos.capture] - setMeridianFlipStage:  3
[2020-02-14T21:18:41.350 CET DEBG ][   org.kde.kstars.ekos.capture] - Guiding state changed from "Guiding" to "Aborted"
[2020-02-14T21:18:41.350 CET INFO ][     org.kde.kstars.ekos.guide] - "Autoguiding aborted."
 
// Guide aborted guiding, but it seems PHD2 aborts because the mount is slewing, not because it was told to abort (FIXME)
[2020-02-14T21:18:41.879 CET DEBG ][   org.kde.kstars.ekos.capture] - setMeridianFlipStage:  5
[2020-02-14T21:18:42.086 CET INFO ][     org.kde.kstars.ekos.guide] - "PHD2: Guiding Stopped."
[2020-02-14T21:18:42.102 CET INFO ][     org.kde.kstars.ekos.guide] - "PHD2: Looping Exposures Stopped."
[2020-02-14T21:18:42.104 CET INFO ][     org.kde.kstars.ekos.guide] - "PHD2: Lock Position Lost."
 
// Flip completes
[2020-02-14T21:19:42.333 CET DEBG ][   org.kde.kstars.ekos.capture] - meridianFlipStatusChanged:  5
[2020-02-14T21:19:42.333 CET DEBG ][   org.kde.kstars.ekos.capture] - setMeridianFlipStage:  6
[2020-02-14T21:19:42.333 CET INFO ][   org.kde.kstars.ekos.capture] - "Telescope completed the meridian flip."
[2020-02-14T21:19:42.334 CET INFO ][   org.kde.kstars.ekos.capture] - "Performing post flip re-alignment..."
[2020-02-14T21:19:42.336 CET DEBG ][     org.kde.kstars.ekos.align] - Post meridian flip mount model reset successful.
[2020-02-14T21:19:42.336 CET DEBG ][   org.kde.kstars.ekos.capture] - setMeridianFlipStage:  7
[2020-02-14T21:19:43.334 CET DEBG ][   org.kde.kstars.ekos.capture] - meridianFlipStatusChanged:  0
 
// Capture re-aligns after flipping
[2020-02-14T21:21:02.637 CET INFO ][   org.kde.kstars.ekos.capture] - "Post flip re-alignment completed successfully."
[2020-02-14T21:21:02.643 CET INFO ][   org.kde.kstars.ekos.capture] - "Performing post flip re-calibration and guiding..."
[2020-02-14T21:21:02.648 CET DEBG ][   org.kde.kstars.ekos.capture] - setMeridianFlipStage:  8
 
// Capture restarts Guide, though proper log is missing (FIXME)
[2020-02-14T21:21:25.831 CET INFO ][     org.kde.kstars.ekos.guide] - "PHD2: Waiting for guiding to settle."
[2020-02-14T21:21:25.947 CET INFO ][     org.kde.kstars.ekos.guide] - "PHD2: Exposure Time set to: 2.50"
[2020-02-14T21:21:25.957 CET INFO ][     org.kde.kstars.ekos.guide] - "PHD2: DEC Guide Mode is Set to: Auto"
 
// Guide settles and Capture resumes exposing
[2020-02-14T21:21:33.324 CET DEBG ][   org.kde.kstars.ekos.capture] - Guiding state changed from "Aborted" to "Guiding"
[2020-02-14T21:21:33.324 CET INFO ][     org.kde.kstars.ekos.guide] - "Autoguiding started."
[2020-02-14T21:21:33.348 CET INFO ][   org.kde.kstars.ekos.capture] - "Post meridian flip calibration completed successfully."
[2020-02-14T21:21:33.349 CET DEBG ][   org.kde.kstars.ekos.capture] - setMeridianFlipStage:  0
[2020-02-14T21:21:33.366 CET INFO ][   org.kde.kstars.ekos.capture] - "Capturing 180,000-second  image..."
[2020-02-14T21:21:33.414 CET INFO ][           org.kde.kstars.indi] - Canon DSLR EOS 700D :  "[INFO] Starting 180 seconds exposure. "
 
// Exposure is done, but Capture doesn't react
[2020-02-14T21:24:38.600 CET DEBG ][           org.kde.kstars.indi] - Canon DSLR EOS 700D : "[DEBUG] Upload complete "
 
// Now Capture exceeded its exposure timeout, and restarts the capture
[2020-02-14T21:26:18.827 CET INFO ][   org.kde.kstars.ekos.capture] - "CCD capture aborted"
[2020-02-14T21:26:18.832 CET DEBG ][   org.kde.kstars.ekos.capture] - setMeridianFlipStage:  2
[2020-02-14T21:26:18.850 CET DEBG ][   org.kde.kstars.ekos.capture] - "Client module indicates that storage for '/home/steve/astro/M_37/Light/M_37_Light' has already 17 captures processed."
[2020-02-14T21:26:18.851 CET DEBG ][   org.kde.kstars.ekos.capture] - Preparing capture job "/home/steve/astro/M_37/Light/M_37_Light" for execution.
[2020-02-14T21:26:18.856 CET INFO ][   org.kde.kstars.ekos.capture] - "Job requires 180,000-second  images, has 17/40 frames captured and will be processed."
[2020-02-14T21:26:18.858 CET INFO ][   org.kde.kstars.ekos.capture] - "Capturing 180,000-second  image..."
 
// Then the INDI driver more or less successfully applies the abort request (FIXME)
[2020-02-14T21:26:18.884 CET DEBG ][           org.kde.kstars.indi] - Canon DSLR EOS 700D : "[DEBUG] Aborting exposure... "
[2020-02-14T21:26:18.885 CET DEBG ][           org.kde.kstars.indi] - Canon DSLR EOS 700D : "[DEBUG] Closing internal shutter. "
[2020-02-14T21:26:18.885 CET DEBG ][           org.kde.kstars.indi] - Canon DSLR EOS 700D : "[DEBUG] Using widget:eosremoterelease "
[2020-02-14T21:26:18.885 CET DEBG ][           org.kde.kstars.indi] - Canon DSLR EOS 700D : "[DEBUG] Setting radio/menu widget eosremoterelease: 4 (Release Full) "
[2020-02-14T21:26:18.885 CET DEBG ][           org.kde.kstars.indi] - Canon DSLR EOS 700D : "[DEBUG] Setting new configuration OK. "
[2020-02-14T21:26:18.885 CET DEBG ][           org.kde.kstars.indi] - Canon DSLR EOS 700D : "[DEBUG] Reading exposure... "
[2020-02-14T21:26:18.885 CET DEBG ][           org.kde.kstars.indi] - Canon DSLR EOS 700D : "[DEBUG] Exposure complete. "
[2020-02-14T21:26:18.911 CET DEBG ][           org.kde.kstars.indi] - Canon DSLR EOS 700D : "[DEBUG] Capture event completed. "
[2020-02-14T21:26:19.914 CET DEBG ][           org.kde.kstars.indi] - Canon DSLR EOS 700D : "[DEBUG] Event timed out #1, retrying... "
(...)
[2020-02-14T21:26:28.942 CET DEBG ][           org.kde.kstars.indi] - Canon DSLR EOS 700D : "[DEBUG] Event timed out #10, retrying... "
[2020-02-14T21:26:28.945 CET INFO ][           org.kde.kstars.indi] - Canon DSLR EOS 700D :  "[INFO] Starting 180 seconds exposure. "
 
// Capture completes on this second attempt, and asks Guide to dither
[2020-02-14T21:29:36.357 CET INFO ][   org.kde.kstars.ekos.capture] - "Download Time: 2.22 s, New Download Time Estimate: 2.23 s."
[2020-02-14T21:29:36.364 CET INFO ][           org.kde.kstars.fits] - Loading FITS file  "/home/steve/astro/M_37/Light/M_37_Light_018.fits"
[2020-02-14T21:29:36.364 CET INFO ][   org.kde.kstars.ekos.capture] - "Received image 18 out of 40."
[2020-02-14T21:29:36.365 CET INFO ][   org.kde.kstars.ekos.capture] - Dithering...
[2020-02-14T21:29:36.365 CET DEBG ][   org.kde.kstars.ekos.capture] - Guiding state changed from "Guiding" to "Dithering"
[2020-02-14T21:29:36.366 CET INFO ][     org.kde.kstars.ekos.guide] - "Dithering in progress."
 
// Guide is done dithering
[2020-02-14T21:29:53.205 CET DEBG ][   org.kde.kstars.ekos.capture] - Guiding state changed from "Dithering" to "Dithering successful"
[2020-02-14T21:29:53.205 CET INFO ][   org.kde.kstars.ekos.capture] - Dithering succeeded, capture state "Dithering"
[2020-02-14T21:29:53.205 CET INFO ][   org.kde.kstars.ekos.capture] - "Dither complete. Resuming capture in 14 seconds..."
[2020-02-14T21:29:53.206 CET INFO ][     org.kde.kstars.ekos.guide] - "Dithering completed successfully."
[2020-02-14T21:29:53.206 CET DEBG ][   org.kde.kstars.ekos.capture] - Guiding state changed from "Dithering successful" to "Guiding"
[2020-02-14T21:29:53.206 CET INFO ][     org.kde.kstars.ekos.guide] - "Guiding resumed."
 
// Capture resumes exposing
[2020-02-14T21:30:06.831 CET INFO ][   org.kde.kstars.ekos.capture] - "Capturing 180,000-second  image..."

Looking at the code (albeit probably a more recent code than the log source), the function that is *not* called after the flip is "setCaptureComplete".
There are multiple reasons for this:
- no active job - not the case here as it is the source for the exposure duration, unless we loose it during exposure - and it is notable that the OP indicates progress is counting down (capture.cpp:2307)[/li]
- meridian flip still aligning - not the case here, flip stage is set to 0 explicitly at 21:21:33, just before capturing[/li]
- no actual frame data - possible, but probably not the case here?[/li]
- idle or aborted capture - not the case here, capture is active at 21:21:33[/li]
- unexpected sensor source - probably not the case here[/li]
- non-looping preview mode with darks - not the case here[/li]

On the first item, the OP states that the count goes down, but never gets to zero. This count is updated in "setExposureProgress" (capture.cpp:2318), and set to zero explicitly. Except if:
- sensor source is unexpected - probably not the case here[/li]
- fits type isn't normal - not the case, set explicitely at sequencejob.cpp:292[/li]
- meridian flip is still aligning - not the case here, flip stage is set to 0 explicitly at 21:21:33, just before capturing[/li]

So the last remaining point is the lack of data being received by the Capture module.
// Last capture before flip
[2020-02-14T21:18:01.068 CET DEBG ][           org.kde.kstars.indi] - Canon DSLR EOS 700D : "[DEBUG] Upload complete "
[2020-02-14T21:18:01.221 CET INFO ][           org.kde.kstars.indi] - "FITS" file saved to "/home/steve/astro/M_37/Light/M_37_Light_017.fits"
 
// Non-alignment capture after flip
[2020-02-14T21:24:38.600 CET DEBG ][           org.kde.kstars.indi] - Canon DSLR EOS 700D : "[DEBUG] Upload complete "
(...nothing...)

We see that the INDI client doesn't retrieve the data. This is the responsibility of CCD::processBLOB (ekos client, indiccd.cpp:1603), and we're not using websockets because we see the following log (indilib, indiccd.cpp:2845).
[2020-02-14T21:24:38.600 CET DEBG ][           org.kde.kstars.indi] - Canon DSLR EOS 700D : "[DEBUG] BLOB transfer took 0.138315 seconds "

Now the thing to understand is why, following an alignment, the image blob is not retrieved by the Capture module, while the abort procedure of Capture restores functionality.
Situation is not exactly like starting a fresh new sequence, as we are in the middle of a sequence. When we abort, the active job is reset(), and we see prepareJob() being called afterwards.

It means prepareJob() is doing something we should do post-alignment. We do call resumeSequence() at capture.cpp:3266.
We should make sure resumeSequence() is configuring the sensor as properly as prepareJob() is. Or maybe just call prepareJob() instead at that moment.
Last edit: 4 years 1 month ago by Eric.
4 years 1 month ago #50041

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

  • Posts: 969
  • Thank you received: 94

Ah, OK. I didn't know, although I feel sure I waited for more than 3 minutes... Did I?! I had to abort the capture manually so that it would recover and continue.
Cheers
4 years 1 month ago #50042

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

  • Posts: 1029
  • Thank you received: 301
Just to make it clear, you spotted a real bug that we should fix. That bug is a side-effect of the realignment after flipping. But it appears the system is able to recover from it.

-Eric
4 years 1 month ago #50057

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

  • Posts: 1119
  • Thank you received: 182
Since we're at it, I just now discovered another problem with the Meridian Flip. It did not occur in the scheduler, I was just using the Capture module and let it run past the time for the flip.
Flip was initiated and completed on the mount (i.e. it was in the [nearly] correct, flipped position, but KStars froze upon initiation of the flip and did not recover.
I had to force quit Kstars and restart it.

Here the log to the event. The log ends with Kstars freezing:

[2020-02-24T19:57:05.434 CST DEBG ][ org.kde.kstars.ekos.guide] - Capturing frame...
[2020-02-24T19:57:05.474 CST DEBG ][ org.kde.kstars.indi] - iOptron CEM60 : "[DEBUG] CMD <:GLS#> "
[2020-02-24T19:57:05.474 CST DEBG ][ org.kde.kstars.indi] - iOptron CEM60 : "[DEBUG] RES <-348454442028010801#> "
[2020-02-24T19:57:05.475 CST DEBG ][ org.kde.kstars.indi] - iOptron CEM60 : "[DEBUG] CMD <:GEC#> "
[2020-02-24T19:57:05.475 CST DEBG ][ org.kde.kstars.indi] - iOptron CEM60 : "[DEBUG] RES <-0124139820355120#> "
[2020-02-24T19:57:05.680 CST DEBG ][ org.kde.kstars.indi] - iOptron CEM60 : "[DEBUG] CMD <:Mn00112d#> "
[2020-02-24T19:57:05.681 CST DEBG ][ org.kde.kstars.indi] - ZWO CCD ASI120MM-S : "[DEBUG] StartExposure->setexp : 0.500s "
[2020-02-24T19:57:05.684 CST DEBG ][ org.kde.kstars.indi] - processBLOB() mode 0
[2020-02-24T19:57:05.728 CST INFO ][ org.kde.kstars.indi] - "FITS" file saved to "/home/tas/Pictures/OrionNebulaMC-183/O3/Light/M42-O3_Light_40_secs_2020-02-24T19-57-05_061.fits"
[2020-02-24T19:57:05.729 CST INFO ][ org.kde.kstars.fits] - Reading FITS file buffer
[2020-02-24T19:57:07.709 CST DEBG ][ org.kde.kstars.fits] - FITHistogram: JMIndex 0
[2020-02-24T19:57:07.716 CST INFO ][ org.kde.kstars.ekos.capture] - "Download Time: 2.42 s, New Download Time Estimate: 4.40 s."
[2020-02-24T19:57:07.726 CST INFO ][ org.kde.kstars.fits] - Loading FITS file "/home/tas/Pictures/OrionNebulaMC-183/O3/Light/M42-O3_Light_40_secs_2020-02-24T19-57-05_061.fits"
[2020-02-24T19:57:07.727 CST INFO ][ org.kde.kstars.ekos.capture] - "Received image 58 out of 100."
[2020-02-24T19:57:07.729 CST DEBG ][ org.kde.kstars.ekos.capture] - setMeridianFlipStage: 2
[2020-02-24T19:57:07.759 CST DEBG ][ org.kde.kstars.indi] - ZWO CCD ASI120MM-S : "[DEBUG] Uploading file. Ext: fits, Size: 313920, sendImage? Yes, saveImage? No "
[2020-02-24T19:57:07.760 CST DEBG ][ org.kde.kstars.indi] - ZWO CCD ASI120MM-S : "[DEBUG] BLOB transfer took 0.0021788 seconds "
[2020-02-24T19:57:07.760 CST DEBG ][ org.kde.kstars.indi] - ZWO CCD ASI120MM-S : "[DEBUG] Upload complete "
[2020-02-24T19:57:07.760 CST DEBG ][ org.kde.kstars.indi] - processBLOB() mode 2
[2020-02-24T19:57:07.763 CST INFO ][ org.kde.kstars.fits] - Reading FITS file buffer
[2020-02-24T19:57:07.954 CST DEBG ][ org.kde.kstars.ekos.guide] - Received guide frame.
[2020-02-24T19:57:07.955 CST DEBG ][ org.kde.kstars.ekos.guide] - Tracking Square QRect(543,342 16x16)
[2020-02-24T19:57:07.955 CST DEBG ][ org.kde.kstars.ekos.guide] - ################## BEGIN PROCESSING ##################
[2020-02-24T19:57:07.955 CST DEBG ][ org.kde.kstars.ekos.guide] - Star X : 551.96 Y : 350.355
[2020-02-24T19:57:07.955 CST DEBG ][ org.kde.kstars.ekos.guide] - Reticle X : 551.915 Y : 350.353
[2020-02-24T19:57:07.955 CST DEBG ][ org.kde.kstars.ekos.guide] - Star RA: 3557.81 DEC: 2258.31
[2020-02-24T19:57:07.955 CST DEBG ][ org.kde.kstars.ekos.guide] - Reticle RA: 3557.52 DEC: 2258.3
[2020-02-24T19:57:07.955 CST DEBG ][ org.kde.kstars.ekos.guide] -
> BEFORE ROTATION Diff RA: 0.292148 DEC: -0.0109306
[2020-02-24T19:57:07.956 CST DEBG ][ org.kde.kstars.ekos.guide] -
> AFTER ROTATION Diff RA: 0.0240703 DEC: 0.29136
[2020-02-24T19:57:07.956 CST DEBG ][ org.kde.kstars.ekos.guide] - RA channel ticks: 49 DEC channel ticks: 49
[2020-02-24T19:57:07.956 CST DEBG ][ org.kde.kstars.ekos.guide] - Processing Axes
[2020-02-24T19:57:07.956 CST DEBG ][ org.kde.kstars.ekos.guide] - At # 49 drift[ 0 ][ 49 ] = 0.0240703 , t_delta: 0.0240703
[2020-02-24T19:57:07.956 CST DEBG ][ org.kde.kstars.ekos.guide] - delta [ 0 ]= 0.0240703
[2020-02-24T19:57:07.956 CST DEBG ][ org.kde.kstars.ekos.guide] - drift_integral[ 0 ]= -0.00919591
[2020-02-24T19:57:07.956 CST DEBG ][ org.kde.kstars.ekos.guide] - pulse_length [ 0 ]= 4
[2020-02-24T19:57:07.956 CST DEBG ][ org.kde.kstars.ekos.guide] - Direction : NO DIR
[2020-02-24T19:57:07.956 CST DEBG ][ org.kde.kstars.ekos.guide] - At # 49 drift[ 1 ][ 49 ] = 0.29136 , t_delta: 0.29136
[2020-02-24T19:57:07.956 CST DEBG ][ org.kde.kstars.ekos.guide] - delta [ 1 ]= 0.29136
[2020-02-24T19:57:07.957 CST DEBG ][ org.kde.kstars.ekos.guide] - drift_integral[ 1 ]= 6.18851
[2020-02-24T19:57:07.957 CST DEBG ][ org.kde.kstars.ekos.guide] - pulse_length [ 1 ]= 100
[2020-02-24T19:57:07.957 CST DEBG ][ org.kde.kstars.ekos.guide] - Direction : Increase DEC
[2020-02-24T19:57:07.957 CST DEBG ][ org.kde.kstars.ekos.guide] - ################## FINISH PROCESSING ##################
[2020-02-24T19:57:07.957 CST DEBG ][ org.kde.kstars.ekos.guide] - Capturing frame...
[2020-02-24T19:57:08.000 CST DEBG ][ org.kde.kstars.indi] - iOptron CEM60 : "[DEBUG] CMD <:GLS#> "
[2020-02-24T19:57:08.000 CST DEBG ][ org.kde.kstars.indi] - iOptron CEM60 : "[DEBUG] RES <-348454442028010801#> "
[2020-02-24T19:57:08.001 CST DEBG ][ org.kde.kstars.indi] - iOptron CEM60 : "[DEBUG] CMD <:GEC#> "
[2020-02-24T19:57:08.001 CST DEBG ][ org.kde.kstars.indi] - iOptron CEM60 : "[DEBUG] RES <-0124145520355200#> "
[2020-02-24T19:57:08.002 CST DEBG ][ org.kde.kstars.indi] - iOptron CEM60 : "[DEBUG] CMD <:GLS#> "
[2020-02-24T19:57:08.002 CST DEBG ][ org.kde.kstars.indi] - iOptron CEM60 : "[DEBUG] RES <-348454442028010801#> "
[2020-02-24T19:57:08.003 CST DEBG ][ org.kde.kstars.indi] - iOptron CEM60 : "[DEBUG] CMD <:GEC#> "
[2020-02-24T19:57:08.003 CST DEBG ][ org.kde.kstars.indi] - iOptron CEM60 : "[DEBUG] RES <-0124145520355200#> "
[2020-02-24T19:57:08.007 CST DEBG ][ org.kde.kstars.indi] - INDI Server: "2020-02-25T01:57:06: Driver indi_asi_ccd: No INumber 'Gamma' in ZWO CCD ASI120MM-S.CCD_CONTROLS"
[2020-02-24T19:57:08.007 CST DEBG ][ org.kde.kstars.indi] - INDI Server: ""
[2020-02-24T19:57:08.219 CST INFO ][ org.kde.kstars.ekos.mount] - Meridian flip: slewing to RA= "05h 39m 11s" DEC= "-03° 31' 59\""
[2020-02-24T19:57:08.219 CST DEBG ][ org.kde.kstars.ekos.mount] - Setting meridian flip status to 4
[2020-02-24T19:57:08.220 CST DEBG ][ org.kde.kstars.ekos.capture] - meridianFlipStatusChanged: 4
[2020-02-24T19:57:08.221 CST DEBG ][ org.kde.kstars.ekos.capture] - setMeridianFlipStage: 3
[2020-02-24T19:57:08.223 CST DEBG ][ org.kde.kstars.ekos.capture] - Guiding state changed from "Guiding" to "Aborted"
[2020-02-24T19:57:08.223 CST INFO ][ org.kde.kstars.ekos.guide] - "Autoguiding aborted."
[2020-02-24T19:57:08.227 CST DEBG ][ org.kde.kstars.ekos.guide] - Aborting "Guiding"
[2020-02-24T19:57:08.228 CST DEBG ][ org.kde.kstars.ekos.mount] - Slewing to RA= "05h 39m 11s" DEC= "-03° 31' 59\""
[2020-02-24T19:57:08.230 CST DEBG ][ org.kde.kstars.indi] - ISD:Telescope sending coords RA: "05h 39m 11s" ( 5.65324 ) DE: "-03° 31' 59\"" ( -3.53329 )
[2020-02-24T19:57:08.240 CST DEBG ][ org.kde.kstars.indi] - iOptron CEM60 : "[DEBUG] CMD <:Mn00100d#> "
[2020-02-24T19:57:08.240 CST DEBG ][ org.kde.kstars.indi] - ZWO CCD ASI120MM-S : "[DEBUG] StartExposure->setexp : 0.500s "
[2020-02-24T19:57:08.245 CST DEBG ][ org.kde.kstars.indi] - ZWO CCD ASI120MM-S : "[DEBUG] Aborting camera exposure... "
[2020-02-24T19:57:08.954 CST DEBG ][ org.kde.kstars.indi] - iOptron CEM60 : "[DEBUG] CMD <:Sr20351664#> "
[2020-02-24T19:57:08.954 CST DEBG ][ org.kde.kstars.indi] - iOptron CEM60 : "[DEBUG] RES <31> "
[2020-02-24T19:57:08.954 CST DEBG ][ org.kde.kstars.indi] - iOptron CEM60 : "[DEBUG] CMD <:Sd-01271984#> "
[2020-02-24T19:57:08.954 CST DEBG ][ org.kde.kstars.indi] - iOptron CEM60 : "[DEBUG] RES <31> "
[2020-02-24T19:57:08.955 CST DEBG ][ org.kde.kstars.indi] - iOptron CEM60 : "[DEBUG] CMD <:MS#> "
[2020-02-24T19:57:08.961 CST DEBG ][ org.kde.kstars.indi] - iOptron CEM60 : "[DEBUG] RES <31> "
[2020-02-24T19:57:08.961 CST DEBG ][ org.kde.kstars.indi] - iOptron CEM60 : "[DEBUG] CMD <:GLS#> "
[2020-02-24T19:57:08.962 CST DEBG ][ org.kde.kstars.indi] - iOptron CEM60 : "[DEBUG] RES <-348454442028010801#> "
[2020-02-24T19:57:08.962 CST DEBG ][ org.kde.kstars.indi] - iOptron CEM60 : "[DEBUG] CMD <:GLS#> "
[2020-02-24T19:57:08.962 CST DEBG ][ org.kde.kstars.indi] - iOptron CEM60 : "[DEBUG] RES <-348454442028010801#> "
[2020-02-24T19:57:08.962 CST DEBG ][ org.kde.kstars.indi] - iOptron CEM60 : "[DEBUG] CMD <:GLS#> "
[2020-02-24T19:57:08.962 CST DEBG ][ org.kde.kstars.indi] - iOptron CEM60 : "[DEBUG] RES <-348454442028010801#> "
[2020-02-24T19:57:09.055 CST DEBG ][ org.kde.kstars.indi] - iOptron CEM60 : "[DEBUG] CMD <:GLS#> "
4 years 1 month ago #50068

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

  • Posts: 969
  • Thank you received: 94

Hi
Not after meridian flip but fails to download. Maybe the flip was misleading. Capture counts down, reached 0.1s and waits until timed out.

File Attachment:

File Name: log_21-24-08.txt
File Size:7,420 KB


Cheers,
Steve
4 years 1 month ago #50166
Attachments:

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

  • Posts: 1029
  • Thank you received: 301
I'll have a look at the log, but the issue is bound to happen after the alignment phase, if the sequence is resuming and not restarting. Meridian flip just happens to trigger that sequence every time.

-Eric
4 years 1 month ago #50189

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

  • Posts: 969
  • Thank you received: 94
Hi
No problem. I posted mainly for @hy who had put in some extra debugging.
Now we know it times out and recovers, NP.
Cheers
4 years 1 month ago #50191

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

  • Posts: 1221
  • Thank you received: 565
Thanks for doing that. I did look at you log, log_21-24-08.txt, but nothing was obvious. Here's what I saw:

BTW, the log is full of lots of unhelpful messages (for this--no problem and not your fault) so below I've grepped out a lot of lines as follows in the below examples
grep -v -i eqmod ~/Desktop/log_21-24-08.txt | grep -v -i phd2 > ~/zz

You can see that the previous exposure, starts

[2020-02-26T21:47:43.679 CET INFO ][ org.kde.kstars.ekos.capture] - "Capturing 240,000-second image..."

and ends successfully

[2020-02-26T21:51:38.876 CET DEBG ][ org.kde.kstars.indi] - Canon DSLR EOS 450D (PTP mode) : "[DEBUG] Time left: 4994 ms "
[2020-02-26T21:51:39.599 CET INFO ][ org.kde.kstars.fits] - Reading FITS file buffer
[2020-02-26T21:51:41.934 CET INFO ][ org.kde.kstars.fits] - Reading FITS file buffer
[2020-02-26T21:51:43.784 CET DEBG ][ org.kde.kstars.indi] - Canon DSLR EOS 450D (PTP mode) : "[DEBUG] Reading exposure... "
[2020-02-26T21:51:43.870 CET DEBG ][ org.kde.kstars.indi] - Canon DSLR EOS 450D (PTP mode) : "[DEBUG] Time left: -1 ms "
[2020-02-26T21:51:43.870 CET DEBG ][ org.kde.kstars.indi] - Canon DSLR EOS 450D (PTP mode) : "[DEBUG] Closing internal shutter. "
[2020-02-26T21:51:43.870 CET DEBG ][ org.kde.kstars.indi] - Canon DSLR EOS 450D (PTP mode) : "[DEBUG] Using widget:bulb "
[2020-02-26T21:51:43.870 CET DEBG ][ org.kde.kstars.indi] - Canon DSLR EOS 450D (PTP mode) : "[DEBUG] Setting toggle widget bulb: 0 "
[2020-02-26T21:51:43.904 CET DEBG ][ org.kde.kstars.indi] - Canon DSLR EOS 450D (PTP mode) : "[DEBUG] Setting new configuration OK. "
[2020-02-26T21:51:43.904 CET DEBG ][ org.kde.kstars.indi] - Canon DSLR EOS 450D (PTP mode) : "[DEBUG] Exposure complete. "
[2020-02-26T21:51:43.913 CET DEBG ][ org.kde.kstars.indi] - Canon DSLR EOS 450D (PTP mode) : "[DEBUG] Capture event completed. "
[2020-02-26T21:51:44.234 CET INFO ][ org.kde.kstars.fits] - Reading FITS file buffer
[2020-02-26T21:51:46.746 CET INFO ][ org.kde.kstars.fits] - Reading FITS file buffer
[2020-02-26T21:51:47.094 CET DEBG ][ org.kde.kstars.indi] - Canon DSLR EOS 450D (PTP mode) : "[DEBUG] File added event completed. "
[2020-02-26T21:51:47.094 CET DEBG ][ org.kde.kstars.indi] - Canon DSLR EOS 450D (PTP mode) : "[DEBUG] Downloading image... Name: (capt0009.cr2) Folder: (/) Delete from SD card? (false) "
[2020-02-26T21:51:47.103 CET DEBG ][ org.kde.kstars.indi] - Canon DSLR EOS 450D (PTP mode) : "[DEBUG] Downloaded 0x0 (preview 0x0) "
[2020-02-26T21:51:47.108 CET DEBG ][ org.kde.kstars.indi] - Canon DSLR EOS 450D (PTP mode) : "[DEBUG] Capture target is INTERNAL RAM. "
[2020-02-26T21:51:47.109 CET INFO ][ org.kde.kstars.indi] - Canon DSLR EOS 450D (PTP mode) : "[INFO] Exposure done, downloading image... "
[2020-02-26T21:51:47.932 CET DEBG ][ org.kde.kstars.indi] - Canon DSLR EOS 450D (PTP mode) : "[DEBUG] read_libraw: raw_width: 4312 top_margin 18 left_margin 22 first_visible_pixel 77638 "
[2020-02-26T21:51:47.932 CET DEBG ][ org.kde.kstars.indi] - Canon DSLR EOS 450D (PTP mode) : "[DEBUG] read_libraw: rawdata.sizes.width: 4290 rawdata.sizes.height 2856 memsize 24504480 bayer_pattern RGGB "
[2020-02-26T21:51:47.939 CET DEBG ][ org.kde.kstars.indi] - Canon DSLR EOS 450D (PTP mode) : "[DEBUG] read_libraw: memsize (24504480) naxis (2) w (4290) h (2856) bpp (16) bayer pattern (RGGB) "
[2020-02-26T21:51:47.963 CET DEBG ][ org.kde.kstars.indi] - Canon DSLR EOS 450D (PTP mode) : "[DEBUG] Uploading file. Ext: fits, Size: 24511680, sendImage? Yes, saveImage? No "
[2020-02-26T21:51:48.056 CET DEBG ][ org.kde.kstars.indi] - Canon DSLR EOS 450D (PTP mode) : "[DEBUG] BLOB transfer took 0.0639456 seconds "
[2020-02-26T21:51:48.061 CET DEBG ][ org.kde.kstars.indi] - Canon DSLR EOS 450D (PTP mode) : "[DEBUG] Upload complete "
[2020-02-26T21:51:48.156 CET DEBG ][ org.kde.kstars.indi] - processBLOB() mode 0

***** note the processBLOB() at the end. Without that, capture/focus/align/fitsviewer will not receive the image.


In the next, failed exposure:

[2020-02-26T21:52:35.679 CET INFO ][ org.kde.kstars.ekos.capture] - "Capturing 240,000-second image..."
[2020-02-26T21:52:35.682 CET DEBG ][ org.kde.kstars.ekos.scheduler] - Capture State "Capturing"
[2020-02-26T21:52:35.724 CET INFO ][ org.kde.kstars.indi] - Canon DSLR EOS 450D (PTP mode) : "[INFO] Starting 240 seconds exposure. "

Going to the end of that exposure, it looks like indi receives the image, but the processBLOB() log is never printed.

[2020-02-26T21:56:30.875 CET DEBG ][ org.kde.kstars.indi] - Canon DSLR EOS 450D (PTP mode) : "[DEBUG] Time left: 4994 ms "
[2020-02-26T21:56:31.579 CET INFO ][ org.kde.kstars.fits] - Reading FITS file buffer
[2020-02-26T21:56:34.340 CET INFO ][ org.kde.kstars.fits] - Reading FITS file buffer
[2020-02-26T21:56:35.783 CET DEBG ][ org.kde.kstars.indi] - Canon DSLR EOS 450D (PTP mode) : "[DEBUG] Reading exposure... "
[2020-02-26T21:56:35.869 CET DEBG ][ org.kde.kstars.indi] - Canon DSLR EOS 450D (PTP mode) : "[DEBUG] Time left: -1 ms "
[2020-02-26T21:56:35.869 CET DEBG ][ org.kde.kstars.indi] - Canon DSLR EOS 450D (PTP mode) : "[DEBUG] Closing internal shutter. "
[2020-02-26T21:56:35.869 CET DEBG ][ org.kde.kstars.indi] - Canon DSLR EOS 450D (PTP mode) : "[DEBUG] Using widget:bulb "
[2020-02-26T21:56:35.869 CET DEBG ][ org.kde.kstars.indi] - Canon DSLR EOS 450D (PTP mode) : "[DEBUG] Setting toggle widget bulb: 0 "
[2020-02-26T21:56:35.897 CET DEBG ][ org.kde.kstars.indi] - Canon DSLR EOS 450D (PTP mode) : "[DEBUG] Setting new configuration OK. "
[2020-02-26T21:56:35.897 CET DEBG ][ org.kde.kstars.indi] - Canon DSLR EOS 450D (PTP mode) : "[DEBUG] Exposure complete. "
[2020-02-26T21:56:35.912 CET DEBG ][ org.kde.kstars.indi] - Canon DSLR EOS 450D (PTP mode) : "[DEBUG] Capture event completed. "
[2020-02-26T21:56:36.523 CET INFO ][ org.kde.kstars.fits] - Reading FITS file buffer
[2020-02-26T21:56:39.147 CET DEBG ][ org.kde.kstars.indi] - Canon DSLR EOS 450D (PTP mode) : "[DEBUG] File added event completed. "
[2020-02-26T21:56:39.147 CET DEBG ][ org.kde.kstars.indi] - Canon DSLR EOS 450D (PTP mode) : "[DEBUG] Downloading image... Name: (capt0010.cr2) Folder: (/) Delete from SD card? (false) "
[2020-02-26T21:56:39.158 CET DEBG ][ org.kde.kstars.indi] - Canon DSLR EOS 450D (PTP mode) : "[DEBUG] Downloaded 0x0 (preview 0x0) "
[2020-02-26T21:56:39.162 CET DEBG ][ org.kde.kstars.indi] - Canon DSLR EOS 450D (PTP mode) : "[DEBUG] Capture target is INTERNAL RAM. "
[2020-02-26T21:56:39.163 CET INFO ][ org.kde.kstars.indi] - Canon DSLR EOS 450D (PTP mode) : "[INFO] Exposure done, downloading image... "
[2020-02-26T21:56:39.977 CET DEBG ][ org.kde.kstars.indi] - Canon DSLR EOS 450D (PTP mode) : "[DEBUG] read_libraw: raw_width: 4312 top_margin 18 left_margin 22 first_visible_pixel 77638 "
[2020-02-26T21:56:39.977 CET DEBG ][ org.kde.kstars.indi] - Canon DSLR EOS 450D (PTP mode) : "[DEBUG] read_libraw: rawdata.sizes.width: 4290 rawdata.sizes.height 2856 memsize 24504480 bayer_pattern RGGB "
[2020-02-26T21:56:39.985 CET DEBG ][ org.kde.kstars.indi] - Canon DSLR EOS 450D (PTP mode) : "[DEBUG] read_libraw: memsize (24504480) naxis (2) w (4290) h (2856) bpp (16) bayer pattern (RGGB) "
[2020-02-26T21:56:40.010 CET DEBG ][ org.kde.kstars.indi] - Canon DSLR EOS 450D (PTP mode) : "[DEBUG] Uploading file. Ext: fits, Size: 24511680, sendImage? Yes, saveImage? No "
[2020-02-26T21:56:40.100 CET DEBG ][ org.kde.kstars.indi] - Canon DSLR EOS 450D (PTP mode) : "[DEBUG] BLOB transfer took 0.0685239 seconds "
[2020-02-26T21:56:40.100 CET DEBG ][ org.kde.kstars.indi] - Canon DSLR EOS 450D (PTP mode) : "[DEBUG] Upload complete "
[2020-02-26T21:56:41.502 CET INFO ][ org.kde.kstars.fits] - Reading FITS file buffer
[2020-02-26T21:56:44.057 CET INFO ][ org.kde.kstars.fits] - Reading FITS file buffer
[2020-02-26T21:56:46.582 CET INFO ][ org.kde.kstars.fits] - Reading FITS file buffer
[2020-02-26T21:56:49.697 CET INFO ][ org.kde.kstars.fits] - Reading FITS file buffer
[2020-02-26T21:56:51.876 CET INFO ][ org.kde.kstars.fits] - Reading FITS file buffer
[2020-02-26T21:56:54.271 CET INFO ][ org.kde.kstars.fits] - Reading FITS file buffer

The debug log for processBlob() in kstars/indi/indiccd.cpp is not right at the start of the method, but pretty close, after it filters out ccd type and blob type. I don't know what's going on there either, but I think that either indi is not sending the blob to ekos, or indi is mispackaging it (eg assigning it the wrong blob type or ccd type). The debug statement on line 1566 of indiccd.cpp is not reached or printed, indicating that processBLOB isn't running, but yet it's clear from the log that the indi driver downloaded the image.

I too am seeing stalled exposures from time-to-time too. Not frequently, but I have seen it happen. I really have no experience with indi or the indi/kstars communictions. Does someone out there know why indi might not transfer the image to indiccd.cpp?

I may put several more logging statements in the source on my raspberry pi in hopes of catching something. I would like to put a couple more debugging logs in the code. Hopefully the next time it happens to me, I can get a few more clues.
The following user(s) said Thank You: alacant
4 years 1 month ago #50205

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

Time to create page: 1.164 seconds