Incident
Just after the session had started and the scope had begun the 'first' target (Target 3/39, GCVS S Cyg) and had taken the first 120s V Frame, the Job Queue unexpectedly aborted at 19:49 .

Since there were no alternate checkbox options specified on the Manager Tab, the Obs.Manager took the default action of moving the Session State to 'Closing'., shutting down the Observatory and finishing the session (19:53).     Session was restarted at 20:13

Timeline
19:29 Session Started,  Camera and Telescope Connected
19:29 Equilibration Started
19:34 FocusScope Near Zenith started
19:39 Focus attempt ended (unable to focus scope as TCF-S had been set at a position too far from Focus Posistion)
19:40 Job Queue started (19:40:23).
19:40 Passed Target Azmiuth Check (59° Az/ 88.5° Alt)
19:40 Telescope slewed to 3/39 GCVS S Cyg
19:41 Dome Azimuth Alert (Dome Az 139.8°, is 81.3° different from scope)
19:41 Centering operations started
19:41 4 locate frames taken, each of which linked, but centering attempts had trouble reducing the pointing error    (2.53', 4.11', 3.09' ,1.02')
19:44 Attempt made to autofocus scope (failed QC checks at 19:47:14)
19:47  Began autoguiding (but star lost during settle period)
19:48 Began taking 120s V frame
19:49 Observatory Alert saying that "Telescope has moved beyond Az 349°"
19:49 Telescope Tracking set to OFF.
19:49 Message given that 'Telescope will be moved to a safe position'
19:49 120s V frame finished. Guiding Monitor reported RMS guiding error of 40.5" for first image (Guide 20%, Lost 80%)
19:49 Job Queue aborted (19:49:50)
19:49 "Script Aborting / Script aborted by 'user') messages reported
19:49  Session Closing
19:50  Shutter Closed
19:51  Dome Parked
19:53 Telescope Parked
19:53  Session Finished

Analysis
Obs Pics show the Scope slewing towards the correct position for S Cyg scope at target start time ( ~  Az 59° 11' / Alt 89° 32' )

The message reporting that Dome Aziuth is 81.3° different from scope after the slew although looking anomolous is simply a side effect of the scope pointing at 89° altiutude (ie very close to zenith (89°) and the dome doing its best to given maximum clear vision for the scope.

The observatory alert saying that Telescope had moved beyond Az 349° is anomalous / totally unexpected.  Why would this message appear when scope was pointing at a target near Az 59 ?
Examining Obs Pictures show the scope steadily moving from Az 59° to Az 0° at 19:49.  Again this is anomalous / totally unexpected. How can this happen ?
Playing back the path of GCVS S Cyg in the TheSky6 virtual sky show that target did indeed move quickly in Azmiuth during this time interval as it move rapidly past the zenith position. 

Once the target had moved past Az 0° and entered the azimuthal risk area between 349° and 360° it missed earlier warning early alerts (intended for the zone between 345° and 349°) and directly triggered the 'Beyond 349' Telescope Safety Alert and action  to Turn Off Telescope tracking at 19:49:34, raise flag to abort the Job Queue and slew to a 'Safe Position' at Az 245°, Alt 10° , to avoid cable wrapping around the pier.

ObsPic at 19:50 shows the scope at the Az 245°, Alt 10° position, before slewing to the Park Position at Az 180°.

Conclusion
The aborting of the job queue and subsequent observatory shutdown and session finish can be fully explained.  

Whilst the Obs.Manager responded as per design, the incident highlights a key flaw in the design of the Hard Az Limit protection currently adopted used (not only by AstroMain but also by AstroGuard and AstroPlan) .   Whilst it is intended to avoid the scope moving from 349° to beyond 360° to avoid cable wrap this risk only applies when the scope has physically moved around the Celestrial Pole and is pointing in NNW-N direction. The protection is clearly unnecessary when the scope is pointing to positions near zenith and south of the celestrial pole.

Action

• Hard Az Limit protection needs to modified in AstroMain, AstroGuard and AstroPlan so that it doesn't apply/execute for sky positions lying between  Zenith and the Celestrial Pole.
  ie not to positions with Alt > value of Latitude (57°). In practice a threshold Alt of 65° will be used.
  Fixed 2019-10-13 (AstroMain 3.14.5, AstroPlan .1.12.8 & AstroGuard 1.2.8)
  

 

Background/Aim

There are two issues that peristently occur  with the Telescope.Jog operation using the LX200 Telescope
a)  Rogue jogs affecting 1 in 170 or so jogs (where the scope might move some 30-40 arc minutes away from the intended target, rather than move closer to the target)
b)  Hanging of the job queue execution whilst it waits endlessly for execution to return from a call to TheSky6's Telescope.Jog method

Whilst a workaround for the first issue was been put in place, the second issue is still a major problem as it can lead to the loss of an entire night of automated operation/imaging.

