David's Astronomy - Notes 2021-04-30 (S0893)

Session Aims & Highlights

- Observing Result
- Night Summary Plot
- Session Event Log

Operational Issues

- Critical Issues (0), Major Issues (3), Minor Issues (7), Small Defects (2), Continuous Improvement (6)

Images from 2021-04-30 >> [ Local Files >> ]

2021-05-01

Investigation - JobQueue Freezing during Telescope.Jog

Notes:

Session begun using Autostart.

Autostart Earliest StartTime          2021-04-30 21:49               <-- Intended Start (Sun Alt -10.8 deg - 40 mins)
                                        2021-04-30 22:16               <-- Actual Start   (Sun Alt -12.0 deg - 30 mins)
Plan created                          2021-04-30 22:19 ( -25 mins )
Expected Shutter Opening    Info      2021-04-30 22:21  ( -23 mins ) vs Actual Opening :    22:22
  Expected Equilbrat'n Start  Info      2021-04-30 22:22  ( -22 mins ) vs Actual Equil. Start 22:22
  Expected Run Start          Info      2021-04-30 22:27  ( -17 mins ) vs Actual Run start:   22:27
  Expected Near-Zenith Foc1   Info      2021-04-30 22:28  ( -16 mins ) vs Actual Foc1 start: 22:27
Sun Alt -10.8 deg                               22:29               <-- Desired Queue Start
  Expected Near-Zenith Foc2   Info      2021-04-30 22:36  (  -8 mins ) vs Actual Foc2 start: 22:34
  Expected Queue Start        Info      2021-04-30 22:42  (  -2 mins ) vs Actual Queue Start: 22:39 (10m later than intended)
Sun Alt -12 deg                                 22:44
  Plan Queue Start            Info      2021-04-30 22:44  ( On Track ) <-- Planned Queue Start

Based on Autostart Actual Time (time when conditions were deemed suitable to commit to the session), the actual times came in pretty close to forecast times tabulated at start of Equilibration Stage. But there are some questions :

- Why was Plan Queue Start as late as 22:44 (when the desired Start Time was 22:29 (sun alt -10.8 deg)
   Plan Queue Start is defined at Start of Equilibration, and is largely based on completing various activities following the AutoStart Time

- Autostart Start wasn't made until 22:16, although earliest available start time was 21:49 . Why was the start delayed ?
    - It is normal for AutoStart to wait on conditions to be suitable at start of session.
   - Although this is nornally reported as a 'wait on cloud', it often a wait on AllSkyStars being above the user specified threshold.
   - A fairly low threshold was defined for this session (?10-12 )
   - In practice the Earliest Start Time (21:49) was never feasible. At this time. Light was still falling and AllSkyStar Count was still 0
   - Star Count didn't reach 10 until 22:11 and didn't reach 15 until 22:15.

- Why was is there a 3 minute delay between AutoStart Time (22:16) and Plan Creation Time
   - Times are ok. There is no delay
   - Actual AutoStart time (22:16:55) was much closer to 22:17 than 22:16.
   - 1.25 min of the time was taken up in starting the telescope (60s wait on power, 15s wait on initialisation etc). this is a normal delay

- If early start is required (when one knows the sky is clear), the ideal would be to set AutoStart Referene Start at SunAlt -10.8 degs - 30 minutes
and employ a (Too) Few Stars Threshold of 5.

Operational Issues (2021-04-30, S893)

2021-05-01

Investigation - JobQueue Freezing during Telescope.Jog

Issue : Job Queue held up by a blocking TheSky6/ASCOM dialog box "Unable to start direct slew" after calling Telescope.Jog causing loss of obsevring time, and eventually leads to the ObsOverseer initiating the MakeObservatorySafe routine, with sideeffects.

Description :
During session S893 there were two separate incidents involving this issue:

1) Job Queue held up by blocking TheSky6/ASCOM dialog box "Unable to start direct slew" (23:14) . During Locate Frame1 centering of Target 3/17 (NGC 4227) the JobQueue became held up by a frozen Telescope.jog call which eventually lead to the ObsOverseer initiating the MakeObservatorySafe routine at 23:25. The problem occurred during a 2.77' S Jog at 23:14:49.48 which followed a 1.79' E Jog at 23:14:46.97 and a 1s settle delay at 23:14:48.46. Job Queue was released by user interventing and acknowledging the dialog box message in TheSky6. However after aborting the job it was difficult to successful restart the queue (the shutter kept closing). Eventually got back to starting Target 4/17 at 23:33 (loosing 19 mins of observing time). A seperate ticket has been added for addition of 'A back door method is required to release flags that cause 'MakeObservatorySafe' to be reactivated'.

