PlanManager: Increase Timeouts for Mission Transfer #12184

menschel · 2024-12-09T21:29:29Z

PlanManager: Increase Timeouts for Mission Transfer

Description

This patch fixes runtime issues with Mission Upload/Download when the vehicle connection is based on a 900MHz ELRS System. (See Mavlink via ELRS feature.)

Two timeouts in PlanManager are increased.

The initial timeout is increased to cope with a delay when writing a Mission to the Flight Controller,
i.e. the Flight Controller needs some time to process Way-Points, Fences, Rally-Points etc. and this is enough to trigger the previously used timeout value. It is observed when initially starting the Mission Upload and when consecutively Fences and Rally-Points are written, regardless if there are any to be written.

The repeat timeout is increased to counter mix-up of requests resulting in sequence errors, i.e. when downloading the mission from the remote vehicle, QGroundControl already requested the item X+1 when the delayed response to this item X is received.

Test Steps

Test requires a PC or an arbitrary device running QGroundControl,
a 900MHz ELRS System running the Mavlink Connection and a Flight Controller with Ardupilot.

Prepare the PC and enable an Access-Point for the ELRS backpack to connect to.
Switch on the ELRS TX System and connect the ELRS BackPack to the Access-Point.
Switch on the Flight Controller together with the ELRS RX System.
Start QGroundControl.
Watch QGroundControl connect to the remote vehicle and progress past the Mission Download (validates the repeat timeout).
Go to Mission Plan, create a random mission and upload to remote vehicle. Mission Upload does complete without error (validates the initial timeout).

ELRS Hardware is somewhat standardized, so it should not matter what Manufacturer is used.
I use a Radiomaster TX12MK2 Handset together with a Radiomaster Bandit Transmitter and a BetaFPV SuperD Receiver.

Checklist:

Related Issue

Fixes #12076

By submitting this pull request, I confirm that you can use, modify, copy, and redistribute this contribution, under the terms of your choice.

DonLakeFlyer · 2024-12-10T17:34:13Z

src/MissionManager/PlanManager.h

@@ -68,9 +68,9 @@ class PlanManager : public QObject

    // These values are public so the unit test can set appropriate signal wait times
    // When passively waiting for a mission process, use a longer timeout.
-    static const int _ackTimeoutMilliseconds = 1500;
+    static const int _ackTimeoutMilliseconds = 2500;


This seems super long. This would only take affect on things like a go to location command. Are you sure this is needed? For mission download only the retry timeout comes into play.

Correct, the retry timeout was causing the issues on initial connect and mission download from vehicle to ground station.

The regular timeout hits when uploading a mission from ground station to the vehicle.
I'm not familiar with the sequence but there seems to be the situation where the vehicle should ask the ground station for the mission items and this ends up in this error.

_sendError(ProtocolError, tr("Vehicle did not request all items from ground station: %1").arg(_ackTypeToString(_expectedAck)));
https://github.com/mavlink/qgroundcontrol/blob/master/src/MissionManager/PlanManager.cc#L220

I'll attach a log once I figure out why I don't get any logging if I build Release Goal.

I had to build in debug goal to get logging again. This is the section when uploading mission to vehicle without touching the regular timeout.

