×

INDI Library v1.9.9 Released (30 Nov 2022)

Bi-monthly INDI Library released with new drivers and bug fixes.

Robofocus - 'Busy' state produces tty timeout / bogus

  • Posts: 22
  • Thank you received: 2
Hi All,

I'm running current kStars/eKos 3.6.0 under Astroberry. Recently I added a Robofocus to my setup. I seems to work fine in manual mode but I have problems with the autofocus process. I have other focusers (diy OnStep/OnFocus) autofocusing fine, I only have issues with the RoboFocus.

I have noticed that the RoboFocus indi driver produces errors (tty timeout / bogus position) when autofocusing. I usually manually disconnect/connect the indi driver for the process to continue.

Trying to know what happens in order to tell it more clearly, I have managed to reproduce it when moving the focuser manually: It works fine in normal use, but this issue happens when I change focus directions very fast. In the log, it always reads State: Busy at the end of the position notice, just before the timeouts occur:

INFO ][ org.kde.kstars.ekos.focus] - "Focusing outward by 3 steps..."
[2022-09-30T19:20:35.358 CEST INFO ][ org.kde.kstars.indi] - RoboFocus : "[INFO] Moving outward... "
[2022-09-30T19:20:35.752 CEST INFO ][ org.kde.kstars.indi] - RoboFocus : "[INFO] Stopped. "
[2022-09-30T19:20:35.753 CEST DEBG ][ org.kde.kstars.ekos.focus] - Abs Focuser position changed to 10175 State: Busy
[2022-09-30T19:20:35.758 CEST INFO ][ org.kde.kstars.indi] - RoboFocus : "[INFO] Focuser is moving to position 10181 "
[2022-09-30T19:20:39.007 CEST INFO ][ org.kde.kstars.indi] - RoboFocus : "[ERROR] TTY error detected: Timeout error "
[2022-09-30T19:20:39.012 CEST INFO ][ org.kde.kstars.indi] - RoboFocus : "[WARNING] Bogus position: (00 00 00 00 00 00 00 00 00) - Bytes read: -1 "
[2022-09-30T19:20:46.014 CEST INFO ][ org.kde.kstars.indi] - RoboFocus : "[ERROR] TTY error detected: Timeout error "
[2022-09-30T19:20:46.020 CEST INFO ][ org.kde.kstars.indi] - RoboFocus : "[WARNING] Bogus position: (00 00 00 00 00 00 00 00 00) - Bytes read: -1


If I do nothing, the system keeps outputting this error. In manual mode, if I press again any button for a manual movement, everything works again.

When running autofocus, it keeps waiting until I disconnect/connect manually (then the autofocus process tries to continue). In that case, the log does not tell that 'Busy' state, but the result is exactly the same happening in manual mode:

org.kde.kstars.ekos.focus] - "Focusing outward by 31 steps..."
[2022-09-28T22:28:10.149 CEST DEBG ][ org.kde.kstars.indi] - RoboFocus : "[DEBUG] Moving Absolute Position: 10209 "
[2022-09-28T22:28:10.149 CEST DEBG ][ org.kde.kstars.indi] - RoboFocus : "[DEBUG] CMD (0X46 0X47 0X30 0X31 0X30 0X32 0X30 0X39 0XB9) "
[2022-09-28T22:28:10.151 CEST INFO ][ org.kde.kstars.indi] - RoboFocus : "[INFO] Focuser is moving to position 10209 "
[2022-09-28T22:28:10.394 CEST INFO ][ org.kde.kstars.indi] - RoboFocus : "[INFO] Moving outward... "
[2022-09-28T22:28:10.515 CEST INFO ][ org.kde.kstars.indi] - RoboFocus : "[INFO] Stopped. "
[2022-09-28T22:28:10.515 CEST DEBG ][ org.kde.kstars.ekos.focus] - Abs Focuser position changed to 10209 State: Ok
[2022-09-28T22:28:10.516 CEST DEBG ][ org.kde.kstars.ekos.focus] - "Linear: un-doing extension. Moving back in by 15"
[2022-09-28T22:28:10.517 CEST INFO ][ org.kde.kstars.ekos.focus] - "Focusing inward by 15 steps..."
[2022-09-28T22:28:10.520 CEST DEBG ][ org.kde.kstars.indi] - RoboFocus : "[DEBUG] Moving Absolute Position: 10194 "
[2022-09-28T22:28:10.520 CEST DEBG ][ org.kde.kstars.indi] - RoboFocus : "[DEBUG] CMD (0X46 0X47 0X30 0X31 0X30 0X31 0X39 0X34 0XBC) "
[2022-09-28T22:28:10.522 CEST INFO ][ org.kde.kstars.indi] - RoboFocus : "[INFO] Focuser is moving to position 10194 "
[2022-09-28T22:28:13.774 CEST INFO ][ org.kde.kstars.indi] - RoboFocus : "[ERROR] TTY error detected: Timeout error "
[2022-09-28T22:28:13.778 CEST INFO ][ org.kde.kstars.indi] - RoboFocus : "[WARNING] Bogus position: (00 00 00 00 00 00 00 00 00) - Bytes read: -1 "

I have tried changing the serial<->USB cable, and it makes no difference.

