Silence rsync pull failures for absent remote sources

Author: dteo00

doc/newsfragments/3896_changed.remote_command_log_noise.rst

@@ -0,0 +1 @@
+Reduce Treadmill ``testplan.log`` noise: Tolerated (``check=False``) non-zero exits from remote setup commands are now logged at debug as ``(non-fatal)`` rather than as failures.

testplan/common/remote/remote_resource.py

@@ -26,9 +26,7 @@
     pwd,
     rebase_path,
 )
-from testplan.common.utils.process import (
-    execute_cmd,
-)
+from testplan.common.utils.process import execute_cmd
 from testplan.common.utils.remote import (
     IS_WIN,
     copy_cmd,
@@ -734,23 +732,19 @@ def _fetch_results(self) -> None:
             self.logger.error(
                 "%s not properly set up, skip fetch results stage", self
             )
+            return
         self.logger.debug("Fetch results stage - %s", self.ssh_cfg["host"])
-        try:
-            self._transfer_data(
-                source=self._remote_resource_runpath,
-                remote_source=True,
-                target=cast(Entity, self.parent).runpath,
-                exclude=self.cfg.fetch_runpath_exclude,
-            )
-            if self.cfg.pull:
-                self._pull_files()
-        except Exception as exc:
-            self._error_exec.append(exc)
-            self.logger.warning(
-                "While fetching result from remote resource [%s]: %s",
-                self,
-                exc,
-            )
+        # check=False: a fetch failure (e.g. a source absent on the remote) is
+        # tolerated and logged as (non-fatal), it does not abort teardown.
+        self._transfer_data(
+            source=self._remote_resource_runpath,
+            remote_source=True,
+            target=cast(Entity, self.parent).runpath,
+            exclude=self.cfg.fetch_runpath_exclude,
+            check=False,
+        )
+        if self.cfg.pull:
+            self._pull_files()
 
     def _clean_remote(self) -> None:
         if self.cfg.clean_remote:
@@ -787,20 +781,13 @@ def _pull_files(self) -> None:
         makedirs(pull_dst)
 
         for entry in self.cfg.pull:
-            try:
-                self._transfer_data(
-                    source=entry,
-                    remote_source=True,
-                    target=pull_dst,
-                    exclude=self.cfg.pull_exclude,
-                )
-            except Exception as exc:
-                self._error_exec.append(exc)
-                self.logger.warning(
-                    "While fetching result from remote resource [%s]: %s",
-                    self,
-                    exc,
-                )
+            self._transfer_data(
+                source=entry,
+                remote_source=True,
+                target=pull_dst,
+                exclude=self.cfg.pull_exclude,
+                check=False,
+            )
 
     def _remote_sys_path(self) -> List[str]:
         sys_path: List[str] = [cast(str, self._testplan_import_path.remote)]
@@ -853,8 +840,9 @@ def _transfer_data(
         target: str,
         remote_source: bool = False,
         remote_target: bool = False,
+        check: bool = True,
         **copy_args: Any,
-    ) -> None:
+    ) -> Tuple[int, Optional[str], Optional[str]]:
         if remote_source:
             source = self._remote_copy_path(source)
         if remote_target:
@@ -864,11 +852,12 @@ def _transfer_data(
             source, target, port=self.ssh_cfg["port"], **copy_args
         )
         with open(os.devnull, "w") as devnull:
-            execute_cmd(
+            return execute_cmd(
                 cmd,
                 "transfer data [..{}]".format(os.path.basename(source)),
                 stdout=devnull,  # type: ignore[arg-type]
                 logger=self.logger,
+                check=check,
             )
 
     def _check_remote_os(self) -> None:

testplan/common/remote/ssh_client.py

@@ -171,18 +171,31 @@ def exec_command(
         stderr_str = stderr.read().decode("utf-8").strip()
 
         if exit_code != 0:
-            self.logger.warning(
-                "Failed executing command [%s] after %.2f sec.", label, elapsed
-            )
-            if stdout_str:
-                self.logger.warning("Stdout:\n%s", stdout_str)
-            if stderr_str:
-                self.logger.warning("Stderr:\n%s", stderr_str)
             if check:
+                self.logger.warning(
+                    "Failed executing command [%s] after %.2f sec.",
+                    label,
+                    elapsed,
+                )
+                if stdout_str:
+                    self.logger.warning("Stdout:\n%s", stdout_str)
+                if stderr_str:
+                    self.logger.warning("Stderr:\n%s", stderr_str)
                 raise RuntimeError(
                     f"Command '{cmd_string}' failed with exit code {exit_code}.\n"
                     f"Stdout:\n{stdout_str}\nStderr:\n{stderr_str}"
                 )
+            # check=False => log it as non-fatal
+            self.logger.debug(
+                "Command [%s] returned exit code %d in %.2f sec (non-fatal)",
+                label,
+                exit_code,
+                elapsed,
+            )
+            if stdout_str:
+                self.logger.debug("Stdout:\n%s", stdout_str)
+            if stderr_str:
+                self.logger.debug("Stderr:\n%s", stderr_str)
         else:
             self.logger.debug(
                 "Command [%s] executed successfully in %.2f sec.",

testplan/common/utils/process.py

@@ -355,10 +355,10 @@ def execute_cmd(
     :param stderr: Optional file-like object to redirect stderr to.
     :param logger: Optional logger object as logging destination.
     :param env: Optional dict object as environment variables.
-    :param detailed_log: Enum to determine when stdout and stderr outputs should
-           be logged.
+    :param detailed_log: Enum to determine what is logged when the command runs.
            LOG_ALWAYS - Outputs are logged on success and failure.
-           LOG_ON_ERROR - Outputs are logged on failure.
+           LOG_ON_ERROR - stdout/stderr logged on failure; a non-zero exit is a
+           failure warning when ``check`` is True, else logged plainly at debug.
            NEVER_LOG - Outputs are never logged.
     :return: Return code of the command.
     """
@@ -400,12 +400,23 @@ def execute_cmd(
     elapsed = time.time() - start_time
 
     if handler.returncode != 0:
-        logger.warning(
-            "Failed executing command [%s] after %.2f sec.", label, elapsed
-        )
         output_s = output if output is not None else ""
         error_s = error if error is not None else ""
         if detailed_log is not LogDetailsOption.NEVER_LOG:
+            if check:
+                logger.warning(
+                    "Failed executing command [%s] after %.2f sec.",
+                    label,
+                    elapsed,
+                )
+            else:
+                # check=False => log it as non-fatal
+                logger.debug(
+                    "Command [%s] returned exit code %d in %.2f sec (non-fatal)",
+                    label,
+                    handler.returncode,
+                    elapsed,
+                )
             _log_subprocess_output(logger, output_s, error_s)
         if check:
             raise RuntimeError(

tests/unit/testplan/common/remote/test_remote_resource.py

@@ -2,7 +2,6 @@
 import os
 import shutil
 import tempfile
-
 import pytest
 
 from testplan import TestplanMock