PlanMasterControllerLog: PlanMasterController::sendToVehicle start mission sendToVehicle MissionControllerLog: MissionControllerLog::sendToVehicle MissionControllerLog: _convertToMissionItems seqNum:lastSeqNum:command 0 0 "Mission Start" MissionControllerLog: _convertToMissionItems seqNum:lastSeqNum:command 1 1 "Takeoff" MissionControllerLog: _convertToMissionItems seqNum:lastSeqNum:command 2 2 "Waypoint" MissionControllerLog: _convertToMissionItems seqNum:lastSeqNum:command 3 3 "Waypoint" MissionControllerLog: _convertToMissionItems seqNum:lastSeqNum:command 4 4 "Waypoint" MissionControllerLog: _convertToMissionItems seqNum:lastSeqNum:command 5 5 "Waypoint" MissionControllerLog: _convertToMissionItems seqNum:lastSeqNum:command 6 8 "Landing Pattern" PlanManagerLog: "writeMissionItems T:Mission count:" 9 PlanManagerLog: _setTransactionInProgress "T:Mission" 2 PlanManagerLog: "_writeMissionCount T:Mission count:_retryCount" 9 0 PlanManagerLog: "Retrying T:Mission MISSION_COUNT retry Count" 1 PlanManagerLog: "_writeMissionCount T:Mission count:_retryCount" 9 1 PlanManagerLog: "_handleMissionRequest T:Mission sequenceNumber" 0 PlanManagerLog: "_handleMissionRequest T:Mission sequenceNumber:command" 0 16 PlanManagerLog: "_handleMissionRequest T:Mission sequenceNumber" 0 PlanManagerLog: "_handleMissionRequest T:Mission sequence number requested which has already been sent, sending again:" 0 PlanManagerLog: "_handleMissionRequest T:Mission sequenceNumber:command" 0 16 PlanManagerLog: "_handleMissionRequest T:Mission sequenceNumber" 1 PlanManagerLog: "_handleMissionRequest T:Mission sequenceNumber:command" 1 22 QString::arg: Argument missing: _handleMissionAck ArduPilot sending possibly bogus MAV_MISSION_INVALID_SEQUENCE, T:Mission PlanManagerLog: "_handleMissionAck ArduPilot sending possibly bogus MAV_MISSION_INVALID_SEQUENCE" 0 PlanManagerLog: "_handleMissionRequest T:Mission sequenceNumber" 2 PlanManagerLog: "_handleMissionRequest T:Mission sequenceNumber:command" 2 16 PlanManagerLog: "_handleMissionRequest T:Mission sequenceNumber" 2 PlanManagerLog: "_handleMissionRequest T:Mission sequence number requested which has already been sent, sending again:" 2 PlanManagerLog: "_handleMissionRequest T:Mission sequenceNumber:command" 2 16 PlanManagerLog: "_handleMissionRequest T:Mission sequenceNumber" 3 PlanManagerLog: "_handleMissionRequest T:Mission sequenceNumber:command" 3 16 PlanManagerLog: "_handleMissionRequest T:Mission sequenceNumber" 3 PlanManagerLog: "_handleMissionRequest T:Mission sequence number requested which has already been sent, sending again:" 3 PlanManagerLog: "_handleMissionRequest T:Mission sequenceNumber:command" 3 16 QString::arg: Argument missing: _handleMissionAck ArduPilot sending possibly bogus MAV_MISSION_INVALID_SEQUENCE, T:Mission PlanManagerLog: "_handleMissionAck ArduPilot sending possibly bogus MAV_MISSION_INVALID_SEQUENCE" 0 PlanManagerLog: "_handleMissionRequest T:Mission sequenceNumber" 4 PlanManagerLog: "_handleMissionRequest T:Mission sequenceNumber:command" 4 16 QString::arg: Argument missing: _handleMissionAck ArduPilot sending possibly bogus MAV_MISSION_INVALID_SEQUENCE, T:Mission PlanManagerLog: "_handleMissionAck ArduPilot sending possibly bogus MAV_MISSION_INVALID_SEQUENCE" 0 PlanManagerLog: "_handleMissionRequest T:Mission sequenceNumber" 4 PlanManagerLog: "_handleMissionRequest T:Mission sequence number requested which has already been sent, sending again:" 4 PlanManagerLog: "_handleMissionRequest T:Mission sequenceNumber:command" 4 16 PlanManagerLog: "_handleMissionRequest T:Mission sequenceNumber" 5 PlanManagerLog: "_handleMissionRequest T:Mission sequenceNumber:command" 5 16 QString::arg: Argument missing: _handleMissionAck ArduPilot sending possibly bogus MAV_MISSION_INVALID_SEQUENCE, T:Mission PlanManagerLog: "_handleMissionAck ArduPilot sending possibly bogus MAV_MISSION_INVALID_SEQUENCE" 0 PlanManagerLog: "_handleMissionRequest T:Mission sequenceNumber" 5 PlanManagerLog: "_handleMissionRequest T:Mission sequence number requested which has already been sent, sending again:" 5 PlanManagerLog: "_handleMissionRequest T:Mission sequenceNumber:command" 5 16 PlanManagerLog: "_handleMissionRequest T:Mission sequenceNumber" 6 PlanManagerLog: "_handleMissionRequest T:Mission sequenceNumber:command" 6 189 QString::arg: Argument missing: _handleMissionAck ArduPilot sending possibly bogus MAV_MISSION_INVALID_SEQUENCE, T:Mission PlanManagerLog: "_handleMissionAck ArduPilot sending possibly bogus MAV_MISSION_INVALID_SEQUENCE" 0 PlanManagerLog: "_handleMissionRequest T:Mission sequenceNumber" 7 PlanManagerLog: "_handleMissionRequest T:Mission sequenceNumber:command" 7 31 PlanManagerLog: "Sending error - _planTypeString(T:Mission) errorCode(2) errorMsg(Vehicle did not request all items from ground station: MISSION_REQUEST)" PlanManagerLog: _setTransactionInProgress "T:Mission" 0 PlanMasterControllerLog: PlanMasterController::sendToVehicle start GeoFence sendToVehicle PlanManagerLog: "writeMissionItems T:GeoFence count:" 0 PlanManagerLog: _setTransactionInProgress "T:GeoFence" 2 PlanManagerLog: "_writeMissionCount T:GeoFence count:_retryCount" 0 0 PlanManagerLog: "_handleMissionRequest T:GeoFence Incorrect mission_type received expected:actual" 1 0 PlanManagerLog: "_handleMissionRequest T:GeoFence Incorrect mission_type received expected:actual" 1 0 PlanManagerLog: "_handleMissionAck T:GeoFence type:" "Mission accepted." PlanManagerLog: "_handleMissionAck write sequence complete T:GeoFence" PlanManagerLog: _setTransactionInProgress "T:GeoFence" 0 PlanMasterControllerLog: PlanMasterController::sendToVehicle start rally sendToVehicle PlanManagerLog: "writeMissionItems T:Rally count:" 0 PlanManagerLog: _setTransactionInProgress "T:Rally" 2 PlanManagerLog: "_writeMissionCount T:Rally count:_retryCount" 0 0 PlanManagerLog: "_handleMissionAck T:Rally type:" "Mission accepted." PlanManagerLog: "_handleMissionAck write sequence complete T:Rally" PlanManagerLog: _setTransactionInProgress "T:Rally" 0 PlanMasterControllerLog: PlanMasterController::sendToVehicle Rally Point send complete PlanMasterControllerLog: PlanMasterController::sendToVehicle Rally Point send complete PlanMasterControllerLog: PlanMasterController::sendToVehicle Rally Point send complete PlanMasterControllerLog: PlanMasterController::sendToVehicle start mission sendToVehicle MissionControllerLog: MissionControllerLog::sendToVehicle MissionControllerLog: _convertToMissionItems seqNum:lastSeqNum:command 0 0 "Mission Start" MissionControllerLog: _convertToMissionItems seqNum:lastSeqNum:command 1 1 "Takeoff" MissionControllerLog: _convertToMissionItems seqNum:lastSeqNum:command 2 2 "Waypoint" MissionControllerLog: _convertToMissionItems seqNum:lastSeqNum:command 3 3 "Waypoint" MissionControllerLog: _convertToMissionItems seqNum:lastSeqNum:command 4 4 "Waypoint" MissionControllerLog: _convertToMissionItems seqNum:lastSeqNum:command 5 5 "Waypoint" MissionControllerLog: _convertToMissionItems seqNum:lastSeqNum:command 6 8 "Landing Pattern" PlanManagerLog: "writeMissionItems T:Mission count:" 9 PlanManagerLog: _setTransactionInProgress "T:Mission" 2 PlanManagerLog: "_writeMissionCount T:Mission count:_retryCount" 9 0 PlanManagerLog: "_handleMissionRequest T:Mission sequenceNumber" 8 PlanManagerLog: "_handleMissionRequest T:Mission sequenceNumber:command" 8 21 PlanManagerLog: "Fell off end of switch statement T:Mission 15" PlanManagerLog: "_handleMissionAck T:Mission type:" "Unknown error: 15. Item #8 Command: Land" PlanManagerLog: "Fell off end of switch statement T:Mission 15" PlanManagerLog: "Sending error - _planTypeString(T:Mission) errorCode(5) errorMsg(Unknown error: 15. Item #8 Command: Land)" PlanManagerLog: _setTransactionInProgress "T:Mission" 0 PlanMasterControllerLog: PlanMasterController::sendToVehicle start GeoFence sendToVehicle PlanManagerLog: "writeMissionItems T:GeoFence count:" 0 PlanManagerLog: _setTransactionInProgress "T:GeoFence" 2 PlanManagerLog: "_writeMissionCount T:GeoFence count:_retryCount" 0 0 PlanManagerLog: "Sending error - _planTypeString(T:GeoFence) errorCode(2) errorMsg(Mission write failed, vehicle failed to send final ack.)" PlanManagerLog: _setTransactionInProgress "T:GeoFence" 0 PlanMasterControllerLog: PlanMasterController::sendToVehicle start rally sendToVehicle PlanManagerLog: "writeMissionItems T:Rally count:" 0 PlanManagerLog: _setTransactionInProgress "T:Rally" 2 PlanManagerLog: "_writeMissionCount T:Rally count:_retryCount" 0 0 PlanManagerLog: "_handleMissionRequest T:Rally Incorrect mission_type received expected:actual" 2 0 PlanManagerLog: "_handleMissionAck T:Rally Incorrect mission_type received expected:actual" 2 0 PlanManagerLog: "_handleMissionAck T:Rally Incorrect mission_type received expected:actual" 2 1 PlanManagerLog: "_handleMissionAck T:Rally type:" "Mission accepted." PlanManagerLog: "_handleMissionAck write sequence complete T:Rally" PlanManagerLog: _setTransactionInProgress "T:Rally" 0 PlanMasterControllerLog: PlanMasterController::sendToVehicle Rally Point send complete PlanMasterControllerLog: PlanMasterController::sendToVehicle Rally Point send complete PlanMasterControllerLog: PlanMasterController::sendToVehicle Rally Point send complete PlanMasterControllerLog: PlanMasterController::sendToVehicle start mission sendToVehicle MissionControllerLog: MissionControllerLog::sendToVehicle MissionControllerLog: _convertToMissionItems seqNum:lastSeqNum:command 0 0 "Mission Start" MissionControllerLog: _convertToMissionItems seqNum:lastSeqNum:command 1 1 "Takeoff" MissionControllerLog: _convertToMissionItems seqNum:lastSeqNum:command 2 2 "Waypoint" MissionControllerLog: _convertToMissionItems seqNum:lastSeqNum:command 3 3 "Waypoint" MissionControllerLog: _convertToMissionItems seqNum:lastSeqNum:command 4 4 "Waypoint" MissionControllerLog: _convertToMissionItems seqNum:lastSeqNum:command 5 5 "Waypoint" MissionControllerLog: _convertToMissionItems seqNum:lastSeqNum:command 6 8 "Landing Pattern" PlanManagerLog: "writeMissionItems T:Mission count:" 9 PlanManagerLog: _setTransactionInProgress "T:Mission" 2 PlanManagerLog: "_writeMissionCount T:Mission count:_retryCount" 9 0 PlanManagerLog: "Retrying T:Mission MISSION_COUNT retry Count" 1 PlanManagerLog: "_writeMissionCount T:Mission count:_retryCount" 9 1 PlanManagerLog: "_handleMissionRequest T:Mission sequenceNumber" 0 PlanManagerLog: "_handleMissionRequest T:Mission sequenceNumber:command" 0 16 PlanManagerLog: "_handleMissionRequest T:Mission sequenceNumber" 0 PlanManagerLog: "_handleMissionRequest T:Mission sequence number requested which has already been sent, sending again:" 0 PlanManagerLog: "_handleMissionRequest T:Mission sequenceNumber:command" 0 16 PlanManagerLog: "_handleMissionRequest T:Mission sequenceNumber" 1 PlanManagerLog: "_handleMissionRequest T:Mission sequenceNumber:command" 1 22 PlanManagerLog: "Sending error - _planTypeString(T:Mission) errorCode(2) errorMsg(Vehicle did not request all items from ground station: MISSION_REQUEST)" PlanManagerLog: _setTransactionInProgress "T:Mission" 0 PlanMasterControllerLog: PlanMasterController::sendToVehicle start GeoFence sendToVehicle PlanManagerLog: "writeMissionItems T:GeoFence count:" 0 PlanManagerLog: _setTransactionInProgress "T:GeoFence" 2 PlanManagerLog: "_writeMissionCount T:GeoFence count:_retryCount" 0 0 PlanManagerLog: "_handleMissionAck T:GeoFence Incorrect mission_type received expected:actual" 1 0 PlanManagerLog: "_handleMissionRequest T:GeoFence Incorrect mission_type received expected:actual" 1 0 PlanManagerLog: "_handleMissionAck T:GeoFence type:" "Mission accepted." PlanManagerLog: "_handleMissionAck write sequence complete T:GeoFence" PlanManagerLog: _setTransactionInProgress "T:GeoFence" 0 PlanMasterControllerLog: PlanMasterController::sendToVehicle start rally sendToVehicle PlanManagerLog: "writeMissionItems T:Rally count:" 0 PlanManagerLog: _setTransactionInProgress "T:Rally" 2 PlanManagerLog: "_writeMissionCount T:Rally count:_retryCount" 0 0 PlanManagerLog: "_handleMissionRequest T:Rally Incorrect mission_type received expected:actual" 2 0 PlanManagerLog: "_handleMissionAck T:Rally type:" "Mission accepted." PlanManagerLog: "_handleMissionAck write sequence complete T:Rally" PlanManagerLog: _setTransactionInProgress "T:Rally" 0 PlanMasterControllerLog: PlanMasterController::sendToVehicle Rally Point send complete PlanMasterControllerLog: PlanMasterController::sendToVehicle Rally Point send complete PlanMasterControllerLog: PlanMasterController::sendToVehicle Rally Point send complete PlanMasterControllerLog: PlanMasterController::sendToVehicle start mission sendToVehicle MissionControllerLog: MissionControllerLog::sendToVehicle MissionControllerLog: _convertToMissionItems seqNum:lastSeqNum:command 0 0 "Mission Start" MissionControllerLog: _convertToMissionItems seqNum:lastSeqNum:command 1 1 "Takeoff" MissionControllerLog: _convertToMissionItems seqNum:lastSeqNum:command 2 2 "Waypoint" MissionControllerLog: _convertToMissionItems seqNum:lastSeqNum:command 3 3 "Waypoint" MissionControllerLog: _convertToMissionItems seqNum:lastSeqNum:command 4 4 "Waypoint" MissionControllerLog: _convertToMissionItems seqNum:lastSeqNum:command 5 5 "Waypoint" MissionControllerLog: _convertToMissionItems seqNum:lastSeqNum:command 6 8 "Landing Pattern" PlanManagerLog: "writeMissionItems T:Mission count:" 9 PlanManagerLog: _setTransactionInProgress "T:Mission" 2 PlanManagerLog: "_writeMissionCount T:Mission count:_retryCount" 9 0 PlanManagerLog: "_handleMissionRequest T:Mission sequenceNumber" 2 PlanManagerLog: "_handleMissionRequest T:Mission sequenceNumber:command" 2 16 PlanManagerLog: "_handleMissionRequest T:Mission sequenceNumber" 0 PlanManagerLog: "_handleMissionRequest T:Mission sequenceNumber:command" 0 16 QString::arg: Argument missing: _handleMissionAck ArduPilot sending possibly bogus MAV_MISSION_INVALID_SEQUENCE, T:Mission PlanManagerLog: "_handleMissionAck ArduPilot sending possibly bogus MAV_MISSION_INVALID_SEQUENCE" 0 PlanManagerLog: "Sending error - _planTypeString(T:Mission) errorCode(2) errorMsg(Vehicle did not request all items from ground station: MISSION_REQUEST)" PlanManagerLog: _setTransactionInProgress "T:Mission" 0 PlanMasterControllerLog: PlanMasterController::sendToVehicle start GeoFence sendToVehicle PlanManagerLog: "writeMissionItems T:GeoFence count:" 0 PlanManagerLog: _setTransactionInProgress "T:GeoFence" 2 PlanManagerLog: "_writeMissionCount T:GeoFence count:_retryCount" 0 0 PlanManagerLog: "_handleMissionRequest T:GeoFence Incorrect mission_type received expected:actual" 1 0 PlanManagerLog: "_handleMissionAck T:GeoFence type:" "Mission accepted." PlanManagerLog: "_handleMissionAck write sequence complete T:GeoFence" PlanManagerLog: _setTransactionInProgress "T:GeoFence" 0 PlanMasterControllerLog: PlanMasterController::sendToVehicle start rally sendToVehicle PlanManagerLog: "writeMissionItems T:Rally count:" 0 PlanManagerLog: _setTransactionInProgress "T:Rally" 2 PlanManagerLog: "_writeMissionCount T:Rally count:_retryCount" 0 0 PlanManagerLog: "_handleMissionRequest T:Rally Incorrect mission_type received expected:actual" 2 0 PlanManagerLog: "_handleMissionAck T:Rally type:" "Mission accepted." PlanManagerLog: "_handleMissionAck write sequence complete T:Rally" PlanManagerLog: _setTransactionInProgress "T:Rally" 0 PlanMasterControllerLog: PlanMasterController::sendToVehicle Rally Point send complete PlanMasterControllerLog: PlanMasterController::sendToVehicle Rally Point send complete PlanMasterControllerLog: PlanMasterController::sendToVehicle Rally Point send complete

