×

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

Bi-monthly release with minor bug fixes and improvements

Bug report -- autofocus on filter change confuses capture

  • Posts: 1208
  • Thank you received: 559
I've come across what looks like an odd bug related to the focus on filter change feature.
The last few nights, my jobs shooting M33 have stopped (around 3am) soon after a successful meridian flip. From looking at the logs (and I was logging all modules, pretty much) it seems like after the flip, align, guiding re-start, the capture module restarted it's captures, but *at the same time* an auto-focus operation was ongoing. This concurrent capture and auto-focus brought down the job. 
I'm guessing that the reason for the auto-focus was because the post-flip align used a different filter than the capture tab, and that somehow triggered an auto-focus. 
Also, clearly, when one requests auto-focus-on-filter-change, one means only for the capture tab, not for the align tab. 
Anyway, perhaps my theory is wrong, but here are a couple of logs.

Note in the log named log_01-45-25.txt

[2019-09-25T02:47:46.643 PDT INFO ][   org.kde.kstars.ekos.capture] - "Capturing 240.000-second Green image..."
...[2019-09-25T02:47:58.470 PDT INFO ][     org.kde.kstars.ekos.focus] - "Image received."
[2019-09-25T02:48:00.023 PDT INFO ][     org.kde.kstars.ekos.focus] - "Capturing image..."
...

and in log_21-40-37.txt

[2019-09-24T02:47:11.823 PDT INFO ][   org.kde.kstars.ekos.capture] - "Capturing 240.000-second Red image..."
[2019-09-24T02:47:23.254 PDT INFO ][     org.kde.kstars.ekos.focus] - "Image received."

File Attachment:

File Name: log_01-45-25.txt
File Size:4,016 KB

File Attachment:

File Name: log_21-40-37.txt
File Size:7,450 KB

[2019-09-24T02:47:25.174 PDT INFO ][     org.kde.kstars.ekos.focus] - "Capturing image..."
...[2019-09-24T02:54:11.775 PDT INFO ][   org.kde.kstars.ekos.capture] - "Exposure timeout. Restarting exposure..."
[2019-09-24T03:01:11.775 PDT INFO ][   org.kde.kstars.ekos.capture] - "Exposure timeout. Restarting exposure..."
[2019-09-24T03:08:11.795 PDT INFO ][   org.kde.kstars.ekos.capture] - "CCD capture aborted"

The system seems to be doing two things at once in both these logs.
Hy
4 years 6 months ago #43880
Attachments:

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

  • Posts: 1208
  • Thank you received: 559
Forgot to mention, on the log_01-45-25.txt log, I was running kstars v3.3.6 (really compiled from the 3.3.6 commit on a raspberry pi 4), and on the other log it was a bleeding-edge compile around v3.3.4 also on the RPi4. Used a ZWO ASI1600 mmpro with zwo filter wheel.
Hy
4 years 6 months ago #43881

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

