Skip to content

autotest: reboot the vehicle before every test - #34417

Merged
peterbarker merged 7 commits into
ArduPilot:masterfrom
peterbarker:pr-claude2/reboot-before-every-test
Oct 17, 2026
Merged

peterbarker merged 7 commits into
ArduPilot:masterfrom
peterbarker:pr-claude2/reboot-before-every-test

Conversation

@peterbarker

@peterbarker peterbarker commented Sep 16, 2026 •

Copy link
Copy Markdown
Contributor

Summary

Reboot the vehicle before every autotest test, so no test inherits another test's in-RAM state. Measured cost on the two Copter CI buckets: +3.6 % and +0.3 %.

Classification & Testing (check all that apply and add your own)

  • Checked by a human programmer
  • Non-functional change
  • No-binary change
  • Infrastructure change (e.g. unit tests, helper scripts)
  • Automated test(s) verify changes (e.g. unit test, autotest)
  • Tested manually, description below (e.g. SITL)
  • Tested on hardware
  • Logs attached
  • Logs available on request

Testing, all of it an A/B of master against master plus these commits, run back
to back on the same idle machine:

  • CI: 102 checks, 102 pass.
  • Serial, 16C/32T Linux, eight suites (QuadPlane, Rover, Sub, Helicopter,
    BalanceBot, Sailboat, Tracker, Blimp), 364 tests:
    the test.* steps go
    2036 s -> 2125 s, +4.4 %, with the same 364 tests passing on both sides
    and no failures either side. Measured before the teardown already-rebooted
    case was handled, so an upper bound.
  • Serial, 10-core macOS, seven suites, 270 tests: +8.6 % on test time; the
    same three standing environment failures on both sides, and one fewer in the
    reboot half.
  • --parallel=32, all twelve suites, 1091 tests (on top of Add --parallel autotest option #34279, which
    is where --parallel lives): the pool's span goes 430.2 s -> 445.9 s,
    +3.6 %.
  • The failure this fixes, reproduced: AutoModeAccelChanges leaves the
    rover ~850 m from home; forcing DriveRTL to run next makes it fail on
    master with Didn't see wp 3, and pass with this change.

Description

run_one_test_attempt() reboots SITL before handing control to the test. A
SITL which has only just been started, or which the teardown has just rebooted,
is not rebooted again, so a single-test run costs what it always did.

A test that passes alone and fails after some particular neighbour is a
recurring and expensive class of bug, and it cannot happen to a test which
boots its own vehicle. The suite has been paying for that isolation piecemeal:
18 tests open with a bare reboot_sitl() or reset_SITL_commandline(), 187 of
951 test methods reboot or reset within their first three statements, and the
per-test teardown has grown a list of things to put back, each added after some
test was found inheriting something. --reset-after-every-test exists for the
same reason but restarts SITL with wipe=True and re-applies the whole
parameter set, which is far more expensive.

The worked example above is latent in master's own test list today, hidden only
because DriveRTL happens to sit earlier in the Rover list than the tests
merged alongside it.

What a reboot resets, and what it does not

SITL reboots with execv() of its own command line, so the vehicle and the
simulator restart together: position and attitude, EKF state and origin, home,
mission progress, armed state, and anything held only in RAM. Storage -
parameters, missions, rally points, fence - is a file and survives, which is
what the teardown's clears and --check-parameter-leaks are for. The exec
replaces the vehicle process alone, so a simulated peripheral started alongside
it keeps its state; a test which cares restarts its peripherals itself, as
CANGPSCopterMission does.

What it costs

What the reboot costs. Measured at this head, on one idle 16C/32T
machine, master against the branch, back to back, no failures on either side:

suite tests master this branch pre-test reboots delta
CopterTests1e 69 415 s 430 s 20 +15 s, +3.6 %, 0.22 s/test
CopterTests2b 202 1525 s 1530 s 58 +5 s, +0.3 %, 0.025 s/test

One pair per suite, so +/-1 % is noise and the tests2b figure means only "too
small to resolve this way". reboot_sitl() returns once it has seen three
RC_CHANNELS and does not wait for the EKF, so the reconvergence a reboot
forces is paid later inside each test's wait_ready_to_arm(); both are inside
the step times above.

Most tests do not pay for a reboot at all: the teardown already reboots after a
failed test, after a test which ended armed, and whenever a context pop
requires it, and the next test then skips its own - 20 reboots across 69 tests
in tests1e, 58 across 202 in tests2b.

The overhead lands hardest on suites of short tests: in an earlier serial
eight-suite A/B it was +1.0 % on QuadPlane and +21 % on Tracker, whose mean
test is 1.2 s.

The reconnect after a reboot needs a pymavlink which accepts reconnect_delay,
or each refused connect costs a fixed 1 s. That is in the submodule CI
installs from, and in the 2.4.50 release; on 2.4.49 the cost is 1.10 s per
reboot instead of 0.23 s.

The other commits

More boots means more logs, and that broke two things which the old log count
had been hiding:

  • AP_Logger: allow 5000 log files in SITL. CopterTests2b reaches 611
    logs with this change, against master's 454 and a 500 cap. Past the cap the
    log number wraps to 1 while the harness takes the highest-numbered file as
    the current log, so CompassLearnCopyFromEKFAffinity read a stale one and
    failed. The cap, and with it the LOG_MAX_FILES default, becomes 5000 for
    SITL only; real vehicles keep 500.
  • autotest: do not overflow STATUSTEXT's chunk_seq and keep log_list()'s listing out of STATUSTEXT. log_list() prints every log
    name on one line, and progress() also sent each line to the vehicle in
    50-byte chunks numbered by a uint8. Past ~600 logs that overflowed, and
    because progress() is also called while handling a test's exception, any
    failure was then reported as struct.error instead of its real cause. The
    listing no longer goes to the vehicle, and the chunk count is capped as a
    backstop.

What it does not fix

State which survives a reboot: anything in storage, anything the harness itself
remembers, and the log directory. It does nothing for the sampling races and
wall-clock-budget flakes, which are a separate family. The harness's
"highest-numbered log is the current one" assumption is still wrong after a
wrap; the larger cap only keeps the suites well away from it.

Follow-ups, not in this PR

The 18 tests which open with a reboot can drop it, and
--reset-after-every-test narrows to the cases which genuinely need
wipe=True.

This PR was AI-assisted: the change, the measurements and this description were
produced with Claude Code, and reviewed and tested by me.

🤖 Generated with Claude Code

@AP-Review

AP-Review commented Sep 16, 2026 •

Copy link
Copy Markdown

Deprecated — see below for the updated review.

Previous review (superseded 2026-09-17)

Automated review note — AI-generated (Claude), validated against the live diff. Please sanity-check before acting.

Reviewed at head 18b89f1ca7.

Full report, with everything that was checked: https://uav.tridgell.net/DevCallReviews/2026_09_16_AIReview/devcall_pr_reviews.html#pr34417

Verdict: COMMENT — 2 issues below.

A 23-line diff with a very large blast radius, and that asymmetry is the review. Measured A/B across six full suite runs (Tracker/Sub/Rover × two pymavlink versions, 208 distinct tests, 362 pre-test reboots): identical pass/fail sets in every pair, no reboot failures. The cost is right in CI and ~5× higher for a developer.

