UAV-develop/PX4-Autopilot
1
0
Fork 0
mirror of https://github.com/PX4/PX4-Autopilot.git synced 2026-07-24 15:27:41 +08:00
Code Issues Packages Projects Releases Wiki Activity

fix(bench): reuse shell sessions and confirm prompts to stop leaking nsh tasks

Browse Source 
A hardware run exhausted the board's task/fd table after a few probe
cycles: shell open failed while heartbeat still worked, and continued
writes eventually stalled the link. Not a firmware hang, a resource leak
the tooling drove.

The firmware spawns a new nsh task plus two pipes (four fds) on the
first SERIAL_CONTROL write of a session (Mavlink::get_shell) and only
frees them when a SERIAL_CONTROL message arrives with the RESPOND flag
cleared (Mavlink::close_shell). Two tooling bugs combined to leak them:

- MavlinkShell.open() returned True on any buffered byte, including
  leftover output from a prior session, so it reported a live shell
  without one. It now confirms an actual 'nsh>' prompt or a completed
  echo-sentinel round-trip before returning True, keeping the same
  timeout-and-report-failure behavior.
- open/close cycles reopened before the single flags=0 teardown was
  processed, spawning a second shell before the first was freed. close()
  now sends the flags=0 teardown and then briefly drains incoming
  SERIAL_CONTROL until quiet (bounded, never a hang) so the firmware
  runs close_shell before a caller can reopen.

Lifecycle: every MavlinkShell user now opens one session, runs all its
work on it, and closes it in a finally so no error path leaks a shell.
The SIH flight and storage tests run all their probes on a single shell
(shell_command_exists already takes an open shell); flight_mission no
longer opens a throwaway probe shell separate from the flight session
beyond the unavoidable reboot boundary in enter_sih.

Folds in the sentinel fix (run() sends the echo sentinels on their own
input line, because nsh aborts a ';' chain when a command fails, which
previously lost the sentinel for a failing probe and read as a stall).

Signed-off-by: Ramon Roche <mrpollo@gmail.com>
This commit is contained in:
Ramon Roche
2026-07-07 15:36:25 -07:00
parent 83f68f709c
commit 6e2ef3345f
10 changed files with 187 additions and 89 deletions
Download Patch File Download Diff File Expand all files Collapse all files

14
Tools/bench_test/bench/boot_health.py
View File

@@ -151,6 +151,16 @@ def run_capture(args, report):
return report_dir
report.ok('shell open', 'nsh responded')
try:
_capture(report, shell, report_dir, require_wq)
finally:
shell.close()
mav.close()
return report_dir
def _capture(report, shell, report_dir, require_wq):
"""Run the capture commands and evaluate them on an open shell."""
outputs = {}
for cmd, timeout in CAPTURE_COMMANDS:
output, timed_out = shell.run(cmd, timeout=timeout)
@@ -189,10 +199,6 @@ def run_capture(args, report):
n = px4bench.count_mavlink_instances(outputs['mavlink status'])
report.info('mavlink instances: {}'.format(n))
shell.close()
mav.close()
return report_dir
def read_saved(report_dir, cmd):
"""Read a previously saved command output from a report dir, or ''."""

47
Tools/bench_test/bench/link_forwarding.py
View File

