Mavsdk: Timesync message warning spam

[depauwjimmy]

Continued from : https://github.com/mavlink/MAVSDK/issues/955

Summary

1 test program connected on TELEM1 with an FTDI cable to act as GroundStation
1 companion computer connected on TELEM2
AP is running using current PX4 beta firmware on master branch.
A Here2 GPS unit is connected.

GS receives the following message at a regular interval

[12:02:24|Warn ] RTT too high for timesync: 1.57917e+12 ms

CC receives the same message but sometimes with "1.57917e+12 ms" and sometimes a normal amount of time below 100ms

I don't know how to verify/set the time settings of the AP to see if it can fix the issue.

[irsdkv]

Please check if these messages appear again if:

1. GC connected, CC disconnected
2. CC connected, GC disconnected

Can you please tell which system time on CC and on GS PC during tests?

[depauwjimmy]

Here's the result, the test last 2 minutes.

Date on CC : Fri 24 Jan 09:49:52 UTC 2020
Date on GS : Fri 24 Jan 10:49:36 CET 2020

1. GC connected, CC disconnected

No message

1. CC connected, GC disconnected

No message

1. Both connected

On CC

[09:46:17|Warn ] RTT too high for timesync: 32.87 ms. (timesync.cpp:87)
[09:46:42|Warn ] RTT too high for timesync: 49.294 ms. (timesync.cpp:87)
[09:46:58|Warn ] RTT too high for timesync: 1.57986e+12 ms. (timesync.cpp:87)
[09:47:22|Warn ] RTT too high for timesync: 48.844 ms. (timesync.cpp:87)
[09:47:38|Warn ] RTT too high for timesync: 1.57986e+12 ms. (timesync.cpp:87)

On GS, 1 or 2 warnings every seconds.

[10:47:55|Warn ] RTT too high for timesync: 1.57986e+12 ms. (timesync.cpp:87)

[irsdkv]

Thank you!

Seems that:

1. On AP you have a not current UTC time but boot time.
2. TIMESYNC Messages from AP to CC and to GS have a one "extra hop":
   2.1. TIMESYNC request AP -> CC (msg.tc1: around 1970 (boot time), msg.ts1: 0)
   2.2. TIMESYNC response CC -> AP (msg.tc1: around 1970 (boot time), msg.ts1: current CC time)
   2.3. Extra hop:
   2.3.1. TIMESYNC response (CC -> AP) AP -> GS (msg.tc1: around 1970 (boot time), msg.ts1: current CC time).
   3.3.2. Warning from GS every 10.Hz / 5 times skipping == 2Hz from this line

The same situation appears with CC, I think (are you use ROS on CC?).

I'm not familiar with MAVLink stack so it is complicate to me to say where is the problem and how you can solve it just now.

@julianoes may be you can help with message routing?

[irsdkv]

Seems that https://github.com/PX4/Firmware/pull/14016 related to this problem. It might fix this I suppose.

[julianoes]

I need to look into the timesync stuff at some point. Right now I don't understand what it really does, so I rather not comment.

[irsdkv]

Just for help if you or something else will need to understand tymesync mechanism:

• MAVLink have an a simple message called TIMESYNC:
  It have only two fields:
  ts1 - the one who needs (Client) to synchronize time with other side (Server) put in this field his own time (in nanoseconds)
  tc1 - Server put in this field his own current time in response message (see below).

• Algorithm of timesync in common words (Client: MAVSDK, Server: Autopilot):

1. Client send TIMESYNC message (request) with tc1: 0; ts1: current_client_time.
2. Server receiving this message.
3. Server create response TIMESYNC message with tc1: current_server_time; ts1: current_client_time. current_client_time received in request message - Server just make copy of it
4. Server send response message to Client
5. Client receive TIMESYNC message and see that tc1 is not eq 0, so this is response message.
6. Client calculate time diff (tc1 - ts1) and set time offset.

[irsdkv]

@depauwjimmy is this issue still actual or PX4/Firmware#14016 resolve it?

[julianoes]

I think this is resolved unless when PX4 runs faster than realtime. For that case we can probably open a new issue.