Bug 410094 - Kstars sometimes fails to wait for a slew to happen before slew is regarded as complete on the mount tool.
Summary: Kstars sometimes fails to wait for a slew to happen before slew is regarded a...
Status: RESOLVED WORKSFORME
Alias: None
Product: kstars
Classification: Applications
Component: general (show other bugs)
Version: git
Platform: Compiled Sources Linux
: NOR normal
Target Milestone: ---
Assignee: Jasem Mutlaq
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2019-07-22 06:55 UTC by James Lancaster
Modified: 2021-01-13 04:33 UTC (History)
0 users

See Also:
Latest Commit:
Version Fixed In: 3.3.5


Attachments
Wireshark Log (1.07 MB, application/gzip)
2019-08-06 21:53 UTC, James Lancaster
Details
kstars log (307.18 KB, application/zip)
2019-08-06 21:54 UTC, James Lancaster
Details
align debug patch (4.45 KB, patch)
2019-08-12 15:14 UTC, Jasem Mutlaq
Details
Kstars log after patch using CCD simulator (532.70 KB, application/zip)
2019-08-22 19:15 UTC, James Lancaster
Details

Note You need to log in before you can comment on or make changes to this bug.
Description James Lancaster 2019-07-22 06:55:58 UTC
SUMMARY
In some cases when using the mount model tool, KStars/Ekos has immediately decided the slew is over. 

Ex: 
[2019-07-19T01:17:54.891 CDT INFO ][     org.kde.kstars.ekos.align] - "Slewing to target coordinates: RA (00h 00m 00s) DEC ( 55° 51' 27\")."
[2019-07-19T01:17:55.064 CDT INFO ][     org.kde.kstars.ekos.align] - "Slew complete. Solving Alignment Point. . ."
[2019-07-19T01:17:55.065 CDT INFO ][     org.kde.kstars.ekos.align] - "Settling..."

