Finish OTA policy cleanup when seeder log close fails

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]:

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()

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__":