diff --git a/mfd_connect/sol.py b/mfd_connect/sol.py index a573e54..91afc7b 100644 --- a/mfd_connect/sol.py +++ b/mfd_connect/sol.py @@ -327,17 +327,109 @@ def _establish_connection(self, retry_count: int = 0) -> "pexpect.spawn": return sol_connection_process - def _deactivate_sol_session(self) -> None: - # clearing old session + def _deactivate_sol_session(self, retry_count: int = 2) -> None: + """ + Clear/deactivate previous SoL IPMI session before opening a new one. + + Retries graceful deactivation via ipmiutil, then falls back to killing + defunct ipmiutil process(es) if all attempts fail. + + :param retry_count: Number of graceful deactivation attempts + :raises SolException: if graceful deactivation and fallback cleanup fail + """ logger.log(level=log_levels.MODULE_DEBUG, msg="Clearing/Deactivating previous SoL IPMI session...") - process = pexpect.popen_spawn.PopenSpawn(f"{self._ipmi_tool_name} sol -d {self._ipmi_parameters}", timeout=60) + # Both patterns below signal a successful deactivation (either the session was closed, + # or there was none to close in the first place) - pexpect.expect() raises TIMEOUT/EOF + # if neither is matched, so a returned index always means success. correct_responses = [ "completed successfully", "Invalid Session Handle or Empty Buffer", ] - expect_index = process.expect(correct_responses) - if expect_index > len(correct_responses) - 1: - raise SolException(f"Fatal Error while deactivating previous SoL session! \n{process.before}") + + for attempt in range(1, retry_count + 1): + logger.log( + level=log_levels.MODULE_DEBUG, + msg=f"Attempt {attempt}/{retry_count} to deactivate previous SoL session...", + ) + try: + process = pexpect.popen_spawn.PopenSpawn( + f"{self._ipmi_tool_name} sol -d {self._ipmi_parameters}", timeout=60 + ) + process.expect(correct_responses) + except (pexpect.TIMEOUT, pexpect.EOF) as e: + logger.log( + level=log_levels.MODULE_DEBUG, + msg=f"Attempt {attempt}/{retry_count}: " + f"{self._ipmi_tool_name} did not respond as expected while deactivating SoL session: {e}", + ) + continue + + logger.log(level=log_levels.MODULE_DEBUG, msg="...Done - previous SoL session deactivated.") + return + + logger.log( + level=log_levels.MODULE_DEBUG, + msg=f"Could not gracefully deactivate SoL session after {retry_count} attempt(s). " + f"Trying to locate and kill defunct {self._ipmi_tool_name} process(es)...", + ) + self._kill_defunct_ipmiutil_processes() + + def _kill_defunct_ipmiutil_processes(self) -> None: + """ + Find and kill defunct/stopped ipmiutil process(es). + + Processes are matched by command name and only STAT='T' entries are killed. + 'T' means stopped by job control signal, while healthy ipmiutil usually + has 'S' or 'S+' (interruptible sleep, waiting for an event). + + :raises SolException: if process listing fails, no defunct process is found, + or kill operation fails + """ + try: + ps_process = pexpect.popen_spawn.PopenSpawn(f"ps aux | grep {self._ipmi_tool_name}", timeout=30) + ps_process.expect(pexpect.EOF) + ps_output = ps_process.before.decode("ASCII", errors="ignore") + except (pexpect.TIMEOUT, pexpect.EOF) as e: + raise SolException(f"Fatal Error while searching for defunct {self._ipmi_tool_name} process(es)! \n{e}") + + defunct_pids = [] + for line in ps_output.splitlines(): + columns = line.split() + if len(columns) <= 10: + continue + pid, stat, command = columns[1], columns[7], columns[10] + if command.rsplit("/", 1)[-1] != self._ipmi_tool_name: + continue + if stat.startswith("T"): + defunct_pids.append(pid) + else: + logger.log( + level=log_levels.MODULE_DEBUG, + msg=f"{self._ipmi_tool_name} process PID {pid} is in a healthy state '{stat}' " + "- leaving it running.", + ) + + if not defunct_pids: + raise SolException( + f"Fatal Error while deactivating previous SoL session! " + f"No defunct (stopped, STAT=T) {self._ipmi_tool_name} process(es) found to kill." + ) + + logger.log( + level=log_levels.MODULE_DEBUG, + msg=f"Found defunct {self._ipmi_tool_name} process(es) with PID(s): {defunct_pids}. Killing them...", + ) + for pid in defunct_pids: + logger.log(level=log_levels.MODULE_DEBUG, msg=f"Killing defunct {self._ipmi_tool_name} process, PID: {pid}") + try: + # sudo -n (non-interactive) fails immediately if a password prompt would appear, + # avoiding indefinite blocking in automation. + kill_process = pexpect.popen_spawn.PopenSpawn(f"sudo -n kill -KILL {pid}", timeout=30) + kill_process.expect(pexpect.EOF) + except (pexpect.TIMEOUT, pexpect.EOF) as e: + raise SolException(f"Fatal Error while killing defunct {self._ipmi_tool_name} process PID {pid}! \n{e}") + + logger.log(level=log_levels.MODULE_DEBUG, msg=f"...Done - defunct {self._ipmi_tool_name} process(es) killed.") @log_func_info(logger) def wait_for_string(self, string_list: List[str], expect_timeout: bool = False, timeout: int = 30) -> int: diff --git a/tests/unit/test_mfd_connect/test_sol.py b/tests/unit/test_mfd_connect/test_sol.py index 21e8c09..ddf3187 100644 --- a/tests/unit/test_mfd_connect/test_sol.py +++ b/tests/unit/test_mfd_connect/test_sol.py @@ -4,6 +4,7 @@ from subprocess import CalledProcessError from textwrap import dedent +import pexpect import pytest from mfd_typing.os_values import OSBitness, OSType, OSName from pytest import raises, fixture @@ -152,6 +153,146 @@ def test_establish_connection_retries_once(self, sol, mocker): assert spawn.call_count == 2 assert result is second_child + def test_deactivate_sol_session_success_first_attempt(self, sol, mocker): + sol._ipmi_tool_name = "ipmiutil" + sol._ipmi_parameters = "-F lan2 -U admin -P secret -N 10.10.10.10 -V 4" + child = mocker.Mock() + child.expect.return_value = 0 + popen_spawn = mocker.patch("mfd_connect.sol.pexpect.popen_spawn.PopenSpawn", return_value=child) + kill_mock = mocker.patch.object(sol, "_kill_defunct_ipmiutil_processes") + + sol._deactivate_sol_session() + + popen_spawn.assert_called_once() + kill_mock.assert_not_called() + + def test_deactivate_sol_session_retries_after_timeout_then_succeeds(self, sol, mocker): + sol._ipmi_tool_name = "ipmiutil" + sol._ipmi_parameters = "-F lan2 -U admin -P secret -N 10.10.10.10 -V 4" + first_child = mocker.Mock() + first_child.expect.side_effect = pexpect.TIMEOUT("timed out") + second_child = mocker.Mock() + second_child.expect.return_value = 0 + popen_spawn = mocker.patch( + "mfd_connect.sol.pexpect.popen_spawn.PopenSpawn", side_effect=[first_child, second_child] + ) + kill_mock = mocker.patch.object(sol, "_kill_defunct_ipmiutil_processes") + + sol._deactivate_sol_session() + + assert popen_spawn.call_count == 2 + kill_mock.assert_not_called() + + def test_deactivate_sol_session_falls_back_to_kill_after_repeated_failures(self, sol, mocker): + """Both attempts raise pexpect exceptions (defunct process) - the whole run must not crash.""" + sol._ipmi_tool_name = "ipmiutil" + sol._ipmi_parameters = "-F lan2 -U admin -P secret -N 10.10.10.10 -V 4" + first_child = mocker.Mock() + first_child.expect.side_effect = pexpect.TIMEOUT("timed out") + second_child = mocker.Mock() + second_child.expect.side_effect = pexpect.EOF("eof") + popen_spawn = mocker.patch( + "mfd_connect.sol.pexpect.popen_spawn.PopenSpawn", side_effect=[first_child, second_child] + ) + kill_mock = mocker.patch.object(sol, "_kill_defunct_ipmiutil_processes") + + sol._deactivate_sol_session() # must not raise + + assert popen_spawn.call_count == 2 + kill_mock.assert_called_once() + + def test_kill_defunct_ipmiutil_processes_kills_found_pid(self, sol, mocker): + sol._ipmi_tool_name = "ipmiutil" + ps_child = mocker.Mock() + ps_child.before = ( + b"berta 206865 0.0 0.3 9368 6700 pts/0 T 15:40 0:00 " + b"ipmiutil sol -a -F lan2 -U -P -N 10.102.20.61 -V 4\n" + b"berta 213349 0.0 0.1 6544 2392 pts/1 S+ 16:00 0:00 grep --color=auto ipmiutil\n" + ) + kill_child = mocker.Mock() + popen_spawn = mocker.patch("mfd_connect.sol.pexpect.popen_spawn.PopenSpawn", side_effect=[ps_child, kill_child]) + + sol._kill_defunct_ipmiutil_processes() + + assert popen_spawn.call_args_list[0].args[0] == "ps aux | grep ipmiutil" + assert popen_spawn.call_args_list[1].args[0] == "sudo -n kill -KILL 206865" + ps_child.expect.assert_called_once_with(pexpect.EOF) + kill_child.expect.assert_called_once_with(pexpect.EOF) + + def test_kill_defunct_ipmiutil_processes_kills_multiple_pids(self, sol, mocker): + """Mirrors real-world output: two stopped (T) ipmiutil sessions must both be killed.""" + sol._ipmi_tool_name = "ipmiutil" + ps_child = mocker.Mock() + ps_child.before = ( + b"berta 206865 0.0 0.3 9368 6700 pts/0 T 15:40 0:00 " + b"ipmiutil sol -a -F lan2 -U -P -N 10.102.20.61 -V 4\n" + b"berta 210671 0.0 0.3 9368 6644 pts/0 T 15:52 0:00 " + b"ipmiutil sol -a -F lan2 -U -P -N 10.102.20.61 -V 4\n" + b"berta 213349 0.0 0.1 6544 2392 pts/1 S+ 16:00 0:00 grep --color=auto ipmiutil\n" + ) + kill_child_1 = mocker.Mock() + kill_child_2 = mocker.Mock() + popen_spawn = mocker.patch( + "mfd_connect.sol.pexpect.popen_spawn.PopenSpawn", + side_effect=[ps_child, kill_child_1, kill_child_2], + ) + + sol._kill_defunct_ipmiutil_processes() + + assert popen_spawn.call_args_list[1].args[0] == "sudo -n kill -KILL 206865" + assert popen_spawn.call_args_list[2].args[0] == "sudo -n kill -KILL 210671" + + def test_kill_defunct_ipmiutil_processes_kills_only_stopped_ones(self, sol, mocker): + """Mix of stopped (T) and healthy (S+) processes - only the stopped one gets killed.""" + sol._ipmi_tool_name = "ipmiutil" + ps_child = mocker.Mock() + ps_child.before = ( + b"berta 206865 0.0 0.3 9368 6700 pts/0 T 15:40 0:00 " + b"ipmiutil sol -a -F lan2 -U -P -N 10.102.20.61 -V 4\n" + b"berta 220000 0.0 0.3 9368 6700 pts/0 S+ 15:41 0:00 " + b"ipmiutil sol -a -F lan2 -U -P -N 10.102.20.62 -V 4\n" + b"berta 213349 0.0 0.1 6544 2392 pts/1 S+ 16:00 0:00 grep --color=auto ipmiutil\n" + ) + kill_child = mocker.Mock() + popen_spawn = mocker.patch("mfd_connect.sol.pexpect.popen_spawn.PopenSpawn", side_effect=[ps_child, kill_child]) + + sol._kill_defunct_ipmiutil_processes() + + assert popen_spawn.call_count == 2 # ps aux + single kill (healthy one skipped) + assert popen_spawn.call_args_list[1].args[0] == "sudo -n kill -KILL 206865" + + def test_kill_defunct_ipmiutil_processes_raises_when_no_pid_found(self, sol, mocker): + sol._ipmi_tool_name = "ipmiutil" + ps_child = mocker.Mock() + ps_child.before = b"user 3333 0.0 0.1 1 1 pts/0 S+ 12:00 0:00 grep ipmiutil\n" + mocker.patch("mfd_connect.sol.pexpect.popen_spawn.PopenSpawn", return_value=ps_child) + + with pytest.raises(SolException): + sol._kill_defunct_ipmiutil_processes() + + def test_kill_defunct_ipmiutil_processes_raises_when_ps_times_out(self, sol, mocker): + sol._ipmi_tool_name = "ipmiutil" + ps_child = mocker.Mock() + ps_child.expect.side_effect = pexpect.TIMEOUT("timed out") + mocker.patch("mfd_connect.sol.pexpect.popen_spawn.PopenSpawn", return_value=ps_child) + + with pytest.raises(SolException): + sol._kill_defunct_ipmiutil_processes() + + def test_kill_defunct_ipmiutil_processes_raises_when_kill_fails(self, sol, mocker): + sol._ipmi_tool_name = "ipmiutil" + ps_child = mocker.Mock() + ps_child.before = ( + b"berta 206865 0.0 0.3 9368 6700 pts/0 T 15:40 0:00 " + b"ipmiutil sol -a -F lan2 -U -P -N 10.102.20.61 -V 4\n" + ) + kill_child = mocker.Mock() + kill_child.expect.side_effect = pexpect.TIMEOUT("timed out") + mocker.patch("mfd_connect.sol.pexpect.popen_spawn.PopenSpawn", side_effect=[ps_child, kill_child]) + + with pytest.raises(SolException): + sol._kill_defunct_ipmiutil_processes() + def test__parse_selection_regex_fallback_blue_background(self): output = "\x1b[44mSelected Boot Option"