David's Astronomy Pages
Notes - Session 818 (2020-10-09)

 
Bullet Session Aims & Highlights
 - Observing Result
 - Night Summary Plot
 - Session Event Log
 
Bullet Operational Issues
  - Critical Issues (0),  Major Issues (1),  Minor Issues (6),  Continuous Improvement (10)
Bullet Images from 2020-10-09 >>
 
Bullet Investigation - Frozen job queue following start of autoguide operations
 

Session Aims & Highlights (2020-10-09)

Main aims

  1. Autoguide Monitoring / Charts. Check that autoguide monitoring / charts are now working correctly following revision to PHD2 Messaging Routines made in AstroMain 3.30.3
  2. Targets.  Acquire images of a selection of deep sky targets
  3. Bug fixes.  Check that bugs discovered in last session in AstroMain 3.30.3 have been fixed.

Equipment & Software

Highlights

Lowlights

Summary Plots & Logs

Observing Plan
Image
  
Observing Result
Image
   
Dome & Scope Slewing Performance
Image
  
Slew/Centering Performance
Image
  
Guiding Performance
Image
Image
  
Sky Conditions (Locate Frames)
Image
  
Night Sky Summary Plot
Top axis: Sky Brightness at Zenith (in ADU/s)
Lefthand axis: Local Time (hh LT). Righthand axis: Sun Altitude (degs)
Image   
  
Pre-Session Weather Forecast (API data from darksky.net)
Pre-Session Weather forecast showed initial wet and cloudy conditions (64-93% cloud cover),
gradually improving to become failry clear from 01:00 onwards (15-23% cloud cover)
Wind (13-16 mph), Minimum temperature 12°C by dawn

In the event conditions were initial showery with rain at 19:00 and 21:30.
Sky clear and dry between 21:40 and  01:00 allowing observing session to take place.
Cloud developed rapidly at 01:10 and ended the night's observing. Rain from 03:00 to 04:40.
Image
Image   
  
