Hi all,

New test tonight, and same results in the log. After every "Linear: un-doing extension. Moving back in by XX", there is a tty error.
I post here the lines, no need to attach all the log file, it's the very same.

---

---

And I did use another power source this time to feed the Robofocus: a reliable 12V 4A, to discard that also.

I guess next test will be to change the autofocus algorithm...

Any other idea?

Thanks for you help, and regards.

Jordi.

Hi Jordi,

Are you able to build from source?
If not, please ignore the rest of this message
=========================
Some thoughts.
In robofocus.cpp, search for
"TTY error detected"

I see three of them. They are all the same string, can you enumerate them like:
TTY error detected1
TTY error detected2
TTY error detected3

So can tell which one fired
One is in SendCommand and two are in ReadResponse

A -BIG- kludge to slow things down a bit for sending the actual move commands
In the routine
int RoboFocus::updateRFPositionAbsolute(double value)

Just before
if ((robofocus_rc = SendCommand(rf_cmd)) < 0)
return robofocus_rc;

Add a usleep (below is sleep for at least 5 milliseconds), i.e.

usleep(5000);
if ((robofocus_rc = SendCommand(rf_cmd)) < 0)
return robofocus_rc;


If you get an error that usleep is undefined, add this near the top

#include <unistd.h>

Gene

Hi Gene, thanks for your suggestions.

I do not have a developer environment in the rPi (it runs from an SD card), but I can do it in the Mac. I will try to modify the driver following your advice, but it may take longer to test.

In the meantime, yesterday night I switched to the Polynomial algorithm and the autofocus process (I ran it three times) worked without timeouts. Perhaps it has to do with how the Linear algorithm works? well, anyway, it is a positive change.

I will go on with my tests and update this thread with my results. If you have any other suggestions, they will be very welcome!

Thanks for your help, and regards,

Jordi.

Hi Jordi,

Would be interesting to see the log when you are using Polynomial.

You sure captured the failure in the other log's and identified it was the reversing.

Gene

Hi Gene and Jordi!

Jordi, many thanks for raising this issue! I am using a Robofocus clone (Stepperfocuser) and have to deal with these TTY/timeout error messages for years. I didn't bother to bring it up here since I was able to work around them by disconnecting-reconnecting the focuser.

Gene, thanks a lot for your help! I applied the changes you have suggested and although I was clicking wildly on the focus in / focus out buttons (with and without backlash enabled) I am currently unable to cause any TTY/timeout error messages!

I'll test a bit more and will come back should I encounter error messages again. But until now this looks very promising!

Thanks again!
Alfred

Hi Alfred,

Interesting to hear the usleep did -something-.
It is a kludge as it will stall the whole thread the focus routine is running in.

In the robofocus.cpp there are two commented out usleep's from time past, not sure what/why they were originally added then removed.

If you have the time, change the usleep(5000) to lower and lower values with bisection, say
2500
Then if 2500 fails
3750
Or if it works
1250

Each time taking the difference and adding half or subtracting half based on works or fails.

usleep is -supposed- to wait at least the given value long but may wait longer depending on system load scheduling.

Gene

Until now I tried 2000 (doing fine) and 1000 where I got a few error messages. I'll fine-tune further but wanted to let you know the error that I got is "error detected2:"

