diff --git a/codecarbon/core/powermetrics.py b/codecarbon/core/powermetrics.py index bffc19ce4..8a86b753b 100644 --- a/codecarbon/core/powermetrics.py +++ b/codecarbon/core/powermetrics.py @@ -30,6 +30,26 @@ def clear_powermetrics_cache() -> None: is_powermetrics_available.cache_clear() +def _kill_process(process: subprocess.Popen) -> None: + """ + Kill a Powermetrics subprocess, tolerating a failure to do so. + + The command runs through `sudo`, so the child may be owned by root and + refuse our signal. Letting that raise would replace the timeout we are + handling with a PermissionError, and waiting on it without a bound would + hang for as long as the child lives. + """ + try: + process.kill() + process.wait(timeout=1) + except (OSError, subprocess.SubprocessError): + logger.debug("Could not kill the Powermetrics process.") + finally: + for stream in (process.stdout, process.stderr): + if stream is not None: + stream.close() + + def _has_powermetrics_sudo() -> bool: if shutil.which("sudo") is None: logger.debug("sudo not available, we won't use Apple PowerMetrics.") @@ -40,7 +60,9 @@ def _has_powermetrics_sudo() -> bool: ) return False - with subprocess.Popen( + # No context manager here: Popen.__exit__ would wait() without a timeout, + # which is exactly the hang we are trying to avoid when the kill fails. + process = subprocess.Popen( [ "sudo", "powermetrics", @@ -53,30 +75,31 @@ def _has_powermetrics_sudo() -> bool: "-o", "/dev/null", ], + stdin=subprocess.DEVNULL, stdout=subprocess.PIPE, stderr=subprocess.PIPE, text=True, - ) as process: - deadline = time.time() + 3 - while process.poll() is None and time.time() < deadline: - time.sleep(0.05) - if process.poll() is None: - process.kill() - logger.debug("PowerMetrics sudo check timed out.") - return False - _, stderr = process.communicate() - - if re.search(r"[sudo].*password", stderr): - logger.debug("""Not using PowerMetrics, sudo password prompt detected. - If you want to enable Powermetrics please modify your sudoers file - as described in : - https://docs.codecarbon.io/latest/explanation/methodology/#power-usage - """) - return False - if process.returncode != 0: - raise Exception("Return code != 0") + ) + deadline = time.time() + 3 + while process.poll() is None and time.time() < deadline: + time.sleep(0.05) + if process.poll() is None: + logger.debug("PowerMetrics sudo check timed out.") + _kill_process(process) + return False + _, stderr = process.communicate() - return True + if re.search(r"[sudo].*password", stderr): + logger.debug("""Not using PowerMetrics, sudo password prompt detected. + If you want to enable Powermetrics please modify your sudoers file + as described in : + https://docs.codecarbon.io/latest/explanation/methodology/#power-usage + """) + return False + if process.returncode != 0: + raise Exception("Return code != 0") + + return True class ApplePowermetrics: @@ -130,47 +153,69 @@ def _setup_cli(self) -> None: else: raise SystemError("Platform not supported by Powermetrics") - def _log_values(self) -> None: + def _log_values(self) -> bool: """ Logs output from Powermetrics to a file - """ - returncode = None - if self._system.startswith("darwin"): - # Run the powermetrics command with sudo and capture its output - cmd = [ - "sudo", - "powermetrics", - "-n", - str(self._n_points), - "", - "--samplers", - "cpu_power", - "--format", - "csv", - "-i", - str(self._interval), - "-o", - self._log_file_path, - ] - returncode = subprocess.call(cmd, universal_newlines=True) + :return: False when the command did not run, so that the caller knows + the log file was not refreshed and still holds the previous + measure. + """ + if not self._system.startswith("darwin"): + return False - else: - return None + # Run the powermetrics command with sudo and capture its output + cmd = [ + "sudo", + "powermetrics", + "-n", + str(self._n_points), + "", + "--samplers", + "cpu_power", + "--format", + "csv", + "-i", + str(self._interval), + "-o", + self._log_file_path, + ] + # _n_points samples of _interval ms is the nominal runtime of the + # command. Double it to absorb sampler overhead and scheduling jitter, + # and add a floor so short configurations keep a usable margin. This is + # a heuristic: it only has to be loose enough that a healthy run never + # trips it, because its only job is to bound a hang. + timeout = self._n_points * self._interval / 1000 * 2 + 5 + # DEVNULL so that sudo gets EOF and fails fast instead of blocking + # forever on a password prompt when it has no cached credential. + # No context manager: Popen.__exit__ would wait() without a timeout. + process = subprocess.Popen( + cmd, universal_newlines=True, stdin=subprocess.DEVNULL + ) + try: + returncode = process.wait(timeout=timeout) + except subprocess.TimeoutExpired: + logger.warning( + f"Powermetrics did not complete within {timeout:g} seconds, " + "skipping this measure." + ) + _kill_process(process) + return False if returncode != 0: logger.warning( "Returncode while logging power values using " + f"Powermetrics: {returncode}" ) - return + return True def get_details(self) -> Dict: """ Fetches the CPU Power Details by fetching values from a logged csv file in _log_values function """ - self._log_values() + if not self._log_values(): + return dict() details = dict() try: with open(self._log_file_path) as f: diff --git a/tests/test_powermetrics.py b/tests/test_powermetrics.py index b20f5df2c..283ed28ed 100644 --- a/tests/test_powermetrics.py +++ b/tests/test_powermetrics.py @@ -1,4 +1,5 @@ import os +import subprocess from unittest import mock import pytest @@ -11,6 +12,8 @@ class FakeProcess: def __init__(self, stderr="", returncode=0): self._stderr = stderr self.returncode = returncode + self.stdout = None + self.stderr = None def communicate(self): return ("", self._stderr) @@ -29,14 +32,24 @@ def __exit__(self, exc_type, exc, tb): class HangingProcess: - def __init__(self): + """A process that never exits, and optionally cannot be killed.""" + + def __init__(self, kill_error=None): self.killed = False + self.stdout = None + self.stderr = None + self._kill_error = kill_error def poll(self): return None def kill(self): self.killed = True + if self._kill_error is not None: + raise self._kill_error + + def wait(self, timeout=None): + raise subprocess.TimeoutExpired(cmd="powermetrics", timeout=timeout) def communicate(self): return ("", "") @@ -209,29 +222,89 @@ def test_setup_cli_raises_when_binary_missing_on_apple_silicon(self): with pytest.raises(FileNotFoundError): ApplePowermetrics() - def test_log_values_returns_none_on_non_darwin(self): + def test_log_values_returns_false_on_non_darwin(self): powermetrics = ApplePowermetrics.__new__(ApplePowermetrics) powermetrics._system = "linux" - assert powermetrics._log_values() is None + assert powermetrics._log_values() is False - def test_log_values_warns_on_nonzero_returncode(self): + @staticmethod + def _powermetrics_instance(): powermetrics = ApplePowermetrics.__new__(ApplePowermetrics) powermetrics._system = "darwin" powermetrics._n_points = 3 powermetrics._interval = 100 powermetrics._log_file_path = "powermetrics_log.txt" + return powermetrics + + def test_log_values_warns_on_nonzero_returncode(self): + powermetrics = self._powermetrics_instance() + process = mock.Mock() + process.wait.return_value = 1 + + with ( + mock.patch( + "codecarbon.core.powermetrics.subprocess.Popen", return_value=process + ) as mock_popen, + mock.patch("codecarbon.core.powermetrics.logger.warning") as mock_warning, + ): + assert powermetrics._log_values() is True + + mock_popen.assert_called_once() + mock_warning.assert_called_once() + + def test_log_values_runs_with_a_timeout_and_no_stdin(self): + powermetrics = self._powermetrics_instance() + process = mock.Mock() + process.wait.return_value = 0 + + with mock.patch( + "codecarbon.core.powermetrics.subprocess.Popen", return_value=process + ) as mock_popen: + assert powermetrics._log_values() is True + + # 3 points of 100 ms is 0.3 s of nominal work: 0.3 * 2 + 5. + assert process.wait.call_args.kwargs["timeout"] == pytest.approx(5.6) + assert mock_popen.call_args.kwargs["stdin"] is subprocess.DEVNULL + + def test_log_values_warns_on_timeout(self): + powermetrics = self._powermetrics_instance() + hanging = HangingProcess() with ( mock.patch( - "codecarbon.core.powermetrics.subprocess.call", return_value=1 - ) as mock_call, + "codecarbon.core.powermetrics.subprocess.Popen", return_value=hanging + ), mock.patch("codecarbon.core.powermetrics.logger.warning") as mock_warning, ): - powermetrics._log_values() + assert powermetrics._log_values() is False - mock_call.assert_called_once() mock_warning.assert_called_once() + assert hanging.killed is True + + def test_log_values_survives_an_unkillable_process_on_timeout(self): + """The child runs as root through sudo, so the kill can be refused.""" + powermetrics = self._powermetrics_instance() + hanging = HangingProcess(kill_error=PermissionError("not permitted")) + + with ( + mock.patch( + "codecarbon.core.powermetrics.subprocess.Popen", return_value=hanging + ), + mock.patch("codecarbon.core.powermetrics.logger.warning"), + ): + assert powermetrics._log_values() is False + + def test_get_details_returns_empty_dict_when_log_values_fails(self): + powermetrics = ApplePowermetrics.__new__(ApplePowermetrics) + powermetrics._log_file_path = os.path.join( + os.path.dirname(__file__), "test_data", "mock_powermetrics_log.txt" + ) + + with mock.patch.object(ApplePowermetrics, "_log_values", return_value=False): + # The log file still holds the previous measure, it must not be + # reported a second time as if it were fresh. + assert powermetrics.get_details() == {} @mock.patch("codecarbon.core.powermetrics.ApplePowermetrics._log_values") @mock.patch("builtins.open", side_effect=OSError("missing"))