A new development version of MeadeGeneric driver was installed on the observatory computer today (2021-12-16).  This contains a fix for issue when TrackingRate returns driveLunar (normally 57.9z) for actual scope tracking rate of 60.0Hz  which is actually the tracking rate for driveSolar.

Results
MeadeGeneric 1.3.3.373 was successfully used in session S942 (2021-12-16).

>> MeadeGeneric Releases : https://bitbucket.org/cjdskunkworks/meadeautostar497/wiki/Release%20History

Issue:  PHD2 Guiding Run suddenly ended when a key thread in PHD2 crashed due to a fatal exception and prevented autoguiding for the remainder of the automated session.

Description.   Checking in with observing session in morning showed although the session had completed normally the targets from second part of night hadn't been auto-guided. Guide Charts had been created with normal header data, but the graphs were devoid of any guide data and GuideSummary Plots and Table only show data for Guide Run 1 to 16,  whilst Guide Run 17 to 43 were devoid of data.  Report Log indicates problem capturing Focus Reference image.

Checking the PHD2 application showed an error dialog with the message "*** Caught, unhandled, unknown exception; terminating".
The Image in PHD2 show a region of sky including M42 consistent with the target NV Ori (guide run 16) and guiding history plot was normal.

The error dialog was dismissed with click on its Ok button whereupon the PHD2 GUI was found to be non-responsive and had to be killed.

Data in AstroMain indicates that the PHD2 server was responsive throughout,  for example the temperature of the camera connected to PHD2 was able to be monitored and its graphs show normal data throughout.   General data from PHD2 (Profile Name, Connected Camera / Mount etc) was also recoverable with no problem

AstroMain Report files shows 'Failed to capture frame'  (ie 10s Reference Frame from PHD2) at 23:08 during attempted Guide Run 17 for FU Ori.
Guiding data seems to stops coming through at or just before the the start of Image Group 2 at 23:04:30 during Guide Run 16 for NV Ori.

PHD2 Debug Log shows output that consistent with active Guiding up until 23:03:45. After this there are just mainly "evsrv: cli ... " messages associated with PHD2 server requests and responses.  At 23:08:46 there is a "request: {"method":"guide".... " from AstroMain to begin guiding for the next target (NV Ori).  PHD2 then outs as series of "PhdController::Guide begins . sequence consistent with request from AstroMain

 << Normal sequence of Guiding Related activity
23:03:44.573 00.003 12516 UpdateImageDisplay: Size=(3096,2080) min=283, max=65531, med=900, FiltMin=489, FiltMax=65531, Gamma=0.300
23:03:44.875 00.302 12516 UpdateGuideState exits: m=1217784 SNR=435.5
23:03:44.875 00.000 12516 OnExposeComplete: CaptureActive=1 m_continueCapturing=1
23:03:44.875 00.000 12516 ScheduleExposure(1500,3,1) exposurePending=0
23:03:44.883 00.008 12516 Enqueuing Expose request
23:03:44.887 00.004 12516 evsrv: cli 0CDA5F30 request: {"method":"get_ccd_temperature","id":1321}
23:03:44.890 00.003 12516 evsrv: cli 0CDA5F30 response: {"jsonrpc":"2.0","result":{"temperature":12.2},"id":1321}
23:03:45.288 00.398 11812 IsGuiding returns 0
23:03:45.288 00.000 11812 Move returns status 0, amount 91
23:03:45.288 00.000 11812 MoveAxis(N, 66, ABG)
23:03:45.288 00.000 11812 duration set to 0 by GuideMode
23:03:45.288 00.000 11812 Move returns status 0, amount 0
23:03:45.288 00.000 11812 move complete, result=0
23:03:45.288 00.000 11812 worker thread done servicing request
23:03:45.288 00.000 12516 GuideStep: 0.8 px 91 ms WEST, -1.4 px 0 ms NORTH
23:03:45.288 00.000 11812 Worker thread wakes up
23:03:45.288 00.000 11812 worker thread servicing REQUEST_EXPOSE 1500
23:03:45.288 00.000 11812 Handling exposure in thread, d=1500 o=3 r=(1958,1796,41,41)
 << Guiding Related activity suddenly and unexpectedly stops here (no errors or unusual messages)
23:04:05.058 19.770 12516 evsrv: cli 0CDA5F30 request: {"method":"get_ccd_temperature","id":1322}
23:04:05.062 00.004 12516 evsrv: cli 0CDA5F30 response: {"jsonrpc":"2.0","result":{"temperature":12.2},"id":1322}
23:04:25.495 20.433 12516 evsrv: cli 0CDA5F30 request: {"method":"get_ccd_temperature","id":1323}
23:04:25.504 00.009 12516 evsrv: cli 0CDA5F30 response: {"jsonrpc":"2.0","result":{"temperature":12.1},"id":1323}
 << PHD2 Server requests and responses (4 mins of data not shown)