2) Job Queue held up by an assumed blocking TheSky6/ASCOM dialog box "Unable to start direct slew" (02:04). During Locate Frame2 centering of Target 11/17 (UGC 11177) the JobQueue became held up by a frozen Telescope.jog call . Problem occurred during a 0.44' W Jog at 02:03:58. ObsOverseer declared that the JobQueue was frozen 10 minutes later at 02:14. It is unclear if the MakeObservatorySafe routine was initiated/run. It seems not but this is most likely due to Observatory entering suspended state at 02:14 . (some 90 mins of observatory time were lost)

Analysis

In the past there have been occasional problems with this or very similar issue using MeadeLX200GPS driver with POTH.Hub, but these problems largely went away using MeadeLX200GPS driver with DeviceHub.Telescope. The issue affected session S888 and S889 badly when using an March 2021 verison of MeadeGeneric driver which had a bug that caused it to never set Slewing property to True, and in particular not setting it to True when the telescope was physically slewing (see Investigation - Jog Execution held up by "Unable to start the DirectSlew" dialog from TheSky6/ASCOM, 2021-04-20) . This prevented automated operations and the session had to be run in a semi-manual mode where the TheSky6/ASCOM dialog boxes was dismissed when it occured, releasing the block and allowimg Job Queue to continue before MakeObservatorySafe was initiated. This bug was fixed in 1.0.1.327 but due to DeviceHub not going immediately over to fast polling when there is a slew or slew request there is seeminngly a residual weakness that makes TheSky6 still prone to the issue occuring occasionally.

1) Case at 23:14 :

Client Log
23:14:46.97 | NGC 4227 Make E Jog Info | W= -1.79' (-2.14' at Dec 33.4) 23:14:48.46 | NGC 4227 WaitOn Scope.Settling Info | Sleeping For 1.0 secs 23:14:49.48 | NGC 4227 Make S Jog Info | N= -2.77'
Slew appeared to take <2s to finish before execution returned from TheSky.Telescope.Jog
(or ASynch is 1 rather than 0)

MeadeGeneric Log
23:14:47.080 SlewToCoordinatesAsync Ra=12.2867840874976, Dec=33.2890143017561 23:14:47.111 Slewing Result = False 23:14:47.376 DoSlewAsync Slewing to target no slewing messages during this time (some 8 secs) 23:14:55.574 Slewing Result = True 23:14:57.016 Slewing Result = True 23:14:58.232 Slewing Result = True to 23:15:08.794 Slewing Result = True 23:15:10.884 Slewing Result = False

It is evident that SlewToCoordinatesAsync at 23:14:47.080 is associated with E Jog Call from client at 23:14:46.97
The log doesn't have any SlewToCoordinatesAsync message associated with S Jog Call from Client

Slew took 8.5s to turn Slewing=True, Slew took some 21s to finish.

23:14:47.111 TargetDeclination Get 33.2852305555556 23:14:47.111 TargetRightAscension Set 12.2867840874976

DeviceHub log (for TheSky6)
23:14:47.376 SlewToCoordinatesAsync: RightAscension = 12.2867840874976, Declination = 33.2890143017561 23:14:48.453 Get Slewing: False (done) 23:14:48.562 Get RightAscension: 12:17:04 (done) to 23:14:49.373 Get RightAscension: 12:17:04 (done) 23:14:49.373 Get Declination: 33[B0] 17' 16" (done) gap in messages no Get Ra/Get Dec messages ! 23:14:54.646 SlewToCoordinatesAsync: RightAscension = 12.2844006447618, Declination = 33.2419057267208 (failed)

No Get Slewing: True messages !

(does this failed request produce any exceptions ? that find there way back to client ?)

2) Case at 02:04 :

Client Log
02:03:58.78 | UGC 11177 Make W Jog Info | W= 0.44' (0.45' at Dec 6.8) 02:04:00.37 | UGC 11177 Trace Telescope.Jog Ok | IamAlive: MakeJogCorrection, JogW 02:04:22.72 | UGC 11177 Get Scope.RaDec Fail | Exception in Scope.GetRaDec 02:04:22.72 | UGC 11177 Get Scope.RaDec Fail | Timed out waiting for received data 02:04:31.04 | Observatory Overseer Check JobQueue Info | Task In MakeJogCorrection/JogW is taking a Long time? (Telescope.Jog) 02:09:31.50 | Observatory Overseer Check JobQueue Info | Task In MakeJogCorrection/JogW is taking a Long time? (Telescope.Jog) 02:14:31.96 | Observatory Overseer Check Operation Info | Task In MakeJogCorrection/JogW appears to be frozen (Telescope.Jog)