Actually, after investigating the log for bit. That's not the reason. The reason is that PHD2 failed to resume after pause, so that aborted the capture job. But then PHD2 continued to guide, but apparently no signal about guiding was sent out so capture remained as aborted.
[2019-09-25T02:48:34.581 PDT INFO ][     org.kde.kstars.ekos.focus] - "Autofocus complete after 5 iterations."
[2019-09-25T02:48:34.585 PDT DEBG ][     org.kde.kstars.ekos.focus] - Stopppig Focus
[2019-09-25T02:48:34.585 PDT DEBG ][     org.kde.kstars.ekos.focus] - AutoFocus result: true
[2019-09-25T02:48:34.586 PDT DEBG ][     org.kde.kstars.ekos.guide] - PHD2: request: "{\"id\":846,\"jsonrpc\":\"2.0\",\"method\":\"set_paused\",\"params\":[false]}"
[2019-09-25T02:48:34.597 PDT DEBG ][     org.kde.kstars.ekos.focus] - State: "Complete"
[2019-09-25T02:48:34.903 PDT DEBG ][     org.kde.kstars.ekos.guide] - PHD2: event: "{\"Event\":\"Resumed\",\"Timestamp\":1569404914.897,\"Host\":\"raspberrypi\",\"Inst\":1}\r\n"
[2019-09-25T02:48:34.904 PDT INFO ][     org.kde.kstars.ekos.guide] - "PHD2: Guiding Resumed."
[2019-09-25T02:48:34.906 PDT INFO ][     org.kde.kstars.ekos.guide] - "Guiding resumed."
[2019-09-25T02:48:34.908 PDT DEBG ][     org.kde.kstars.ekos.guide] - PHD2: response: "{\"jsonrpc\":\"2.0\",\"result\":0,\"id\":846}\r\n"
[2019-09-25T02:48:38.319 PDT DEBG ][     org.kde.kstars.ekos.guide] - PHD2: event: "{\"Event\":\"SettleDone\",\"Timestamp\":1569404918.318,\"Host\":\"raspberrypi\",\"Inst\":1,\"Status\":1,\"Error\":\"timed-out waiting for guider to settle\",\"TotalFrames\":8,\"DroppedFrames\":0}\r\n"
[2019-09-25T02:48:38.319 PDT INFO ][     org.kde.kstars.ekos.guide] - "PHD2: Settling failed (timed-out waiting for guider to settle)."
[2019-09-25T02:48:38.324 PDT INFO ][     org.kde.kstars.ekos.guide] - "PHD2: Settling failed, aborted."
[2019-09-25T02:48:38.326 PDT INFO ][   org.kde.kstars.ekos.capture] - "Autoguiding stopped. Aborting..."
[2019-09-25T02:48:38.327 PDT INFO ][   org.kde.kstars.ekos.capture] - "CCD capture aborted"
[2019-09-25T02:48:38.335 PDT INFO ][     org.kde.kstars.ekos.guide] - "Autoguiding aborted."
[2019-09-25T02:48:38.421 PDT DEBG ][     org.kde.kstars.ekos.guide] - PHD2: event: "{\"Event\":\"GuideStep\",\"Timestamp\":1569404918.376,\"Host\":\"raspberrypi\",\"Inst\":1,\"Frame\":8,\"Time\":61.387,\"Mount\":\"INDI Mount [EQMod Mount]\",\"dx\":0.430,\"dy\":-0.811,\"RADistanceRaw\":-0.907,\"DECDistanceRaw\":0.067,\"RADistanceGuide\":-0.572,\"DECDistanceGuide\":0.000,\"RADuration\":145,\"RADirection\":\"East\",\"StarMass\":401,\"SNR\":13.92,\"HFD\":3.96,\"AvgDist\":0.92}\r\n"
[2019-09-25T02:48:38.451 PDT DEBG ][     org.kde.kstars.ekos.guide] - PHD2: request: "{\"id\":847,\"jsonrpc\":\"2.0\",\"method\":\"get_star_image\",\"params\":[32]}"
[2019-09-25T02:48:38.493 PDT DEBG ][     org.kde.kstars.ekos.guide] - PHD2: received star image response, id 847
[2019-09-25T02:48:38.497 PDT INFO ][           org.kde.kstars.fits] - Loading FITS file  "/tmp/kstars/phd2_ICoiHY"
[2019-09-25T02:48:41.882 PDT DEBG ][     org.kde.kstars.ekos.guide] - PHD2: event: "{\"Event\":\"GuideStep\",\"Timestamp\":1569404921.881,\"Host\":\"raspberrypi\",\"Inst\":1,\"Frame\":9,\"Time\":64.891,\"Mount\":\"INDI Mount [EQMod Mount]\",\"dx\":0.304,\"dy\":-1.706,\"RADistanceRaw\":-1.552,\"DECDistanceRaw\":0.650,\"RADistanceGuide\":-1.018,\"DECDistanceGuide\":0.000,\"RADuration\":259,\"RADirection\":\"East\",\"StarMass\":396,\"SNR\":13.87,\"HFD\":4.07,\"AvgDist\":1.16}\r\n"
[2019-09-25T02:48:41.937 PDT DEBG ][     org.kde.kstars.ekos.guide] - PHD2: request: "{\"id\":848,\"jsonrpc\":\"2.0\",\"method\":\"get_star_image\",\"params\":[32]}"
[2019-09-25T02:48:41.979 PDT DEBG ][     org.kde.kstars.ekos.guide] - PHD2: received star image response, id 848
[2019-09-25T02:48:41.982 PDT INFO ][           org.kde.kstars.fits] - Loading FITS file  "/tmp/kstars/phd2_OYxcSd"
[2019-09-25T02:48:45.479 PDT DEBG ][     org.kde.kstars.ekos.guide] - PHD2: event: "{\"Event\":\"GuideStep\",\"Timestamp\":1569404925.478,\"Host\":\"raspberrypi\",\"Inst\":1,\"Frame\":10,\"Time\":68.490,\"Mount\":\"INDI Mount [EQMod Mount]\",\"dx\":-0.658,\"dy\":-0.963,\"RADistanceRaw\":-0.382,\"DECDistanceRaw\":1.069,\"RADistanceGuide\":-0.312,\"DECDistanceGuide\":1.069,\"RADuration\":79,\"RADirection\":\"East\",\"DECDuration\":205,\"DECDirection\":\"South\",\"StarMass\":386,\"SNR\":13.66,\"HFD\":4.27,\"AvgDist\":1.16}\r\n"
[2019-09-25T02:48:45.503 PDT DEBG ][     org.kde.kstars.ekos.guide] - PHD2: request: "{\"id\":849,\"jsonrpc\":\"2.0\",\"method\":\"get_star_image\",\"params\":[32]}"
[2019-09-25T02:48:45.535 PDT DEBG ][     org.kde.kstars.ekos.guide] - PHD2: received star image response, id 849
[2019-09-25T02:48:45.537 PDT INFO ][           org.kde.kstars.fits] - Loading FITS file  "/tmp/kstars/phd2_UAGhFy"
[2019-09-25T02:48:48.910 PDT DEBG ][     org.kde.kstars.ekos.guide] - PHD2: event: "{\"Event\":\"GuideStep\",\"Timestamp\":1569404928.909,\"Host\":\"raspberrypi\",\"Inst\":1,\"Frame\":11,\"Time\":71.834,\"Mount\":\"INDI Mount [EQMod Mount]\",\"dx\":-0.525,\"dy\":-0.402,\"RADistanceRaw\":-0.011,\"DECDistanceRaw\":0.658,\"RADistanceGuide\":0.000,\"DECDistanceGuide\":0.658,\"DECDuration\":126,\"DECDirection\":\"South\",\"StarMass\":383,\"SNR\":13.63,\"HFD\":3.73,\"AvgDist\":1.01}\r\n"