This comes from Align::processNumber in align.cpp, which seems to only check if the Equatorial coordinates show as IPS_OK, even if the mount has had no chance to update the status. (In this case I had it as 200ms, you'll note that the Slew to Slew Complete is less than that, and I think the default polling is something like 500ms from the lx200 derived drivers.) So it seems that there should be a minimum delay before it fires off, and/or a state change to/from tracking/slewing before it registers.

Do note this is also kstars running on one machine, and gigabit ethernet to a mini pc (also running the same OS) 

It's also possible that the driver isn't doing something right, but based on what I can tell, the driver starts doing that immediately after a status update finishes. (Which is a little talky, but I don't belive that's the issue here.)

Timeline which may be more clear:
2019-07-19T01:17:54.555 (Update, Mode: Tracking)
2019-07-19T01:17:54.870 (Command to sync sent to mount)
2019-07-19T01:17:54.891 (Ekos align module, says send to slew) 
2019-07-19T01:17:54.951 (Update, Mode: Tracking as Command not yet sent)
2019-07-19T01:17:55.064 (Ekos regards slew as complete)
2019-07-19T01:17:55.096 (Command to Goto sent to mount)
2019-07-19T01:17:55.292 (Update, Mode: Slewing)
2019-07-19T01:17:55.365 (Ekos mount registers status change)
2019-07-19T01:17:55.660 (Update, Mode: Slewing)


STEPS TO REPRODUCE
1. Keep Aligning and it will sometimes happen. It is not a regular thing. My assumption is that there is the condition of it getting to that case only sometimes. 

OBSERVED RESULT
Using the mount model, sometimes the Align module decides it's done with the slew, even if the slew is far from complete. 

EXPECTED RESULT
Wait for the slew, solve, sync, slew, until everything is done. As it does, some times. 


SOFTWARE/OS VERSIONS
Kstars: (roughly 3.3.2) Build: 2019-07-03T05:13:32Z

Operating System: Kubuntu 19.04
KDE Plasma Version: 5.15.4
KDE Frameworks Version: 5.56.0
Qt Version: 5.12.2
Kernel Version: 5.0.0-20-generic
OS Type: 64-bit
Processors: 8 × Intel® Core™ i7-4700HQ CPU @ 2.40GHz
Memory: 23.5 GiB of RAM



ADDITIONAL INFORMATION


More complete log section, if needed the full one can be attached, but it is 213MB


[2019-07-19T01:17:54.790 CDT INFO ][     org.kde.kstars.ekos.align] - "Solver completed in 4 seconds."
[2019-07-19T01:17:54.798 CDT INFO ][     org.kde.kstars.ekos.align] - "Solution coordinates: RA (18h 35m 21s) DEC ( 38° 51' 53\") Telescope Coordinates: RA (18h 37m 35s) DEC ( 38° 48' 07\")"
[2019-07-19T01:17:54.798 CDT DEBG ][           org.kde.kstars.indi] - ISD:Telescope: Syncing...
[2019-07-19T01:17:54.803 CDT DEBG ][           org.kde.kstars.indi] - ISD:Telescope sending coords RA: "18h 35m 21s" ( 18.5893 ) DE: " 38° 51' 53\"" ( 38.8649 )
[2019-07-19T01:17:54.803 CDT INFO ][     org.kde.kstars.ekos.align] - "Syncing to RA (18h 35m 21s) DEC ( 38° 51' 53\")"
[2019-07-19T01:17:54.840 CDT INFO ][           org.kde.kstars.indi] - Nikon DSLR DSC D5300 :  "[INFO] Saving device configuration... "
[2019-07-19T01:17:54.840 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] <setObjectRA> "
[2019-07-19T01:17:54.840 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:Sr 18:35:21#> "
[2019-07-19T01:17:54.840 CDT INFO ][           org.kde.kstars.indi] - Nikon DSLR DSC D5300 :  "[INFO] Device configuration saved. "
[2019-07-19T01:17:54.841 CDT DEBG ][           org.kde.kstars.indi] - Nikon DSLR DSC D5300 : "[DEBUG] Configuration successfully saved. "
[2019-07-19T01:17:54.842 CDT INFO ][           org.kde.kstars.indi] - Nikon DSLR DSC D5300 :  "[INFO] CCD FOV rotation updated to -107.446 degrees. "
[2019-07-19T01:17:54.853 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:Sr 18:35:21#> successful. "
[2019-07-19T01:17:54.854 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] <setObjectDEC> "
[2019-07-19T01:17:54.854 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:Sd +38:51:54#> "
[2019-07-19T01:17:54.870 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:Sd +38:51:54#> successful. "
[2019-07-19T01:17:54.870 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[DEBUG] CMD <:CM#> "
[2019-07-19T01:17:54.870 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:CM#> "
[2019-07-19T01:17:54.881 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <N/A> "
[2019-07-19T01:17:54.882 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[DEBUG] RES <N/A> "
[2019-07-19T01:17:54.882 CDT INFO ][           org.kde.kstars.indi] - LX200 OnStep :  "[INFO] OnStep: Synchronization successful. "
[2019-07-19T01:17:54.882 CDT INFO ][     org.kde.kstars.ekos.align] - "Mount is synced to solution coordinates. Astrometric solver is successful."
[2019-07-19T01:17:54.885 CDT DEBG ][           org.kde.kstars.indi] - ISD:Telescope:  TRACK
[2019-07-19T01:17:54.890 CDT DEBG ][           org.kde.kstars.indi] - ISD:Telescope sending coords RA: "00h 00m 00s" ( 9.8125e-05 ) DE: " 55° 51' 27\"" ( 55.8577 )
[2019-07-19T01:17:54.891 CDT INFO ][     org.kde.kstars.ekos.align] - "Slewing to target coordinates: RA (00h 00m 00s) DEC ( 55° 51' 27\")."
[2019-07-19T01:17:54.926 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GR#> "
[2019-07-19T01:17:54.926 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <18:37:35> "
[2019-07-19T01:17:54.951 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] VAL [18.6264] "
[2019-07-19T01:17:54.951 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GD#> "
[2019-07-19T01:17:54.951 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <+38*48:07> "
[2019-07-19T01:17:54.951 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] VAL [38.8019] "
[2019-07-19T01:17:54.951 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GU#> "
[2019-07-19T01:17:54.951 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <Nptza/ET270> "
[2019-07-19T01:17:54.951 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:Gm#> "
[2019-07-19T01:17:54.951 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <E> "
[2019-07-19T01:17:54.951 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:%BD#> "
[2019-07-19T01:17:54.957 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <0> "
[2019-07-19T01:17:54.957 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:%BR#> "
[2019-07-19T01:17:54.966 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <0> "
[2019-07-19T01:17:54.966 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GX90#> "
[2019-07-19T01:17:54.978 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <1.00> "
[2019-07-19T01:17:54.979 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[DEBUG] Guide Rate: 1.000000 "
[2019-07-19T01:17:54.979 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GX95#> "
[2019-07-19T01:17:54.988 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <1> "
[2019-07-19T01:17:54.989 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GX96#> "
[2019-07-19T01:17:54.998 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <B> "
[2019-07-19T01:17:54.998 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GXE9#> "
[2019-07-19T01:17:55.009 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <30> "
[2019-07-19T01:17:55.009 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GXEA#> "
[2019-07-19T01:17:55.019 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <30> "
[2019-07-19T01:17:55.021 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:A?#> "
[2019-07-19T01:17:55.029 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <636> "
[2019-07-19T01:17:55.029 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[DEBUG] Align: max_stars: 6 current star: 3, align_stars 6 "
[2019-07-19T01:17:55.030 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GX02#> "
[2019-07-19T01:17:55.039 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <0> "
[2019-07-19T01:17:55.039 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GX03#> "
[2019-07-19T01:17:55.048 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <0> "
[2019-07-19T01:17:55.049 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:$QZ?#> "
[2019-07-19T01:17:55.058 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <I> "
[2019-07-19T01:17:55.064 CDT INFO ][     org.kde.kstars.ekos.align] - "Slew complete. Solving Alignment Point. . ."
[2019-07-19T01:17:55.065 CDT INFO ][     org.kde.kstars.ekos.align] - "Settling..."
[2019-07-19T01:17:55.065 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] <setObjectRA> "
[2019-07-19T01:17:55.066 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:Sr 00:00:00#> "
[2019-07-19T01:17:55.096 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:Sr 00:00:00#> successful. "
[2019-07-19T01:17:55.096 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] <setObjectDEC> "
[2019-07-19T01:17:55.096 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:Sd +55:51:28#> "
[2019-07-19T01:17:55.096 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:Sd +55:51:28#> successful. "
[2019-07-19T01:17:55.096 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] <Slew> "
[2019-07-19T01:17:55.096 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:MS#> "
[2019-07-19T01:17:55.102 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <0> "
[2019-07-19T01:17:55.103 CDT INFO ][           org.kde.kstars.indi] - LX200 OnStep :  "[INFO] Slewing to RA:  0:00:00 - DEC: 55:51:28 "
[2019-07-19T01:17:55.259 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GR#> "
[2019-07-19T01:17:55.275 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <18:37:31> "
[2019-07-19T01:17:55.276 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] VAL [18.6253] "
[2019-07-19T01:17:55.276 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GD#> "
[2019-07-19T01:17:55.291 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <+38*49:05> "
[2019-07-19T01:17:55.292 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] VAL [38.8181] "
[2019-07-19T01:17:55.292 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GU#> "
[2019-07-19T01:17:55.310 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <nptza/ET270> "
[2019-07-19T01:17:55.310 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:Gm#> "
[2019-07-19T01:17:55.317 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <E> "
[2019-07-19T01:17:55.317 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:%BD#> "
[2019-07-19T01:17:55.326 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <0> "
[2019-07-19T01:17:55.326 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:%BR#> "
[2019-07-19T01:17:55.335 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <0> "
[2019-07-19T01:17:55.335 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GX90#> "
[2019-07-19T01:17:55.348 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <1.00> "
[2019-07-19T01:17:55.348 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[DEBUG] Guide Rate: 1.000000 "
[2019-07-19T01:17:55.349 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GX95#> "
[2019-07-19T01:17:55.358 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <1> "
[2019-07-19T01:17:55.358 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GX96#> "
[2019-07-19T01:17:55.365 CDT DEBG ][     org.kde.kstars.ekos.mount] - Mount status changed from  3  to  2
Comment 1 Jasem Mutlaq 2019-07-22 15:22:45 UTC
Git commit a5b559fa45c8aeae22bb061cb5923cc07d0d45c5 by Jasem Mutlaq.
Committed on 22/07/2019 at 15:21.
Pushed by mutlaqja into branch 'master'.

refactor isSlewDirty and set it as false in cases of IDLE and ALERT states for EqNP.

Please test if this fixes the reported issue in the alignment module.
FIXED-IN:3.3.3

M  +26   -13   kstars/ekos/align/align.cpp
M  +1    -1    kstars/ekos/align/align.h

https://commits.kde.org/kstars/a5b559fa45c8aeae22bb061cb5923cc07d0d45c5
Comment 2 James Lancaster 2019-08-04 06:13:00 UTC
This did the same thing, and there's another report ( https://www.indilib.org/forum/development/1406-driver-onstep-lx200-like-for-indi.html?start=564 ) of someone else having it. 

When I had it, the same thing happened (unfortunately, I think I deleted that night's log) and the slew 'finished' before the command got issued. 

I tried with my own method, which was using an int, marked as 0, 1 (on slew) and 2 (when back to tracking) Which resulted in a similar thing. So my thought is that there needs to be a minimum timer. 

I'm experimenting with a single shot QTimer m_minSlewTimer at 5000ms (Yes, it's probably a bit long), and if it works, I'll provide a patch. (or let you know)
Comment 3 Jasem Mutlaq 2019-08-04 06:18:18 UTC
There is already a settle timer, so I don't think adding another timer is the right approach. There is a problem with the state transition.. so what is causing that? some race condition? driver issue perhaps?
Comment 4 James Lancaster 2019-08-04 15:44:39 UTC
The settle timer operates from when it thinks the end of a slew is and is up to 15 seconds long, whereas slews (especially meridian flips) might be minutes. 

I went back to the version in git, rebuilt kstars. Also commented out the one reference to EqNP.s being set to anything other than IPS_ALERT in lx200_OnStep (in the Sync, which is a modified copy from lx200telescope file, which sets that) 

So I reproduced it running wireshark to make sure there's no odd settings being made in INDI and sent to Kstars, and there don't appear to be. I have saved the wireshark log and attached what seem to be relevant packets below. (EQUATORIAL_EOD_COORD or EQUATORIAL_COORD are being looked for by Kstars, EQUATORIAL_COORD does not appear (not unexpectedly) at all) 

Timeline/Description

Start with slew in progress: EQUATORIAL_EOD_COORD" state="Busy" at 19:03 (Packet 1) (Note: As OnStep sometimes has an issue with not finishing, the behavior here is running into it's internal: Is it done timer? which is why no more RA/DEC changes)

Slew from prior sync is finished at :19:07, EQUATORIAL_EOD_COORD" state="Ok" (Packet 2)

Ekos Starts captue and solving is done at :19:26 and sends sync and CCD rotation values (At this point m_wasSlewStarted should be false with the Mount was synced message) (Packet 3)

INDI sends back changes, and log inforation and still shows EQUATORIAL_EOD_COORD" state="Ok" (Packet 4)

Ekos sends new coordinates (Packet 5) to slew to

INDI sends back current coordnates with no change in status (EQUATORIAL_EOD_COORD" state="Ok") (Packet 6) 

INDI sends back new target coordinates and state change EQUATORIAL_EOD_COORD" state="Busy" in (Packet 7) Acknowledging Packet 5, and beginning move. At this point m_wasSlewStarted should be changed to true. But as per getting the: "Slew complete. Solving Alignment Point. . ." message at :19:26 it seems to be true. Otherwise it should break. This also starts the Settling timer. 

Slew is continuning (Packet 8, 9) in :19:26 (Not included next packet is in :19:27) 


My guess is that something about getting packet 6 with an OK, means there's a breakdown, in some logic that I'm not seeing, and somehow m_wasSlewStarted is true when it shouldn't be, or the break isn't breaking to the right point? 
--------------------

Second test I modified it as such: 
 case ALIGN_SLEWING:
			    appendLogText(i18n("ALIGN_SLEWING (%1)", m_wasSlewStarted));
                        // If mount has not started slewing yet, then skip
                        if (m_wasSlewStarted == false) {
				appendLogText(i18n("m_wasSlewStarted false!"));
                            break;
			}
			appendLogText(i18n("m_wasSlewStarted true!"));
                        m_wasSlewStarted = false;



2019-08-04T10:35:00 Settling...
2019-08-04T10:35:00 Slew complete. Solving Alignment Point. . .
2019-08-04T10:35:00 m_wasSlewStarted true!
2019-08-04T10:35:00 ALIGN_SLEWING (1)
2019-08-04T10:35:00 Slewing to target coordinates: RA (03h 11m 55s) DEC ( 23° 51' 01").
2019-08-04T10:35:00 Mount is synced to solution coordinates. Astrometric solver is successful.
2019-08-04T10:35:00 Syncing to RA (02h 58m 48s) DEC ( 28° 53' 51")
2019-08-04T10:35:00 Solution coordinates: RA (02h 58m 48s) DEC ( 28° 53' 51") Telescope Coordinates: RA (02h 58m 49s) DEC ( 28° 54' 04")
2019-08-04T10:35:00 WCS information updated. Images captured from this point forward shall have valid WCS.


Hope that's helpful. Because Argh. 


===================================================

1st test
===================================================
Ekos window messages (Oldest on bottom)

2019-08-04T09:19:26 Settling...
2019-08-04T09:19:26 Slew complete. Solving Alignment Point. . .
2019-08-04T09:19:26 Slewing to target coordinates: RA (23h 54m 33s) DEC ( 52° 02' 30").
2019-08-04T09:19:26 Mount is synced to solution coordinates. Astrometric solver is successful.
2019-08-04T09:19:26 Syncing to RA (00h 15m 39s) DEC ( 38° 40' 48")
2019-08-04T09:19:26 Solution coordinates: RA (00h 15m 39s) DEC ( 38° 40' 48") Telescope Coordinates: RA (00h 15m 39s) DEC ( 38° 41' 05")
2019-08-04T09:19:26 Solver completed in 5 seconds.
2019-08-04T09:19:20 Starting solver...
2019-08-04T09:19:20 Image received.
2019-08-04T09:19:12 Capturing image...
2019-08-04T09:19:07 Settling...
2019-08-04T09:19:07 Slew complete. Solving Alignment Point. . .
2019-08-04T09:18:33 Slewing to target coordinates: RA (00h 15m 38s) DEC ( 38° 41' 04").




Any Wireshark packets on loopback with EQUATORIAL_EOD_COORD mentioned (Oldest first, --- indicates INDI > KStars/Ekos, ==TO indicates Kstars/Ekos > INDI, plus a number)
-----1
<setNumberVector device="LX200 OnStep" name="EQUATORIAL_EOD_COORD" state="Busy" timeout="60" timestamp="2019-08-04T14:19:03">
    <oneNumber name="RA">
0.26083333333333336146
    </oneNumber>
    <oneNumber name="DEC">
38.684722222222220012
    </oneNumber>
</setNumberVector>


-----2
<setSwitchVector device="LX200 OnStep" name="TELESCOPE_TRACK_STATE" state="Busy" timeout="0" timestamp="2019-08-04T14:19:07">
    <oneSwitch name="TRACK_ON">
On
    </oneSwitch>
    <oneSwitch name="TRACK_OFF">
Off
    </oneSwitch>
</setSwitchVector>
<setNumberVector device="LX200 OnStep" name="EQUATORIAL_EOD_COORD" state="Ok" timeout="60" timestamp="2019-08-04T14:19:07">
    <oneNumber name="RA">
0.26083333333333336146
    </oneNumber>
    <oneNumber name="DEC">
38.684722222222220012
    </oneNumber>
</setNumberVector>

====TO3
device='CCD Simulator'
  name='CCD_ROTATION'
>  <oneNumber
    name='CCD_ROTATION_VALUE'>
      89.9867
  </oneNumber>
</newNumberVector>
<newSwitchVector
  device='LX200 OnStep'
  name='ON_COORD_SET'>
  <oneSwitch
    name='SYNC'>
      On
  </oneSwitch>
</newSwitchVector>
<newNumberVector
  device='LX200 OnStep'
  name='EQUATORIAL_EOD_COORD'
>  <oneNumber
    name='RA'>
      0.260904
  </oneNumber>
  <oneNumber
    name='DEC'>
      38.6803
  </oneNumber>
</newNumberVector>

-----4
<setNumberVector device="CCD Simulator" name="CCD_ROTATION" state="Ok" timeout="60" timestamp="2019-08-04T14:19:26">
    <oneNumber name="CCD_ROTATION_VALUE">
89.986699999999999022
    </oneNumber>
</setNumberVector>
<message device="CCD Simulator" timestamp="2019-08-04T14:19:26" message="[INFO] CCD FOV rotation updated to 89.9867 degrees."/>
<message device="LX200 OnStep" timestamp="2019-08-04T14:19:26" message="[SCOPE] &lt;setObjectRA&gt;"/>
<message device="LX200 OnStep" timestamp="2019-08-04T14:19:26" message="[SCOPE] CMD &lt;:Sr 00:15:39#&gt;"/>
<message device="LX200 OnStep" timestamp="2019-08-04T14:19:26" message="[SCOPE] CMD &lt;:Sr 00:15:39#&gt; successful."/>
<message device="LX200 OnStep" timestamp="2019-08-04T14:19:26" message="[SCOPE] &lt;setObjectDEC&gt;"/>
<message device="LX200 OnStep" timestamp="2019-08-04T14:19:26" message="[SCOPE] CMD &lt;:Sd +38:40:49#&gt;"/>
<message device="LX200 OnStep" timestamp="2019-08-04T14:19:26" message="[SCOPE] CMD &lt;:Sd +38:40:49#&gt; successful."/>
<message device="LX200 OnStep" timestamp="2019-08-04T14:19:26" message="[DEBUG] CMD &lt;:CM#&gt;"/>
<message device="LX200 OnStep" timestamp="2019-08-04T14:19:26" message="[SCOPE] CMD &lt;:CM#&gt;"/>
<message device="LX200 OnStep" timestamp="2019-08-04T14:19:26" message="[SCOPE] RES &lt;N/A&gt;"/>
<message device="LX200 OnStep" timestamp="2019-08-04T14:19:26" message="[DEBUG] RES &lt;N/A&gt;"/>
<message device="LX200 OnStep" timestamp="2019-08-04T14:19:26" message="[INFO] OnStep: Synchronization successful."/>
<setNumberVector device="LX200 OnStep" name="EQUATORIAL_EOD_COORD" state="Ok" timeout="60" timestamp="2019-08-04T14:19:26">
    <oneNumber name="RA">
0.26090400000000002478
    </oneNumber>
    <oneNumber name="DEC">
38.680300000000002569
    </oneNumber>
</setNumberVector>
<setNumberVector device="LX200 OnStep" name="EQUATORIAL_EOD_COORD" state="Ok" timeout="60" timestamp="2019-08-04T14:19:26">
    <oneNumber name="RA">
0.26090400000000002478
    </oneNumber>
    <oneNumber name="DEC">
38.680300000000002569
    </oneNumber>
</setNumberVector>
<message device="LX200 OnStep" timestamp="2019-08-04T14:19:26" message="[SCOPE] CMD &lt;:GR#&gt;"/>


======TO5

device='LX200 OnStep'
  name='ON_COORD_SET'>
  <oneSwitch
    name='TRACK'>
      On
  </oneSwitch>
</newSwitchVector>
<newNumberVector
  device='LX200 OnStep'
  name='EQUATORIAL_EOD_COORD'
>  <oneNumber
    name='RA'>
      23.9092
  </oneNumber>
  <oneNumber
    name='DEC'>
      52.0419
  </oneNumber>
</newNumberVector>
-----6
<setNumberVector device="LX200 OnStep" name="EQUATORIAL_EOD_COORD" state="Ok" timeout="60" timestamp="2019-08-04T14:19:26">
    <oneNumber name="RA">
0.26083333333333336146
    </oneNumber>
    <oneNumber name="DEC">
38.680277777777774872
    </oneNumber>
</setNumberVector>
-----7
<setNumberVector device="LX200 OnStep" name="TARGET_EOD_COORD" state="Idle" timeout="60" timestamp="2019-08-04T14:19:26">
    <oneNumber name="RA">
23.909199999999998454
    </oneNumber>
    <oneNumber name="DEC">
52.041899999999998272
    </oneNumber>
</setNumberVector>
<setNumberVector device="LX200 OnStep" name="EQUATORIAL_EOD_COORD" state="Busy" timeout="60" timestamp="2019-08-04T14:19:26">
    <oneNumber name="RA">
0.26083333333333336146
    </oneNumber>
    <oneNumber name="DEC">
38.680277777777774872
    </oneNumber>
</setNumberVector>

-----8
<setNumberVector device="LX200 OnStep" name="EQUATORIAL_EOD_COORD" state="Busy" timeout="60" timestamp="2019-08-04T14:19:26">
    <oneNumber name="RA">
0.26055555555555554026
    </oneNumber>
    <oneNumber name="DEC">
38.686388888888885162
    </oneNumber>
</setNumberVector>
-----9
<setNumberVector device="LX200 OnStep" name="EQUATORIAL_EOD_COORD" state="Busy" timeout="60" timestamp="2019-08-04T14:19:26">
    <oneNumber name="RA">
0.25861111111111112493
    </oneNumber>
    <oneNumber name="DEC">
38.714166666666670835
    </oneNumber>
</setNumberVector>
Comment 5 James Lancaster 2019-08-04 21:03:39 UTC
Adding a couple more, it seems much more rare, but it still seems to happen, I added more print statements, and ended up with this, didn't get a wireshark capture, but this seems just odd. 


Chronoloical order is oldest on bottom (like in archaeology :) ) 
Ekos status output box:
----
2019-08-04T15:38:46 IPS_BUSY
2019-08-04T15:38:46 IPS_BUSY
2019-08-04T15:38:46 IPS_BUSY
2019-08-04T15:38:45 IPS_BUSY
2019-08-04T15:38:45 IPS_BUSY
2019-08-04T15:38:45 IPS_BUSY
2019-08-04T15:38:45 IPS_BUSY
2019-08-04T15:38:44 IPS_BUSY
2019-08-04T15:38:44 Settling...
2019-08-04T15:38:44 Slew complete. Solving Alignment Point. . .
2019-08-04T15:38:44 m_wasSlewStarted true!
2019-08-04T15:38:44 ALIGN_SLEWING (1)
2019-08-04T15:38:44 IPS_BUSY
2019-08-04T15:38:44 end of IPS_OK
2019-08-04T15:38:44 Slewing to target coordinates: RA (13h 06m 39s) DEC ( 53° 08' 33").
2019-08-04T15:38:44 Mount is synced to solution coordinates. Astrometric solver is successful.
2019-08-04T15:38:44 Syncing to RA (12h 56m 51s) DEC ( 39° 45' 57")
2019-08-04T15:38:44 Solution coordinates: RA (12h 56m 51s) DEC ( 39° 45' 57") Telescope Coordinates: RA (12h 56m 54s) DEC ( 39° 45' 41")
2019-08-04T15:38:44 Solver completed in 5 seconds.
2019-08-04T15:38:39 Starting solver...
2019-08-04T15:38:39 Image received.
2019-08-04T15:38:31 Capturing image...
2019-08-04T15:38:26 Settling...
2019-08-04T15:38:26 Slew complete. Solving Alignment Point. . .
2019-08-04T15:38:26 m_wasSlewStarted true!
2019-08-04T15:38:26 ALIGN_SLEWING (1)
2019-08-04T15:38:22 IPS_BUSY

==========================
(:GU# is status, // [n]ot tracking // [N]o goto (Breakdown for most, NewRaDec is called later which sets it.)
           
            IUSaveText(&OnstepStat[0],OSStat);
            if (strstr(OSStat,"n") && strstr(OSStat,"N"))
            {
                IUSaveText(&OnstepStat[1], "Idle");
                TrackState = SCOPE_IDLE;
            }
            if (strstr(OSStat, "n") && !strstr(OSStat, "N"))
            {
                IUSaveText(&OnstepStat[1], "Slewing");
                TrackState = SCOPE_SLEWING;
            }
            if (strstr(OSStat, "N") && !strstr(OSStat, "n"))
            {
                IUSaveText(&OnstepStat[1], "Tracking");
                TrackState = SCOPE_TRACKING;
            }
            
)

EqNP.s does get set to IPS_BUSY in ::Sync (lx200) 
However, the very next line is: 
    EqNP.s     = IPS_BUSY;

    LOGF_INFO("Slewing to RA: %s - DEC: %s", RAStr, DecStr);
Which doesn't occur until 2019-08-04T15:38:44.802 after we already see an IPS_BUSY. Which I have no idea where it's from. 

Of note: 
[2019-08-04T15:38:44.662 CDT INFO ][     org.kde.kstars.ekos.align] - "end of IPS_OK"
[2019-08-04T15:38:44.666 CDT INFO ][     org.kde.kstars.ekos.align] - "IPS_BUSY"














[2019-08-04T15:38:44.148 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GU#> "
[2019-08-04T15:38:44.166 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <Nprsza/EW150> "
[2019-08-04T15:38:44.166 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:Gm#> "
[2019-08-04T15:38:44.173 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <W> "
[2019-08-04T15:38:44.173 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:%BD#> "
[2019-08-04T15:38:44.182 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <17> "
[2019-08-04T15:38:44.182 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:%BR#> "
[2019-08-04T15:38:44.190 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <0> "
[2019-08-04T15:38:44.190 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GX90#> "
[2019-08-04T15:38:44.202 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <0.50> "
[2019-08-04T15:38:44.202 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[DEBUG] Guide Rate: 0.500000 "
[2019-08-04T15:38:44.202 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GX95#> "
[2019-08-04T15:38:44.210 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <1> "
[2019-08-04T15:38:44.210 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GX96#> "
[2019-08-04T15:38:44.219 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <B> "
[2019-08-04T15:38:44.219 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GXE9#> "
[2019-08-04T15:38:44.229 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <30> "
[2019-08-04T15:38:44.229 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GXEA#> "
[2019-08-04T15:38:44.239 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <30> "
[2019-08-04T15:38:44.239 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:A?#> "
[2019-08-04T15:38:44.248 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <600> "
[2019-08-04T15:38:44.248 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[DEBUG] Align: max_stars: 6 current star: 0, align_stars 0 "
[2019-08-04T15:38:44.248 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GX02#> "
[2019-08-04T15:38:44.256 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <0> "
[2019-08-04T15:38:44.256 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GX03#> "
[2019-08-04T15:38:44.265 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <0> "
[2019-08-04T15:38:44.365 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GR#> "
[2019-08-04T15:38:44.381 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <12:56:54> "
[2019-08-04T15:38:44.381 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] VAL [12.9483] "
[2019-08-04T15:38:44.381 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GD#> "
[2019-08-04T15:38:44.391 CDT INFO ][     org.kde.kstars.ekos.align] - "Solver completed in 5 seconds."
[2019-08-04T15:38:44.407 CDT INFO ][     org.kde.kstars.ekos.align] - "Solution coordinates: RA (12h 56m 51s) DEC ( 39° 45' 57\") Telescope Coordinates: RA (12h 56m 54s) DEC ( 39° 45' 41\")"
[2019-08-04T15:38:44.412 CDT DEBG ][           org.kde.kstars.indi] - ISD:Telescope: Syncing...
[2019-08-04T15:38:44.418 CDT DEBG ][           org.kde.kstars.indi] - ISD:Telescope sending coords RA: "12h 56m 51s" ( 12.9478 ) DE: " 39° 45' 57\"" ( 39.7661 )
[2019-08-04T15:38:44.418 CDT INFO ][     org.kde.kstars.ekos.align] - "Syncing to RA (12h 56m 51s) DEC ( 39° 45' 57\")"
[2019-08-04T15:38:44.424 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <+39*45:41> "
[2019-08-04T15:38:44.424 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] VAL [39.7614] "
[2019-08-04T15:38:44.424 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GU#> "
[2019-08-04T15:38:44.424 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <Nprsza/EW150> "
[2019-08-04T15:38:44.424 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:Gm#> "
[2019-08-04T15:38:44.425 CDT INFO ][           org.kde.kstars.indi] - CCD Simulator :  "[INFO] CCD FOV rotation updated to 89.9964 degrees. "
[2019-08-04T15:38:44.425 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <W> "
[2019-08-04T15:38:44.425 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:%BD#> "
[2019-08-04T15:38:44.465 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <17> "
[2019-08-04T15:38:44.465 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:%BR#> "
[2019-08-04T15:38:44.465 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <0> "
[2019-08-04T15:38:44.465 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GX90#> "
[2019-08-04T15:38:44.465 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <0.50> "
[2019-08-04T15:38:44.465 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[DEBUG] Guide Rate: 0.500000 "
[2019-08-04T15:38:44.465 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GX95#> "
[2019-08-04T15:38:44.466 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <1> "
[2019-08-04T15:38:44.466 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GX96#> "
[2019-08-04T15:38:44.467 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <B> "
[2019-08-04T15:38:44.467 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GXE9#> "
[2019-08-04T15:38:44.477 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <30> "
[2019-08-04T15:38:44.477 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GXEA#> "
[2019-08-04T15:38:44.487 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <30> "
[2019-08-04T15:38:44.487 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:A?#> "
[2019-08-04T15:38:44.496 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <600> "
[2019-08-04T15:38:44.496 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[DEBUG] Align: max_stars: 6 current star: 0, align_stars 0 "
[2019-08-04T15:38:44.496 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GX02#> "
[2019-08-04T15:38:44.505 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <0> "
[2019-08-04T15:38:44.505 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GX03#> "
[2019-08-04T15:38:44.514 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <0> "
[2019-08-04T15:38:44.514 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] <setObjectRA> "
[2019-08-04T15:38:44.514 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:Sr 12:56:52#> "
[2019-08-04T15:38:44.529 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:Sr 12:56:52#> successful. "
[2019-08-04T15:38:44.529 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] <setObjectDEC> "
[2019-08-04T15:38:44.529 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:Sd +39:45:58#> "
[2019-08-04T15:38:44.649 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:Sd +39:45:58#> successful. "
[2019-08-04T15:38:44.650 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[DEBUG] CMD <:CM#> "
[2019-08-04T15:38:44.650 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:CM#> "
[2019-08-04T15:38:44.650 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <N/A> "
[2019-08-04T15:38:44.650 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[DEBUG] RES <N/A> "
[2019-08-04T15:38:44.650 CDT INFO ][           org.kde.kstars.indi] - LX200 OnStep :  "[INFO] OnStep: Synchronization successful. "
[2019-08-04T15:38:44.650 CDT INFO ][     org.kde.kstars.ekos.align] - "Mount is synced to solution coordinates. Astrometric solver is successful."
[2019-08-04T15:38:44.655 CDT DEBG ][           org.kde.kstars.indi] - ISD:Telescope:  TRACK
[2019-08-04T15:38:44.659 CDT DEBG ][           org.kde.kstars.indi] - ISD:Telescope sending coords RA: "13h 06m 39s" ( 13.1111 ) DE: " 53° 08' 33\"" ( 53.1427 )
[2019-08-04T15:38:44.659 CDT INFO ][     org.kde.kstars.ekos.align] - "Slewing to target coordinates: RA (13h 06m 39s) DEC ( 53° 08' 33\")."
[2019-08-04T15:38:44.662 CDT INFO ][     org.kde.kstars.ekos.align] - "end of IPS_OK"
[2019-08-04T15:38:44.666 CDT INFO ][     org.kde.kstars.ekos.align] - "IPS_BUSY"
[2019-08-04T15:38:44.669 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GR#> "
[2019-08-04T15:38:44.669 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <12:56:52> "
[2019-08-04T15:38:44.669 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] VAL [12.9478] "
[2019-08-04T15:38:44.669 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GD#> "
[2019-08-04T15:38:44.669 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <+39*45:58> "
[2019-08-04T15:38:44.669 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] VAL [39.7661] "
[2019-08-04T15:38:44.669 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GU#> "
[2019-08-04T15:38:44.679 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <Nprsza/EW150> "
[2019-08-04T15:38:44.679 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:Gm#> "
[2019-08-04T15:38:44.705 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <W> "
[2019-08-04T15:38:44.705 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:%BD#> "
[2019-08-04T15:38:44.705 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <17> "
[2019-08-04T15:38:44.705 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:%BR#> "
[2019-08-04T15:38:44.705 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <0> "
[2019-08-04T15:38:44.705 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GX90#> "
[2019-08-04T15:38:44.706 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <0.50> "
[2019-08-04T15:38:44.706 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[DEBUG] Guide Rate: 0.500000 "
[2019-08-04T15:38:44.706 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GX95#> "
[2019-08-04T15:38:44.707 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <1> "
[2019-08-04T15:38:44.707 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GX96#> "
[2019-08-04T15:38:44.715 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <B> "
[2019-08-04T15:38:44.716 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GXE9#> "
[2019-08-04T15:38:44.725 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <30> "
[2019-08-04T15:38:44.725 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GXEA#> "
[2019-08-04T15:38:44.735 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <30> "
[2019-08-04T15:38:44.735 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:A?#> "
[2019-08-04T15:38:44.744 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <600> "
[2019-08-04T15:38:44.744 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[DEBUG] Align: max_stars: 6 current star: 0, align_stars 0 "
[2019-08-04T15:38:44.744 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GX02#> "
[2019-08-04T15:38:44.753 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <0> "
[2019-08-04T15:38:44.753 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GX03#> "
[2019-08-04T15:38:44.761 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <0> "
[2019-08-04T15:38:44.765 CDT INFO ][     org.kde.kstars.ekos.align] - "ALIGN_SLEWING (1)"
[2019-08-04T15:38:44.769 CDT INFO ][     org.kde.kstars.ekos.align] - "m_wasSlewStarted true!"
[2019-08-04T15:38:44.772 CDT INFO ][     org.kde.kstars.ekos.align] - "Slew complete. Solving Alignment Point. . ."
[2019-08-04T15:38:44.775 CDT INFO ][     org.kde.kstars.ekos.align] - "Settling..."
[2019-08-04T15:38:44.778 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] <setObjectRA> "
[2019-08-04T15:38:44.779 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:Sr 13:06:40#> "
[2019-08-04T15:38:44.779 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:Sr 13:06:40#> successful. "
[2019-08-04T15:38:44.779 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] <setObjectDEC> "
[2019-08-04T15:38:44.779 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:Sd +53:08:34#> "
[2019-08-04T15:38:44.793 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:Sd +53:08:34#> successful. "
[2019-08-04T15:38:44.793 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] <Slew> "
[2019-08-04T15:38:44.793 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:MS#> "
[2019-08-04T15:38:44.801 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <0> "
[2019-08-04T15:38:44.802 CDT INFO ][           org.kde.kstars.indi] - LX200 OnStep :  "[INFO] Slewing to RA: 13:06:40 - DEC: 53:08:34 "
[2019-08-04T15:38:44.802 CDT INFO ][     org.kde.kstars.ekos.align] - "IPS_BUSY"
[2019-08-04T15:38:44.862 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GR#> "
[2019-08-04T15:38:44.877 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <12:56:53> "
[2019-08-04T15:38:44.877 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] VAL [12.9481] "
[2019-08-04T15:38:44.877 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GD#> "
[2019-08-04T15:38:44.892 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <+39*45:59> "
[2019-08-04T15:38:44.893 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] VAL [39.7664] "
[2019-08-04T15:38:44.893 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GU#> "
[2019-08-04T15:38:44.911 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <nprsza/EW150> "
[2019-08-04T15:38:44.911 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:Gm#> "
[2019-08-04T15:38:44.917 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <W> "
[2019-08-04T15:38:44.917 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:%BD#> "
[2019-08-04T15:38:44.926 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <17> "
[2019-08-04T15:38:44.926 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:%BR#> "
[2019-08-04T15:38:44.934 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <0> "
[2019-08-04T15:38:44.934 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GX90#> "
[2019-08-04T15:38:44.939 CDT DEBG ][     org.kde.kstars.ekos.mount] - Mount status changed from  3  to  2
[2019-08-04T15:38:44.946 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <0.50> "
[2019-08-04T15:38:44.946 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[DEBUG] Guide Rate: 0.500000 "
[2019-08-04T15:38:44.946 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GX95#> "
[2019-08-04T15:38:44.955 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <1> "
[2019-08-04T15:38:44.955 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GX96#> "
[2019-08-04T15:38:44.964 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <B> "
[2019-08-04T15:38:44.964 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GXE9#> "
[2019-08-04T15:38:44.974 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <30> "
[2019-08-04T15:38:44.974 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GXEA#> "
[2019-08-04T15:38:44.983 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <30> "
[2019-08-04T15:38:44.984 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:A?#> "
[2019-08-04T15:38:44.992 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <600> "
[2019-08-04T15:38:44.992 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[DEBUG] Align: max_stars: 6 current star: 0, align_stars 0 "
[2019-08-04T15:38:44.992 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GX02#> "
[2019-08-04T15:38:45.001 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <0> "
[2019-08-04T15:38:45.001 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GX03#> "
[2019-08-04T15:38:45.010 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <0> "
[2019-08-04T15:38:45.010 CDT INFO ][     org.kde.kstars.ekos.align] - "IPS_BUSY"
[2019-08-04T15:38:45.110 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GR#> "
[2019-08-04T15:38:45.126 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <12:57:00> "
[2019-08-04T15:38:45.126 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] VAL [12.95] "
[2019-08-04T15:38:45.126 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GD#> "
[2019-08-04T15:38:45.141 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <+39*47:32> "
[2019-08-04T15:38:45.141 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] VAL [39.7922] "
[2019-08-04T15:38:45.141 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GU#> "
[2019-08-04T15:38:45.159 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <nprsza/EW150> "
[2019-08-04T15:38:45.159 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:Gm#> "
[2019-08-04T15:38:45.166 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <W> "
[2019-08-04T15:38:45.166 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:%BD#> "
[2019-08-04T15:38:45.175 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <17> "
[2019-08-04T15:38:45.175 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:%BR#> "
[2019-08-04T15:38:45.182 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <0> "
[2019-08-04T15:38:45.182 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GX90#> "
[2019-08-04T15:38:45.194 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <0.50> "
[2019-08-04T15:38:45.194 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[DEBUG] Guide Rate: 0.500000 "
[2019-08-04T15:38:45.194 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GX95#> "
[2019-08-04T15:38:45.203 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <1> "
[2019-08-04T15:38:45.203 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GX96#> "
[2019-08-04T15:38:45.212 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <B> "
[2019-08-04T15:38:45.212 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GXE9#> "
[2019-08-04T15:38:45.222 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <30> "
[2019-08-04T15:38:45.222 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GXEA#> "
[2019-08-04T15:38:45.231 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <30> "
[2019-08-04T15:38:45.232 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:A?#> "
[2019-08-04T15:38:45.240 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <600> "
[2019-08-04T15:38:45.240 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[DEBUG] Align: max_stars: 6 current star: 0, align_stars 0 "
[2019-08-04T15:38:45.240 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GX02#> "
[2019-08-04T15:38:45.249 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <0> "
[2019-08-04T15:38:45.249 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] CMD <:GX03#> "
[2019-08-04T15:38:45.258 CDT DEBG ][           org.kde.kstars.indi] - LX200 OnStep : "[SCOPE] RES <0> "
[2019-08-04T15:38:45.258 CDT INFO ][     org.kde.kstars.ekos.align] - "IPS_BUSY"



-------- Changes to align.cpp, including those in prior post (just for reference for where the messages are, I think it's fairly obvious, but)
                }
            }
            appendLogText(i18n("end of IPS_OK"));
            break;
	    
		
            // Busy --> Mount Slewing or Moving (NSWE buttons)
            case IPS_BUSY:
            {
		appendLogText(i18n("IPS_BUSY"));
                m_wasSlewStarted = true;
            }

-------------
Comment 6 Jasem Mutlaq 2019-08-05 03:06:09 UTC
Thanks for the detailed report! This should win the trophy for the most _detailed_ bug report yet! However, the attachments are missing and I need to put the two logs (wireshark + kstars) next to each other to get a sense of this. Can you please try to zip them and attach them?
Comment 7 James Lancaster 2019-08-06 21:53:33 UTC
Realized something just before posting this, make sure you read to at least the !!!! note 

I apparently didn't save the wireshark log, but I was able to reproduce it. Attaching it with large packets removed, and kstars log. 

(Haven't changed build since then.) 

What's confusing is this sequence (time order: correct (reversed from below, which is from kstars)) Which should mean that it gets an IPS_OK, which sets the syncs, and tells it to move, then gets an EqNP.s == IPS_BUSY, and then after that gets an IPS_OK which is wrapped around the ALIGN_SLEWING: 
2019-08-06T15:26:12 end of IPS_OK 
2019-08-06T15:26:12 IPS_BUSY
2019-08-06T15:26:12 ALIGN_SLEWING (1) 

When I look in wireshark filter: (tcp and frame contains "EQUATORIAL_EOD_COORD\" state") (and colorizing based on state="Ok or "Busy, there are no other packets with state in them): 
I see what would be IPS_OK at packet #/time 41554/162 (end of last capture), 47728/180.179602120, 47779/180.331602725 Note that the values for at least RA are slightly different, 8.867380000000000706 v 8.867499999999997158 and 67.049000000000006594 v 67.048888888888888232 almost certainly due to the sync/rounding/CCD simulation which disagreed by 4 arcsec.) 

I see IPS_BUSY at 47795/180.366809423 and on, and from 40566/158.52 and before, as it should be. 


Relevant times (time order reversed, from kstars box): 
2019-08-06T15:26:12 IPS_BUSY
2019-08-06T15:26:12 IPS_BUSY
2019-08-06T15:26:12 Settling...
2019-08-06T15:26:12 Slew complete. Solving Alignment Point. . .
2019-08-06T15:26:12 m_wasSlewStarted true!
2019-08-06T15:26:12 ALIGN_SLEWING (1)
2019-08-06T15:26:12 IPS_BUSY
2019-08-06T15:26:12 end of IPS_OK
2019-08-06T15:26:12 Slewing to target coordinates: RA (10h 56m 02s) DEC ( 67° 01' 13").
2019-08-06T15:26:12 Mount is synced to solution coordinates. Astrometric solver is successful.
2019-08-06T15:26:12 Syncing to RA (08h 52m 02s) DEC ( 67° 02' 56")
2019-08-06T15:26:12 Solution coordinates: RA (08h 52m 02s) DEC ( 67° 02' 56") Telescope Coordinates: RA (08h 52m 06s) DEC ( 67° 02' 52")
2019-08-06T15:26:12 Solver completed in 5 seconds.
2019-08-06T15:26:07 Starting solver...
2019-08-06T15:26:07 Image received.
2019-08-06T15:25:59 Capturing image...
2019-08-06T15:25:54 Settling...
2019-08-06T15:25:54 Slew complete. Solving Alignment Point. . .
2019-08-06T15:25:54 m_wasSlewStarted true!
2019-08-06T15:25:54 ALIGN_SLEWING (1)
2019-08-06T15:25:50 IPS_BUSY
2019-08-06T15:25:50 IPS_BUSY


------ Full Kstars align -----

!!!!!!!
(Note that I messed up on the first, by not setting the tracking to on, so OnStep didn't respond, though that it did get to ............OH, interesting, packet 8928/35.414 has the Error on Slew (state="Alert), but I noticed that there's this: 2019-08-06T15:23:47 IPS_BUSY which makes no sense at all, and it's not in the packet log) So something is messed up with the switch (nvp->s), because until 16308/64.444 (Idle) 16501/70.1174 (Ok) and finally 16515/70.15 (Busy) the status is that one IPS_ALERT and IPS_IDLE the whole time. 


2019-08-06T15:26:42 end of IPS_OK
2019-08-06T15:26:41 IPS_BUSY
2019-08-06T15:26:41 IPS_BUSY
2019-08-06T15:26:41 IPS_BUSY
2019-08-06T15:26:40 IPS_BUSY
2019-08-06T15:26:40 IPS_BUSY
2019-08-06T15:26:40 IPS_BUSY
2019-08-06T15:26:40 IPS_BUSY
2019-08-06T15:26:39 IPS_BUSY
2019-08-06T15:26:39 IPS_BUSY
2019-08-06T15:26:39 IPS_BUSY
2019-08-06T15:26:39 IPS_BUSY
2019-08-06T15:26:38 IPS_BUSY
2019-08-06T15:26:38 IPS_BUSY
2019-08-06T15:26:38 IPS_BUSY
2019-08-06T15:26:38 IPS_BUSY
2019-08-06T15:26:37 IPS_BUSY
2019-08-06T15:26:37 IPS_BUSY
2019-08-06T15:26:37 IPS_BUSY
2019-08-06T15:26:37 IPS_BUSY
2019-08-06T15:26:36 IPS_BUSY
2019-08-06T15:26:36 IPS_BUSY
2019-08-06T15:26:36 IPS_BUSY
2019-08-06T15:26:36 IPS_BUSY
2019-08-06T15:26:35 IPS_BUSY
2019-08-06T15:26:35 IPS_BUSY
2019-08-06T15:26:35 IPS_BUSY
2019-08-06T15:26:35 IPS_BUSY
2019-08-06T15:26:34 IPS_BUSY
2019-08-06T15:26:34 IPS_BUSY
2019-08-06T15:26:34 IPS_BUSY
2019-08-06T15:26:33 IPS_BUSY
2019-08-06T15:26:33 IPS_BUSY
2019-08-06T15:26:33 IPS_BUSY
2019-08-06T15:26:33 IPS_BUSY
2019-08-06T15:26:32 IPS_BUSY
2019-08-06T15:26:32 IPS_BUSY
2019-08-06T15:26:32 IPS_BUSY
2019-08-06T15:26:32 IPS_BUSY
2019-08-06T15:26:31 IPS_BUSY
2019-08-06T15:26:31 IPS_BUSY
2019-08-06T15:26:31 IPS_BUSY
2019-08-06T15:26:31 Solver aborted after 6 seconds
2019-08-06T15:26:31 The Mount Model Tool is Reset.
2019-08-06T15:26:31 IPS_BUSY
2019-08-06T15:26:30 IPS_BUSY
2019-08-06T15:26:30 IPS_BUSY
2019-08-06T15:26:30 IPS_BUSY
2019-08-06T15:26:30 IPS_BUSY
2019-08-06T15:26:29 IPS_BUSY
2019-08-06T15:26:29 IPS_BUSY
2019-08-06T15:26:29 IPS_BUSY
2019-08-06T15:26:29 IPS_BUSY
2019-08-06T15:26:28 IPS_BUSY
2019-08-06T15:26:28 IPS_BUSY
2019-08-06T15:26:28 Solver aborted after 3 seconds
2019-08-06T15:26:28 The Mount Model Tool is Reset.
2019-08-06T15:26:28 IPS_BUSY
2019-08-06T15:26:28 IPS_BUSY
2019-08-06T15:26:27 IPS_BUSY
2019-08-06T15:26:27 IPS_BUSY
2019-08-06T15:26:27 IPS_BUSY
2019-08-06T15:26:27 IPS_BUSY
2019-08-06T15:26:26 IPS_BUSY
2019-08-06T15:26:26 IPS_BUSY
2019-08-06T15:26:26 IPS_BUSY
2019-08-06T15:26:26 IPS_BUSY
2019-08-06T15:26:25 IPS_BUSY
2019-08-06T15:26:25 IPS_BUSY
2019-08-06T15:26:25 Starting solver...
2019-08-06T15:26:25 Image received.
2019-08-06T15:26:25 IPS_BUSY
2019-08-06T15:26:25 IPS_BUSY
2019-08-06T15:26:24 IPS_BUSY
2019-08-06T15:26:24 IPS_BUSY
2019-08-06T15:26:24 IPS_BUSY
2019-08-06T15:26:24 IPS_BUSY
2019-08-06T15:26:23 IPS_BUSY
2019-08-06T15:26:23 IPS_BUSY
2019-08-06T15:26:23 IPS_BUSY
2019-08-06T15:26:23 IPS_BUSY
2019-08-06T15:26:22 IPS_BUSY
2019-08-06T15:26:22 IPS_BUSY
2019-08-06T15:26:22 IPS_BUSY
2019-08-06T15:26:22 IPS_BUSY
2019-08-06T15:26:21 IPS_BUSY
2019-08-06T15:26:21 IPS_BUSY
2019-08-06T15:26:21 IPS_BUSY
2019-08-06T15:26:21 IPS_BUSY
2019-08-06T15:26:20 IPS_BUSY
2019-08-06T15:26:20 IPS_BUSY
2019-08-06T15:26:20 IPS_BUSY
2019-08-06T15:26:20 IPS_BUSY
2019-08-06T15:26:19 IPS_BUSY
2019-08-06T15:26:19 IPS_BUSY
2019-08-06T15:26:19 IPS_BUSY
2019-08-06T15:26:19 IPS_BUSY
2019-08-06T15:26:18 IPS_BUSY
2019-08-06T15:26:18 IPS_BUSY
2019-08-06T15:26:18 IPS_BUSY
2019-08-06T15:26:18 IPS_BUSY
2019-08-06T15:26:17 IPS_BUSY
2019-08-06T15:26:17 Capturing image...
2019-08-06T15:26:17 IPS_BUSY
2019-08-06T15:26:17 Solver aborted after 10 seconds
2019-08-06T15:26:17 The Mount Model Tool is Reset.
2019-08-06T15:26:17 IPS_BUSY
2019-08-06T15:26:17 IPS_BUSY
2019-08-06T15:26:16 IPS_BUSY
2019-08-06T15:26:16 IPS_BUSY
2019-08-06T15:26:16 IPS_BUSY
2019-08-06T15:26:16 IPS_BUSY
2019-08-06T15:26:15 IPS_BUSY
2019-08-06T15:26:15 IPS_BUSY
2019-08-06T15:26:15 IPS_BUSY
2019-08-06T15:26:15 IPS_BUSY
2019-08-06T15:26:14 IPS_BUSY
2019-08-06T15:26:14 IPS_BUSY
2019-08-06T15:26:14 IPS_BUSY
2019-08-06T15:26:14 IPS_BUSY
2019-08-06T15:26:13 IPS_BUSY
2019-08-06T15:26:13 IPS_BUSY
2019-08-06T15:26:13 IPS_BUSY
2019-08-06T15:26:13 IPS_BUSY
2019-08-06T15:26:12 IPS_BUSY
2019-08-06T15:26:12 IPS_BUSY
2019-08-06T15:26:12 Settling...
2019-08-06T15:26:12 Slew complete. Solving Alignment Point. . .
2019-08-06T15:26:12 m_wasSlewStarted true!
2019-08-06T15:26:12 ALIGN_SLEWING (1)
2019-08-06T15:26:12 IPS_BUSY
2019-08-06T15:26:12 end of IPS_OK
2019-08-06T15:26:12 Slewing to target coordinates: RA (10h 56m 02s) DEC ( 67° 01' 13").
2019-08-06T15:26:12 Mount is synced to solution coordinates. Astrometric solver is successful.
2019-08-06T15:26:12 Syncing to RA (08h 52m 02s) DEC ( 67° 02' 56")
2019-08-06T15:26:12 Solution coordinates: RA (08h 52m 02s) DEC ( 67° 02' 56") Telescope Coordinates: RA (08h 52m 06s) DEC ( 67° 02' 52")
2019-08-06T15:26:12 Solver completed in 5 seconds.
2019-08-06T15:26:07 Starting solver...
2019-08-06T15:26:07 Image received.
2019-08-06T15:25:59 Capturing image...
2019-08-06T15:25:54 Settling...
2019-08-06T15:25:54 Slew complete. Solving Alignment Point. . .
2019-08-06T15:25:54 m_wasSlewStarted true!
2019-08-06T15:25:54 ALIGN_SLEWING (1)
2019-08-06T15:25:50 IPS_BUSY
2019-08-06T15:25:50 IPS_BUSY
2019-08-06T15:25:50 IPS_BUSY
2019-08-06T15:25:50 IPS_BUSY
2019-08-06T15:25:49 IPS_BUSY
2019-08-06T15:25:49 IPS_BUSY
2019-08-06T15:25:49 IPS_BUSY
2019-08-06T15:25:49 IPS_BUSY
2019-08-06T15:25:48 IPS_BUSY
2019-08-06T15:25:48 IPS_BUSY
2019-08-06T15:25:48 IPS_BUSY
2019-08-06T15:25:48 IPS_BUSY
2019-08-06T15:25:47 IPS_BUSY
2019-08-06T15:25:47 IPS_BUSY
2019-08-06T15:25:47 IPS_BUSY
2019-08-06T15:25:47 IPS_BUSY
2019-08-06T15:25:46 IPS_BUSY
2019-08-06T15:25:46 IPS_BUSY
2019-08-06T15:25:46 IPS_BUSY
2019-08-06T15:25:46 IPS_BUSY
2019-08-06T15:25:45 IPS_BUSY
2019-08-06T15:25:45 IPS_BUSY
2019-08-06T15:25:45 IPS_BUSY
2019-08-06T15:25:45 IPS_BUSY
2019-08-06T15:25:44 IPS_BUSY
2019-08-06T15:25:44 IPS_BUSY
2019-08-06T15:25:44 IPS_BUSY
2019-08-06T15:25:44 IPS_BUSY
2019-08-06T15:25:43 IPS_BUSY
2019-08-06T15:25:43 IPS_BUSY
2019-08-06T15:25:43 IPS_BUSY
2019-08-06T15:25:43 IPS_BUSY
2019-08-06T15:25:42 IPS_BUSY
2019-08-06T15:25:42 IPS_BUSY
2019-08-06T15:25:42 IPS_BUSY
2019-08-06T15:25:42 IPS_BUSY
2019-08-06T15:25:41 IPS_BUSY
2019-08-06T15:25:41 IPS_BUSY
2019-08-06T15:25:41 IPS_BUSY
2019-08-06T15:25:41 IPS_BUSY
2019-08-06T15:25:40 IPS_BUSY
2019-08-06T15:25:40 IPS_BUSY
2019-08-06T15:25:40 IPS_BUSY
2019-08-06T15:25:40 IPS_BUSY
2019-08-06T15:25:39 IPS_BUSY
2019-08-06T15:25:39 IPS_BUSY
2019-08-06T15:25:39 IPS_BUSY
2019-08-06T15:25:38 IPS_BUSY
2019-08-06T15:25:38 IPS_BUSY
2019-08-06T15:25:38 IPS_BUSY
2019-08-06T15:25:38 IPS_BUSY
2019-08-06T15:25:37 IPS_BUSY
2019-08-06T15:25:37 IPS_BUSY
2019-08-06T15:25:37 IPS_BUSY
2019-08-06T15:25:37 IPS_BUSY
2019-08-06T15:25:36 IPS_BUSY
2019-08-06T15:25:36 IPS_BUSY
2019-08-06T15:25:36 IPS_BUSY
2019-08-06T15:25:36 IPS_BUSY
2019-08-06T15:25:35 IPS_BUSY
2019-08-06T15:25:35 IPS_BUSY
2019-08-06T15:25:35 IPS_BUSY
2019-08-06T15:25:35 IPS_BUSY
2019-08-06T15:25:34 IPS_BUSY
2019-08-06T15:25:34 IPS_BUSY
2019-08-06T15:25:34 IPS_BUSY
2019-08-06T15:25:34 IPS_BUSY
2019-08-06T15:25:33 IPS_BUSY
2019-08-06T15:25:33 IPS_BUSY
2019-08-06T15:25:33 IPS_BUSY
2019-08-06T15:25:33 IPS_BUSY
2019-08-06T15:25:32 IPS_BUSY
2019-08-06T15:25:32 IPS_BUSY
2019-08-06T15:25:32 IPS_BUSY
2019-08-06T15:25:32 IPS_BUSY
2019-08-06T15:25:31 IPS_BUSY
2019-08-06T15:25:31 IPS_BUSY
2019-08-06T15:25:31 IPS_BUSY
2019-08-06T15:25:31 IPS_BUSY
2019-08-06T15:25:30 IPS_BUSY
2019-08-06T15:25:30 IPS_BUSY
2019-08-06T15:25:30 IPS_BUSY
2019-08-06T15:25:30 IPS_BUSY
2019-08-06T15:25:29 IPS_BUSY
2019-08-06T15:25:29 IPS_BUSY
2019-08-06T15:25:29 IPS_BUSY
2019-08-06T15:25:29 IPS_BUSY
2019-08-06T15:25:28 IPS_BUSY
2019-08-06T15:25:28 IPS_BUSY
2019-08-06T15:25:28 IPS_BUSY
2019-08-06T15:25:28 IPS_BUSY
2019-08-06T15:25:27 IPS_BUSY
2019-08-06T15:25:27 IPS_BUSY
2019-08-06T15:25:27 IPS_BUSY
2019-08-06T15:25:27 IPS_BUSY
2019-08-06T15:25:26 IPS_BUSY
2019-08-06T15:25:26 IPS_BUSY
2019-08-06T15:25:26 IPS_BUSY
2019-08-06T15:25:26 IPS_BUSY
2019-08-06T15:25:25 IPS_BUSY
2019-08-06T15:25:25 IPS_BUSY
2019-08-06T15:25:25 IPS_BUSY
2019-08-06T15:25:25 IPS_BUSY
2019-08-06T15:25:24 IPS_BUSY
2019-08-06T15:25:24 IPS_BUSY
2019-08-06T15:25:24 IPS_BUSY
2019-08-06T15:25:24 IPS_BUSY
2019-08-06T15:25:23 IPS_BUSY
2019-08-06T15:25:23 IPS_BUSY
2019-08-06T15:25:23 IPS_BUSY
2019-08-06T15:25:23 IPS_BUSY
2019-08-06T15:25:22 IPS_BUSY
2019-08-06T15:25:22 IPS_BUSY
2019-08-06T15:25:22 IPS_BUSY
2019-08-06T15:25:22 IPS_BUSY
2019-08-06T15:25:21 IPS_BUSY
2019-08-06T15:25:21 IPS_BUSY
2019-08-06T15:25:21 end of IPS_OK
2019-08-06T15:25:21 Slewing to target coordinates: RA (08h 52m 06s) DEC ( 67° 02' 52").
2019-08-06T15:25:21 Mount is synced to solution coordinates. Astrometric solver is successful.
2019-08-06T15:25:21 Syncing to RA (06h 47m 54s) DEC ( 67° 05' 39")
2019-08-06T15:25:21 Solution coordinates: RA (06h 47m 54s) DEC ( 67° 05' 39") Telescope Coordinates: RA (06h 47m 57s) DEC ( 67° 05' 47")
2019-08-06T15:25:21 WCS information updated. Images captured from this point forward shall have valid WCS.
2019-08-06T15:25:21 Solver completed in 6 seconds.
2019-08-06T15:25:15 Starting solver...
2019-08-06T15:25:15 Index files index-4205 to index-4210 are missing. Astrometry.net would not be able to adequately solve plates until you install the missing index files. Download the index files from http://www.astrometry.net
2019-08-06T15:25:15 Image received.
2019-08-06T15:25:07 Capturing image...
2019-08-06T15:25:02 Settling...
2019-08-06T15:25:02 Slew complete. Solving Alignment Point. . .
2019-08-06T15:25:02 m_wasSlewStarted true!
2019-08-06T15:25:02 ALIGN_SLEWING (1)
2019-08-06T15:24:58 IPS_BUSY
2019-08-06T15:24:58 Slewing to target coordinates: RA (06h 47m 56s) DEC ( 67° 05' 47").
2019-08-06T15:24:58 The Mount Model Tool is Starting.
2019-08-06T15:24:53 end of IPS_OK
2019-08-06T15:24:49 IPS_BUSY
2019-08-06T15:24:49 IPS_BUSY
2019-08-06T15:24:48 IPS_BUSY
2019-08-06T15:24:48 IPS_BUSY
2019-08-06T15:24:48 IPS_BUSY
2019-08-06T15:24:48 IPS_BUSY
2019-08-06T15:24:47 IPS_BUSY
2019-08-06T15:24:47 IPS_BUSY
2019-08-06T15:24:47 IPS_BUSY
2019-08-06T15:24:47 IPS_BUSY
2019-08-06T15:24:46 IPS_BUSY
2019-08-06T15:24:46 IPS_BUSY
2019-08-06T15:24:46 IPS_BUSY
2019-08-06T15:24:46 IPS_BUSY
2019-08-06T15:24:45 IPS_BUSY
2019-08-06T15:24:45 IPS_BUSY
2019-08-06T15:24:45 IPS_BUSY
2019-08-06T15:24:45 IPS_BUSY
2019-08-06T15:24:44 IPS_BUSY
2019-08-06T15:24:44 IPS_BUSY
2019-08-06T15:24:44 IPS_BUSY
2019-08-06T15:24:44 IPS_BUSY
2019-08-06T15:24:43 IPS_BUSY
2019-08-06T15:24:43 IPS_BUSY
2019-08-06T15:24:43 IPS_BUSY
2019-08-06T15:24:43 IPS_BUSY
2019-08-06T15:24:42 IPS_BUSY
2019-08-06T15:24:42 IPS_BUSY
2019-08-06T15:24:42 IPS_BUSY
2019-08-06T15:24:42 IPS_BUSY
2019-08-06T15:24:41 IPS_BUSY
2019-08-06T15:24:41 IPS_BUSY
2019-08-06T15:24:41 IPS_BUSY
2019-08-06T15:24:41 IPS_BUSY
2019-08-06T15:24:40 IPS_BUSY
2019-08-06T15:24:40 IPS_BUSY
2019-08-06T15:24:40 IPS_BUSY
2019-08-06T15:24:40 Capture aborted.
2019-08-06T15:24:40 The Mount Model Tool is Reset.
2019-08-06T15:24:39 IPS_BUSY
2019-08-06T15:24:39 IPS_BUSY
2019-08-06T15:24:39 IPS_BUSY
2019-08-06T15:24:39 IPS_BUSY
2019-08-06T15:24:38 IPS_BUSY
2019-08-06T15:24:38 IPS_BUSY
2019-08-06T15:24:38 IPS_BUSY
2019-08-06T15:24:38 IPS_BUSY
2019-08-06T15:24:37 IPS_BUSY
2019-08-06T15:24:37 IPS_BUSY
2019-08-06T15:24:37 IPS_BUSY
2019-08-06T15:24:37 IPS_BUSY
2019-08-06T15:24:36 IPS_BUSY
2019-08-06T15:24:36 IPS_BUSY
2019-08-06T15:24:36 IPS_BUSY
2019-08-06T15:24:36 IPS_BUSY
2019-08-06T15:24:35 IPS_BUSY
2019-08-06T15:24:35 IPS_BUSY
2019-08-06T15:24:35 IPS_BUSY
2019-08-06T15:24:35 Capturing image...
2019-08-06T15:24:34 IPS_BUSY
2019-08-06T15:24:34 IPS_BUSY
2019-08-06T15:24:34 IPS_BUSY
2019-08-06T15:24:34 IPS_BUSY
2019-08-06T15:24:33 IPS_BUSY
2019-08-06T15:24:33 IPS_BUSY
2019-08-06T15:24:33 IPS_BUSY
2019-08-06T15:24:33 IPS_BUSY
2019-08-06T15:24:32 IPS_BUSY
2019-08-06T15:24:32 IPS_BUSY
2019-08-06T15:24:32 IPS_BUSY
2019-08-06T15:24:32 IPS_BUSY
2019-08-06T15:24:31 IPS_BUSY
2019-08-06T15:24:31 IPS_BUSY
2019-08-06T15:24:31 IPS_BUSY
2019-08-06T15:24:30 IPS_BUSY
2019-08-06T15:24:30 IPS_BUSY
2019-08-06T15:24:30 IPS_BUSY
2019-08-06T15:24:30 IPS_BUSY
2019-08-06T15:24:29 IPS_BUSY
2019-08-06T15:24:29 IPS_BUSY
2019-08-06T15:24:29 IPS_BUSY
2019-08-06T15:24:29 IPS_BUSY
2019-08-06T15:24:28 IPS_BUSY
2019-08-06T15:24:28 IPS_BUSY
2019-08-06T15:24:28 IPS_BUSY
2019-08-06T15:24:28 IPS_BUSY
2019-08-06T15:24:27 IPS_BUSY
2019-08-06T15:24:27 Changing filter to Filter#9...
2019-08-06T15:24:27 IPS_BUSY
2019-08-06T15:24:27 IPS_BUSY
2019-08-06T15:24:27 IPS_BUSY
2019-08-06T15:24:26 IPS_BUSY
2019-08-06T15:24:26 IPS_BUSY
2019-08-06T15:24:26 IPS_BUSY
2019-08-06T15:24:26 IPS_BUSY
2019-08-06T15:24:25 IPS_BUSY
2019-08-06T15:24:25 IPS_BUSY
2019-08-06T15:24:25 IPS_BUSY
2019-08-06T15:24:25 IPS_BUSY
2019-08-06T15:24:24 IPS_BUSY
2019-08-06T15:24:24 IPS_BUSY
2019-08-06T15:24:24 IPS_BUSY
2019-08-06T15:24:23 IPS_BUSY
2019-08-06T15:24:23 IPS_BUSY
2019-08-06T15:24:23 IPS_BUSY
2019-08-06T15:24:23 IPS_BUSY
2019-08-06T15:24:22 IPS_BUSY
2019-08-06T15:24:22 IPS_BUSY
2019-08-06T15:24:22 IPS_BUSY
2019-08-06T15:24:22 Settling...
2019-08-06T15:24:22 Slew complete. Solving Alignment Point. . .
2019-08-06T15:24:22 m_wasSlewStarted true!
2019-08-06T15:24:22 ALIGN_SLEWING (1)
2019-08-06T15:24:20 Slewing to target coordinates: RA (06h 47m 56s) DEC ( 67° 05' 47").
2019-08-06T15:24:20 The Mount Model Tool is Starting.
2019-08-06T15:24:19 Solver aborted after 0 seconds
2019-08-06T15:24:19 The Mount Model Tool is Reset.
2019-08-06T15:23:47 IPS_BUSY
2019-08-06T15:23:47 Syncing to RA (23h 56m 00s) DEC ( 180° 00' 00")
2019-08-06T15:23:47 Slewing failed.
2019-08-06T15:23:47 Slewing to target coordinates: RA (06h 47m 56s) DEC ( 67° 05' 47").
2019-08-06T15:23:47 The Mount Model Tool is Starting.
2019-08-06T15:18:34 World Coordinate System (WCS) is enabled. CCD rotation must be set either manually in the CCD driver or by solving an image before proceeding to capture any further images, otherwise the WCS information may be invalid.
2019-08-06T15:18:34 Detected Astrometry.net version 0.76
2019-08-06T15:18:34 Idle.
Comment 8 James Lancaster 2019-08-06 21:53:55 UTC
Created attachment 121979 [details]
Wireshark Log

Log with ignoring packets above 10000 bytes (as it's using the CCD simulator and it ballons the size, even gzipped way above the 4000 KB limit)

Issue happens about ~ 179 in the capture. 00:26:12
Comment 9 James Lancaster 2019-08-06 21:54:54 UTC
Created attachment 121980 [details]
kstars log
Comment 10 Jasem Mutlaq 2019-08-07 05:52:48 UTC
Thanks for the logs! Do you know why in #16483 the state was set to Ok?
Comment 11 James Lancaster 2019-08-07 19:14:44 UTC
That case the Idle > OK is because of me turning tracking on. Then the mount model starts slewing it. Ok > Busy

(Seen in packet 16405) :Te# sent (Tracking Enable)
Comment 12 Jasem Mutlaq 2019-08-08 01:08:03 UTC
Ok I'm not sure...

Is the driver update period 250ms? I see 4 IPS_BUSYs in 1 second. If that is the case, just try to make the period 1 second and see if that makes any difference?
Comment 13 James Lancaster 2019-08-12 08:59:59 UTC
So different periods do affect how often it gets triggered. 

However, when I tried set at down at 100ms (really more like 200-250ish) and locally 17/25 instances encounter it. If it's at 1 second, maybe 1/10 do. 

I did try last night, with the timer idea, set for 1 second (oneshot and isactive checks right after the m_hasSlewStarted.) That *masks* the issue, but the erroneous IPS_BUSY is still being processed. Which has to be somewhere where kstars is setting it internally, because it's not on the wire. (As shown with wireshark)


Solving: 
I do see nvp->s = IPS_BUSY in indiproperty.cpp, could that or something like that be causing it? (I haven't yet gone through and checked why that's being set. Actually, that might make sense if it were: it's in sendText, and that seems like there might be when updating, but not something actually passed to INDI? )


As far as masking the issue: 
Thinking on it, I'm not sure that the Timer is a good idea, because in the event that the slew is < timer, only one IPS_OK, should be emitted. Hrm. 

Oh, an idea that might mask it better, and not mess up like the solution that works for me: The settle timer is ALSO updated if IPS_BUSY is noted? (Or the IPS_OK, which starts it now) is called. (Note that this was come up with on the fly and I haven't tested.)

QTimer maybeMasking; in header
When ALIGN_SYNCING is called, it sets up. 
maybeMasking.setSingleShot();
maybeMasking.setInterval(delaySpin->value());
connect(&maybeMasking, &QTimer::timeout, this, &Ekos::Align::captureAndSolve);

However, it doesn't start it, that's done with:
ALIGN_SLEWING, where currently it has this: 
                            if (delaySpin->value() >= DELAY_THRESHOLD_NOTIFY)
                                appendLogText(i18n("Settling..."));
                            QTimer::singleShot(delaySpin->value(), this, &Ekos::Align::captureAndSolve);

Replace that with 
                            if (delaySpin->value() >= DELAY_THRESHOLD_NOTIFY)
                                appendLogText(i18n("Settling..."));
                            maybeMasking.start()


Then in IPS_BUSY it becomes :
case IPS_BUSY:
    m_wasSlewStarted = true;
    if (maybeMasking.isActive()){
        maybeMasking.start()
        if (showbug410094 == true) 
          appendLogText(i18n("Bug 410094 masking..."));
    }

Which would reset it. (And if the optional and silly showbug... is shown, it would also leave a log of when it happened.) 


As an aside, how many other drivers can use the mount model? I know Eqmod can, but I'm not sure of others to compare with just to make sure that the INDI driver isn't the cause, which I'm 99%+ sure isn't the case because of wireshark, but still?
Comment 14 Jasem Mutlaq 2019-08-12 15:14:13 UTC
Created attachment 122087 [details]
align debug patch

I don't think we should opt for the hack-workaround just yet. Can you please apply this patch and share the log again? Hopefully it sheds more light on the issue.
Comment 15 Jasem Mutlaq 2019-08-19 07:01:55 UTC
Did you have a chance to test this? I included this patch in KStars by mistake as well. So if you just compile from git, you can test it out right away.
Comment 16 James Lancaster 2019-08-22 16:40:48 UTC
I have had some troubles and the one (real sky) test I did have (where I also put a timer in) worked, but had other issues, so I'll attempt to sim it again, shortly. 

Did you want wireshark or just kstars logs?
Comment 17 James Lancaster 2019-08-22 19:15:36 UTC
Created attachment 122295 [details]
Kstars log after patch using CCD simulator
Comment 18 James Lancaster 2019-08-22 19:22:27 UTC
Well, there's at least one instance seen here that I looked at. 


[2019-08-22T14:00:48.074 CDT INFO ][           org.kde.kstars.indi] - LX200 OnStep :  "[INFO] OnStep: Synchronization successful. "
[2019-08-22T14:00:48.074 CDT DEBG ][     org.kde.kstars.ekos.align] - ## RA "04:10:48" DE "61:35:06" state: Ok slewStarted? false
[2019-08-22T14:00:48.074 CDT DEBG ][     org.kde.kstars.ekos.align] - ## ALIGN_SYNCING --> setting slewStarted to FALSE
[2019-08-22T14:00:48.074 CDT INFO ][     org.kde.kstars.ekos.align] - "Mount is synced to solution coordinates. Astrometric solver is successful."
[2019-08-22T14:00:48.108 CDT DEBG ][     org.kde.kstars.ekos.align] - ## Before SLEW command: wasSlewStarted --> false
[2019-08-22T14:00:48.108 CDT DEBG ][           org.kde.kstars.indi] - ISD:Telescope:  TRACK
[2019-08-22T14:00:48.115 CDT DEBG ][           org.kde.kstars.indi] - ISD:Telescope sending coords RA: "06h 59m 17s" ( 6.98829 ) DE: " 61° 30' 54\"" ( 61.515 )
[2019-08-22T14:00:48.115 CDT DEBG ][     org.kde.kstars.ekos.align] - ## After SLEW command: wasSlewStarted --> true
[2019-08-22T14:00:48.115 CDT INFO ][     org.kde.kstars.ekos.align] - "Slewing to target coordinates: RA (06h 59m 17s) DEC ( 61° 30' 54\")."
[2019-08-22T14:00:48.116 CDT DEBG ][     org.kde.kstars.ekos.align] - ## RA "04:10:48" DE "61:35:06" state: Busy slewStarted? true
[2019-08-22T14:00:48.116 CDT DEBG ][     org.kde.kstars.ekos.align] - ## IPS_BUSY --> setting slewStarted to TRUE

...

[2019-08-22T14:00:48.268 CDT DEBG ][     org.kde.kstars.ekos.align] - ## RA "04:10:48" DE "61:35:07" state: Ok slewStarted? true
[2019-08-22T14:00:48.268 CDT DEBG ][     org.kde.kstars.ekos.align] - ## IPS_OK --> Auto Update Position...
[2019-08-22T14:00:48.268 CDT DEBG ][     org.kde.kstars.ekos.align] - ## Mount has not started slewing yet...
[2019-08-22T14:00:48.268 CDT DEBG ][     org.kde.kstars.ekos.align] - ## ALIGN_SLEWING --> setting slewStarted to FALSE
[2019-08-22T14:00:48.269 CDT INFO ][     org.kde.kstars.ekos.align] - "Slew complete. Solving Alignment Point. . ."
[2019-08-22T14:00:48.269 CDT INFO ][     org.kde.kstars.ekos.align] - "Settling..."
[2019-08-22T14:00:48.270 CDT INFO ][     org.kde.kstars.ekos.align] - "ReConnecting timer..."

... 

[2019-08-22T14:00:48.305 CDT DEBG ][     org.kde.kstars.ekos.align] - ## RA "04:10:48" DE "61:35:07" state: Busy slewStarted? false
[2019-08-22T14:00:48.305 CDT DEBG ][     org.kde.kstars.ekos.align] - ## IPS_BUSY --> setting slewStarted to TRUE
[2019-08-22T14:00:48.305 CDT INFO ][     org.kde.kstars.ekos.align] - "Bug 410094 settle restarting timer..."



Which has two problems:

1.     m_wasSlewStarted = currentTelescope->Slew(&targetCoord); (Ref 2019-08-22T14:00:48.115 )
2. The State being set erroniously to IPS_BUSY (Ref 2019-08-22T14:00:48.116), and not by the INDI driver, which comes back with the telescope status at 2019-08-22T14:00:48.268 with an IPS_OK. The command to issue it 


However, in the past I have tested it (and will again) with #1 not returning anything. So while potentially annoying, it is not the overall issue. (And could trigger when status is reported.) 


Just for reference, here's the diff as regards git (I haven't updated since the patch) Also to show where I have the timers set/reset if busy. 

diff --git a/kstars/ekos/align/align.cpp b/kstars/ekos/align/align.cpp
index 1cdc9026d..bd004125d 100644
--- a/kstars/ekos/align/align.cpp
+++ b/kstars/ekos/align/align.cpp
@@ -3489,11 +3489,15 @@ void Align::processNumber(INumberVectorProperty *nvp)
         ScopeRAOut->setText(ra_dms);
         ScopeDecOut->setText(dec_dms);
 
+        qCDebug(KSTARS_EKOS_ALIGN) << "## RA" << ra_dms << "DE" << dec_dms
+                                   << "state:" << pstateStr(nvp->s) << "slewStarted?" << m_wasSlewStarted;
+
         switch (nvp->s)
         {
             // Idle --> Mount not tracking or slewing
             case IPS_IDLE:
                 m_wasSlewStarted = false;
+                qCDebug(KSTARS_EKOS_ALIGN) << "## IPS_IDLE --> setting slewStarted to FALSE";
                 break;
 
             // Ok --> Mount Tracking. If m_wasSlewStarted is true
@@ -3503,6 +3507,7 @@ void Align::processNumber(INumberVectorProperty *nvp)
                 // Update the boxes as the mount just finished slewing
                 if (m_wasSlewStarted && Options::astrometryAutoUpdatePosition())
                 {
+                    qCDebug(KSTARS_EKOS_ALIGN) << "## IPS_OK --> Auto Update Position...";
                     opsAstrometry->estRA->setText(ra_dms);
                     opsAstrometry->estDec->setText(dec_dms);
 
@@ -3522,6 +3527,7 @@ void Align::processNumber(INumberVectorProperty *nvp)
                 // If we are looking for celestial pole
                 if (m_wasSlewStarted && pahStage == PAH_FIND_CP)
                 {
+                    qCDebug(KSTARS_EKOS_ALIGN) << "## PAH_FIND_CP--> setting slewStarted to FALSE";
                     m_wasSlewStarted = false;
                     appendLogText(i18n("Mount completed slewing near celestial pole. Capture again to verify."));
                     setSolverAction(GOTO_NOTHING);
@@ -3575,6 +3581,8 @@ void Align::processNumber(INumberVectorProperty *nvp)
                     case ALIGN_SYNCING:
                     {
                         m_wasSlewStarted = false;
+
+                        qCDebug(KSTARS_EKOS_ALIGN) << "## ALIGN_SYNCING --> setting slewStarted to FALSE";
                         if (currentGotoMode == GOTO_SLEW)
                         {
                             Slew();
@@ -3588,7 +3596,6 @@ void Align::processNumber(INumberVectorProperty *nvp)
                             state = ALIGN_COMPLETE;
                             emit newStatus(state);
                             solverIterations = 0;
-
                             if (mountModelRunning)
                                 finishAlignmentPoint(true);
                         }
@@ -3597,9 +3604,16 @@ void Align::processNumber(INumberVectorProperty *nvp)
 
                     case ALIGN_SLEWING:
                         // If mount has not started slewing yet, then skip
+                        qCDebug(KSTARS_EKOS_ALIGN) << "## Mount has not started slewing yet...";
                         if (m_wasSlewStarted == false)
                             break;
 
+                        qCDebug(KSTARS_EKOS_ALIGN) << "## ALIGN_SLEWING --> setting slewStarted to FALSE";
+                        
+                        if (maybeMasking.isActive()) {
+                            qCDebug(KSTARS_EKOS_ALIGN) << "## ALIGN_SLEWING --> maybeMasking.isActive() is still true, continuing";
+                        }
+                        
                         m_wasSlewStarted = false;
                         if (loadSlewState == IPS_BUSY)
                         {
@@ -3640,13 +3654,20 @@ void Align::processNumber(INumberVectorProperty *nvp)
 
                             if (delaySpin->value() >= DELAY_THRESHOLD_NOTIFY)
                                 appendLogText(i18n("Settling..."));
-                            QTimer::singleShot(delaySpin->value(), this, &Ekos::Align::captureAndSolve);
+//                             QTimer::singleShot(delaySpin->value(), this, &Ekos::Align::captureAndSolve);
+                                maybeMasking.setSingleShot(true);
+                                appendLogText(i18n("ReConnecting timer..."));
+                                maybeMasking.disconnect();
+                                connect(&maybeMasking, &QTimer::timeout, this, &Ekos::Align::captureAndSolve);
+                                maybeMasking.setInterval(delaySpin->value());
+                                maybeMasking.start();
                             return;
                         }
                         break;
 
                     default:
                     {
+                        qCDebug(KSTARS_EKOS_ALIGN) << "## Align State " << state << "--> setting slewStarted to FALSE";
                         m_wasSlewStarted = false;
                     }
                     break;
@@ -3657,13 +3678,19 @@ void Align::processNumber(INumberVectorProperty *nvp)
             // Busy --> Mount Slewing or Moving (NSWE buttons)
             case IPS_BUSY:
             {
+                qCDebug(KSTARS_EKOS_ALIGN) << "## IPS_BUSY --> setting slewStarted to TRUE";
                 m_wasSlewStarted = true;
+                if (maybeMasking.isActive()){
+                    maybeMasking.start();
+                    appendLogText(i18n("Bug 410094 settle restarting timer..."));
+                }
             }
             break;
 
             // Alert --> Mount has problem moving or communicating.
             case IPS_ALERT:
             {
+                qCDebug(KSTARS_EKOS_ALIGN) << "## IPS_ALERT --> setting slewStarted to FALSE";
                 m_wasSlewStarted = false;
 
                 if (state == ALIGN_SYNCING || state == ALIGN_SLEWING)
@@ -3877,7 +3904,10 @@ void Align::Slew()
     state = ALIGN_SLEWING;
     emit newStatus(state);
 
-    m_wasSlewStarted = currentTelescope->Slew(&targetCoord);
+    qCDebug(KSTARS_EKOS_ALIGN) << "## Before SLEW command: wasSlewStarted -->" << m_wasSlewStarted;
+    //m_wasSlewStarted = 
+    currentTelescope->Slew(&targetCoord);
+    qCDebug(KSTARS_EKOS_ALIGN) << "## After SLEW command: wasSlewStarted -->" << m_wasSlewStarted;
 
     appendLogText(i18n("Slewing to target coordinates: RA (%1) DEC (%2).", targetCoord.ra().toHMSString(),
                        targetCoord.dec().toDMSString()));
diff --git a/kstars/ekos/align/align.h b/kstars/ekos/align/align.h
index 4c3caa23f..e01aac786 100644
--- a/kstars/ekos/align/align.h
+++ b/kstars/ekos/align/align.h
@@ -750,6 +750,7 @@ class Align : public QWidget, public Ui::Align
 
         /// Have we slewed?
         bool m_wasSlewStarted { false };
+        QTimer maybeMasking;
 
         // Online and Offline parsers
         AstrometryParser* parser { nullptr };
Comment 19 Jasem Mutlaq 2019-08-23 00:49:51 UTC
Git commit e8b1be7eeed609101d6c491b14816f12ba4e5c03 by Jasem Mutlaq.
Committed on 23/08/2019 at 00:48.
Pushed by mutlaqja into branch 'master'.

+ Do not set m_wasSlewStarted explicity when issusing GOTO command. Wait for IPS_BUSY from mount driver.
+ Using Enums instead of string comprison for mount model object type.
FIXED-IN:3.3.5

M  +30   -14   kstars/ekos/align/align.cpp
M  +10   -1    kstars/ekos/align/align.h

https://commits.kde.org/kstars/e8b1be7eeed609101d6c491b14816f12ba4e5c03
Comment 20 James Lancaster 2019-09-02 04:13:20 UTC
This isn't resolved. I went ahead and updated as well, as adding in my timer, thinking it solved one but not the main problem, which was the IPS_BUSY being generated by kstars (and not showing up in wireshark logs)

I was unfortunately right. :( 

I added it in, and also added the timer, with a message, and on my tests tonight, so far at least 2/9 have shown the issue. 

Until the spurious IPS_BUSY status is located/suppressed dealt with, I'd suggest adding the timer, to make it usable.
Comment 21 Jasem Mutlaq 2019-09-02 05:23:04 UTC
The only place where this happens is in sendNewNumber(...) so it sets the EQNP property to IPS_BUSY. However, processNumber(...) in Align class looks for updates in EQUATORIAL_EOD_COORD (sent by the driver). So this whole logic is locked behind getting an update in this property from the driver.

Therefore, if the driver now sends EQNP with IPS_OK, then m_wasSlewStarted remains false and nothing happens.

Does your driver define EQUATORIAL_COORD as well?
Comment 22 Jasem Mutlaq 2020-12-14 17:00:07 UTC
Is this reproducible on 3.5.0?
Comment 23 Bug Janitor Service 2020-12-29 04:34:24 UTC
Dear Bug Submitter,

This bug has been in NEEDSINFO status with no change for at least
15 days. Please provide the requested information as soon as
possible and set the bug status as REPORTED. Due to regular bug
tracker maintenance, if the bug is still in NEEDSINFO status with
no change in 30 days the bug will be closed as RESOLVED > WORKSFORME
due to lack of needed information.

For more information about our bug triaging procedures please read the
wiki located here:
https://community.kde.org/Guidelines_and_HOWTOs/Bug_triaging

If you have already provided the requested information, please
mark the bug as REPORTED so that the KDE team knows that the bug is
ready to be confirmed.

Thank you for helping us make KDE software even better for everyone!
Comment 24 Bug Janitor Service 2021-01-13 04:33:57 UTC
This bug has been in NEEDSINFO status with no change for at least
30 days. The bug is now closed as RESOLVED > WORKSFORME
due to lack of needed information.

For more information about our bug triaging procedures please read the
wiki located here:
https://community.kde.org/Guidelines_and_HOWTOs/Bug_triaging

Thank you for helping us make KDE software even better for everyone!