23:08:45.649 00.003 12516 evsrv: cli 0CDA5F30 response: {"jsonrpc":"2.0","result":{"id":1,"name":"TS80/178MC"},"id":1370}
23:08:46.060 00.411 12516 evsrv: cli 0CDA5F30 request: {"method":"get_search_region","id":1371}
23:08:46.064 00.004 12516 evsrv: cli 0CDA5F30 response: {"jsonrpc":"2.0","result":20,"id":1371}
23:08:46.176 00.112 12516 evsrv: cli 0CDA5F30 request: {"method":"get_camera_frame_size","id":1372}
23:08:46.180 00.004 12516 evsrv: cli 0CDA5F30 response: {"jsonrpc":"2.0","result":[3096,2080],"id":1372}
 << Request to Start Guiding
23:08:46.293 00.113 12516 evsrv: cli 0CDA5F30 request: {"method":"guide","params":[{"pixels":2,"time":10,"timeout":15},false,[341,229,2415,1622]],"id":1373}
 << Phd2 Controller seems to still be active
23:08:46.296 00.003 12516 PhdController::Guide begins
23:08:46.299 00.003 12516 PhdController: newstate STATE_SETUP
23:08:46.301 00.002 12516 PhdController: setup
23:08:46.302 00.001 12516 PhdController: newstate STATE_ATTEMPT_START
23:08:46.302 00.000 12516 PhdController: guider state = 6
23:08:46.307 00.005 12516 PhdController: newstate STATE_SETTLE_BEGIN
23:08:46.312 00.005 12516 PhdController: newstate STATE_SETTLE_WAIT
23:08:46.316 00.004 12516 evsrv: cli 0CDA5F30 response: {"jsonrpc":"2.0","result":0,"id":1373}
23:08:47.188 00.872 12516 evsrv: cli 0CDA5F30 request: {"method":"get_ccd_temperature","id":1374}
23:08:47.191 00.003 12516 evsrv: cli 0CDA5F30 response: {"jsonrpc":"2.0","result":{"temperature":11.7},"id":1374}
23:09:07.789 20.598 12516 evsrv: cli 0CDA5F30 request: {"method":"get_ccd_temperature","id":1375}
23:09:07.791 00.002 12516 evsrv: cli 0CDA5F30 response: {"jsonrpc":"2.0","result":{"temperature":11.7},"id":1375}
23:09:16.188 08.397 12516 evsrv: cli 0CDA5F30 request: {"method":"save_image","id":1376}
23:09:16.194 00.006 12516 GetString("/profile/1/name", "") returns "TS80/178MC"
 << SideOfPier Not Implemented Exception Occurs (red-herring)
23:09:16.197 00.003 12516 invoke: [80020009] Exception occurred.
23:09:16.198 00.001 12516 Error thrown from C:\cygwin\home\agalasso\projects\phd2\scope_ascom.cpp:1119->ASCOM Scope: SideOfPier failed: (ASCOM.DeviceHub.Telescope) Property read ASCOM.MeadeGeneric.Telescope SideOfPier is not implemented in this driver.
23:09:16.198 00.000 12516 ScopeASCOM::SideOfPier() returns -1
23:09:16.207 00.009 12516 evsrv: cli 0CDA5F30 response: {"jsonrpc":"2.0","result":{"filename":"C:\\Users\\David\\AppData\\Local\\phd2\\savD7FB.tmp"},"id":1376}
23:09:30.237 14.030 12516 evsrv: cli 0CDA5F30 request: {"method":"get_ccd_temperature","id":1377}
23:09:30.240 00.003 12516 evsrv: cli 0CDA5F30 response: {"jsonrpc":"2.0","result":{"temperature":11.7},"id":1377}
 << PHD2 Server requests and responses (18 mins not shown here)
23:27:03.390 00.000 12516 evsrv: cli 0CDA5F30 response: {"jsonrpc":"2.0","result":{"id":1,"name":"TS80/178MC"},"id":1501}
23:27:03.803 00.413 12516 evsrv: cli 0CDA5F30 request: {"method":"get_search_region","id":1502}
23:27:03.806 00.003 12516 evsrv: cli 0CDA5F30 response: {"jsonrpc":"2.0","result":20,"id":1502}
23:27:03.904 00.098 12516 evsrv: cli 0CDA5F30 request: {"method":"get_camera_frame_size","id":1503}
23:27:03.907 00.003 12516 evsrv: cli 0CDA5F30 response: {"jsonrpc":"2.0","result":[3096,2080],"id":1503}
 << Next Request to Start Guiding
23:16:50.249 00.113 12516 evsrv: cli 0CDA5F30 request: {"method":"guide","params":[{"pixels":2,"time":10,"timeout":15},false,[341,229,2415,1622]],"id":1436}
 << Phd2 Controller seems to less active
