Issue 
Problem starting Night Services - Obs.Monitor became frozen in section Focuser1 (00:15), causing problems connecting Telescope and PHD2 services

Description
Whilst starting night services manually, Telescope Power service failed (with message 'Telescope Power is Off' and Telescope Connection didn't proceed.  After the Start Services operation finished the Obs.Overseer then reported "Obs.Monitor is frozen (00:15) in section Focuser1". 

UPB Software Interface indicates that LX200 Power was on which was in contradiction to the 'Start Night Services' message that 'telelscope power is off'
Thinking that there might be a problem with ASCOM.pegasus_upb.Switch, despite absence of any reported errors,  all services were stopped at 00:19:26, and AstroMain and other observatory software were closed down / stopped.

After restarting observatory software including AstroMain a fresh attempt to start Night Services was made. This time there were no anomalies or errors and the S1018 session was then successfully started and executed with further problem. 

There are three main questions to be addressed

1) Why did Scope.PowerOn() routine return a failure, when the operation to turn on scope power did actually succeed ?
2) Why did PHD2 failed to connect to camera/mount devices
3) Why did Obs.Monitor become frozen ?

Analysis

Scope.PowerOn 'failure' ?
Log files ahead of the event are completely normal with no exceptions or anomalies. AstroMain 3.51.15 was restarted at 14:04 and daytime services started with no problem.  A saved ObsPic shows the Telescope Power being off at 00:14:48 which is a few seconds prior to user action to start night services at 00:15:00.  The message  "Telescope Power has been switched on" at 00:15:04.74 suggests that the call to Scope.PowerOn  was successful A remote connection view of the UPB Software Interface made at  around 00:20 indicated that the LX200 Power had been succcessfully turned (the next saved ObsPic confirms the scope power was already on at 00:25:22) .

It can be concluded that there was no problem with UPB Power Box or with 'ASCOM.pegasus_upb.Switch' driver & connection going into the connect night services operation.

So why did the Scope.PowerOn routine report that it had failed and produce the message 'Telescope Power is Off'.

At the time it was thought that the issue was related to a problem with ASCOM Switch connection but no errors or exceptions were recorded for the ASCOM.pegasus_upb.Switch and turning on LX200 Power (which uses the ASCOM Switch) evidently occurred ok.

At 00:15:19.34 there was an Exception in PHD2.GetCalibrationData, handling 'calibrated'  "Conversion from string "Error: device not connected" to type 'Boolean' is not valid"  and  Connect PHD2 routine reported that it was unable to connect to either Camera or Mount. These problems are most likely related to fact that Telescope hadn't been connected to or more specifically the LX200 telescope hadn't finished initialising when PHD2 made a connection attempt, since attempt was made only 15s after scope was powered on, when normally 60s are allowed for before making a connection.

Log file

00:15:00.61 | User Action Select NightServices        Info  | User action to select Night Services
00:15:02.85 | User Action Start Services              Info  | User request to start observatory services
00:15:02.85 | ObsServices Start Services              Try   | Starting Observatory Services
   Report:    Start Observatory Services                      2022-06-07 00:15 (Local)

00:15:02.88 | ObsServices Check Scope.Power           Info  | Checking Telescope Power State (0)
00:15:02.88 | ObsServices WaitOn User                 Ok    | Confirm with user whether to Switch Scope Power On
00:15:04.74 | ObsServices Set Scope.PowerOn           Ok    | Telescope Power has been switched on
   Report:    Telescope Power:                        Fail    Telescope Power is off
   Report:    Telescope: (COM6)                       Fail
00:15:14.78 | Observatory Services Start PHD2 Listen  Ok    | Starting PHD2 Listening Loop
   Report:    PHD2 Client                             Ok      Started (00:15) (TCP/IP Port 4400, LocalHost)
   Report:    PHD2 Profile                            Ok      Started already (Profile:TS80/178MC, ID: 1)
   Report:    - PHD2 Camera                           Fail(0) Unable to connect (Camera: ZWO ASI178MC)
   Report:    - PHD2 Mount                            Fail(0) Unable to connect (Mount: DeviceHub -> Meade Generic (ASCOM))
00:15:15.90 | Observatory Overseer Check ObsMonitor   Alert | Obs.Monitor is Frozen (15s) in section : Monitor Focuser1
00:15:19.34 | ObsServices Get PHD2.CalibrationData    Fail  | Exception in PHD2.GetCalibrationData, handling 'calibrated'
00:15:19.34 | ObsServices Get PHD2.CalibrationData    Fail  | Conversion from string "Error: device not connected" to type 'Boolean' is not valid.