Over 5.5 hours were lost from this session (S709) for example
- on the first occasion (22:52) the problem was spotted at 23:25 and the Observatory Software/Session were restarted.
- on second occasion (01:54) the problem wasn't noticed until  morning check at 06:45.

There is no information to indicate why Telescope.Jog sometimes hangs (it is assumed to be due to some conflict where the telescope TELEAPI driver is being asked to do two tasks at the same time.  POTH should be coordinating communicating to/from the scope handling requests from the various POTH.Scope clients operating concurrently TheSky/TeleAPI,  AstroMain, AstroGuard, PHD2 )

Since there is a way to recognise when the frozen Telescope.Jog call has hung, the hope is that there is a way to come up with a practical workaround that will be to release the hung call, in a as graceful manner as possible that allows operations to continue.   A glimmer of hope is provided in the Report, Log and Session Event records that show when interventation is made the Job Queue execution does proceed, somehow a release to the Jog is occuring.  Aim is to find out precisely what is the trigger that releases the hung call, and then workout how to utilise it in a workaround which also controls the behaviour the AstroMain and TheSky programs with things destablising the system.

Analysis.

Log file from Incident at 22:52 

22:51:05.93 | GCVS BL Lac                Pointing Check        Info   | Attempting Pointing Check (CalculatePointingErrorQSO)
22:51:05.93 | GCVS BL Lac                Target Coords (2000)  Data   | RA= 22 02 18.971 Dec= +42 14 04.00 | Epoch 2000
22:51:05.93 | GCVS BL Lac                Image Coords (2000)   Data   | RA= 22 02 13.960 Dec= +42 14 10.58 | Epoch 2000
22:51:05.93 | GCVS BL Lac                Pointing Check (Image)Data   | Object Offset:   [W: 5.43', N: -2.49'] 5.97 arc mins
22:51:05.93 | GCVS BL Lac                Pointing Check (Image)Data   | Pointing Error:  [W: 0.93', N: 0.11'] 0.93 arc mins
22:51:05.93 | GCVS BL Lac                Pointing Check (Image)Data   | Correction Requir[W: -0.93', N: -0.11'] 0.93 arc mins
22:51:05.93 | GCVS BL Lac                Apply JogWAdj         Info   | JogWAdj=1.42'
22:51:05.93 | GCVS BL Lac                Start                 Ok     | IamAlive: JogQSO
22:51:05.93 | GCVS BL Lac                                             | 
22:51:05.93 | GCVS BL Lac                Jog                   Data   | Net Jog    W: 0.49', N: -0.11'
22:51:05.93 | GCVS BL Lac                Making Jog            Info   | 0.50 arc mins (W= 0.49', N= -0.11')
22:51:05.93 | GCVS BL Lac                Telescope.GetRaDec    Ok     | IamAlive: JogQSO, PreJogPosition
22:51:05.99 | GCVS BL Lac                Continue              Ok     | IamAlive: JogQSO
22:51:05.99 | GCVS BL Lac                Making W Jog          Info   | W= 0.49' (0.66' at Dec 42.4)
22:51:05.99 | GCVS BL Lac                Telescope.Jog         Ok     | IamAlive: JogQSO, JogW
22:51:19.84 | GCVS BL Lac                Continue              Ok     | IamAlive: JogQSO
22:51:19.84 | GCVS BL Lac                Telescope.Jog         Ok     | IamAlive: JogQSO, JogW
22:51:38.79 | GCVS BL Lac                Continue              Ok     | IamAlive: JogQSO
22:51:38.79 | GCVS BL Lac                Jog                   Info   | Sleeping For 2.0 secs
22:51:40.81 | GCVS BL Lac                Making S Jog          Info   | N= -0.11'
22:51:40.81 | GCVS BL Lac                Telescope.Jog         Ok     | IamAlive: JogQSO, JogS        < Execution Hung Here

23:26:17.23 | --------------------------------------------------------------------------------------------------
23:26:17.23 | Observatory                Stop Services         Try    | Stopping Observatory Services
23:26:17.23 | Observatory Services       Stop CloudSensor      Ok     | Service stopped
23:26:17.23 | Observatory Services       Stop WeatherStation   Ok     | Service stopped
23:26:17.23 | Observatory Services       Stop ObsWorker        Ok     | Service stopped
23:26:17.33 | Observatory Services       Stop UiChecker        Ok     | Service stopped
23:26:17.45 | Observatory Services       Stop ObsManager       Ok     | Service stopped
23:26:17.45 | Observatory Services       Stop Scorecard        Ok     | Service stopped
23:26:17.45 | Observatory Services       Stop TelePosition     Ok     | Service stopped
23:26:17.45 | Observatory Services       Stop ObsEnv           Ok     | Service stopped
23:26:17.45 | Observatory Services       Stop DomeMonitor      Ok     | Service stopped
23:26:17.59 | Observatory Services       Stop AscomDome        Ok     | Service stopped
23:26:17.67 | Observatory Services       Stop ObsOverseer      Ok     | Service stopped
23:26:17.78 | Observatory Services       Stop AscomScope       Ok     | Service stopped
23:26:17.79 | Observatory Services       Stop Phd2             Ok     | Service stopped
23:26:17.79 | Observatory Services       Stop ObsMonitor       Ok     | Service stopped
23:26:17.79 | Observatory Services       Stop TempMonitor      Ok     | Service stopped
23:26:17.79 | GCVS BL Lac                Continue              Ok     | IamAlive: ImageTargetT_CentreTarget 
                                                                         < Execution Begun Again Here
