David's Astronomy - Notes 2024-09-12 (S1242)

Issue

1a) Job Queue froze whilst performing an Image Link on Locate Frame (23:22, S1242)
1b) Job Queue froze whilst performing an Image Link on Locate Frame (23:40, S1242)
2) Alerts raised that ScopeMonitor was frozen and TheSky6 isn't running (2024-09-10 22:28, S1240 ).
3) Session interrupted by a session suspension when Image Link operation in CCDSoft/TheSky6 took an unusually long time (2024-08-31 03:40, S1237).
4) Session interrupted by a session suspension when Image Link operation in CCDSoft/TheSky6 took an unusually long time, TheSky6 appeared to 'hang' and AstroMain's scope monitor froze (2024-08-29 00:01, S1235)
5) Three Job Queue freezes during session S1243 (2024-09-12) at 21:12, 00:38 & 04:05
6) Two Job Queue freezes during session S1244 (2024-09-15) at 00:21 & 04:38

Description

1a) S1242 2024-09-12 23:22. Whilst performing plate solution on Locate 1 frame (#1242034, 111 stars) for Target 5/24 (AT2023csw) Obs.Overseer gave a warning "ScopeMonitor is frozen (23:22) ", followed by a Red 'TheSky6' Alert with the message "TheSky6 isn't running or isn't working correctly" and a warning "Task in ImageAndLink/LinkImage is taking a long time? (23:23)". The ObsManager aborted the target and the session was suspended.

1b) S1242 2024-09-12 23:40. Whilst performing plate solution on Locate 2 frame (#1242043, 14 stars) for Target 6/25 (GCVS T CrB) Obs.Overseer gave a warning "ScopeMonitor appears to be frozen (last cycle at 23:38:22) ", a TheSky6 Alert with message "TheSky6 isn't running or isn't working correctly" and a warning "Task in ImageAndLink/LinkImage is taking a long time? (23:40)" . The ObsManager aborted the Target and the session suspended.

In both cases the issue resolved itself after a short while, with the results of Image Link (solved in 309.9s and solved in 305.2s respectively ) being posted whilst ObsCam was taking a 'Supended Session' image. Whilst the session then continued on ok , the issue causes a significant delay, and lost observations for the target affected.

Similar problems have occurred on two other occasions recently. Is there a common factor ?

2) S1240 2024-09-10 22:28. Whilst performing plate solution on Locate 1 frame (#01240030, 136 stars) for Target 4/24 (AT2023exh ) Obs.Overseer gave a warning "ScopeMonitor is frozen (22:29) ", followed by a Red 'TheSky6' Alert with the message "TheSky6 isn't running or isn't working correctly" and a warning "Task in ImageAndLink/LinkImage is taking a long time? (22:30)". The ObsManager aborted the target and the session was suspended. In this case Scope Monitor resumed again at 22:33, indicating a freeze of around 4-5 minutes. The results of a successful image link ("Solved in 310.3s (Stars 117, Scale 1.406, Angle 180.1°) " ) were reported whilst ObsCam was taking a 'Suspended' Image.

3) S1237 2024-08-31 03:40 Session interrupted by a session suspension when Image Link operation in CCDSoft/TheSky6 took an unusually long time (03:40). TheSky6 appeared to 'hang' and AstroMain's scope monitor froze. The ScopeMonitor was identified to be frozen and a red alert raised at 03:40:38, after the Monitor had been frozen since it's last completed cycle at 03:38:53. This was during Image Linking of Locate 2 frame (#01237205 ) for Target 25/27 (M33 w/AT2023nou) , and the following warning was reported "TheSky6 isn't running or isn't working correctly ". ObsManager intervened and raised a bHardSuspend flag (03:40:42 ) in order to suspend the session. ObsOverseer warned that "a task in ImageAndLink/LinkImage is taking a long time?" (03:41:28). After a prescribed amount of waiting ObsManager gave the following warning "Timed out waiting for JobQueue to raise bSuspendOk" (03:42:43 ) and set session state to Suspending. This indicates that JobExecution was held up (almost certainly held up waiting for TheSky6 to complete the ImageLink action). After closing the dome and whilst Session State was suspended the Image Linking operation eventually completed with the success message "Ok Solved in 293.5s (Stars 11, Scale 1.408, Angle 179.9°) " (03:43:46 ). At the same time the Scope Monitor was recorded as having resumed (03:43:46). Inspecting the #01237205 frame it seems normal with plenty of stars and should be easy to link. Indeed during Post-Session 'Reduction/Analyse All Frames' the frame was image linked in only 0.6s. This suggests that the delay was likely not caused by the specific frame been image linked at the time, but was due to some other hold-up with the TheSky6 program.

4) S1235 2024-08-29 00:01. The ScopeMonitor was identified to be frozen and a red alert raised at 00:01:53, after the Monitor had been frozen since it's last completed cycle at 00:00:12. This was during Image Linking of Locate 2 frame (#1235037) for Target 4/19 (NGC 7053), and the following warning was reported "TheSky6 isn't running or isn't working correctly ". ObsManager intervened and raised a bHardSuspend flag (00:01:58) in order to suspend the session. ObsOverseer warned that "a task in ImageAndLink/LinkImage is taking a long time?" (00:02:48). After a prescribed amount of waiting ObsManager gave the following warning "Timed out waiting for JobQueue to raise bSuspendOk" (00:03:58) and set session state to Suspending. This indicates that JobExecution was held up (almost certainly held up waiting for TheSky6 to complete the ImageLink action). After closing the dome and whilst Session State was suspended the Image Linking operation eventually completed with the success message "Ok Solved in 341.5s (Stars 57, Scale 1.407, Angle 180.0°) " (00:05:54). At the same time the Scope Monitor was recorded as having resumed (00:05:54). Inspecting the #1235037 frame it seems normal with plenty of stars and should be easy to link. Indeed during Post-Session 'Reduction/Analyse All Frames' the frame was image linked in only 0.6s. This suggests that the delay was likely not caused by the specific frame been image linked at the time, but was due to some other hold-up with the TheSky6 program. Issue reviewed and analysed as far as it could be taken. No identified action is required.