Code
The Scope.Connect() routine calls Scope.SetPowerOn_Quiet() routine to turn telescope power on (after calling objPowerBox.SetSwitch(cSwitchPower1, True) the writing of "Telescope Power has been switched on" proves that no exception occurred, again confirming that UPB powerbox and ASCOM.pegasus_upb.Switch were working ok at the time)
The Scope.Connect() routine then waits up to 10s for Scope.PowerState to become 1 (On).   If Scope.PowerState = 0 after 10s the routine reports the job as a "Fail"  & gives the message "Telescope Power is off".

Whilst Scope.SetPowerOn() method (called manually using the 'Switch On Scope' button routine) sets Scope.PowerState = 1 (and also VM.ScopePowerState = 2, VM.ScopePowerSeconds = "0s" ) after calling objPowerBox.SetSwitch(cSwitchPower1, True),  the Scope.SetPowerOn_Quiet() method called by Scope.Connect() doesn't set Scope.PowerState but relies on the Obs.Monitor ("Monitor PowerBox" section) to set Scope.PowerState property after reading the value of objPowerBox.GetSwitch(cSwitchPower1).  The Scope.SetPowerOn_Quiet() method may have to do it this way as it runs from the 'ObsServicesThread' thread and may have had a historic problem in calling objPowerBox object directly as it was created on the main UI thread ?

It is conjectured that Obs.Monitor didn't set Scope.PowerState = 1 because it was frozen in the "Monitor Focuser1" section and was not actively cycling around to the "Monitor PowerBox" section.

Frozen Obs.Monitor ?
At 00:15:05.90 the Observatory Overseer checked the status of ObsMonitor and found "Obs.Monitor is Pending (5s) in section : Monitor Focuser1", subsequently confirmed to be "Frozen (10s, 15s etc) in section : Monitor Focuser1".   It would seem that Obs.Monitor froze at around 00:15:00 to 00:15:02.

It is highly likely that frozen Obs.Monitor prevented the setting of Scope.PowerState = 1 (in "Monitor PowerBox" section) and led to Connect Telescope and Connect PHD2 services failing.

Problems with the Obs.Monitor freezing in the section "Focuser1" have been seen before, but haven't been fully understood.

[ The ObsMonitor cycle immeditely prior to the ObsMonitor freeze was logged at 00:14:58.84. During this cycle the Focuser1 section of code took 627ms to execute which is not an atypical duration.  The section varies from around 14 to 650ms (dependant on whether is executes in a single go or if the ObsMonitor thread is suspended in order to execute other program threads or other applications ]

So what caused Obs.Monitor to freeze in the section "Monitor Focuser1" ?

The "Monitor Focuser1" code section contain multiple references to objFocuser1 object. These comprise

- objFocuser1.Connected (direct call)
- objFocuser1.Temperature (called via Focuser1.PreciseTemperature),
- objFocuser1.Position (called via Focuser1.Position)
- objFocuser1.IsMoving (called via Focuser1.IsMoving)

If there is a problem with the TCF Focuser/Driver it is conjectured that any of these calls might lead to execution hanging.

The "Calc Foc1 AvTemp" code section does contain any code that would be likely to cause execution to hang

The "Update Foc1 Fields" code section calls 'UpdateFoc1Fields' which contains several references to Camera and objFocuser1 objects

 - Camera.FilterIndexZeroBased (direct call)
 - Camera.FilterIndexZeroBased   (called via Focuser1.GetTempCompPositionForFilter() )
 - objFocuser1.Temperature  (called via Focuser1.GetTempCompPositionForFilter()  / Focuser1.Temperature

If there is a problem with the TCF Focuser/Driver or CCDSoft.Camera it is conjectured that any of these calls might lead to execution hanging.

At the time that ObsMonitor froze CCDSoft.Camera was connected and working ok at around 00:14.  User request to connect CCD Camera was made at 00:14:53.51. Report file shows successful connection and successful access to Camera properties (CCD temperature etc)

Changes in AstroMain 3.51.16
Besides the main "Monitor Focuser1" code the section also includes extra code to i) calculate a Rolling Average Focuser Temperature and ii) Update Foc1 Fields in the ObsConsole window . In order to distinguish where the Obs.Monitor is freezing these 2 intervals of extra code  are  defined as two separate code sections in AstroMain 3.51.16 named "Calc Foc1 AvTemp" and  "Update Foc1 Fields" respectively.

Beginning around 40-45s after the ObsMonitor froze the Logfile shows 'DewHeater'  cycles failing with the message "Tube Temperature is vcNull", repeated every 60s thereafter.

