David's Astronomy - Notes 2020-09-26 (S0813)

An issue has arisen in recent sessions following introduction of extended Near Zenith Focusing (including precursive Wide Focus Search) and the new AutoStart mode, whereby the 1st target in the Observing Plan normally ends up being missed. A solution has been developed in AstroMain 3.29.1 and AstroPlan 1.16.2 to try to ensure that Observing Plan Start Time corresponds better with the time that the Observatory is ready including near zenith auto-focusing of both main LX200 Scope and the TS-80 GuideScope.

A new routine ObservatoryManager.GetPreQueueActivityMins() has been written in AstroMain to compile the minimum reasonable time that is needed before Obs.Manager will be ready to begin an observing plan. This takes into account the time needed to open the dome (1 min), equilibrate the camera & dome (5 mins), perform near zenith focusing of main scope and guide scope (up to 14 mins), and add contingency (2 mins). Timings are based on those used for determining Open Dome time and reporting pre-queue activities in the ObservatoryManager.SetState_Equilibrating() routine. At the moment the timings are set separately in the two routines, such that for the time being any changes need to be made in both routines)

There is no point in creating a new observing plan with a Start Time that is before time that the observatory will be ready to commence the plan., and therefore the InitiateNewPlan() routine has been modified to set the overall StartingMins required (from 2.0 + GetPreQueueActivityMins()) and include this time as an additional line in the CreatePlanFlag.dat file that is used to trigger AstroPlan program to make a new plan.

AstroPlan's AutoBuildSchedule() routine has been modified to read the required StartingMins and copy it to the ScheduleBuilder's txtStartingMins.text field
After reading the CreatePlanFlag.dat this routine goes on to execute the following commands
   checkboxStartTimeFromNow.Checked = True
   txtNightDate.Text = GetNightDateNow()
   ResetNightDetails()
   AutoSelectStartAlt()
   RunBuilder()

Note: ResetNightDetails() gets run 3 times (once in AutoBuildSchedule(), once in AutoSelectStartAlt and once in RunBuilder). This is overkill but ensure that night details are definately set before a New Plan is created.

