Issue

1a) Telescope service failed to connect during Autostart (S1122 2024-08-03 23:17)
1b) Telescope service failed to connect during Autostart (S1124 2024-08-07 22:46)
1c) Telescope service failed to connect during Autostart (S1125 2024-08-09 22:40)

Description
In three recent sessions (S1222, S1224 & S1225) the telescope has failed to connect correctly during AutoStart attempt at the beginning of the session using Start Observatory Services / Start Telescope Service.  In each case the telescope service failed to connect, a red telescope alert was raised with the message "ASCOM Telescope not connected" and the session was prevented from proceeding in Fully Automated Mode and was placed back into Manual Mode.   In sessions S1222 & S1224, the issue was identfied after 5 mins and after 15mins respectively, and a user intervention made to rerun the 'Start Observatory Services' routine and recommence Autostart, and this time the Telescope Service started ok, though with the loss of around 5-10% of the night's observing time.  In session S1125 the issue wasn't noticed until some 5 hour later wasting nearly 95% of the night's observing time.

The issue is ranked as 'Major' due to the potential, and in case of S1125 the actuality,  of loosing an entire night's observing time.

Analysis
AstroMain's log show 'Start  DeviceHub.Scope  - Fail' with message  "Failed to connect (ASCOM.MeadeGeneric.Telescope, 1.3.9.482) . Examining MeadeGeneric log show each case that after making initial connection and bypassing the Date/Time prompts, there is a timeout after around 5s when waiting for responses to :GD (Get Declination) requests to the physical telescope.

SendString        Transmitting #:GD#
SendString        Timed out waiting for received data
Declination Get   Error: Timed out waiting for received data
Connected Set     Error connecting to port COM6 - Timed out waiting for received data

e.g. from S1125

22:39:58.477 SendString Transmitting #:GR#
22:39:59.917 SendString Received 18:46:59#
22:39:59.917 RightAscension Get - 18:46:59 convert to 18.7830555555556 18:46:59
22:39:59.918 AtPark Get - False
22:39:59.918 SendString Transmitting #:GD#
22:40:04.957 SendString Timed out waiting for received data
22:40:04.957 Declination Get Error: Timed out waiting for received data
22:40:05.077 Connected Set Error connecting to port COM6 - Timed out waiting for received data

When a second attempt is made to connect Telescope it is typically successful.
e.g. from S1125

03:33:32.082 SendString Transmitting #:GR#
03:33:32.449 SendString Received 18:43:06#
03:33:32.449 RightAscension Get - 18:43:06 convert to 18.7183333333333 18:43:06
03:33:32.450 AtPark Get - False
03:33:32.450 SendString Transmitting #:GD#
03:33:32.497 SendString Received -29[DF]24:57#
03:33:32.497 Declination Get - -29[DF]24:57 convert to -29.4158333333333 -29:24:57"
03:33:32.497 AtPark Get - False
03:33:32.498 SendString Transmitting #:GA#
03:33:32.528 SendString Received -16[DF]21:31#
03:33:32.528 Altitude -16.3586111111111
03:33:32.528 AtPark Get - False
03:33:32.529 SendString Transmitting #:GZ#
03:33:32.561 SendString Received 240[DF]34:30#
03:33:32.562 Azimuth Get 240.575
03:33:32.562 Connected Set Connected OK. Current RA = 18:43:06 Dec = -29[B0] 24' 57" Az=240.575 Alt=-16.3586111111111

Problem seemed to appear with Session S1122 (2024-08-03) since the issue had been noticed with Session S1121 (2024-05-29) and before.

•  there is no indication that this is due to a change in MeadeGeneric as  the current version (1.3.9.482)  has been used since 2024-03-02 and there were no problems during sessions S1196 to S1221. 
   
•  similarly there is no indication that this is due to a change in DeviceHub as the current version (6.6.1.10) has been in use since 2022-11-12.
   
•  the telescope itself appears to be operating normally once it is successully connected upon a second attempt.  
   
•  there is no indication that this is due to the mandatory 60s wait ( that is applied after turning on scope power) is too short.   The same 60s wait has been used on past sessions which have successfully connected to scope first time, and in any case the first part of telescope connection proceeds normally in these new problem cases.
   
• AstroMain version changed from 3.68.10 to 3.69.1 between sessions S1121 and S1122,  but this doesn't immediately seem to be involved.
  
  It is noted that telescope connection proceeded completely normally during Autostart operations in session S1123 that used AstroMain 3.69.1.
   
