David's Astronomy Pages
Notes - Session 878 (2021-03-31)

 
Bullet Session Aims & Highlights
 - Observing Result
 - Night Summary Plot
 - Session Event Log
 
Bullet Operational Issues
  - Critical Issues (0),  Major Issues (1),  Minor Issues (0),  Continuous Improvement (2)
Bullet Images from 2021-03-31 >>     [ Local Files >> ]
Bullet Pulsar Dome - Software Update (Shutter 1.25)
Bullet Investigation - AstroMain Stalls When Importing Observing Plan

Session Aims & Highlights (2021-03-31)

Main aims

  1. Pulsar Shutter. Test out  new v1.25 of Pulsar Shutter Software/Driver
  2. AstroMain  Test out v 3.38.11, Check bug fixes and new features
  3. Targets. Acquire images of a selection of variable stars, nearby stars, comets & deep sky targets as allowed by conditions

Equipment & Software

Highlights

Summary Plots & Logs

Observing Plan
Image
  
Observing Result
Image
   
Dome & Scope Slewing Performance
Image
  
Slew/Centering Performance
Image
  
Guiding Performance
Dec Notes :
Run 11 (black) failed due to cloud during settling period and setting too short (frame 1 started before selection of Dec Guide Mode)
Run 3 (red) impacted by wrong Dec Guide Mode (should have used South Mode, instead of North Mode)
Run 4 (red) impacted by periods of ineffective Dec guiding
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   
  
Actual Weather vs Pre-Session Weather Forecast
Image
Image   
  