MeadeGeneric Log
02:03:58.815 Slewing Result = False 02:03:58.878 SlewToCoordinatesAsync Ra=18.2830433880329, Dec=6.55555199894204 02:03:59.252 DoSlewAsync Slewing to target 02:04:00.500 SlewToCoordinatesAsync Ra=18.2847688498846, Dec=6.55520642849791 02:04:06.188 GetSlewing Result = True (T+7.4s) 02:04:07.290 GetSlewing Result = True (T+8.5s) 02:04:21.471 GetSlewing Result = False (T+22.7s)

Notes:
Polling seems very limited between 02:04:08 & 02:04:21 . How much of this is associated with or has same underying cause as the ' Get Declination: (failed) messages received by DeviceHub.Telescope at 02:04:22.7 & 02:04:25.2

There were no slewing messages in the first 6s (ie in the time interval between 02:04:00.5 & 02:04:06.1)
In fact there were no messages of any kind between 2:04:01.998 & 02:04:05.991 (1.5s), presumably slow polling by DH, frozen job queue,

3) Control Case : Locate Frame 1 for NGC 4165 (22:51) was associated with 13.18' pointing error so long jogs must be involved.

22:52:11.33 | NGC 4165 Start Jog Info | 13.24 arc mins (W= 6.43', N= 11.57') 22:52:11.36 | NGC 4165 Make W Jog Info | W= 6.43' (6.60' at Dec 13.1) 22:52:26.17 | NGC 4165 WaitOn Scope.Settling Info | Sleeping For 1.0 secs 22:52:27.18 | NGC 4165 Make N Jog Info | N= 11.57' 22:52:41.76 | NGC 4165 WaitOn Jog Info | Sleeping For 1.0 secs 22:52:42.77 | NGC 4165 Finish Jog Ok | [W] [N] Jog Completed

W Jog took 15s to return
N Jog took 14s to return

MeadeGeneric Log
22:52:10.791 Slewing Result = False 22:52:11.415 SlewToCoordinatesAsync Ra=12.2098175517483, Dec=12.9327611237471 22:52:11.695 DoSlewAsync Slewing to target 22:52:14.800 GetSlewing Result = True / 22:52:14.800 Slewing Result = True Slewing (T+3.4s) to 22:52:22.943 GetSlewing Result = True / 22:52:22.943 Slewing Result = True 22:52:24.643 GetSlewing Result = False / 22:52:24.643 Slewing Result = True 22:52:25.876 GetSlewing Result = False / 22:52:25.876 Slewing Result = False Slewing Stopped ! 22:52:27.230 SlewToCoordinatesAsync Ra=12.2099158320193, Dec=13.1253423561364 22:52:27.496 DoSlewAsync Slewing to target 22:52:29.820 GetSlewing Result = True / 22:52:29.820 Slewing Result = True Slewing (T+2.5s) to 22:52:39.461 GetSlewing Result = True / 22:52:39.461 Slewing Result = True 22:52:41.567 GetSlewing Result = False / 22:52:41.567 Slewing Result = False Slewing Stopped ! What is difference between 22:52:41.567 IsSlewingToTarget IsSlewing = False : result = 22:52:41.567 GetSlewing Result = False 22:52:41.567 Slewing Result = False

Attempted Fix (2021-05-01)

Fixed attempted by creating new Scope.Jog routine, calling Telescope.Asynchronous=1 and entering a loop to monitor Scope.Slewing and use it to spot the start and end of slewing before returning, with 2 minute timeout.

Actions:

Attempt fix (new Scope.Jog routine)
Test fix (new Scope.Jog routine) in next session

Update 2021-05-03

Results from using new Scope.Jog routine :

This Web Page:	Notes - Session 893 (2021-04-30)
Last Updated :	2024-03-23
Site Owner :	David Richards
Home Page :	David's Astronomy Web Site

David's Astronomy Pages
Notes - Session 893 (2021-04-30)

Session Aims & Highlights (2021-04-30)

Operational Issues (2021-04-30, S893)

2021-05-01

Investigation - JobQueue Freezing during Telescope.Jog

David's Astronomy Pages Notes - Session 893 (2021-04-30)

Session Aims & Highlights (2021-04-30)

Operational Issues (2021-04-30, S893)

2021-05-01

Investigation - JobQueue Freezing during Telescope.Jog

David's Astronomy Pages
Notes - Session 893 (2021-04-30)