5) S1243 2024-09-14. Three cases with very similar descriptions to earlier cases, except that two of them were associated to image linking the Cam2 Reference Frame. (see Minor Issues 2024-09-14). Collectively the 3 cases were recorded as a Major Issue (see Major Issues 2024-09-15).

6) S1244 2024-09-15. Two cases with very similar descriptions to earlier cases (see Minor Issues 2024-09-15)

Analysis

The descriptions of the 9 cases are almost identical, and point to a common cause. However it obviously doesn't happen for every Locate frame that is being image linked nor does it happen for every target and clearly some sessions are unaffected. Session S1242 appears to have unlucky by having two occurances of the problem (though there turned out later on that there were 3 cases & 2 cases in Session S1243 & S1244 respectively .

Some images can take a very long time to image link (often because they have a very large number of stars or hot pixels). Examing the post-session results from 'Analyse Reduced Folder' operation shows that the locate frame from case 1a & 1b took only 1.6s only 0.7s to image link, strongly suggesting that there was no fundamental issue that caused image linking to take so long during session execution.

At around the time of the 1a incident an attempt was being made to access the ToO form in AstroPlan for Target 'GCVS T CrB (centered)', with the aim of adding it as a ToO target. The AstroPlan program began to run very slowly & stopped responding. It was presumed at the time that the user action taken in AstroPlan with its calls to TheSky6 method/properties led to TheSky6 program to stop responding & thereby caused the ImageLink process/routine to hang which then caused the Job Queue to hand/freeze. However with no similar user involvement in the 1b incident it is concluded that AstroPlan was most likely hanging/running slowing in the 1a case because TheSky6 was already not responding.