I have to amend my initial comment. I just had the same issue when just uploading a mission that already is on the vehicle but I have a wireshark recording from the issue.

menschel · 2024-12-10T20:23:12Z

Just asking, is there a recipe for logging response times on mavlink, maybe with mavproxy or something?
I think we need to measure this instead of guessing.

EDIT: This looks promising. I'll try wireshark next
https://mavlink.io/en/guide/wireshark.html

HTRamsey · 2024-12-11T14:17:48Z

I think the technical way to find a response time would be to save the time diff from a PING message and add for processing time, but that's probably a little complicated for this purpose

menschel · 2024-12-11T17:56:29Z

Is this flow chart mandatory?
https://mavlink.io/en/services/mission.html#uploading_mission

Because it's the wrong message id then. 3 is the ELRS BackPack and 1 is the PC.

menschel · 2024-12-12T16:16:06Z

Ok, from what I figured out, I need to check how these duplicates from QGC to Vehicle happen.
And I need to create some dedicated timeout just for the mission transfer. Converting to draft therefore.

-2

DonLakeFlyer · 2024-12-12T17:29:34Z

Does Mission Planner work or does it show the same problem?

Because it's the wrong message id then. 3 is the ELRS BackPack and 1 is the PC.

Don't know what you mean by this.

menschel · 2024-12-13T06:50:10Z

