See this Comm Center message by Lloyd Smith, and the attached zip file with logs. After an autofocus, for some reason ACP appears busy to ACP for 20 sec. Then the dispatcher successfully starts another Observation in ACP, yet the scheduler engine logs a bunch of warning messages!



15-Feb-2015 08:42:12.6: Acquire data for Observation M81 IFN Short...

15-Feb-2015 08:42:12.6:   (belongs to Project M81 IFN Short, Plan M81 IFN Short-B 120s (1-30))

15-Feb-2015 08:42:12.6: ACP Last AF Time 15-Feb-2015 07:10:19 UTC

15-Feb-2015 08:42:12.6: Send Observation M81 IFN Short to ACP Sequencer

15-Feb-2015 08:42:12.7: WARNING: Failed to start ACP script (0)

15-Feb-2015 08:42:12.7: Observatory is currently in use

15-Feb-2015 08:42:17.5: WARNING: Failed to start ACP script (1)

15-Feb-2015 08:42:17.5: Observatory is currently in use

15-Feb-2015 08:42:21.5: WARNING: Failed to start ACP script (2)

15-Feb-2015 08:42:21.5: Observatory is currently in use

15-Feb-2015 08:42:26.2: WARNING: Failed to start ACP script (3)

15-Feb-2015 08:42:26.2: Observatory is currently in use

15-Feb-2015 08:42:31.0: WARNING: Failed to start ACP script (4)

15-Feb-2015 08:42:31.0: Observatory is currently in use



15-Feb-2015 08:42:36.0: WARNING: Request sent to busy ACP (AcquireScheduler)

15-Feb-2015 08:43:36.1: WARNING: Request sent to busy ACP (AcquireScheduler)

15-Feb-2015 08:44:36.1: WARNING: Request sent to busy ACP (AcquireScheduler)

15-Feb-2015 08:45:38.3: WARNING: Request sent to busy ACP (AcquireScheduler)

15-Feb-2015 08:46:41.7: WARNING: Request sent to busy ACP (AcquireScheduler)

15-Feb-2015 08:47:45.0: WARNING: Request sent to busy ACP (AcquireScheduler)

15-Feb-2015 08:48:45.5: WARNING: Request sent to busy ACP (AcquireScheduler)

15-Feb-2015 08:49:45.6: WARNING: Request sent to busy ACP (AcquireScheduler)

15-Feb-2015 08:50:48.7: WARNING: Request sent to busy ACP (AcquireScheduler)

15-Feb-2015 08:51:49.5: WARNING: Request sent to busy ACP (AcquireScheduler)

15-Feb-2015 08:52:49.5: ACP data acquisition failed for Observation M81 IFN Short.

15-Feb-2015 08:52:49.5:   (Observation M81 IFN Short interrupted by ACP sequencer problem.)

15-Feb-2015 08:52:50.6: ACP Last AF Time 15-Feb-2015 07:10:19 UTC




In the gap the run on ACP is successfully started. Then at 8:52 it thought that the run had ended unsuccessfully but the ACP log shows it continuing until 10:17 when it got a weather alert!

 

  
SVN Comment
 
 

  
Author
  
rbdenny
 
 

  
Repository
  
svn+ssh://rbdenny@a2_svn_dc3/home/rbdenny/svn/astro/acp
 
 

  
SVN Revision
  
780
 
 

  
Affected files
  
/trunk/Util.cls (Modified)

 
 

  
Check-in comment
  
Clean up locking logic in Util.RunScript()
GEM:1304

 

Wow, this was laying there for so long! There is a timing hole in ACP where, even though ACP raises an error, the script gets started successfully. This is by the nature of the RunScriptAsync() etc. So in the for-loop, besides checking for the weather script, it needs to see if the running script is the one that was requested, and if so drop out with success. Holy s**t. Note that the error coming back is OBS_LOCKED. How did that happen with Scheduler in charge? The Observatory is locked by Observatory Operator for all Scheduler runs...

I can't escape the conclusion that ACP successfully started the script, and then raised the "Observatory is Currently in Use" error instead of returning normally from Util.RunScript(). HOW??



Moving this to ACP.

I see what happened, but not why. It actually successfully started AcquireScheduler




ACP console log opened 15-Feb-2015 08:42:31 UTC
This is ACP version 7.2 (build 5, V7.2a Production Release Sep 2014)
Licensed to Lloyd Smith
08:42:31 This is AcquireScheduler V3.7.1




which ran happily along, but still reported




15-Feb-2015 08:42:31.0: WARNING: Failed to start ACP script (4)
15-Feb-2015 08:42:31.0: Observatory is currently in use




then after that, it correctly reported 





15-Feb-2015 08:42:36.0: WARNING: Request sent to busy ACP (AcquireScheduler)




until the 15 count loop terminated and RunScript() returned false. It was downhill from there!!