ResetNightDetails() is modified to read the StartingMins from txtStartingMins.text field and use it to define the EarliestQueueStartTime (from Now().AddMinutes(StartingMins)

S813 Results

StartingMins passed to AstroPlan = 25
(from AstroPlan 2 min, Open Dome 1 min, Equilibration 5 min, NearZenithFocusing 14 min, Contingency 2 min = 24 mins)

SunAlt -12 20.18

Create Observing Plan            
2020-09-26 20:18 (Local)
Starting Minutes           
Info  25 minutes required
Request Observing Plan...  Ok
Generate 
Night Plan...     Ok    Schedule Builder has 
completed
Selecting Plan...          
Ok    2020-09-26 V1 BEST PLAN (Plan ID: 548)
Retrieving 
Targets ...     Ok    36 Targets. 
Reading 
Start Time...      Ok    2020-09-26 
20:43 (Scheduled StartTime, Local)

Session Equilibration            2020-09-26 20:19 (Local)
Now                        Info  2020-09-26 20:19 ( 
-24 mins )
Expected Shutter Opening   Info  2020-09-26 20:20 ( -23 mins )

Expected Equilbrat'n Start Info  2020-09-26 20:21 ( -22 mins )
Expected Run 
Start         Info  2020-09-26 20:26 ( -17 mins )
Expected Near-Zenith Foc1  Info  
2020-09-26 20:27 ( -16 mins )
Expected Near-Zenith Foc2  Info  2020-09-26 20:35 
( -8 mins )
Expected Queue Start       Info  2020-09-26 20:41 ( -2 mins )
Plan 
Queue Start           Info  2020-09-26 20:43 ( On Track )



Session Running                  
2020-09-26 20:26 (Local)

GCVS U Her (1/36)                
2020-09-26 20:43 (Local)
Target:                    
Ok    GCVS U Her (ID: 107)
Type:                      
Ok    Mira variable
Program:                   
Ok    Main Variables (ID: 12)

Planned Start..            
Ok    2020-09-26 20:43 (Scheduled)
Planned End..              
Ok    2020-09-26 20:55 (Scheduled) Duration : 11.4 mins

Start 
Actual Start               
Ok    2020-09-26 20:43 (Local)

Due to focusing failures on Near Zenith Focus Field, extra focusing was conducted as part of Target 1/36 (U Her) which unfortunately led to Image Sets 2 and 3 being cancelled in order to prevent the observation from over-runnng its time slot. This does not take away from the fact that code changes to ensure that the 1st Target isn't missed did work as per design.

After two successful 8 hour sessions (using DeviceHub 6.4.1.11 which I’ve now upgraded to) session S813 was operating for around 1.5 hours when there was a repeat of the issue that I described in a Posting made to ASCOM Talk Forum "DeviceHub problem - dome information stops refreshing" 2020-09-18 https://ascomtalk.groups.io/g/Help/topic/76935263#42838

DeviceHub's Activity Log (DeviceHub.DomeActivityLog_2020-09-26.txt) shows everything working ok until 21:53:46.340 when after getting Dome-Statuses okay (ShutterStatus, Azimuth etc ) Dome-Commands show Dome Slaving calculation starting but apparently not finishing.

21:53:41.223: Dome - Statuses: Get ShutterStatus: shutterOpen
21:53:41.223: Dome - Statuses: Get AtHome: False
21:53:41.223: Dome - Statuses: Get AtPark: False
21:53:41.223: Dome - Statuses: Get Azimuth: 265.5
21:53:41.223: Dome - Others: Get Connected flag - True
21:53:41.223: Dome - Statuses: Get Slewing: False
21:53:41.223: Dome - Commands: Dome position recalculation due to telescope slew-in-progress.
21:53:41.332: Dome - Commands: Slaving the dome to telescope Az: 280.78, Alt: 81.24, HA: 1.08741, SOP: pierEast.
21:53:41.332: Dome - Commands: The calculated dome position is Az: 265.78, Alt: 84.06.
21:53:41.332: Dome - Commands: The dome azimuth is close to the target azimuth...no slew is needed.
21:53:46.340: Dome - Statuses: Get ShutterStatus: shutterOpen
21:53:46.340: Dome - Statuses: Get AtHome: False
21:53:46.340: Dome - Statuses: Get AtPark: False
21:53:46.340: Dome - Statuses: Get Azimuth: 265.5
21:53:46.340: Dome - Others: Get Connected flag - True
21:53:46.340: Dome - Statuses: Get Slewing: False
21:53:46.340: Dome - Commands: Dome position recalculation due to telescope slew-in-progress.
22:05:26.427: Dome - Others: Get Connected flag - True
22:05:26.427: Dome - Commands: CloseShutter: (done)

At the time (21:53:46) my client program (AstroMain) was under automated control and was actively undertaking imaging of S Cyg whilst monitoring sky conditions which were deteriorating. Finally at 22:05:22 there was a critical cloud alert and the dome shutter was commanded to close (via DeviceHub.Dome.CloseShutter). The activity log shows the CloseShutter Command at 22:05:26.427. After this DeviceHub.Dome reported to my two clients (AstroMain & AstroGuard) that ShutterStatus was 'shutterClosing'. My main client program (AstroMain) waited in vain for the status to change to shutterClosed but it never reached the Closed state, whilst an oversight client program also recorded that shutter closure operation had overrun its normal closing time. I went outside to visually check the Observatory and found the Shutter was physically closed. (i.e. the Command to CloseShutter had operated successfully)

Even though DeviceHub was telling my clients that the ShutterStatus was Closing, a screen capture of the DeviceHub at 22:15 shows Shutter Position as Open (the position it was in before DeviceHub's dome data refreshing stopped at 21:53:46). Both are wrong as the Shutter was proven to be physically closed.

The Pulsar Dome Ascom Log (ASCOM.Pulsar_Observatories_Dome.1918.437520.txt) shows the Dome Driver receiving the CloseShutter command at 22:05:26.552, and the ShutterStatus progressing from Open (0) to Closing (3) to become Closed (1) at 22:06:10.622. The same log shows that the regular 5s interrogations of ShutterStatus, Park State, Slew State, Azimuth stop at 21:53:46.340, which is the same time that the DeviceHub activity log stops refreshing.

Separate to the Activity Log which I captured via the clipboard there was an ASCOM log file (ASCOM.DeviceHubDome.1918.437050.txt) that was being written to disk which I also attach (In fact there was a second file (ASCOM.DeviceHubDome.2019.465710.txt) that was also being written concurrently to disk. Not sure if there are two because I had two clients using the DeviceHub.Dome. These show reporting of Dome Statuses (ShutterStatus, dome Azimuth) every 5s but continuing on past the 21:53:46 time when the Activity Log show things stalling.

They show ShutterStatus switching from Open to Closing at 22:05:31.263, but the logs still report shutter is Closing at 22:22:58 (18 minutes later) when the logs end.

[ One thing I notice is in the ASCOM.DeviceHubDome.1918.437050.txt log (assume these are messages associated with my main program client which starts earlier) there are repeating sets of multiple (20) GetShutterStatus lines listed with the same or very similar ms time, i can’t think why my client program would be making 20 requests at a time (I will check for some accidental/unintended loop in my code). These sets stop at around the time the observatory is commanded to close. Checking backs show there were the same sets of 20 GetShutterStatus lines at a time throughout the previous two sessions which both operated without any problem ]

At the time the screen captures where made (22:15) skies had cleared and automated operations would normally have reopened the shutter, but with the DeviceHub.Dome stalled on ‘Closing’ my clients couldn’t track /confirm any reopening of the dome even though an OpenShutter command would have still worked (as shown in previous sessions using Pulsar Dome Trace Logs)

Again, as part of disconnecting Clients from DeviceHub to restart things , DeviceHub produced a fatal exception that was reported/detailed in original posting to ASCOM Talk Forum. It seems to be more an artefact of the problem rather than highlighting anything useful about the original cause of the problem.

Examining the session logs shows that at the time the DeviceHub.Dome appears to have stalled (21:53:46) the imaging of S Cyg target hadn’t yet started, the observatory was instead performing a small jog (1.05 arc min) jog to centre the telescope onto the required target following a plate solution on initial post-slew locate frame. This explains the messages ‘Dome position recalculation due to telescope slew-in-progress’ and ‘The dome azimuth is close to the target azimuth...no slew is needed’ shown on Activity Log directly before the stall.
( Jog was performed using the TheSky6.Telescope.Jog command (ie via TeleApi to Ascom.DeviceHub.Telescope to Meade LX200 GPS/R ) )


	Session Aims & Highlights
	- Observing Result - Night Summary Plot - Session Event Log

	Operational Issues
	- Critical Issues (0), Major Issues (2), Minor Issues (8), Continuous Improvement (4)

	Images from 2020-09-26 >>

	Earliest Plan Start Time
	Dome Data Stalled (S813)

This Web Page:	Notes - Session 813 (2020-09-26)
Last Updated :	2024-02-21
Site Owner :	David Richards
Home Page :	David's Astronomy Web Site

David's Astronomy Pages
Notes - Session 813 (2020-09-26)

Session Aims & Highlights (2020-09-26)

Operational Issues (2020-09-26 S813)

Earliest Plan Start Time

Dome Data Stalled (S813)

David's Astronomy Pages Notes - Session 813 (2020-09-26)

Session Aims & Highlights (2020-09-26)

Operational Issues (2020-09-26 S813)

Earliest Plan Start Time

Dome Data Stalled (S813)

David's Astronomy Pages
Notes - Session 813 (2020-09-26)