Conclusion
It is unclear exactly why Obs.Monitor frooze.

Actions

  Extra Tracing. Add extra named sections to Obs.Monitor so that freezes in core part of "Monitor Focuser1" section can be definively distinguished from freezes in two newly defined "Calc Foc1 AvTemp" and  "Update Foc1 Fields" sections (that were previously included in "Monitor Focuser1".

  PHD2. Prevent PHD2 Service from starting if Scope.PowerState isn't 1.

  TCF-S restart.  In the event that ObsOverseer detects that ObsMonitor is frozen in section "Monitor Focuser1", it may be worth attempting to "Restart TCF-S Service".  

Issue 
Anomalous slew case identified by the slew monitor (01:40:04). 

Q. Does the issue shed any light upon the likely origin of the SS Cyg slew anomaly in session S1014 2022-05-31 (more) ?

Description
Recently improved slew monitoring routine picked up and issued an Dome Slew Anomaly alert  (Dome slew resumed at Az 236.2°) at 01:40:04 whilst performing a slew to Target 5/6 (HIP 87937, alias Barnards Star).

Analysis
The timeline associated with this particular slew based on combining multiple logs is as follows:

01:39:55.653:  DH Dome performs position recalculation due to periodic timer expiration.
               (calculated dome position is Az: 238.11)
               (dome azimuth is close to the target azimuth...no slew is needed)

01:40:03.700:  DH sends Slewing=False to AstroMain Dome client

01:40:03.77    AstroMain requests Telescope to slew to Target 5/6 (HIP 87937) This is time T0.
              (Scope at Az: 242.5°, Scope needs to move to Az 172.2°. 
               Dome at Az 237.3°, Dome needs to move to Az 172.4°)

01:40:03.796:  DH Dome begins fast polling every 1000 ms, performs a Dome position recalculation due
               to telescope slew-in-progress and calculates a destination Az (172.39) 
01:40:03.821:  Pulsar Dome receives SlewToAzimuth (172.393863)
01:40:03.835:  DH Dome reports SlewToAzimuth (172.39386°):

01:40:03.796:  MeadeGeneric recieves SlewToCoordinatesAsync (Ra=17.9808749512575, Dec=5.30341351083939)
01:40:04.082:  DH Telescope reports SlewToCoordinatesAsync (Ra ***, Dec ***)

01:40:04.123:  DH Dome reports SlewToAzimuth (172.39431°)
               (further SlewToAzimuth commands every 50ms not shown)
01:40:04.299   DH sends Slewing=True to AstroMain Dome client
01:40:04.29:   AstroMain sees Dome Slewing=True    (T+0.5s)

01:40:04.50:   AstroMain sees Dome Slewing=False   (T+0.7s, dome slew appears to have stopped)
01:40:04.666:  Pulsar Dome reports Slewing=False
01:40:04.715:  DH sends Slewing=False to AstroMain Dome client
 
01:40:04.933:  DH sends Slewing=True to AstroMain Dome client
01:40:04.95:   AstroMain sees Dome Slewing=True    (T+1.2s, dome slew appears to have started again)
 
01:40:04.731:  DH Dome sends SlewToAzimuth (172.39824°):
01:40:04.731:  Pulsar Dome reports Slewing=True  (Dome is moving !)

01:40:05.234:  MeadeGeneric reports IsSlewing = True(Telescope is moving !)
01:40:05.922:  DH Telescope starts fast polling every 550 ms.

01:40:30.317:  DH Telescope returns to normal polling every 3000 ms.
 
01:40:36.781:  Pulsar Dome reports Slewing=False
01:40:36.782:  DH Dome returns to normal polling every 5000 ms.
01:40:36.875   DH sends Slewing=False to AstroMain Dome client
01:40:36.89    AstroMain recognises that the Slew is Complete

01:40:46.775:  DH Dome performs position recalculation due to periodic timer expiration
               (calculated dome position is Az: 172.59)
               (dome azimuth is close to the target azimuth...no slew is needed).

From the view of AstroMain's slew monitor its sees Dome Slewing = True (at T+0.5s), before it goes to Slewing = False (at T+0.7s), before going to Slewing=True again (at T+1.2s) and stays in this state until finally Slewing=False at T+33s.

DomePath Info | Time: 0.5, Slewing: 1, Slew: 0.0, Az: 237.3
DomePath Info | Time: 0.7, Slewing: 0, Slew: 0.0, Az: 237.3
DomePath Info | Time: 1.2, Slewing: 1, Slew: 1.1, Az: 236.2
DomePath Info | Time: 2.0, Slewing: 1, Slew: 2.7, Az: 234.6
DomePath Info | Time: 3.1, Slewing: 1, Slew: 4.6, Az: 232.7
DomePath Info | Time: 4.1, Slewing: 1, Slew: 6.7, Az: 230.6
DomePath Info | Time: etc

AstroMain's slew monitor recieves the dome slewing state that DeviceHub.Dome gives it. This isn't necessarily the same slewing state that the Pulsar Dome has at any one time. In this particular case whilst the slew monitor percieves the dome slewing stopping and then resuming again at an interim moment around 0.7s into the slew operation (which caused the alert to be raised),  the Pulsar Dome log clearly records just a single slew event (i.e. it doesn't have any intermediate slew stop & resume).  

What actually happens is that immediately after the slew is commanded (by Dome Manager performing a 'dome position recalculation due to telescope slew-in-progress'), DH begins to return dome Slewing=True to the attached clients, which it continues to do up until the moment that it next polls the dome which will typically still have Slewing=False (as the Pulsar dome has started moving yet).   When the dome finally begins moving (typically after 1s) fresh polling detects this and DH then starts returning Slewing=True.  This continues until Polling of the dome identifies that slewing has stopped and DH finally returns Slewing=False.

This initial Slewing=True before switching back to Slewing=False is only occasionally seen. It is likely to depend on where DH is in its polling cycle compared to the precise moments that AstroMain requests the Slewing property value from DH.  For the slew to the target that proceded the one to HIP 87937 the dome monitor recorded the following :

DomePath Info | Time: 0.5, Slewing: 0, Slew: 0.0, Az: 256.7
DomePath Info | Time: 1.1, Slewing: 1, Slew: 1.4, Az: 255.3
DomePath Info | Time: 2.2, Slewing: 1, Slew: 3.1, Az: 253.6
DomePath Info | Time: 3.1, Slewing: 1, Slew: 5.1, Az: 251.6
DomePath Info | Time: 4.1, Slewing: 1, Slew: 6.8, Az: 249.9
DomePath Info | Time: 5.2, Slewing: 1, Slew: 9.0, Az: 247.7
DomePath Info | Time: etc

Conclusion
The dome slewing anomaly in this particular case is a false alert and is a completely explainable condition that is caused by the way that DH initially returns  Slewing=True as soon as SlewToAzimuth is commanded whilst Pulsar Dome continues to return Slewing = False until the dome actually starts moving some 1s later.   Whether a given slew creates an anomalous condition in AstroMain's slew monitor depends on the precise timing of DH dome polling and the timing of Slewing enquiries from AstroMain.

The particular situation that gave rise to false alert in case of this slew to HIP 87937 can be recognised because at the moment the Slewing flag temporariliy drops back to 0 (False), the Slew Angle is 0.0, and the apparent resumption of slewing comes < 2s after the slew operation commenced.

Unfortunately the case doesn't shed any light on the earlier dome slew anomaly from SS Cyg (S1014, 2022-05-31) which remains a mystery.

Actions
  Slew Monitor. AstroMain's Slew Monitor to be modified to not recognise this particular situation as an anomaly and therefore not to raise this an alert.

DeviceHub was updated on Development & Observatory Computers today (2022-06-09) from version 6.6.0.10 to new 6.6.0.11 version. 

This new version contains a fix for an issue with dome slewing interruption that may have caused the anomalous slew seen in session S1014 (see Issue Identifying End Of Dome Slew, 2022-05-31).  The version also fixes an activity log format error for Telescope.SlewToCoordinatesASync which was noticed in session S1016 (2022-06-03) after the earlier installation of prior version (6.6.0.10).

6.6.0.11 Release Notes
- Added ability to restore expanded panels at startup
- Fixed issue with dome slewing interruption
- Changed Activity Log to not show icon on the Taskbar
- Fixed Activity Log format error for SlewToCoordinatesAsync

Activity Log
After installation of the new version the Activity Log Capacity value (which was reset to its standard default value (125000) during installation ) was again increased ten-fold (1250000) by editing the  DeviceHub configuration file  (C:\Program Files (x86)\Common Files\ASCOM\DeviceHub\ASCOM.DeviceHub.exe.config)  as follows:

  <setting name="ActivityLogCapacity" serializeAs="String">
    <value>1250000</value>
  </setting>

Results
The first live observing session using DeviceHub 6.6.0.11 will be S1019 (date TBA).

>> Device Hub Releases :  https://github.com/ASCOMInitiative/ASCOMDeviceHub/releases