• there is no particular indication that the cause of the issue is related to calling Connect Telescope from within AutoStart routine as opposed to manually initiating the telescope connection.
  

During a daytime test on 2023-08-10 (day after S1125 session)  the telescope connection was made from the DeviceHub UI  and was successful, however the MeadeGeneric log showed that despite completing successfully, the string response to :GD (Get Declination) took 5.022s to receive and evidentally didn't trigger a timeout at all.

12:24:59.855 SendString Transmitting #:GR#
12:25:00.302 SendString Received 08:34:21#
12:25:00.302 RightAscension Get - 08:34:21 convert to 8.5725 08:34:21
12:25:00.303 AtPark Get - False
12:25:00.303 SendString Transmitting #:GD#
12:25:05.325 SendString Received -29[DF]40:00#
12:25:05.325 Declination Get - -29[DF]40:00 convert to -29.6666666666667 -29:40:00"
12:25:05.326 AtPark Get - False
12:25:05.326 SendString Transmitting #:GA#
12:25:05.373 SendString Received +03[DF]14:05#
12:25:05.373 Altitude 3.23472222222222
12:25:05.374 AtPark Get - False
12:25:05.374 SendString Transmitting #:GZ#
12:25:05.453 SendString Received 180[DF]04:17#
12:25:05.453 Azimuth Get 180.071388888889
12:25:05.453 Connected Set Connected OK. Current RA = 08:34:21 Dec = -29[B0] 40' 00" Az=180.071388888889 Alt=3.23472222222222

Examining logs associated with other successful connections show that a response delay of around 5s is quite common it seems (occur for :GR calls in the two cases below) but fortunately they don't trigger a timeout delay, e.g. :

MeadeGeneric Log (S1221).  Here the telescope connection was successful with the wait for the  :GD (Get Declination) response taking only 0.063s, however it is noted that the response to preceeding :GR (Get RA) took 5.006s (ie is very close to a timeout condition).

23:51:32.324 SendString Transmitting #:GR#
23:51:37.330 SendString Received 20:03:27#
23:51:37.331 RightAscension Get - 20:03:27 convert to 20.0575 20:03:27
23:51:37.331 AtPark Get - False
23:51:37.331 SendString Transmitting #:GD#
23:51:37.394 SendString Received -29[DF]39:55#
23:51:37.394 Declination Get - -29[DF]39:55 convert to -29.6652777777778 -29:39:55"
23:51:37.395 AtPark Get - False
23:51:37.395 SendString Transmitting #:GA#
23:51:37.475 SendString Received +03[DF]14:14#
23:51:37.476 Altitude 3.23722222222222
23:51:37.476 AtPark Get - False
23:51:37.476 SendString Transmitting #:GZ#
23:51:37.522 SendString Received 180[DF]05:45#
23:51:37.522 Azimuth Get 180.095833333333
23:51:37.522 Connected Set Connected OK. Current RA = 20:03:27 Dec = -29[B0] 39' 55" Az=180.095833333333 Alt=3.23722222222222

MeadeGeneric Log (S1223)
Again the telescope connection was successful with the wait for the  :GD (Get Declination) response taking only 0.062s, however it is noted that the response to the preceeding :GR (Get RA) took 5.007s (i.e. very close to a timeout condition).

22:48:15.759 SendString Transmitting #:GR#
22:48:20.766 SendString Received 20:03:27#
22:48:20.767 RightAscension Get - 20:03:27 convert to 20.0575 20:03:27
22:48:20.767 AtPark Get - False
22:48:20.767 SendString Transmitting #:GD#
22:48:20.829 SendString Received -29[DF]39:55#
22:48:20.830 Declination Get - -29[DF]39:55 convert to -29.6652777777778 -29:39:55"
22:48:20.830 AtPark Get - False
22:48:20.830 SendString Transmitting #:GA#
22:48:20.910 SendString Received +03[DF]14:07#
22:48:20.910 Altitude 3.23527777777778
22:48:20.910 AtPark Get - False
22:48:20.910 SendString Transmitting #:GZ#
22:48:20.958 SendString Received 180[DF]05:39#
22:48:20.958 Azimuth Get 180.094166666667
22:48:20.958 Connected Set Connected OK. Current RA = 20:03:27 Dec = -29[B0] 39' 55" Az=180.094166666667 Alt=3.23527777777778

