Issue

1) Job Execution had to wait a long time for CCD Camera Cooling to stablise & timed out after 5 minutes (22:55)

2) An inappropriate set point temperature of -25°C was set (one that camera cooling couldn't reach given the ambient temperature)

Description

WIth CCD Camera initially connected with a set point temperature of -15°C, ( vs Ambient Temperature of 6°C) and then moved to -20°C , whilst waiting for CCD Temperature to stabilise ahead of Centering Target 1/17 (AT2023tsk), CCDTemp monitor announched that CCD Temperature would be lowered to -25°C. 

The camera didn't seem to make any progress below -22°C  and as -25°C didn't look to be achievable temperature as that would be 31°C below ambient it was decided by user to update the Set Point Temperature back to -20°C (this was after 'Propose' temperature utility suggested only -15°C) .

Even though CCD Temperature dropped back to -20°C and seemed to be stabilised at this temperature the job executor continued to wait until the loop timed out after 5 mins.

Other cases with confusing CCD Temperature decisions have been seen in 2 or 3 other sessions. 

Analysis

• A time line has been established .

  22:53:30   Check   CCD Cooler          Alert   | Av. Cooler Power (59.3%) is below Lower Threshold (60%)
  22:53:39   Change  CCDSetPoint         Info    | CCD Temperature SetPoint has been lowered to -20.0 degC (22:53)
  22:53:39   WaitOn  Camera.CCD Cooler   Info    | Wait for CCD Temperature Stabilisation is deferred until start of the next CCD image

  22:55:12   WaitOn  Camera.CCD Cooler   Info    | Waiting for CCD Temperature (-19.1) to stabilise at new set point (-20.0°C)
  22:55:12.  Change  CCDSetPoint         Info    | CCD Temperature SetPoint has been lowered to -25.0 degC (22:55)
  22:55:21   Check   CCD SetPoint        Info    | CCD Temperature Set Point has changed to -25.0 degC

  22:57:08   Request Cam1.SetPointChange Info    | User request to update Camera1 SetPoint Temperature
  22:57:21   Check   CCD SetPoint        Info    | CCD Temperature Set Point has changed to -20.0 degC

• A summary of ambient temperature, CCD Temperature and Cooling Power based on the Monitor log (which records data every 2 mins) is shown below along with points where Set Point temperature changed.

  22:38:54 7.6 -13.1  100    Set Point -15
  22:40:54 7.5 -16.5   60    "
  22:42:54 7.4 -15.2   59    "
  22:44:54 7.5 -15.2   61    "
  22:46:54 7.4 -15.2   60    "
  22:48:54 7.4 -14.8   58    "
  22:50:54 7.3 -14.8   60    "
  22:52:54 7.3 -14.8   58    "
  22:53:39                   Set Point -20
  22:54:54 7.3 -18.7  100    "
  22:55:12                   Set Point -25
  22:56:54 7.2 -21.3  100    "
  22:57:21                   Set Point -20
  22:58:54 7.2 -20.4   69    "
  23:00:54 7.1 -20.0   76    "
  23:02:54 7.0 -20.0   76    "
  23:04:54 7.0 -20.0   76    "
  23:06:54 6.9 -20.0   75    "
 

• Need to investigate the hypothesis that CCD Monitor believed that  temperature needed to go back to -15°C, but raise/lower were mixed up and it requested  -25°C instead ?  Code shows that set point was set to -25°C in ChangeCameraSetPoint() routine (reported by "CCD Temperature SetPoint has been lowered to -25.0°C (22:55)" and performed using code Camera.TemperatureSetPoint = Camera.TemperatureSetPoint - 5.0 and this happened when the CcdMonitor.bLowerSetPoint flag was raised.  Hypothesis is that it should have been CcdMonitor.bRaiseSetPoint flag that should have been raised ?.  The only place that CcdMonitor.bLowerSetPoint flag is set to true is if the following conditions are true:
     MinutesSince(PhaseStartTime) > SettlingMins + GraceMins OrElse (MinutesSince(PhaseStartTime) > 8
  AndAlso CCDCamera.CoolerPower > 95 AndAlso CcdTempIsAcceptable = False) and AvCoolerPower > UpperPowerLevel
  and it doesn't seem that a mistake has been made
   
• A further hypothesis was that after lowering the SetPoint from -15 to -20°C the bLowerSetPointFlag somehow remained in place and wasn't reset ? allowing the SetPoint to  to be unexpectedly lowered again from -20 to -25°C. However the code clearly reset the  bLowerSetPoint flag to False after the set point temperature is lowered.

Conclusion

• T

Actions:

• AstroMain. Continue to investigate & fix
  To do  2024-03-31+ (AstroMain 3.67.3+).
   

Issue

1. Operations including Image linking and Slew Monitoring ran very slowly and in case of image linking failed during a 50 min period (02:11 to 03:02)
    
2. ObsOverseer mistook slow Job Execution as being a frozen Job Queue and ordered a CCDSoft/SBIG Camera restart (02:21 & 02:45 )
    
3.  Two consecutive targets failed with 'RPC Server is unavailable' exceptions following issues during Locate Frame Linking / CCDSoft Restart (02:22 & 02:45).
   

The issues resulted in 2 out 17 planning targets failing (fortunately the issue resolved itself)

Description

Around the time that two consecutive targets 11/17 (NGC 3690 w/SN2023wrk) and 12/17 (NGC 4216 w/SN2024gy) failed with "RPC server is unavailable" exceptions a number of strange things were happening , with Image linking running very slowly & failing and Slew Monitoring having 7-15s gaps in both scope & dome positions.

The following timeline describes the key events during this time.  The problem period seems to begin around 02:11 during Target 11/17 and last until 03:02 during Target 13/17.



 02:09:51  Slew to Target 11/17 (NGC 3690) started. Slew reporting was normal
 02:11:17  Imaging linking of Locate Frame 1 (#1201074) took a very long time (546s total) and failed without finding a match. 
           (during later linking of the Reduced Image, image linking took just 4s !) .
 02:21:52  ObsOverseer judged that the Job Queue was frozen and ordered a CCDSoft/SBIG Camera Restart in
           an 'attempt to fix locked thread'
           (this was an incorrect assessment, the job queue was in fact just running but very slowly)
 02:22:19  'RPC server is unavailable' exception
 02:22:50  Target Failed
 
 02:33:05  Slew to Target 12/17 (NGC 4216) started
 02:33:12  Reporting of Scope Path & Listing of Dome Path 'held up' for 10s interval
 02:33:22  Reporting of Scope Path & Listing of Dome Path 'held up' for 15s interval
 02:34:03  Imaging linking of Locate Frame 1 (#1201075) failed due to too few stars 
 02:35:01  Imaging linking of Locate Frame 2 (#1201076) took a very long time (386s total) and failed without finding a match. 
           (during late linking of the Reduced Image, image linking took just 1s !) .
 02:45:34  ObsOverseer judged that the Job Queue was frozen and ordered a CCDSoft/SBIG Camera Restart in
           an 'attempt to fix locked thread'
           (again this was an incorrect assessment, the job queue was in fact just running but very slowly)
 02:45:38  'RPC server is unavailable' exception
 02:46:33   Target Failed

 02:55:23  Slew to Target 13/17 (NGC 3206) started
 02:55:32  Reporting of Scope Path & Listing of Dome Path 'held up' for 7s interval
 02:55:40  Reporting of Scope Path & Listing of Dome Path 'held up' for 15s interval
 02:56:52  Imaging linking of Locate Frame 1 (#1201077) took a long time (288s total) but did eventually succeed
           (during late linking of the Reduced Image, image linking took just 1s !) .
 02:35:01  Imaging linking of Locate Frame 2 (#1201078) was normal, taking just 3s and find a match. 

           Rest of session normal.....

Analysis

• It was initally hypothesised that the Computer was slowed down by some Windows activity or other and that AstroMain and other Astronomy programs were being significantlly slowed down but analysis shows that this wasn't the case  through analysis of logs during the slew to Target 12/17 (NGC 4216).
   
• Logs from the MeadeGeneric and PulsarDome drivers shows a normal sequence of activity during the slew to Target 12/17 (02:33:05 to 02:33:38) and show they are both operating completely normally, this doesn't support the idea that programs were being slowed up by USB/Comms or CPU restrictions.
   
• DeviceHub.Telescope & DeviceHub.Dome logs for AstroGuard connections show Ra/Dec, Az  messages at a usual rate of once every 5s are present through the slew and indicate that Device Hub program is operating normally.  
   
  The DeviceHub.Telescope log for PHD2 connection shows no activity at this time but this is expected as Guiding wasn't active at this time.
   
• DeviceHub.Telescope log for TheSky6 connection shows that after the SlewToCoordinatesAsync command at 02:33:08, RA/Dec messages only being recorded  for a 1-2s interval (02:33:22 to 02:33:23) during the slew, before resuming after slewing at 02:33:38.  Normally there are Ra/Dec message to TheSky6 every 1s throughout the slew as TheSky6 updates the Telescope poistion in TheSky6's virtual view.
   
• The DeviceHub.Telescope Log for AstroMain connection shows the expected level of messaging during the slew (every 0.2s), there are no gaps, during the 'apparent' hold up times at 02:33:12- 02:33:22  and 02:33:23-02:33:38  and the RA/Dec, Az/Alt values are ticking over every 1s or so.  Similarly the DeviceHub.Dome Log for AstroMain connection shows a normal level of messaging no gaps and with dome az ticking over every 0.5 - 1.0s.   but there are small 1s gaps or so every 2-3s.  (is this indicating a conflict between Slew Monitoring and ObsMonitor ?)
   
  The gaps in Scope/Dome Path monitoring can't be easily explained as they get their data from DeviceHub.Telescope and DeviceHub.Dome not through ThySky6.  However the correspondance between the gaps in the logging of Scope/Dome Path  and the absence of Ra/Dec message to the TheSky at this time suggest that there is a depandance, such that a hold-up in AstroMain's TheSky6Monitor is causing a hold-up in
  
• DeviceHub.Telescope log for TheSky6 connection shows that after the SlewToCoordinatesAsync command at 02:33:08, RA/Dec messages only being recorded  for a 1-2s interval (02:33:22 to 02:33:23) during the slew, before resuming after slewing at 02:33:38.  Normally there are Ra/Dec message to TheSky6 every 1s throughout the slew as TheSky6 updates the Telescope poistion in TheSky6's virtual view.
   
  This points to an issue with TheSky6 at this time.
   
• There were no issues with the taking any of Locate Frames using CCDSoft/SBIG camera at this time and given that the image frames were completely normal (and capable of later image linking), that there were no issues with AstroMain CcdCamera object at this time and that neither of the two CCDSoft/SBIG Camera restarts fixed the problem it can be concluded that the issue didn't lie with CCDSoft/SBIG Camera in anyway.

Conclusion

• The root cause is most likely a glitch in TheSky6 program caused by some unknown factor (TheSky6 update check ?) which slowed down the update of telescope coords during slewing, temporarily slowed/blocked access to TheSky.Telesope from AstroMain, and prevented successful image linking by CCDSoft/TheSky6, but was one that eventually resolved itself (after 50 mins or so).
   
• AstroMain Scope/Dome Path Monitoring during a slew appears to be dependant on TheSky6 in unexpected way.
   
• The ObsOverseer logic that it had detected a frozen Job Queue was invalid . It failed to recognise that ImageLinking task was simply just slow, but not frozen.
   
• ObsOverseer action to Restart CCDSoft/SBIG Camera was unnecessary on this occasion and led in part to the situation where 'RPC Server is unavailable' exception occured.
   
• Job Queue should have paused or have been made to pause whilst Restarting CCDSoft & SBIG Camera.

Actions:

• Job Queue. Job Queue (specifically during image linking task) should flag up that it is still alive at a more frequent rate, so that ObsOverseer doesn't make the conclusion that the Job Queue is frozen when it's not. This might need a special 'IamAlive message so that Job Queue/Image Linking doesn't produce a high number of log messages.  Currently the expected duration of entire ImageLink process is set to 120s meaning that Task will be overdue after 150s (expected duration + a 30s grace), and ObsOverseer will deem an OverDue conition as being a frozen Job Queue. The entire ImageLink process for Target 11/17 took 596s. with the longest element taking 248s, so 120s expected duration is clearly too small.    Fixed in AstroMain 3.67.1 by updating expected duration to 250s and adding a new RefreshIamAliveTime() routine which resets the currently  defined IamAlive.AliveTime =Now() and updates the .CheckTime when called, with calls to RefreshIamAliveTIme added before/after each Locate Frame element:  AttemptFailSafeLink(), SolvePlateWithTheSky(), DoImageLink(), SolvePlateWithASTAP(). As RefreshIamAliveTime is placed with loops the individual InsertWCS attempt might take less than 120s, however duration is left at new value of 250s.
  Done 2024-03-28 (AstroMain 3.67.1).
   
• ObsOverseer. If JobQueue gives IamAlive message at higher frequency it won't lead to ObsOverseer concluding the JobQueue is frozen, but in principal the ObsOverseer should act if there is truely a case where JobQueue is frozen.  Have the selection of the appropriate action, Restart CCDSoft/SBIG Camera vs Restart TheSky6 should be better worked.    Implemented in AstroMain 3.67.1  RestartTheSky is tried after 6 minutes if the IamAliveData.Section = "LinkImage".
  Done 2024-03-28+ (AstroMain 3.67.1).
   
• JobQueue/ObsOverseer. If CCDSoft/SBIG Camera is to be restarted there should be appropriate preparation to ensure that the JobQueue is paused during the Restart Operation in order to ensure that Job Queue or other activity doesn't try to access the Camera whilst it is being restarted.   Pausing the job queue in order to RestartCCDSoft is part of a larger requirements review into  Pausing the Job Queue for various purposes (user, required queued maintainance task). Preparatory coding for this has included in AstroMain 3.67.3)
  Closed 2024-03-28+ (AstroMain 3.67.3).