Does Mission Planner work or does it show the same problem?

I have no working setup with MissionPlanner via UDP. Windows 10 Issue.

Because it's the wrong message id then. 3 is the ELRS BackPack and 1 is the PC.

Don't know what you mean by this.

This is a side finding, message is deprecated since 2020.
https://mavlink.io/en/messages/common.html#MISSION_REQUEST

DonLakeFlyer · 2024-12-13T17:40:51Z

message is deprecated since 2020.

That's just the difference between the INT version of messages and the non-INT versions. QGC supports both.

menschel · 2024-12-14T12:52:53Z

Intermediate change with additional timeout value. I'm checking if I must prevent repetition of MISSION_ITEM_INT being sent because flow chart does not account for it.

I noticed that there are tests. Is there also coverage somewhere?

menschel · 2024-12-14T18:27:08Z

I have just learned of TIMESYNC service but I can't grep it inside qgroundcontrol repo.
Am I correct that this is not implemented yet in qgroundcontrol?

DonLakeFlyer · 2024-12-14T19:33:34Z

You should be testing this first with mission uploads. That way QGC side is in control of the protocol state. Then I would up the timeouts to something like 5 minutes. Then try an upload. If you get double messages in the vehicle->qgc direction then this isn't a timeout problem it is a hardware setup problem.

