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

2021-05-01

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

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.

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:

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

This Web Page:

Notes - Session 893 (2021-04-30)

Last Updated :

2024-09-30

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)