23:26:17.81 | GCVS BL Lac                CenterTarget          Ok     | IamAlive: ImageTargetT_QSO            
                                                                        ( may be caused by Abort or Stopped Services)
23:26:17.86 | Job Executor               Abort                 Info   | Job Queue has been aborted           
                                                                         < Job Queue recorded as aborted Here
23:26:17.86 | GCVS BL Lac                SetScopeMode          Info   | Setting Scope Mode to Waiting (Mode 2)
23:26:17.92 | GCVS BL Lac                StopPHD2Guiding       Info   | Checking PHD2 App State (Result=)    
                                                                         < Job Queue Tidying Up Here
23:26:17.92 | GCVS BL Lac                Stop PHD2 Guiding     Try    | Stopping PHD2 Capture & Guiding      
23:26:18.06 | Observatory Services       Stop Focuser1         Ok     | Service stopped
23:26:18.07 | Observatory Services       Stop UPB.Switch       Ok     | Service stopped
23:26:18.07 | Observatory Services       Stop UPB.Environment  Ok     | Service stopped
23:26:18.07 | Observatory Services       Stop UPB.Focuser      Ok     | Service stopped
23:26:18.12 | GCVS BL Lac                StopPHD2Guiding       Info   | Checking PHD2 App State (Result=)
23:26:18.15 | Job Executor               Finish TakeFrameJobsQSOInfo  | Setting RunningFrameJobs to False & Finishing Thread
23:26:38.71 | --------------------------------------------------------------------------------------------------

This shows that the Job Queue beginning to move again 23:26:17.79.   Indicating that some trigger was applied to release the Telescope.Jog.

The timings make it unclear if the trigger was
a)  the stopping of one of the observatory services from 23:26:17.23 to 23:26:17.79 (such as Obs.Manager at 23:26:17.45 or AscomScope at 23:26:17.78 ) or
b) Aborting of the Job Queue (at or just before 23:26:17.86). It is unclear is this was
   b1) a user activated abort (via Screen Button) or
   b2) a Obs.Manageractivated abort during a final cycle through its loop. (in response to a.)

Obs.Manager can abort the Job Queue using 'AbortJobExplicit', or abort just the current target using 'AbortTargetExplicit'.  Both have the interesting feature that they terminate any active slewing

            ' Terminate Telescope Slewing
            ' ---------------------------
            If objScope.Slewing Then
                ObservatoryManager.SetSlavingOff()
                objScope.AbortSlew()
            End If

            If objDome.Slewing Then
                ObservatoryManager.SetSlavingOff()
                objDome.AbortSlew()
            End If

It doesn't seem the AbortTargetExplicit was used as the Job Executor exited out of the whole TakeFrameJobs procedure at 23:26:18:1

Looking at the Report Messages :

 Applying JogW Adjustment    Ok        JogWAdj=1.42'
  Jogging ...                 

---

Observatory Mode                        2019-10-12 23:25  (Local)
  Obs.Overseer                Warning   Telescope.Jog task in JogQSO/JogS is taking a long time? (22:52)
  Obs.Overseer                Warning   Telescope.Jog task in JogQSO/JogS is taking a very long time  (22:57)
  Obs.Overseer                Warning   Job Queue appears to be frozen. (23:02)
  Obs.Overseer                Warning   Last IamAlive message was from JogQSO/JogS/Telescope.Jog at 22:51
  Setting Mode ...            Ok        Manual

---

Stop Observatory Services               2019-10-12 23:26  (Local)
  Cloud Sensor:               Ok        Stopped
  Weather Station:            Ok        Stopped
  Observatory Manager:        Ok        Stopped
  Scorecard:                  Ok        Stopped
  TelePosition:               Ok        Stopped
  ObsEnv:                     Ok        Stopped
  Dome Monitor:               Ok        Stopped
  POTH.Dome:                  Ok        Stopped
  POTH.Telescope:             Ok        Stopped
  PHD2 Client                 Ok        Stopped
  Observatory Monitor:        Ok        Stopped
  TempMonitor:                Ok        Stopped
  Focuser1:                   Ok        Stopped
  ( Jogging ... )             Failed    Exception in JogQSO: No connection. Error code =  200 (0xc8).
  Acceptance test ...         Passed    Pointing within 1.0 arc mins