QGC doesn't support TIMESYNC. Don't see how that is related to this either way though.

menschel · 2024-12-15T11:44:24Z

TIMESYNC is the successor of PING. The documentation is just completely outdated. So I requested change there as well.
mavlink/mavlink-devguide#585

IMO, tracing link latency would end up somewhere in the LinkInterface.

menschel · 2024-12-15T16:03:11Z

I have the measured round trip times, collected by a simple python script.

from datetime import datetime
from statistics import median
from pymavlink import mavutil

if __name__ == "__main__":
    from argparse import ArgumentParser

    parser = ArgumentParser()
    parser.add_argument("--baudrate", type=int,
                        help="master port baud rate", default=115200)
    parser.add_argument("--device", required=True, help="serial device")
    parser.add_argument("--source-system", dest='SOURCE_SYSTEM', type=int,
                        default=255, help='MAVLink source system for this GCS')
    args = parser.parse_args()

    master = mavutil.mavlink_connection(args.device, baud=args.baudrate, source_system=args.SOURCE_SYSTEM)
    for i in range(10):
        print(master.recv_match())
    master.wait_heartbeat(blocking=True)
    print("heartbeat")
    round_trip_times = []
    start_time = datetime.now()
    start_time_ns = int(start_time.timestamp() * 10 ** 9)
    master.mav.timesync_send(tc1=0, ts1=start_time_ns)
    for i in range(200):
        message = master.recv_match(type="TIMESYNC", blocking=True)
        if message.ts1 == start_time_ns:
            round_trip_time = datetime.now()-start_time
            print("Link Latency {0}".format(round_trip_time))
            start_time = datetime.now()
            start_time_ns = int(start_time.timestamp() * 10 ** 9)
            master.mav.timesync_send(tc1=0, ts1=start_time_ns)
            round_trip_times.append(round_trip_time)
    print("Statistics: {0} {1} {2}".format(min(round_trip_times), median(round_trip_times), max(round_trip_times)))

