[BUG] FreeBSD debug output gets merged when using runas

[network-shark]

Description
When I use cmd.run 'X' runas=$user -ltrace the command is executed , but additionally the output got some lines from the debug.

Setup
(Please provide relevant configs and/or SLS files (be sure to remove sensitive info. There is no general set-up of Salt.)

Please be as specific as possible and give set-up details.

• on-prem machine
• VM (Virtualbox, KVM, etc. please specify)
• VM running on a cloud service, please be explicit and add details
• container (Kubernetes, Docker, containerd, etc. please specify)
• or a combination, please be explicit
• jails if it is FreeBSD

Steps to Reproduce the behavior
salt-call cmd.run "pkg info | head -5" runas=unbound -l trace

root@unbound:~ # salt-call cmd.run "pkg info | head -5" runas=unbound -ltrace
[DEBUG   ] Reading configuration from /usr/local/etc/salt/minion
[DEBUG   ] Including configuration from '/usr/local/etc/salt/minion.d/_schedule.conf'
[DEBUG   ] Reading configuration from /usr/local/etc/salt/minion.d/_schedule.conf
[DEBUG   ] Using importlib_metadata to load entry points
[TRACE   ] The required configuration section, 'fluent_handler', was not found the in the configuration. Not loading the fluent logging handlers module.
[TRACE   ] None of the required configuration sections, 'logstash_udp_handler' and 'logstash_zmq_handler', were found in the configuration. Not loading the Logstash logging handlers module.
[DEBUG   ] Override  __grains__: <module 'salt.loaded.int.log_handlers.sentry_mod' from '/usr/local/lib/python3.8/site-packages/salt/log/handlers/sentry_mod.py'>
[DEBUG   ] Configuration file path: /usr/local/etc/salt/minion
[WARNING ] Insecure logging configuration detected! Sensitive data may be logged.
[DEBUG   ] Grains refresh requested. Refreshing grains.
[DEBUG   ] Reading configuration from /usr/local/etc/salt/minion
[DEBUG   ] Including configuration from '/usr/local/etc/salt/minion.d/_schedule.conf'
[DEBUG   ] Reading configuration from /usr/local/etc/salt/minion.d/_schedule.conf
[TRACE   ] 'dig' could not be found in the following search path: '['/sbin', '/bin', '/usr/sbin', '/usr/bin', '/usr/local/sbin', '/usr/local/bin', '/root/bin']'
[TRACE   ] 'nslookup' could not be found in the following search path: '['/sbin', '/bin', '/usr/sbin', '/usr/bin', '/usr/local/sbin', '/usr/local/bin', '/root/bin']'
[TRACE   ] 'dig' could not be found in the following search path: '['/sbin', '/bin', '/usr/sbin', '/usr/bin', '/usr/local/sbin', '/usr/local/bin', '/root/bin']'
[TRACE   ] 'nslookup' could not be found in the following search path: '['/sbin', '/bin', '/usr/sbin', '/usr/bin', '/usr/local/sbin', '/usr/local/bin', '/root/bin']'
[TRACE   ] Error loading grains.napalm: "napalm"" (/usr/local/lib/python3.8/site-packages/salt/grains/napalm.py) cannot be loaded: NAPALM is not installed: ``pip install napalm``
[TRACE   ] Error loading grains.nxos: No host specified and no UDS found at /tmp/nginx_local/nginx_1_be_nxapi.sock

[TRACE   ] Error loading grains.pending_reboot: 'pending_reboot' grain only available on Windows
[DEBUG   ] Override  __utils__: <module 'salt.loaded.int.grains.zfs' from '/usr/local/lib/python3.8/site-packages/salt/grains/zfs.py'>
[TRACE   ] Loading core.append_domain grain
[TRACE   ] Loading core.cwd grain
[TRACE   ] Loading core.default_gateway grain
[TRACE   ] 'ip' could not be found in the following search path: '['/sbin', '/bin', '/usr/sbin', '/usr/bin', '/usr/local/sbin', '/usr/local/bin', '/root/bin']'
[TRACE   ] Loading core.dns grain
[TRACE   ] Loading core.fqdns grain
[TRACE   ] 'ip' could not be found in the following search path: '['/sbin', '/bin', '/usr/sbin', '/usr/bin', '/usr/local/sbin', '/usr/local/bin', '/root/bin']'
[DEBUG   ] Unable to resolve address fe80::1: [Errno 1] Unknown host
[DEBUG   ] Elapsed time getting FQDNs: 0.029315710067749023 seconds
[TRACE   ] Loading core.get_machine_id grain
[TRACE   ] Loading core.get_master grain
[TRACE   ] Loading core.get_server_id grain
[TRACE   ] Loading core.hostname grain
[TRACE   ] Loading core.hwaddr_interfaces grain
[TRACE   ] Loading core.id_ grain
[TRACE   ] Loading core.ip4_interfaces grain
[TRACE   ] Loading core.ip6_interfaces grain
[TRACE   ] Loading core.ip_fqdn grain
[TRACE   ] 'ip' could not be found in the following search path: '['/sbin', '/bin', '/usr/sbin', '/usr/bin', '/usr/local/sbin', '/usr/local/bin', '/root/bin']'
[TRACE   ] 'ip' could not be found in the following search path: '['/sbin', '/bin', '/usr/sbin', '/usr/bin', '/usr/local/sbin', '/usr/local/bin', '/root/bin']'
[TRACE   ] Loading core.ip_interfaces grain
[TRACE   ] Loading core.kernelparams grain
[TRACE   ] Loading core.locale_info grain
[TRACE   ] Loading core.os_data grain
[TRACE   ] 'arch' could not be found in the following search path: '['/sbin', '/bin', '/usr/sbin', '/usr/bin', '/usr/local/sbin', '/usr/local/bin', '/root/bin']'
[TRACE   ] 'dmidecode' could not be found in the following search path: '['/sbin', '/bin', '/usr/sbin', '/usr/bin', '/usr/local/sbin', '/usr/local/bin', '/root/bin']'
[TRACE   ] 'smbios' could not be found in the following search path: '['/sbin', '/bin', '/usr/sbin', '/usr/bin', '/usr/local/sbin', '/usr/local/bin', '/root/bin']'
[TRACE   ] 'fw_printenv' could not be found in the following search path: '['/sbin', '/bin', '/usr/sbin', '/usr/bin', '/usr/local/sbin', '/usr/local/bin', '/root/bin']'
[TRACE   ] 'virt-what' could not be found in the following search path: '['/sbin', '/bin', '/usr/sbin', '/usr/bin', '/usr/local/sbin', '/usr/local/bin', '/root/bin']'
[TRACE   ] 'systemd-detect-virt' could not be found in the following search path: '['/sbin', '/bin', '/usr/sbin', '/usr/bin', '/usr/local/sbin', '/usr/local/bin', '/root/bin']'
[TRACE   ] 'virt-what' could not be found in the following search path: '['/sbin', '/bin', '/usr/sbin', '/usr/bin', '/usr/local/sbin', '/usr/local/bin', '/root/bin']'
[TRACE   ] 'dmidecode' could not be found in the following search path: '['/sbin', '/bin', '/usr/sbin', '/usr/bin', '/usr/local/sbin', '/usr/local/bin', '/root/bin']'
[TRACE   ] Loading core.path grain
[TRACE   ] Loading core.pythonexecutable grain
[TRACE   ] Loading core.pythonpath grain
[TRACE   ] Loading core.pythonversion grain
[TRACE   ] Loading core.saltpath grain
[TRACE   ] Loading core.saltversion grain
[TRACE   ] Loading core.saltversioninfo grain
[TRACE   ] Loading core.zmqversion grain
[TRACE   ] Loading disks.disks grain
[TRACE   ] Loading extra.config grain
[TRACE   ] Loading extra.shell grain
[TRACE   ] Loading extra.transactional grain
[TRACE   ] 'transactional-update' could not be found in the following search path: '['/sbin', '/bin', '/usr/sbin', '/usr/bin', '/usr/local/sbin', '/usr/local/bin', '/root/bin']'
[TRACE   ] Loading extra.uefi grain
[TRACE   ] Loading lvm.lvm grain
[TRACE   ] LVM grain does not support this OS
[TRACE   ] Loading mdadm.mdadm grain
[TRACE   ] Loading minion_process.grains grain
[TRACE   ] Loading opts.opts grain
[TRACE   ] Loading zfs.zfs grain
[DEBUG   ] LazyLoaded zfs.is_supported
[INFO    ] Executing command '/sbin/zpool' in directory '/root'
[DEBUG   ] output:
[DEBUG   ] Connecting to master. Attempt 1 of 1
[DEBUG   ] "salt" Not an IP address? Assuming it is a hostname.
[DEBUG   ] Master URI: tcp://192.168.10.98:4506
[DEBUG   ] Initializing new AsyncAuth for ('/usr/local/etc/salt/pki/minion', 'unbound', 'tcp://192.168.10.98:4506')
[DEBUG   ] Generated random reconnect delay between '1000ms' and '11000ms' (6232)
[DEBUG   ] Setting zmq_reconnect_ivl to '6232ms'
[DEBUG   ] Setting zmq_reconnect_ivl_max to '11000ms'
[DEBUG   ] Connecting the Minion to the Master URI (for the return server): tcp://192.168.10.98:4506
[DEBUG   ] Trying to connect to: tcp://192.168.10.98:4506
[DEBUG   ] salt.crypt.get_rsa_pub_key: Loading public key
[DEBUG   ] Decrypting the current master AES key
[DEBUG   ] salt.crypt.get_rsa_key: Loading private key
[DEBUG   ] salt.crypt._get_key_with_evict: Loading private key
[DEBUG   ] Loaded minion key: /usr/local/etc/salt/pki/minion/minion.pem
[DEBUG   ] salt.crypt.get_rsa_pub_key: Loading public key
[DEBUG   ] Closing AsyncZeroMQReqChannel instance
[DEBUG   ] Connecting the Minion to the Master publish port, using the URI: tcp://192.168.10.98:4505
[DEBUG   ] salt.crypt.get_rsa_key: Loading private key
[DEBUG   ] Loaded minion key: /usr/local/etc/salt/pki/minion/minion.pem
[DEBUG   ] Determining pillar cache
[DEBUG   ] Initializing new AsyncAuth for ('/usr/local/etc/salt/pki/minion', 'unbound', 'tcp://192.168.10.98:4506')
[DEBUG   ] Connecting the Minion to the Master URI (for the return server): tcp://192.168.10.98:4506
[DEBUG   ] Trying to connect to: tcp://192.168.10.98:4506
[TRACE   ] ext_pillar_extra_data = {}
[DEBUG   ] salt.crypt.get_rsa_key: Loading private key
[DEBUG   ] Loaded minion key: /usr/local/etc/salt/pki/minion/minion.pem
[DEBUG   ] Closing AsyncZeroMQReqChannel instance
[DEBUG   ] Using importlib_metadata to load entry points
[DEBUG   ] LazyLoaded jinja.render
[DEBUG   ] LazyLoaded yaml.render
[TRACE   ] Loaded cmdmod as virtual cmd
[DEBUG   ] LazyLoaded cmd.run
[DEBUG   ] LazyLoaded direct_call.execute
[DEBUG   ] LazyLoaded config.get
[INFO    ] Executing command 'pkg' as user 'unbound' in directory '/var/unbound'
[DEBUG   ] env command: ('su', '-', 'unbound', '-c', '/bin/csh -c /usr/local/bin/python3.8')
[ERROR   ] Environment could not be retrieved for user 'unbound': stderr='' stdout='This account is currently not available.\n'
[DEBUG   ] stdout: [TRACE   ] Trying os.getgrouplist for 'unbound'
[TRACE   ] Group list for user 'unbound': ['unbound']
ca_root_nss-3.71               Root certificate bundle from the Mozilla Project
curl-7.80.0                    Command line tool and library for transferring data with URLs
expat-2.4.1                    XML 1.0 parser written in C
gettext-runtime-0.21           GNU gettext runtime libraries and programs
git-2.34.1                     Distributed source code management tool
[DEBUG   ] output: [TRACE   ] Trying os.getgrouplist for 'unbound'
[TRACE   ] Group list for user 'unbound': ['unbound']
ca_root_nss-3.71               Root certificate bundle from the Mozilla Project
curl-7.80.0                    Command line tool and library for transferring data with URLs
expat-2.4.1                    XML 1.0 parser written in C
gettext-runtime-0.21           GNU gettext runtime libraries and programs
git-2.34.1                     Distributed source code management tool
[DEBUG   ] Initializing new AsyncAuth for ('/usr/local/etc/salt/pki/minion', 'unbound', 'tcp://192.168.10.98:4506')
[DEBUG   ] Connecting the Minion to the Master URI (for the return server): tcp://192.168.10.98:4506
[DEBUG   ] Trying to connect to: tcp://192.168.10.98:4506
[DEBUG   ] Closing AsyncZeroMQReqChannel instance
[DEBUG   ] LazyLoaded nested.output
[TRACE   ] data = {'local': "[TRACE   ] Trying os.getgrouplist for 'unbound'\n[TRACE   ] Group list for user 'unbound': ['unbound']\nca_root_nss-3.71               Root certificate bundle from the Mozilla Project\ncurl-7.80.0                    Command line tool and library for transferring data with URLs\nexpat-2.4.1                    XML 1.0 parser written in C\ngettext-runtime-0.21           GNU gettext runtime libraries and programs\ngit-2.34.1                     Distributed source code management tool"}
local:
    [TRACE   ] Trying os.getgrouplist for 'unbound'
    [TRACE   ] Group list for user 'unbound': ['unbound']
    ca_root_nss-3.71               Root certificate bundle from the Mozilla Project
    curl-7.80.0                    Command line tool and library for transferring data with URLs
    expat-2.4.1                    XML 1.0 parser written in C
    gettext-runtime-0.21           GNU gettext runtime libraries and programs
    git-2.34.1                     Distributed source code management tool

This looks odd

[INFO    ] Executing command 'pkg' as user 'unbound' in directory '/var/unbound'
[DEBUG   ] env command: ('su', '-', 'unbound', '-c', '/bin/csh -c /usr/local/bin/python3.8')
[ERROR   ] Environment could not be retrieved for user 'unbound': stderr='' stdout='This account is currently not available.\n'
[DEBUG   ] stdout: [TRACE   ] Trying os.getgrouplist for 'unbound'
[TRACE   ] Group list for user 'unbound': ['unbound']

Expected behavior

local:
    ca_root_nss-3.71               Root certificate bundle from the Mozilla Project
    curl-7.80.0                    Command line tool and library for transferring data with URLs
    expat-2.4.1                    XML 1.0 parser written in C
    gettext-runtime-0.21           GNU gettext runtime libraries and programs
    git-2.34.1                     Distributed source code management tool

Screenshots
If applicable, add screenshots to help explain your problem.

**Versions Report**
root@unbound:~ # salt-call cmd.run "pkg info | head -5" runas=unbound -l trace
root@unbound:~ # salt -V
Salt Version:
          Salt: 3004

Dependency Versions:
          cffi: 1.15.0
      cherrypy: Not Installed
      dateutil: Not Installed
     docker-py: Not Installed
         gitdb: Not Installed
     gitpython: Not Installed
        Jinja2: 3.0.1
       libgit2: Not Installed
      M2Crypto: Not Installed
          Mako: Not Installed
       msgpack: 1.0.2
  msgpack-pure: Not Installed
  mysql-python: Not Installed
     pycparser: 2.21
      pycrypto: Not Installed
  pycryptodome: 3.10.1
        pygit2: Not Installed
        Python: 3.8.12 (default, Nov  6 2021, 01:10:35)
  python-gnupg: Not Installed
        PyYAML: 5.4.1
         PyZMQ: 22.3.0
         smmap: Not Installed
       timelib: Not Installed
       Tornado: 4.5.3
           ZMQ: 4.3.4

System Versions:
          dist: freebsd 13.0
        locale: utf-8
       machine: amd64
       release: 13.0-RELEASE-p4
        system: FreeBSD
       version: FreeBSD 13.0

[garethgreenaway]

@network-shark Thanks for the report. Do you see the same results with the logging if you're not using runas?

[network-shark]

@garethgreenaway Luckily the error still occurs . If I run the command without runas like this .

unbound# salt-call cmd.run "pkg info | head -5" -l trace

The output is normal and not mixed up.

I thought a bit about it and compared the my environments . root / unbound

The Problem is that I can't run a shell with the unbound user .

unbound:*:59:59:Unbound DNS Resolver:/var/unbound:/usr/sbin/nologin

It is silly what I did there , but maybe this should throw an error and I still think the output should not mix up.

[s0undt3ch]

What seems to be happening here is that Salt is printing output before the logging system has had time to flush(and print) all the log messages, in particular, because the TRACE log level is being asked.

Fixing this would require some changes on Salt's CLI to make sure that the logging system is completely shutdown before anything is printed.

[s0undt3ch]

Also, if you need "clean" output, Salt prints to stdout while logging prints to stderr. Try just to capture stdout.