Script Aborting ...           
  PowerBox Switch:            Ok        Stopped
  PowerBox Env:               Ok        Stopped
  PowerBox Foc2:              Ok        Stopped
Script Aborting ...           Aborted   (Script aborted by user)

We can see execution going into Jogging at 22:51 but only coming out at around 23:26+ when the Telescope.Jog failed with the exception 'No connection. Error code=200' which explain the normal post jog 'IamAlive (Continue)' message is missing from the log file.

Whilst the Obs.Overseer has the appearance of picking up on the overdue Telescope.Jog operation (22:52 and 22:57), the messages only appeared at 23:25 (and when they did they both appeared at the same moment. This would indicate that the Obs.OverSeer was hung  between 22:52 and 23:25.     But what is hung itself.   The log files show the Obs.Manager was active throughout this period.  So it seems it was the ReportQueue which was hung and then only released when the Observatory Mode was set to manual at 23:25

Log file from Incident at 01:54

01:53:52.74 | GCVS DX Cnc                Pointing Check (Image)Data   | Pointing Error:     [W: 10.40', N: -8.07'] 13.16 arc mins
01:53:52.74 | GCVS DX Cnc                Pointing Check (Image)Data   | Correction Required:[W: -10.40', N: 8.07'] 13.16 arc mins
01:53:52.76 | GCVS DX Cnc                Apply JogWAdj         Info   | JogWAdj=0.54'
01:53:52.76 | GCVS DX Cnc                Start                 Ok     | IamAlive: JogQSO
01:53:52.76 | GCVS DX Cnc                                             | 
01:53:52.76 | GCVS DX Cnc                Jog                   Data   | Net Jog    W: -9.87', N: 8.07'
01:53:52.76 | GCVS DX Cnc                Making Jog            Info   | 12.74 arc mins (W= -9.87', N= 8.07')
01:53:52.76 | GCVS DX Cnc                Telescope.GetRaDec    Ok     | IamAlive: JogQSO, PreJogPosition
01:53:52.87 | GCVS DX Cnc                Continue              Ok     | IamAlive: JogQSO
01:53:52.87 | GCVS DX Cnc                Making E Jog          Info   | W= -9.87' (-11.04' at Dec 26.7)
01:53:52.87 | GCVS DX Cnc                Telescope.Jog         Ok     | IamAlive: JogQSO, JogE
01:54:02.53 | Observatory (autodew)      Set DewHeaters        Ok     | Setting dew heaters to 98%
01:54:14.62 | GCVS DX Cnc                Continue              Ok     | IamAlive: JogQSO
01:54:14.62 | GCVS DX Cnc                Jog                   Info   | Sleeping For 2.0 secs
01:54:16.64 | GCVS DX Cnc                Making N Jog          Info   | N= 8.07'
01:54:16.64 | GCVS DX Cnc                Telescope.Jog         Ok     | IamAlive: JogQSO, JogN

06:58:03.60 | **************************************************************************************************
06:58:03.60 | Observatory Manager        Change State          Info   | Session Pending
06:58:03.62 | **************************************************************************************************
06:58:03.62 | Observatory Manager        Change State          Info   | Session Initiating (NightDate: 2019-10-12)
06:58:03.63 | Observatory Manager        ObservingPlan         Info   | Importing Observing Plan
06:58:28.06 | Observatory Manager        Plan                  Info   | Loading Latest Observing Plan
06:58:28.06 | Observatory Manager        Plan                  Info   | Latest Plan: 2019-10-12   V3   BEST PLAN           
06:58:28.59 | **************************************************************************************************
06:58:28.59 | Observatory Manager        Change State          Info   | Session Starting
06:58:28.66 | Observatory Manager        Camera                Info   | Connecting Camera
06:58:29.76 | Observatory Overseer       Write LatestReport    Ok     | File Written
06:58:29.78 | Observatory Overseer       Write LatestLog       Ok     | File Written
06:58:30.51 | Observatory (autodew)      Set DewHeaters        Ok     | Setting dew heaters to 98%
06:58:31.70 | Observatory Services       Start TempMonitor     Ok     | Service already started
06:58:31.70 | Observatory Manager        Telescope             Info   | Connecting Scope (TheSky6)
06:58:35.78 | GCVS DX Cnc                SetScopeMode          Info   | Setting Scope Mode to Connected (Mode 8)
06:58:38.80 | GCVS DX Cnc                objScope.Tracking     Ok     | IamAlive: SetTrackingOff, TurnOffTracking
06:58:39.82 | GCVS DX Cnc                Continue              Ok     | IamAlive: SetTrackingOff
06:58:39.82 | Observatory Manager        Telescope             Info   | Set Tracking OFF
06:58:40.79 | Observatory Overseer       Check UserInterface   Alert  | UI is Pending
06:58:40.79 | Observatory Overseer       Check ObsManager      Alert  | Obs.Manager is Frozen
06:58:44.79 | Observatory Overseer       Check UserInterface   Alert  | UI is Not Responding
06:58:44.79 | Observatory Overseer       Check ObsManager      Alert  | Obs.Manager is Frozen
06:58:49.79 | Observatory Overseer       Check UserInterface   Alert  | UI is Not Responding
06:58:49.79 | Observatory Overseer       Check ObsManager      Alert  | Obs.Manager is Frozen