On the UDP port of the target PC with ELRS 900M,
I see everything from 0.8 to 1.8 seconds and the median is roughly 1 second.

Same Test with 2G4 ELRS results in 0.1 to 0.5 seconds and the median is 0.2 seconds.
That explains why 2G4 has absolutely no timing issues with QGroundControl.

DonLakeFlyer · 2024-12-15T19:11:41Z

With close to two second latency mission problems would be the tip of the iceberg. Nearly all traffic to the vehicle which requires acks will fail.

Did you verify that there isn't a double send problem vehicle->qgc that is unrelated to things timing out?

menschel · 2024-12-15T21:53:15Z

I believe the measurements are valid.
I have not checked in wireshark but the script's invariant should guarantee no double messages.

It seems to be a bandwidth issue on ELRS and how ELRS splits bandwidth between RC and Mavlink, according to LUA script, the bandwidths are:
900M + 200Hz +1:2 TelemRatio -> 3921bps
2G4 + 1000Hz +1:2 TelemRatio -> 19921bps

Note: The link-latency is half the round-trip-time, so 900ms worst-case according to measurements.

menschel · 2024-12-16T08:23:34Z

PCAPNG attached, again, this time only the relevant packets...
link_latency.zip

menschel · 2024-12-16T12:12:14Z