Looking back at a MeadeGeneric log from 2024-03-04, just after 1.3.9 was installed, and I can see a 4.91s wait for the GR (Get RightAscension) call.

18:26:40.810 SendString Transmitting #:GR#
18:26:45.720 SendString Received 20:03:27#
18:26:45.721 RightAscension Get - 20:03:27 convert to 20.0575 20:03:27
18:26:45.721 AtPark Get - False

Looking at a MeadeGeneric log from 2024-01-12, when I was running 1.3.5, it is harder / impossible(?) to calculate the wait times as it doesn't contain the 'SendString Transmitting' and 'SendString Transmitting' messages, that logs from 1.3.9 have.

So although wait times of 4.9 - 5.022s have been associated with telescope connections during sessions between 2023-03-02 and 2023-05-29, its only sessions since 2024-08-03 (post-summer hiatus) (have 3 out of 4 sessions produce these timeout / connection failures.

I've now implemented a workaround fix, whereby my client program automatically makes up to 3 attempts to get a successful telescope connection before it gets up. This fix was successfully employed last night - the 1st attempt failed in the manner described above, the automatic 2nd attempt succeeded and the session ran the whole night.

Conclusion

• An edge situation is sometimes exposed during Telescope Connection  whereby SendString calls to :GD (Get Declination), but potentially other SendString calls, that can sometimes take around 5s to return a response, can on occasions lead to a timeout after a wait of around 5.05s+, and leading to a Connect exception and that the failure to successfully connect to the telescope
   
• It is unclear why the incidence of timeouts  / connection failures has increased in frequency to being 3 times in the last 4 sessions. It is suspected that the timeout cutoff and speed of computer / port is having a subtle - knifeedge association

Actions:

• AstroMain. Change CCDSoft.Camera calls (outside of CCDCamera) to use CCDCamera calls instead.
     Done.  AstroMain 3.69.2
   
• MeadeGeneric. Contact Colin Dawson, author of MeadeGeneric regarding issue & associated observations
     In Progress  (emails have been sent on 2024-08-11 & 2024-08-19  but no replied has been received as of 2024-08-25)
  

Update 2024-08-10
A daytime test of 3.69.2 was made,  during Connect Telescope Services, the first attempt failed but the new code automatically made a second attempt which was successful.

Meade Generic logs show that the first connection attempt failed due to a timeout on SendString :GR (Get RightAscension) showing that (as suspected) timeouts can happen on other strings (not just :GD)

16:02:38.450 SendString Transmitting #:GR#
16:02:43.473 SendString Timed out waiting for received data
16:02:43.473 RightAscension Get Error: Timed out waiting for received data
16:02:43.592 Connected Set Error connecting to port COM6 - Timed out waiting for received data
16:02:44.109 Connected Get False

whilst the automated second attempt succeeded:

16:02:55.909 SendString Transmitting #:GR#
16:02:55.956 SendString Received 12:12:33#
16:02:55.956 RightAscension Get - 12:12:33 convert to 12.2091666666667 12:12:33
16:02:55.957 AtPark Get - False
16:02:55.957 SendString Transmitting #:GD#
16:02:56.004 SendString Received -29[DF]40:05#
16:02:56.004 Declination Get - -29[DF]40:05 convert to -29.6680555555556 -29:40:05"
16:02:56.004 AtPark Get - False
16:02:56.005 SendString Transmitting #:GA#
16:02:56.052 SendString Received +03[DF]13:58#
16:02:56.052 Altitude 3.23277777777778
16:02:56.052 AtPark Get - False
16:02:56.052 SendString Transmitting #:GZ#
16:02:56.100 SendString Received 180[DF]08:00#
16:02:56.100 Azimuth Get 180.133333333333
16:02:56.100 Connected Set Connected OK. Current RA = 12:12:33 Dec = -29[B0] 40' 05" Az=180.133333333333 Alt=3.23277777777778
16:02:56.612 Connected Get True

Tracing shows that the error in first attempt doesn't thrown an exception to the client, but it results in Get property Scope.Connected = False

Update 2024-08-11
A workaround fix has been implemented in AstroMain 3.69.2, whereby the client program now automatically makes up to 3 attempts to get a successful telescope connection before it gives up.  This fix was successfully employed last night (2024-08-10) - the 1st attempt failed in the manner described above, but the automatically applied 2nd attempt succeeded and the session successfully ran the whole night.