FocusMax run-time error 91

[Tom Krajci]

See attached jpeg. I have been getting this error over and over. Sometimes I can restart the system to work properly, but not tonight...four times in a row failure.

And this is the error I get in the plan-specific log for ACP:

01:44:53 Start slew to AY_Psc...
01:44:54 (wait for slew to complete)
01:44:55 (slew complete)
01:44:55 Target is now centered.
01:44:55 (long exp, no orbital tracking, trying to autoguide)
01:44:55 Switching from C to V filter for imaging
01:44:55 Focus change of 1 steps required
01:45:13 **Script Error (Tracking has been stopped)**
01:45:14 Source: FocusMax
01:45:15 Message: Application-defined or object-defined error at line 1236 column 5.
ACP console log closed 17-Feb-2011 01:45:22 UTC


Sometimes I get this error in the high-level log:

16-Feb-2011 01:52:04.3: Plan L1022_IRS has Monitor Mode. Time to resubmit it.
16-Feb-2011 01:52:04.3: Plan MIS_V1294 has Monitor Mode. Time to resubmit it.
16-Feb-2011 01:52:04.3: Plan V1647_ORI has Monitor Mode. Time to resubmit it.
16-Feb-2011 01:52:04.4: ++ Observatory Startup ++
16-Feb-2011 01:52:04.4: Startup attempted, but no StartupObs script found
16-Feb-2011 01:52:04.4: ++ Auto Focus ++
16-Feb-2011 01:52:04.4: Doing initial autofocus.
16-Feb-2011 01:52:04.4: Start special ACP AutoFocus script for scheduler
16-Feb-2011 01:55:40.2: Next periodic autofocus at 16-Feb-2011 15:55:40 UTC
16-Feb-2011 01:55:41.2: Dispatcher cycle time: 1.078125 sec.
16-Feb-2011 01:55:41.2: Acquire data for Observation MIS_V1294...
16-Feb-2011 01:55:41.2: (16 sets)
16-Feb-2011 01:55:41.3: Send Observation MIS_V1294 to ACP Sequencer
16-Feb-2011 01:55:41.3: WARNING: Failed to start ACP script (0)
16-Feb-2011 01:55:41.3: Observatory is currently in use
16-Feb-2011 01:58:07.5: Data acquisition failed for Observation MIS_V1294.
16-Feb-2011 01:58:07.5: (ACP reported Imager system failure. See run log.)
16-Feb-2011 01:58:08.0: Dispatcher cycle time: 0.296875 sec.
16-Feb-2011 01:58:08.0: Acquire data for Observation IRAS00470+6429...
16-Feb-2011 01:58:08.0: Send Observation IRAS00470+6429 to ACP Sequencer
16-Feb-2011 01:58:08.0: WARNING: Failed to start ACP script (0)
16-Feb-2011 01:58:08.0: Observatory is currently in use
16-Feb-2011 01:58:10.4: Dispatcher stopped at 16-Feb-2011 01:58:10 UTC
16-Feb-2011 01:58:10.4: **DISPATCHER INTERRUPT LEVEL 1 RECEIVED**
16-Feb-2011 01:58:35.7: REQUEST ABORTED: The dispatcher was interrupted and aborted this ACP run
16-Feb-2011 01:58:35.7: Data acquisition failed for Observation IRAS00470+6429.


FocusMax is 3.5.94. Acquire star works just fine under control of ACP (or manually)...but when it comes to the first filter change for an imaging plan (and use of a filter offset value)....things hang up and when I click on the error message box...FocusMax crashes and disappears.

What am I doing wrong?

Thanks in advance

[Dick Berg]

Works sometimes and fails other times? Here are some thoughts.

In the ACP log, these three lines tell us something.

01:44:55 Switching from C to V filter for imaging
01:44:55 Focus change of 1 steps required
01:45:13 **Script Error (Tracking has been stopped)**

The code being traversed is in the AutoFocus() part of AcquireSupport.vbs.

The first line comes out of AcquireSupport from the Function SetFilterForTask(), at the bottom of the function:
01:44:55 Switching from C to V filter for imaging

This line comes from AcquireSupport, in the Sub SetFilterOffset(), where the code first calls FocusMax to move the focuser its one step
01:44:55 Focus change of 1 steps required

