From aac0d4e801feacf448ef0e0ee18e777c2fd71b09 Mon Sep 17 00:00:00 2001 From: mikecarper Date: Fri, 16 Oct 2026 00:28:56 -0700 Subject: [PATCH] Finish OTA policy cleanup when seeder log close fails --- tools/lora_ota/lora_ota.py | 38 ++++-- tools/lora_ota/test_lora_ota.py | 94 +++++++++++++ .../lora_ota/test_lora_ota_seeder_startup.py | 126 ++++++++++++++++++ 3 files changed, 246 insertions(+), 12 deletions(-) diff --git a/tools/lora_ota/lora_ota.py b/tools/lora_ota/lora_ota.py index 83b42edbe..f1685c378 100755 --- a/tools/lora_ota/lora_ota.py +++ b/tools/lora_ota/lora_ota.py @@ -3863,11 +3863,23 @@ class SeederProcess: creationflags=creationflags, ) except FileNotFoundError as exc: - self.log_file.close() + self._close_log() raise OtaError(f"required command was not found: {self.args.motatool}") from exc self._wait_until_attached() print("[seeder] running (device COUNT confirmed)") + def _close_log(self) -> None: + log_file = self.log_file + self.log_file = None + if log_file is not None and not log_file.closed: + try: + log_file.close() + except OSError as exc: + print( + f"WARNING: could not close seeder log {self.log_path}: {exc}", + file=sys.stderr, + ) + def _read_log(self) -> str: if self.log_file is not None and not self.log_file.closed: try: @@ -3998,22 +4010,24 @@ class SeederProcess: return len(set(payload_reads)), total, len(payload_reads) def stop(self) -> None: - if self.process is None: - return - if self.process.poll() is None: + process = self.process + if process is not None and process.poll() is None: try: if os.name == "nt": - self.process.terminate() + process.terminate() else: - self.process.send_signal(signal.SIGINT) - self.process.wait(timeout=10) + process.send_signal(signal.SIGINT) + process.wait(timeout=10) except (subprocess.TimeoutExpired, ProcessLookupError): - self.process.kill() - self.process.wait(timeout=5) - if self.log_file is not None and not self.log_file.closed: - self.log_file.close() + process.kill() + process.wait(timeout=5) + # Keep ownership if shutdown fails: the child may still own the source + # serial port. Once exit is confirmed, a log-close failure must not + # prevent the caller from restoring radio and RXPS policies. self.process = None - print("[seeder] stopped") + self._close_log() + if process is not None: + print("[seeder] stopped") def parse_relay(value: str, default_password: str) -> tuple[str, str]: diff --git a/tools/lora_ota/test_lora_ota.py b/tools/lora_ota/test_lora_ota.py index 1f4efb467..6c72ceb9a 100644 --- a/tools/lora_ota/test_lora_ota.py +++ b/tools/lora_ota/test_lora_ota.py @@ -1670,6 +1670,100 @@ class SourceCliTests(unittest.TestCase): self.assertEqual(result, 2) self.assertEqual(restore_source.call_count, 2) + def test_seeder_log_close_failure_does_not_skip_failure_policy_restore(self) -> None: + saved = ota.RxpsSettings(True, 18205, 20423, 8, 16) + image = firmware(b"seeder-close-failure" * 500, VERSION_NEW) + package = ota.parse_mota(mota_blob(image)) + expected_body_hash = ota.parse_endf(image).body_hash + normal = ota.RadioSettings(910.525, 62.5, 7, 5, False) + controller = mock.Mock() + controller.get_radio.return_value = normal + controller.remote_command.return_value = "OK" + cleanup = [] + + def fail_close(): + cleanup.append("close log") + raise OSError("log close failed") + + with tempfile.TemporaryDirectory() as directory: + work_dir = Path(directory) / "work" + argv = [ + "release.mota", "remote", + "--controller-serial", "/dev/controller", + "--source-serial", "/dev/source", + "--password", "secret", "--work-dir", str(work_dir), "--yes", + ] + seeder = ota.SeederProcess( + argparse.Namespace( + motatool="motatool", source_serial="/dev/source", + source_tcp=None, source_baud=115200, + ), + Path(directory), work_dir, + ) + seeder.start = mock.Mock() + seeder.process = mock.Mock() + seeder.process.poll.return_value = 0 + log_file = seeder.log_file = mock.Mock(closed=False) + log_file.close.side_effect = fail_close + error = io.StringIO() + with contextlib.ExitStack() as stack: + for name in ( + "preflight_inputs", "preflight_source_cli", + "ensure_source_clock_gate_safe", "ensure_controller_clock_safe", + "verify_shared_source_identity", "confirm_update", + "run_temp_radio_preflight", "arm_target_temp_radio", + "arm_source_temp_radio_once", "switch_controller_to_temp_radio", + "find_and_start_pull", + ): + stack.enter_context(mock.patch.object(ota, name)) + stack.enter_context(mock.patch.object(ota, "read_source_rxps", return_value=saved)) + stack.enter_context(mock.patch.object(ota, "disable_source_rxps", return_value=True)) + restore_source = stack.enter_context(mock.patch.object( + ota, "restore_source_rxps", + side_effect=lambda *args: cleanup.append("restore source RXPS"), + )) + stack.enter_context(mock.patch.object(ota, "query_target", return_value=target())) + stack.enter_context(mock.patch.object( + ota, "prepare_package", + return_value=(Path("release.mota"), package, expected_body_hash), + )) + stack.enter_context(mock.patch.object( + ota, "read_lora_ota_participant_versions", + return_value={"destination": VERSION_NEW}, + )) + stack.enter_context(mock.patch.object( + ota, "read_remote_rxps", return_value=ota.RxpsSettings(False, 0, 0), + )) + monitor = stack.enter_context(mock.patch.object( + ota, "monitor_download", side_effect=ota.OtaError("synthetic transfer failure"), + )) + shorten_source = stack.enter_context(mock.patch.object( + ota, "shorten_source_temp_window", return_value=True, + )) + stack.enter_context(mock.patch.object(ota, "SeederProcess", return_value=seeder)) + stack.enter_context(mock.patch.object(ota.time, "sleep")) + source_command = stack.enter_context(mock.patch.object( + ota, "source_cli_command", + side_effect=lambda args, command, **kwargs: cleanup.append(command) or "OK", + )) + stack.enter_context(contextlib.redirect_stdout(io.StringIO())) + stack.enter_context(contextlib.redirect_stderr(error)) + result = ota.main(argv, controller_override=controller) + + self.assertEqual(result, 2) + monitor.assert_called_once() + log_file.close.assert_called_once_with() + self.assertIsNone(seeder.process) + self.assertIsNone(seeder.log_file) + source_command.assert_called_once_with(mock.ANY, "ota folder off", check=False) + shorten_source.assert_called_once_with(mock.ANY, check=False) + controller.set_radio.assert_called_once_with(normal, "restore controller radio after failure") + restore_source.assert_called_once_with(mock.ANY, saved) + self.assertEqual(cleanup, ["close log", "ota folder off", "restore source RXPS"]) + self.assertIn("ERROR: synthetic transfer failure", error.getvalue()) + self.assertIn("WARNING: could not close seeder log", error.getvalue()) + self.assertIn("log close failed", error.getvalue()) + def test_shared_failure_cleanup_never_persists_temp_radio_tuple(self) -> None: normal = ota.RadioSettings(910.525, 62.5, 7, 5, False) controller = mock.Mock() diff --git a/tools/lora_ota/test_lora_ota_seeder_startup.py b/tools/lora_ota/test_lora_ota_seeder_startup.py index 1fce6b1a5..ad44ca739 100644 --- a/tools/lora_ota/test_lora_ota_seeder_startup.py +++ b/tools/lora_ota/test_lora_ota_seeder_startup.py @@ -4,6 +4,7 @@ import argparse import contextlib import io from pathlib import Path +import subprocess import sys import tempfile import unittest @@ -243,6 +244,130 @@ class SeederStartupTests(unittest.TestCase): self.assertIn("child diagnostic", str(failure.exception)) +class SeederStopTests(unittest.TestCase): + def seeder(self, return_code=0): + args = argparse.Namespace( + motatool="motatool", source_serial="/dev/source", + source_tcp=None, source_baud=115200, + ) + seeder = ota.SeederProcess(args, Path("/served"), Path("/work")) + seeder.process = mock.Mock() + seeder.process.poll.return_value = return_code + seeder.log_file = mock.Mock(closed=False) + return seeder + + def test_log_close_failure_warns_once_and_allows_later_cleanup(self): + seeder = self.seeder() + process, log_file = seeder.process, seeder.log_file + log_file.close.side_effect = OSError("log close failed") + output, error = io.StringIO(), io.StringIO() + restored = [] + with contextlib.redirect_stdout(output), contextlib.redirect_stderr(error): + seeder.stop() + restored.append("policy restored") + seeder.stop() + self.assertEqual(restored, ["policy restored"]) + self.assertIsNone(seeder.process) + self.assertIsNone(seeder.log_file) + process.send_signal.assert_not_called() + process.kill.assert_not_called() + log_file.close.assert_called_once_with() + self.assertEqual(output.getvalue().count("[seeder] stopped"), 1) + self.assertEqual(error.getvalue().count("WARNING:"), 1) + self.assertIn("/work/motatool-serve.log", error.getvalue()) + self.assertIn("log close failed", error.getvalue()) + + def test_running_child_is_waited_for_before_releasing_ownership(self): + seeder = self.seeder(return_code=None) + process, log_file = seeder.process, seeder.log_file + with mock.patch.object(ota.os, "name", "posix"), contextlib.redirect_stdout(io.StringIO()): + seeder.stop() + process.send_signal.assert_called_once_with(ota.signal.SIGINT) + process.wait.assert_called_once_with(timeout=10) + process.kill.assert_not_called() + log_file.close.assert_called_once_with() + self.assertIsNone(seeder.process) + self.assertIsNone(seeder.log_file) + + def test_graceful_timeout_is_followed_by_confirmed_kill(self): + seeder = self.seeder(return_code=None) + process, log_file = seeder.process, seeder.log_file + process.wait.side_effect = [subprocess.TimeoutExpired("motatool", 10), 0] + with contextlib.redirect_stdout(io.StringIO()): + seeder.stop() + process.kill.assert_called_once_with() + self.assertEqual(process.wait.call_args_list, [ + mock.call(timeout=10), mock.call(timeout=5), + ]) + log_file.close.assert_called_once_with() + self.assertIsNone(seeder.process) + self.assertIsNone(seeder.log_file) + + def test_failed_shutdown_retains_ownership_and_does_not_claim_stopped(self): + for failure in ("kill", "final wait"): + with self.subTest(failure=failure): + seeder = self.seeder(return_code=None) + process, log_file = seeder.process, seeder.log_file + process.wait.side_effect = [ + subprocess.TimeoutExpired("motatool", 10), + subprocess.TimeoutExpired("motatool", 5), + ] + expected = subprocess.TimeoutExpired + if failure == "kill": + process.kill.side_effect = OSError("kill failed") + expected = OSError + output = io.StringIO() + with contextlib.redirect_stdout(output), self.assertRaises(expected): + seeder.stop() + self.assertIs(seeder.process, process) + self.assertIs(seeder.log_file, log_file) + log_file.close.assert_not_called() + self.assertNotIn("stopped", output.getvalue()) + + def test_log_without_a_child_is_closed_and_detached(self): + for close_error in (None, OSError("log close failed")): + with self.subTest(close_error=close_error): + seeder = self.seeder() + seeder.process = None + log_file = seeder.log_file + log_file.close.side_effect = close_error + output, error = io.StringIO(), io.StringIO() + with contextlib.redirect_stdout(output), contextlib.redirect_stderr(error): + seeder.stop() + log_file.close.assert_called_once_with() + self.assertIsNone(seeder.log_file) + self.assertNotIn("stopped", output.getvalue()) + self.assertEqual(bool(error.getvalue()), close_error is not None) + + def test_already_closed_log_is_detached_without_closing_again(self): + seeder = self.seeder() + log_file = seeder.log_file + log_file.closed = True + with contextlib.redirect_stdout(io.StringIO()): + seeder.stop() + log_file.close.assert_not_called() + self.assertIsNone(seeder.process) + self.assertIsNone(seeder.log_file) + + def test_spawn_failure_retains_primary_diagnostic_if_log_close_fails(self): + seeder = self.seeder() + seeder.process = None + log_file = seeder.log_file + log_file.close.side_effect = OSError("log close failed") + error = io.StringIO() + with ( + mock.patch.object(Path, "open", return_value=log_file), + mock.patch.object(ota.subprocess, "Popen", side_effect=FileNotFoundError("missing")), + contextlib.redirect_stdout(io.StringIO()), + contextlib.redirect_stderr(error), + self.assertRaisesRegex(ota.OtaError, "required command was not found: motatool"), + ): + seeder.start() + self.assertIn("log close failed", error.getvalue()) + self.assertIsNone(seeder.process) + self.assertIsNone(seeder.log_file) + + class SeederOptionTests(unittest.TestCase): def arguments(self, chain=False, *options): parser = rak_chain.build_parser() if chain else ota.build_parser() @@ -317,6 +442,7 @@ class SeederSubprocessTests(unittest.TestCase): self.assertIn("running (device COUNT confirmed)", output.getvalue()) self.assertIn("host compression complete", output.getvalue()) self.assertIsNone(seeder.process) + self.assertIsNone(seeder.log_file) if __name__ == "__main__":