23:16:50.252 00.003 12516 PhdController::Guide reentrancy state = 9 op = 1
23:16:50.252 00.000 12516 evsrv: cli 0CDA5F30 response: {"jsonrpc":"2.0","error":{"code":1,"message":"Cannot initiate guide while guide is in progress"},"id":1436}
23:17:09.454 19.202 12516 evsrv: cli 0CDA5F30 request: {"method":"get_ccd_temperature","id":1437}
23:17:09.455 00.001 12516 evsrv: cli 0CDA5F30 response: {"jsonrpc":"2.0","result":{"temperature":11.6},"id":1437}
23:17:20.132 10.677 12516 evsrv: cli 0CDA5F30 request: {"method":"save_image","id":1438}
23:17:20.138 00.006 12516 GetString("/profile/1/name", "") returns "TS80/178MC"

PHD2 Guide Log shows the last recorded guide sequence  starting at around 22:59  ('Guiding Begins at 2021-12-16 22:59:43 , whilst debug log shows 22:59:31for PhdController::Guide begins) . Once guiding gets underways Guidesteps are reported until 242s after start of guiding . This would equate with 23:03:45 and is thus consistent with the end of guiding activity in the debug log.

The following sofware versions where being used :
  - ASCOM 6.5 SP1
  - AstroMain 3.48.4
  - MeadeGeneric 1.3.3.373
  - DeviceHub 6.5.1.9
  - PHD2 Guiding 2.6.10

Analysis

• Dead end 1: At first site the exception "Error thrown from C:\cygwin\home\agalasso\ .......  ASCOM Scope: SideOfPier failed: (ASCOM.DeviceHub.Telescope) Property read ASCOM.MeadeGeneric.Telescope SideOfPier is not implemented in this driver." looked as it might be implicated in the PHD2 application failure.  However another look shows that this exception crops up throughout the entire session including throughout the first half of the session when PHD2 guiding was working ok.
   
• Deadend 2: The associated line  "ScopeASCOM::SideOfPier() returns -1" is believed to be PHD2 response to the 'SideOfPier Not Implemented .." exception. Suggesting the exception is handled and therefore can't be the 'unhandled, unknown exception .." referred to in the error dialog. Telescope drivers logs were checked and confirm there  no SideOfPier = -1 responses were sent from the driver.  Logs show each request returned a Not Implemented exception.
   
• Deadend 3:   Testing of Telescope Drive Rate setting & reporting was being undertaken between 22:39 and 22:46 during which the telescope tracking was changed from 60.1 Hz (driveSidereal) to 60.0 (driveSolar) to 57.9 (driveLunar) to 59.9 and finally 58.5 hz (driver returns "driveKing" ).  This final setting was accidently left running until noticed as 23:40 when the tracking rate was changed back to 60.1 (driveSidereal).     Whilst this testing might have potentially changed data being supplied by the ASCOM telescope during this time interval,  no changes were being made at the time of the fatal exception at 22:03:45 and there were no problems with guide run 16 when it started at 22:59.
   
• Unhandled, Unknown Exception in PHD2 : The only information that we have is that the exception was unhandled and unknown and is presumed to have occurred in the middle of 'normal' guiding at 23:03:45 and ended guiding.   It would seem that just the main guiding thread and the GUI that were  affected (the PHD2 controller and PHD2 server were evidently still active after this time)
  

Conclusion
PHD2 failed due to an unhandled, unknown exception.  There is no information to diagnose the cause of the exception any further.   It may be a glitch that will never be seen again or it might be something that occurs from time to time .  The problem is not related to recent SideOfPier/Calibration Flipping Issue.

Actions:
 
Pass details of the case to PHD2 Forum/Support

Add code to AstroMain to monitor the PHD2 application and kill/restart PHD2 if it has stalled. Add code to Obs.Monitor/Obs.Manager  to monitor the apparent level of activity in PHD2  and if it seems to have stalled  then call a new routine to Close PHD2 Server connection and then kill PHD2 process before restarting it and reconnecting.

 

Update 2022-07-29

Code added to AstroMain 3.53.1 that will check PHD2 functioning following a request to Guide, and if PHD2 appears stalled it will kill and restarted PHD2 & restart PHD2 service.

It is noticed that following the exception in PHD2 and its failure to guide from 23:04 , PHD2 responded to requests (like 'get_current_equipment') but in response to 'guide' request there wasn't the usual sequence of Events that would be sent out by PHD2.   Apart from 'GuideParamChange'  and 'ConfigurationChange' events associated with 'set_dec_guide_mode' requests the only guiding related event seen is a single 'SettleBegin' event associated with 'guide' request at 23:08:46.  The usual events 'LoopingExposures', 'LockPositionSet', 'StarSelected', 'StartGuiding' , 'Settling', 'GuideStep' are all missing.

The absence of these normal guiding events following 'guide' request will be used to indicate a probably problem with the PHD2 program.  Specifically the absence of 'LoopingExposures' events will be used to diagnose an issue.




The correct functioning of PHD2 will be identified presence of LoopingExposures events following request to 'Guide', and incrementing the variable nLoopingExposureEvents