Session Event Log
Time     Event Detail
23:26:18 Session Monitoring AutoStart monitoring for Live Session opportunity starting between 23:26 & 04:38
23:26:21 Session AutoStarting Session autostarting (23:26)
23:26:52 Session Created Live Session Created (2021-03-31 S00878, ImageSaveNum: 878001)
23:26:54   Scope Switched On Telescope Power has been switched on via UPB Powerbox.
23:28:53   Services Started Observatory Services started
23:29:01 Observatory (Auto) Observatory placed in Fully-Automated Mode
23:29:06 Session Pending Session pending (2021-03-31)
23:29:08 Session Initiating Session initiating (2021-03-31)
23:29:10   Plan Requested Observing Plan requested from AstroPlan (1.21.5)
23:33:51 Load Plan Loading plan had taken an unexpectedly long time (3 min)
23:33:53 Observatory (Manual) Observatory returned to Manual Mode
23:37:07   Telescope Switched Off Telescope Power has been switched off via UPB Switch.
23:37:36 Program Closed Program closed by User
23:38:00 User Intervention User intervention to restart observatory software including AstroMain
23:42:32 Session Monitoring AutoStart monitoring for Live Session opportunity starting between 23:42 & 04:38
23:42:37 Session AutoStarting Session autostarting (23:42)
23:43:08 Session Resumed Live Session Resumed (2021-03-31 S00878, ImageSaveNum: 878001)
23:43:10   Scope Switched On Telescope Power has been switched on via UPB Powerbox.
23:44:53   Services Started Observatory Services started
23:45:01 Observatory (Auto) Observatory placed in Fully-Automated Mode
23:45:02 Session Pending Session pending (2021-03-31)
23:45:04 Session Initiating Session initiating (2021-03-31)
23:48:03 Load Plan Loading plan had taken an unexpectedly long time (3 min)
23:48:05 Observatory (Manual) Observatory returned to Manual Mode
23:49:20 Program Closed Program closed by User
23:50:00 User Intervention User intervention to restart observatory software with rollback to AstroMain 3.38.10
23:57:43 Session Monitoring AutoStart monitoring for Live Session opportunity starting between 23:57 & 04:38
23:57:44   AutoStart Delayed Session delayed due to threat of rain
00:08:05 Session AutoStarting Session autostarting (00:08)
00:08:34 Session Resumed Live Session Resumed (2021-03-31 S00878, ImageSaveNum: 878001)
00:08:37   Scope Switched On Telescope Power has been switched on via UPB Powerbox.
00:10:21   Services Started Observatory Services started
00:10:30 Observatory (Auto) Observatory placed in Fully-Automated Mode
00:10:32 Session Pending Session pending (2021-03-31)
00:10:34 Session Initiating Session initiating (2021-03-31)
00:10:38   Plan Loaded Observing Plan loaded to queue (, Plan ID: 616)
00:10:52   Camera1 Connected SBIG Camera Connected (set point -20°C)
00:10:58   Telescope Connected Telescope Connected (TheSky6)
00:11:08 Session Equilibration Session ready for dome & camera equilibration
00:11:55   Dome Opened Dome opened (opening time 46s)
00:11:57 Session Running Session running
00:11:59   Queue Started Observing Queue started (19 targets selected)
00:13:12       Focusing Started-Foc1 Foc1 Focusing Started (TCF-S)
00:16:34       Focusing Completed Foc1 AutoFocus Completed (Profile No 1, wide)
00:18:32       Focusing Completed Foc1 AutoFocus Completed (Profile No 1)
00:18:35       Focusing Started-Foc2 Foc2 Focusing Started (Secondary Scope, using ShCap)
00:20:57       Focusing Completed Foc2 AutoFocus Completed (Profile No 2, wide)
00:22:47       Focusing Completed Foc2 AutoFocus Completed (Profile No 2)
00:23:03       Focusing Checked Foc2 Focusing Check Succeeded
00:23:11     Target Missed (1/19) Target's time slot was missed (1/19, Nova Per 2020 (CV))
00:23:13     Target Missed (2/19) Target's time slot was missed (2/19, AT2021gyc (CV))
00:23:15     Target Missed (3/19) Target's time slot was missed (3/19, AT2021dbp (CV))
00:23:17     Target Started (4/19) Target started (4/19, UGC 3502 w/SN2021cwc)
00:25:31   SoftSuspend Called Soft Suspend is called due to Deteriorating Conditions (too few stars)
00:26:56   SoftSuspend Cancelled Soft Suspend is cancelled due to Improved Conditions
00:31:13       Focusing Skipped Foc1 focusing skipped - unable to find a star (TCF-S)
00:32:11   SoftSuspend Called Soft Suspend is called due to Deteriorating Conditions (too few stars)
00:34:12 Critical Cloud Alert Critical Cloud Alert (Obs.Manager will close the Shutter)
00:34:14   HardSuspend Called Hard Suspend is called due to Critical Conditions (cloud)
00:34:17     Target Aborted (4/19) Target aborted (4/19, UGC 3502 w/SN2021cwc) due to cloud
00:34:19   Queue Paused Queue paused For Session Suspension
00:34:22 Session Suspended Session suspended
00:35:12   Dome Closed Dome closed (closing time 50s)
00:41:04     Target Cancelled Target cancelled (4/19, UGC 3502 w/SN2021cwc) due to cloud
00:41:27 Session Resuming Session resuming
00:42:12   Dome Opened Dome opened (opening time 45s)
00:42:14 Session Running Session running
00:42:16   Queue Resumed Observing Queue resumed
00:44:04     Target Started (5/19) Target started (5/19, NGC 4165 w/SN2021gno)
00:49:32       Focusing Started-Foc1 Foc1 Focusing Started (TCF-S)
00:51:33       Focusing Completed Foc1 AutoFocus Completed (Profile No 3)
01:07:37     Target Completed Target completed (5/19, NGC 4165 w/SN2021gno)
01:07:40     Target Started (6/19) Target started (6/19, NGC 5018 w/SN2021fxy)
01:12:26       Focusing Started-Foc1 Foc1 Focusing Started (TCF-S)
01:14:39       Focusing Completed Foc1 AutoFocus Completed (Profile No 4)
01:30:44     Target Completed Target completed (6/19, NGC 5018 w/SN2021fxy)
01:30:46     Target Started (7/19) Target started (7/19, NGC 3310 w/SN2021gmj)
01:35:03       Focusing Started-Foc1 Foc1 Focusing Started (TCF-S)
01:37:23       Focusing Completed Foc1 AutoFocus Completed (Profile No 5)
01:52:09   SoftSuspend Called Soft Suspend is called due to Deteriorating Conditions (too few stars)
01:52:34 Critical Cloud Alert Critical Cloud Alert (Obs.Manager will close the Shutter)
01:52:36   HardSuspend Called Hard Suspend is called due to Critical Conditions (cloud)
01:52:41     Target Aborted (7/19) Target aborted (7/19, NGC 3310 w/SN2021gmj) due to cloud
01:52:43   Queue Paused Queue paused For Session Suspension
01:52:46 Session Suspended Session suspended
01:53:34   Dome Closed Dome closed (closing time 50s)
02:05:02     Target Cancelled Target cancelled (8/19, UGC 6930 w/SN2020rcq) due to cloud
02:25:54     Target Cancelled Target cancelled (9/19, NGC 4227 w/SN2021biz) due to cloud
02:47:46     Target Cancelled Target cancelled (10/19, IC 863 w/SN2021foa) due to cloud
03:09:38     Target Cancelled Target cancelled (11/19, IC 992 w/SN2021dwg) due to cloud
03:23:30     Target Cancelled Target cancelled (12/19, AT2021gux (CV)) due to cloud
03:32:56     Target Cancelled Target cancelled (13/19, GCVS R CrB) due to cloud
03:52:03     Target Cancelled Target cancelled (14/19, MCG +11-22-33 w/SN2021eay) due to cloud
04:04:21     Target Cancelled Target cancelled (15/19, GCVS BL Lac) due to cloud
04:24:13     Target Cancelled Target cancelled (16/19, VV 807 w/AT2021fbu) due to cloud
04:31:03   UPB.Switch Restart UPB.Switch has been restarted.
04:35:49     Target Cancelled Target cancelled (17/19, GCVS SS Her) due to cloud
04:54:21     Target Cancelled Target cancelled (18/19, 7P/Pons-Winnecke) due to cloud
05:12:56     Target Cancelled Target cancelled (19/19, HIP 87937) due to cloud
05:13:01   Queue Completed Job Queue completed
05:13:07 Session Closing Session closing
05:13:12   Dome Closed Dome already closed (closed at 01:53, closing time 50s)
05:14:39   Dome Parked Dome parked (parking time 79s), Az: 90.0 deg
05:15:23   Telescope Parked Telescope parked (parking time 37s)
05:15:53   Telescope Switched Off Telescope Power has been switched off via UPB Switch.
05:16:44   Services Stopped Night Services stopped
05:16:46 Session Housekeeping Housekeeping Started (Cleanup FITS, Create Fits Summary, Transfer Files)
05:16:53 Session Finished Session Finished
 
