[3007.x] print minion output, mirror salt-ssh log level

changelog/66951.fixed.md

@@ -0,0 +1 @@
+Fix salt-ssh minion logs to stdout

salt/client/ssh/__init__.py

@@ -1536,6 +1536,7 @@ def _cmd_str(self):
 OPTIONS.tty = {tty}
 OPTIONS.cmd_umask = {cmd_umask}
 OPTIONS.code_checksum = {code_checksum}
+OPTIONS.log_level = '{log_level}'
 ARGS = {arguments}\n'''.format(
             config=self.minion_config,
             delimeter=RSTR,
@@ -1549,6 +1550,7 @@ def _cmd_str(self):
             cmd_umask=self.cmd_umask,
             code_checksum=thin_code_digest,
             arguments=self.argv,
+            log_level=self.opts["log_level"],
         )
         py_code = SSH_PY_SHIM.replace("#%%OPTS", arg_str)
         py_code_enc = base64.encodebytes(py_code.encode("utf-8")).decode("utf-8")
@@ -1591,15 +1593,15 @@ def execute_script(self, script, extension="py", pre_dir="", script_args=None):
 
         return ret
 
-    def shim_cmd(self, cmd_str, extension="py"):
+    def shim_cmd(self, cmd_str, extension="py", print_output=False):
         """
         Run a shim command.
 
         If tty is enabled, we must scp the shim to the target system and
         execute it there
         """
         if not self.tty and not self.winrm:
-            return self.shell.exec_cmd(cmd_str)
+            return self.shell.exec_cmd(cmd_str, print_output=print_output)
 
         # Write the shim to a temporary file in the default temp directory
         with tempfile.NamedTemporaryFile(mode="w+b", delete=False) as shim_tmp_file:
@@ -1627,7 +1629,7 @@ def shim_cmd(self, cmd_str, extension="py"):
 
         return ret
 
-    def cmd_block(self, is_retry=False):
+    def cmd_block(self, is_retry=False, print_output=False):
         """
         Prepare the pre-check command to send to the subsystem
 
@@ -1644,7 +1646,7 @@ def cmd_block(self, is_retry=False):
             " ".join([str(arg) for arg in self.argv]),
         )
         cmd_str = self._cmd_str()
-        stdout, stderr, retcode = self.shim_cmd(cmd_str)
+        stdout, stderr, retcode = self.shim_cmd(cmd_str, print_output=print_output)
 
         log.trace("STDOUT %s\n%s", self.target["host"], stdout)
         log.trace("STDERR %s\n%s", self.target["host"], stderr)
@@ -1654,14 +1656,18 @@ def cmd_block(self, is_retry=False):
         if error:
             if error == "Python environment not found on Windows system":
                 saltwinshell.deploy_python(self)
-                stdout, stderr, retcode = self.shim_cmd(cmd_str)
+                stdout, stderr, retcode = self.shim_cmd(
+                    cmd_str, print_output=print_output
+                )
                 while re.search(RSTR_RE, stdout):
                     stdout = re.split(RSTR_RE, stdout, 1)[1].strip()
                 while re.search(RSTR_RE, stderr):
                     stderr = re.split(RSTR_RE, stderr, 1)[1].strip()
             elif error == "Undefined SHIM state":
                 self.deploy()
-                stdout, stderr, retcode = self.shim_cmd(cmd_str)
+                stdout, stderr, retcode = self.shim_cmd(
+                    cmd_str, print_output=print_output
+                )
                 if not re.search(RSTR_RE, stdout) or not re.search(RSTR_RE, stderr):
                     # If RSTR is not seen in both stdout and stderr then there
                     # was a thin deployment problem.
@@ -1700,7 +1706,9 @@ def cmd_block(self, is_retry=False):
                 and retcode == salt.defaults.exitcodes.EX_THIN_DEPLOY
             ):
                 self.deploy()
-                stdout, stderr, retcode = self.shim_cmd(cmd_str)
+                stdout, stderr, retcode = self.shim_cmd(
+                    cmd_str, print_output=print_output
+                )
                 if not re.search(RSTR_RE, stdout) or not re.search(RSTR_RE, stderr):
                     if not self.tty:
                         # If RSTR is not seen in both stdout and stderr then there
@@ -1712,7 +1720,7 @@ def cmd_block(self, is_retry=False):
                             stderr,
                             retcode,
                         )
-                        return self.cmd_block()
+                        return self.cmd_block(print_output=print_output)
                     elif not re.search(RSTR_RE, stdout):
                         # If RSTR is not seen in stdout with tty, then there
                         # was a thin deployment problem.
@@ -1732,7 +1740,9 @@ def cmd_block(self, is_retry=False):
                         stderr = re.split(RSTR_RE, stderr, 1)[1].strip()
             elif "ext_mods" == shim_command:
                 self.deploy_ext()
-                stdout, stderr, retcode = self.shim_cmd(cmd_str)
+                stdout, stderr, retcode = self.shim_cmd(
+                    cmd_str, print_output=print_output
+                )
                 if not re.search(RSTR_RE, stdout) or not re.search(RSTR_RE, stderr):
                     # If RSTR is not seen in both stdout and stderr then there
                     # was a thin deployment problem.

salt/client/ssh/shell.py

@@ -333,7 +333,7 @@ def exec_nb_cmd(self, cmd):
             yield None, None, None
         yield "".join(r_out), "".join(r_err), rcode
 
-    def exec_cmd(self, cmd):
+    def exec_cmd(self, cmd, print_output=False):
         """
         Execute a remote command
         """
@@ -348,7 +348,7 @@ def exec_cmd(self, cmd):
         else:
             log.debug(logmsg)
 
-        ret = self._run_cmd(cmd)
+        ret = self._run_cmd(cmd, print_output=print_output)
         return ret
 
     def send(self, local, remote, makedirs=False):
@@ -403,7 +403,7 @@ def _sanitize_str(self, text, sanitize_text):
         replace_str = "*" * 6
         return re.sub(r"\b" + re.escape(sanitize_text) + r"\b", replace_str, text)
 
-    def _run_cmd(self, cmd, key_accept=False, passwd_retries=3):
+    def _run_cmd(self, cmd, key_accept=False, passwd_retries=3, print_output=False):
         """
         Execute a shell command via VT. This is blocking and assumes that ssh
         is being run
@@ -436,10 +436,14 @@ def _run_cmd(self, cmd, key_accept=False, passwd_retries=3):
                 if stdout:
                     ret_stdout += stdout
                     buff = old_stdout + stdout
+                    if print_output:
+                        print(stdout, file=sys.stdout, end="")
                 else:
                     buff = stdout
                 if stderr:
                     ret_stderr += stderr
+                    if print_output:
+                        print(stderr, file=sys.stderr, end="")
                 if buff and RSTR_RE.search(buff):
                     # We're getting results back, don't try to send passwords
                     send_password = False

salt/client/ssh/ssh_py_shim.py

@@ -7,6 +7,7 @@
 helper script used by salt.client.ssh.Single.  It is here, in a
 separate file, for convenience of development.
 """
+
 from __future__ import absolute_import, print_function
 
 import hashlib
@@ -359,8 +360,8 @@ def main(argv):  # pylint: disable=W0613
         "--metadata",
         "--out",
         "json",
-        "-l",
-        "quiet",
+        "--log-level",
+        OPTIONS.log_level,
         "-c",
         OPTIONS.saltdir,
     ]

salt/client/ssh/wrapper/state.py

@@ -60,7 +60,7 @@ def _ssh_state(chunks, st_kwargs, kwargs, pillar, test=False):
         **st_kwargs,
     )
     single.shell.send(trans_tar, "{}/salt_state.tgz".format(__opts__["thin_dir"]))
-    stdout, stderr, retcode = single.cmd_block()
+    stdout, stderr, retcode = single.cmd_block(print_output=True)
 
     # Clean up our tar
     try:
@@ -234,7 +234,7 @@ def sls(mods, saltenv="base", test=None, exclude=None, **kwargs):
             **st_kwargs,
         )
         single.shell.send(trans_tar, "{}/salt_state.tgz".format(opts["thin_dir"]))
-        stdout, stderr, retcode = single.cmd_block()
+        stdout, stderr, retcode = single.cmd_block(print_output=True)
 
         # Clean up our tar
         try:
@@ -372,7 +372,7 @@ def low(data, **kwargs):
             **st_kwargs,
         )
         single.shell.send(trans_tar, "{}/salt_state.tgz".format(__opts__["thin_dir"]))
-        stdout, stderr, retcode = single.cmd_block()
+        stdout, stderr, retcode = single.cmd_block(print_output=True)
 
         # Clean up our tar
         try:
@@ -465,7 +465,7 @@ def high(data, **kwargs):
             **st_kwargs,
         )
         single.shell.send(trans_tar, "{}/salt_state.tgz".format(opts["thin_dir"]))
-        stdout, stderr, retcode = single.cmd_block()
+        stdout, stderr, retcode = single.cmd_block(print_output=True)
 
         # Clean up our tar
         try:
@@ -716,7 +716,7 @@ def highstate(test=None, **kwargs):
             **st_kwargs,
         )
         single.shell.send(trans_tar, "{}/salt_state.tgz".format(opts["thin_dir"]))
-        stdout, stderr, retcode = single.cmd_block()
+        stdout, stderr, retcode = single.cmd_block(print_output=True)
 
         # Clean up our tar
         try:
@@ -807,7 +807,7 @@ def top(topfn, test=None, **kwargs):
             **st_kwargs,
         )
         single.shell.send(trans_tar, "{}/salt_state.tgz".format(opts["thin_dir"]))
-        stdout, stderr, retcode = single.cmd_block()
+        stdout, stderr, retcode = single.cmd_block(print_output=True)
 
         # Clean up our tar
         try:
@@ -1269,7 +1269,7 @@ def single(fun, name, test=None, **kwargs):
     single.shell.send(trans_tar, "{}/salt_state.tgz".format(opts["thin_dir"]))
 
     # Run the state.pkg command on the target
-    stdout, stderr, retcode = single.cmd_block()
+    stdout, stderr, retcode = single.cmd_block(print_output=True)
 
     # Clean up our tar
     try:

tests/pytests/unit/client/ssh/test_shell.py

@@ -217,3 +217,47 @@ def test_scp_command_execution_uses_custom_path():
         args, _ = mock_run_cmd.call_args
         assert "/custom/scp" in args[0]
         assert "source_file.txt example.com:/path/dest_file.txt" in args[0]
+
+
+def test_run_cmd_print_output_streams_stdout_stderr(capsys):
+    """
+    Test that _run_cmd with print_output=True prints stdout to sys.stdout
+    and stderr to sys.stderr as output arrives.
+    """
+    term = MagicMock()
+    has_unread_data = PropertyMock(side_effect=(True, True, False))
+    type(term).has_unread_data = has_unread_data
+    term.exitstatus = 0
+    term.signalstatus = None
+    term.recv.side_effect = (
+        ("hello stdout", "hello stderr"),
+        (None, None),
+        (None, None),
+    )
+
+    shl = shell.Shell({}, "localhost")
+    with patch("salt.utils.vt.Terminal", autospec=True, return_value=term):
+        stdout, stderr, retcode = shl._run_cmd("echo hello", print_output=True)
+
+    captured = capsys.readouterr()
+    assert "hello stdout" in captured.out
+    assert "hello stderr" in captured.err
+    assert stdout == "hello stdout"
+    assert stderr == "hello stderr"
+
+
+def test_exec_cmd_passes_print_output_to_run_cmd(capsys):
+    """
+    Test that Shell.exec_cmd(cmd, print_output=True) passes the flag through
+    to _run_cmd so output is streamed to stdout/stderr.
+    """
+    shl = shell.Shell({}, "localhost")
+    exp_ret = ("out", "err", 0)
+    mock_run = MagicMock(return_value=exp_ret)
+    with patch.object(shl, "_run_cmd", mock_run):
+        ret = shl.exec_cmd("echo test", print_output=True)
+
+    assert ret == exp_ret
+    mock_run.assert_called_once()
+    _, kwargs = mock_run.call_args
+    assert kwargs.get("print_output") is True

tests/pytests/unit/client/ssh/test_single.py

@@ -1019,3 +1019,118 @@ def test_ssh_single__cmd_str_sudo_passwd_user(opts):
     )
 
     assert expected in cmd
+
+
+def test_cmd_str_includes_log_level(opts, target):
+    """
+    Test that _cmd_str() passes the master log_level into OPTIONS.log_level
+    so the remote shim mirrors the configured log level instead of always
+    using quiet.
+    """
+    import base64
+    import re
+
+    opts["log_level"] = "debug"
+    single = ssh.Single(
+        opts,
+        opts["argv"],
+        "localhost",
+        mods={},
+        fsclient=None,
+        thin=salt.utils.thin.thin_path(opts["cachedir"]),
+        mine=False,
+        **target,
+    )
+    # _cmd_str calls thin_sum which needs a cached thin tarball; mock it.
+    with patch("salt.utils.thin.thin_sum", return_value=("abc123", "sha1sum")):
+        cmd = single._cmd_str()
+
+    # The OPTIONS block is inside the base64-encoded Python payload embedded
+    # as exec(base64.b64decode("""<data>""").decode("utf-8"))
+    m = re.search(r'b64decode\("""(.+?)"""', cmd, re.DOTALL)
+    assert m, "No base64 payload found in cmd"
+    py_code = base64.b64decode(m.group(1)).decode("utf-8")
+    assert "OPTIONS.log_level = 'debug'" in py_code
+
+
+def test_cmd_str_log_level_defaults_to_info(opts, target):
+    """
+    When no log_level is set in opts, _cmd_str() must default to 'info'.
+    """
+    import base64
+    import re
+
+    opts.pop("log_level", None)
+    single = ssh.Single(
+        opts,
+        opts["argv"],
+        "localhost",
+        mods={},
+        fsclient=None,
+        thin=salt.utils.thin.thin_path(opts["cachedir"]),
+        mine=False,
+        **target,
+    )
+    with patch("salt.utils.thin.thin_sum", return_value=("abc123", "sha1sum")):
+        cmd = single._cmd_str()
+
+    m = re.search(r'b64decode\("""(.+?)"""', cmd, re.DOTALL)
+    assert m, "No base64 payload found in cmd"
+    py_code = base64.b64decode(m.group(1)).decode("utf-8")
+    assert "OPTIONS.log_level = 'info'" in py_code
+
+
+def test_shim_cmd_passes_print_output_to_exec_cmd(opts, target):
+    """
+    Test that Single.shim_cmd(print_output=True) propagates print_output
+    to Shell.exec_cmd when not using tty or winrm.
+    """
+    single = ssh.Single(
+        opts,
+        opts["argv"],
+        "localhost",
+        mods={},
+        fsclient=None,
+        thin=salt.utils.thin.thin_path(opts["cachedir"]),
+        mine=False,
+        winrm=False,
+        tty=False,
+        **target,
+    )
+
+    exp_ret = ("output", "", 0)
+    mock_exec_cmd = MagicMock(return_value=exp_ret)
+    with patch.object(single.shell, "exec_cmd", mock_exec_cmd):
+        ret = single.shim_cmd("echo test", print_output=True)
+    assert ret == exp_ret
+    mock_exec_cmd.assert_called_once()
+    _, kwargs = mock_exec_cmd.call_args
+    assert kwargs.get("print_output") is True
+
+
+def test_cmd_block_passes_print_output_to_shim_cmd(opts, target):
+    """
+    Test that Single.cmd_block(print_output=True) propagates print_output
+    to shim_cmd.
+    """
+    single = ssh.Single(
+        opts,
+        opts["argv"],
+        "localhost",
+        mods={},
+        fsclient=None,
+        thin=salt.utils.thin.thin_path(opts["cachedir"]),
+        mine=False,
+        winrm=False,
+        tty=False,
+        **target,
+    )
+
+    exp_ret = ("output", "", 0)
+    mock_shim = MagicMock(return_value=exp_ret)
+    with patch.object(single, "shim_cmd", mock_shim):
+        single.cmd_block(print_output=True)
+
+    mock_shim.assert_called_once()
+    _, kwargs = mock_shim.call_args
+    assert kwargs.get("print_output") is True