David's Astronomy Pages Notes - Session 795 (2020-07-17)

Notes (S794)

Notes Main

Home Page

Notes (S796)

	Session Aims & Highlights
	- Observing Result  - Night Summary Plot  - Session Event Log
	Operational Issues
	- Critical Issues (0),  Major Issues (1),  Minor Issues (4),  Continuous Improvement (2)
	Images from 2020-07-17 >>
	Investigation: Obs.Manager freezing upon entering Closing State

Session Aims & Highlights (2020-07-17)

Main aims

1. Dome Driver. Test out dome driver under Device Hub control. Look for any glitches which had hampered the previous two sessions (S792 & S793) that were under DeviceHub control
2. Targets. Aquire variety of targets if conditions allow

Equipment & Software

• 12" LX200 and ST-10XME
• 80mm APO and ZWO ASI 178MC
• CCDApp2, TheSky6, CCDSoft5, PHD2,  DeviceHub 4.6.1.10, UPB 1.5 
• Pegasus UPB & Motor Focus, TCF-S
• SharpCap 3.2, PHD2  2.6.8
   
• AstroMain 3.25.9,  AstroGuard 1.4.2,   AstroPlan 1.15.3,  AstroShCap 1.2.22, AstroVOE 1.3.6
  (AstroWeather 1.10.8, AstroAllSky 3.6)
  

Highlights

•  Dome Driver.   No repeat of the dome driver issue that had hampered the previous two sessions.
• Supernova in M85. Images of Supernova in M85 were acquired

Lowlights

• None

Summary Plots & Logs

Observing Plan

Observing Result (Southern targets added as ToO targets)

Dome & Scope Slewing Performance

Slew/Centering Performance

Guiding Performance

Sky Conditions (Locate Frames)

Night Sky Summary Plot Top axis: Sky Brightness at Zenith (in ADU/s) Lefthand axis: Local Time (hh LT). Righthand axis: Sun Altitude (degs)

Pre-Session Weather Forecast (API data from darksky.net) Pre-Session Weather forecast showed moderate cloud (68-72% cloud cover) in first part of night improving towards dawn (29-39% cloud cover) with light wind (5 - 7 mph) , no rain and a minimum temperature of 7°C. In the event conditions were clear the whole night (though a bit hazy) with a minimum temperature of 5°C

Session Event Log