Example:
[2022-10-04T14:44:07.731 CEST DEBG ][ org.kde.kstars.ekos.focus] - Abs Focuser position changed to 19000 State: Ok
[2022-10-04T14:44:07.731 CEST DEBG ][ org.kde.kstars.indi] - RoboFocus : "[DEBUG] Moving Absolute Position: 19200 "
[2022-10-04T14:44:07.731 CEST DEBG ][ org.kde.kstars.indi] - RoboFocus : "[DEBUG] CMD (0X46 0X47 0X30 0X31 0X39 0X32 0X30 0X30 0XFFFFFFB9) "
[2022-10-04T14:44:07.732 CEST DEBG ][ org.kde.kstars.indi] - RoboFocus : "Focuser is moving 200 steps outward... "
[2022-10-04T14:44:11.237 CEST INFO ][ org.kde.kstars.indi] - RoboFocus : "[ERROR] TTY error detected2: Timeout error "
[2022-10-04T14:44:11.239 CEST INFO ][ org.kde.kstars.indi] - RoboFocus : "[WARNING] Bogus position: (00 00 00 00 00 00 00 00 00) - Bytes read: -1 "
[2022-10-04T14:44:11.245 CEST DEBG ][ org.kde.kstars.indi] - RoboFocus : "[DEBUG] Moving Absolute Position: 19200 "
[2022-10-04T14:44:11.245 CEST DEBG ][ org.kde.kstars.indi] - RoboFocus : "[DEBUG] CMD (0X46 0X47 0X30 0X31 0X39 0X32 0X30 0X30 0XFFFFFFB9) "
[2022-10-04T14:44:11.245 CEST DEBG ][ org.kde.kstars.indi] - RoboFocus : "Focuser is moving 200 steps outward... "
[2022-10-04T14:44:11.245 CEST DEBG ][ org.kde.kstars.indi] - RoboFocus : "[DEBUG] Moving Absolute Position: 19200 "
[2022-10-04T14:44:11.245 CEST DEBG ][ org.kde.kstars.indi] - RoboFocus : "[DEBUG] CMD (0X46 0X47 0X30 0X31 0X39 0X32 0X30 0X30 0XFFFFFFB9) "
[2022-10-04T14:44:11.245 CEST DEBG ][ org.kde.kstars.indi] - RoboFocus : "Focuser is moving 200 steps outward... "
[2022-10-04T14:44:11.245 CEST DEBG ][ org.kde.kstars.indi] - RoboFocus : "[DEBUG] Moving Absolute Position: 19200 "
[2022-10-04T14:44:11.245 CEST DEBG ][ org.kde.kstars.indi] - RoboFocus : "[DEBUG] CMD (0X46 0X47 0X30 0X31 0X39 0X32 0X30 0X30 0XFFFFFFB9) "
[2022-10-04T14:44:11.245 CEST DEBG ][ org.kde.kstars.indi] - RoboFocus : "Focuser is moving 200 steps outward... "
[2022-10-04T14:44:11.245 CEST DEBG ][ org.kde.kstars.indi] - RoboFocus : "[DEBUG] Moving Absolute Position: 19200 "
[2022-10-04T14:44:11.245 CEST DEBG ][ org.kde.kstars.indi] - RoboFocus : "[DEBUG] CMD (0X46 0X47 0X30 0X31 0X39 0X32 0X30 0X30 0XFFFFFFB9) "
[2022-10-04T14:44:11.245 CEST DEBG ][ org.kde.kstars.indi] - RoboFocus : "Focuser is moving 200 steps outward... "
[2022-10-04T14:44:11.245 CEST DEBG ][ org.kde.kstars.indi] - RoboFocus : "[DEBUG] Moving Absolute Position: 19200 "
[2022-10-04T14:44:11.245 CEST DEBG ][ org.kde.kstars.indi] - RoboFocus : "[DEBUG] CMD (0X46 0X47 0X30 0X31 0X39 0X32 0X30 0X30 0XFFFFFFB9) "
[2022-10-04T14:44:11.245 CEST DEBG ][ org.kde.kstars.indi] - RoboFocus : "Focuser is moving 200 steps outward... "
[2022-10-04T14:44:12.132 CEST DEBG ][ org.kde.kstars.ekos.focus] - Abs Focuser position changed to 19200 State: Ok
[2022-10-04T14:44:13.133 CEST DEBG ][ org.kde.kstars.indi] - RoboFocus : "[DEBUG] Querying Position... "
[2022-10-04T14:44:13.134 CEST DEBG ][ org.kde.kstars.indi] - RoboFocus : "[DEBUG] CMD (0X46 0X47 0X30 0X30 0X30 0X30 0X30 0X30 0XFFFFFFAD) "
[2022-10-04T14:44:13.152 CEST DEBG ][ org.kde.kstars.indi] - RoboFocus : "[DEBUG] Position: 19200 "
[2022-10-04T14:44:14.154 CEST DEBG ][ org.kde.kstars.indi] - RoboFocus : "[DEBUG] Querying Position... "
[2022-10-04T14:44:14.155 CEST DEBG ][ org.kde.kstars.indi] - RoboFocus : "[DEBUG] CMD (0X46 0X47 0X30 0X30 0X30 0X30 0X30 0X30 0XFFFFFFAD) "

Ok, I tested thoroughly with usleep(1200). It works in so far as I do not get any timeout errors. Fine!

However, I encountered a strange behaviour:
If I press the "focus in" button once and wait till the focuser has finished its move, everything is fine.
If I press the "focus in" buttone while the focuser is still moving, this is what happens:
1. Press "focus in" button
2. Focuser starts moving in
3. Press "focus in" again while focuser is still moving in from previous press.
4. Focuser will finish the first move as expected (going the full distance) and start a second move right away. However, this second move is clearly shorter (you can hear and see it) than the first one. It won't move the full distance but finishes short/early.

If I press the "focus in" button for a third time while the focuser is still moving in executing the 2nd press:
5. Focuser will finish its second (short) move and start a thrid move right away. This third one will be a full move again (like the first one).

If I press the "focus in" button for a 4th time while the focuser is executing the 3rd move, it will add another "short" move. And so on....

If I press "focus in" twice while the focuser is executing the first move, just one additional move is added.

I don't know whether this makes any sense. All I can do is report what I see happening here. I can post a video if needed.

Yes Gene, of course. Here you have the log of that session.



Thanks for your help, and regards.

Jordi.

Hi Alfred, welcome to the thread!



Very interesting. I also wanted to test that <strong>usleep</strong>, it's great reading that it works for you!

And about that strange behaviour... What about the debug log? All clicks should move a fixed amount of ticks/steps and go to an absolute position. Do you have a backlash value defined?

Regards from Barcelona,

Jordi.