Issues

  • Tools/autotest/vehicle_test_suite.py:2645 — The advertised cost holds only with an unreleased pymavlink; with the released one it is ~5× higher. reboot_sitl() drops the TCP link and pymavlink reconnects with time.sleep(self.reconnect_delay). get_mavlink_connection_going() asks for reconnect_delay=0.05, but only when mavlink_connection_supports_reconnect_delay() is true; otherwise it falls back to pymavlink's default of 1 s. That kwarg was added in pymavlink c056feb9 (2026-08-06), which git tag --contains reports as being in no tagged release — the submodule is v2.4.49-110-gb7527da9 and PyPI's newest is 2.4.49. So CI is fine (build_ci.sh installs from the submodule), but a developer who followed install-prereqs-ubuntu.sh gets PyPI pymavlink and every pre-test reboot is a hard 1.0 s time.sleep(). 49 of 50 Sub pre-test reboots hit [Errno 111] Connection refused sleeping; the one that did not cost 0.1 s total, so the sleep, not the boot, is the cost. A full serial run of all 12 suites (982 tests) gains ~3 min on the submodule pymavlink and ~16 min of pure sleep on the released one. Worth calling out in the PR body, or making the reconnect fast independently of pymavlink's version.

  • Tools/autotest/vehicle_test_suite.py:10374 — "Before every test" is not what the flag delivers. sitl_is_freshly_started is set by any start_SITL() and cleared only in reboot_sitl_before_test(). Measured skips: 17 reboots / 20 Tracker tests, 50 / 57 Sub, 114 / 131 Rover. Every skip audited was legitimate, so this is not a live bug — but the invariant is hand-maintained: arduplane.py:7369 has to set sitl_commandline_customised = True by hand precisely so its mid-test start_SITL() forces a teardown reset. A future test that restarts SITL mid-test without that line silently removes the next test's reboot, and nothing fails. Clearing the flag in the teardown would make it robust.

6 further minor notes (style, coverage, pre-existing items) are in the report rather than here, so they don't bury the above.


Independent cold pass: no actionable defect, APPROVE.

Reviewed by: Claude (full read of the diff, thread and surrounding source) + an independent Codex cold pass that was not shown these findings. Findings marked both reviewers were reproduced independently twice.

@AP-Review

AP-Review commented Sep 16, 2026 •

Copy link
Copy Markdown

Deprecated — see below for the updated review.

Previous review (2026-09-16)

Automated review note — AI-generated (Claude), validated against the live diff. Please sanity-check before acting.

Re-reviewed at head e33beeda11 (previously reviewed at 18b89f1ca7); my earlier comment above is superseded.

Full report, including everything that was checked and found clean: https://uav.tridgell.net/DevCallReviews/2026_09_17_AIReview/devcall_pr_reviews.html#pr34417

Verdict: REQUEST CHANGES

Draft, so incompleteness is not the issue — but the red CI job is a real regression caused by this change, and it was reproduced locally by mutation. The failing test is CompassLearnCopyFromEKFAffinity, and the cause is that the extra reboots push CopterTests2b from master's 454 logs to the 500-log MAX_LOG_FILES cap, at which point the logger wraps to 00000001.BIN while current_onboard_log_filepath() keeps returning 00000500.BIN. 88 call sites read the "current" onboard log, so it mis-reads silently rather than failing loudly. Runtime cost was measured rather than estimated.


BUG — Tools/autotest/vehicle_test_suite.py:10078

The per-test reboot pushes CopterTests2b to the 500-log cap, the log number wraps, and the suite then reads a stale log. Each link verified: AP_Logger.cpp:93 sets MAX_LOG_FILES = 500 and AP_Logger_File.cpp:805-806 wraps log_num back to 1 past that; vehicle_test_suite.py:4793's log_list() is sorted(glob.glob("logs/00*.BIN")) and :13825 returns logs[-1]; autotest.py:422 clears logs/ only once per suite step. Measured high-water marks from the job logs: master CopterTests2b 454, this PR 500 (pinned at the cap) — roughly +34% logs, against a suite already at 91% of the cap. RED/GREEN reproduced locally at e33beeda11: the test with an empty logs/ PASSES; the same test with logs/ pre-seeded to exactly 500 files and LASTLOG.TXT=500 FAILS with Want 1 EV.Id=167, got 0 and Most recent logfile: logs/00000500.BIN — the exact CI error. A direct SITL run with LOG_MAX_FILES=4 over 8 reboots ended with sorted-by-name[-1]=00000004.BIN while the current log was 00000001.BIN. Note the compass offsets were saved in CI (COMPASS_OFS_X=193.2, COMPASS_OFS2_X=-142.99 both passed assert_parameter_values immediately before); only the log read was stale. It failed identically at both PR heads, so it is not a flake.

ISSUE — Tools/autotest/vehicle_test_suite.py:13825

The latent defect this change exposes: logs[-1] is only the current log while the log number has never wrapped. Keying off logs/LASTLOG.TXT or newest mtime would be correct regardless of wrap. This is latent on master today and will resurface on any long suite.

ISSUE — Tools/autotest/vehicle_test_suite.py:10078

Fixing only CopterTests2b leaves the trap armed — plane-tests1b is ~12 tests behind it. plane-tests1b now reaches 488/500 logs (master 364). It passes today, but it is close enough that the next few tests added anywhere in that suite will trip the same silent-stale-log failure.

ISSUE — Tools/autotest/vehicle_test_suite.py:9863

STILL OPEN from the previous round: the advertised cost holds only with an unreleased pymavlink. reconnect_delay falls back to 1 s when pymavlink lacks the kwarg. Re-confirmed at this head: released PyPI pymavlink 2.4.49 reports supports reconnect_delay: False; the submodule v2.4.49-110-gb7527da9 reports True. CI is fine; developers pay ~1 s per pre-test reboot.

Lower-priority notes (2)

Tools/autotest/vehicle_test_suite.py:10263 — This PR unblocks the commented-out remove_bin_logs(), which is the root-cause fix. The comment there says "can't do this as one of the binlogs is probably open for writing… If we force a rotate before running tests then we can do this" — and this PR supplies exactly that forced rotate. Enabling that line would cap log growth for good and fix the cause rather than the symptom.

Tools/autotest/vehicle_test_suite.py:2641 — Runtime cost, measured rather than guessed. Per pre-test reboot, wall clock from the CI log: mean 0.27 s (median 0.27, min 0.25, max 0.30, 160 samples) — 43 s total for CopterTests2b. Job wall clock: master tests2b 58.98 min → PR 61.80 min, +2.8 min (+4.8%); the reboots are only 43 s of that and the rest is EKF reconvergence (average wait-to-arm rose from 21.92 s over 285 arms to 24.32 s over 290 arms, +11%). Across the 16 CI suites' 955 tests, tests2b's 195 tests produced 160 pre-test reboots (0.82/test, the rest skipped by sitl_is_freshly_started), so a full serial run is ~783 reboots ≈ 3.5 min on the submodule pymavlink — and ~783 × 1.0 s ≈ 13 min of pure time.sleep() on the released one. Reconnect sleeps went 419 → 585 in tests2b, +166 for 160 reboots, confirming the arithmetic.

What was checked and found clean

The previous round's second finding is RESOLVED. "'Before every test' is not what the flag delivers; clear it in the teardown" — commit e33beeda11 is exactly that fix: sitl_is_freshly_started = False added at :10102 in the teardown path, so a mid-test start_SITL() can no longer silently skip the next test's reboot.

@AP-Review

AP-Review commented Sep 17, 2026 •

Copy link
Copy Markdown

Deprecated — see below for the updated review.

Previous review (head `90fd59741d`)

Automated review note — AI-generated (Claude), validated against the live diff. Please sanity-check before acting.

Full report: https://uav.tridgell.net/DevCallReviews/2026_09_17_AIReview/devcall_pr_reviews.html#pr34417

Re-reviewed at head 90fd59741d; my earlier comment above is superseded. Still a draft — treating it as such.

The BUG I raised last round is fixed. Verdict moves REQUEST CHANGES → COMMENT.

Previous round

  • BUG — pre-test reboots push CopterTests2b past the 500-log cap, the log number wraps, and the harness reads a stale log — RESOLVED. 90fd5974 raises MAX_LOG_FILES to 5000 for SITL. Reproduced both halves locally rather than reading: seeding logs/ with 500 files plus LASTLOG.TXT=500 and booting with LOG_DISARMED=1 gives, on the parent, LASTLOG=1 with 00000001.BIN overwritten so sorted(glob)[-1] returns the stale 00000500.BIN; at your head, LASTLOG=501, a new file, and every seed file preserved. A second reviewer reproduced the same independently.
  • ISSUE — logs[-1] is only the current log while the number has never wrapped — STILL OPEN, re-raised below.
  • ISSUE — advertised cost holds only with unreleased pymavlink — STILL OPEN. Re-verified today: PyPI pymavlink 2.4.49 has no reconnect_delay in mavutil.mavlink_connection's signature; the submodule pin b7527da9 does.
  • NOTE — this PR unblocks the commented-out remove_bin_logs() at :10263 — still open, and it's also the cleanest fix for the item below.

