Description of the Event
During fully automated operation AstroMain's Job Executor froze at 22:41 whilst it was making pointing corrections on the Abell 55 Target (5/30).

This wasn't known until 00:59 when the Observatory Session was checked and it was found that the program was displaying 'Jogging..' message associated with the first locate frame from Abell 55. A target that should have been all done and completed by 23:04. There was no indication of anything happening.
Screen capture below.

Job Queue frozen on "Jogging..." whilst waiting for a telescope jog to finish Screen capture at 00:59 of AstroMain Program still apparently in the process of making pointing correction for Abell 55. (Logs show Jog N was commanded at 22:41)

It was unclear what had happened, but it was hypothesized that the job executor has called a TheSky6  Telescope.Jog method, but execution had failed to return from the method for some reason.

 The AstroMain program interface itself was not frozen and it was possible to click the 'Abort Target' button and put the Session Mode back to Manual and then move back to Fully Automated.   It was noticed that the telescope was not connected in TheSky and it was possible to get a confirmed connection from clicking the 'Establish Link' button.  At some point the Job Executor/ObsManager returned to life at 01:01 and messages were displayed saying the JogN operation had been taking longer than expected (an understatement !). The camera then proceeded to take a second locate frame for the Abell 55 target at 01:08 and began trying to link it in TheSky but failed (it turned out not to have any RaDec coordinates in its header).

Observatory Restart

It was decided to restart the system.  The telescope was parked via button on the POTH.Hub window, and its power turned off using Pegasus UPB Software.  AstroMaim, TheSky CCDSoft and other observatory software was then closed down and a rogue TheSky background processes killed using Task Manager.

Observatory software was then restarted (using a single launch button in AstroLaunch), power to the telescope was turned on  again and the Session resumed in AstroMain that included establishing new connections to the Dome and Telescope. The original observing plan was reloaded and the queue recommenced. Execution passed over the 9 targets that should have been imaged whilst the Queue was frozen, and began imaging IC 1029 (16/30). The rest of the session proceeded normally in respect to telescope control (slewing, jogging,  plate solutions etc).  


- recovery seemed possible by moving Session to Manual and then moving back to Fully Automated,
  but unable to connect to Telescope in TheSky,
  Upon restarting the Job,  the Job Executor suddenly began linking the image it had from 2 hours before.
  Decided to abort things
- Finally,  elected to Park the scope and shutdown the majority of the Observatory Software and start again.

Analysis
Log file shows that when centering the 1st Locate Image for Abell 55 (5/30) at 22:41 the Telescope completed a 9.28' Jog W operation but when it came to a 3.4' Jog N operation  (Telescope.Jog task in JogQSO/JogN )  execution didn't return from the call to 'Telescope.Jog' and execution of the queue effectively hung.

This type of issue has happened before and seems to occur when TheSky is called to perform a telescope action but somehow looses its connection to POTH Telescope during the operation, and doesn't return control to the calling program.   Because of this special IamAlive routines are used to record that the executor is about to call a method that may not return and specify a checktime to indicate the point at which the method is taking too long to complete and can be presumed to have hung.

In case of the Jog N operation the code is as follows

IamAlive(ThisRoutine(), "JogN", "Telescope.Jog", dNorth * 5)
Telescope.Jog(dNorth, "North")
IamAlive(ThisRoutine(), "Continue", "", 0)

Other code back in Obs.Manager main loop spots when a IamAlive Operation record hasn't been closed off with a following IamAlive 'Continue' record, before its check time. At the moment the code recognises and report that an Operation has just overrun its expected time by 5s / by 5 mins / by 10mins.

 If RunningFrameJobs And Now() > IamAliveData.CheckTime Then

 ' Report Problem with Job Executor
 ' --------------------------------
  With IamAliveData

    If .bWarningReported = False And .Operation <> "" Then
      ReportComment2B(Tab2 + "Obs.Manager", "Warning", .Operation + " task in " + .Routine + "/" + .Section + " is taking a long time?")
      .bWarningReported = True
    End If

    If .bSecondWarningReported = False And .Operation <> "" And Now() > .CheckTime.AddMinutes(5) Then
      ReportComment2B(Tab2 + "Obs.Manager", "Warning", .Operation + " task in " + .Routine + "/" + .Section + " is taking a very long time")
     .bSecondWarningReported = True
        ' <<< actions to add ?
    End If

    If .bFrozenQueueReported = False And Now() > .CheckTime.AddMinutes(10) Then
      ReportComment2B(Tab2 + "Obs.Manager", "Warning", "Job Queue appears to be frozon. ")
      ReportComment2B(Tab2 + "Obs.Manager", "Warning", "Last IamAlive message was from "
        + .Routine + "/" + .Section + "/" + .Operation + .AliveTime.ToString("HH:mm"))
      .bFrozenQueueReported = True
       ' <<< actions to add ?
    End If
  End With