A side note:
MissionPlanner Mission Upload without using MavFTP is also broken.
It may be an option to switch mission upload to MavFTP in QGroundControl.

HTRamsey · 2024-12-16T12:55:06Z

Just out of curiosity could you update to the latest commit and see if the latency is any different? I moved an expensive operation out of the UDP receive slot and it should make a noticeable difference

menschel · 2024-12-16T17:37:23Z

Just out of curiosity could you update to the latest commit and see if the latency is any different? I moved an expensive operation out of the UDP receive slot and it should make a noticeable difference

infinite errors on my setup

qgc.comms.udplink: Failed to join multicast group "224.0.0.1"
qgc.comms.udplink: Communication error: "Failed to join multicast group"

DonLakeFlyer · 2024-12-16T18:00:13Z

It may be an option to switch mission upload to MavFTP in QGroundControl.

That would only help missions. Parameter downloads/uploads will likely fail intermittently. Commands will fail because acks don't come back fast enough. QGC just isn't designed to work with round trip latencies close to two seconds.

HTRamsey · 2024-12-16T18:53:24Z

@menschel your issue should be resolved in #12216. The multicast error shouldn't have been fatal to the link

menschel · 2024-12-16T19:01:19Z

@menschel your issue should be resolved in #12216. The multicast error shouldn't have been fatal to the link

ok, I'll rebase on that. I had to revert all 3 changes to Comms to get it working again.

HTRamsey · 2024-12-16T19:03:47Z

was there an issue with the serial link too? I think I might have a similar thing with being too harsh about the errors

This patch fixes runtime issues which are observed on 900MHz ELRS. During mission download from the vehicle, repeat timeout occurs, causing mixup of request-response pairs which results in sequence errors of mission items. The repeat timeout is therefore increased to 1.5 seconds. GCS based message repetition eventually bites with ELRS stubborn sender feature. During mission upload to the vehicle, the regular timeout of 1.5 seconds is too tight and causes reported errors about not all mission items retrieved by vehicle. Therefore a separate timeout for MISSION_REQUEST_INT service is added with a value of 2.5 seconds which seems appropriate. For clarity the word default is added to the name of the original timeout values.

menschel · 2024-12-16T19:49:34Z

was there an issue with the serial link too? I think I might have a similar thing with being too harsh about the errors

The commit with serial link had some effect on the parameter retrieval, no clue what the issue was.

With 54a27d4 everything works again.

I'll see that I write some function in LinkInterface to mimic what my python script has been doing and use that as timeout for these operations.

menschel mentioned this pull request Dec 10, 2024

[Mavlink] Stubborn Sender feature breaks Message sequences on 900Mhz RC Link ExpressLRS/ExpressLRS#3046