Then there's an AWFULLY LONG period of time where nothing is happening before some process times out and throws an error.
01:45:13 **Script Error (Tracking has been stopped)**

What should be written in the log next, and way sooner than after 20 seconds, is
"Starting FocusMax AcquireStar autofocus..." (you're using FMx's AcquireStar, yes?)

and this is after the offset is done and after some further calls to FocusMax to set up various parameters for error recovery. We're talking about what should take only milliseconds between the last real log entry and the log entry that didn't get printed. There's no difference in this code from the AcquireSupport used in ACP vs AcquireSupport used in Scheduler.

I can see where it's gone awry, but I can't offer any solution here. I would suggest you reseat the connections between the computer and the focuser, especially if you find this works sometimes and not others. You probably don't remember if the focuser actually changed positions or not, but if it stalls, or if there's a lost connection, I could imagine the FMx driver timing out after a delay.

[Bob Denny]

Maybe it's just changing the focus per FilterInfo? Either way "fails sometimes" and "AWFULLY LONG" period of time before the error/stop sounds like hardware to me!

[Tom Krajci]

Maybe it's just changing the focus per FilterInfo? Either way "fails sometimes" and "AWFULLY LONG" period of time before the error/stop sounds like hardware to me!

Now I'm getting error messages all the time...and from what I can determine, I don't think it's hardware.

it's been a few weeks...here's where I stand with this one rig:

When I try and use FocusMax/AcquireStar, and ACP Scheduler periodic refocus, I get this sort of error:

ACP console log opened 10-Mar-2011 01:54:04 UTC
This is ACP version 5.1 (build 3, Maintenance release 5.1)
Licensed to Arne Henden
01:54:04 This is AcquireScheduler V3.2.2
01:54:05 Custom image file path/names are in use
01:54:05 Custom auto-flip parameters are in use
01:54:05 PreFlip=-360 PostFlip=0 AF=180 PU=60
01:54:06 Initializing AcquireSupport V5.1.17
01:54:06 Telescope is ACP->K35, driver V2
01:54:06 MaxIm DL/CCD is version 5.12
01:54:06 Imager is SBIG Universal
01:54:06 Guider is SBIG Universal(internal)
01:54:06 Calculated unbinned plate scales (arcsec/pix): H = 1.24 V = 1.24
01:54:06 Calculated field of view (arcmin): H = 21.2 V = 21.2
01:54:06 Using focus offsets from FilterInfo.txt
01:54:19 ACPS Observation #99 - UX_Ori
01:54:19 Pointing updates are enabled
01:54:19 Starting observation 1 for plan UX_Ori
01:54:19 Start slew to UX_Ori...
01:54:20 (wait for slew to complete)
01:54:28 (slew complete)
01:54:28 Doing auto-center...
01:54:28 Switching from V to C filter for pointing exposure
01:54:28 Focus change of -1 steps required
01:54:33 **Pointing update error from FocusMax:
Object variable or With block variable not set
01:54:33 Imaging to UX_Ori_R645_20110310_015433
01:54:33 Switching from V to R645 filter for imaging
01:54:33 Focus change of 4 steps required
01:54:38 Object variable or With block variable not set
ACP console log closed 10-Mar-2011 01:54:38 UTC


AcquireStar has been successfully completed, now it's time to run the first plan...must change filter....but I get a pointing update error from FocusMax?

How are filter changes and pointing updates associated?

I have reverted back to original versions of AcquireScheduler.VBS and AcquireSupport.wsc...but I get the same error.

I also get this error in the high-level log for every plan:

Log opened at Fri, Mar 04 2011 13:52:52 UTC (actual time)
Scheduler version 3.2.2
Multi-user license: Arne Henden
04-Mar-2011 13:52:52.8: Simulated clock initialized at 04-Mar-2011 13:52:52 UTC
04-Mar-2011 13:52:53.5: Loaded Constraint plugin AirMass
04-Mar-2011 13:52:53.5: Loaded Constraint plugin AirmassRange
04-Mar-2011 13:52:53.5: Loaded Constraint plugin Horizon
04-Mar-2011 13:52:53.5: Loaded Constraint plugin HourAngle
04-Mar-2011 13:52:53.5: Loaded Constraint plugin MoonAvoid
04-Mar-2011 13:52:53.5: Loaded Constraint plugin MoonDown
04-Mar-2011 13:52:53.5: Loaded Constraint plugin SkyCondition
04-Mar-2011 13:52:54.3: 34 plans are now pending.
04-Mar-2011 13:52:54.3: Attach ACP sequencer
05-Mar-2011 01:50:11.3: Dispatcher started at 05-Mar-2011 01:50:11 UTC
05-Mar-2011 01:50:11.3: Priority: W[0]=1.00
05-Mar-2011 01:50:11.3: Transit Altitude: W[1]=0.00
05-Mar-2011 01:50:11.3: Highest Altitude: W[6]=0.00
05-Mar-2011 01:50:11.3: Lateness: W[5]=0.70
05-Mar-2011 01:50:11.3: Slew Distance: W[2]=0.30
05-Mar-2011 01:50:11.3: Retry Count: W[3]=0.20
05-Mar-2011 01:50:11.3: Meridian Crossing: W[4]=0.30
05-Mar-2011 01:50:11.3: Obs Conditions: W[7]=0.40
05-Mar-2011 01:50:11.3: Rising Plan Delay: disabled
05-Mar-2011 01:50:11.8: Plan AT_Cnc has Monitor Mode. Time to resubmit it.
05-Mar-2011 01:50:11.9: Plan BI_Ori has Monitor Mode. Time to resubmit it.
05-Mar-2011 01:50:11.9: Plan CN_Ori has Monitor Mode. Time to resubmit it.
05-Mar-2011 01:50:11.9: Plan DY_Per has Monitor Mode. Time to resubmit it.
05-Mar-2011 01:50:11.9: Plan FS_Aur has Monitor Mode. Time to resubmit it.
05-Mar-2011 01:50:11.9: Plan HL_CMa has Monitor Mode. Time to resubmit it.
05-Mar-2011 01:50:11.9: Plan HS_0642+5049 has Monitor Mode. Time to resubmit it.
05-Mar-2011 01:50:11.9: Plan IW_And has Monitor Mode. Time to resubmit it.
05-Mar-2011 01:50:11.9: Plan KR_Aur has Monitor Mode. Time to resubmit it.
05-Mar-2011 01:50:11.9: Plan KT_Per has Monitor Mode. Time to resubmit it.
05-Mar-2011 01:50:11.9: Plan L1022_IRS has Monitor Mode. Time to resubmit it.
05-Mar-2011 01:50:11.9: Plan MIS_V1294 has Monitor Mode. Time to resubmit it.
05-Mar-2011 01:50:11.9: Plan PY_Per has Monitor Mode. Time to resubmit it.
05-Mar-2011 01:50:11.9: Plan RX_And has Monitor Mode. Time to resubmit it.
05-Mar-2011 01:50:11.9: Plan SDSS074545 has Monitor Mode. Time to resubmit it.
05-Mar-2011 01:50:11.9: Plan SY_Cnc has Monitor Mode. Time to resubmit it.
05-Mar-2011 01:50:11.9: Plan TW_Tri has Monitor Mode. Time to resubmit it.
05-Mar-2011 01:50:11.9: Plan TZ_Per has Monitor Mode. Time to resubmit it.
05-Mar-2011 01:50:11.9: Plan V368_Per has Monitor Mode. Time to resubmit it.
05-Mar-2011 01:50:11.9: Plan V513_Cas has Monitor Mode. Time to resubmit it.
05-Mar-2011 01:50:11.9: Plan WZ_CMa has Monitor Mode. Time to resubmit it.
05-Mar-2011 01:50:12.0: ++ Observatory Startup ++
05-Mar-2011 01:50:12.0: Startup attempted, but no StartupObs script found
05-Mar-2011 01:50:15.5: Dispatcher cycle time: 3.34375 sec.
05-Mar-2011 01:50:15.5: Acquire data for Observation IW_And...
05-Mar-2011 01:50:15.5: Send Observation IW_And to ACP Sequencer
05-Mar-2011 02:04:17.0: Acquisition time: 841.540375 sec.
05-Mar-2011 02:04:17.0: Data for Observation IW_And acquired successfully.
05-Mar-2011 02:04:17.1: Image Efficiency: 85.2%
05-Mar-2011 02:04:17.1: Cycle Efficiency: 99.6%
05-Mar-2011 02:04:17.2: Plan Z_Cam has Monitor Mode. Time to resubmit it.
05-Mar-2011 02:04:19.7: Dispatcher cycle time: 2.5 sec.
05-Mar-2011 02:04:19.7: Acquire data for Observation RX_And...
05-Mar-2011 02:04:19.7: Send Observation RX_And to ACP Sequencer
05-Mar-2011 02:04:19.8: WARNING: Failed to start ACP script (0)
05-Mar-2011 02:04:19.8: Observatory is currently in use
05-Mar-2011 02:18:19.4: Acquisition time: 839.666375 sec.
05-Mar-2011 02:18:19.4: Data for Observation RX_And acquired successfully.
05-Mar-2011 02:18:19.4: Image Efficiency: 85.5%
05-Mar-2011 02:18:19.4: Cycle Efficiency: 99.7%
05-Mar-2011 02:18:19.5: Plan Leo5 has Monitor Mode. Time to resubmit it.
05-Mar-2011 02:18:22.8: Dispatcher cycle time: 3.21875 sec.
05-Mar-2011 02:18:22.8: Acquire data for Observation TW_Tri...
05-Mar-2011 02:18:22.8: Send Observation TW_Tri to ACP Sequencer
05-Mar-2011 02:18:22.9: WARNING: Failed to start ACP script (0)
05-Mar-2011 02:18:22.9: Observatory is currently in use
05-Mar-2011 02:32:21.5: Acquisition time: 838.714625 sec.
05-Mar-2011 02:32:21.5: Data for Observation TW_Tri acquired successfully.
05-Mar-2011 02:32:21.6: Image Efficiency: 85.5%
05-Mar-2011 02:32:21.6: Cycle Efficiency: 99.6%
05-Mar-2011 02:32:21.7: Plan AH_Her has Monitor Mode. Time to resubmit it.
05-Mar-2011 02:32:21.7: Plan T_CrB has Monitor Mode. Time to resubmit it.
05-Mar-2011 02:32:24.7: Dispatcher cycle time: 3.03125 sec.
05-Mar-2011 02:32:24.7: Acquire data for Observation V513_Cas...
05-Mar-2011 02:32:24.8: Send Observation V513_Cas to ACP Sequencer
05-Mar-2011 02:46:25.8: Acquisition time: 841.023375 sec.
05-Mar-2011 02:46:25.8: Data for Observation V513_Cas acquired successfully.
05-Mar-2011 02:46:25.8: Image Efficiency: 85.3%
05-Mar-2011 02:46:25.8: Cycle Efficiency: 99.6%
05-Mar-2011 02:46:25.9: Plan V849_Her has Monitor Mode. Time to resubmit it.
05-Mar-2011 02:46:27.9: Dispatcher cycle time: 1.90625 sec.
05-Mar-2011 02:46:27.9: Acquire data for Observation MIS_V1294...
05-Mar-2011 02:46:27.9: Send Observation MIS_V1294 to ACP Sequencer
05-Mar-2011 02:46:28.0: WARNING: Failed to start ACP script (0)
05-Mar-2011 02:46:28.0: Observatory is currently in use
05-Mar-2011 03:03:09.4: Acquisition time: 1001.465625 sec.
05-Mar-2011 03:03:09.4: Data for Observation MIS_V1294 acquired successfully.
05-Mar-2011 03:03:09.4: Image Efficiency: 83.7%
05-Mar-2011 03:03:09.4: Cycle Efficiency: 99.8%
05-Mar-2011 03:03:11.5: Dispatcher cycle time: 2 sec.
05-Mar-2011 03:03:11.5: Acquire data for Observation KT_Per...
05-Mar-2011 03:03:11.6: Send Observation KT_Per to ACP Sequencer
05-Mar-2011 03:03:11.6: WARNING: Failed to start ACP script (0)
05-Mar-2011 03:03:11.6: Observatory is currently in use
05-Mar-2011 03:17:12.8: Acquisition time: 841.220875 sec.
05-Mar-2011 03:17:12.8: Data for Observation KT_Per acquired successfully.
05-Mar-2011 03:17:12.8: Image Efficiency: 85.4%
05-Mar-2011 03:17:12.8: Cycle Efficiency: 99.8%
05-Mar-2011 03:17:14.5: Dispatcher cycle time: 1.546875 sec.
05-Mar-2011 03:17:14.5: Acquire data for Observation V368_Per...
05-Mar-2011 03:17:14.5: Send Observation V368_Per to ACP Sequencer
05-Mar-2011 03:17:14.6: WARNING: Failed to start ACP script (0)