@@ -216,27 +216,28 @@ def phase3_nested_hammer(report, mav1, mav2, global_deadline):
hard_deadline = min(time.monotonic() + PARAM_HARD_CAP + 15.0, global_deadline)
next_status = 0.0
shell_runs = 0
while downloader.is_alive():
now = time.monotonic()
if now > hard_deadline:
break
# keep link1 pumping so the autopilot keeps streaming to us
mav1.recv_match(blocking=True, timeout=0.1)
if now >= next_status:
_, timed_out = shell.run('mavlink status', timeout=SHELL_RUN_TIMEOUT)
if timed_out:
report.fail('phase3_shell_stall',
'shell over link1 stalled during param download on link2 '
'(param {}/{})'.format(downloader.received, downloader.expected))
shell.close()
return False
shell_runs += 1
next_status = now + SHELL_STATUS_INTERVAL
try:
while downloader.is_alive():
now = time.monotonic()
if now > hard_deadline:
break
# keep link1 pumping so the autopilot keeps streaming to us
mav1.recv_match(blocking=True, timeout=0.1)
if now >= next_status:
_, timed_out = shell.run('mavlink status', timeout=SHELL_RUN_TIMEOUT)
if timed_out:
report.fail('phase3_shell_stall',
'shell over link1 stalled during param download on link2 '
'(param {}/{})'.format(downloader.received, downloader.expected))
return False
shell_runs += 1
next_status = now + SHELL_STATUS_INTERVAL
# Join the worker with a hard deadline. A thread stuck past the deadline is
# itself the finding; it is a daemon so the script can still exit.
downloader.join(timeout=max(0.1, hard_deadline - time.monotonic()) + 2.0)
shell.close()
# Join the worker with a hard deadline. A thread stuck past the deadline
# is itself the finding; it is a daemon so the script can still exit.
downloader.join(timeout=max(0.1, hard_deadline - time.monotonic()) + 2.0)
finally:
shell.close()
if downloader.is_alive():
report.fail('phase3_param_stall',
@@ -283,8 +284,10 @@ def phase4_post_liveness(report, mav1, mav2, global_deadline):
if not shell.open(timeout=5):
report.fail('phase4_shell_open', 'nsh shell over link1 did not respond after stress')
return False
out, timed_out = shell.run('mavlink status', timeout=SHELL_RUN_TIMEOUT)
shell.close()
try:
out, timed_out = shell.run('mavlink status', timeout=SHELL_RUN_TIMEOUT)
finally:
shell.close()
if timed_out:
report.fail('phase4_shell_stall', '`mavlink status` over link1 stalled after stress')
return False

14
Tools/bench_test/bench/log_transfer.py
View File

@@ -47,6 +47,7 @@ def main():
report = Reporter('log_transfer')
mav = None
shell = None
try:
report.info('Connecting: {} @ {}'.format(args.connection, args.baudrate))
try:
@@ -55,6 +56,9 @@ def main():
report.fail('connect', str(e))
sys.exit(report.finish())
# One shell session for the logger commands, torn down in finally so
# no early exit leaks the firmware nsh task. The FTP phase below uses
# no shell, so the shell is closed as soon as the logging is flushed.
shell = MavlinkShell(mav)
if not shell.open(timeout=5):
report.fail('shell_open', 'nsh shell did not respond within 5s')
@@ -65,21 +69,18 @@ def main():
if timed_out:
report.fail('logger_status', '`logger status` stalled (no output in {:.0f}s)'.format(
SHELL_TIMEOUT))
shell.close()
sys.exit(report.finish())
low = out.lower()
if ('not running' in low or 'never' in low or
(low.strip() == '') or ('running' not in low and 'log' not in low)):
report.fail('logger_status',
'logger module not running (check SDLOG_MODE): {}'.format(out.strip()[:200]))
shell.close()
sys.exit(report.finish())
report.ok('logger_status', 'logger module running')
out, timed_out = shell.run('logger on', timeout=SHELL_TIMEOUT)
if timed_out:
report.fail('logger_on', '`logger on` stalled')
shell.close()
sys.exit(report.finish())
report.ok('logger_on', 'logging started')
@@ -93,10 +94,10 @@ def main():
out, timed_out = shell.run('logger off', timeout=SHELL_TIMEOUT)
if timed_out:
report.fail('logger_off', '`logger off` stalled (flush not confirmed)')
shell.close()
sys.exit(report.finish())
report.ok('logger_off', 'logging stopped and flushed')
shell.close()
shell = None
# give the filesystem a moment to settle after the flush
time.sleep(1.0)
@@ -173,6 +174,11 @@ def main():
report.fail('pyulog_parse', 'pyulog failed to parse the log: {}'.format(e))
sys.exit(report.finish())
finally:
if shell is not None:
try:
shell.close()
except Exception: # noqa: BLE001 - cleanup only
pass
if mav is not None:
try:
mav.close()

6
Tools/bench_test/bench/param_stress.py
View File

@@ -192,8 +192,10 @@ def phase_persistence(report, mav, param, conn_str, baud, original_value):
if not shell.open(timeout=5):
report.fail('persistence_shell', 'could not open nsh shell for param save')
return mav
out, timed_out = shell.run('param save', timeout=10)
shell.close()
try:
out, timed_out = shell.run('param save', timeout=10)
finally:
shell.close()
if timed_out:
report.fail('persistence_save',
"'param save' did not complete within 10s (stalled)")

6
Tools/bench_test/bench/reboot_loop.py
View File

@@ -73,8 +73,10 @@ def main():
report.info('aborting remaining {} cycle(s)'.format(args.iterations - i))
sys.exit(report.finish())
_, timed_out = shell.run('free', timeout=10)
shell.close()
try:
_, timed_out = shell.run('free', timeout=10)
finally:
shell.close()
if timed_out:
report.fail('cycle {}'.format(i),
'shell command free stalled (no completion within 10s)')

42
Tools/bench_test/bench/storage_stress.py
View File

@@ -164,18 +164,37 @@ def main():
except OSError:
pass
# probe both commands; '-x' is an unknown flag, so an existing command
# replies with its usage text while a missing one replies not-found
bench_present, _ = px4bench.shell_command_exists(shell, 'sd_bench -x')
stress_present, _ = px4bench.shell_command_exists(shell, 'sd_stress -x')
# One shell session for both probes and both phases, torn down in finally
# so no path leaks the firmware nsh task.
ran_any = False
no_sd = False
try:
# probe both commands; '-x' is an unknown flag, so an existing command
# replies with its usage text while a missing one replies not-found
bench_present, _ = px4bench.shell_command_exists(shell, 'sd_bench -x')
stress_present, _ = px4bench.shell_command_exists(shell, 'sd_stress -x')
if bench_present is None or stress_present is None:
report.fail('probe', 'command probe stalled over the shell')
if bench_present is None or stress_present is None:
report.fail('probe', 'command probe stalled over the shell')
sys.exit(report.finish())
ran_any, no_sd = run_phases(report, shell, args, save,
bench_present, stress_present)
finally:
shell.close()
mav.close()
sys.exit(report.finish())
if not ran_any and report.num_failed == 0:
print('storage_stress: skipped (no usable storage commands or no SD '
'card); this is a warning, not a failure.', flush=True)
sys.exit(px4bench.EXIT_SKIP)
sys.exit(report.finish())
def run_phases(report, shell, args, save, bench_present, stress_present):
"""Run the sd_bench and sd_stress phases. Returns (ran_any, no_sd)."""
ran_any = False
no_sd = False
if bench_present:
cmd = 'sd_bench -r {} -d {} -b {} -v'.format(
@@ -240,14 +259,7 @@ def main():
'found); stress phase skipped. Enable '
'CONFIG_SYSTEMCMDS_SD_STRESS=y')
shell.close()
mav.close()
if not ran_any and report.num_failed == 0:
print('storage_stress: skipped (no usable storage commands or no SD '
'card); this is a warning, not a failure.', flush=True)
sys.exit(px4bench.EXIT_SKIP)
sys.exit(report.finish())
return ran_any, no_sd
if __name__ == '__main__':

32
Tools/bench_test/bench/usb_replug.py
View File

@@ -139,10 +139,11 @@ def main():
shell.close()
mav.close()
sys.exit(report.finish())
baseline = read_baseline(shell, report)
shell.close()
mav.close()
try:
baseline = read_baseline(shell, report)
finally:
shell.close()
mav.close()
if baseline is None:
sys.exit(report.finish())
@@ -200,13 +201,21 @@ def main():
mav.close()
continue
# instance count must not grow (a leak means instances pile up on replug)
ms_out, timed_out = shell.run('mavlink status', timeout=10)
if timed_out:
report.fail('cycle {}'.format(i),
'shell command mavlink status stalled (no completion within 10s)')
# One shell session per cycle, torn down in finally so the leak this
# test hunts is not one the test itself introduces.
try:
# instance count must not grow (a leak piles up instances on replug)
ms_out, ms_timed_out = shell.run('mavlink status', timeout=10)
free_out, free_timed_out = (None, False)
if not ms_timed_out:
free_out, free_timed_out = shell.run('free', timeout=10)
finally:
shell.close()
mav.close()
if ms_timed_out:
report.fail('cycle {}'.format(i),
'shell command mavlink status stalled (no completion within 10s)')
continue
instances = px4bench.count_mavlink_instances(ms_out)
report.check('cycle {} instances'.format(i),
@@ -214,10 +223,7 @@ def main():
'instances={} (baseline={})'.format(instances, baseline['instances']))
# free used must not exceed baseline + tolerance * cycle_index (steady growth = leak)
free_out, timed_out = shell.run('free', timeout=10)
shell.close()
mav.close()
if timed_out:
if free_timed_out:
report.fail('cycle {}'.format(i),
'shell command free stalled (no completion within 10s)')
continue

61
Tools/bench_test/px4bench/__init__.py
View File

@@ -255,12 +255,30 @@ class MavlinkShell:
self.buf += ''.join(chr(x) for x in m.data[:m.count])
def open(self, timeout: float = 5):
"""Wake the shell; returns True if any shell output is seen."""
"""Wake the shell and confirm a live prompt. Returns True on success.
The firmware spawns a fresh nsh task plus two pipes on the first
SERIAL_CONTROL write of a session, so opening is not free; we must
confirm the task is actually up and reading, not just that some byte
arrived. Leftover bytes from a prior session would pass a naive
len(buf) > 0 check and report a shell that is not there.
We require either the 'nsh>' prompt token, or a completed sentinel
round-trip driven through the shell: sending 'echo <sentinel>' and
seeing that sentinel echoed back proves nsh is up and processing our
input. The sentinel round-trip also covers builds whose prompt token
differs or is suppressed.
"""
self._seq += 1
sentinel = 'BENCHOPEN{}'.format(self._seq)
self.buf = ''
self._write('\n')
self._write('echo {}\n'.format(sentinel))
deadline = time.monotonic() + timeout
while time.monotonic() < deadline:
self._pump()
if 'nsh>' in self.buf or len(self.buf) > 0:
if 'nsh>' in self.buf or re.search(
r'^{}\s*$'.format(re.escape(sentinel)), self.buf, re.MULTILINE):
self.buf = ''
return True
return False
@@ -274,8 +292,15 @@ class MavlinkShell:
self._seq += 1
sentinel = 'BENCHDONE{}'.format(self._seq)
self.buf = ''
# two echos like run_nsh_cmd.py, in case the first line is garbled
self._write('{}; echo {}; echo {}\n'.format(cmd, sentinel, sentinel))
# The sentinel echoes go on their OWN line: nsh aborts the rest of a
# ';' chain when a command fails (including 'command not found'), so
# chaining them onto the command line loses the sentinel for any
# non-zero exit and a failing command reads as a stall. nsh consumes
# input lines sequentially, so the sentinel line runs after the
# command finishes regardless of its exit status.
# Two echoes like run_nsh_cmd.py, in case the first line is garbled.
self._write('{}\n'.format(cmd))
self._write('echo {0}; echo {0}\n'.format(sentinel))
deadline = time.monotonic() + timeout
while time.monotonic() < deadline:
self._pump()
@@ -297,14 +322,38 @@ class MavlinkShell:
continue
if cmd in line and 'echo' in line:
continue
# the terminal echo of the command itself (possibly prefixed by
# the prompt and ANSI erase sequences) is not command output
bare = re.sub(r'\x1b\[[0-9;]*[A-Za-z]', '', line).replace('nsh>', '').strip()
if bare == cmd:
continue
lines.append(line)
return '\n'.join(lines).strip()
def close(self):
def close(self, drain: float = 1.0):
"""Tear down the firmware shell session and confirm teardown.
A SERIAL_CONTROL message with the RESPOND flag cleared (flags=0) is
what triggers Mavlink::close_shell() and frees the nsh task and its
two pipes. Sending it and returning immediately lets a caller reopen
before the firmware has processed the teardown, which spawns a second
shell before the first is freed: repeat that and the board's task/fd
table is exhausted (a leak we drive, not a firmware hang). So after
sending flags=0 we briefly drain incoming SERIAL_CONTROL traffic to
give the firmware time to run close_shell before the caller can
reopen. Bounded wait, never a hang.
"""
try:
self.mav.mav.serial_control_send(SERIAL_CONTROL_DEV_SHELL, 0, 0, 0, 0, [0] * 70)
except Exception:
pass
return
deadline = time.monotonic() + drain
while time.monotonic() < deadline:
m = self.mav.recv_match(type='SERIAL_CONTROL', blocking=True, timeout=0.1)
if m is None:
# a quiet window means the shell has stopped emitting; teardown
# has been processed
break
def shell_command_exists(shell, probe_cmd, timeout=10):

6
Tools/bench_test/px4bench/firmware.py
View File

@@ -109,8 +109,10 @@ def board_identity(mav, timeout=15):
shell = MavlinkShell(mav)
if not shell.open(timeout=5):
return None, 'nsh shell did not respond within 5s'
out, timed_out = shell.run('ver all', timeout=timeout)
shell.close()
try:
out, timed_out = shell.run('ver all', timeout=timeout)
finally:
shell.close()
if timed_out:
return None, "'ver all' stalled (no completion within {}s)".format(timeout)

48
Tools/bench_test/sih/flight_mission.py
View File

@@ -131,8 +131,10 @@ def save_params(report, mav, label):
if not shell.open(timeout=5):
report.fail(label, 'could not open nsh shell for param save')
return False
_, timed_out = shell.run('param save', timeout=10)
shell.close()
try:
_, timed_out = shell.run('param save', timeout=10)
finally:
shell.close()
if timed_out:
report.fail(label, "'param save' stalled")
return False
@@ -397,13 +399,18 @@ def main():
# Probe the live firmware for the SIH module before touching any config.
# nsh replies 'command not found' when the module is not in this build.
# One shell session for the probe, always torn down (a leaked shell leaks
# a firmware nsh task plus its two pipes). enter_sih() reboots the board
# below, so this session cannot be reused past the probe anyway.
probe_shell = MavlinkShell(mav)
if not probe_shell.open(timeout=5):
report.fail('sih_probe', 'nsh shell did not respond within 5s')
return report.finish()
present, probe_out = px4bench.shell_command_exists(
probe_shell, 'simulator_sih status')
probe_shell.close()
try:
present, probe_out = px4bench.shell_command_exists(
probe_shell, 'simulator_sih status')
finally:
probe_shell.close()
if present is None:
report.fail('sih_probe', "'simulator_sih status' stalled (probe hung)")
return report.finish()
@@ -434,25 +441,28 @@ def main():
px4bench.attach_viewer_tee(mav, port=args.viewer_port)
report.info('viewer tee on udp:127.0.0.1:{}'.format(args.viewer_port))
# One shell session for the whole flight, torn down in finally so an
# error path never leaks the firmware nsh task.
shell = MavlinkShell(mav)
if not shell.open(timeout=5):
report.fail('shell', 'could not open nsh shell')
return report.finish()
try:
if args.viewer:
for cmd in ('mavlink stream -d {} -s HIL_STATE_QUATERNION -r 25'
.format(args.board_dev),
'mavlink stream -d {} -s HIL_ACTUATOR_CONTROLS -r 200'
.format(args.board_dev)):
shell_cmd(report, shell, cmd, 'viewer_stream')
report.info('viewer streams on; watch with: hawkeye -udp {} -mc'
.format(args.viewer_port))
if args.viewer:
for cmd in ('mavlink stream -d {} -s HIL_STATE_QUATERNION -r 25'
.format(args.board_dev),
'mavlink stream -d {} -s HIL_ACTUATOR_CONTROLS -r 200'
.format(args.board_dev)):
shell_cmd(report, shell, cmd, 'viewer_stream')
report.info('viewer streams on; watch with: hawkeye -udp {} -mc'
.format(args.viewer_port))
ok = fly(report, mav, shell, args.alt, report_dir)
if not ok:
# Best effort: never leave a (simulated) vehicle armed.
shell.run('commander disarm -f', timeout=5)
shell.close()
ok = fly(report, mav, shell, args.alt, report_dir)
if not ok:
# Best effort: never leave a (simulated) vehicle armed.
shell.run('commander disarm -f', timeout=5)
finally:
shell.close()
# Post-flight verification starts from the ULog; always retrieve it.
download_flight_log(report, mav, report_dir)