Rework MAVLink dataflash log download: reliability, cancellation, and tests - #3764
Rework MAVLink dataflash log download: reliability, cancellation, and tests#3764userepo wants to merge 9 commits into
Conversation
- track received blocks in a HashSet with a lowest-missing cursor instead of a string-keyed Hashtable rescanned from zero every retry tick - wait on a semaphore signalled per LOG_DATA packet instead of polling with Thread.Sleep(10); only enqueue LOG_DATA in the packet handler - add optional CancellationToken and delete the partial temp file on timeout/cancel/link loss - only treat a short packet as end-of-log at the highest offset seen, so a reordered short chunk cannot truncate the download; use a ceiling block count (old len/90+1 requested a block past EOF on exact multiples) - remove per-download JSON serialization of the packet event list LogDownloadMavLink: cancel the transfer when the form closes, name the file from LOG_ENTRY time_utc instead of re-parsing the whole download (DFLogBuffer scan kept as fallback), scale the progress bar to 0-1000 so >2GB batches do not overflow it, and fix the rename error message showing the destination path twice.
Let the semaphore wait carry the retry/re-request timeout instead of looping on a DateTime deadline; replace the start=MinValue re-request hack with a RequestFirstMissing local function.
Cover the log download protocol with an in-memory fake vehicle in tests/MissionPlanner.ArduPilot.Tests: complete/reordered/dropped-block transfers, exact-multiple-of-90 logs, empty logs, cancellation, and timeout. Split the protocol into internal GetLogInternal taking the destination path, make the retry/refetch timeouts injectable, and add InternalsVisibleTo for the test assembly. Pin CsWin32 to the resolved 0.3.269 to silence NU1603.
A cancelled or failed GetLog left the vehicle streaming LOG_DATA, which made the next log operation fail with "Existing log download already in progress". Found via SITL end-to-end testing; covered by a unit test.
Console harness that lists and downloads a log from a live ArduPilot SITL vehicle, verifies it byte-for-byte against the log file SITL wrote to disk, and exercises mid-download cancellation. Includes a MAVLink- aware lossy proxy for fill-in phase testing and a README with the SITL setup recipe and reference results.
userepo
changed the title
|
Hi @meee1, could you take a look at this PR. |
There was a problem hiding this comment.
Pull request overview
Warning
Copilot couldn't run its full agentic review because it didn't start before the timeout. Make sure your repository has a runner available, or add a copilot-code-review.yml file specifying one with the runs-on attribute. See the docs for more details.
Reworks MAVLink dataflash log download flow to improve reliability and cancellation behavior, and adds dedicated automated/manual test harnesses for verification.
Changes:
- Adds xUnit protocol-level unit tests using an in-memory fake vehicle +
CommsInjection. - Updates log download UI to support cancellation, avoid unnecessary re-parsing for timestamps, and prevent
ProgressBaroverflow on large logs. - Refactors
MAVLinkInterface.GetLoginternals (block tracking, retry/refetch logic, cancellation, cleanup) and bumpsCsWin32package version to resolve restore warnings.
Reviewed changes
Copilot reviewed 10 out of 10 changed files in this pull request and generated 11 comments.
Show a summary per file
| File | Description |
|---|---|
| tests/MissionPlanner.ArduPilot.Tests/MissionPlanner.ArduPilot.Tests.csproj | Adds a net472 xUnit test project referencing production projects. |
| tests/MissionPlanner.ArduPilot.Tests/GetLogTests.cs | Implements unit tests for in-order/reordered transfers, refetch, EOF edge cases, cancellation, and timeout. |
| tests/MissionPlanner.ArduPilot.SitlTests/lossy_proxy.py | Adds a lossy TCP proxy to simulate LOG_DATA drops for manual SITL testing. |
| tests/MissionPlanner.ArduPilot.SitlTests/README.md | Documents the manual SITL test harness and lossy-link procedure. |
| tests/MissionPlanner.ArduPilot.SitlTests/Program.cs | Adds a manual end-to-end console harness for listing + downloading + optional cancel/oracle compare. |
| tests/MissionPlanner.ArduPilot.SitlTests/MissionPlanner.ArduPilot.SitlTests.csproj | Adds a net472 console harness project and copies the proxy script to output. |
| Log/LogDownloadMavLink.cs | Wires cancellation into the UI, improves naming/timestamps, and rescales progress display. |
| ExtLibs/WinUSBNet/Nefarius.Drivers.WinUSB.csproj | Bumps Microsoft.Windows.CsWin32 package version. |
| ExtLibs/ArduPilot/MissionPlanner.ArduPilot.csproj | Exposes internals to the new test assembly. |
| ExtLibs/ArduPilot/Mavlink/MAVLinkInterface.cs | Refactors GetLog implementation for reliability, cancellation, and unit-testability. |
💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.
- GetLog: unsubscribe the Progress handler in a finally so throws and cancels cannot leak it - clamp the scaled progress value; the sender may deliver more bytes than LOG_ENTRY reported - dispose CancellationTokenSources: on replacement, on download completion, and guard the Cancel/Dispose race on form close - filter LOG_DATA by sysid/compid before enqueueing so unrelated traffic cannot grow the queue or reset the silence timers - lossy_proxy.py: bytearray buffer instead of O(n^2) bytes slicing - exclude tests/** from the app project's compile globs
Harden GetLog against malformed packets and fill-in stalls - skip LOG_DATA whose count exceeds the 90-byte payload instead of aborting the download - ignore fill-in data beyond the log length established by the end marker so a bogus offset cannot extend the file - bound the fill-in phase with the same total silence budget as the streaming phase (3x LogDataTimeoutMs) instead of re-requesting forever
- only a newly received block triggers the immediate fill re-request, so stale or duplicated packets on an echoing link cannot multiply LOG_REQUEST_DATA traffic - only packets near the contiguous frontier raise the end-of-log bar, a corrupt far offset cannot poison end detection; the log length comes from the end packet itself and the file is truncated to it - two new tests, both failing before the fix; SITL clean and lossy runs re-verified byte-identical (0.42 s / 55.5 s)
fallenmi
left a comment
fallenmi
left a comment
There was a problem hiding this comment.
The new end-detection guard still trusts a corrupt short packet when the packet is also at a far offset. On exact head a99de123, I injected a valid-looking LOG_DATA packet with ofs=1_000_000 and count=40 after five normal blocks, then continued the real 1,234-byte stream. GetLogInternal() treats that packet as the end marker and the download fails with Timeout on read - GetLog fill-in instead of returning the log.
The packet is correctly excluded from maxEnd because it is beyond endDetectionSlack, but the later EOF condition does not apply the same trust boundary: data.ofs + data.count >= maxEnd is true for the far offset, so the code sets totallength to 1,000,040. The existing tests cover a far packet only at count=90 and a stray short packet only at an old near-stream offset; they do not combine the two properties.
Please require an end packet to satisfy the same near-contiguous-frontier condition before it can terminate the streaming phase (or validate it against an independently known log size), and add the combined regression. Applying that same-frontier predicate to the EOF branch makes the new case pass, and all 13 GetLogTests pass together. There are currently no published checks for this head.
Disclosure: I used OpenAI Codex to inspect the exact revision and construct and run this MAVLink packet-sequence regression; I verified the failure and the minimal guarded variant locally.
A LOG_DATA packet that is both short and at a corrupt far offset cleared the end-of-log bar trivially: maxEnd is only raised by packets near the contiguous frontier, so ofs + count >= maxEnd held and the streaming phase ended at a phantom length, failing the download in the fill-in phase. Requiring the end packet itself to sit near the frontier is not enough: on a lossy link the frontier stalls at the first dropped block, and the genuine end of a large log then sits far past any fixed trust window. Rejecting it forces the whole stream to be re-sent per recovered gap. Instead, an end packet past the trusted window becomes a candidate that is only accepted once the stream goes quiet: a corrupt packet is followed by more stream, the real end is not. Corrupt far packets are also kept away from the retry offset, and only packets carrying new blocks reset the retry budget, so a resent stale packet cannot keep the streaming phase alive forever. Verified against SITL: clean-link download unchanged (0.44s byte identical), 5% LOG_DATA loss completes in 58.4s byte-identical, where a plain near-frontier requirement on the end packet never completed.
Good catch, thank you, @fallenmi. Confirmed on a99de12 and fixed in ed2d40b. One note on the fix shape: I tried the same-frontier predicate on the EOF branch first, and while all unit tests pass with it, the SITL lossy harness rejected it - at 5% loss the contiguous frontier stalls at the first dropped block, so the genuine end packet of a 2.3 MB log sits far past any fixed trust window, and rejecting it forces the whole stream to be re-sent for every recovered gap (the proxy logged five full re-streams without completing). So an end packet past the trusted window is now a deferred candidate instead: it only ends the streaming phase if the stream then goes quiet - a corrupt mid-stream packet is followed by more data, the real end is not. Your combined regression is added, plus three related ones (retry-offset hijack by the same packet, stale resends must not keep resetting the retry budget, and a stalled-frontier end must hand over to fill-in rather than re-stream). 16 tests pass, and re-verified against SITL: clean 0.44 s byte-identical, 5% loss 58.4 s byte-identical. |
A LOG_DATA packet that is both short and at a corrupt far offset cleared the end-inference bar trivially: only frontier-near packets raise the bar, so end >= bar held and the download ended at a phantom length. Past the true end that stalls the repair phase into a timeout; below it the phantom silently truncated the returned file. Rejecting far end packets outright is not an option: packet loss stalls the frontier at the first dropped block, so the genuine end of a large log always sits far past the trust window, and every recovered gap then forces the vehicle to re-stream the whole log (that variant never finished the lossy SITL run). Instead the tracker records a deferred candidate, discarded when more stream arrives, and GetLog promotes it once a silence window expires: a corrupt packet is followed by more stream, the real end is not. Found via review of the equivalent change on the upstream PR (ArduPilot#3764). SITL: clean unchanged (0.44 s byte-identical), 5% LOG_DATA loss 77.3 s byte-identical in one streaming pass - the earlier 72.9 s reference plus one silence window confirming the end. Harness README reference results and the STATUS.md checkpoint updated to match.
Problem
Log download over MAVLink has long-standing reliability and performance problems
(#3461, and the class of complaints in #3387 and the forum's many
"slow log download" threads). In
MAVLinkInterface.GetLog:Hashtablekeyed by the decimal string ofofs/90, and every 500 ms retry tick re-scanned all blocks from zero — on alarge log with a late gap, millions of string allocations per tick.
Thread.Sleep(10), adding up to 10 ms oflatency per packet independent of link speed.
LOG_DATApacket ended the streaming phase even when it arrived outof order, silently truncating the download.
was an exact multiple of 90 bytes.
the transfer (and the vehicle's streaming) kept running, and the partial temp
file was leaked.
DFLogBuffer) just toextract a GPS timestamp for the filename.
Changes
ExtLibs/ArduPilot/Mavlink/MAVLinkInterface.cs:HashSet<uint>with a lowest-missing cursor;finding the first gap is O(1) instead of an O(n) string-keyed rescan.
LOG_DATApacket.The waits carry the timeouts, so the loops only run when a packet arrives or
a deadline genuinely expires.
correct ceiling block count (no phantom block past EOF).
CancellationToken(public signature otherwise unchanged;the
[Obsolete]GetLog(ushort)wrapper still compiles and behaves the same).LOG_REQUEST_ENDwhen a download is abandoned, so the vehicle stopsstreaming and the next log operation works immediately.
GetLogInternal(..., filename, ...)thattakes the destination path, with the retry/refetch timeouts injectable —
defaults and public behavior are unchanged; this is what makes the code unit
testable.
Log/LogDownloadMavLink.cs:LOG_ENTRY.time_utc; the full-log GPS scanruns only as a fallback when the vehicle reports no valid time. This removes
a second full pass over every downloaded log.
the
int-basedProgressBar.Behavior changes to be aware of
LOG_DATAreceived" ratherthan a rolling deadline since the last accepted packet. These differ only
when a second GCS is downloading a different log on the same link — and the
new behavior avoids retry-spamming a busy vehicle.
time_utcinstead of a GPS-messagescan (same times in practice; the old scan remains as the fallback).
Tests
tests/MissionPlanner.ArduPilot.Tests— xUnit suite (7 tests) driving theprotocol against an in-memory fake vehicle over
CommsInjection: in-orderand reordered transfers, dropped-block refetch, exact-multiple-of-90 logs,
empty logs, cancellation (including
LOG_REQUEST_END), and timeout. Runs in~3 s via the built exe or
dotnet test.tests/MissionPlanner.ArduPilot.SitlTests— manual end-to-end harness plus aMAVLink-aware lossy proxy and a README with the SITL setup recipe.
Neither project is in
MissionPlanner.sln, so CI is unaffected.Verification against ArduPilot SITL (Copter stable, TCP)
byte-for-byte identical to the log file SITL wrote to its own disk.
LOG_DATAloss (1,348 of 26,971 frames dropped by the proxy): fill-inphase recovered every gap; result still byte-identical.
OperationCanceledException, no leaked tempfile, and the very next
LOG_REQUEST_LISTsucceeds.Not exercised end-to-end: tlog-replay mode (
logreadmode) and MAVLink1-onlyvehicles (covered by the protocol logic and unit tests, but SITL testing used
MAVLink2 over TCP).
Also included:
Microsoft.Windows.CsWin32pin inExtLibs/WinUSBNetbumped0.3.268 → 0.3.269 (the version NuGet already resolves — 0.3.268 is no longer
on the feed) to fix the NU1603 restore warning.
Addresses #3461.