OK, not for every plan...but for most plans...but ACP Scheduler continues to run and I get the data.

If I configure the periodic refocus time interval to be zero in ACP Scheduler, then I no longer get the FocusMax/pointing update error. (But I have to manually perform the autofocus run and then manually start ACP Scheduler to take data.)

But I still get the 'failed to start ACP script' warning in the high level log.

What can I do to better troubleshoot and ID this strange behavior?

Thanks in advance.

[Bob Denny]

The first one will take some troubleshooting. The second one, WARNING: Failed to start ACP script (0) is Scheduler saying that, although the ACP script AcquireScheduler marked the observation as completed (or failed), and indicated that it (the script) had completed, when the scheduler tried to send the next observation to ACP and start AcquireScheduler again, ACP reported that it still had a script active. This shouldn't ordinarily happen. But it's OK, because Scheduler will wait a few seconds and try again. Since you see the warning only once, that means that the second time it tried ACP was really finished. The (0) is the number or retries minus one (I forgot to add 1 to the counter for display).

[Tom Krajci]

The first one will take some troubleshooting.

What do you want me to do? Add/enable more trace statements in AcquireScheduler.VBS?

The second one, WARNING: Failed to start ACP script (0) is Scheduler saying that, although the ACP script AcquireScheduler marked the observation as completed (or failed), and indicated that it (the script) had completed, when the scheduler tried to send the next observation to ACP and start AcquireScheduler again, ACP reported that it still had a script active. This shouldn't ordinarily happen. But it's OK, because Scheduler will wait a few seconds and try again. Since you see the warning only once, that means that the second time it tried ACP was really finished. The (0) is the number or retries minus one (I forgot to add 1 to the counter for display).