This shows that the Job Queue beginning to move again 06:58:35.78 some 5 hours after the original freeze, indicating that some trigger caused the release of the Telescope.Jog.
It would seem that the trigger was the act of Connecting the Scope at 06:58:31.70 (4 secs before the queue started), rather than Setting Tracking off at 06:58:39.82 (4 secs after queue started again)

It can be seen the User Interface and the Obs.Manager both freeze at around 06:58:40.   
So whilst the trigger released the stuck queue, the consequences on this occasion were apparently far from graceful.

Report Messages associated with 01:54 incident :

  Applying JogW Adjustment    Ok        JogWAdj=0.54'
  Jogging ...                 

---

Observatory Mode                        2019-10-13 06:54  (Local)
  Obs.Overseer                Warning   Telescope.Jog task in JogQSO/JogN is taking a long time? (01:55)
  Obs.Overseer                Warning   Telescope.Jog task in JogQSO/JogN is taking a very long time  (02:00)
  Obs.Overseer                Warning   Job Queue appears to be frozen. (02:05)
  Obs.Overseer                Warning   Last IamAlive message was from JogQSO/JogN/Telescope.Jog at 01:54
  Setting Mode ...            Ok        Manual

---

Observatory Mode                        2019-10-13 06:57  (Local)
  Setting Mode...             Ok        Fully-Automated

---

Session Pending                         2019-10-13 06:58  (Local)
  NightDate:                  Ok        2019-10-12        (NightDate)

---

Session Initiating                      2019-10-13 06:58  (Local)
  NightDate:                  Ok        2019-10-12        (NightDate)
  Import Observing Plan...

---

Create Observing Plan                   2019-10-13 06:58  (Local)
  Request Observing Plan...   Ok
  Generate Night Plan...      Ok        Schedule Builder has completed
  Selecting Plan...           Ok        2019-10-12   V3   BEST PLAN   (Plan ID: 391)
  Retrieving Targets ...      Ok        28 Targets. 
  Reading Start Time...       Ok        2019-10-12 19:29  (Scheduled StartTime, Local)

---

Session Starting                        2019-10-13 06:58  (Local)
  Session:                    Ok        2019-10-12        (NightDate)

---

Connect Camera                          2019-10-13 06:58  (Local)
  Connecting camera...        Ok
  Temperature Regulation...   Ok
  Temperature Set Point...    Ok        -20 °C
  TempMonitor:                Ok        Already active

---

Connect Telescope                       2019-10-13 06:58  (Local)
  Establishing link...        Ok
  Telescope Coords...         Ok        Az: 148.4, Alt: 56.6

---

  Turn Off Tracking..         Ok        Telescope Tracking is OFF

---

Connect PHD2 Guiding Software           2019-10-13 06:58  (Local)
  - Profile                   Yes       ZWO ASI178MC         (ID: 1)
  - Camera                    Yes       ZWO ASI178MC         (Connected)
  - Mount                     Yes       POTH->LX200GPS/R (AS (Connected)
  - Aux Mount                 No        
  - Calibration               Yes       
  - Binning & Pixel Scale     Ok        1, 1.03132 arc sec/px

---

Setting Up Session                      2019-10-13 06:58  (Local)
   (Jogging ...)              Failed    Exception in JogQSO: No connection. Error code =  200 (0xc8).

Script Aborting ... 

Different steps were taken after setting observatory mode to Manual. Instead of stopping observatory services the session was placed back in to Fully Automated Mode.

We can see execution going into Jogging at 01:54 but only coming out at around 06:58 when the Telescope.Jog again failed with the exception 'No connection. Error code=200'

It would seem that the trigger was the connection of the scope just beforehand, possibly associated with turning the telescope tracking off.

 Again we see delayed Report Messages, with messages series of 4 message from the Obs.Overseer at  01:55 - 02:00 only getting written to the ReportFile at 06:54.

Conclusion

The precise trigger to release the hung Telescope.Jog is still uncertain and there may not be a single trigger, but the analysis suggests some possible ways forward to try when the Job Queue is in this positions next time:

- Abort Slewing
- Turn Off Tracking
- Reconnect Telescope
- Disconnect/Reconnect Tracking is already in the code to try

Action

• Repeat test, but modified so Dome is Slaved to Telescope position, an image is taken between each set of jogs, and (replaced by a test frame) is image linked.  Placing max pressure on TheSky / POTH
  

Background/Aim

A special daytime test session was conducted to look at Telescope.Jog operation using the LX200 Telescope, following two ongoing issues with Telescope Jogs
a)  Rogue jogs affecting 1 in 170 or so jogs (where the scope might move some 30-40 arc minutes away from the intended target, rather than move closer to the target)
b)  Hanging of the job queue execution whilst it waits endlessly for execution to return from a call to TheSky6's Telescope.Jog method

