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

[dead10ck]

What does this PR do?

What issues does this PR fix or reference?

Fixes #66951

New Behavior

Minion logs are logged to stderr. Log level matches that of salt-ssh.

Merge requirements satisfied?

[NOTICE] Bug fixes or features added to Salt require tests.

• Docs
• Changelog - https://docs.saltproject.io/en/master/topics/development/changelog.html
• Tests written/updated

Commits signed with GPG?

No

[twangboy]

Could we get a test, please?

[dead10ck]

Sure, do you have any suggestions? The change is to print output to the terminal, so it's not really clear to me how one would test this in an automated way. And what the test would be.

[lkubb]

https://docs.pytest.org/en/stable/reference/reference.html#std-fixture-capfd

You probably want to print stderr only, stdout is used by the SHIM for communication with the remote (printing stdout additionally prints the remote minion's return and breaks the existing state wrapper tests [?]).

[dead10ck]

https://docs.pytest.org/en/stable/reference/reference.html#std-fixture-capfd

Thanks for the link. I can certainly do that, but what exactly am I testing? Just that stderr is not empty? Is this helpful as a test? This wouldn't necessarily validate that what we're seeing is actually the logs of the state.pkg application. It could be something else, and we'd have no way of knowing. It wouldn't really be a good regression test.

You probably want to print stderr only, stdout is used by the SHIM for communication with the remote (printing stdout additionally prints the remote minion's return and breaks the existing state wrapper tests [?]).

If I'm not mistaken, both stdout and stderr are read from the ssh process and accumulated into a buffer, which is the returned to the caller. This change simply adds logic that prints out the contents as they are read—they are also still accumulated into the same buffer as before.

[lkubb]

what exactly am I testing? Just that stderr is not empty? Is this helpful as a test? This wouldn't necessarily validate that what we're seeing is actually the logs of the state.pkg application. It could be something else, and we'd have no way of knowing. It wouldn't really be a good regression test.

I would advise the following:

• Make this change effective for all execution module calls, not just those using the state wrapper
• In your test, add a new execution module that logs a specific string at a specified log level
• Call it, capture stderr and assert the specific string was logged

You can add the same test for the state wrapper by calling your execution module in a .sls file.

If I'm not mistaken, both stdout and stderr are read from the ssh process and accumulated into a buffer, which is the returned to the caller. This change simply adds logic that prints out the contents as they are read—they are also still accumulated into the same buffer as before.

Right, although the SHIM communication is filtered out before returning them to the caller (which parses them again). The tests are breaking because the test helpers parse stdout as JSON, which does not work when the function call prints more than the function return (e.g. the SHIM communication and the remote minion's return, possibly more):

ret        = ProcessResult(
                returncode=0,
                stdout='''
/usr/bin/scp
_edbc7885e4f9aac9b83b35999b68d015148caf467b78fa39c05f669c0ff89878
{
    "local": {
        "jid": "20241009083652243241",
        "return": {
            "test_|-target_check_|-target_check_|-check_pillar": {
                "name": "target_check",
                "changes": {},
                "result": true,
                "comment": "",
                "__sls__": "showpillar",
                "__run_num__": 0,
                "start_time": "08:36:52.664145",
                "duration": 1.873,
                "__id__": "target_check"
            }
        },
        "retcode": 0,
        "out": "highstate",
        "id": "localhost",
        "fun": "state.pkg",
        "fun_args": [
            "/var/tmp/.root_c4ac4b_salt/salt_state.tgz",
            "test=None",
            "pkg_sum=efc5c8f8ab098da6990b2bbfea476b3c820159a50451acb3cded97cfedd72f18",
            "hash_type=sha256"
        ]
    }
}
{
"localhost": {
"test_|-target_check_|-target_check_|-check_pillar": {
"name": "target_check",
"changes": {},
"result": true,
"comment": "",
"__sls__": "showpillar",
"__run_num__": 0,
"start_time": "08:36:52.664145",
"duration": 1.873,
"__id__": "target_check"
}
}
}
''',
                stderr="""
SALT_ARGV: ['/usr/bin/python3', '/var/tmp/.root_c4ac4b_salt/salt-call', '--retcode-passthrough', '--local', '--metadata', '--out', 'json', '--log-level', 'critical', '-c', '/var/tmp/.root_c4ac4b_salt', '--', 'state.pkg', '/var/tmp/.root_c4ac4b_salt/salt_state.tgz', 'test=None', 'pkg_sum=efc5c8f8ab098da6990b2bbfea476b3c820159a50451acb3cded97cfedd72f18', 'hash_type=sha256']
_edbc7885e4f9aac9b83b35999b68d015148caf467b78fa39c05f669c0ff89878
/usr/lib64/python3.9/tarfile.py:2239: RuntimeWarning: The default behavior of tarfile extraction has been changed to disallow common exploits (including CVE-2007-4559). By default, absolute/parent paths are disallowed and some mode bits are cleared. See https://access.redhat.com/articles/7004769 for more details.
  warnings.warn(
""",
                cmdline=['/tmp/testing/.nox/ci-test-onedir/bin/python', '/tmp/stsuite/scripts/cli_salt_ssh.py', '--roster-file=/tmp/stsuite/master-VEaCae/conf/roster', '--priv=/tmp/stsuite/sshd/client_key', '--user=root', '--config-dir=/tmp/stsuite/master-VEaCae/conf', '--out=json', '--out-indent=0', '--log-level=critical', 'localhost', 'state.sls_id', 'target_check', 'showpillar', 'pillar={"the_meaning": {"of": {"life": [2.71], "foo": "lish"}}, "btw": "turtles"}'],
                data_key=None,
                data=None
            )

I don't think these internals should be printed, thus would advise to only print stderr (which is where logging takes place) + possibly filter it before printing (e.g. only print after _edbc7885e4f9aac9b83b35999b68d015148caf467b78fa39c05f669c0ff89878 has been found).

Edit: Something else to consider is the security angle. Printing arbitrary output from a remote system is risky (especially if the local one is running a Salt master), I'd probably filter it down to ASCII characters only.

[dead10ck]

Thanks, I appreciate the tips! This helps a lot. I'll do this when I get some time.