I think I worked out your *strange behaviour*, Alfred. I guess the target focus position gets updated the moment we click, calculating the destinantion position adding to the current position, and not the to the end of the previous click (the ongoing movement)

In this log, every click should move 500 steps, but look what happens every time we meet <strong>Focusing outward by 500 steps</strong>

<code>
[2022-10-04T19:45:43.663 CEST INFO ][ org.kde.kstars.indi] - OnFocus : "[INFO] Focuser is moving to position 6500 "
[2022-10-04T19:45:43.894 CEST DEBG ][ org.kde.kstars.ekos.focus] - Abs Focuser position changed to 6004 State: Busy
[2022-10-04T19:45:45.460 CEST DEBG ][ org.kde.kstars.ekos.focus] - Abs Focuser position changed to 6038 State: Busy
[2022-10-04T19:45:47.026 CEST DEBG ][ org.kde.kstars.ekos.focus] - Abs Focuser position changed to 6168 State: Busy
[2022-10-04T19:45:48.587 CEST DEBG ][ org.kde.kstars.ekos.focus] - Abs Focuser position changed to 6324 State: Busy
[2022-10-04T19:45:50.152 CEST DEBG ][ org.kde.kstars.ekos.focus] - Abs Focuser position changed to 6461 State: Busy
[2022-10-04T19:45:51.718 CEST DEBG ][ org.kde.kstars.ekos.focus] - Abs Focuser position changed to 6496 State: Busy
[2022-10-04T19:45:53.282 CEST DEBG ][ org.kde.kstars.ekos.focus] - Abs Focuser position changed to 6500 State: Busy
[2022-10-04T19:45:53.312 CEST INFO ][ org.kde.kstars.indi] - OnFocus : "[INFO] Focuser reached requested position. "
[2022-10-04T19:45:58.067 CEST INFO ][ org.kde.kstars.ekos.focus] - "Focusing outward by 500 steps..."
[2022-10-04T19:45:58.083 CEST INFO ][ org.kde.kstars.indi] - OnFocus : "[INFO] Focuser is moving to position 7000 "
[2022-10-04T19:45:59.443 CEST DEBG ][ org.kde.kstars.ekos.focus] - Abs Focuser position changed to 6520 State: Busy
[2022-10-04T19:46:01.005 CEST DEBG ][ org.kde.kstars.ekos.focus] - Abs Focuser position changed to 6604 State: Busy
[2022-10-04T19:46:02.567 CEST DEBG ][ org.kde.kstars.ekos.focus] - Abs Focuser position changed to 6760 State: Busy
[2022-10-04T19:46:03.248 CEST INFO ][ org.kde.kstars.ekos.focus] - "Focusing outward by 500 steps..."
[2022-10-04T19:46:03.263 CEST INFO ][ org.kde.kstars.indi] - OnFocus : "[INFO] Focuser is moving to position 7260 "
[2022-10-04T19:46:04.123 CEST INFO ][ org.kde.kstars.ekos.focus] - "Focusing outward by 500 steps..."
[2022-10-04T19:46:04.138 CEST DEBG ][ org.kde.kstars.ekos.focus] - Abs Focuser position changed to 6916 State: Busy
[2022-10-04T19:46:04.159 CEST INFO ][ org.kde.kstars.indi] - OnFocus : "[INFO] Focuser is moving to position 7260 "
[2022-10-04T19:46:04.861 CEST INFO ][ org.kde.kstars.ekos.focus] - "Focusing outward by 500 steps..."
[2022-10-04T19:46:04.881 CEST INFO ][ org.kde.kstars.indi] - OnFocus : "[INFO] Focuser is moving to position 7416 "
[2022-10-04T19:46:05.693 CEST DEBG ][ org.kde.kstars.ekos.focus] - Abs Focuser position changed to 7071 State: Busy
[2022-10-04T19:46:07.254 CEST DEBG ][ org.kde.kstars.ekos.focus] - Abs Focuser position changed to 7227 State: Busy
[2022-10-04T19:46:08.815 CEST DEBG ][ org.kde.kstars.ekos.focus] - Abs Focuser position changed to 7372 State: Busy
[2022-10-04T19:46:10.379 CEST DEBG ][ org.kde.kstars.ekos.focus] - Abs Focuser position changed to 7410 State: Busy
[2022-10-04T19:46:11.945 CEST DEBG ][ org.kde.kstars.ekos.focus] - Abs Focuser position changed to 7416 State: Busy
[2022-10-04T19:46:11.975 CEST INFO ][ org.kde.kstars.indi] - OnFocus : "[INFO] Focuser reached requested position. "

</code>

Not sure if this is a bug or a feature... anyway, it explains what you see. Besides, this was with another focuser I had nearby (DIY OnFocus), which proves it has nothing to do with our Robofocus, it's the way eKos works.

Regards,

Jordi.

The only timeout error I still get (with usleep 1200) is a "TTY error detected3:" right after connecting the Robofocus device. The "multiple press" issue is irrelevant to Ekos AFAIAC as Autofocus should work perfectly well despite it. I attach my latest logfile. Looks good to me...