It is hypothesized that the issue occurs because there are calls on TheSky6 from certain routines whilst TheSky is busy performing ImageLinking.
Disabling/deferring calls to TheSky6 whilst Image Linking is being undertaken might fix the problem.

The ScopeMonitor was implemented around 2022-10-24 (CI S1048) and it is unclear why the issue has only appeared in S1235 (2024-08-29).
ScopeMonitor is a loop that cycles every 2.5s that reads the value of TheSky6.Telescope.IsConnected, and checks whether the Telescope is connected or not in TheSky6

If execution holds up it usually means that TheSky6 is too busy to respond or is hung up in someway. When TheSky6 starts responding again, the ScopeMonitor loop continues again.

There is possibility that it an initial freeze in CCDSoft.Image.InsertWCS routine that is at the route of the problem. This is probably unlikely and it certain be shown that TheSky6 is effectivity frozen during the problem intervals, and has therefore likely received the Imageand begun the Image Linking process.

The DeviceHub.Telescope log of messages to/from TheSky6 during the S1243 session was examined to see if there are any anomalies at the time of the 3 ImageLink freeze incidents (21:12:49, 00:38:08 & 04:05:35). Normally there are 4 to 6 messages records every second, however for during each of the 3 cases there is a 5 minutes or so gap in records (21:12:50 to 21:18:09 for first incident, 00:38:10 to 00:43:24 for second case, 04:05:37 to 04:10:29 for third case). Are these gaps due to TheSky6 being effectivity frozen during this time (so not making Ra/Dec requests) or were issues with Telescope causing TheSky and Job Queue to lock up. The latter explanation seems a very unlikely multiple coincidence, and the presence of unniterrupted message records in the DeviceHub.Telescope logs of messages to/from AstroMain and to/from AstroGuard rule out a problem with DeviceHub.Telescope, MeadeGeneric Driver or the LX200 Telescope.

Using TheSky6.Telescope.Abort is unlikely to be effective as the Telescope isn't being slewed at the time of the incidents, and may in any case cause the calling routine in AstroMain to freeze.

Locate Frame image linking uses the PlateSolveImage() routine, which calls SolvePlateWithTheSky() [ via a call to SolvePlate() ]. Image Link is performed by call to DoImageLink(x, y)

Examining the Job Queue freeze whilst performing an Image Link on Locate 2 Frame for Target 23/25 (SN 2022qwx ) during sesion S1243 (04:05) the log messages were :

This shows that DoImageLink was passed through

Common Factor is that the first call to DoImageLink (x,y) with x=-, y=0 executes ok and produces a log entry like

this means that the first call to Image.InsertWCS(1) works ok.

During Session S1244 (2024-09-15) there were 2 further incidents (00:21 & 04:38)

The following trace data was collected for the 00:21 case (AT2021aeft)

The trace information shows that point of freeze came in between the two following trace points
- Back from TheSky.GetObjectRaDec2000("Image Link Information")
- Back from TheSky.GetObjectRaDec("Image Link Information")

This narrows the point of freeze down to being in SolvePlateWithTheSky() routine in the code between the two tracing statement

WriteLogFileRecord(szTargetName, "(trace)", "(trace)", "ImageLinking", "Back from TheSky.GetObjectRaDec2000(""Image Link Information"")") TheSky.GetObjectRaDec("Image Link Information") BestRA = TheSky.dObjectRa BestDec = TheSky.dObjectDec WriteLogFileRecord(szTargetName, "(trace)", "(trace)", "ImageLinking", "Back from TheSky.GetObjectRaDec(""Image Link Information"")")

The following abbreviated trace data was collected for the 04:38 case (GCVS RR Tau), which confirms the exact same freeze point.

This raises the two following questions
- why is freezing occuring during the call to GetObjectRaDec when it appears to have no problem getting TheSky.GetObjectRaDec2000() immediately beforehand. ?
- why does 'Get TheSky.GetObjectRaDec()' cause the freeze, but only sometimes ?

