fix(powermetrics): time out the powermetrics subprocess

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:

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