Move command run log to execute

Simplify code

Author: penguinolog

exec_helpers/_log_templates.py

@@ -16,8 +16,6 @@
 
 """Text templates for logging."""
 
-CMD_EXEC: str = "Executing command:\n{cmd!r}\n"
-
 CMD_WAIT_ERROR: str = (
     "Wait for {result.cmd!r} during {timeout!s}s: no return code!\n"
     "\tSTDOUT:\n"

exec_helpers/_ssh_client_base.py

@@ -603,8 +603,6 @@ def _execute_async(  # pylint: disable=arguments-differ
         stdin: typing.Union[bytes, str, bytearray, None] = None,
         open_stdout: bool = True,
         open_stderr: bool = True,
-        verbose: bool = False,
-        log_mask_re: typing.Optional[str] = None,
         *,
         chroot_path: typing.Optional[str] = None,
         get_pty: bool = False,
@@ -622,11 +620,6 @@ def _execute_async(  # pylint: disable=arguments-differ
         :type open_stdout: bool
         :param open_stderr: open STDERR stream for read
         :type open_stderr: bool
-        :param verbose: produce verbose log record on command call
-        :type verbose: bool
-        :param log_mask_re: regex lookup rule to mask command for logger.
-                            all MATCHED groups will be replaced by '<*masked*>'
-        :type log_mask_re: typing.Optional[str]
         :param chroot_path: chroot path override
         :type chroot_path: typing.Optional[str]
         :param get_pty: Get PTY for connection
@@ -656,12 +649,6 @@ def _execute_async(  # pylint: disable=arguments-differ
         .. versionchanged:: 3.2.0 Expose pty options as optional keyword-only arguments
         .. versionchanged:: 4.1.0 support chroot
         """
-        cmd_for_log: str = self._mask_command(cmd=command, log_mask_re=log_mask_re)
-
-        self.logger.log(
-            level=logging.INFO if verbose else logging.DEBUG, msg=_log_templates.CMD_EXEC.format(cmd=cmd_for_log)
-        )
-
         chan: paramiko.Channel = self._ssh.get_transport().open_session()
 
         if get_pty:
@@ -950,7 +937,7 @@ def execute_through_host(
         with self.proxy_to(  # type: ignore
             host=hostname, port=port, auth=auth, verbose=verbose, ssh_config=self.ssh_config, keepalive=False
         ) as conn:
-            return conn.execute(
+            return conn(
                 command,
                 timeout=timeout,
                 open_stdout=open_stdout,
@@ -972,6 +959,7 @@ def execute_together(
         raise_on_err: bool = True,
         *,
         stdin: typing.Union[bytes, str, bytearray, None] = None,
+        verbose: bool = False,
         log_mask_re: typing.Optional[str] = None,
         exception_class: "typing.Type[exceptions.ParallelCallProcessError]" = exceptions.ParallelCallProcessError,
         **kwargs: typing.Any,
@@ -990,6 +978,8 @@ def execute_together(
         :type raise_on_err: bool
         :param stdin: pass STDIN text to the process
         :type stdin: typing.Union[bytes, str, bytearray, None]
+        :param verbose: produce verbose log record on command call
+        :type verbose: bool
         :param log_mask_re: regex lookup rule to mask command for logger.
                             all MATCHED groups will be replaced by '<*masked*>'
         :type log_mask_re: typing.Optional[str]
@@ -1016,17 +1006,20 @@ def get_result(remote: "SSHClientBase") -> exec_result.ExecResult:
             :param remote: SSH connection instance
             :return: execution result
             """
-            async_result: SshExecuteAsyncResult = remote._execute_async(  # pylint: disable=protected-access
+            # pylint: disable=protected-access
+            cmd_for_log: str = remote._mask_command(cmd=command, log_mask_re=log_mask_re)
+
+            remote.logger.log(
+                level=logging.INFO if verbose else logging.DEBUG, msg=f"Executing command:\n{cmd_for_log!r}\n"
+            )
+            async_result: SshExecuteAsyncResult = remote._execute_async(
                 command, stdin=stdin, log_mask_re=log_mask_re, **kwargs
             )
+            # pylint: enable=protected-access
 
             async_result.interface.status_event.wait(timeout)
             exit_code = async_result.interface.recv_exit_status()
 
-            # pylint: disable=protected-access
-            cmd_for_log: str = remote._mask_command(cmd=command, log_mask_re=log_mask_re)
-            # pylint: enable=protected-access
-
             res = exec_result.ExecResult(cmd=cmd_for_log, stdin=stdin, started=async_result.started)
             res.read_stdout(src=async_result.stdout)
             res.read_stderr(src=async_result.stderr)

exec_helpers/api.py

@@ -246,8 +246,6 @@ def _execute_async(
         stdin: typing.Union[bytes, str, bytearray, None] = None,
         open_stdout: bool = True,
         open_stderr: bool = True,
-        verbose: bool = False,
-        log_mask_re: typing.Optional[str] = None,
         *,
         chroot_path: typing.Optional[str] = None,
         **kwargs: typing.Any,
@@ -262,11 +260,6 @@ def _execute_async(
         :type open_stdout: bool
         :param open_stderr: open STDERR stream for read
         :type open_stderr: bool
-        :param verbose: produce verbose log record on command call
-        :type verbose: bool
-        :param log_mask_re: regex lookup rule to mask command for logger.
-                            all MATCHED groups will be replaced by '<*masked*>'
-        :type log_mask_re: typing.Optional[str]
         :param chroot_path: chroot path override
         :type chroot_path: typing.Optional[str]
         :param kwargs: additional parameters for call.
@@ -287,6 +280,7 @@ def _execute_async(
         .. versionchanged:: 1.2.0 stdin data
         .. versionchanged:: 2.1.0 Use typed NamedTuple as result
         .. versionchanged:: 4.1.0 support chroot
+        .. versionchanged:: 6.0.0 command start log moved to execute, verbose and log_mask_re removed as unused
         """
 
     @abc.abstractmethod
@@ -357,6 +351,10 @@ def execute(
         .. versionchanged:: 1.2.0 default timeout 1 hour
         .. versionchanged:: 2.1.0 Allow parallel calls
         """
+        cmd_for_log: str = self._mask_command(cmd=command, log_mask_re=log_mask_re)
+
+        self.logger.log(level=logging.INFO if verbose else logging.DEBUG, msg=f"Executing command:\n{cmd_for_log!r}\n")
+
         async_result: ExecuteAsyncResult = self._execute_async(
             command, verbose=verbose, log_mask_re=log_mask_re, stdin=stdin, **kwargs
         )

exec_helpers/async_api/api.py

@@ -141,8 +141,6 @@ async def _execute_async(  # type: ignore
         stdin: typing.Union[str, bytes, bytearray, None] = None,
         open_stdout: bool = True,
         open_stderr: bool = True,
-        verbose: bool = False,
-        log_mask_re: typing.Optional[str] = None,
         *,
         chroot_path: typing.Optional[str] = None,
         **kwargs: typing.Any,
@@ -157,11 +155,6 @@ async def _execute_async(  # type: ignore
         :type open_stdout: bool
         :param open_stderr: open STDERR stream for read
         :type open_stderr: bool
-        :param verbose: produce verbose log record on command call
-        :type verbose: bool
-        :param log_mask_re: regex lookup rule to mask command for logger.
-                            all MATCHED groups will be replaced by '<*masked*>'
-        :type log_mask_re: typing.Optional[str]
         :param chroot_path: chroot path override
         :type chroot_path: typing.Optional[str]
         :param kwargs: additional parameters for call.
@@ -209,6 +202,10 @@ async def execute(  # type: ignore
         :rtype: ExecResult
         :raises ExecHelperTimeoutError: Timeout exceeded
         """
+        cmd_for_log: str = self._mask_command(cmd=command, log_mask_re=log_mask_re)
+
+        self.logger.log(level=logging.INFO if verbose else logging.DEBUG, msg=f"Executing command:\n{cmd_for_log!r}\n")
+
         async_result: api.ExecuteAsyncResult = await self._execute_async(
             command, verbose=verbose, log_mask_re=log_mask_re, stdin=stdin, **kwargs
         )

exec_helpers/async_api/subprocess_runner.py

@@ -169,8 +169,6 @@ async def _execute_async(  # type: ignore
         stdin: typing.Union[str, bytes, bytearray, None] = None,
         open_stdout: bool = True,
         open_stderr: bool = True,
-        verbose: bool = False,
-        log_mask_re: typing.Optional[str] = None,
         *,
         chroot_path: typing.Optional[str] = None,
         cwd: typing.Optional[typing.Union[str, bytes]] = None,
@@ -189,11 +187,6 @@ async def _execute_async(  # type: ignore
         :type open_stdout: bool
         :param open_stderr: open STDERR stream for read
         :type open_stderr: bool
-        :param verbose: produce verbose log record on command call
-        :type verbose: bool
-        :param log_mask_re: regex lookup rule to mask command for logger.
-                            all MATCHED groups will be replaced by '<*masked*>'
-        :type log_mask_re: typing.Optional[str]
         :param chroot_path: chroot path override
         :type chroot_path: typing.Optional[str]
         :param cwd: Sets the current directory before the child is executed.
@@ -215,12 +208,6 @@ async def _execute_async(  # type: ignore
                 )
         :raises OSError: impossible to process STDIN
         """
-        cmd_for_log: str = self._mask_command(cmd=command, log_mask_re=log_mask_re)
-
-        self.logger.log(
-            level=logging.INFO if verbose else logging.DEBUG, msg=_log_templates.CMD_EXEC.format(cmd=cmd_for_log)
-        )
-
         started = datetime.datetime.utcnow()
 
         process: asyncio.subprocess.Process = await asyncio.create_subprocess_shell(  # pylint: disable=no-member

exec_helpers/subprocess_runner.py

@@ -188,8 +188,6 @@ def _execute_async(  # pylint: disable=arguments-differ
         stdin: typing.Union[str, bytes, bytearray, None] = None,
         open_stdout: bool = True,
         open_stderr: bool = True,
-        verbose: bool = False,
-        log_mask_re: typing.Optional[str] = None,
         *,
         chroot_path: typing.Optional[str] = None,
         cwd: typing.Optional[typing.Union[str, bytes]] = None,
@@ -208,11 +206,6 @@ def _execute_async(  # pylint: disable=arguments-differ
         :type open_stdout: bool
         :param open_stderr: open STDERR stream for read
         :type open_stderr: bool
-        :param verbose: produce verbose log record on command call
-        :type verbose: bool
-        :param log_mask_re: regex lookup rule to mask command for logger.
-                            all MATCHED groups will be replaced by '<*masked*>'
-        :type log_mask_re: typing.Optional[str]
         :param chroot_path: chroot path override
         :type chroot_path: typing.Optional[str]
         :param cwd: Sets the current directory before the child is executed.
@@ -239,12 +232,6 @@ def _execute_async(  # pylint: disable=arguments-differ
         .. versionchanged:: 3.2.0 Expose cwd and env as optional keyword-only arguments
         .. versionchanged:: 4.1.0 support chroot
         """
-        cmd_for_log: str = self._mask_command(cmd=command, log_mask_re=log_mask_re)
-
-        self.logger.log(
-            level=logging.INFO if verbose else logging.DEBUG, msg=_log_templates.CMD_EXEC.format(cmd=cmd_for_log)
-        )
-
         started = datetime.datetime.utcnow()
 
         process = subprocess.Popen(

test/async_api/test_subprocess.py

@@ -252,7 +252,6 @@ async def test_001_execute_async(create_subprocess_shell, logger, run_parameters
     if stdin is not None:
         res.interface.stdin.write.assert_called_once_with(stdin)
         res.interface.stdin.drain.assert_awaited_once()
-    logger.log.assert_called_once_with(level=logging.DEBUG, msg=command_log)
 
 
 async def test_002_execute(create_subprocess_shell, logger, exec_result, run_parameters) -> None:
@@ -261,6 +260,7 @@ async def test_002_execute(create_subprocess_shell, logger, exec_result, run_par
     res = await runner.execute(command, stdin=run_parameters["stdin"])
     assert isinstance(res, exec_helpers.async_api.ExecResult)
     assert res == exec_result
+    assert logger.mock_calls[0] == mock.call.log(level=logging.DEBUG, msg=command_log)
     assert logger.mock_calls[-1] == mock.call.log(
         level=logging.DEBUG, msg=f"Command {res.cmd!r} exit code: {res.exit_code!s}"
     )

test/test_ssh_client_execute.py

@@ -249,7 +249,7 @@ def execute(mocker, exec_result):
     return mocker.patch("exec_helpers.ssh_client.SSHClient.execute", name="execute", return_value=exec_result)
 
 
-def test_001_execute_async(ssh, paramiko_ssh_client, ssh_transport_channel, chan_makefile, run_parameters, get_logger):
+def test_001_execute_async(ssh, paramiko_ssh_client, ssh_transport_channel, chan_makefile, run_parameters):
     open_stdout = run_parameters["open_stdout"]
     open_stderr = run_parameters["open_stderr"]
     get_pty = run_parameters.get("get_pty", False)
@@ -316,11 +316,9 @@ def test_001_execute_async(ssh, paramiko_ssh_client, ssh_transport_channel, chan
     if stdin:
         res.stdin.write.assert_called_with(stdin.encode("utf-8"))
         res.stdin.flush.assert_called_once()
-    log = get_logger(ssh.__class__.__name__).getChild(f"{host}:{port}")
-    log.log.assert_called_once_with(level=logging.DEBUG, msg=command_log)
 
 
-def test_002_execute(ssh, ssh_transport_channel, exec_result, run_parameters) -> None:
+def test_002_execute(ssh, ssh_transport_channel, exec_result, run_parameters, get_logger) -> None:
     kwargs = {}
     if "get_pty" in run_parameters:
         kwargs["get_pty"] = run_parameters["get_pty"]
@@ -339,6 +337,8 @@ def test_002_execute(ssh, ssh_transport_channel, exec_result, run_parameters) ->
     assert isinstance(res, exec_helpers.ExecResult)
     assert res == exec_result
     ssh_transport_channel.assert_has_calls((mock.call.status_event.is_set(),))
+    log = get_logger(ssh.__class__.__name__).getChild(f"{host}:22")
+    assert log.mock_calls[0] == mock.call.log(level=logging.DEBUG, msg=command_log)
 
 
 def test_003_context_manager(ssh, exec_result, run_parameters, mocker) -> None:

test/test_subprocess.py

@@ -226,7 +226,6 @@ def test_001_execute_async(popen, subprocess_logger, run_parameters) -> None:
     if stdin is not None:
         res.interface.stdin.write.assert_called_once_with(stdin)
         res.interface.stdin.close.assert_called_once()
-    subprocess_logger.log.assert_called_once_with(level=logging.DEBUG, msg=command_log)
 
 
 def test_002_execute(popen, subprocess_logger, exec_result, run_parameters) -> None:
@@ -241,6 +240,7 @@ def test_002_execute(popen, subprocess_logger, exec_result, run_parameters) -> N
     assert isinstance(res, exec_helpers.ExecResult)
     assert res == exec_result
     popen().wait.assert_called_once_with(timeout=default_timeout)
+    assert subprocess_logger.mock_calls[0] == mock.call.log(level=logging.DEBUG, msg=command_log)
 
 
 def test_003_context_manager(mocker, popen, subprocess_logger, exec_result, run_parameters) -> None: