diff --git a/Tools/bench_test/bench/boot_health.py b/Tools/bench_test/bench/boot_health.py index 075823e2165..794440ad1af 100755 --- a/Tools/bench_test/bench/boot_health.py +++ b/Tools/bench_test/bench/boot_health.py @@ -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 ''.""" diff --git a/Tools/bench_test/bench/link_forwarding.py b/Tools/bench_test/bench/link_forwarding.py index 753f227f743..63447241ce1 100755 --- a/Tools/bench_test/bench/link_forwarding.py +++ b/Tools/bench_test/bench/link_forwarding.py @@ -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 diff --git a/Tools/bench_test/bench/log_transfer.py b/Tools/bench_test/bench/log_transfer.py index c0a46c35715..4a744b2b167 100755 --- a/Tools/bench_test/bench/log_transfer.py +++ b/Tools/bench_test/bench/log_transfer.py @@ -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() diff --git a/Tools/bench_test/bench/param_stress.py b/Tools/bench_test/bench/param_stress.py index 9c4f0d9a63e..72ca08b5f9b 100755 --- a/Tools/bench_test/bench/param_stress.py +++ b/Tools/bench_test/bench/param_stress.py @@ -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)") diff --git a/Tools/bench_test/bench/reboot_loop.py b/Tools/bench_test/bench/reboot_loop.py index ddb673f30c4..a33705a3d42 100755 --- a/Tools/bench_test/bench/reboot_loop.py +++ b/Tools/bench_test/bench/reboot_loop.py @@ -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)') diff --git a/Tools/bench_test/bench/storage_stress.py b/Tools/bench_test/bench/storage_stress.py index 05caceef453..2772c6b7cee 100755 --- a/Tools/bench_test/bench/storage_stress.py +++ b/Tools/bench_test/bench/storage_stress.py @@ -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__': diff --git a/Tools/bench_test/bench/usb_replug.py b/Tools/bench_test/bench/usb_replug.py index 77aa96013b7..66616df17dc 100755 --- a/Tools/bench_test/bench/usb_replug.py +++ b/Tools/bench_test/bench/usb_replug.py @@ -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 diff --git a/Tools/bench_test/px4bench/__init__.py b/Tools/bench_test/px4bench/__init__.py index bd83010dc47..3ea8e90af0d 100644 --- a/Tools/bench_test/px4bench/__init__.py +++ b/Tools/bench_test/px4bench/__init__.py @@ -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 ' 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): diff --git a/Tools/bench_test/px4bench/firmware.py b/Tools/bench_test/px4bench/firmware.py index bd135f787ba..f582ea817b0 100644 --- a/Tools/bench_test/px4bench/firmware.py +++ b/Tools/bench_test/px4bench/firmware.py @@ -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) diff --git a/Tools/bench_test/sih/flight_mission.py b/Tools/bench_test/sih/flight_mission.py index c239b56f398..d4a153fbbad 100755 --- a/Tools/bench_test/sih/flight_mission.py +++ b/Tools/bench_test/sih/flight_mission.py @@ -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)