End If

Logs record the preceeding IamAlive executing at 22:41:23.78, but this is the last message to be logged until 01:01 or so. The following IamAlive 'Continue' message was never executed. It would be expected that Obs.Manager should have issued messages that the JogN operation was taking longer than expected at the CheckTime , CheckTime + 5 mins, and CheckTime + 10mins. In this case the Jog operation would  have been associated with a check time that was 47secs after the Jog was started (from 3.4 * 5  + 30).

However these message didn't appear at the expected time.   Instead the message suddenly all appeared together at 01:01 just after Abort Target // Return to Manual Mode was initiated.

Observatory Mode                        2019-08-26 01:01  (Local)
  Obs.Manager                 Warning   Telescope.Jog task in JogQSO/JogN is taking a long time?
  Obs.Manager                 Warning   Telescope.Jog task in JogQSO/JogN is taking a very long time
  Obs.Manager                 Warning   Job Queue appears to be frozon. 
  Obs.Manager                 Warning   Last IamAlive message was from JogQSO/JogN/Telescope.Jog22:41

It isn't understood why the messages weren't shown within a 10-15 minutes of the originak Jog task, rather than 140 minutes later

The fact the message were issued one after the other in a fraction of a second suggest that one of the criteria to the reporting code (in ObsManger's Main Loop) was blocking entry to code. This would
  i) RunningFrameJobs being false,   
  ii) something was caused an exception in main loop that prevented execution reaching the IamAlive Check Lines
  iii) else that was stopping Obs.Manager main loop from executing.

RunningFrameJobs is set to false during  'RunTakeFramesJobQSO' if the routine determines that the Job Queue has no targets or there are no targets selected , or at the very end of 'RunTakeFramesJobQSO' when the Job has been finished. Neither apply to this situation.

If an exception was occuring then the exception messages would have sent to the logfile, but there are no such messages.

It is concluded the Obs.Manager had somehow become frozen, probably because it tried to interrogate the Telescope object and like the Job Executor / Telescope.Jog, it stalled waiting for exectution to return.

After the Job Executor was triggered back to life (by execution returning from the Telescope.Jog call), a second locate frame was taking which failed plate solution.  The log file has an unusual  catch #Temp4a1 Fits CENTALT message.

01:08:06.39 | Abell 55     Info TakeLocateImage | Locate Image No. 2
..
01:08:15.63 | Abell 55     Ok   TakeImage       | IamAlive: ImageReview
01:08:15.69 | catch #Temp4a1 Fits CENTALT
01:08:15.88 | Abell 55     Ok   TakeImage       | Exposure Time 5s (Recorded FITS Exposure Time 5s)

Catch occurs in TakeImage routine when attempting to get Altitude from the FIT Image Header :

Try
   fits_centalt = Val(Image.FitsKeyword("CENTALT"))
   calc_airmass = ComputeAirMass(fits_centalt)
Catch e As Exception
   WriteLogFile("catch #Temp4a1 " + "Fits CENTALT")
End Try

It would seem this was caused by the failure of CCDSoft to find out where the telescope was pointing and thus the telescope altitude associated with the  Image wasn't not stored as a keyword entry.

Risks
It's not totally possible to be sure about all the risks associated with this issue. However some reasonable assertions can be made.

Rain damage to Observatory & Equipment ?   NO
Assuming that the Obs.Manager had frozen, then it would imply that it wouldn't have been able to respond to developing cloud and start of rain to order a closure of the Observatory Shutter. However protection against rain damage would still be provided by AstroGuard and CloudSensor Relay, which would still operate to command a closure of the Shutter.
ie there should be no risk

