From bf7dcb72292a0076dccbfc07abac12033649c140 Mon Sep 17 00:00:00 2001 From: Ramon Roche Date: Tue, 7 Jul 2026 16:08:51 -0700 Subject: [PATCH] fix(bench): confirm param committed and saved before reboot in persistence test The full-suite persistence check failed on hardware with 'after reboot SDLOG_UTC_OFFSET = 740 (expected 777)'. Firmware persistence is solid; this was a test race. A PARAM_SET propagates through the param system asynchronously, and phase_persistence ran 'param save' on the strength of the PARAM_VALUE echo alone. When save raced ahead of the commit it persisted the PRIOR value (740, the last value Phase 2 wrote). The echo was not even proof of the new value: wait_param_echo returned seen=[740, 777], a stale queued PARAM_VALUE from Phase 2 having slipped past drain_param_values. Make persistence deterministic with two gates instead of timing: 1. After setting the marker, read it back from the board until it reports MARKER_VALUE (read_until) before saving. This confirms the value is committed to RAM and trusts the board's read over any stale echo. 2. After 'param save', confirm the saved state with 'param show ' and require the '+' (saved) flag AND the marker value before rebooting (retry save once first). '*' means unsaved; the test never reboots on an unsaved marker. Flag columns per src/systemcmds/param/param.cpp:822 (x used, + saved, * unsaved, l locked). phase_set_readback now also trusts read_until over the echo, so the same stale-queued-echo does not fail it either; its pass criteria stay the readback match. Restores in phase_persistence and the final cleanup use read_until too. New shared helpers in px4bench.params: read_until(mav, name, expected, timeout) -> (ok, last_seen), and param_is_saved(shell, name) plus its parse_param_show() parser for the 'param show' saved flag and value. Signed-off-by: Ramon Roche --- Tools/bench_test/bench/param_stress.py | 124 ++++++++++++++++--------- Tools/bench_test/px4bench/params.py | 77 +++++++++++++++ 2 files changed, 159 insertions(+), 42 deletions(-) diff --git a/Tools/bench_test/bench/param_stress.py b/Tools/bench_test/bench/param_stress.py index 72ca08b5f9b..3ba6a00b1f4 100755 --- a/Tools/bench_test/bench/param_stress.py +++ b/Tools/bench_test/bench/param_stress.py @@ -34,8 +34,10 @@ sys.path.insert(0, os.path.dirname(os.path.dirname(os.path.abspath(__file__)))) import px4bench from px4bench.params import (READ_TIMEOUT_S, SET_ECHO_TIMEOUT_S, drain_param_values, param_float_to_int32, - param_id_str, read_param, set_param_int32, - wait_param_echo) + param_id_str, param_is_saved, read_param, + read_until, set_param_int32, wait_param_echo) + +COMMIT_TIMEOUT_S = 8.0 DEFAULT_PARAM = 'SDLOG_UTC_OFFSET' DEFAULT_ITERATIONS = 50 @@ -133,7 +135,6 @@ def phase_set_readback(report, mav, param, iterations): Individual failures are counted but the loop continues. """ report.info('Phase 2: set/readback loop, {} iterations'.format(iterations)) - echo_failures = 0 read_failures = 0 mismatch_failures = 0 @@ -143,32 +144,37 @@ def phase_set_readback(report, mav, param, iterations): drain_param_values(mav) set_param_int32(mav, param, value) matched, seen = wait_param_echo(mav, param, value, SET_ECHO_TIMEOUT_S) - if not matched: - report.fail('param_set_echo', - 'set iteration {}: no echo of {} within {}s (saw: {})'.format( - i, value, SET_ECHO_TIMEOUT_S, seen or 'nothing')) - echo_failures += 1 - # keep going: still try to read back - readback, _ = read_param(mav, param, READ_TIMEOUT_S) - if readback is None: - report.fail('param_readback', - 'set iteration {}: no PARAM_VALUE on readback'.format(i)) - read_failures += 1 - continue - if readback != value: - report.fail('param_readback', - 'set iteration {}: readback {} != set {}'.format( - i, readback, value)) - mismatch_failures += 1 + # read_param is the source of truth: a set propagates asynchronously, + # so the echo can be a stale queued PARAM_VALUE from a prior set that + # slipped past the drain. read_until confirms the board actually holds + # the new value; an echo that disagrees with a confirmed read-back is + # not counted as a failure. + confirmed, readback = read_until(mav, param, value, COMMIT_TIMEOUT_S) + if not confirmed: + if readback is None: + report.fail('param_readback', + 'set iteration {}: no PARAM_VALUE on readback'.format(i)) + read_failures += 1 + else: + report.fail('param_readback', + 'set iteration {}: readback {} != set {}'.format( + i, readback, value)) + mismatch_failures += 1 + elif not matched: + # board holds the right value but the echo never showed it; this is + # the stale-echo case, informational not a failure + report.info(' iteration {}: value confirmed by read-back; echo saw ' + '{} (stale queued echo tolerated)'.format(i, seen or 'nothing')) if (i + 1) % 10 == 0: report.info(' {}/{} iterations done'.format(i + 1, iterations)) report.check('param_set_readback_loop', - echo_failures == 0 and read_failures == 0 and mismatch_failures == 0, - '{} iterations: {} echo, {} read, {} mismatch failures'.format( - iterations, echo_failures, read_failures, mismatch_failures)) + read_failures == 0 and mismatch_failures == 0, + '{} iterations: {} read, {} mismatch failures (readback is the ' + 'source of truth; stale echoes tolerated)'.format( + iterations, read_failures, mismatch_failures)) def phase_persistence(report, mav, param, conn_str, baud, original_value): @@ -179,29 +185,61 @@ def phase_persistence(report, mav, param, conn_str, baud, original_value): """ report.info('Phase 3: persistence across reboot') + # 1. Set the marker and confirm it is actually committed to RAM by reading + # it back, not merely by matching the echo. A PARAM_SET propagates + # asynchronously; if we saved on the strength of the echo alone, save + # could race ahead of the commit and persist the PRIOR value (the last + # value Phase 2 wrote). read_until closes that gap, and it trusts the + # board's read over any stale queued echo. drain_param_values(mav) set_param_int32(mav, param, MARKER_VALUE) - matched, seen = wait_param_echo(mav, param, MARKER_VALUE, SET_ECHO_TIMEOUT_S) - if not matched: + committed, seen = read_until(mav, param, MARKER_VALUE, COMMIT_TIMEOUT_S) + if not committed: report.fail('persistence_set', - 'no echo of marker {} (saw: {})'.format(MARKER_VALUE, seen or 'nothing')) + 'marker {} not committed to RAM within {:.0f}s (read back: ' + '{})'.format(MARKER_VALUE, COMMIT_TIMEOUT_S, + seen if seen is not None else 'nothing')) return mav - # Force an explicit flush to storage before we pull the power. + # 2. Save, then confirm the SAVED state before rebooting: param show must + # report the '+' (saved) flag AND the marker value. A '*' (unsaved) or a + # wrong value means save did not persist the marker; retry once, then + # fail without rebooting on an unsaved marker. shell = px4bench.MavlinkShell(mav) if not shell.open(timeout=5): report.fail('persistence_shell', 'could not open nsh shell for param save') return mav try: - out, timed_out = shell.run('param save', timeout=10) + saved_ok = False + saved, shown = None, None + for attempt in range(2): + out, timed_out = shell.run('param save', timeout=10) + if timed_out: + report.fail('persistence_save', + "'param save' did not complete within 10s (stalled)") + return mav + report.info("'param save' output: {}".format(out.strip() or '(none)')) + saved, shown, show_timed_out = param_is_saved(shell, param) + if show_timed_out: + report.fail('persistence_save', + "'param show {}' stalled confirming the saved " + 'state'.format(param)) + return mav + if saved is True and shown == MARKER_VALUE: + saved_ok = True + break + report.info('param show reports saved={} value={} after save ' + 'attempt {}'.format(saved, shown, attempt + 1)) + if not saved_ok: + report.fail('persistence_save', + 'marker {} not confirmed saved (param show saved={} ' + 'value={}); not rebooting on an unsaved marker'.format( + MARKER_VALUE, saved, shown)) + return mav finally: shell.close() - if timed_out: - report.fail('persistence_save', - "'param save' did not complete within 10s (stalled)") - return mav - report.info("'param save' output: {}".format(out.strip() or '(none)')) + # 3. Reboot and read the marker back. try: newmav, elapsed = px4bench.reboot_and_reconnect(mav, conn_str, baud, timeout=60) except TimeoutError as e: @@ -220,13 +258,14 @@ def phase_persistence(report, mav, param, conn_str, baud, original_value): 'after reboot {} = {} (expected {})'.format( param, survived, MARKER_VALUE)) - # Restore original inside this phase too, then verify. + # Restore original inside this phase too, then verify by read-back. drain_param_values(mav) set_param_int32(mav, param, original_value) - matched, seen = wait_param_echo(mav, param, original_value, SET_ECHO_TIMEOUT_S) + restored, seen = read_until(mav, param, original_value, COMMIT_TIMEOUT_S) report.check('persistence_restore', - matched, - 'restored {} to {} (saw: {})'.format(param, original_value, seen)) + restored, + 'restored {} to {} (read back: {})'.format( + param, original_value, seen if seen is not None else 'nothing')) return mav @@ -288,12 +327,13 @@ def main(): try: drain_param_values(mav) set_param_int32(mav, args.param, original_value) - matched, seen = wait_param_echo(mav, args.param, original_value, - SET_ECHO_TIMEOUT_S) + restored, seen = read_until(mav, args.param, original_value, + COMMIT_TIMEOUT_S) report.check('final_restore', - matched, - 'restored {} to {} (saw: {})'.format( - args.param, original_value, seen)) + restored, + 'restored {} to {} (read back: {})'.format( + args.param, original_value, + seen if seen is not None else 'nothing')) except Exception as e: report.fail('final_restore', 'exception while restoring {}: {}'.format(args.param, e)) diff --git a/Tools/bench_test/px4bench/params.py b/Tools/bench_test/px4bench/params.py index bd2d80c23ad..1932182b700 100644 --- a/Tools/bench_test/px4bench/params.py +++ b/Tools/bench_test/px4bench/params.py @@ -13,6 +13,7 @@ before a set and then match the echo by expected value, never consume it positionally. """ +import re import struct import time @@ -22,6 +23,7 @@ MAV_PARAM_TYPE_INT32 = mavutil.mavlink.MAV_PARAM_TYPE_INT32 SET_ECHO_TIMEOUT_S = 5.0 READ_TIMEOUT_S = 5.0 +READ_UNTIL_TIMEOUT_S = 8.0 def int32_to_param_float(value): @@ -104,3 +106,78 @@ def wait_param_echo(mav, name, expected, timeout=SET_ECHO_TIMEOUT_S): if value == expected: return True, seen return False, seen + + +def read_until(mav, name, expected, timeout=READ_UNTIL_TIMEOUT_S): + """Poll read_param until the board reports the expected int32 value. + + A PARAM_SET propagates through the param system asynchronously, so an + echo (or even a single read) right after a set can still reflect the + prior value. Reading back in a loop until the board actually reports the + new value confirms it is committed to RAM, which closes the gap before a + save or a dependent check. This trusts the board's own read, not a queued + echo, so a stale PARAM_VALUE from an earlier set cannot satisfy it. + + Returns (ok, last_seen): ok True once the board reports expected, + otherwise False with the last value read (None if nothing read back). + """ + deadline = time.monotonic() + timeout + last_seen = None + while True: + remaining = deadline - time.monotonic() + if remaining <= 0: + return False, last_seen + value, _ = read_param(mav, name, timeout=min(READ_TIMEOUT_S, remaining)) + if value is not None: + last_seen = value + if value == expected: + return True, last_seen + else: + # brief pause so a non-responding read does not busy-spin + time.sleep(0.2) + + +# param show prints one line: +# x + l SDLOG_UTC_OFFSET [used,idx] : 777 +# three flag columns then the name; the SECOND flag is the save state: +# '*' unsaved, '+' saved, ' ' unmodified from default +# (src/systemcmds/param/param.cpp:822-823). +_PARAM_SHOW_RE = re.compile( + r'^\s*(?P[x ])\s?(?P[*+ ])\s?(?P[l ])\s+' + r'(?P[A-Z0-9_]+)\s+\[[^\]]*\]\s*:\s*(?P-?\d+)') + + +def parse_param_show(output, name): + """Parse `param show ` output for one parameter. + + Returns (saved, value) where saved is True/False/None (None when the + line is not found or the save state is 'default'/unknown) and value is + the int32 value or None. Tolerant of ANSI escapes and the prompt. + """ + for raw in output.splitlines(): + line = re.sub(r'\x1b\[[0-9;]*[A-Za-z]', '', raw).replace('nsh>', '') + m = _PARAM_SHOW_RE.search(line) + if not m or m.group('name') != name: + continue + flag = m.group('saved') + saved = True if flag == '+' else (False if flag == '*' else None) + try: + value = int(m.group('value')) + except ValueError: + value = None + return saved, value + return None, None + + +def param_is_saved(shell, name, timeout=10): + """Run `param show ` over an open MavlinkShell and report save state. + + Returns (saved, value, timed_out): saved True/False/None as parsed by + parse_param_show, value the int32 shown, timed_out True if the shell + command did not complete. Caller owns the shell (open and close it). + """ + out, timed_out = shell.run('param show {}'.format(name), timeout=timeout) + if timed_out: + return None, None, True + saved, value = parse_param_show(out, name) + return saved, value, False