Only 2 cases have been traced so far and they show the same freeze point. However it leaves open the possibility that the freeze due to TheSky.GetObjectRaDec2000 simply hasn't been observed yet. If they had equal probability of occurance (we simply don't know at this time), then getting two out of two freezes from GetObjectRaDec() only has a 25% probability outcome.

More 'traced cases' need to be logged and examined.

Despite the absence of a complete confirmation of where the freezes are happening a number of hypothesis can be constructed based on information to date:

1) The 'TheSky.GetObjectRaDec()' call somehow clash in time with the TheSky's own call to Get Telescope Ra/Dec from the scope
The 'TheSky.dObjectRa' and/or 'TheSky.dObjectDec' property reads somehow clash in time with updates to TheSky's own internal property values as a result of Ra/Dec updates from the scope.
The 'TheSky.GetObjectRaDec()' call somehow comes too soon after the call to TheSky.GetObjectRaDec2000(), or TheSky.dObjectRa comes too soon after the retrospective call to TheSky.GetObjectRaDec() or TheSky.GetObjectRaDec2000()

Previously (though not last since session S1229) ScopeMonitor would record periods of around 90s duration where TheSky6 would stop responding. It was annoying but not cirtical. This 90s duration was very consistent across the number of cases that this earlier problem occurred, so much so that only when the non-response had lasted more than 100s would ScopeMonitor' be given a 'Frozen' Status, before that it was given a 'Pending' Status.

In session S1237, the ScopeMonitor was Pending for 68s (at 01:07) whilst waiting for Target 15/27 to start.

Proposals:

Add further tracing message statements to see if the freeze point is associated with the TheSky.GetObjectRaDec() call or the subsequent
'TheSky.dObjectRa' and/or 'TheSky.dObjectDec' property reads
Add small Thread.Sleep statements to slow down the calls to TheSky6

The other potential course of action is to allow ObsManger to allow the session to continue to run on when the ImageLinking appears to have frozen, and only intervene to Abort Target and Suspend Session after the freeze has lasted more than 6 minutes (the typical freeze time is 5 minutes).

Conclusion

The issue is caused by TheSky6 not responding during image linking / plate solution, leading to the Job Queue freezing.
Typically the freeze come when image linking a Locate Frame, but it can also occur when image linking a Cam2 Reference Frame
Eventually the 'freeze' times-out after 5 minutes when TheSky6 starts responding again.
The issue is unrelated to the physical Telescope or its driver.
The issue is unrelated to the particular starfield being image linked.
The issue could be due to a subtle timing/conflict. It doesn't happen for every Image Link or Target.
(it seems to occur during 1 in 10 targets, each of which has 2-3 image links, so say a 1 in 25 chance of occuring)
It may not be neccessary for ObsManager to suspend the session and close the dome when this issue occurs, provided the frozen state doesn't last longer than 6 minutes.
The point at which the freeze has been narrowed down. It turns out that freeze isn't triggered directly by the 'InsertWCS' call (Image Linking) but is triggered instead by following GetObjectRaDec() , .dObjectRa, .dObjectDec calls which access the result of the Image Linking. But it is unclear which one of these is the precie trigger and whether the proceeding GetObjectRaDec2000() call could sometimes trigger the freeze (although not seen to date).
It is hypothesized that TheSky6 is being overwhelmed with method/property calls, and there may be opportunity/benefit to slow down the rate at which calls are made to TheSky6.
It is possible that the issue is related to the ImageLinking/TheSky6 freezing that very occasionally occurs during "Analyse Reduced Folder" operation.

Actions:

