From cfaa8437f27eb4fce8ecf28e0f998fe8bb180519 Mon Sep 17 00:00:00 2001 From: Skyler Hawthorne Date: Tue, 8 Oct 2024 19:50:57 -0400 Subject: [PATCH 1/2] print minion output, mirror salt-ssh log level --- changelog/66951.fixed.md | 1 + salt/client/ssh/__init__.py | 28 +++++++++++++++++++--------- salt/client/ssh/shell.py | 10 +++++++--- salt/client/ssh/ssh_py_shim.py | 5 +++-- salt/client/ssh/wrapper/state.py | 14 +++++++------- 5 files changed, 37 insertions(+), 21 deletions(-) create mode 100644 changelog/66951.fixed.md diff --git a/changelog/66951.fixed.md b/changelog/66951.fixed.md new file mode 100644 index 000000000000..c73c6d666fd3 --- /dev/null +++ b/changelog/66951.fixed.md @@ -0,0 +1 @@ +Fix salt-ssh minion logs to stdout diff --git a/salt/client/ssh/__init__.py b/salt/client/ssh/__init__.py index f29bb7539e7d..58abc70622d9 100644 --- a/salt/client/ssh/__init__.py +++ b/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,7 +1593,7 @@ 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. @@ -1599,7 +1601,7 @@ def shim_cmd(self, cmd_str, extension="py"): 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. diff --git a/salt/client/ssh/shell.py b/salt/client/ssh/shell.py index 7b20714e7860..c3dc6c551423 100644 --- a/salt/client/ssh/shell.py +++ b/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 diff --git a/salt/client/ssh/ssh_py_shim.py b/salt/client/ssh/ssh_py_shim.py index 679fb52cbbb4..4e746f4dd82a 100644 --- a/salt/client/ssh/ssh_py_shim.py +++ b/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, ] diff --git a/salt/client/ssh/wrapper/state.py b/salt/client/ssh/wrapper/state.py index 79667a4dedea..867744a90701 100644 --- a/salt/client/ssh/wrapper/state.py +++ b/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: From 909f79a5cad5cd5851f5b6b1d330cf99b7b4a985 Mon Sep 17 00:00:00 2001 From: "Daniel A. Wozniak" Date: Fri, 26 Jun 2026 04:55:57 -0700 Subject: [PATCH 2/2] Add tests for print_output and log_level mirroring in salt-ssh - test_cmd_str_includes_log_level: verifies OPTIONS.log_level in the base64-encoded shim payload matches the master log_level - test_cmd_str_log_level_defaults_to_info: verifies default when unset - test_shim_cmd_passes_print_output_to_exec_cmd: propagation through Single.shim_cmd -> Shell.exec_cmd - test_cmd_block_passes_print_output_to_shim_cmd: propagation through Single.cmd_block -> shim_cmd - test_run_cmd_print_output_streams_stdout_stderr: Shell._run_cmd with print_output=True writes to sys.stdout/stderr - test_exec_cmd_passes_print_output_to_run_cmd: Shell.exec_cmd passes the flag through to _run_cmd --- tests/pytests/unit/client/ssh/test_shell.py | 44 +++++++ tests/pytests/unit/client/ssh/test_single.py | 115 +++++++++++++++++++ 2 files changed, 159 insertions(+) diff --git a/tests/pytests/unit/client/ssh/test_shell.py b/tests/pytests/unit/client/ssh/test_shell.py index 3e63a3e8a76a..7b470ab10d2f 100644 --- a/tests/pytests/unit/client/ssh/test_shell.py +++ b/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 diff --git a/tests/pytests/unit/client/ssh/test_single.py b/tests/pytests/unit/client/ssh/test_single.py index 0c1ed798a970..54171906d556 100644 --- a/tests/pytests/unit/client/ssh/test_single.py +++ b/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("""""").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