Damage to Telescope / Telescope Cables ?   POSSIBLY
Assuming that the Obs.Manager had frozen, then it would imply that it wouldn't have been able to respond to the telescope movinbg close to North position where cables could begin to be wrapped around the pier.   In theory protection against telescope/cable damage would still be provided by AstroGuard which can suspend telescope tracking or move telescope back to a safe location. However the problem with TheSky and its telescope connection could possibly have prevented AstroGuard from operating the scope.

Actions
Consider the above information and see what can be done to ensure Obs,Manager stays active in such an event.   A frozen Job Queue shouldn't be allowed to lead to a freezing of the Obs.Manager Main Loop.

>> Add something to logfile record the passing of 5s cycles of the main loop. In this way it can be seen if the Obs.Manager freezes.
   (during a 6 hour session this would generate 4320 extra rows in the log file. The S684 session log file already had 11700 rows.).

>>

Plots illustrating the 40 minute anomaly in Clarity values from the Cloud Sensor. The drop in Clarity values clearly didn't represent a change in sky conditions as there is no change in the brightness/character of AllSky Image or the number of bright stars that are automatically counted.

Portion of Night Summary Plot showing Clarity anomaly between 01:53 and 02:33

Portion of Cloud Sensor Plot showing Clarity & Sky Temp anomaly between 01:53 and 02:33

There have also been anomolous spikes in Clarity, for example session 2019-09-07 (Anomaly in Cloud Sensor Clarity readings, S691)

Other Similar Anomalies in Clarity Sensor Reading Portion of Night Summary Plot  (2019-09-07, S691)

Portion of Cloud Sensor Plot showing Clarity & Sky Temp anomaly between 01:53 and 02:33

Plots illustrating the effect of dew heating on OTA temperature.  These include new graphs just added to AstroWeather 1.7.3

 

Temperature Plot at 21:20 (below) Outside Temp (white line) falls steadily through the late afternoon. It then falls more rapidly from around 19:40  to 20:30 (just before Sunset at 20:24). Had it reached dew point ? UPB Env Temp (purple line) and OTA Temp (orange line) also fall steadily through the afternoon. Importantly we can see that the Dome Observatory is nicely loosing the heat built up during the day. (Former wooden Roll-Off Roof Observatory was much slowly to lose its heat.) UPB Env Temp sits close to the Outside Temp., but OTA Temp is 1 to 1.5°C lower. (having been much closer to the UPB Env Temp at ~13:00) Other data shows that OTA Temp reached the UPB Env Dew Point at 19:30 Dew Heaters turned on at 19:40 at 90% power. OTA Temp rapidly rises. Within 20 mins it matches UPB Env Temp and after 1.5 hours it is sitting 1°C higher than the UPB Env Temp. (The timing of the rise in OTA Temp and the fall in Outside Temp is not considered to be linked in any direct way, its just a coincidence in timing)

Temperature Plot at 06:25 (below) Outside Temp (white line) bounces around 14°C from 22:30 to 01:30 but then falls to reach a low of 12°C around 06:00. UPB Env Temp (purple line) consistently around 1 to 1.5°C higher than outside temperature. Dew Heaters turned down to 50% at 21:40. (outside of graph range)  OTA Temp (orange line) falls to that of the UPB Env Temp by 22:30 and roughly falls that of UPB Env Temp until 01:50 when Dew Heater turned up to 80% or so. OTA Temp climbs above UPB Env Temp over next 30 minutes. Observatory closed at 04:52.  OTA Temp reaches 1°C higher than UPB Env Temp by 06:00.

Dew Point Depression Plot at 12:25 High Humidity (96%) through the night lead to fairly a flat lying Outside DPD (Outside Temp-DewPoint , White Line) of  ~0.6°C from 04:30 to 07:30 Dew Heater running through the niight keeps the OTA's DPD (OTA Temp-DewPoint, Orange Line) well above the Outside Dew Point. Observatory closed at 04:52. Sunrise at 05:56.  Dew Heaters turned off at 06:50.   OTA temperature falls whilst the outside temperature and outside Dew Point start to rise OTA DPD falls and reaches 1 to 2°C below Outside DewPoint from 07:40 to 09:40. Formation of dew on telescope at this time is quite likely. and suggests that the dew heater should be kept on for longer in the mornings. (UPB Env Dew Point reading are invalid when Humidity is 97% plus, but at around 09:30 where UPB Env Dew Point becomes valid again the OTA Temp is sitting up to 0.5°C below the local Dew Point)

Temperature Plot for whole of session S684