Perhaps this device needs a small extra pause after sending every command?. I have not found a place to make such an adjustment in the driver interface. Setting higher values in the polling period (4s right now) or settle times (2s) made no difference.

Is there anything else I can try in order to solve this issue?

Thanks for your help.

Regards from Barcelona
3 months 3 weeks ago #86748

Please Log in or Create an account to join the conversation.

  • Posts: 22
  • Thank you received: 2
I have done the same test (manual focusing changing focus directions as fast as I can) in my Mac, with the most recent 3.6.1 beta (Build: 2022-09-30T18:04:42Z), another serial/USB cable, and it behaves the same way.

When It gets the timeout, I wait some seconds, click again on a manual focus button and starts working again. If I don't click, it goes on with the timeout/bogus errors

File Attachment:

File Name: log_22-42-00.txt
File Size:90 KB
Last edit: 3 months 3 weeks ago by Jordi Sesé. Reason: specify test type
3 months 3 weeks ago #86754
Attachments:

Please Log in or Create an account to join the conversation.

  • Posts: 264
  • Thank you received: 50
Hi Jordi,

Starting at timestamp [2022-09-30T22:45:02.978] in your log, there are more than a few move absolute commnads sent in just 6 milliseconds.

Sending this many move commands, not sure what it does to timer_hit with all the remove/set's done at the end of MoveAbsFocuser.

The above does not help with your autofocus issue, is your power to the unit known good?

Gene
3 months 3 weeks ago #86767

Please Log in or Create an account to join the conversation.

  • Posts: 22
  • Thank you received: 2
Thanks for your replay Gene,

Yes, the latter log was obtained in the Mac, where I clicked as fast as I could both manual focus buttons in order to reproduce the same response from the driver. It is not the same operation, but the resulting response was the same.

The Astroberry based kstars/ekos enabled/disabled debug without my intervention and seemed a bit more obscure, that's why I cropped it in the first message... I'm attaching it now anyway, I hope it shows the issue in a better way.

File Attachment:

File Name: log_19-16-36.txt
File Size:382 KB


The lines reading "RoboFocus" is disconnected it's me, manually disconnecting/reconnecting the driver in the indi interface for the process to go on.

Anyway, reviewing the logs again, now I see that every time there is a timeout, it is preceeded by a line reading Linear: un-doing extension. Moving back in by... I guess this happens every time backlash correction is applied.
Perhaps those orders are sent too fast for this focuser? Any other ideas?

As per the power source, it is a 12V 10A power supply. It feeds most of the equipment. I think I will power the focuser from a separate source next time to assure it has nothing to do with this issue.

Thanks for your help, and regards,

Jordi.
3 months 3 weeks ago #86769
Attachments:

Please Log in or Create an account to join the conversation.

  • Posts: 22
  • Thank you received: 2
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.
[2022-10-01T23:40:04.814 CEST INFO ][           org.kde.kstars.indi] - RoboFocus :  "[INFO] Moving outward... "
[2022-10-01T23:40:04.841 CEST INFO ][           org.kde.kstars.indi] - RoboFocus :  "[INFO] Stopped. "
[2022-10-01T23:40:04.841 CEST DEBG ][     org.kde.kstars.ekos.focus] - Abs Focuser position changed to  10301 State: Ok
[2022-10-01T23:40:04.841 CEST DEBG ][     org.kde.kstars.ekos.focus] - "Linear: un-doing extension. Moving back in by 15"
[2022-10-01T23:40:04.841 CEST INFO ][     org.kde.kstars.ekos.focus] - "Focusing inward by 15 steps..."
[2022-10-01T23:40:04.847 CEST INFO ][           org.kde.kstars.indi] - RoboFocus :  "[INFO] Focuser is moving to position 10286 "
[2022-10-01T23:40:08.102 CEST INFO ][           org.kde.kstars.indi] - RoboFocus :  "[ERROR] TTY error detected: Timeout error "
[2022-10-01T23:40:08.107 CEST INFO ][           org.kde.kstars.indi] - RoboFocus :  "[WARNING] Bogus position: (00 00 00 00 00 00 00 00 00) - Bytes read: -1 "


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.
3 months 3 weeks ago #86798

Please Log in or Create an account to join the conversation.

  • Posts: 264
  • Thank you received: 50
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
3 months 3 weeks ago #86815

Please Log in or Create an account to join the conversation.

  • Posts: 22
  • Thank you received: 2
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.
3 months 3 weeks ago #86866

Please Log in or Create an account to join the conversation.

  • Posts: 264
  • Thank you received: 50
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
3 months 3 weeks ago #86874

Please Log in or Create an account to join the conversation.

  • Posts: 858
  • Thank you received: 139
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
Last edit: 3 months 3 weeks ago by Alfred.
3 months 3 weeks ago #86891

Please Log in or Create an account to join the conversation.

  • Posts: 264
  • Thank you received: 50
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
3 months 3 weeks ago #86893

Please Log in or Create an account to join the conversation.

  • Posts: 858
  • Thank you received: 139
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) "
3 months 3 weeks ago #86894

Please Log in or Create an account to join the conversation.

  • Posts: 858
  • Thank you received: 139
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.
Last edit: 3 months 3 weeks ago by Alfred.
3 months 3 weeks ago #86895

Please Log in or Create an account to join the conversation.

Time to create page: 0.673 seconds