Whilst a workaround for the first issue was been put in place, the second issue is still a major problem as it can lead to the loss of an entire night of automated operation/imaging.

Method

A simple routine (JogTesting).  The routine loops round at 60s intervals and makes call to the standard 'JogQSO' routine, commanding a random jog  (up to +/12' N, up to +/-6' W) which is the typical size of jog movements during live centering operations.  JogQSO makes calls to Telescope.Jog with the requested Jogs. The routine also compares the apparent movement of the scope with the jogs requested.  Any scope position discrepancies more than >3 arc min are noted and recorded as 'rogue jogs' . A corrective jog is applied to rogue jogs of between 3 and 60' in order fix the issue and achieve the required target centering.

The routine was made to act as a proxy for the normal Job Queue Executor (TakeFrameJobs_QSO) , by setting the RunningFrameJobs flag to True

The Obs.Overseer process monitored the execution by keeping tags on IamAlive Timeouts and looking specifically where pre-jog IamAlive 'Doing Telescope.Jog' message was not followed by post-jog  IamAlive 'Continue' message within a specified time interval  (something like 50-60s), indicating that the Execution was frozen.   If the task overruns by more than 10 minutes,  new code is designed to disconnect TheSky.Telescope and then reconnect in the hope of releasing the hung call to Telescope Jog.

Results

The test ran from 12:38 to 17:56 (5.3 hours), during which 199 calls to JogQSO where made (i.e. around 400 calls to Telescope.Jog).

During this time there was one instance of a rogue jog. 
- At 16:34, the telescope was commanded to jog 8.6' east,  4.3' south,  but it actually moved 46' east, 4.2' south.  This is typical of behaviour seen during live sessions
- Frequency of rogue jogs was less than commonly seen during live sessions but it is significant that it was repeatable under test conditions

There were no instances where the job execution froze whilst waiting for Telescope.Jog to return
 - This might be because the TheSky/Telescope was having a good day, or the test didn't emmulate a live session sufficiently well.
-  As there were no instances of the Telescope.Jog hanging it was not possible to test the code designed to resolve the condition

Conclusion

The testing of specific code designed to workaround  the Telescope.Jog hang was not achieved.
The overall jog test may either not have run long enough to produce an instance of the hang condition or the conditions didn't emmulate a live test sufficiently well.

Action

• Repeat test, but modified so Dome is Slaved to Telescope position, an image is taken between each set of jogs, and (replaced by a test frame) is image linked.  Placing max pressure on TheSky / POTH
  

Background/Aim

A special daytime test session was conducted to look at Telescope.Jog operation using the LX200 Telescope, following two ongoing issues with Telescope Jogs
a)  Rogue jogs affecting 1 in 170 or so jogs (where the scope might move some 30-40 arc minutes away from the intended target, rather than move closer to the target)
b)  Hanging of the job queue execution whilst it waits endlessly for execution to return from a call to TheSky6's Telescope.Jog method

Whilst a workaround for the first issue was been put in place, the second issue is still a major problem as it can lead to the loss of an entire night of automated operation/imaging.

Testing on the previous day had shown one instance of 'Rogue Jogging' but no instances of the Telescope.Jog hanging issue, which prevented the testing of code designed to resolve the hung task.  It was unclear if the  jog test may either not have run long enough to produce an instance of the hang condition or the conditions didn't emmulate a live test sufficiently well.

The test was therefore repeated today but modified so Dome is Slaved to Telescope position, and an image is taken and (a subsitute of night sky) linked  between each set of jogs, placing max pressure on TheSky / POTH

Method

A simple routine (JogTesting).  The routine loops round at 30s intervals and makes call to the standard 'JogQSO' routine, commanding a random jog  (up to +/12' N, up to +/-6' W) which is the typical size of jog movements during live centering operations.  JogQSO makes calls to Telescope.Jog with the requested Jogs. The routine also compares the apparent movement of the scope with the jogs requested and any scope position discrepancies more than >3 arc min are noted and recorded as 'rogue jogs' . A corrective jog is applied to rogue jogs of between 3 and 60' in order fix the issue and achieve the required target centering.

The routine was made to act as a proxy for the normal Job Queue Executor (TakeFrameJobs_QSO) , by setting the RunningFrameJobs flag to True