Time     Event Detail 22:43:40   Camera1 Connected SBIG Camera Connected (set point -15°C) 22:43:42 Session Created Live Session Created (2020-07-17 S00795, ImageSaveNum: 795001) 22:43:52   Services Started Observatory Services started 22:44:13 Observatory (Auto) Observatory placed in Fully-Automated Mode 22:44:16 Session Pending Session pending (2020-07-17) 22:44:18 Session Initiating Session initiating (2020-07-17) 22:44:20   Plan Loaded Observing Plan loaded to queue (2020-07-17 V1 BEST PLAN, Plan ID: 525) 22:44:22   Camera1 Connected SBIG Camera Connected (set point -10°C) 22:44:28   Telescope Connected Telescope Connected (TheSky6) 22:44:39 Session Equilibration Session ready for dome & camera equilibration 23:16:18   Dome Opened Dome opened (opening time 45s) 23:16:21   Equilibration Started Dome Equilibration started 23:29:34   Equilibration Ended Dome Equilibration ended (13.3 mins total) 23:29:36 Session Running Session running 23:29:38   Queue Started Observing Queue started (13 targets selected) 23:30:32       Focusing Started-Foc1 Foc1 Focusing Started (TCF-S) 23:33:13       Focusing Completed Foc1 AutoFocus Completed (Profile No 1) 23:33:16       Focusing Started Foc2 Focusing Started (Secondary Scope, using ShCap) 23:35:50       Focusing Failed Foc2 Focusing Failed - failed QC check (Quadratic) 23:35:53     Target Started (1/13) Target started (1/13, HIP 87937) 23:38:37       Focusing Started-Foc1 Foc1 Focusing Started (TCF-S) 23:41:38       Focusing Completed Foc1 AutoFocus Completed (Profile No 3) 23:43:21     Target Completed Target partially completed (1/13, HIP 87937) 23:43:23     Target Started (2/13) Target started (2/13, GCVS CY Lyr) 23:45:26       Focusing Failed Foc1 Focusing Failed - star is lost (TCF-S) 23:50:48     Target Completed Target completed (2/13, GCVS CY Lyr) 23:50:50     Target Started (3/13) Target started (3/13, NGC 6928) 23:53:31       Focusing Started-Foc1 Foc1 Focusing Started (TCF-S) 23:56:10       Focusing Completed Foc1 AutoFocus Completed (Profile No 4) 00:12:12     Target Completed Target completed (3/13, NGC 6928) 00:12:14     Target Started (4/13) Target started (4/13, NGC 6962) 00:15:02       Focusing Started-Foc1 Foc1 Focusing Started (TCF-S) 00:18:05       Focusing Completed Foc1 AutoFocus Completed (Profile No 5) 00:34:08     Target Completed Target completed (4/13, NGC 6962) 00:34:10     Target Started (5/13) Target started (5/13, IC 1365) 00:37:35       Focusing Started-Foc1 Foc1 Focusing Started (TCF-S) 00:40:43       Focusing Completed Foc1 AutoFocus Completed (Profile No 6) 00:56:54     Target Completed Target completed (5/13, IC 1365) 00:56:56     Target Started (6/13) Target started (6/13, IC 1370) 00:59:45       Focusing Started-Foc1 Foc1 Focusing Started (TCF-S) 01:02:45       Focusing Completed Foc1 AutoFocus Completed (Profile No 7) 01:18:56     Target Completed Target completed (6/13, IC 1370) 01:18:58     Target Started (7/13) Target started (7/13, UGC 12040) 01:20:49       Focusing Started-Foc1 Foc1 Focusing Started (TCF-S) 01:23:49       Focusing Completed Foc1 AutoFocus Completed (Profile No 8) 01:39:54     Target Completed Target completed (7/13, UGC 12040) 01:40:33     Target Started (8/13) Target started (8/13, Basel 14) 01:43:21       Focusing Started-Foc1 Foc1 Focusing Started (TCF-S) 01:46:02       Focusing Completed Foc1 AutoFocus Completed (Profile No 9) 01:52:08     Target Completed Target completed (8/13, Basel 14) 01:52:33     Target Started (9/13) Target started (9/13, GCVS SS Cyg) 01:55:04       Focusing Started-Foc1 Foc1 Focusing Started (TCF-S) 01:57:42       Focusing Completed Foc1 AutoFocus Completed (Profile No 10) 02:01:14     Target Completed Target completed (9/13, GCVS SS Cyg) 02:07:45     Target Started (10/13) Target started (10/13, Berkeley 101) 02:10:16       Focusing Started-Foc1 Foc1 Focusing Started (TCF-S) 02:12:54       Focusing Completed Foc1 AutoFocus Completed (Profile No 11) 02:18:31     Target Completed Target completed (10/13, Berkeley 101) 02:19:44     Target Started (11/13) Target started (11/13, GCVS HH And) 02:21:44       Focusing Started-Foc1 Foc1 Focusing Started (TCF-S) 02:24:44       Focusing Completed Foc1 AutoFocus Completed (Profile No 12) 02:26:27     Target Completed Target completed (11/13, GCVS HH And) 02:27:59     Target Started (12/13) Target started (12/13, WDS GRB 34) 02:30:23       Focusing Started-Foc1 Foc1 Focusing Started (TCF-S) 02:33:03       Focusing Completed Foc1 AutoFocus Completed (Profile No 13) 02:34:53     Target Completed Target completed (12/13, WDS GRB 34) 02:36:14     Target Started (13/13) Target started (13/13, GCVS RX And) 02:38:15       Focusing Started-Foc1 Foc1 Focusing Started (TCF-S) 02:41:05       Focusing Completed Foc1 AutoFocus Completed (Profile No 14) 02:43:39     Target Completed Target completed (13/13, GCVS RX And) 02:43:42   Queue Completed Job Queue completed 03:23:00 User Intervention User intervention to close & park dome