Session Alerts
Time     Alert Detail
23:33:51 Plan Loading Plan had taken an unexpectedly long time (3 min)
23:48:03 Plan Loading Plan had taken an unexpectedly long time (3 min)
04:31:03 UPB.Switch disconnected UPB.Switch has unexpectedly disconnected. Restart will be attempted
04:31:05 UPB.Switch UPB.Switch has been successfully restarted.

Back to Top


Operational Issues (2021-03-31 S878)

[ Prev | Next ]

Critical Issues

Major Issues

Minor Issues

Continuous Improvement

[ Prev | Next ]

Back to Top


Pulsar Dome - Software Update (Shutter 1.25)

Update 2021-04-08

Update 2021-05-03

Back to Top


Investigation - AstroMain stalls whilst importing Observing Plan

Issue:   Show-stopping bug in new AstroMain 3.38.11 version.  Retrieve Targets Thread,  Obs.Monitor Thread & TheSky6 freezing when importing night's observing plan as part of AutoStart Start-Up

Description:  Import of Observing Plan stalled after writing report message "Retrieving Targets ..." and after writing log message 'Retrieving 19 targets'  After 3 minutes the  Obs.Manger came back with the Alert that "Loading appears to be frozen. (23:33)", and the Session dropped back to Manual Mode

Session Initiating                      2021-03-31 23:45  (Local)
  NightDate:                  Ok        2021-03-31        (NightDate)
  Import Observing Plan...
  Selecting Plan...           Ok        2021-03-31   V1   BEST PLAN   (Plan ID: 616)
  Retrieving Targets ...      **        
> Obs.Manager                 Alert     Plan Loading appears to be frozen. (23:48)
> Obs.Manager                 Alert     Returning Observatory to Manual Mode

