Is there a log file for Focuser Pro2 when it's controlled by ASCOM? I know how to get the log file when using the windows software, but not when I'm using something like Sequence Generator Pro.
The reason I ask is that "seeming" randomly when SGP is focusing via ASCOM, the focuser will go to zero then return to the commanded focuser position. Say I'm at 6000 and I use the course button in SGP to ask the focuser to go to 6500. On occasion, the focuser will go to zero then back to 6500.
Other times it just goes to 6 and stops there (when asked to go to any position).
So, I'm stumped. A log file would really help me diagnose what is going on.
-Jim
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
I'm wondering whether Jim found out anything about this. I am experiencing the same thing. I started a thread on the SGP forum asking them to look into it.
Once again, thanks Robert for such a fine project. After a couple of years using my DIY focus controller, I'm still giddy that I have one of the best controllers available for an investment of about $10.
Tim
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
Ensure you have the power-on reset circuit fitted to prevent the controller from resetting all the time due to SGP disconnects.
Also see the private messages I send you re what happens when you enable temp comp in the controller and that SGP ignores this when requesting a move - SGP should first check to see if it is enabled Before trying to do a move - I have noted in the logfile where this occurs - SGP then instead of handling the ascom exception correctly just disconnects the focuser then tries to reconnect 5ms later.
As for the position 0, the likely cause could also be SGP as its clear in previous log entries that the focuser position returned by the controller is valid and non-zero. There is no evidence in the SGP log that the controller returned a 0 or invalid number.
[01/04/18 20:53:03.344][DEBUG][Focuser Move Thread] Focuser backlash active, modified move to 25256 [01/04/18 20:53:03.344][DEBUG][Focuser Move Thread] Focuser move call complete [01/04/18 20:53:05.953][DEBUG][Focuser Backlash Thread] Focuser moving to 25206 [01/04/18 20:53:05.965][DEBUG][Focuser Backlash Thread] Attempting to move focuser to 0, but it is greater than max value 0
so SGP knew it was at 25256 and then tried 25206 and somehow decided to go to 0 - there is no evidence in the SGP log that it requested anything from the controller - either the SGP is not logging all calls or it assumed by itself for some reason to goto 0. We can only know for certain if we have the ascom driver log then we could match the times and see if SGP issued some other focuser request between 20:53:05:953 and 20:53:05:965 - the SGP log is very silent on this.
If I was guessing I would say it has something to do with
1. the backlash routines in SGP
2. the fact that SGP keeps disconnecting/reconnecting the focuser
3. that SGP does NOT bother to check TempCOmp before any move request (which it should) and does not handle the ASCOM exception correctly
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
Hi Tim
I can see multiple things wrong but here is another
You said
Since SGP does not fully honor the ASCOM standard for temperature compensation by allowing me to enable it or disable it from the GUI, I have to close the focuser and then open the ASCOM settings to toggle TempComp and then reconnect as needed. I don’t know if this is relevant or not.
That is very relevant. I can see in the log file where you do this. Immediately after, what happens is SGP tries a MOVE which fails (the driver throws an exception which in ASCOM is what it should do). SGP then disconnects the focuser, reconnects 5ms later (it should be waiting a lot longer than 5ms - that is just stupid, any focuser needs time to restart). On that reconnect SGP does NOT bother to check TempComp but just assumes everything is as before. SGP should not be dropping the connection or attempting any reconnect 5ms later.
After immediately reconnecting, SGP then attempts the Move again. Same result. SGP is assuming TempComp has not changed. What SGP should be doing is checking for TempComp before every Move OR handling the exception in a cleaner way (it could easily check TempComp after the exception and then it would know and then how to handle it instead of blindly dropping the focuser connection). Because SGP is not providing a means for the user to control TempComp on or off, if the focuser changes tempcomp state SGP then has no way of knowing and subsequent moves fail because the code logic is flawed.
Cheers
Robert
If Temperature Compensation is being handled by the focuser, then SGP needs to recognize that and respect that instead of trying to do whatever it wants (like moving the focuser or attempting auto-focus when TempComp is true)
Last edit: brownrb 2018-01-08
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
On the latest thread, looks like they think its the driver returning 0 (I seriously doubt that - correction it did but there is a reason for this - explanation below in further post) - I suspect its the former (the focuser was disconnected and SGP returned 0) - and I think it all points to the fact that SGP is not bothering to check TempComp before a Move (if it is then its checking a cached copy - they admit that much that they only read the value on connect then cache it).
The fact that SGP is handling the ASCOM exception by simplying disconnecting and then reconnecting 5ms later is a pretty poor way of handling exceptions.
To be fair, what is being attempted here by Tim is something SGP was not coded for - the developers never assumed that the focuser might enable TempComp during operation after connecting - not a valid assumption - had they provided the means for the user to enable/disable TempComp via the user interface then NONE of these issues wouldve happened and I believe SGP would be operating fine.
Just to add one final thing - the myFocuserPro2 has an ASCOM conform and validation file - it has passed ALL the tests without issue.
regards
Last edit: brownrb 2018-01-09
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
Right around 21:02:08 is where the trouble starts. Unfortunately I am not very skilled at interpreting the log, so any help you can provide would be greatly appreciated. I think the SGP developers will be willing to work with me on this if I can prove that the problem is on their end.
Tim
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
Hi Tim
As I go through this I will post what I find so there may be more than one post
First
19:52:21.203 CS: Set TempComp ON/OFF c :231#
Focus controller starts with TempComp ON (Enabled)
19:55:37.109 CS: Set TempComp ON/OFF c :230#
SGP turns TEMPCOMP OFF
Then SGP starts moving the focuser (auto-focus routine?)
19:55:37.184 Move 25325
and continues to move the focuser
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?
Then SGP repeatedly calls for focuser position every second (in one instance only 10ms apart). I cannot see any justification for this. The focuser is under control of SGP. Its position will not move. This places (according to Chris) an unnecessary load on the driver.
19:56:46.126 Position Get calling
19:56:46.535 Position Get calling
19:56:46.553 Position Get calling
19:56:46.677 Position Get calling
19:56:47.550 Position Get calling
19:56:47.566 Position Get calling
19:56:48.609 Position Get calling
19:56:49.867 Position Get calling
19:56:50.884 Position Get calling
19:56:51.901 Position Get calling
and so on
Then
19:57:55.451 TempComp Get Sending to controller
SGP requests TempComp state which is OFF (correct)
19:57:55.465 CS: Set TempComp ON/OFF c :231#
SGP turns TempComp ON
and then returns to polling the focuser for position again every second and temperature every 20 seconds and isMoving every 20 seconds
Again I would have to say that calling get position every second places a high load on any driver.
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 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 ccall. 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 bewteen each call - 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
1. 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.
2. SGP should not initiate an auto-focus when temperature compensation is enabled in the focuser. It should give the user the choice to override
3. 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
4. SGP should wait for a response before issuing another call of the same type (getPosition)
4. 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+
5. The 1ms repeat getPosition call at 21:02:08.000 from SGP causes the issue
6. 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?
7. After calling getPosition, SGP keeps requesting maxSteps from the focuser. This is unnecessary and SGP should be using the cached version
8. 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.
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 the 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.
Happy for you to post.
Regards
Robert
Last edit: brownrb 2018-01-09
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
Tim
As a temporary fix for what SGP is doing, please try this ASCOM driver v247 (making changes to correct for bad behaviour in a client application)
The change I have made in this driver is that it checks maxSteps for a value of 0 and if it is, reissues the call to the controller (after 10ms delay) in the hope that the second call will return the correct value. It tries to adjust for what SGP is doing.
I have also protected the serial port with a Mutex (only one call allowed at a time) - which should prevent SGP from overloading the driver with repeated calls over a short period of time.
Included is the ASCOM validation/conform files to show there is nothing wrong with the focuser and it passes all the ASCOM tests.
I will need to look at the Arduino code soon, the issue is the 1ms time between the calls is causing an issue with the code and not sure I can overcome that. The changes in the ASCOM driver with the Mutex should slow down SGP's over enthusiam in sending calls quickly. I think SGP is doing something wrong when its issuing 10 calls for getPosition in 1second when only one is necessary,
Regards
Robert
I also recommend disabling temperature compensation in the controller if you are using SGP and have SGP configured to auto-focus
Please let me know if 247 fixes your issue with SGP
Thanks Robert. I will try that out as soon as I get some clear skies again. I'm a little frustrated with what to do about tempcomp and autofocus. My scope changes focus pretty dramatically when the temperature is changing rapidly. It is not uncomon for a 300s sub to start in perfect focus and be outside of the CFZ by the time the exposure ends. However, the temperature coefficient is not constant. I have checked this several times. Focus might change by 20 steps per degree for the first 3 hours or so, but drop to closer to 10 steps per degree for the rest of the night. So, I can't rely on tempcomp to keep me in perfect focus throughout the night. I really need an AF routine from time to time . SGP should be able to do this. I can say, knowing their philosophy, that they will not want user interaction (like approving dsabling of tempcomp for autofocus) once a sequence starts. I tend to agree, since most of my imaging is remote, when I start a sequence, I want it to run without my intervention.
Of course a simple way to do this is to allow the user to give SGP permission to override tempcomp when a profile is set up. That is what I would be after - run the focuser with tempcomp enabled, and allow AF to disable it temporarily, run the AF routine and then re-enable temocomp.
Tim
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
Hi Tim
I do not know what focuser firmware you are using - I have added some extra code to the firmware
Hi Tim
Yes, I understand about the tempcomp coefficient steps being different - we are using an approximation/average whereas some implementations use a slope curve and that is probably what we should migrate to. I'll think more about this,
At present SGP is doing Autofocus by disabling tempcomp in the focuser, then re-enabling it once auto-focus is completed - this is working - just in your case there is an issue with the driver not being able to handle calls which are 1ms apart - I did some testing and its handling calls at 5ms apart without issue and down to 2ms apart with the very rare occassional issue. 1ms it does not handle.
The new driver should not give the issue you are experiencing. Calls are now protected with a mutex sempahore, so if the ascom driver gets multiple calls in a short period from SGP these will not proceed/interrupt the previous call. I believe the new driver will resolve your issue. I do not know how SGP will react to this but what I have done is recommended in the ASCOM developer notes so I have not broken any rules or good programming practise.
It still does not account for the excessive number of calls that SGP is doing - I believe that is a coding issue within SGP and just because other focusers have not reported issues doesnt mean to say its correct behaviour. I just cannot see any reason why SGP is doing that and it just does not make any sense. Calling the same ASCOM method 10 times in less than one second - I cannot see the reasoning behind that.
Let me know how 247 goes.
Cheers
Robert
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
Thanks so much for your help with this Robert. I'll have to check too be sure (the computer with the firmware is in the observatory), but I just updated the firmware a few days ago so I'm pretty sure it is 263.
I have the new ASCOM driver installed waiting for some clear skies. As soon as you publish a firmware update, I'll install that too.
Tim
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
I am not sure we will much of a shift from SGP but am happy to try and put a workaround in the driver to compensate. Ideally they should fix their code logic and reduce the number of calls for getPosition and getMaxSteps, that would solve the problem right away without affecting any driver.
I do not expect any movement re the temperature compensation issue and I like your idea of a profile setting in SGP which I think is a great comprimise.
SGP may find something, I don't know. But for now, I am hoping 247 will address the issues you are finding.
Hey, thanks for perserving and raising it, the log files were really helpful and if we don't know about issues they would never get fixed! Thanks
Regards
Robert
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
Hi
I have updated the ASCOM driver (significantly) to v249. This has a lot more code in it to handle wayward clients, so am hoping that this will fix the issues being caused by SGP. I have got a lot of feedback and advice from other ASCOM developers over the last day or two which has been really great.
Is there a log file for Focuser Pro2 when it's controlled by ASCOM? I know how to get the log file when using the windows software, but not when I'm using something like Sequence Generator Pro.
The reason I ask is that "seeming" randomly when SGP is focusing via ASCOM, the focuser will go to zero then return to the commanded focuser position. Say I'm at 6000 and I use the course button in SGP to ask the focuser to go to 6500. On occasion, the focuser will go to zero then back to 6500.
Other times it just goes to 6 and stops there (when asked to go to any position).
So, I'm stumped. A log file would really help me diagnose what is going on.
-Jim
In the setupdialog box, check Trace On
The log file is in Documents\ASCOM\Logs-xx-xx-xx folder where xx-xx-xx is the date
This has been reported before as an issue with SGP
Robert: Man, your support for this free project is above and beyond and beyond. Thank you.
Do you have a donte button somewhere?
Not necessary - its all about helping others,
I'm wondering whether Jim found out anything about this. I am experiencing the same thing. I started a thread on the SGP forum asking them to look into it.
http://forum.mainsequencesoftware.com/t/autofocus-bug-causing-focuser-runaway/6899
Once again, thanks Robert for such a fine project. After a couple of years using my DIY focus controller, I'm still giddy that I have one of the best controllers available for an investment of about $10.
Tim
Ensure you have the power-on reset circuit fitted to prevent the controller from resetting all the time due to SGP disconnects.
Also see the private messages I send you re what happens when you enable temp comp in the controller and that SGP ignores this when requesting a move - SGP should first check to see if it is enabled Before trying to do a move - I have noted in the logfile where this occurs - SGP then instead of handling the ascom exception correctly just disconnects the focuser then tries to reconnect 5ms later.
As for the position 0, the likely cause could also be SGP as its clear in previous log entries that the focuser position returned by the controller is valid and non-zero. There is no evidence in the SGP log that the controller returned a 0 or invalid number.
[01/04/18 20:53:03.344][DEBUG] [Focuser Move Thread] Focuser backlash active, modified move to 25256
[01/04/18 20:53:03.344][DEBUG] [Focuser Move Thread] Focuser move call complete
[01/04/18 20:53:05.953][DEBUG] [Focuser Backlash Thread] Focuser moving to 25206
[01/04/18 20:53:05.965][DEBUG] [Focuser Backlash Thread] Attempting to move focuser to 0, but it is greater than max value 0
so SGP knew it was at 25256 and then tried 25206 and somehow decided to go to 0 - there is no evidence in the SGP log that it requested anything from the controller - either the SGP is not logging all calls or it assumed by itself for some reason to goto 0. We can only know for certain if we have the ascom driver log then we could match the times and see if SGP issued some other focuser request between 20:53:05:953 and 20:53:05:965 - the SGP log is very silent on this.
If I was guessing I would say it has something to do with
1. the backlash routines in SGP
2. the fact that SGP keeps disconnecting/reconnecting the focuser
3. that SGP does NOT bother to check TempCOmp before any move request (which it should) and does not handle the ASCOM exception correctly
Hi Tim
I can see multiple things wrong but here is another
You said
Since SGP does not fully honor the ASCOM standard for temperature compensation by allowing me to enable it or disable it from the GUI, I have to close the focuser and then open the ASCOM settings to toggle TempComp and then reconnect as needed. I don’t know if this is relevant or not.
That is very relevant. I can see in the log file where you do this. Immediately after, what happens is SGP tries a MOVE which fails (the driver throws an exception which in ASCOM is what it should do). SGP then disconnects the focuser, reconnects 5ms later (it should be waiting a lot longer than 5ms - that is just stupid, any focuser needs time to restart). On that reconnect SGP does NOT bother to check TempComp but just assumes everything is as before. SGP should not be dropping the connection or attempting any reconnect 5ms later.
After immediately reconnecting, SGP then attempts the Move again. Same result. SGP is assuming TempComp has not changed. What SGP should be doing is checking for TempComp before every Move OR handling the exception in a cleaner way (it could easily check TempComp after the exception and then it would know and then how to handle it instead of blindly dropping the focuser connection). Because SGP is not providing a means for the user to control TempComp on or off, if the focuser changes tempcomp state SGP then has no way of knowing and subsequent moves fail because the code logic is flawed.
Cheers
Robert
If Temperature Compensation is being handled by the focuser, then SGP needs to recognize that and respect that instead of trying to do whatever it wants (like moving the focuser or attempting auto-focus when TempComp is true)
Last edit: brownrb 2018-01-08
On the latest thread, looks like they think its the driver returning 0 (I seriously doubt that - correction it did but there is a reason for this - explanation below in further post) - I suspect its the former (the focuser was disconnected and SGP returned 0) - and I think it all points to the fact that SGP is not bothering to check TempComp before a Move (if it is then its checking a cached copy - they admit that much that they only read the value on connect then cache it).
The fact that SGP is handling the ASCOM exception by simplying disconnecting and then reconnecting 5ms later is a pretty poor way of handling exceptions.
To be fair, what is being attempted here by Tim is something SGP was not coded for - the developers never assumed that the focuser might enable TempComp during operation after connecting - not a valid assumption - had they provided the means for the user to enable/disable TempComp via the user interface then NONE of these issues wouldve happened and I believe SGP would be operating fine.
Just to add one final thing - the myFocuserPro2 has an ASCOM conform and validation file - it has passed ALL the tests without issue.
regards
Last edit: brownrb 2018-01-09
Thanks for your help with this Robert. I didd find a focuser log where this happened. Here:
https://www.dropbox.com/s/fnzpa9z19wawd8r/ASCOM.myFocuserPro2ASCOM.1952.189250.txt?dl=0
Right around 21:02:08 is where the trouble starts. Unfortunately I am not very skilled at interpreting the log, so any help you can provide would be greatly appreciated. I think the SGP developers will be willing to work with me on this if I can prove that the problem is on their end.
Tim
Hi Tim
As I go through this I will post what I find so there may be more than one post
First
19:52:21.203 CS: Set TempComp ON/OFF c :231#
Focus controller starts with TempComp ON (Enabled)
19:55:37.109 CS: Set TempComp ON/OFF c :230#
SGP turns TEMPCOMP OFF
Then SGP starts moving the focuser (auto-focus routine?)
19:55:37.184 Move 25325
and continues to move the focuser
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?
Then SGP repeatedly calls for focuser position every second (in one instance only 10ms apart). I cannot see any justification for this. The focuser is under control of SGP. Its position will not move. This places (according to Chris) an unnecessary load on the driver.
19:56:46.126 Position Get calling
19:56:46.535 Position Get calling
19:56:46.553 Position Get calling
19:56:46.677 Position Get calling
19:56:47.550 Position Get calling
19:56:47.566 Position Get calling
19:56:48.609 Position Get calling
19:56:49.867 Position Get calling
19:56:50.884 Position Get calling
19:56:51.901 Position Get calling
and so on
Then
19:57:55.451 TempComp Get Sending to controller
SGP requests TempComp state which is OFF (correct)
19:57:55.465 CS: Set TempComp ON/OFF c :231#
SGP turns TempComp ON
and then returns to polling the focuser for position again every second and temperature every 20 seconds and isMoving every 20 seconds
Again I would have to say that calling get position every second places a high load on any driver.
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 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 ccall. 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 bewteen each call - 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
1. 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.
2. SGP should not initiate an auto-focus when temperature compensation is enabled in the focuser. It should give the user the choice to override
3. 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
4. SGP should wait for a response before issuing another call of the same type (getPosition)
4. 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+
5. The 1ms repeat getPosition call at 21:02:08.000 from SGP causes the issue
6. 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?
7. After calling getPosition, SGP keeps requesting maxSteps from the focuser. This is unnecessary and SGP should be using the cached version
8. 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.
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 the 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.
Happy for you to post.
Regards
Robert
Last edit: brownrb 2018-01-09
Tim
As a temporary fix for what SGP is doing, please try this ASCOM driver v247 (making changes to correct for bad behaviour in a client application)
The change I have made in this driver is that it checks maxSteps for a value of 0 and if it is, reissues the call to the controller (after 10ms delay) in the hope that the second call will return the correct value. It tries to adjust for what SGP is doing.
I have also protected the serial port with a Mutex (only one call allowed at a time) - which should prevent SGP from overloading the driver with repeated calls over a short period of time.
Included is the ASCOM validation/conform files to show there is nothing wrong with the focuser and it passes all the ASCOM tests.
I will need to look at the Arduino code soon, the issue is the 1ms time between the calls is causing an issue with the code and not sure I can overcome that. The changes in the ASCOM driver with the Mutex should slow down SGP's over enthusiam in sending calls quickly. I think SGP is doing something wrong when its issuing 10 calls for getPosition in 1second when only one is necessary,
Regards
Robert
I also recommend disabling temperature compensation in the controller if you are using SGP and have SGP configured to auto-focus
Please let me know if 247 fixes your issue with SGP
Last edit: brownrb 2018-01-09
Thanks Robert. I will try that out as soon as I get some clear skies again. I'm a little frustrated with what to do about tempcomp and autofocus. My scope changes focus pretty dramatically when the temperature is changing rapidly. It is not uncomon for a 300s sub to start in perfect focus and be outside of the CFZ by the time the exposure ends. However, the temperature coefficient is not constant. I have checked this several times. Focus might change by 20 steps per degree for the first 3 hours or so, but drop to closer to 10 steps per degree for the rest of the night. So, I can't rely on tempcomp to keep me in perfect focus throughout the night. I really need an AF routine from time to time . SGP should be able to do this. I can say, knowing their philosophy, that they will not want user interaction (like approving dsabling of tempcomp for autofocus) once a sequence starts. I tend to agree, since most of my imaging is remote, when I start a sequence, I want it to run without my intervention.
Of course a simple way to do this is to allow the user to give SGP permission to override tempcomp when a profile is set up. That is what I would be after - run the focuser with tempcomp enabled, and allow AF to disable it temporarily, run the AF routine and then re-enable temocomp.
Tim
Hi Tim
I do not know what focuser firmware you are using - I have added some extra code to the firmware
Hi Tim
Yes, I understand about the tempcomp coefficient steps being different - we are using an approximation/average whereas some implementations use a slope curve and that is probably what we should migrate to. I'll think more about this,
At present SGP is doing Autofocus by disabling tempcomp in the focuser, then re-enabling it once auto-focus is completed - this is working - just in your case there is an issue with the driver not being able to handle calls which are 1ms apart - I did some testing and its handling calls at 5ms apart without issue and down to 2ms apart with the very rare occassional issue. 1ms it does not handle.
The new driver should not give the issue you are experiencing. Calls are now protected with a mutex sempahore, so if the ascom driver gets multiple calls in a short period from SGP these will not proceed/interrupt the previous call. I believe the new driver will resolve your issue. I do not know how SGP will react to this but what I have done is recommended in the ASCOM developer notes so I have not broken any rules or good programming practise.
It still does not account for the excessive number of calls that SGP is doing - I believe that is a coding issue within SGP and just because other focusers have not reported issues doesnt mean to say its correct behaviour. I just cannot see any reason why SGP is doing that and it just does not make any sense. Calling the same ASCOM method 10 times in less than one second - I cannot see the reasoning behind that.
Let me know how 247 goes.
Cheers
Robert
Thanks so much for your help with this Robert. I'll have to check too be sure (the computer with the firmware is in the observatory), but I just updated the firmware a few days ago so I'm pretty sure it is 263.
I have the new ASCOM driver installed waiting for some clear skies. As soon as you publish a firmware update, I'll install that too.
Tim
Hi Tim
I dont know if its DRV8825_HW203?
I am not sure we will much of a shift from SGP but am happy to try and put a workaround in the driver to compensate. Ideally they should fix their code logic and reduce the number of calls for getPosition and getMaxSteps, that would solve the problem right away without affecting any driver.
I do not expect any movement re the temperature compensation issue and I like your idea of a profile setting in SGP which I think is a great comprimise.
SGP may find something, I don't know. But for now, I am hoping 247 will address the issues you are finding.
Hey, thanks for perserving and raising it, the log files were really helpful and if we don't know about issues they would never get fixed! Thanks
Regards
Robert
Sorry for the delay. I've been away on busiess. I'm using L293D
Tim
Hi Tim
No worries.
I am hoping that with the latest v249 ASCOM drivers there will be no need to change the arduino firmware.
Regards
Robert
Hi
I have updated the ASCOM driver (significantly) to v249. This has a lot more code in it to handle wayward clients, so am hoping that this will fix the issues being caused by SGP. I have got a lot of feedback and advice from other ASCOM developers over the last day or two which has been really great.
Cheers
Robert
Robert:
I'm happy to report that I am on my third night of imaging. Two full nights and counting with no trouble. Thanks a bunch.
Tim
Thanks for the help Tim, most appreciated.
Regards
Robert