Did I goof in the configuration of ACP Scheduler? Should I increase the value for image download time? Or is there something else I should be tracking down?

Thanks in advance.

[Bob Denny]

I don't know. What could have changed to make it start happening? Software doesn't wear out or drift :-) So something changed. For tonight just ignore it, it's a soft failure that's being recovered from. Then tomorrow start looking at things to see what might have changed or ??? You didn't goof in the configuration. The Image Download Time is only used to estimate how long an Observation will take, during scheduling. It is not used in the actual timing with ACP.

If you can't find something then post back here and I'll look at the Scheduler/ACP synchronization code, and post in more detail what is going on (I don' t have it memorized, it's been years since I worked on that part of the code).

[Tom Krajci]

I don't know. What could have changed to make it start happening? Software doesn't wear out or drift :-) So something changed.

This is the newest rig (number seven) to come operational here. It's the 'baby' at Astrokolkhoz, so there is no long track record of smooth performance followed by the appearance of this weird behavior.

For these few weeks it's been running I've been beta testing various versions of FocusMax (which all run error-free on the other six rigs). This is also the only rig with an Optec TCF-S focuser...all others use MoonLite focusers.

This rig is the only Paramount up here...albeit a 10-year-old GT-1100S that I refurbished. (All other rigs are non-Paramounts...but all of them use TheSky6Pro/TheSkyControlledTelescope ASCOM driver)

OK, that's a rundown of the rigs/configuration here. I can't give you a history of this rig, but I know that after ACP Scheduler runs a periodic focus run (with AcquireStar)...pointing update error (huh?!) happens during first filter change for the first plan that is being executed. When I set the periodic focus time to zero (disable this feature)....rig runs fine all night...using filter offsets, making filter/focus changes, etc.

That's where I stand with this rig - puzzled that a filter offset/focus change invokes a pointing update error.

[Bob Denny]

OK, there are two separate problems here:

1. FocusMax Issues

This appears to be something within the focuser and/or its driver. Details:

01:44:55 Switching from C to V filter for imaging
01:44:55 Focus change of 1 steps required
01:45:13 **Script Error (Tracking has been stopped)**
01:45:14 Source: FocusMax
01:45:15 Message: Application-defined or object-defined error at line 1236 column 5.