Tracing. Add tracing message statements to PlateSolving code in an attempt to better understand the problem and narrow down the position where the freeze is occuring.
Done (2024-09-15, AstroMain 3.69.7)
Tracing. Add further tracing message statements to PlateSolving code in an attempt to narrow down the position where the freeze is occuring even more precisely.
Done (2024-09-16, AstroMain 3.69.8)
Thread.Sleep statements. Add Thread.Sleep(500) statements to PlateSolving code section that calls GetObjectRaDec to slow down calls/reads to TheSky6 to see if that resolves the issue.
Done (2024-09-16, AstroMain 3.69.8)
Session Tests. Use AstroMain 3.69.8 (with added Thread.Sleep(500) statements) during two live sessions on 2024-09-16 & 2024-09-17 to see it provides a fix or partial fix to the issue, but if not provide additional tracing information about where the issue is arising
Done (2024-09-17)

Update 2024-09-18

Two sessions (S1245 2024-09-16 & S1246 2024-09-17) have been now been conducted with AstroMain 3.69.8 which contained a potential fix for the 'Frozen ImageLinking / Non-Responsive TheSky' Issue, by the insertion of Thread.Sleep(500) delays into the Plate Solving routine to slow down the calls sent to TheSky.

It wasn't certain that this potential fix would work, but there was a possibility and one worth trying based on a hunch.

In the event the fix seems to have significantly reduced the incidence of issue, but it is too soon to know if the fix is absolute.

In sessions S1243 and S1244 there were a total of 5 incidences of the issue during the course of 50 targets (an incidence rate of 1 in 10 targets)
In sessions S1245 & S1246 (using AstroMain 3.69.8) there were no incidences of the issue during the course of 33 targets.
(it would have been expected to have had 3 incidents during these two incidents based on earlier 1 in 10 targets rate of occurance)
The fact there were no incidents is deemed a significant result, but it is still too soon to say that the issue is fixed.

Update 2024-09-19

The session S1247 (2024-09-18) similarly has no incidences of the issue during course of 17 targets.
Over the last 3 sessions, there have been no issues during the course of 50 targets now
(it would have been expected to have had 5 incidents during this time based on the earlier 1 in 10 targets rate of occurance)

Update 2024-09-29

The session attempt S1248A (2024-09-28) similarly has no incidences of the issue during course of 6 targets.
Over the last 4 sessions/sessions attempts, there have been no issues during the course of 56 targets now
(it would have been expected to have had around 6 incidents during this time based on the earlier 1 in 10 targets rate of occurance)
It is concluded that the issue is most-likely fixed (by AstroMain 3.69.8), and the issue is judged as being resolved/closed.

Update 2024-10-15