Session Event Log
Time     Event Detail
21:59:12 Session Monitoring AutoStart monitoring for Live Session opportunity starting between 21:59 & 05:38
21:59:14   AutoStart Delayed Session delayed due to cloud
21:59:29 Session AutoStarting Session autostarting (21:59)
21:59:59 Session Created Live Session Created (2020-10-09 S00818, ImageSaveNum: 818001)
22:00:02   Scope Switched On Telescope Power has been switched on via UPB Powerbox.
22:01:51   Services Started Observatory Services started
22:02:00 Observatory (Auto) Observatory placed in Fully-Automated Mode
22:02:04 Session Pending Session pending (2020-10-09)
22:02:06 Session Initiating Session initiating (2020-10-09)
22:02:08   Plan Requested Observing Plan requested from AstroPlan (1.16.5)
22:02:34   Plan Loaded Observing Plan loaded to queue (2020-10-09 V1 BEST PLAN, Plan ID: 553)
22:02:46   Camera1 Connected SBIG Camera Connected (set point -20°C)
22:02:52   Telescope Connected Telescope Connected (TheSky6)
22:03:02 Session Equilibration Session ready for dome & camera equilibration
22:05:50   Dome Opened Dome opened (opening time 45s)
22:05:53   Equilibration Started Dome Equilibration started
22:10:05   Equilibration Ended Dome Equilibration ended (4.3 mins total)
22:10:07 Session Running Session running
22:10:09   Queue Started Observing Queue started (26 targets selected)
22:11:19       Focusing Started-Foc1 Foc1 Focusing Started (TCF-S)
22:15:50       Focusing Completed Foc1 AutoFocus Completed (Profile No 1)
22:18:30       Focusing Completed Foc1 AutoFocus Completed (Profile No 1)
22:18:32       Focusing Started-Foc2 Foc2 Focusing Started (Secondary Scope, using ShCap)
22:20:55       Focusing Completed Foc2 AutoFocus Completed (Profile No 2, wide)
22:22:56       Focusing Completed Foc2 AutoFocus Completed (Profile No 2)
22:23:14       Focusing Checked Foc2 Focusing Check Succeeded
22:23:17     Target Started (1/26) Target started (1/26, 61 Cyg)
22:36:32   Dome Closed Dome closed (closing time 50s)
22:37:33   Dome Parked Dome moved to Az 90 deg (Park Position)
22:41:00 User Intervention User intervention to unlock frozen job queue and restart
22:41:02 Observatory (Manual) Observatory placed in Manual Mode
22:42:20 Observatory (Auto) Observatory placed in Fully-Automated Mode
22:42:23 Session Pending Session pending (2020-10-09)
22:42:25 Session Initiating Session initiating (2020-10-09)
22:42:26   Camera1 Connected SBIG Camera Connected (set point -20°C)
22:42:27   Plan Loaded Observing Plan loaded to queue (2020-10-09 V1 ACTIVE PLAN S818, Plan ID: 553)
22:42:31   Telescope Connected Telescope Connected (TheSky6)
22:42:41 Session Equilibration Session ready for dome & camera equilibration
22:43:28   Dome Opened Dome opened (opening time 47s)
22:43:31   Equilibration Started Dome Equilibration started
22:43:33   Equilibration Skipped Dome Equilibration skipped by user
22:43:35 Session Running Session running
22:43:37   Queue Started Observing Queue started (25 targets selected)
22:43:39     Target Started (2/26) Target started (2/26, GCVS SS Cyg)
22:49:19     Target Completed Target partially completed (2/26, GCVS SS Cyg)
22:49:21     Target Started (3/26) Target started (3/26, NGC 6978)
22:52:00       Focusing Failed Foc1 Focusing Failed - star is lost (TCF-S)
23:09:34     Target Completed Target completed (3/26, NGC 6978)
23:09:36     Target Started (4/26) Target started (4/26, UGC 12304)
23:11:07       Focusing Started-Foc1 Foc1 Focusing Started (TCF-S)
23:13:45       Focusing Completed Foc1 AutoFocus Completed (Profile No 3)
23:29:14     Target Completed Target completed (4/26, UGC 12304)
23:29:17     Target Started (5/26) Target started (5/26, NGC 7722)
23:31:07       Focusing Failed Foc1 Focusing Failed - star is lost (TCF-S)
23:43:23     Target Completed Target completed (5/26, NGC 7722)
23:46:27     Target Started (6/26) Target started (6/26, NGC 514)
23:58:56   Dome Closed Dome closed (closing time 46s)
23:59:28   Dome Parked Dome moved to Az 90 deg (Park Position)
23:59:29 User Intervention User intervention to unlock frozen job queue and restart
23:59:30 Observatory (Manual) Observatory placed in Manual Mode
23:59:42 Observatory (Auto) Observatory placed in Fully-Automated Mode
23:59:46 Session Pending Session pending (2020-10-09)
23:59:48 Session Initiating Session initiating (2020-10-09)
23:59:49   Camera1 Connected SBIG Camera Connected (set point -20°C)
23:59:50   Plan Loaded Observing Plan loaded to queue (2020-10-09 V1 ACTIVE PLAN S818, Plan ID: 553)
23:59:54   Telescope Connected Telescope Connected (TheSky6)
00:00:04 Session Equilibration Session ready for dome & camera equilibration
00:00:51   Dome Opened Dome opened (opening time 47s)
00:00:54   Equilibration Started Dome Equilibration started
00:00:56   Equilibration Skipped Dome Equilibration skipped by user
00:00:58 Session Running Session running
00:01:00   Queue Started Observing Queue started (21 targets selected)
00:01:02     Target Started (6/26) Target started (6/26, NGC 514)
00:08:50 User Intervention User intervention to unlock frozen job queue and restart
00:08:52     Target Failed Target failed due to aborted (6/26, NGC 514)
00:08:54   Queue Aborted Job Queue aborted
00:08:56 Observatory (Manual) Observatory placed in Manual Mode
00:09:08 Observatory (Auto) Observatory placed in Fully-Automated Mode
00:09:10 Session Pending Session pending (2020-10-09)
00:09:11   Camera1 Connected SBIG Camera Connected (set point -20°C)
00:09:12 Session Initiating Session initiating (2020-10-09)
00:09:14   Plan Loaded Observing Plan loaded to queue (2020-10-09 V1 ACTIVE PLAN S818, Plan ID: 553)
00:09:16   Telescope Connected Telescope Connected (TheSky6)
00:09:27 Session Equilibration Session ready for dome & camera equilibration
00:09:30   Equilibration Started Dome Equilibration started
00:09:32   Equilibration Skipped Dome Equilibration skipped by user
00:09:34 Session Running Session running
00:09:36   Queue Started Observing Queue started (20 targets selected)
00:09:38     Target Started (7/26) Target started (7/26, UGC 12423)
00:11:08       Focusing Started-Foc1 Foc1 Focusing Started (TCF-S)
00:14:06       Focusing Completed Foc1 AutoFocus Completed (Profile No 4)
00:30:12     Target Completed Target completed (7/26, UGC 12423)
00:30:14     Target Started (8/26) Target started (8/26, WDS GRB 34)
00:32:55       Focusing Started-Foc1 Foc1 Focusing Started (TCF-S)
00:35:49       Focusing Completed Foc1 AutoFocus Completed (Profile No 5)
00:37:22     Target Completed Target completed (8/26, WDS GRB 34)
00:37:24     Target Started (9/26) Target started (9/26, GCVS RX And)
00:39:08       Focusing Started-Foc1 Foc1 Focusing Started (TCF-S)
00:41:46       Focusing Completed Foc1 AutoFocus Completed (Profile No 6)
00:44:18     Target Completed Target completed (9/26, GCVS RX And)
00:44:20     Target Started (10/26) Target started (10/26, UGC 1178)
00:46:14       Focusing Started-Foc1 Foc1 Focusing Started (TCF-S)
00:49:24       Focusing Completed Foc1 AutoFocus Completed (Profile No 7)
01:05:07     Target Completed Target completed (10/26, UGC 1178)
01:05:09     Target Started (11/26) Target started (11/26, GCVS HH And)
01:10:24   SoftSuspend Called Soft Suspend is called due to Deteriorating Conditions (too few stars)
01:11:02 User Intervention User intervention to unlock frozen job queue and restart
01:11:04     Target Failed Target failed due to aborted (11/26, GCVS HH And)
01:11:06   Queue Aborted Job Queue aborted
01:11:19 Observatory (Auto) Observatory placed in Fully-Automated Mode
01:11:21 Session Pending Session pending (2020-10-09)
01:11:22   Camera1 Connected SBIG Camera Connected (set point -20°C)
01:11:23 Session Initiating Session initiating (2020-10-09)
01:11:25   Plan Loaded Observing Plan loaded to queue (2020-10-09 V1 ACTIVE PLAN S818, Plan ID: 553)
01:11:27   Telescope Connected Telescope Connected (TheSky6)
01:11:38 Session Equilibration Session ready for dome & camera equilibration
01:11:41   Equilibration Started Dome Equilibration started
01:11:43   Equilibration Skipped Dome Equilibration skipped by user
01:11:45 Session Running Session running
01:11:47   Queue Started Observing Queue started (16 targets selected)
01:11:49     Target Started (11/26) Target started (11/26, GCVS HH And)
01:15:30 User Intervention User intervention to unlock frozen job queue and restart
01:15:31     Target Aborted (11/26) Target aborted (11/26, GCVS HH And) due to User Intervention
01:15:33   Queue Paused Queue paused for SoftSuspend
01:15:35 Session Suspended Session suspended
01:16:25   Dome Closed Dome closed (closing time 50s)
01:28:44     Target Cancelled Target cancelled (12/26, M31_AT2020vak) due to cloud
01:43:20     Target Cancelled Target cancelled (13/26, GCVS U And) due to cloud
02:04:12     Target Cancelled Target cancelled (14/26, NGC 596) due to cloud
02:26:34     Target Cancelled Target cancelled (15/26, NGC 615) due to cloud
02:48:56     Target Cancelled Target cancelled (16/26, NGC 772) due to cloud
03:05:45   Camera1 SetPoint SBIG Camera Set Point Temperature Updated (new set point -15°C)
03:11:18     Target Cancelled Target cancelled (17/26, NGC 779) due to rain
03:33:40     Target Cancelled Target cancelled (18/26, UGCA 25) due to rain
03:46:18     Target Cancelled Target cancelled (19/26, GCVS DY Per) due to cloud
03:55:14     Target Cancelled Target cancelled (20/26, GCVS GK Per) due to rain
04:10:51     Target Cancelled Target cancelled (21/26, UGC 6930) due to rain
04:32:13     Target Cancelled Target cancelled (22/26, UGCA 105) due to rain
05:13:54     Target Cancelled Target cancelled (23/26, NGC 2158) due to cloud
05:26:35     Target Cancelled Target cancelled (24/26, Nova AT2020bfc) due to cloud
05:46:46     Target Cancelled Target cancelled (25/26, Scholz's Star) due to cloud
06:18:08     Target Cancelled Target cancelled (26/26, NGC 2782) due to cloud
06:18:13   Queue Completed Job Queue completed
06:18:18 Session Closing Session closing
06:18:22   Dome Closed Dome already closed (closed at 01:16, closing time 50s)
06:19:38   Dome Parked Dome parked (parking time 74s), Az: 90.0 deg
06:20:28   Telescope Parked Telescope parked (parking time 44s)
06:20:58   Telescope Switched Off Telescope Power has been switched off via UPB Powerbox.
06:21:49   Services Stopped Night Services stopped
06:21:51 Session Housekeeping Housekeeping Started (Cleanup FITS, Create Fits Summary, Transfer Files)
06:21:58 Session Finished Session Finished
 
Session Alerts
Time     Alert Detail
-- No Alerts                --                              
 

Back to Top


Operational Issues (2020-10-09 S818)

[ Prev | Next ]

Critical Issues

Major Issues

Minor Issues

Continuous Improvement

[ Prev | Next ]

Back to Top


Investigation - Frozen job queue following start of autoguide operations

Issue
Job Queue frooze around end of centering / start of autoguiding of Target 1/26 (61 Cyg)  leading to Obs.Overseer making the observatory safe whilst autoguiding/monitoring continued with multiple 'star lost' messages reported.  

Description
Last IamAlive message was from ExecuteTarget/CenterTarget/ at 22:25.  Abort Target, Abort Job wouldn't work. Manually aborted PHD2 guiding and moved AstroMain to Manual and manually used the 'Kill Job' backdoor button to kill the Job Queue task. Restarted Automated mode without closing the program (a calculated risk / experiment).   Target 2/26 (SS Cyg) and Target 3/26 (NGC 6978) successfully acquired.

The last few log messages , would seem to confirm that Centering had finished and operations had moved onto to AutoGuiding in preparation for focusing/imaging.
22:25:08.65 | 61 Cyg                Continue       Ok   | IamAlive: CentreTarget
22:25:08.66 | 61 Cyg                CenterTarget   Ok   | IamAlive: ExecuteTarget
22:25:08.66 | 61 Cyg                Session.Slew   Info | Starting SaveSlewFileToLiveFolder
22:25:09.23 | Observatory           PHD2           Info | Connect PHD2 Devices
22:25:09.48 | Observatory Services  Get GuideRate  Ok   | 0.003763944 (0.90)

The same issue happened with Target 6/26 (NGC 514), where job queue again stopped at the same point. Again the same manual method was used to resume session.

The PHD2 Graph suggests that problem happened before Dec Drift Direction / Required Dec Guide Direction was determined and set. 

The same issue happened again when Target 6/26 (NGC 514) was restarted., and then again later on with Target 11/26 (HH And)  These times the job queue was aborted using 'Abort Job' button before the Obs.Overseer intervened to make the observatory safe (allowing a faster restart).

Analysis
Hypothesis is that Job Executor calls 'Guider.StartGuider, but execution doesn't return for some reason and/or some finished flag isn't set or not read..   Multiple 'Star ...    Fail      Star lost - low HFD"  messages more than 10 mins after Job Queue is believed to have frozen indicate that the 'Guider.StartPHD2Guiding' is still running.  Report records shows that the scope hasn't exit the routine and  started the Focusing stage. Within StartPHD2Guiding routine the execution enters a Do While bGuideMethodFinished = false' loop where it appears that bGuideMethodFinished is never set to True and the execution remains locked in the loop giveing the outside appearance that the Job Queue has frozen. The only conditions in which bGuideMethodFinished is set to True are if a SettleDone event is received or an error Response is received.  

Examining  the PHD2 Message Log messages associated with 61 Cyg  the Guide request was made at 22:25:10
    {"method": "guide", "params": [{"pixels": 2.0, "time": 6, "timeout": 10}, false], "id": 36}
for which there was a 'SettleDoneEvent'  27s later at 22:25:37.48
   {"Event":"SettleDone","Timestamp":1602278737.469,"Host":"LAPTOP9_CHILL","Inst":1,"Status":0,"TotalFrames":4,"DroppedFrames":0}
however it was superseded by a following "GuideStep" event just  30ms later at 22:25:37.51

It is supposed that due to unfortunate timing issue (Guide Steps are typically 2600ms apart) the LastEvent variable wih SettleDone event was overwritten before if had been read, after which there was no way for the loop to be exited.

Fix
A fix has been attempted in AstroMain 3.30.5 by making PHD2 Listening Loop send events to an Event queue (qEvent) instead of an overwrittable LastEvent variable and editing PHD2.GetEvent read from this queue, ensuring that 'Do While bGuideMethodFinished = false' loop processes each Event received without missing any. As a further backup a timeout of  2 x  TimeOut of the Guide Method is used as additional condition to exit out of the StartPHD2Guiding routine.

After monitoring later sessions it was concluded that the fix had been successful.

Image Fixed 2020-10-10 (AstroMain 3.30.5).

Back to Top