Page 1 of 6 123456 LastLast
Results 1 to 10 of 58
  1. #1
    Join Date
    Nov 2007
    Location
    Australia
    Posts
    98

    Default ACP not detecting FM4 Acquire Failure - API Sync Issue

    Apologies if this has been raised before but I did search the forum before hand and didn't come up with a match. In reviewing the Scheduler Engine log, I see the following events highlighted in yellow.

    01-Aug-2015 08:37:36.2: ++ Auto Focus ++
    01-Aug-2015 08:37:36.3: Doing initial autofocus.
    01-Aug-2015 08:37:36.3: Start special ACP AutoFocus script for scheduler
    01-Aug-2015 08:45:01.6: Next periodic autofocus ASAP after 01-Jan-0001 00:30:00 UTC <<< Why the strange date?
    01-Aug-2015 08:45:11.6: Dispatcher cycle time: 9.8 sec.
    01-Aug-2015 08:45:11.6: Acquire data for Observation M16...
    01-Aug-2015 08:45:11.6: (belongs to Project M16, Plan M16-HA (5-8))
    01-Aug-2015 08:45:12.6: ++ Auto Focus ++
    01-Aug-2015 08:45:12.7: Doing periodic autofocus.
    01-Aug-2015 08:45:12.7: Start special ACP AutoFocus script for scheduler
    01-Aug-2015 08:52:51.5: ** Autofocus failed (n=1), will retry ASAP after 0 min.
    01-Aug-2015 08:52:51.7: Send Observation M16 to ACP Sequencer
    01-Aug-2015 10:10:36.8: Acquisition time: 4665.1588318 sec.
    01-Aug-2015 10:10:36.8: Data for Observation M16 of Plan M16-HA (5-8) acquired successfully.
    01-Aug-2015 10:10:36.9: Plan M16-HA (5-8) completed successfully.
    01-Aug-2015 10:10:37.0: Image Efficiency: 77.0%
    01-Aug-2015 10:10:37.0: Cycle Efficiency: 99.8%
    01-Aug-2015 10:10:37.5: ++ Auto Focus ++
    01-Aug-2015 10:10:37.6: Doing periodic autofocus.
    01-Aug-2015 10:10:37.6: Start special ACP AutoFocus script for scheduler
    01-Aug-2015 10:18:46.9: ** Autofocus failed (n=2), will retry ASAP after 5 min.

    ...

    On each of these autofocus runs, autofocus was successfully completed per the attached logs. Is this due to a time out of scheduler waiting for a response? Doing an advanced focus run in FMax v4 can take up to 6mins to complete.

    Has anyone else come across this?

    [edit: changed hard-coded yellow text to [high]xxx[/high] (also the pencil icon on the advanced text editor toolbar) so can be seen on all themes (I use light colored Royal Flush)]
    Attached Files Attached Files
    Last edited by Bob Denny; Aug 15, 2015 at 17:41.

  2. #2
    Join Date
    Nov 2007
    Location
    Australia
    Posts
    98

    Default

    ok, digging a little deeper on this problem. This is not consistent as I had originally thought. The previous post implies that every autofocus run in the scheduler script failed (even though they did not per the autofocus logs) however in later logs I can confirm that there are some successful autofocus events being flagged in the scheduler log. So this may not strictly be a scheduler related problem, but there is a twist...

    I am wondering if Scheduler is acknowledging the focus status in general. For example when FocusMax AcquireStar fails perhaps due to the star flux not being bright enough and attempts to slew to another star (three retry attempts are configured), ACP/Scheduler doesn't want to know about it. As soon as auto focus fails, Scheduler just goes straight into observation mode, even if FocusMax is busy.

    If I can draw your attention to what occurred at 09:30 UTC or 19:30 local time.
    FocusMax fails as the star flux was too low for the exposure time. Clould have been passing cloud or whatever. The cause is not so important, its the effect of a failed autofocus which is the item of interest.

    09:29:31 19:29:30 Exp = 2.00 HFD = 5.12 X: 2333 Y: 1494 Flux: 2105
    09:29:31 19:29:31 ** Star is too dim **
    09:29:32 19:29:31 Exposure > 15.00 maximum exposure setting
    09:29:32 19:29:32 Stopping process
    09:29:33 19:29:32 Cannot find target star
    09:29:33 19:29:33 Focus not achieved with star 1 of 3 - trying next target star
    09:29:33 **Autofocus failed. Check FocusMax log for details.
    09:29:33 Autofocus finished.
    09:29:33 ***AutoFocus failed.

    So based on the above FocusMax tries again with star 2 of 3 per the below.

    ACP console log opened 08-Aug-2015 09:30:22 UTC
    This is ACP version 8.0 (build 5, V8 Production Release A)
    Licensed to Jason Jennings
    09:30:34 (AF will use Monochrome readout mode)
    09:30:34 Starting FocusMax AcquireStar autofocus...
    09:30:35 **AutoFocus failed. Check FocusMax log for details.
    09:30:35 Autofocus finished.
    09:30:35 ***AutoFocus failed.
    ACP console log closed 08-Aug-2015 09:30:38 UTC

    The FocusMax log lists the following;
    19:30:31 ** Beginning Find Star **
    19:30:31 Filter = Clear (slot 4)
    19:30:31 Flux target: 200K
    19:30:31 Star subframe width: 100
    19:30:31 Base exposure: 2.00 sec
    19:30:31 Min/Max exposure: 0.01 / 15.00 sec
    19:30:31 Target star binning: 2
    19:30:31 CCD central region: 45%
    19:30:35 Error COM function AcquireStarAsync
    19:30:43 * COM FocusControl.Halt initiated *
    19:30:44 Moving to previous focus position of 12850

    19:30:45 Stopping operation
    19:30:46 AcquireStar not completed

    So I'm lead to believe that ACP/Scheduler is not acknowledging the need to let FocusMax continue on to star 2 or 3. Has anybody seen this?
    I'm running ACP 8, build 5, production release A with Scheduler 8.0.3.


    Separate unrelated topic (answered inline below):
    The next question I have is around the below line item in the ACP logs;
    ACP console log opened 08-Aug-2015 10:30:06 UTC
    This is ACP version 8.0 (build 5, V8 Production Release A)
    Licensed to Jason Jennings
    10:30:06 This is AcquireScheduler V8.0.8
    10:30:06 Custom image file path/names are in use
    10:30:06 [PreFlip=-300 PostFlip=300 AF=180 PU=60]
    10:30:06 Hardware GEM pier side reporting is available.
    10:30:08 Initializing AcquireSupport V8.0.3
    10:30:08 Weather safe, server is WeatherWatcher Server
    10:30:08 Telescope is ACP->Driver for telescope connected through TheSky, driver V3
    10:30:10 MaxIm DL is version 6.08
    10:30:10 Imager is Apogee USB/Net
    10:30:10 Using focus offsets and star mags from FilterInfo.txt
    10:30:10 Selecting filter Clear from previous ACP run at 20150808@092630 UTC
    10:30:10 Imager readout modes:
    10:30:10 0 is Monochrome
    10:30:10 1 is Monochrome (Preflash)
    10:30:10 Guider is SX Universal (no rotator)
    10:30:10 Guider plate scale unknown, guided dither with guider pixels

    What does this line in yellow mean?? Is it that when the Clear filter is selected it uses the previous runs focus position? What if that focus position was sub optimal? This looks to be something new in version 8.

    Answer: It is the new "filter initialization" which simply selects the filter. No attempt is made to restore focus like it did a few releases ago. That was a bad idea.


    [edit: changed hard-coded yellow text to [high]xxx[/high] (also the pencil icon on the advanced text editor toolbar) so can be seen on all themes (I use light colored Royal Flush)]

    [edit: separated the filter initialization question and answered it inline to avoid fracturing the thread]
    Attached Files Attached Files
    Last edited by Bob Denny; Aug 15, 2015 at 17:46.

  3. #3
    Join Date
    Nov 2007
    Location
    Australia
    Posts
    98

    Default

    ACP/Scheduler and FocusMax did the exact same thing to me tonight. AcquireStar failed and went to on to attempt focusing with star 2 of 3 (as star 1 failed). Scheduler simply ignores the state that FocusMax is in as soon as the focus failure occurs, which I must say is interesting to watch as they battle each other for telescope and camera control. It normally takes operator intervention to regain control. Stopping Scheduler and then stopping the autofocus run manually. In the scheduler engine log you can see I stopped the dispatcher a couple of times.

    A slightly different message from the previous post;

    20:51:17 AcquireStarAsync failed to get Posted Start Message

    I've enclosed the latest logs.

    ..and how's this for a quick focus! 7 seconds! What is really odd is that in the FocusMax log, nothing is displayed before 10:38:37s, so I wonder what happened.

    ACP console log opened 09-Aug-2015 10:38:16 UTC
    This is ACP version 8.0 (build 5, V8 Production Release A)
    Licensed to Jason Jennings
    10:38:30 (AF will use Monochrome readout mode)
    10:38:30 Starting FocusMax AcquireStar autofocus...
    10:38:36 FocusMax auto-focus successful!
    10:38:36 HFD = 2.92
    10:38:36 Focus position = 12770
    10:38:37 Autofocus finished.
    ACP console log closed 09-Aug-2015 10:38:38 UTC

    I don't know if what I'm experiencing are multiple issues on just one that is related to the two symptoms, being the communication breakdown between what FocusMax is doing and what ACP/Scheduler *thinks* FocusMax is doing.

    In summary, the two issues I see are;
    A) Scheduler Engine log highlights autofocus has failed when in fact autofocus completed successfully according to the FocusMax logs. This triggers Scheduler to reschedule an autofocus run asap when it is actually needed.
    B) When FocusMax AcquireStar does fail to focus on the first star and wants to select the second star to retry, ACP/Scheduler doesn't seem have knowledge of this and starts dispatching plans despite FocusMax trying to perform a focus run at the same time.

    I recall something similar with ACP 7 and FocusMax 4 but was under the impression it was addressed in ACP 8.
    Attached Files Attached Files

  4. #4
    Join Date
    Oct 2005
    Location
    Mesa, AZ
    Posts
    25,797

    Default

    I haven't done the detailed analysis yet, (but I will soon). I do believe you have spotted a bug. I think Scheduler is looking for focus completion (success or failure) and when it sees that, it moves on to its next task. I'll have to look at a different way to monitor AcquireStar completion (all I have is the status coming back from FocusMax via its API so it has to be something I can read externally).

    If you want to get work done, you can save your FMx system file then alter the AcquireStar settings to increase the chances of getting the focus done on the first try, or reduce the retries to 1, or switch off AcquireStar and let ACP pick the star and then do a single focus. You'll notice that Scheduler will retry the focus after the next Observation if the current focus fails.
    Last edited by Bob Denny; Aug 15, 2015 at 17:47.
    -- Bob

  5. #5
    Join Date
    Nov 2007
    Location
    Australia
    Posts
    98

    Default

    Thanks Bob. Apologies for delayed response. I'm currently abroad on business.
    Please start with the first post as part of your analysis. I have seen quite a few events where autofocus has successfully completed, yet Scheduler flags it as a failure in the engine log and wants to force another focus asap. This doesn't help with observing efficiency wanting to refocus all the time. The other condition is when an autofocus does indeed fail, Scheduler doesn't give FocusMax an opportunity to address it. This is perhaps the more critical one as it may be the initial focus for the start of the evening that fails which in turn results in an hour or two of out of focus data. The weather hasn't been cooperative to provide more logs but when it clears and send them through. What I've provided to date should be a good starting point however. Let me know if you need me to enable debugging or similar.

    Regards

  6. #6
    Join Date
    Oct 2005
    Location
    Mesa, AZ
    Posts
    25,797

    Default

    Ok, I'll do the best I can. Allow me to catch up with things over the weekend (it's Friday night now).
    -- Bob

  7. #7
    Join Date
    Oct 2005
    Location
    Mesa, AZ
    Posts
    25,797

    Default

    Quote Originally Posted by Jason
    Please start with the first post as part of your analysis.
    First focus"

    01-Aug-2015 08:37:36.2: ++ Auto Focus ++
    01-Aug-2015 08:37:36.3: Doing initial autofocus.
    01-Aug-2015 08:37:36.3: Start special ACP AutoFocus script for scheduler
    01-Aug-2015 08:45:01.6: Next periodic autofocus ASAP after 01-Jan-0001 00:30:00 UTC

    Succeeded and ACP knew it. Second focus:

    01-Aug-2015 08:45:12.6: ++ Auto Focus ++
    01-Aug-2015 08:45:12.7: Doing periodic autofocus.
    01-Aug-2015 08:45:12.7: Start special ACP AutoFocus script for scheduler
    01-Aug-2015 08:52:51.5: ** Autofocus failed (n=1), will retry ASAP after 0 min.

    08:52:45 FocusMax auto-focus successful!
    08:52:45 HFD = 2.77
    08:52:45 Focus position = 12684
    08:52:46 Autofocus finished.

    Succeeded but Scheduler thought it had failed. Third focus:

    01-Aug-2015 10:10:37.5: ++ Auto Focus ++
    01-Aug-2015 10:10:37.6: Doing periodic autofocus.
    01-Aug-2015 10:10:37.6: Start special ACP AutoFocus script for scheduler
    01-Aug-2015 10:18:46.9: ** Autofocus failed (n=2), will retry ASAP after 5 min.

    10:18:41 FocusMax auto-focus successful!
    10:18:41 HFD = 3.10
    10:18:41 Focus position = 12712
    10:18:42 Autofocus finished.

    Same deal. Will start with this.
    -- Bob

  8. #8
    Join Date
    Oct 2005
    Location
    Mesa, AZ
    Posts
    25,797

    Default

    Interesting... the linkage is through a file LastAFTime.txt that is supposed to be written and updated in Public Documents\ACPConfig every time ACP performs an AutoFocus. The above behavior, including the odd "ASAP after 01-Jan-0001 00:30:00 UTC" can be explained by a missing LastAFTime.txt file. Reading AcquireSupport.Autofocus(), it is impossible that the code that writes this file is not being executed, as the log reports

    10:18:41 FocusMax auto-focus successful!
    10:18:41 HFD = 3.10
    10:18:41 Focus position = 12712
    <--- The LasfAFTime file gets deleted and a new one written here --->
    10:18:42 Autofocus finished.

    There is some SuperDebug tracing in the Scheduler that will tell us if indeed this file is missing. Change the Scheduler to Extreme debugging (highest level) and run a night. Then post back with the log.

    If you can think of a reason this file would be wiped out or not created that might be a hint.
    -- Bob

  9. #9
    Join Date
    Nov 2007
    Location
    Australia
    Posts
    98

    Default

    Hi Bob,
    I have done as you've requested and ran some nights with extreme debugging enabled in Scheduler. I can't see how the LastAFTime.txt file gets deleted. In fact I think its safe to say that it doesn't get deleted. When I check the file properties, it was created 1-Aug-2015 which coincides when I upgraded from ACP 7 to ACP8. I have uploaded some of the scheduler logs for your reference. Could it be that it doesn't successfully get updated?
    Attached Files Attached Files

  10. #10
    Join Date
    Nov 2007
    Location
    Australia
    Posts
    98

    Default

    Hi Bob,
    I've had a few more occurrences where Scheduler simply doesn't acknowledge the status of FocusMax. A failed attempt such as slewing to a part of the sky that could be partly cloudy results in a failed attempt. AcquireStar attempt 2 or 3 are simply ignored by Scheduler. Scheduler just continues on its merry way, leaving FocusMax thinking it can now move to its 2nd star despite not having control of the mount or camera. Its rather interesting to see both ACP and FocusMax fight it out. Typically FocusMax fails completely not understanding what to do with platesolve point exposures, etc.

    I'm lost as to where to troubleshoot this next. Sure, I could go on at use ACP to select a star instead of AcquireStar as you suggest but I feel this is a cop out. Its only going to be a matter of time before someone else encounters the problem so may as well progress with troubleshooting until its resolved.
    Last edited by Jason Jennings; Aug 24, 2015 at 18:11. Reason: typo

 

 

Thread Information

Users Browsing this Thread

There are currently 1 users browsing this thread. (0 members and 1 guests)

Similar Threads

  1. Sync Scope failure...
    By Chris Brennan in forum Hardware/Software/Driver Topics Not Directly Related to Our Software
    Replies: 6
    Last Post: Jan 3, 2009, 00:37

Posting Permissions

  • You may not post new threads
  • You may not post replies
  • You may not post attachments
  • You may not edit your posts
  •