Session Alerts

Time     Alert Detail -- No Alerts                --

Back to Top

Operational Issues (2020-07-17, S795)

• Critical Issues (0)
• Major Issues (1)
• Minor Issues (4)
• Continuous Improvement (2)

[ Prev | Next ]

Critical Issues

• None

Major Issues

• AstroMain UI, Obs.Manager, Obs.Worker hung immediately after the session entered closing state (2020-07-17, S795). Job Manager finished plan and the session entered closing state at 02:43.  Before beginning to Check Shutter/Park Dome etc, the program effectively hung.    Program has hung/crashed at a similar point in the past (eg S740, S763). In the event the Shutter remained open for 40 minutes until session was checked remotely. Conditions were good and were being monitored by AstroGuard & Cloud Sensor Relays.  Status of observatory was checked via website/remote connection at 03:15. Finding the  session was still active and after making appropriate lock-down screen captures at 03:21, the Dome was closed & parked via AstroGuard program at 03:23 and the Telescope parked from the DeviceHub at around 03:30.  Log file contained no error messages, other than messages indicating the time when particular threads become unresponsive or frozen.  How can the root cause to this issue be found ?    What happens when code begins to execute Closing.    Issue closed on 2021-01-04 following a review that showed that the AstroMain was essentially stable (following a series of improvements and fixes), with an absence of any unexplained program hangs or crashed during the 35 sessions between  2020-09-18 & 2021-01-03.
  Closed 2021-01-04 (AstroMain)

Minor Issues

• Best Focus Graph started at 23:00 whilst Focus Temperature, Zenith FWHM & CCD Temperature charts all started at 22:00. BestFocusChart is started by first call to AddData made from MeasureFocusProfile_Foc1() using DateX = Now().   DateX is used to set graph's StartTime unless MasterGraphStartTime has been set (ie <> vcNullDate) in which case StartTime is set to MasterGraphStartTime.  2020-07-17 S00795 (Session) was first created at 22:32 and after initial services started  MasterGraphSetTime must have been set to 22:00 when the first of the 3 other graph types was first created at c. 22:33 which was around the time that MonitorFile was first written to.  Due to a mix up deleting attempted session 2020-07-13 S00795 which caused a problem with the session displayed on the observing plan for 2020-07-17 V1 Best Plan, the session was stopped at 23:41, the S00795 session was deleted in AstroPlan, and the 2020-07-17 S00795 (Session) was created again at 22:43.  MasterGraphSetTime would have been reset to null (ie vcNullDate) when AssignObservatorySession was re-called.  The final SessionDate file has MasterGraphSetTime of 23:00 which indicates MasterGraphSetTime must have had vcNullDate at time that BestFocusGraph.StartChart was called (~23:33).    This issue has arisen due to an abnormal situation that shouldn't have arisen if correct user procedures had been used.
  Closed 2020-07-19 (User Awareness)
   