Closed

DonLakeFlyer reviewed Dec 10, 2024

View reviewed changes

menschel marked this pull request as draft December 12, 2024 16:16

menschel mentioned this pull request Dec 13, 2024

GCS_MAVLINK: Fix Deprecation of MISSION_REQUEST ArduPilot/ardupilot#28854

Open

menschel force-pushed the pr-fix-elrs-900-timings branch from 4a1247d to b5f418a Compare December 14, 2024 12:30

menschel force-pushed the pr-fix-elrs-900-timings branch from b5f418a to 1c616ec Compare December 16, 2024 15:58

HTRamsey and others added 2 commits December 16, 2024 20:35

Comms: Ignore UDP Link Multicast Failure

000757a

menschel force-pushed the pr-fix-elrs-900-timings branch from ec7b85d to 54a27d4 Compare December 16, 2024 19:39

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

PlanManager: Increase Timeouts for Mission Transfer #12184

PlanManager: Increase Timeouts for Mission Transfer #12184

menschel commented Dec 9, 2024

DonLakeFlyer Dec 10, 2024

menschel Dec 10, 2024

menschel Dec 10, 2024

menschel Dec 11, 2024

menschel commented Dec 10, 2024 •

edited

Loading

HTRamsey commented Dec 11, 2024

menschel commented Dec 11, 2024

menschel commented Dec 12, 2024

DonLakeFlyer commented Dec 12, 2024

menschel commented Dec 13, 2024

DonLakeFlyer commented Dec 13, 2024

menschel commented Dec 14, 2024

menschel commented Dec 14, 2024

DonLakeFlyer commented Dec 14, 2024

menschel commented Dec 15, 2024

menschel commented Dec 15, 2024 •

edited

Loading

DonLakeFlyer commented Dec 15, 2024

menschel commented Dec 15, 2024 •

edited

Loading

menschel commented Dec 16, 2024 •

edited

Loading

menschel commented Dec 16, 2024

HTRamsey commented Dec 16, 2024

menschel commented Dec 16, 2024 •

edited

Loading

DonLakeFlyer commented Dec 16, 2024 •

edited

Loading

HTRamsey commented Dec 16, 2024

menschel commented Dec 16, 2024

HTRamsey commented Dec 16, 2024 •

edited

Loading

menschel commented Dec 16, 2024

PlanManager: Increase Timeouts for Mission Transfer #12184

Are you sure you want to change the base?

PlanManager: Increase Timeouts for Mission Transfer #12184

Conversation

menschel commented Dec 9, 2024

Description

Test Steps

Checklist:

Related Issue

DonLakeFlyer Dec 10, 2024

Choose a reason for hiding this comment

menschel Dec 10, 2024

Choose a reason for hiding this comment

menschel Dec 10, 2024

Choose a reason for hiding this comment

menschel Dec 11, 2024

Choose a reason for hiding this comment

menschel commented Dec 10, 2024 • edited Loading

HTRamsey commented Dec 11, 2024

menschel commented Dec 11, 2024

menschel commented Dec 12, 2024

DonLakeFlyer commented Dec 12, 2024

menschel commented Dec 13, 2024

DonLakeFlyer commented Dec 13, 2024

menschel commented Dec 14, 2024

menschel commented Dec 14, 2024

DonLakeFlyer commented Dec 14, 2024

menschel commented Dec 15, 2024

menschel commented Dec 15, 2024 • edited Loading

DonLakeFlyer commented Dec 15, 2024

menschel commented Dec 15, 2024 • edited Loading

menschel commented Dec 16, 2024 • edited Loading

menschel commented Dec 16, 2024

HTRamsey commented Dec 16, 2024

menschel commented Dec 16, 2024 • edited Loading

DonLakeFlyer commented Dec 16, 2024 • edited Loading

HTRamsey commented Dec 16, 2024

menschel commented Dec 16, 2024

HTRamsey commented Dec 16, 2024 • edited Loading

menschel commented Dec 16, 2024

menschel commented Dec 10, 2024 •

edited

Loading

menschel commented Dec 15, 2024 •

edited

Loading

menschel commented Dec 15, 2024 •

edited

Loading

menschel commented Dec 16, 2024 •

edited

Loading

menschel commented Dec 16, 2024 •

edited

Loading

DonLakeFlyer commented Dec 16, 2024 •

edited

Loading

HTRamsey commented Dec 16, 2024 •

edited

Loading