@rlancaste any possible explanation for not emitting the signal?
4 years 6 months ago #43882

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

  • Posts: 1208
  • Thank you received: 559
Jasem,
Hope it's OK if I probe a little further. 
I understand what you're saying (that there's a potential issue with PHD2 at 02:48:38) but doesn't that happen after the original strangeness?
That is, looking at the 3 lines here:
[2019-09-25T02:47:46.643 PDT INFO ][   org.kde.kstars.ekos.capture] - "Capturing 240.000-second Green image..."
[2019-09-25T02:47:58.470 PDT INFO ][     org.kde.kstars.ekos.focus] - "Image received."
[2019-09-25T02:48:00.023 PDT INFO ][     org.kde.kstars.ekos.focus] - "Capturing image..."
It seems that Capture started a 240s exposure at 02:47:46.6,but then 12 seconds later focus receives an exposure at 2:47:58.4,and starts up another exposure at 2:48:00, and no word from capture in between, so there are overlapping requests take an image from both the capture and focus tabs on the same camera. 
So, perhaps, PHD2 might have not resumed because of the autofocus?
I've had this crash 3 nights in a row. I'm trying to re-run this tonight, but without autofocus-on-filter-change, and hoping that the crash will not recur and give us a clue.
Hy
4 years 6 months ago #43883

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

  • Posts: 1208
  • Thank you received: 559
I re-ran the same job last night (that had failed the previous 3 nights) but this time, without autofocus-on-filter-change (I set autofocus every 30 minutes instead, and filter changes were about every 30 minutes). My job ran through the night, no problems, completing the meridian flip, etc.

I did try and see if I could find a bug in the filter-change-autofocus stuff, and admittedly, I didn't see anything, but am pretty unfamiliar with that stuff and it's complex.
I'll report back if I ever do get to the bottom of it.

My workaround is not to use the autofocus-on-filter-change. I do think that's a nice feature, so I'll make an effort to track things down.
Hy
4 years 6 months ago #43915

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

  • Posts: 2876
  • Thank you received: 809
I found some issues in PHD2 earlier this week that I decided I wanted to address. It has been a little while since I did the huge overhaul of phd2 support awhile back. So I decided to attack those issues and added some more support too. But I think one of the changes that I made might help in your case. I haven’t had time to look through your log. But based on what was said, it sounds like the guide state wasn’t set back to guiding after it had been restarted. Probably there was a communication glitch with phd2. Sometimes the messages don’t make it. But I think the change I made to address a similar issue might fix your issue too.

Basically my solution is if Ekos is getting guide step signals and the guide state hasn’t been changed to guide, then to just go ahead and change the state because we can’t be getting guide steps if it’s not guiding :-)
The following user(s) said Thank You: Peter Sütterlin
4 years 6 months ago #43920

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

  • Posts: 1009
  • Thank you received: 133

Ah, I was hit by that one last night, too. I had started guiding in PHD2, but EKOS, although connected, stayed in 'Stop' state and didn't do dithers. I had to press 'Guide' in Guide Tab to have it eventually start dithering...
4 years 6 months ago #43928

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

Time to create page: 0.447 seconds