• NGC 6928 Locate 2 Frame (0.6' pointing error) looks further off target than its 0.6' annotated error suggests.  Examining report file :  Target 3/13 (NGC 6928) Centering 2 Locate Frame (Image 00795015). Reviewing position (2)... Ok Pointing Error: 0.57 arc mins (W: 0.56', N: -0.11') .   Frame 795015_sm.jpg (x0.52 scale) shows the 'target' positioned  at CenterX +5 px, CenterY +44 px equivalent to a pointing error of 1.99 arc mins (W 0.23',   N  -1.98' ) .  This would normally dictate a Yellow cross (1' to 3') rather than the Green cross (<1') used on the Locate frame picture.    Target Cross is positoned at GalaxyX + 0 px, GalaxyY -32 px equivalent to an offset of W: 0', N: -1.5'.
  Reviewing Centering 1 (Image 00795014):  Reviewing position (1)... Ok Pointing Error: 1.33 arc mins (W: -1.14', N: -0.67')
  Frame 795015_sm.jpg uses a yellow cross (1' to 3') as expected but shows the  target positioned (at  CenterX -24 px, CenterX +57 px) equivalent to a pointing error of W: -1.08',   N:  -2.56' .  Target Cross is again positoned at GalaxyX + 0 px, GalaxyY -32 px equivalent to an offset of W: 0', N: -1.5'. 
  It is suspected that the target's non-zero centre offset (W 0.0' N -1.5'  in the case of NGC 6928 target) might be a factor in the issue.   At the time a slew adjustment of W: 0.5, N: 1.5 [arc mins] was being used but this should be irrelevant for the Second Centering (Locate Frame 2).  It seems that Locate Frame picture is plotting the correct target point (including offsets from target Object),  but the pointing error is being incorrectly determined.
  A similar issue might be expected with Target 4/13 (NGC 6962) with target offset of  W: 0.0, N 2.2 [arc mins]. It's target cross is drawn at GalaxyX +0 px, GalaxyY +50 px.  equivalent to W: 0', N: 2.25',  but in its Locate 2 frame (pointing error: 0.71 arc mins (W: -0.70', N: -0.14'), target cross is at CentreX - 16 px, CenterY + 3px equivalent to pointing error of 0.73 arc min (-0.72',  N: - 0.14'), which is consistent.    In NGC 6982 the north offset (2.2') is +ve, whilst for NGC 6928 the north offset is -ve (-1.5') is this the difference ? It doesn't seem so since Target 2/13 (GCVS CY Lyr) has a -ve north target (-1.6') but doesn't suffer from the issue. 
  Issue no longer present when images original FITS file 'replayed'  using AstroMain 3.36. Issue considered to be fixed/closed
  Closed 2021-02-07 (AstroMain 3.36)
   
• DeviceHub showing dome at 90.6deg when slewed to 90.5deg and showing as 90.1 deg when parked (90.0).   Investigating Pulsar ASCOM trace logs shows that DeviceHub is send requests to Dome correctly (e.g slew to 95 leads to dome slewing to 95.1) as shown by Volatile lines. Rebooting the Dome Controller didn't resolve the issue. After noticing that the two halves of the induction charger weren't aligned when dome was parked, it was evident that there had probably been some slippage of the dome encoder wheel.   Issue was fixed by recalibrating the dome.
  Fixed 2020-07-18 (Observatory, Pulsar Dome)
   
• UPB EnvTemp and (Foc1) Tube Temperature flat-lined at 02:43. Other monitoring CCD Properties, Weather data functioned as per normal. MonitorEnvTemperature is set by  PowerBox.GetEnvSensorData() routine, which is called by the Observatory Monitoring Thread ( RunObservatoryMonitoring() ).  This thread also sets MonitorFoc1AvTemperature.    Issue closed as time flat-lining started corresponded precisely with the time that Obs.Worker along with Obs.Manager and UI froze.   
  Closed (AstroMain, Session)

Continuous Improvement

• Check that Dome is exactly at 90.0 deg when Parked.  A difference of 0.1 deg (eg 90.1) is enough to indicate that dome encoder has slipped,  causing a potential misalignment of the two parts of the induction charger and indicating that a recalibration of the dome may be required. 
  Done 2020-07-19 (AstroMain 3.26)
   
• Extend Obs.Overseer code to include checking whether Obs.Monitoring is running ok and isn't frozen. 
  Done 2020-07-19 (AstroMain 3.26)

[ Prev | Next ]

Back to Top

Investigation: Obs.Manager freezing upon entering Closing State

Issue : Session S795 became frozen at 02:43 just after entering Closing state.     

Details : Job Manager finished the observing plan at ~ 02:42/02:43 and the session entered closing state at 02:43.  Before beginning to Close Shutter/Park Dome etc, the program effectively hung.  Program has hung/crashed at a similar point in the past (eg S740, S763). In the event the Shutter remained open for 40 minutes until session was checked remotely.
 
Conditions were good and were being monitored by AstroGuard & Cloud Sensor Relays.  Status of observatory was checked via website/remote connection at 03:15. Finding the  session was still active and after making appropriate lock-down screen captures at 03:21, the Dome was closed & parked via AstroGuard program at 03:23 and the Telescope parked from the DeviceHub at around 03:30.  Log file contained no error messages, other than messages indicating the time when particular threads become unresponsive or frozen.  How can the root cause to this issue be found ?    What happens when code begins to execute Closing

AstroMain Report Logs (S795)

Logs show the following :

AstroMain ObsPics (S795)
Final ObsPic is from 02:43:16 and shows session still running and operating on Target GCVS RX And.  The dome is open and positioned with shutter at Az 93deg and slaved to Telescope. The telescope is tracking and at Az 90 deg, Alt 51 deg. Conditions are good.

AstroGuard (S795)
AstroGuard log shows the dome opening at 23:15. Later on (under User Intevention) the log shows the dome closing and parking at 03:23

Data (S740)

Program appears to freeze at precisely the same point at start of closing (07:06)

Data (S763)

Program appears to freeze at precisely the same point at start of closing (04:50)

Normal Data (S791)

Although the issue has arisen in S795, S763 and S740, in the vast majority of sessions the issue hasn't arisen. Therefore it must be concluded that the bug is subtle and is condition or timing dependant in some way.

Code Review

 Sub SetState_Closing()
'================

' Give one final chance for Job Queue to finish running
' ----------------------------------------------------
If RunningFrameJobs Then
  If jobAbort = False Then
    objConsole.AbortJobExplicit()
  End If

  Sleep(4) ' << give time for Job To finishing Aborting

End If

' Switch State to Closing
' -----------------------
SessionState = SessionState.Closing

WriteLogFile(StarBreak)
WriteLogFileRecord("Observatory Manager", "Info", "Change State", "Session Closing")   ' <<<< Executed okay

Session.DeltaMinsFromPlan = vcNull

' Set Session End Time
' --------------------
Session.EndTime = Now()

' Report Session State
' --------------------
ReportLine()
ReportTitle("Session Closing")        ' <<<< Executed okay
UpdateStatusNote("Session Closing...")    ' routine calls two invoke methods so should be okay

ReportComment("")    ' <<<< Not executed  (or at least not written to file)
ReportComment(LAlign2_Special(Tab2 + "<u>" + FillText("Begin Shutdown") + "</u>", 37) _
   + LPad10("Ok") + LPad18(Session.Name) + "(Session)")     ' <<<< Not executed  (or at least not written to file)


' Event
' --------
StoreSessionEvent("Session Closing", 1, FlagState.Green, "Session closing")     ' <<<< Not executed (at least not written to database)
SetFlagChanged("Session", 0) ' Signal to AstroPlan to upload revised ObservingResult Chart

' Reset Variables
' ---------------
ParkingInitiated = False
bParkingDome = False
bParkingScope = False

ClosingStageNo = 0
FinalCloseShutterAttempts = 0

Scope.ResetLastGetRaDecException()

End Sub

Session freezes before SetState_Closing is finished,  but there doesn't seem to a bug in the code executed, or obvious point where execution would obviously need to be wait for  significant time or to freeze waiting on other process.   The Obs.Manager has 10 points within the main loop from where SetState_Closing () can be called, so if SetState_Closing() did freeze it would have the affect of freezing the Obs.Manager.

Another possibility is that a freeze to the UI (objConsole) could cause UpdateStatusNote () to freeze.

Another possibility is that another thread (ObsWorker, etc) freezes when it mets a specific condition when  SessionState = SessionState.Closing

Conclusion
.

Recommendation

- Add trace code to manager.vb that allow execution of each and every line in SetState_Closing () to be followed   (More Data).   Done 2020-07-20 (AstroMain 3.26)

- See if it possible to replicate frozen program but special tests that cycles from running to closing multiple times  (More Data)

- Consider always starting Live Sessions from a clean program start (Potential Prevention)

- Alter Obs.Overseer code so that if Obs.Manger becomes frozen during Closing, then this situation is passed to AstroGuard so that it can take the appropriate action to close and park dome and park scope.   (Mitigation)

Back to Top