Observatory Mode
                        2021-03-31 23:48  (Local)

  Setting Mode ...            Ok        Manual

The log file showed messages that Obs.Monitor is frozen and TheSky6 was found to be non-responsive.

After parking scope & restarting observatory software (including killing and restarting AstroMain 3.38.11) autostart was again used to kick off session but the same issue occurred again at exactly the same point.  In order to allow the S878 observing session and establish if there was a wider issue or not AstroMain installation was rolled back to previous 3.38.10 version, and this time the observing plan imported ok and session continued normally.

Log File from first instance

23:30:51.67 | Observatory Manager    Plan                  Info  | Loading Latest Observing Plan
23:30:51.67 | Database               Get ListOfPlans       Ok    | Getting List of Plans from Database
23:30:51.67 | Database               Get ListOfPlans       Ok    | 1 plans are listed
23:30:51.67 | Observatory Manager    Select Plan           Info  | Latest Plan: 2021-03-31 V1 BEST PLAN
23:30:51.67 | Plan Loader            Start LoadPlanFromDB  Ok    | Starting Thread to LoadPlanFromDBShell
23:30:52.12 | Latest Plan Loader     Load PlanFromDB       Ok    | Calling ObservingDB.RetrievePlan(PlanID=616)
23:30:52.12 | Database               Retrieve Plan         Ok    | Retrieving Plan
23:30:52.12 | Database               Retrieve Targets      Ok    | Retrieving 19 targets
23:31:01.54 | Observatory Overseer   Check.ObsMonitor      Info  | Obs.Monitor is Pending (7s)
23:31:06.55 | Observatory Overseer   Check.ObsMonitor      Alert | Obs.Monitor is Frozen (12s)
23:31:11.56 | Observatory Overseer   Check.ObsMonitor      Alert | Obs.Monitor is Frozen (17s)
23:31:16.56 | Observatory Overseer   Check.ObsMonitor      Alert | Obs.Monitor is Frozen (22s)
23:31:21.57 | Observatory Overseer   Check.ObsMonitor      Alert | Obs.Monitor is Frozen (27s)
23:31:26.58 | Observatory Overseer   Check.ObsMonitor      Alert | Obs.Monitor is Frozen (32s)

Log File from second instance (showing that issue occurs at exactly the same point)

23:45:02.89 | Observatory Manager    ObservingPlan         Info  | Importing Observing Plan
23:45:02.90 | Database               Get ListOfPlans       Ok    | Getting List of Plans from Database
23:45:02.90 | Database               Get ListOfPlans       Ok    | 1 plans are listed
23:45:02.90 | Observatory Manager    Select Plan           Info  | Latest Plan: 2021-03-31 V1 BEST PLAN
23:45:02.90 | Plan Loader            Start LoadPlanFromDB  Ok    | Starting Thread to LoadPlanFromDBShell
23:45:03.56 | Latest Plan Loader     Load PlanFromDB       Ok    | Calling ObservingDB.RetrievePlan(PlanID=616)
23:45:03.58 | Database               Retrieve Plan         Ok    | Retrieving Plan
23:45:03.58 | Database               Retrieve Targets      Ok    | Retrieving 19 targets
23:45:12.72 | Observatory Overseer   Check.ObsMonitor      Info  | Obs.Monitor is Pending (9s)
23:45:17.73 | Observatory Overseer   Check.ObsMonitor      Alert | Obs.Monitor is Frozen (14s)
23:45:22.74 | Observatory Overseer   Check.ObsMonitor      Alert | Obs.Monitor is Frozen (19s)
23:45:27.74 | Observatory Overseer   Check.ObsMonitor      Alert | Obs.Monitor is Frozen (24s)
23:45:32.75 | Observatory Overseer   Check.ObsMonitor      Alert | Obs.Monitor is Frozen (29s)
23:45:37.76 | Observatory Overseer   Check.ObsMonitor      Alert | Obs.Monitor is Frozen (34s)
23:45:42.77 | Observatory Overseer   Check.ObsMonitor      Alert | Obs.Monitor is Frozen (39s)

