salt
salt copied to clipboard
saltstack
[BUG] FreeBSD debug output gets merged when using runas
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
- [x] 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
- [x] 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
@network-shark Thanks for the report. Do you see the same results with the logging if you're not using runas?
@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.
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.
Also, if you need "clean" output, Salt prints to stdout while logging prints to stderr. Try just to capture stdout.