The Obs.Overseer process monitored the execution by keeping tags on IamAlive Timeouts and looking specifically where pre-jog IamAlive 'Doing Telescope.Jog' message was not followed by post-jog  IamAlive 'Continue' message within a specified time interval  (something like 50-60s), indicating that the Execution was frozen.   If the task overruns by more than 10 minutes,  new code is designed to disconnect TheSky.Telescope and then reconnect in the hope of releasing the hung call to Telescope Jog.

Results

The test ran from 12:01 to 17:42 (5.7 hours) during which 268 calls to JogQSO where made (i.e. around 536 calls to Telescope.Jog)

During this time there was 3 instances of a rogue jog. 
- At 13:55, the telescope was commanded to jog 10.7' west, 3.7' south, but it actually moved 0.5' east, 3.7' south. 
- At 15:10, the telescope was commanded to jog   9.3' west, 1.7' south, but it actually moved 27.7' east, 1.7' south
- At 17:25, the telescope was commanded to jog   2.2' west, 5.5' north, but it actually moved 35.3' east, 5.3' north
- This equates with a frequency of 1 rogue jog per 178 jogs, which is very similar to frequency measured during live sessions.

There were no instances where the job execution froze whilst waiting for Telescope.Jog to return.
Given the test environment was made as close to a live session as possible with the limits of daytime testing and the vey large number of jog operations it is surprising that not
 - This might be because the TheSky/Telescope was having a good day, or the test didn't emmulate a live session sufficiently well.
-  As there were no instances of the Telescope.Jog hanging it was not possible to test the code designed to resolve the condition

Conclusion

