As the author of the ASCOM driver (which fully passes CONFORM and all the tests), I have followed this with interest and have a few comments on this. Yes the driver did return an invalid value but the reason for this occurs a little earlier (I will get to that in a moment though).
19:56:45.629 CS: GetMaxStep Recvd M50000
SGP still moving but again requests MaxSteps
and then requests MaxSteps again 100ms later
19:56:45.764 CS: GetMaxStep Recvd M50000
and then again
19:56:45.899 CS: GetMaxStep Recvd M50000
and keeps requesting focuser position and Maxsteps again and again from
19:56:45.999 Position Get calling
19:56:46.014 CS: Get MaxStep cmd= :08#
to
19:56:46.141 CS: Get MaxStep cmd= :08#
That just seems to be overkill - it should be caching MaxSteps and it should not need to get the position after the move has finished at < 100ms intervals because the move is finished. On what assumption is maxSteps changed? Why is it necessary to call it more than once?
Then SGP repeatedly calls for focuser position every second (in one instance only 10ms apart). I cannot see any justification for this.
19:56:47.550 Position Get calling
19:56:47.566 Position Get calling
20:08:18.497 CS: GetPosition Recvd: P24976
We see the focuser position change - this was due to the temperature compensation within the focuser being applied (not from SGP)
and again at
20:16:19.704 CS: GetPosition Recvd: P24969
Now what is also evident that when the focuser position changes, SGP then requests maxSteps again
20:08:18.538 CS: GetMaxStep Recvd M50000
20:16:19.717 CS: GetMaxStep Recvd M50000
20:16:19.843 CS: GetMaxStep Recvd M50000
Again, every time this happens SGP again requests maxSteps - I would argue (with Chris) that SGP should be using a cached copy. Here two maxStep get calls are issued by SGP 100ms apart. There is NO NEED to call maxsteps THREE times in the space of 1.3 seconds. There should be ONLY ONE call needed.
So far the focuser is operating fine (apart from maxSteps being repeatedly requested and sometimes 100ms apart, and that the focuser position is being requested every 1 second, somes more frequently)
Again the focuser is controlling focus position through temperature compensation (the position changes again - about 5s-8s apart as temperature drops)
20:21:47.022 CS: GetPosition Recvd: P24962
after which SGP again calls for MaxStep (so SGP is making an assumption that whenever the focuser position changes maxsteps may also change)
20:21:47.062 CS: GetMaxStep Recvd M50000
SGP requests the state of TempComp which is True (correct)
20:26:03.499 CS: TempCompEnabled Recvd 11
SGP turns off temperature compensation
20:26:03.502 CS: Set TempComp ON/OFF c :230#
SGP gets position
20:26:03.532 CS: GetPosition Recvd: P24962
SGP gets maxsteps
20:26:03.564 CS: GetMaxStep Recvd M50000
SGP checks ismoving which is false (correct)
20:26:03.581 CS: IsMoving Recvd: I00
SGP sets new position
20:26:03.581 CS: SET NEW POSITION cmd= :0525287#
Now something initiated this in SGP - perhaps an autofocus routine?
I would argue that because the focuser is in temperature compensation mode, the focuser is controlling focus, not SGP, and SGP should not be trying to move the focuser position. I believe SGP shouldve popped up a dialog box warning the user that temperature compensation was enabled and gave the user the choice to leave it alone or let SGP take over
SGP then goes into a series of GetPosition and GetMaxSteps calls. There is NO need to call maxSteps all the time like this. Again repeated calls to GetMaxSteps are often only 100ms apart. What is the justification for more than one call? And repeated again and again over such a small time frame? Why doesnt SGP just issue one call and wait?
20:27:42.800 Position Get 24959
it seems the auto-focus is completed
SGP requests tempcomp state
20:28:13.801 TempComp Get Sending to controller
SGP turns on temperature compensation
20:28:13.813 CS: Set TempComp ON/OFF c :231#
Focuser applies temperature compensation internally
20:34:54.907 CS: GetPosition Recvd: P24952
SGP again requests maxSteps
20:34:54.948 CS: GetMaxStep Recvd M50000
Focuser applies temperature compensation internally
20:45:42.981 CS: GetPosition Recvd: P24945
SGP again requests maxSteps
20:45:43.029 CS: GetMaxStep Recvd M50000
Focuser applies temperature compensation internally
20:51:27.258 Position Get 24938
SGP again requests maxSteps
20:51:27.299 MaxStep Get 50000
Another auto-focus by SGP
21:02:05.862 TempComp Get Sending to controller
21:02:05.873 CS: TempCompEnabled Recvd 11
21:02:05.877 CS: Set TempComp ON/OFF c :230#
Now here is where it goes wrong
21:02:07.987 CS: Get Position cmd= :00#
21:02:07.987 CS: :00#
21:02:07.988 Position Get calling
21:02:07.999 CS: GetPosition Recvd: P25263
21:02:07.999 CS: :00#
21:02:07.999 CS: 25263
21:02:07.999 Position Get 25263
21:02:07.999 CS: Get Position cmd= :00#
21:02:07.999 CS: :08#
21:02:08.000 CS: Get Position cmd= :00#
21:02:08.005 CS: Get MaxStep cmd= :08#
21:02:08.011 CS: GetPosition Recvd: P25263
21:02:08.011 CS: 25263
21:02:08.011 Position Get 25263
21:02:08.019 CS: GetPosition Recvd: P25263
21:02:08.020 CS: 25263
21:02:08.020 CS: :01#
21:02:08.020 Position Get 25263
21:02:08.028 CS: GetMaxStep Recvd 50000
21:02:08.028 CS: 0000
21:02:08.028 MaxStep Get 0000
21:02:08.028 CS: IsMoving cmd= :01#
21:02:08.040 CS: IsMoving Recvd: I00
21:02:08.040 CS: 00
21:02:08.040 IsMoving 00
21:02:08.040 IsMoving Returning 0 - not moving
21:02:08.040 Move 0
21:02:08.040 Move Position = 0
21:02:08.040 Move focuserPosition = 25263
21:02:08.040 Move Maxsteps = 0
21:02:08.040 Move focuserPosition = 0
21:02:08.040 Move 0
A breakdown
21:02:07.987 CS: Get Position cmd= :00#
21:02:07.999 CS: Get Position cmd= :00#
21:02:08.000 CS: Get Position cmd= :00#
21:02:08.005 CS: Get MaxStep cmd= :08#
and then
21:02:08.028 CS: GetMaxStep Recvd 50000
21:02:08.028 CS: 0000
21:02:08.028 MaxStep Get 0000
Because the driver returned maxSteps 0 then SGP sets focuser position to 0.
What caused this?
21:02:07.987 CS: Get Position cmd= :00#
21:02:07.999 CS: Get Position cmd= :00#
21:02:08.000 CS: Get Position cmd= :00#
21:02:08.005 CS: Get MaxStep cmd= :08#
12ms between first Getposition command and second
1ms between second GetPosition command and third
WHY did SGP issue 3 get position commands so quickly one after the other when only 1 would suffice? SGP did not even bother to wait for a reply before issuing a second and a third call. This caused the focuser driver to overload and return the wrong value as commands were coming in too quickly. It was the third command that caused the driver to fail.
Now this did not happen after the previous auto-focus routine at 19:57 because there is more time delays between all the getPosition calls that follow at the end of the auto-focus routine. The driver handles repeated calls with 5ms delays between them without issue.
SGP should only need to issue 1 getPosition command and 1 getmaxcall and wait for the response.
Again lets look at this sequence
20:27:41.957 CS: Get Position cmd= :00#
20:27:42.094 CS: Get Position cmd= :00#
20:27:42.137 CS: Get Position cmd= :00#
20:27:42.149 CS: Get Position cmd= :00#
again very little time between each call - and again and again
20:27:42.225 CS: Get Position cmd= :00#
20:27:42.239 CS: Get Position cmd= :00#
20:27:42.377 CS: Get Position cmd= :00#
20:27:42.511 CS: Get Position cmd= :00#
20:27:42.651 CS: Get Position cmd= :00#
20:27:42.786 CS: Get Position cmd= :00#
That is 10 calls is less than 1 second
20:27:43.525 CS: Get Position cmd= :00#
20:27:43.613 CS: Get Position cmd= :00#
20:27:44.537 CS: Get Position cmd= :00#
20:27:44.553 CS: Get Position cmd= :00#
There are times that SGP issues two or more getPosition commands within very small delays between calls.
my conclusions about what is happening in relation to SGP
- Immediately after completing an auto-focus, SGP issues multiple getPosition calls over very short intervals and does not wait for a reply before issuing the next one. There is no need for 10 getPosition calls within the space of 1 second as the log shows
- SGP should wait for a response before issuing another call of the same type (getPosition)
- At this time in the sequence (after auto-focus is finished) SGP is generating too may getPosition calls with little or no delay between them. SGP should only require a single call to getPosition not 10. The log shows the time between calls varies from 1ms all the way to 10ms+
- The 1ms repeat getPosition call at 21:02:08.000 from SGP causes the issue
- On getting maxSteps at 0, SGP then tries to move the focuser to position 0. Logic might dictate that perhaps a drastic change from a previous value of 50000 to 0 was maybe an error, so SGP mightve been better to flag that and attempt another maxSteps call before assuming 0 was the right value?
- After calling getPosition, SGP keeps requesting maxSteps from the focuser. This is unnecessary and SGP should be using the cached version
- If SGP feels that it is necessary to issue so many getPosition calls in such a short space of time, it should WAIT for response before issuing the next getPosition call. SGP should also ensure that calls for getPosition are just not fired off in quick succession.
- SGP does not need to poll getposition every second. Every 2 or 3s (like focusmax) woud place less strain on any driver and still achieve the same results. This is a focuser, not a telescope which would be changing position all the time.
- SGP should not initiate an auto-focus when temperature compensation is enabled in the focuser. It should give the user the choice to override
I think that because SGP is multi-threaded, there maybe multiple threads that are generating getPosition calls, and that these end up all occuring around the same time with little or no gaps between them. It would be better having this handled by a single thread. It appears that this ONLY happens when an auto-focus routine is completed.
This is based on these facts - that the two previous auto-focus routines worked without issue. Immediately following the auto-focus there is a burst of getPosition calls - the first and second instances show the times between these calls to be ok that the driver handles fine, but in the third sequence at 21:02:08.000 its 1ms or less and the driver cannot handle that. The variation in times for the getPosition calls between the three sequences indicates this is based in SGP, not the driver.
Thus SGP is determining the frequency and timing of these getPosition calls. And when completing an auto-focus, SGP is generating too many (possibly from multiple threads) and with little or no time lapse between them.
Chris - can you please give a view on my logic - I am happy to be corrected. I just don’t see the need for any client to repeat getposition and getmaxstep calls to any driver repeatedly again and again over such a short time (1ms apart is a good idea?) or 10 calls in under a second for the same value?
I am not trying to place blame on SGP - Yes the driver should not have returned an invalid value. I do accept that. But I would like an explanation as to why SGP is generating so many repeated calls to the driver when only one would suffice?
Regards
Robert