Analysis
Examination of code shows the point in the ObservingDB.RetrievePlan() routine where  "Retrieving 19 targets" is written to log file.  This is last point that can be traced. After this point the code enters a loop ( For i = 1 To TIS.nItems ) in which  RetrieveTarget () routine is called once for each target.   This routine retrieves data from database for a given target and performs some manipulation and expansion of the target dataset.  At the end of routine the name of the retrieved target is written to the logfile.

The expected set of messages are as follows

00:10:31.06 | Database Retrieve       Target               Ok    | Retrieved Nova Per 2020 (CV)
00:10:31.11 | Database Retrieve       Target               Ok    | Retrieved AT2021gyc (CV)
(For brevity 16 other target loading messages are not shown here)
00:10:38.32 | Database Retrieve       Target               Ok    | Retrieved HIP 87937
00:10:38.32 | Database Retrieve       Targets              Ok    | Total of 19 targets have been loaded
00:10:38.38 | Latest Plan Loader      Load PlanFromDB      Ok    | Plan has been loaded

(Note: these are the messages that were written to logfile later on when the V1 Best Plan was successfully loaded later on using AstroMain 3.38.10)

It is clear from the log file that execution of the RetrieveTarget() routine stalled before reaching the routines end for first target (Nova Per 2020) since logfile contain neither aneither a message confirming retrieval of target nor a message reporting an exception (there was no message ' Exception in Database.RetrieveTarget' written to logfile)

RetrieveTarget() routine in 3.38.11 is identical to that in 3.38.10, as are GetObjectSize()  &  LookupTargetRaDec() routines which are called from the RetrieveTarget()

Possibilities  ?
1)   stall happened at one of three or four calls to the database using
         objReader = objCommand.ExecuteReader() 
            ' where objCommand  is of type SQLiteCommand  , and  objReader is of type SQLiteDataReader
           (ie a database lock issue)

2)  stall in the GetObjectSize() routine that is called to get Object Size, and in which there are calls to TheSky6's Chart object
        ObjectInfo = Chart.Find(MOT(Sky6Name))
         with subsequent calls to ObjectInfo.Property()

3) stall in the LookupTargetRaDec() routine which is called to get Targets's Ra Dec,  and in which there are calls to TheSky6's Chart object
        ObjectInfo = Chart.Find(MOT(TargetName))
        with subsequent calls to ObjectInfo.Property()

4) Some issue with the 3.38.11 build/executable used on Observatory Computer

5) Some environmental glitch.  But hard to see why the glitch happened twice in a row after observatory software had been completely restarted.


RetrieveTargets Testing
Executing 'Session Initiating' routine (3.38.11) in on Development Computer shows no problem,  the code executes normally and targets from a new test plan are all retrieved ok.

Executing 'Session Initiating' routine in a test version (based on 3.38.11) but manipulated to load the same plan (plan id 616) as used during the S878 session also executed normally.

Changes in 3.38.11 compared to 3.38.10
 - New Feature: AstroMain checks and automatically opens AstroGuard at start of a new session
 - New Feature: Session Alerts added when Pulsar Shutter Data suffers an outage of >20 mins (Yellow Alert) or resumes again (Green Alert)
 - Fixed Issue:  Guiding Results are now reset/incorrectly reported for Target when SoftSuspend occurs or other conditions interfere with normal operations.

Prehaps looking for issue in RetrieveTarget is a red herring and the issue lies with Obs.Monitor which frooze at the same time.

Interaction with AstroPlan / TheSky6

1st instance stalled at ~ 23:30:52.12

AstroPlan finished making plan at 23:30:49.28
AstroPlan uploading Session.TargetFrame16.jpg & Session.Images.js at 23:30:52
AstroPlan, FTP Queue Loop resumed at 23:34:02
AstroPlan, RunFtpQueue has finishing uploading a batch of 141 files at 23:34:46.35

2nd instance stalled at ~23:45:03.58

AstroPlan finished getting Sun data at 23:43:08.46
AstroPlan uploading Session.TargetFrame18.jpg & Session.Images.js at 23:45:03
AstroPlan had Exception in 'UploadFileFTP2' whilst getting RequestStream at 23:46:28.07

Back to Top