The testing of specific code designed to workaround  the Telescope.Jog hang was again not achieved.
It would be nice to think the problem has simply gone away (the issue wasn't seen during the 3.9 hour session S710 on 2019-10-15).

Action

Suspend further daytime testing, and move effort to just trying  out alternate workarounds / strategies when the problem next crops up during a live session

On attempting to use SharpCap in order to reinvigorate wider view colour imaging and luner imaging I found that my SharpCap Pro license  (necessary for accessing python scripting) had expired on the Observatory Computer. I also found that I didn't have SharpCap installed on my Development Laptop.  I bought a new 1 yr SharpCap licence for £10 and downloaded and installed the latest 3.20 version of (3.2.6117.0) on both computers.

As part of reinvigorating wider view colour imaging and luner imaging, my earlier Python program (known as 'SharpCap Server' or 'SharpCap Interface 11') has been dusted down,  moved to the Visual Studio 2017 development environment and given the new name 'AstroShCap' , placing it with my AstroSuite Software range.  

SharpCap has a Scripting Object Model than can be accessed via Python scripts executed by SharpCap's IronPython Console. See SharpCap Connection and Control (2017-02-07). This makes SharpCap particularly well suitable for automating the capture of images taken with my ZWO ASI 178MC colour camera & 80mm APO scope, when it is not being used for autoguiding using PHD2.  

The aim is to to get SharpCap Imaging integrated into my Queue Based Observing Sequences to significantly widen the data captured during Fully Automated Sessions

List of Tasks  ( - To Do,  - In Progress,  - Done ) 

• Move to latest version of SharpCap (3.2) 
• Setup AstroShCap project to VS2017
• Setup version control , using a special AstroShCp_version.py file
• Extend AstroMove program to copy AstroShCp.py to the Observatory Computer at the click of button
• Extend AstroMove program to back up AstroShCp project at the click of button
  
• Modify AstroMain to be able to start up the SharpCap 3.2 version
• Fix linebreak and font size issues on the AstroShCp Console
• Ensure AstroShCap opens and runs in the SharpCap script environment
• Confirm AstroShCap can command SharpCap to perform operations
• Confirm AstroMain can connect to and talk with AstroShCap 
        (Done, but their are reconnection issues, that require AstroMain to be restarted each time AstroShCap restarts)
• Establish how AstroShCap can command SharpCap to connect to a specific camera and how to disconnect it - Done
  
• Update AstroMain-AstroShCap communication code to allow reconnects
• Allow seamless trouble-free switching of ZWO ASI Camera Contol from PHD2 to SharpCap, and back again

Go to latest version of this list :  AstroShCap Development Section (AstroSuite Page)

SharpCap

'AddCustomButton', 'AppName', 'BlindSolver', 'Cameras', 'CanDeleteLastOutput', 'Caption', 'CaptureEvent', 'CaptureFolder', 'CaptureStarting', 'CheckAccess', 'CreateFileNameProvider', 'CustomButtons', 'DevicesUpdated', 'Dispatcher', 'Dispose', 'Equals', 'ExceptionReportStrategy', 'Focusers', 'FrameType', 'GetHashCode', 'GetLastCaptureFilename', 'GetType', 'Initialize', 'IsCameraSelected', 'LiveStacking', 'LogException', 'LogMessage', 'MainWindow', 'Mainwindow', 'MemberwiseClone', 'Mounts', 'NightModeControl', 'Notification', 'PreviewWindow', 'PropertyChanged', 'ReferenceEquals', 'RefreshCameras', 'RemoveCustomButton', 'Reticules', 'SelectedCamera', 'SelectedCameraChanged', 'Settings', 'ShowErrorReportTaskDialog', 'ShowMessageBox', 'ShowNotification', 'TargetName', 'ToString', 'Transforms', 'VerifyAccess', 'Wheels', 'WindowEnabled'

SharpCap.IsCameraSelected      (returns: boolean True/False)

SharpCap.GetLastCaptureFilename()    (returns: None or string filename)

SharpCap.LiveStacking

'AcceptsRawFrame', 'Activate', 'Activated', 'AlignStatus', 'AltersImage', 'App', 'AutoSave', 'BeforeFrameProcessed', 'CanAlign', 'DetectedStars', 'DetectsHotPixels', 'DisplayParameters', 'Dispose', 'DroppedFrames', 'Equals', 'FrameProcessed', 'GetBins', 'GetControl', 'GetHashCode', 'GetType', 'ImageUpdateRequest', 'IsActive', 'IsEndOfChainTransform', 'IsFocusScore', 'LastExposure', 'LiveStackReset', 'LocalLogger', 'MaxValue', 'MemberwiseClone', 'PHDGuiding', 'Parameters', 'ProcessFrame', 'ProcessTime', 'PropertyChanged', 'ReGetFrame', 'ReferenceEquals', 'RenderTime', 'RequiresLiveMode', 'RequiresROI', 'Reset', 'SaveFrame', 'SaveFrameAsSeen', 'SaveImageWithDisplayStretchAsync', 'SaveStackedFrames', 'SetActive', 'SetROIRect', 'SetStackMode', 'StackEffectiveBitDepth', 'StackInfo', 'StackProgress', 'StackedFrames', 'Status', 'SupportsPixelFormat', 'SupportsROI', 'ToString', 'TotalExposure', 'TotalFrames', 'TransformFrame', 'TransformName', 'UpdateDisplayParameters', 'UpdateImage', 'UpdateTransferCurve', 'UsedFrame', 'ViewModel', 'WantsFrame'

SharpCap.LiveStacking.Activate()

SharpCap.Transforms.SelectTransform("Live Stacking")

float = SharpCap.LiveStacking.TotalExposure  ( eg 72000 in msecs)

SharpCap.LiveStacking.SaveFrameAsSeen("C:\\Data\\ZWO Imaging\\Test2.png")

properties

int = SharpCap.LiveStacking.DroppedFrames
int = SharpCap.LiveStacking.StackedFrames
int = SharpCap.LiveStacking.TotalFrames
string = SharpCap.LiveStacking.Status                    ( e.g.  89 Stacked, 15 Ignored, 81.86s)

SharpCap.LiveStacking.Reset()    # Method to Reset/Clear the current stack, keeps

'Align', 'AlignStarCount', 'AllowRotation', 'AutoReset', 'AutoResetPeriod', 'BlackThreshold', 'BlurAmount', 'Clone', 'DigitalGain', 'Equals', 'Filter', 'FilterBrightness', 'FilterFWHM', 'GetHashCode', 'GetType', 'HighlightStars', 'IgnoredFrameWarningThreshold', 'MaxFWHM', 'MaxStarWidth', 'MemberwiseClone', 'MinBrightness', 'MinStarWidth', 'OnPropertyChanged', 'Pause', 'PauseReason', 'Paused', 'PropertyChanged', 'ReferenceEquals', 'SigmaClipInitialCount', 'SigmaClipThreshold', 'SigmaMinimumPercent', 'ToString', 'UnPause', 'ViewRawFrames']

SharpCap.Transforms.SelectedTransform = None

SharpCap.LiveStacking.Parameters.Pause()        # Pause the LiveStack
SharpCap.LiveStacking.Parameters.UnPause()   #   Un-Pause the LiveStack

SharpCap.Transforms

'AllTransforms', 'AnyTransformSelected', 'AreaSelection', 'AvailableTransformsChanged', 'Count', 'Equals', 'GetEnumerator', 'GetHashCode', 'GetType', 'IsTransformAvailable', 'Item', 'LoadTransforms', 'MemberwiseClone', 'NullTransform', 'OnPropertyChanged', 'PreviewPixelFormat', 'PropertyChanged', 'ROISelectionChanged', 'ReferenceEquals', 'Refresh', 'SelectTransform', 'SelectedTransform', 'SelectedTransformChanged', 'SelectionRect', 'ToString'

SharpCaps.Transforms.SelectedTransform

'CanUseTransform', 'Equals', 'FrameProcessor', 'FrameTransform', 'GetHashCode', 'GetType', 'IsFocusScore', 'MemberwiseClone', 'Name', 'ReferenceEquals', 'RequiresLiveMode', 'RequiresROI', 'SupportsROI', 'ToString', 'UIControl', 'Visible'