Still open — the root cause

Tools/autotest/vehicle_test_suite.py:13824-13825 — the cap raise moves the cliff from 500 to 5000; it doesn't remove it. current_onboard_log_filepath() is still sorted(glob.glob("logs/00*.BIN"))[-1] and AP_Logger_File.cpp still wraps log_num to 1 past the cap, so the same bug returns at 5000 — a second reviewer reproduced exactly that by seeding 5000 logs. The reason I'd still push for the root-cause fix is that the failure is quiet when it returns: you get Want 1 EV.Id=167, got 0 rather than anything mentioning logs.

Two corrections to my own previous numbers, both from the second pass and both accepted: the call-site count is 20 direct + 40 through the reader wrapper, not 23 + 40; and "every one fails silently" was too strong — some sites only print paths, and downstream assertions can fail visibly. Headroom, from archived high-water ratios (Sub 3.74, Rover 2.25, Tracker 2.2 logs/test — not 2.0 as I first said) against test.Copter's 391 tests: roughly 860–1450 logs, i.e. 3.5–5.8× headroom. That's extrapolated from other vehicles, not measured on Copter.

Keying off logs/LASTLOG.TXT or newest mtime, or enabling remove_bin_logs(), removes the cliff rather than moving it.

Smaller points

  • libraries/AP_Logger/AP_Logger.cpp:207-208 — the LOG_MAX_FILES metadata still says @Range: 2 500 and "Limit is capped at 500 logs", so on SITL the default is now outside its own declared range. No CI job catches this: param_parse.py only cross-checks Range against Values, never against the AP_GROUPINFO default.
  • libraries/AP_Logger/AP_Logger.cpp:97 — the per-logs/ disk ceiling rises about 10×. Measured over 341 real autotest SITL logs: mean 0.844 MiB, median 0.188, max 12.23, 287.8 MiB total (my previous comment mislabelled these as MB). Projecting gives roughly 422 MiB → 4.12 GiB — though as the second pass fairly points out, those are projections, since the cap limits file count rather than size. CI is largely insulated by rm -f logs/*.BIN at each step start; the exposure is a developer's sim_vehicle.py logs/ directory, which is never cleared.
  • The PR body still says "26 added lines in vehicle_test_suite.py, no other difference" and ticks No-binary change, while the head also changes AP_Logger.cpp. The substance is fine and I confirmed it — preprocessing the logger against real waf-generated compile commands gives 5000 for SITL and 500 for CubeOrange, so real-board policy is unchanged and this is not the undefined-macro trap — but strictly, CubeOrange objects do differ in diagnostic line-number constants. Worth updating the body so a reviewer isn't surprised by a flight-code file in the diff.

Withdrawn

I previously raised, as unconfirmed, that download_full_log_list()'s fixed 5-sim-second budget might be exceeded now the entry count isn't bounded by 500. That's refuted — please ignore it. Driving the real helper over TCP at speedup 100 for 501/1001/2001/5000 entries takes 0.039–0.134 s wall, and cached simulator time does advance (0.300–3.102 s), so the budget isn't being silently bypassed the way I supposed. No failure occurred.

CI at this head: 73 green, 29 queued or running, zero failures. Every autotest (sitltest-*) job — including copter-tests2b, the one that was red last round — was still queued when I looked, so the result that motivated this fix is not yet independently confirmed.

@AP-Review

AP-Review commented Sep 17, 2026 •

Copy link
Copy Markdown

Deprecated — see below for the updated review.

Previous review (2026-09-17)

Automated review note — AI-generated (Claude), cross-checked by an independent Codex pass against the live diff. Please sanity-check before acting.

Full report, including everything that was checked and found clean: https://uav.tridgell.net/DevCallReviews/2026_09_17_AIReview/devcall_pr_reviews.html#pr34417


COMMENT

Re-reviewed at head 18e05676c1 (previously 90fd59741d); my earlier comment above is superseded.

The new three-line guard is necessary, not defensive tidying, and I verified the whole causal chain rather than assuming it. Raising MAX_LOG_FILES to 5000 on SITL removed the ceiling that had been implicitly keeping log_list()'s progress line under STATUSTEXT's 256-chunk limit.

Verified end to end

Parsing your own cancelled copter-tests2b job at the parent head (run 35172740284): it reached 593 logs and a
12,474-character progress line = 250 of the 256 available chunks. Capacity is 256x50 = 12,800 bytes, so that
run was roughly sixteen more log files from a hard struct.error.

RED/GREEN under the netns wrapper on test.Tracker, seeding logs/ with 620 files, same SITL binary both halves:
head PASSED; parent FAILED with exactly struct.error: 'B' format requires 0 <= number <= 255.

Still open

  • Tools/autotest/vehicle_test_suite.py:4794 — the guard is the right safety net but the wrong layer.
    What overflowed chunk_seq is log_list() statustexting the entire log list. Two things the guard does not address:
    (a) that job made 97 log_list() calls, each STATUSTEXT logged by handle_statustext() as a Write_MessageChunk
    into the dataflash log the suite is about to read — log pollution rather than runtime cost, the 620-entry call
    was sub-0.1s here;
    (b) more importantly, the parent's traceback arrives through print_exception_caught(), which itself calls
    current_onboard_log_filepath() — so once logs/ is that big, any test failure gets reported as
    struct.error instead of its real cause.
    One line fixes it: self.progress("log list: %s" % str(ret), send_statustext=False), or log len(ret) and keep the
    full list on stdout. Keep the seq <= 255 guard as the backstop.

Smaller points

  • vehicle_test_suite.py:9932 — the truncation is silent. Nothing sends anywhere near 12,800 bytes today
    (longest direct test payload is 141 chars), so this is not live, but a trailing truncation marker would make a future
    overflow visible rather than mysterious.
  • libraries/AP_Logger/AP_Logger.cpp:205 — LOG_MAX_FILES metadata now contradicts its own default.
    The description still says "capped at 500 logs" with @Range: 2 500, while the SITL default is now 5000.
    param_parse.py only checks Range against Values, never against the AP_GROUPINFO default, so CI cannot catch it.
  • vehicle_test_suite.py:4198 — TestLogDownloadWrap no longer wraps at the default LOG_MAX_FILES.
    :4263-4264 still covers the 500 boundary explicitly, so this is one lost path rather than lost coverage —
    flagging so it is deliberate.
  • The PR body describes a diff that no longer exists (it claims 26 lines in one file and ticks No-binary change;
    the head is +33/-1 there plus +7/-0 in AP_Logger.cpp, which is flight code). Worth a refresh before leaving draft.
  • Re-raised, unchanged: current_onboard_log_filepath() is still sorted(glob)[-1] (:13826) — the 5000 cap
    moves the wrap cliff rather than removing it.
  • Re-raised, now measured: the advertised per-reboot cost needs an unreleased pymavlink. Measured four TCP reboots per
    version: 1.051-1.053 s with released 2.4.49 against 0.210-0.229 s with the submodule pin. CI uses the
    submodule and is unaffected; a developer following install-prereqs-ubuntu.sh pays the difference every pre-test reboot.

Withdrawn, and staying withdrawn: the download_full_log_list() 5-sim-second-budget concern from two rounds ago.

@AP-Review

AP-Review commented Sep 18, 2026 •

Copy link
Copy Markdown

Deprecated — see below for the updated review.

Previous review (2026-09-18)

Automated review note — AI-generated (Claude), validated against the live diff. Please sanity-check before acting.

Full report, with what was checked and found clean: https://uav.tridgell.net/DevCallReviews/2026_09_18/devcall_pr_reviews.html#pr34417

Re-reviewed at head 480af164f6 (previously 18e05676c1). COMMENT — no blockers. The mechanism holds up: I traced sitl_is_freshly_started through every producer and consumer and found no path that marks a dirty SITL fresh, and the armed-at-start, RC-state, post-reboot-settling, parameter-leak and displaced-vehicle interactions all check out. An independent codex exec pass, given only the PR number, ran eight isolated lifecycle cases (success, failure, mid-test restart, teardown restart) and reproduced no incorrect skip either.

ISSUE — libraries/AP_Logger/AP_Logger.cpp:208 — re-raised

@Range: 2 500 still contradicts the SITL default of 5000. AP_Logger.cpp:97 sets MAX_LOG_FILES = 5000 under HAL_BOARD_SITL and :212 uses it as the AP_GROUPINFO default, so on SITL the parameter's default is ten times its own declared maximum. The head commit edits the @Description on the line directly above and leaves @Range alone, which reads like the fix stopped one line short. CI cannot catch it — param_parse.py cross-checks Range only against Values and never reads the AP_GROUPINFO default — so the effect is a GCS clamping the SITL slider at 500. @Range: 2 5000 under SITL, or drop the numeric range the way the description's cap was dropped.

NOTE — the cost figures in the PR body

Recomputing the "Per suite, in seconds" table: tests sum to 363 (the body says 364), baselines 2036 s, reboot 2125 s, delta 89 s; 89/2036 = 4.371 % matches the stated +4.4 %. But total-delta-over-total-tests is 89/363 = 0.245 s, against the 0.37 s the summary line and the CI projection use. The table does label 0.37 as a trimmed mean, so it is not wrong — the Codex pass pushed back on exactly that and the pushback is right — but the summary and the projection drop the qualification, and a trimmed mean over suites weights Sailboat (n=2) the same as QuadPlane (n=93). On the aggregate figure, "422 tests gain about 156 s" becomes 103 s. Per suite the cost spans 0.086 s/test (QuadPlane) to 1.0 s/test (Sailboat); QuadPlane is the closest structural analogue to Copter and is the lowest in the set, which does not settle Copter either way but does make a single constant hard to defend.

Related: the summary quotes "+4.4 % serial, +3.6 % parallel" and omits the mac run's +8.6 %, the worst of the three. On that run the reboots themselves are 227 × 0.23 s = 52 s, i.e. 56 % of the delta; the remaining ~41 s is not attributed anywhere.

NOTE — two costs no published measurement covers

  • vehicle_test_suite.py:9865: reconnect_delay only drops from 1 s to 0.05 s when mavlink_connection_supports_reconnect_delay() is true. The installed pymavlink here is 2.4.49 (newest on PyPI) and does not have it — mavutil.py:1256 is a bare time.sleep(1). So anyone who installed via install-prereqs-ubuntu.sh pays 1 s whenever a reconnect finds SITL not yet listening; conditional, not every reboot, but this PR turns it from rare into per-test. CI uses modules/mavlink and is unaffected.
  • vehicle_test_suite.py:2557: under --valgrind/--callgrind a reboot is not an execv at all but stop_SITL() + start_SITL(wipe=False), so those runs now pay a full process restart on every required pre-test reboot. Unmeasured. (Upside: reboot_check_valgrind_log() per test attributes findings to the right test.)

NOTE — vehicle_test_suite.py:13829

Raising the cap to 5000 moves the wrap cliff rather than removing it: current_onboard_log_filepath() is still sorted(glob)[-1] and AP_Logger_File.cpp:805 still wraps. The Codex pass reproduced it — 5000 seeded filenames plus a modelled wrap to log 1 returns the stale 00005000.BIN. Worth saying because the two extra defensive commits on this branch are both treating symptoms of an unbounded logs/; remove_bin_logs() at :10263 is commented out and its own comment asks for exactly the forced pre-test rotate this PR adds.

NOTE — PR body scope

It says "26 added lines in vehicle_test_suite.py, no other difference" and ticks No-binary change, while the PR is now +36/−2 there and +8/−1 in AP_Logger.cpp, which changes a compiled SITL default. The sentence is scoped to the A/B experiment and is true of it, so this is not a false claim — but a reader can take the numbers as measured at this head. Worth clearing before the draft flag comes off.

Withdrawn during validation, so you do not chase it: I had flagged the comment at :2168 ("nothing has run against a SITL we have not started yet" above = False) as arguing for the opposite value. The Codex pass refuted it and is right — "not started yet" does not imply "freshly started", and False is correct. Dropped.

CI was 101 passing with 1 pending at review time; sitltest-copter-tests2b is the job that was red two rounds ago and is the reason the AP_Logger commit exists, so it is the one worth waiting for specifically.

@peterbarker
peterbarker force-pushed the pr-claude2/reboot-before-every-test branch from 480af16 to 948a14d Compare September 18, 2026 10:13
@AP-Review

AP-Review commented Sep 18, 2026 •

Copy link
Copy Markdown

Deprecated — see below for the updated review.

Previous review (2026-09-18)

Automated review note — AI-generated (Claude), validated against the live diff. Please sanity-check before acting.

Full report: https://uav.tridgell.net/DevCallReviews/2026_09_19_AIReview/devcall_pr_reviews.html#pr34417

Re-reviewed at head 948a14d23b (previously 480af164f6) — my earlier comment above is superseded.

Verdict: COMMENT

Still a draft, and the delta since the last round is exactly one line — the explanatory comment at AP_Logger.cpp:205; everything else is byte-identical after a rebase onto 2ecf55b847. The mechanism, the log-count cap raise and the STATUSTEXT changes all hold up on a full read, and the one open question from last round (@Range: 2 500 against a SITL default of 5000) is now answered in the source as a deliberate choice. The single red job is, on the evidence below, a pre-existing TakeoffTakeoff2 sampling race rather than a regression, but it should be re-run before the draft flag comes off.

CI at this head: ✗ 1 failing, 101 passing.

Previous round — every finding accounted for

Previous finding Status Evidence at this head
ISSUE AP_Logger.cpp:208: @Range: 2 500 contradicts the SITL default of 5000 ANSWERED BY AUTHOR — deliberate, not re-raised The head commit adds AP_Logger.cpp:205: SITL defaults to 5000 and values above 500 are still in testing, so the documented range stays at 500. Residual fact only: get_max_num_logs() (AP_Logger.cpp:866) constrains at runtime to [MIN_LOG_FILES, MAX_LOG_FILES] = [2, 5000] on SITL, so the SITL apm.pdef.xml carries a default ten times its declared maximum and a GCS slider clamps at 500. Harmless for autotest.
NOTE: cost figures in the PR body (trimmed mean 0.37 s; the mac +8.6 % omitted) STILL OPEN Body unchanged. See the independent cost measurement below.
NOTE vehicle_test_suite.py:9865: released pymavlink 2.4.49 has no reconnect_delay, so a developer pays ~1 s per reconnect STILL OPEN Code unchanged; not re-measured this round.
NOTE vehicle_test_suite.py:2557: under --valgrind/--callgrind the reboot is stop_SITL() + start_SITL(wipe=False), not an execv STILL OPEN Confirmed still true at :2553-2559. Unmeasured.
NOTE: the 5000 cap moves the sorted(glob)[-1] wrap cliff rather than removing it STILL OPEN current_onboard_log_filepath() is unchanged and AP_Logger_File.cpp:805 still wraps log_num to 1. Derived headroom for the suite that motivated the fix: plane-tests1b's high-water at this head is 483 logs for 137 tests, i.e. 10.3× headroom under the new cap. Adequately sized; the cliff is just further away.
NOTE: PR body scope ("26 added lines… no other difference", No-binary change ticked) STILL OPEN The PR is now +36/−2 in vehicle_test_suite.py and +9/−1 in AP_Logger.cpp across 4 commits.
Withdrawn last round: :2168 comment polarity Stays withdrawn Re-read; False is correct.

Findings

  • NOTE — Tools/autotest/arduplane.py:6276 — The red plane-tests1b job is a wait_altitude sampling race, and the evidence says this PR did not cause it. TakeoffTakeoff2 does wait_altitude(TKOFF_LVL_ALT-10, +2) — a 2 m window at 20-22 m. In the job log the printed samples go Altitude=0.63 then Altitude=32.45, and wait_and_maintain_range (vehicle_test_suite.py:8479) returns on the first in-band sample when minimum_duration is 0, so no sample ever landed inside [20, 22]. Three independent reasons it is not this change: (a) no pre-test reboot ran before it — the last Rebooting before test in that job is at AT-0412.2 and the test starts at AT-0439.2, because TakeoffTakeoff1 uses customise_SITL_commandline() and its teardown marks the SITL fresh; (b) TakeoffTakeoff2 itself opens with customise_SITL_commandline(model='plane-catapult'), so it restarts SITL regardless; (c) plane-tests1b passed at heads 90fd59741d, 18e05676c1 and 480af164f6, and the only delta since 480af164f6 is a C++ comment. Re-run the job; if it recurs, the fix belongs in the test (widen the band, or give the climb a minimum_duration), not here.

  • NOTE — Tools/autotest/vehicle_test_suite.py:10082 — A failed reboot is charged to the wrong test. reboot_sitl_before_test() is called inside run_one_test_attempt's try, so if detect_and_handle_reboot() hits its 10 s wall-clock timeout (:2660-2672) or reboot_sitl() raises NotAchievedException("Reboot attempted while armed") (:2618-2619), the test that is about to run is recorded as FAILED with a message about a reboot — when the cause is always the previous test's leftovers. Cheap fix: catch in reboot_sitl_before_test() and re-raise with the previous test's name in the message, so the buildlog names the culprit.

  • NOTE — Tools/autotest/vehicle_test_suite.py:2646 — The only non-default branch of the new function has no CI coverage. self.reboot_sitl(force=self.is_tracker(), mark_context=False) — and there is no Tracker, Sub or Blimp autotest job among the 102 checks, so this new caller's force=True selection is exercised only by local runs. To be precise about the scope, per the Codex pass: the forced-reboot implementation is already used by Plane and Copter tests, and antennatracker.py:100 overrides reboot_sitl to disarm_vehicle() first; it is the new call site's choice of force, not the underlying path, that CI never sees. Worth saying in the PR body that those three were covered locally, since CI cannot.

  • NOTE — libraries/AP_Logger/AP_Logger.cpp:205 — Style only: the new comment is 160 characters (167 columns with its indentation) on one line and sits immediately above the // @Param: block. It is safe — param_parse and param-file-validation both pass, and the parser keys off // @ — but a two-line comment would not sit inside the metadata block's visual scope.

  • NOTE — Tools/autotest/vehicle_test_suite.py:2646 — Independent cost measurement, from the job log rather than the PR body. plane-tests1b at this head: 137 tests, 100 pre-test reboots (37 skipped by sitl_is_freshly_started, i.e. 27 %). Wall clock from each Rebooting before test to its matching Reboot complete: mean 0.1604 s, median 0.1588, min 0.1386, max 0.1849, 16.037 s total — both passes reproduced those figures independently from the job timestamps. The denominator needed correcting: the test.PlaneTests1b span is 844.7 s, not 982, so the direct cost is 1.90 %. The indirect estimate the primary pass offered (about 7 s of extra EKF convergence inside the 71.7 s spent in 166 wait_ready_to_arm() calls, for ~2.3 % total) is withdrawn: one run cannot separate reboot-induced convergence from the baseline, so only the 1.90 % direct figure is substantiated. Still comfortably under the body's +4.4 %.

Both a primary read and an independent second pass were run; where the two disagreed the disagreement is stated in the report rather than averaged away. Anything marked unconfirmed was not reproduced — please push back on it.

@peterbarker
peterbarker force-pushed the pr-claude2/reboot-before-every-test branch from 948a14d to 369e9a1 Compare September 20, 2026 00:41
@AP-Review

AP-Review commented Sep 20, 2026 •

Copy link
Copy Markdown

Deprecated — see below for the updated review.

Previous review (2026-09-20)

Automated review note — AI-generated (Claude), validated against the live diff (Claude + Codex cross-checked). Please sanity-check before acting.

Re-reviewed at head 369e9a1b75 (previously 948a14d23b) — my earlier comment above is superseded.

Full report: https://uav.tridgell.net/DevCallReviews/2026_09_20/devcall_pr_reviews.html#pr34417

Verdict: COMMENT. Still a draft. This round is a pure rebase — zero content change. Using the merge-base method (old base 2ecf55b847, new base 368dc0c428), the two base-to-head patches are byte-identical once index lines are stripped, and the commit messages match exactly. So nothing below is a response to new code; every previous finding is accounted for, one is withdrawn as my error, and there's one stronger measurement.

CI is now fully green: 102 checks, 102 pass. The red plane-tests1b from last round is passing, which is what the previous review predicted when it diagnosed that failure as a pre-existing TakeoffTakeoff2 sampling race rather than a regression. That's resolved.

Previous round — every finding accounted for

Previous finding Status Evidence at this head
ISSUE AP_Logger.cpp:208: @Range: 2 500 vs the SITL default of 5000 WITHDRAWN — my own residual claim was wrong Last round I added: "the SITL apm.pdef.xml carries a default ten times its declared maximum." That is false. Tools/autotest/param_metadata/param.py:42-58 lists known_param_fields and there is no Default field; xmlemit.py:117-154 emits only recognised fields, not the compiled default. So the generated metadata carries no default and there's no contradiction. What survives is only that a GCS slider built from @Range stops at 500 while a SITL vehicle reports 5000 — harmless for autotest, and I didn't test actual GCS behaviour. Sorry for the noise.
NOTE: PR-body cost figures STILL OPEN, re-raised with a stronger measurement See below. Body unchanged.
NOTE :10082: a failed pre-test reboot is charged to the next test STILL OPEN Confirmed at :10080-10096/:10114-10118; exceptions at :2618-2619 and :2671-2672, 10 s default at :2660. One correction: I shouldn't have implied the previous test's leftovers are always the cause — an infrastructure or reboot failure can do it too.
NOTE :2645: the force=self.is_tracker() branch has no CI coverage STILL OPEN, narrowed No Tracker, Sub or Blimp job in this check record. But my claim last round that force is provably necessary (a tracker re-arming before the armed check) is unverified — antennatracker.py:100-102 disarms first and :6399 waits for disarm, and I couldn't demonstrate an intervening rearm. Stating it as unproven rather than as fact.
NOTE :9865: released pymavlink has no reconnect_delay STILL OPEN, acknowledged in the body Conditional selection present at :9865-9870; the gitlink is exactly 71d925850d. "~1 s per reconnect" is too strong — the sleep applies when a connection attempt fails.
NOTE :2548-2558: under --valgrind a reboot is stop+start, not execv STILL OPEN Unchanged, unmeasured.
NOTE: the 5000 cap moves the sorted(glob)[-1] wrap cliff rather than removing it STILL OPEN Mechanism confirmed (:4791-4796 sorts, :13825-13830 takes the last, AP_Logger_File.cpp:805-806 wraps to 1). New data point: CopterTests2b creates 611 distinct logs at this head vs 454 on master, so 8.2× headroom under 5000 — and 611 > 500 independently confirms the wrap this commit exists to fix.
NOTE: PR-body scope claims STILL OPEN Body still cites "26 added lines" against master 2ecf55b847; at this head commit 1 (65b0f18fb1) is 30 insertions and the base is 368dc0c428. Cosmetic but stale.
NOTE AP_Logger.cpp:205: comment length STILL OPEN 167 characters including indentation.
NOTE: red plane-tests1b was a pre-existing sampling race RESOLVED 102/102 pass. The diagnosis held.
Withdrawn last round: :2168 comment polarity Stays withdrawn Re-read; False is correct.

New this round

NOTE — Tools/autotest/vehicle_test_suite.py:2645 — the body's cost projection understates the real cost by about 2×, because the reboot's own wall time is less than half of what it costs.

Measured from the job logs, not estimated.

Direct: CopterTests2b at this head runs 159 pre-test reboots over 188 tests (29 skipped by sitl_is_freshly_started), totalling 42.21 s, mean 0.2655 s.

Indirect: reboot_sitl() returns as soon as initialise_after_reboot_sitl() has seen 3 RC_CHANNELS — it does not wait for the EKF — so reconvergence is paid later inside each test's wait_ready_to_arm(), outside the reboot window entirely. "Spent … waiting to arm" totals are ~7012 s simulated on the PR against ~6244 s on master over 285 identical calls → +767.75 s simulated, +2.694 s per call, which converts to +51.35 s wall (achieved arming speedup is ~13× on both sides, so the two are comparable).

Total attributable: 42.21 + 51.35 = +93.6 s on a master span of 3393.6 s = +2.76 %, 0.498 s per test — about twice the body's 0.245 s aggregate. Note CopterTests2b alone (188 tests) exceeds the body's +103 s projection for the whole 422-test Copter suite. plane-tests1b shows the same shape (100 reboots / 18.7 s direct, +395.6 s simulated arming over 165 calls).

What I deliberately don't claim: the raw step-duration delta. The observed span is +164.1 s over the master mean, but GitHub's ubuntu-22.04 fleet ranges 1347–3652 s on this job across 90 master runs, so ~70 s of that is unattributed host noise.

No code change needed — but if you quote figures in the body, the measured Copter number is the honest one, and the accounting is clearer split into "reboot" and "EKF reconvergence forced by the reboot", since on Copter the second is larger than the first (51.4 s vs 42.2 s) — the opposite of the body's "the reboots themselves are 73 s of the 89 s".

NOTE — :2633-2634 — the docstring's isolation claim covers the vehicle process only. HAL_SITL::actually_reboot() (HAL_SITL_Class.cpp:322-327) is execv, which replaces only that process; supplementary SITL binaries start separately at :10394-10402 and survive an ordinary reboot, so a simulated DroneCAN peripheral's RAM state isn't reset. I'd first written this off as moot because peripheral tests customise the command line — that's too generous: arducopter.py:5229 (CANGPSCopterMission) uses ordinary reboots with explicit peripheral restarts, so the gap is real for at least one test. One clause in the docstring would make the claim exact.

NOTE — :10106 — a teardown reboot_sitl() doesn't clear the freshness mark, so that path reboots twice. sitl_is_freshly_started = False runs right after the test function returns; the reset_SITL_commandline() path sets it true again via start_SITL (:10382) but the plain reboot_sitl() path (:10159, :10168) doesn't. Cost only, and in the conservative direction — noted because the commit message's "a restart by the teardown still marks it fresh" is true for the reset path and not the reboot path. Valgrind restarts do mark it fresh.

What was checked and found clean

Ordering is correct, which is the main correctness risk here: context_push() (:10067) precedes the reboot (:10082), which precedes change_mode(default_mode()), set_current_waypoint(0), drain_mav() and context_set_speedup(); mark_context=False correctly avoids requesting a needless context-pop reboot; customisation marks its context at :3377, teardown detects that at :10111 and resets at :10232-10233. No parameter-loss ordering defect — which is what would otherwise silently un-set parameters tests depend on.

-w is stripped from the re-exec argv (HAL_SITL_Class.cpp:252-259), so "storage survives" is right. Stream rates are restored (:2703 → :3356), nothing left at zero. The STATUSTEXT seq<=255 truncation is safe on the receiving side — GCS_Common.cpp:3873-3906 writes each chunk immediately via Write_MessageChunk() and never awaits a terminating short chunk. %08u filenames keep the glob and lexical sorted()[-1] correct to 999999, so 5000 is safe, and the loops bounded by get_max_num_logs() are do/while scans with no per-log allocation. test_param_upgrade.py drives its own run() and never enters run_one_test_attempt.

The commit message's claim that print_exception_caught() pulled in the huge log listing and masked the original failure with struct.error is accurate — I'd had it down as a wrong detail and checked it specifically.

One correction to my own previous wording: the leak exemptions (:7128-7164) are explicit statistic names rather than a blanket STAT_* match, and extend beyond that list, so "exactly the reboot-driven drift" overstates what static inspection shows.

Not checked: whether any test that manages its own reboots needs an escape hatch. The change applies to every vehicle's suite unconditionally and none is provided — worth a thought for firmware-update, storage or watchdog tests.

Both a primary read and an independent second pass were run; disagreements are recorded in the report rather than averaged away. The cost figures above come from the primary pass only — the second pass had no network access this run and could not re-derive them, so treat them as one measurement.

@peterbarker
peterbarker force-pushed the pr-claude2/reboot-before-every-test branch from 369e9a1 to f2deac4 Compare September 24, 2026 01:22
@github-actions

github-actions Bot commented Sep 24, 2026 •

Copy link
Copy Markdown

Global Size Summary (Total Flash delta in bytes)

Built from f62253f rebased onto 4a2081a

Board Periph tracker blimp bootloader copter heli iofw plane rover sub
DrotekP3Pro _ _ _ * _ _ _ _ _ _
Durandal _ * * _ * * _ * * *
Hitec-Airspeed * _ _ _ _ _ _ _ _ _
KakuteF7 _ * * _ * * _ * * *
MambaH743v4 _ * * _ * * _ * * *
MatekF405-CAN _ _ _ * _ _ _ _ _ _
MatekF405 _ * * _ * * _ * * *
MatekH743-bdshot _ * * _ * * _ * * *
Pixhawk1-1M _ * * _ * * _ * * *
disco _ * * _ * * _ * * *
f103-GPS * _ _ _ _ _ _ _ _ _

@AP-Review

AP-Review commented Sep 24, 2026 •

Copy link
Copy Markdown

Deprecated — see below for the updated review.

Previous review (2026-09-24)

Automated review note — AI-generated (Claude), validated against the live diff. Please sanity-check before acting.

Re-reviewed at head f2deac432a; my earlier comment above is superseded. COMMENT — no blockers, and it is still a draft. Full report: https://uav.tridgell.net/DevCallReviews/2026_09_24_AIReview/devcall_pr_reviews.html#pr34417

Both new commits are direct answers to last round's two new findings, and the rewritten PR body now carries measured cost figures. One of the three teardown reboot paths was missed, and it happens to be the most common one — on the measurement below it accounts for about two thirds of the feature's direct cost.

Re-raised, now measured

Tools/autotest/vehicle_test_suite.py:7389 — context_pop()'s implicit reboot does not mark the SITL fresh.

48e8032fa6 marks the two explicit teardown reboots (:10176 and :10186) but not context_pop()'s elif dead.context_pop_requires_reboot: self.reboot_sitl(mark_context=False). The teardown calls context_pop() after the = False at :10122, so every test whose context was marked reboot-requiring reboots in the teardown and then the next test reboots again immediately.

From this head's sitltest-copter-tests1e job log: 69 test banners, 59 "Doing implicit context-pop reboot", 51 "Rebooting before test". Counting strictly the pattern CTXPOP, <next test banner>, PRE gives 34 of the 51 pre-test reboots (67%) redundant — about 7.0 s of the job's 10.46 s of direct reboot cost. Nothing runs against the vehicle between :7389 and the next test's reboot point (after context_pop the teardown only reads and clears the mission), so marking there is exactly as safe as the two paths you already mark.

Cheapest fix, and it subsumes all three assignments: set self.sitl_is_freshly_started = True at the end of reboot_sitl() itself. An in-test reboot is then cleared by the existing :10122.

Notes

  • vehicle_test_suite.py:10098 (unconfirmed) — reboot_sitl_before_test() is inside the try, so a 10 s AutoTestTimeoutException sets passed=False; the teardown then reaches the unguarded self.reboot_sitl() at :10185. If that second reboot also raises, the exception escapes run_tests (which catches only pexpect.TIMEOUT) and autotest.py:770 fails the entire step, so every remaining test in that vehicle's list never runs. Pre-existing shape, but this PR roughly triples reboots per step so it raises the exposure. Not observed. Guarding reboot_sitl_before_test() and falling back to reset_SITL_commandline() would contain it.
  • The red sitltest-copter-tests1e is not yours. ModeZigZag failed on a wait_and_maintain sampling miss: samples read Distance=0.08, 1.38, then a 0.219 s gap, then 13.93, against an acceptance band of [8, 12]. On the master run at this PR's own merge-base the same call reads 0.08, 1.38, 3.89, 7.22 -> attained 8.002 — it attains on the first in-band sample with the previous at 7.22, i.e. the band is barely one sample wide. ModeZigZag did get its pre-test reboot and the preceding test passed, so neither new commit is on its path. Worth a re-run; a real fix belongs in ModeZigZag.
  • Do not read the raw step-duration A/B as this PR's cost. CopterTests1e is 619.9 s here against 371.9 s on the merge-base run (+66%), but the jobs ran on different runner CPUs. Measured host-independently from 36 paired delay_sim_time calls of >=1 s (each consumes a fixed number of sim seconds), the median PR/master wall ratio is 1.854 (p25 1.792, p75 1.930), flat across the run (1.879 / 1.898 / 1.802 by third) — so essentially all of the +66% is the runner.
  • An independent measurement corroborates your 0.50 s/test. Host-normalised into sim seconds: 51 pre-test reboots over 69 tests (18 skipped), 10.46 s total, mean 0.205 s; 111 identical wait_ready_to_arm calls cost 429.8 vs 307.9 sim seconds, i.e. +1.10 sim s per call. Converted to master's host that is about +26 s on a 371.9 s step, roughly +7%, about +0.39 s per test. The percentage is higher than your +2.8% purely because tests1e's mean test is 5.5 s against tests2b's ~18 s — the "hardest on suites of short tests" effect your body already describes. Good to about +/-5%.
  • Style: libraries/AP_Logger/AP_Logger.cpp:205 is a 167-character single-line comment sitting immediately above the // @Param: block, so it reads as part of the metadata. Two lines would not.

Checked and clean

The sitl_is_freshly_started producer/consumer set is complete (7 references; every vehicle-SITL start goes through self.start_SITL(), and arducopter.py:22592's direct util.start_SITL is a peripheral and correctly unmarked; the start_SITL(wipe=False) paths inside context_pop run after :10122 so their mark survives). Every new wait is wall-clock-correct — detect_and_handle_reboot's 10 s and its inner get_parameter(timeout=0.1) both pass timeout_in_wallclock=True, as does do_timesync_roundtrip. Parameters survive the reboot (set_parameter is PARAM_SET -> set_and_save, and the SITL re-exec strips -w). The Tracker branch is harmless: antennatracker.py:100 disarms first and GCS_Common.cpp:5305 accepts a disarm of an already-disarmed vehicle. MAX_LOG_FILES = 5000 is bounds-safe — AP_Int16 holds it, get_max_num_logs() constrains to [2, 5000], and every loop bounded by it in AP_Logger_File.cpp is O(files present). flake8 clean; commit split is five autotest: and one AP_Logger:.

No SITL or autotest was run locally for this PR — all measurements come from GitHub job logs (this head's tests1e and the master run at this PR's merge-base), one run per side, so per-test timings carry the usual single-run risk. The sim-second figures are host-normalised; the wall figures are not. The Codex cross-check could not reproduce the log-derived counts because its sandbox has no network to fetch the logs; that is a limit of the check, not a refutation.

@peterbarker
peterbarker force-pushed the pr-claude2/reboot-before-every-test branch from f2deac4 to dc68c36 Compare September 24, 2026 04:26
@peterbarker
peterbarker marked this pull request as ready for review September 24, 2026 05:45
@AP-Review

AP-Review commented Sep 24, 2026 •

Copy link
Copy Markdown

Deprecated — see below for the updated review.

Previous review (2026-09-24)

Automated review note — AI-generated (Claude), cross-checked by an independent Codex pass against the live diff. Please sanity-check before acting.
Verdict: COMMENT

Re-reviewed at head dc68c3649e (previously f2deac432a) — my earlier comment above is superseded.

Full report: https://uav.tridgell.net/DevCallReviews/followups/2026_09_24_1756/devcall_pr_reviews.html#pr34417

Verdict: COMMENT (unchanged). No blockers. Both actionable items from last round are fixed — and on the headline one you took the cheaper fix I suggested rather than a narrower one, which subsumes all three teardown paths instead of patching them individually. The PR is also out of draft now, and the red sitltest-copter-tests1e from last round is gone: 104/104 pass.

Resolved

  • context_pop()'s implicit reboot now marks the SITL fresh. 16adfe9f9c drops the two explicit teardown assignments and sets self.sitl_is_freshly_started = True at the end of reboot_sitl() (Tools/autotest/vehicle_test_suite.py:2632), with the in-test reboot cleared by :10127. I enumerated every reboot-ish call after :10127 in run_one_test_attempt — :10154, :10239 (via context_pop), :10176, :10185, :10213, :10254 (via reset_SITL_commandline), :10180, :10189 — and all are covered. The Codex pass audited the same list independently and specifically hunted the dangerous converse, a path where marking is wrong and a test would now skip a reboot it needs; it found none.

    Proved by mutation (Copter SITL from this head, --speedup=10, 6 tests): parent → 9 reboots / 0 pre-test; this head → 12 / 3; this head with :2632 neutered → 14 / 5. Neutering the one new line brings back a redundant pre-test reboot for exactly the two tests that follow a teardown context-pop reboot. Your updated body's 20-of-69 figure for tests1e is consistent with that, against the 51 I measured at the previous head.

  • The 167-character comment above the // @Param: block is now three lines (libraries/AP_Logger/AP_Logger.cpp:205-207).

Still open — re-raised, not new (unconfirmed, not observed)

  • vehicle_test_suite.py:10103 — reboot_sitl_before_test() is inside the try. A timeout there sets passed=False; if wait_heartbeat() at :10143 succeeds, :10182's elif ardupilot_alive and not passed reaches the unguarded self.reboot_sitl() at :10189. If that raises too, the exception escapes run_tests (which catches only pexpect.TIMEOUT, :14112) and reaches autotest.py:770, failing the whole step and abandoning every remaining test for that vehicle. Both passes confirmed the escape path and the line numbers; neither forced a reboot timeout to observe it.
    Exposure is lower than I said last round — with 16adfe9f9c the feature adds about 0.3 reboots per test on tests1e, not "roughly triples". Still worth guarding it and falling back to reset_SITL_commandline().

New

  • LOW — libraries/AP_Logger/AP_Logger_File.cpp:705: the 5000 cap makes an already-wrapped logs/ report 5000 logs, 4500 of them phantom. get_num_logs() computes ret += (get_max_num_logs() - smallest_above_last) + 1, i.e. it assumes the numbering wrapped at the current cap — and 8fce0f8206 changes that cap under directories written with the old one. Probe against real SITL from this head (00000001..00000500.BIN + LASTLOG.TXT=300, LOG_REQUEST_LIST(0, 0xffff)):

    case LOG_MAX_FILES reported num_logs zero-size entries
    A — wrapped dir 5000 (new default) 5000 4500
    B — same dir 500 (pre-PR) 500 0
    C — non-wrapped dir 5000 500 0

    B isolates the cause to the new default; C shows it is harmless on a clean directory. Codex reproduced all three rows by modelling the source independently and added that the impact reaches log-download ID mapping and requests, not just the listing. It needs a SITL logs/ that already wrapped under the 500 cap, CI directories are fresh, and it self-heals once the log number passes 500 — so low, but worth a line in the commit message.

  • NIT — vehicle_test_suite.py:4311: a sibling listing still goes to STATUSTEXT. fabce0186d fixed log_list() (:4816), but self.progress("Directory contents: %s" % str(new_log_list)) in TestLogDownload does the same thing. Exactly 500 standard filenames come to 10,520 bytes, under the 12,800 limit, so no longer a crash thanks to d87b91d5ac — but it is the noise fabce0186d set out to remove, dumped into the log the test then downloads.

Dropped as a false positive

I had a nit about AP_Logger.cpp:211 documenting @Range: 2 500 against a SITL default of 5000. The cross-check refuted it and I agree: you document the reason at :205-207, and param_parse.py validates Range only against Values, never against the C default — running it returns rc=0 with no warnings. Not actionable; ignore it.

Checked clean: d87b91d5ac's guard is exact — chunk_seq is uint8_t, and without the guard a 105,010-byte payload raises struct.error on the 257th chunk; with it, 12750→255 chunks, 12800→256/0 dropped, 12801→256/1 dropped, no off-by-one either way (both passes ran the extracted sender). Truncation is safe because handle_statustext logs each chunk immediately with no reassembly buffer. The 5000 bound is safe end to end — AP_Int16 holds it, get_max_num_logs() clamps to [2, MAX], every bounded loop is O(files present) or advances a counter, and no array is sized by it (checked by both passes). Real boards untouched, so zero flash cost. 29 active log_list() call sites, all using the return value. flake8 rc=0; commit split is one AP_Logger: plus five autotest:. Not verified: your A/B timing table (my sample was 6 tests on a busy machine — only the host-independent reboot counts were reproduced), and the :10103 cascade remains unobserved.

@peterbarker
peterbarker force-pushed the pr-claude2/reboot-before-every-test branch from dc68c36 to 3f5d98f Compare September 28, 2026 05:57
@AP-Review

AP-Review commented Sep 28, 2026 •

Copy link
Copy Markdown

Deprecated — see below for the updated review.

Previous review (2026-09-28)

Automated review note — AI-generated (Claude), validated against the live diff (Claude + Codex cross-checked). Please sanity-check before acting.
Verdict: ACCEPT

Re-reviewed at head 3f5d98f250 (you were last told dc68c3649e); my earlier comment above is superseded. Full report: https://firmware.ardupilot.org/Tools/APReview/DevCallReviews/followups/2026_09_28_1802/devcall_pr_reviews.html#pr34417

All 3 actionable findings from my previous comment are resolved, and I found nothing new. CI is 104/104 green.

Previous finding Status How
Unguarded post-test reboot could escape run_tests and abandon the step Resolved reboot_sitl_or_reset() (Tools/autotest/vehicle_test_suite.py:2634) falls back to reset_SITL_commandline(). Both sites use it: :10199 (armed at end) and :10208 (failed but alive).
LOW: wrapped logs/ reports 5000 logs, 4500 phantom Resolved (documented) The caveat is now in the AP_Logger: allow 5000 log files in SITL commit message, which is what I asked for.
NIT: TestLogDownload listing still sent to STATUSTEXT Resolved send_statustext=False at :4329-4330, folded into the log_list() commit.

How the guard was checked: I ran a 3-test Copter SITL step at this head (GetCapabilities, SetModesViaModeSwitch, ParameterChecks), using scratch fault injection that I reverted afterwards. SetModesViaModeSwitch was made to fail, and the post-test reboot to raise AutoTestTimeoutException:

  • With your change, on both the failed-but-alive branch and the armed-at-end branch: the log shows "Reboot after failed test did not complete ... resetting SITL". The failing test is reported FAILED and ParameterChecks still runs and passes.
  • With the helper cut back to a bare reboot_sitl(), the exception escapes. The step ends with FAILED STEP, ParameterChecks never runs, and the failing test's own result is lost too. So the guard is what keeps the step alive.

The fresh-SITL flag behaves as intended. The first test in the step skips the pre-test reboot. After a teardown reboot or a fallback reset, the next test also skips it. After a passing test, the next test reboots.

The fallback's own reset_SITL_commandline() is still unguarded, like the existing reset branches. I think that's right: if SITL can't be restarted there is nothing left to recover.

Commit split is 1 × AP_Logger: + 6 × autotest:. flake8 is clean.

Each test now starts from a fresh boot, so nothing a test leaves in the
vehicle's RAM - its position, EKF state, home, mission progress, learned
values - reaches the next one.  SITL's reboot is an execv of the same
command line, so the simulator restarts at the startup location too;
storage (parameters, missions, fence) lives in files and survives, which
is what the teardown's clears and the parameter-leak check are for.

The suite has been paying for this isolation in ones and twos for years:
tests which reboot in their first few lines because they cannot trust
what came before, tests which fail only when a particular neighbour runs
first, and the teardown's growing list of things to put back.  A whole
class of them - "test A passes alone and fails after test B" - cannot
occur once every test boots its own vehicle.

A SITL which has only just been started is not rebooted: nothing has run
against it yet, so a single-test run costs exactly what it did before.

The fresh mark is cleared as soon as the test function returns, so a test
which restarts SITL part way through (as every mid-test reboot does under
--valgrind) does not let the next test skip its reboot; a restart by the
teardown still marks it fresh.
An autotest suite step creates a log for most tests and now reboots before
each one, so a single step can create more than 500 logs.  Past 500 the log
number wraps to 1, and the harness, which takes the highest-numbered log as
the current one, then reads a stale log: CopterTests2b's
CompassLearnCopyFromEKFAffinity failed that way.

Raise the cap, and with it the LOG_MAX_FILES default, to 5000 for SITL only.

Real vehicles keep the 500 limit, so LOG_MAX_FILES' documented range stays
at 500, with a comment saying why SITL differs and that values above 500 are
still in testing; the description no longer states the cap.

Note that get_num_logs() assumes a wrapped directory wrapped at the cap in
force now - it adds (LOG_MAX_FILES - smallest_above_last) + 1 - so a logs/
which wrapped under the old 500 is counted against the new one: a directory
holding 00000001..00000500 with LASTLOG.TXT at 300 reports 5000 logs, 4500
of them phantom.  That needs a logs/ which has already wrapped, so CI's
fresh directories are unaffected, and it comes right once the log number
passes 500.  Left alone here rather than widening this commit.
progress() echoes every message to the vehicle as STATUSTEXT, in 50-byte
chunks numbered by the uint8 chunk_seq.  A message longer than 256 chunks
(12800 bytes) made pymavlink raise struct.error, and because progress() is
also called from the harness's exception handling, the error escaped the
test and failed the whole step.

log_list() prints every log name, so a suite step with more than about 600
logs hit this: CopterTests2b's EKF3SRCPerCore took the rest of the step
down once SITL was allowed more than 500 logs.

Send at most 256 chunks; the full text has already been printed locally.
log_list() prints the name of every log in logs/ on one line, and
progress() also sends each line to the vehicle as STATUSTEXT.  With several
hundred logs that is well over two hundred STATUSTEXT chunks per call, each
written into the dataflash log the caller is about to read; with enough logs
it overflowed chunk_seq, and because print_exception_caught() lists the logs
too, any test failure was then reported as that struct.error instead of its
real cause.

Print the listing locally only.  send_statustext()'s 256-chunk limit stays
as the backstop.
The teardown reboots SITL after a test which failed or ended armed.  That
leaves exactly what the pre-test reboot is for - a vehicle which has run
nothing since it booted - but only the reset path said so, via start_SITL(),
so the next test rebooted a second time for nothing.
SITL reboots with execv, which replaces the vehicle process and nothing
else, so simulated peripherals started alongside it survive with their RAM
intact - CANGPSCopterMission reboots that way and restarts its peripheral
itself.
run_one_test_attempt() reboots the vehicle after a test which failed, or
which finished still armed.  Both calls were unguarded, and neither is
inside the method's try: an exception there leaves run_one_test_attempt(),
and run_tests() catches only pexpect.TIMEOUT, so it reaches autotest.py
and fails the step - abandoning every test the vehicle had left to run.
The reboot is tidying up after a test which has already failed, so it is
exactly the place least able to afford taking the rest of the suite with
it.

Fall back to reset_SITL_commandline(), which the neighbouring branches
already use when the vehicle is too sick to reboot.

Not observed in a run; found by reading the failure paths.
@tridge
tridge force-pushed the pr-claude2/reboot-before-every-test branch from 3f5d98f to f62253f Compare October 17, 2026 03:27
@AP-Review

Copy link
Copy Markdown

Automated review note — AI-generated (Claude+Codex), validated against the live diff. Please sanity-check before acting.
Verdict: ACCEPT

Reviewed at head f62253f884.
Full report: https://firmware.ardupilot.org/Tools/APReview/DevCallReviews/PRReviews/ardupilot/ardupilot/34417/1.html#pr34417

This head (f62253f) is a pure rebase of 3f5d98f, which I reviewed last time: git range-diff shows all seven patches identical. Nothing new turned up. The earlier fixes are still in place; only their line numbers moved. reboot_sitl_or_reset() is now at Tools/autotest/vehicle_test_suite.py:2635, called from :10215 and :10224. A Copter SITL run at this head with an injected reboot timeout on the failed-but-alive branch still falls back to a reset, reports the failing test, and goes on to pass the next test. The armed-at-end branch was not re-run in SITL this round. Its patch is unchanged, and an extracted-method probe covers it. Unlike last time, CI is not finished at this head: 103 pass, 7 pending (including five copter SITL jobs), 0 failing. Those pending jobs are worth a glance before merge.

@peterbarker
peterbarker merged commit da512d0 into ArduPilot:master Oct 17, 2026
110 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants