From 1ea5f9340d4cf6ee0220362d0c52a5d55c7a5c10 Mon Sep 17 00:00:00 2001 From: David Berenstein Date: Wed, 19 Aug 2026 16:18:03 +0200 Subject: [PATCH 1/2] fix(powermetrics): time out the powermetrics subprocess subprocess.call had no timeout, so a hung powermetrics blocked the measurement thread forever. Allow twice the expected sampling duration plus a startup margin. --- codecarbon/core/powermetrics.py | 12 +++++++++++- tests/test_powermetrics.py | 19 +++++++++++++++++++ 2 files changed, 30 insertions(+), 1 deletion(-) diff --git a/codecarbon/core/powermetrics.py b/codecarbon/core/powermetrics.py index bffc19ce4..4cd9761cf 100644 --- a/codecarbon/core/powermetrics.py +++ b/codecarbon/core/powermetrics.py @@ -153,7 +153,17 @@ def _log_values(self) -> None: "-o", self._log_file_path, ] - returncode = subprocess.call(cmd, universal_newlines=True) + timeout = self._n_points * self._interval / 1000 * 2 + 5 + try: + returncode = subprocess.call( + cmd, universal_newlines=True, timeout=timeout + ) + except subprocess.TimeoutExpired: + logger.warning( + f"Powermetrics did not complete within {timeout} seconds, " + f"skipping this measure." + ) + return None else: return None diff --git a/tests/test_powermetrics.py b/tests/test_powermetrics.py index b20f5df2c..f66360034 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 @@ -233,6 +234,24 @@ def test_log_values_warns_on_nonzero_returncode(self): mock_call.assert_called_once() mock_warning.assert_called_once() + def test_log_values_warns_on_timeout(self): + powermetrics = ApplePowermetrics.__new__(ApplePowermetrics) + powermetrics._system = "darwin" + powermetrics._n_points = 3 + powermetrics._interval = 100 + powermetrics._log_file_path = "powermetrics_log.txt" + + with ( + mock.patch( + "codecarbon.core.powermetrics.subprocess.call", + side_effect=subprocess.TimeoutExpired(cmd="powermetrics", timeout=1), + ), + mock.patch("codecarbon.core.powermetrics.logger.warning") as mock_warning, + ): + assert powermetrics._log_values() is None + + mock_warning.assert_called_once() + @mock.patch("codecarbon.core.powermetrics.ApplePowermetrics._log_values") @mock.patch("builtins.open", side_effect=OSError("missing")) @mock.patch("codecarbon.core.powermetrics.ApplePowermetrics._setup_cli") From 9720594e1791280dcc36aad4fa7e70cb9fbdfde7 Mon Sep 17 00:00:00 2001 From: benoit-cty Date: Thu, 27 Aug 2026 15:38:23 +0200 Subject: [PATCH 2/2] Review from Claude Opus MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 1. The timeout now actually bounds the hang. Replaced subprocess.call(..., timeout=) with an explicit Popen + wait(timeout=), deliberately not under a context manager, since Popen.__exit__ calls wait() with no timeout and would re-hang when the kill is refused. Added stdin=subprocess.DEVNULL so sudo gets EOF and exits non-zero instead of blocking on a password prompt — that removes the main hang at the source rather than relying on being able to kill a root-owned child. 2. New _kill_process() helper that swallows OSError/SubprocessError from kill()/wait(), so a refused signal can't turn the handled TimeoutExpired into an escaping PermissionError, and closes the pipes the context manager used to close. 3. Applied the same fix to _has_powermetrics_sudo(). It had the identical bug — a return False from inside with Popen(...) after a possibly-failing process.kill(), i.e. an unbounded wait() in __exit__ during startup probing. It now uses a plain Popen, stdin=DEVNULL, and _kill_process(). The sudo-prompt detection still works: with DEVNULL, sudo writes "a terminal is required to read the password" to stderr, which the existing regex matches — just immediately instead of after the 3 s deadline. 4. The skip is now a real skip. _log_values() returns bool, and get_details() returns {} when it's False instead of re-reading a log file that still holds the previous measure. Also {timeout:g} so the warning reads "7 seconds", not "7.0 seconds". I deliberately left the returncode != 0 path returning True (warn, then read the file) — that's today's behaviour, and flipping it would silently turn real readings into zeros for anyone whose powermetrics exits non-zero but still writes data. Say the word if you'd rather that path also skip. One thing this does not fix, and I'd treat as a separate issue: when get_details() returns {}, AppleSiliconChip._get_power() records 0 W for that interval rather than omitting the sample. There's no "no measurement" concept at that layer, so a genuine skip needs a change in hardware.py. --- codecarbon/core/powermetrics.py | 147 ++++++++++++++++++++------------ tests/test_powermetrics.py | 86 +++++++++++++++---- 2 files changed, 161 insertions(+), 72 deletions(-) diff --git a/codecarbon/core/powermetrics.py b/codecarbon/core/powermetrics.py index 4cd9761cf..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,57 +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, - ] - timeout = self._n_points * self._interval / 1000 * 2 + 5 - try: - returncode = subprocess.call( - cmd, universal_newlines=True, timeout=timeout - ) - except subprocess.TimeoutExpired: - logger.warning( - f"Powermetrics did not complete within {timeout} seconds, " - f"skipping this measure." - ) - return None + :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 f66360034..283ed28ed 100644 --- a/tests/test_powermetrics.py +++ b/tests/test_powermetrics.py @@ -12,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) @@ -30,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 ("", "") @@ -210,47 +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.call", return_value=1 - ) as mock_call, + "codecarbon.core.powermetrics.subprocess.Popen", return_value=process + ) as mock_popen, mock.patch("codecarbon.core.powermetrics.logger.warning") as mock_warning, ): - powermetrics._log_values() + assert powermetrics._log_values() is True - mock_call.assert_called_once() + 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 = ApplePowermetrics.__new__(ApplePowermetrics) - powermetrics._system = "darwin" - powermetrics._n_points = 3 - powermetrics._interval = 100 - powermetrics._log_file_path = "powermetrics_log.txt" + powermetrics = self._powermetrics_instance() + hanging = HangingProcess() with ( mock.patch( - "codecarbon.core.powermetrics.subprocess.call", - side_effect=subprocess.TimeoutExpired(cmd="powermetrics", timeout=1), + "codecarbon.core.powermetrics.subprocess.Popen", return_value=hanging ), mock.patch("codecarbon.core.powermetrics.logger.warning") as mock_warning, ): - assert powermetrics._log_values() is None + assert powermetrics._log_values() is False 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"))