FocusMax was asked to pass through a focus change to the focuser. It failed, probably due to the driver itself. The Message "application-defined or object-defined error" is coming from the focuser driver, through FocusMax, and being caught in ACP and logged.

01:54:28 Switching from V to C filter for pointing exposure
01:54:28 Focus change of -1 steps required
01:54:33 **Pointing update error from FocusMax:
Object variable or With block variable not set

In preparation for a pointing update (the reason for that in the error message) it wanted to move the focuser and failed. This time it appears that FocusMax completely lost its reference to the focus driver - "Object variable or With block variable not set". I'm guessing that the focus driver crashed and left FocusMax with a dead handle.

Conculsion: This is being caused by instability with the focuser and/or its driver.

2. Scheduler/ACP timing

As promised, I looked at the logic in Scheduler for submitting and monitoring the jobs it sends to ACP. It's actually quite simple. One thing is that Scheduler needs to see ACP saying "no script running" for 5 continuous seconds (checking once a second) before it really believes that ACP is finished. There are a couple of reasons for this that aren't iomportant here. What is important is that Scheduler is seeing this and then somehow a few seconds later seeing that ACP is running a script! Something about the image acquisition process is causing ACP to drop its "script running" flag for a few seconds then raising it again for a few more seconds, at the end of a run. I can't imagine what that could be. Maybe this will light a bulb in yhour mind?

[Tom Krajci]

1. FocusMax Issues


01:54:28 Switching from V to C filter for pointing exposure
01:54:28 Focus change of -1 steps required
01:54:33 **Pointing update error from FocusMax:
Object variable or With block variable not set

In preparation for a pointing update...

What pointing update?

I have AcquireStar configured so that no pointing update is done at any time during the focus run. There is no need for a pointing update because the mount points well enough in the blind...so it's not enabled in AcquireStar.

Looking inside AcquireScheduler.VBS, there's a section in SubMain() that has these remarks/comments:

'
' If AutoFocus requested, do it now. AutoFlip before doing it
' if needed. 4.2 -- SUP.AutoFocus() -never- does a return
' slew pointing update. So we always do it.

Interesting. I've got the pointing updates turned off in AcquireStar....but AcquireScheduler says it's always gonna do a pointing update.

There is only one place in AcquireScheduler.VBS where this text string is found: Console.PrintLine "**Pointing update error from " ...and it's found in the nested IF/Then/Else clauses that deal with pointing updates. This section of the code starts with:

If Not repeatObs Or bNeedPostAFPtgUpd Then

I don't think I need a post autofocus pointing update...but in the previous code that variable must be set to true.

Here's the previous code that is hard-wired to say that I need a pointing update:

bNeedPostAFPtgUpd = False                                       ' True if we do an AF here, for PtgUpd
    If OBS.AutoFocus Then                                           ' If AF requested
        If Prefs.AutoFocus.Enabled Then                             ' And enabled in ACP
            If PREFLIPMARGIN > 0 Then z = PREFLIPMARGIN Else z = 0  ' Ignore negative PREFLIPMARGIN
            AutoFlipIf (NOMINALAFTIME + NOMINALPUTIME + z), OBS.Name, _
                                   OBS.RA, TargetRARate, _
                                   OBS.Dec, TargetDecRate, OBS.PA   ' Note we add PtgUpd time here to avoid flip before post-AF update
            Call SUP.AutoFocus(OBS.RA, OBS.Dec)                     ' Focus now (most errors non-fatal)
            bNeedPostAFPtgUpd = True
            Console.PrintLine "KR bNeedPostAFPtgUpd = True"
        Else
            Console.PrintLine "**Autofocus requested, but it is disabled in ACP, skipped"
        End If
    End If

Could this be the source of the conflict...AcquireScheduler wants to (always) do a pointing update, but AcquireStar is set up to avoid performing any pointing updates?

(In AcquireStar you can use a centering exposure to start the focus run - I've got that option selected as 'none'. I have disabled the post-focus pointing update by not enabling PinPoint within AcquireStar. This is how it's set up on all scopes here.)

Perhaps I can alter the logic in AcquireScheduler.VBS to set bNeedPostAFPtgUpd to false instead of true? (That does not ID or fix the source of the error...but it may sidestep the issue and give me a working rig?)