There were no incidences of the issue during course of session S1245 - S1254
In session S1255 (2024-10-15) there was one further case of the incidence. This was a suprise as the issue hasn't been seen for one month since a fix was added in AstroMain 3.69.8.
After image linking Locate 2 frame from Target 27/36 (AT2024vhz) the analysis of the result was held up for some 5 minutes starting at 03:05:59 (S1255), during which time the ObsOverseer reported that the ScopeMonitor thread was frozen and that ObsManager reported that TheSky6 was not responding and indicated that session would be suspended at 03:11:59 (T+6 mins) unless TheSky6 resumes. However TheSky6 became responsive again and the ScopeMonitor became unfrozen at 03:10:51 (T+4.9 mins). This was the first time that code was added in AstroMain 3.xx (after problems during sessions S1235, S1240 & S1242 (late Aug-mid Sept 2024) was used in anger to recognise the situation and use the expected behaviour from TheSky6 to defer session suspension until to a point 1 minute longer that the time that TheSky6 normally begins resumes at. After patiently waiting the Job Executor was able to contine on and successfully completed the target (without resorting to a session suspension). This is the first time that TheSky6 has frozen in this manner since new code was added in AstroMain that adds some delays between GetRaDec calls to TheSky. Tracing showed that TheSky6 hung at the point of calling TheSky.GetObjectRaDec("Image Link Information"). i.e. the second call get coordinates call. The first calls to TheSky.GetObjectRaDec2000("Image Link Information") was returned successfully. It is possible that the time delay should be increased slightly to further reduce the incidence of this issue. The existing delay (0.5s) between calls is arbitary and increasing it is a practical solution.

03:05:59.30 | ImageLinking (trace) | Calling DoImageLink (0 \ 0) 03:05:59.32 | ImageLinking (trace) | Calling Image.InsertWCS(1) 03:05:59.83 | ImageLinking (trace) | Back from Image.InsertWCS(1) 03:05:59.86 | ImageLinking (trace) | Image.WcsArray checked 03:05:59.86 | InsertWCS (0\0) Data | Link | Stars 54 | Rms 0.49" | Angle 179.97 | Scale 1.405 | RA= 21 27 19.880 Dec=+60 34 58.82 03:05:59.86 | ImageLinking (trace) | Back from DoImageLink (0 \ 0) 03:05:59.86 | ImageLinking (trace) | Getting TheSky.GetObjectRaDec2000("Image Link Information") 03:05:59.93 | ImageLinking (trace) | Back from TheSky.GetObjectRaDec2000("Image Link Information") 03:05:59.93 | ImageLinking (trace) | Getting TheSky.dObjectRa (BestRA2000) 03:05:59.94 | ImageLinking (trace) | Getting TheSky.dObjectDec (BestDec2000) 03:05:59.98 | ImageLinking (trace) | Back from TheSky.dObjectDec (BestDec2000) 03:06:00.48 | ImageLinking (trace) | Getting TheSky.GetObjectRaDec("Image Link Information") 03:06:17.77 | ScopeMonitor Info | ScopeMonitor is Pending (18s) 03:07:47.94 | ScopeMonitor Alert | ScopeMonitor is Frozen (108s) 03:07:43.00 | Check TheSky6 Fail | Raising bHardSuspend (TheSky6 program isn't responding) 03:07:43.00 | Suspension Warning | Session will be suspended at 03:11:59 unless TheSky6 resumes 03:10:48.29 | ScopeMonitor Alert | ScopeMonitor is Frozen (288s) 03:10:51.57 | ImageLinking (trace) | Back from TheSky.GetObjectRaDec("Image Link Information") 03:10:51.65 | MonitorTheSkyScope | TheSkyScope.Monitor has resumed (cycle = 0.0s) 03:10:52.08 | ImageLinking (trace) | Getting TheSky.dObjectRa (BestRA) 03:10:52.59 | ImageLinking (trace) | Getting TheSky.dObjectDec (BestDec) 03:10:52.62 | ImageLinking (trace) | Back from TheSky.dObjectDec (BestDec) 03:10:52.62 | ImageLinking (trace) | Finished x/y loops 03:10:52.62 | ImageLinking (trace) | BestActiveStars= 54, Match=True 03:10:52.62 | ImageLinking (trace) | Logging BestMatch
The delay time between calls to GetObjectRaDec in SolvePlateWithTheSky has been increased from 0.5s to 1.0s in AstroMain 3.71.8 (2024-10-15) in attempt to further reduce the incidence of this issue.


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

	Operational Issues
	- Critical Issues (0), Major Issues (0), Minor Issues (2), Small Defects (1), Continuous Improvement (0)

	Images from 2024-09-12 >>

	Investigation - Job Queue freezing whilst performing a Locate Frame Image Link, leading to Session Suspension

This Web Page:	Notes - Session 1242 (2024-09-12)
Last Updated :	2024-10-19
Site Owner :	David Richards
Home Page :	David's Astronomy Web Site

David's Astronomy Pages
Notes - Session 1242 (2024-09-12)

Session Aims & Highlights (2024-09-12)

Operational Issues (2024-09-12 S1242)

Investigation - Job Queue freezing whilst performing a Locate Frame Image Link, leading to Session Suspension

David's Astronomy Pages Notes - Session 1242 (2024-09-12)

Session Aims & Highlights (2024-09-12)

Operational Issues (2024-09-12 S1242)

Investigation - Job Queue freezing whilst performing a Locate Frame Image Link, leading to Session Suspension

David's Astronomy Pages
Notes - Session 1242 (2024-09-12)