[BUG] Running master as non-root user fail with logging exceptions when exiting with control-c

[dnessett]

Description
Running salt-master as non-root user, then exiting using control-c results in logging exeptions.

Setup
Follow the instructions here: Running Development Salt to run the salt-master with the following master configuration file:

user: username
root_dir: Salt-source-directory/local/etc/salt
publish_port: 55505
ret_port: 55506
master_sign_pubkey: True

This works. But, terminating the run using a control-c results in logging exceptions.

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
• classic packaging
• onedir packaging
• used bootstrap to install

Steps to Reproduce the behavior
Setup the environment according to Running Development Salt. Running in the salt/scripts directory, execute the salt-master with the following terminal command:
salt-master --config-dir=../local/etc/salt/ --log-level=debug
Allow the salt-master to complete its setup and then control-c. The execution fails with the following traceback information:

[DEBUG ] This salt-master instance has accepted 0 minion keys.
^C[INFO ] MWorkerQueue under PID 34961 is closing
[INFO ] MWorkerQueue under PID 34952 is closing
[DEBUG ] Maintenance received a SIGINT. Exiting
[DEBUG ] RequestServer received a SIGINT. Exiting
--- Logging error ---
[DEBUG ] MWorker received a SIGINT. Exiting
Traceback (most recent call last):
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/logging/init.py", line 1103, in emit
stream.write(msg + self.terminator)
RuntimeError: reentrant call inside <_io.BufferedWriter name=''>

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/logging/init.py", line 1103, in emit
stream.write(msg + self.terminator)
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/transport/zeromq.py", line 464, in _handle_signals
log.debug(msg)
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/logging/init.py", line 1465, in debug
self._log(DEBUG, msg, args, **kwargs)
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/_logging/impl.py", line 294, in _log
LOGGING_LOGGER_CLASS._log(
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/logging/init.py", line 1624, in _log
self.handle(record)
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/logging/init.py", line 1634, in handle
self.callHandlers(record)
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/logging/init.py", line 1696, in callHandlers
hdlr.handle(record)
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/logging/init.py", line 968, in handle
self.emit(record)
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/logging/init.py", line 1108, in emit
self.handleError(record)
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/logging/init.py", line 1021, in handleError
sys.stderr.write('--- Logging error ---\n')
RuntimeError: reentrant call inside <_io.BufferedWriter name=''>
Call stack:
[DEBUG ] EventPublisher received a SIGINT. Exiting
[DEBUG ] RequestServer received a SIGINT. Exiting
[INFO ] MWorkerQueue under PID 34950 is closing
[DEBUG ] RequestServer received a SIGTERM. Exiting
[INFO ] MWorkerQueue under PID 34951 is closing
--- Logging error ---
[INFO ] MWorkerQueue under PID 34960 is closing
[DEBUG ] MWorker received a SIGINT. Exiting
[DEBUG ] MWorker received a SIGINT. Exiting
[INFO ] MWorkerQueue under PID 34962 is closing
--- Logging error ---
Traceback (most recent call last):
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/logging/init.py", line 1103, in emit
stream.write(msg + self.terminator)
RuntimeError: reentrant call inside <_io.BufferedWriter name=''>

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/logging/init.py", line 1103, in emit
stream.write(msg + self.terminator)
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/master.py", line 999, in _handle_signals
super()._handle_signals(signum, sigframe)
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/utils/process.py", line 1076, in _handle_signals
log.debug(msg)
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/logging/init.py", line 1465, in debug
self._log(DEBUG, msg, args, **kwargs)
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/_logging/impl.py", line 294, in _log
LOGGING_LOGGER_CLASS._log(
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/logging/init.py", line 1624, in _log
self.handle(record)
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/logging/init.py", line 1634, in handle
self.callHandlers(record)
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/logging/init.py", line 1696, in callHandlers
hdlr.handle(record)
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/logging/init.py", line 968, in handle
self.emit(record)
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/logging/init.py", line 1108, in emit
self.handleError(record)
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/logging/init.py", line 1021, in handleError
sys.stderr.write('--- Logging error ---\n')
RuntimeError: reentrant call inside <_io.BufferedWriter name=''>
Call stack:
Traceback (most recent call last):
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/logging/init.py", line 1103, in emit
stream.write(msg + self.terminator)
RuntimeError: reentrant call inside <_io.BufferedWriter name=''>

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/logging/init.py", line 1103, in emit
stream.write(msg + self.terminator)
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/master.py", line 999, in _handle_signals
super()._handle_signals(signum, sigframe)
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/utils/process.py", line 1076, in _handle_signals
log.debug(msg)
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/logging/init.py", line 1465, in debug
self._log(DEBUG, msg, args, **kwargs)
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/_logging/impl.py", line 294, in _log
LOGGING_LOGGER_CLASS._log(
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/logging/init.py", line 1624, in _log
self.handle(record)
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/logging/init.py", line 1634, in handle
self.callHandlers(record)
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/logging/init.py", line 1696, in callHandlers
hdlr.handle(record)
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/logging/init.py", line 968, in handle
self.emit(record)
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/logging/init.py", line 1108, in emit
self.handleError(record)
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/logging/init.py", line 1021, in handleError
sys.stderr.write('--- Logging error ---\n')
RuntimeError: reentrant call inside <_io.BufferedWriter name=''>
Call stack:
File "/home/dan/.pyenv/versions/salt/bin/salt-master", line 8, in
sys.exit(salt_master())
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/scripts.py", line 86, in salt_master
master.start()
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/cli/daemons.py", line 203, in start
self.master.start()
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/master.py", line 797, in start
self.process_manager.add_process(
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/utils/process.py", line 532, in add_process
process.start()
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/utils/process.py", line 1120, in start
super().start()
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/multiprocessing/process.py", line 121, in start
self._popen = self._Popen(self)
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/multiprocessing/context.py", line 224, in _Popen
return _default_context.get_context().Process._Popen(process_obj)
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/multiprocessing/context.py", line 281, in _Popen
return Popen(process_obj)
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/multiprocessing/popen_fork.py", line 19, in init
self._launch(process_obj)
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/multiprocessing/popen_fork.py", line 71, in _launch
code = process_obj._bootstrap(parent_sentinel=child_r)
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/multiprocessing/process.py", line 314, in _bootstrap
self.run()
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/utils/process.py", line 999, in wrapped_run_func
return run_func()
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/master.py", line 927, in run
self.__bind()
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/master.py", line 916, in __bind
self.process_manager.add_process(
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/utils/process.py", line 532, in add_process
process.start()
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/utils/process.py", line 1120, in start
super().start()
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/multiprocessing/process.py", line 121, in start
self._popen = self._Popen(self)
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/multiprocessing/context.py", line 224, in _Popen
return _default_context.get_context().Process._Popen(process_obj)
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/multiprocessing/context.py", line 281, in _Popen
return Popen(process_obj)
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/multiprocessing/popen_fork.py", line 19, in init
self._launch(process_obj)
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/multiprocessing/popen_fork.py", line 71, in _launch
code = process_obj._bootstrap(parent_sentinel=child_r)
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/multiprocessing/process.py", line 314, in _bootstrap
self.run()
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/utils/process.py", line 999, in wrapped_run_func
return run_func()
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/master.py", line 1158, in run
self.__bind()
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/master.py", line 1012, in __bind
self.io_loop.start()
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/ext/tornado/ioloop.py", line 865, in start
event_pairs = self._impl.poll(poll_timeout)
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/master.py", line 987, in _handle_signals
channel.close()
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/channel/server.py", line 733, in close
self.transport.close()
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/transport/zeromq.py", line 365, in close
log.info("MWorkerQueue under PID %s is closing", os.getpid())
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/logging/init.py", line 1477, in info
self._log(INFO, msg, args, **kwargs)
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/_logging/impl.py", line 294, in _log
LOGGING_LOGGER_CLASS._log(
Message: 'MWorkerQueue under PID %s is closing'
Arguments: (34951,)
[DEBUG ] MWorker received a SIGINT. Exiting
File "/home/dan/.pyenv/versions/salt/bin/salt-master", line 8, in
sys.exit(salt_master())
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/scripts.py", line 86, in salt_master
master.start()
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/cli/daemons.py", line 203, in start
self.master.start()
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/master.py", line 797, in start
self.process_manager.add_process(
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/utils/process.py", line 532, in add_process
process.start()
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/utils/process.py", line 1120, in start
super().start()
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/multiprocessing/process.py", line 121, in start
self._popen = self._Popen(self)
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/multiprocessing/context.py", line 224, in _Popen
return _default_context.get_context().Process._Popen(process_obj)
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/multiprocessing/context.py", line 281, in _Popen
return Popen(process_obj)
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/multiprocessing/popen_fork.py", line 19, in init
self._launch(process_obj)
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/multiprocessing/popen_fork.py", line 71, in _launch
code = process_obj._bootstrap(parent_sentinel=child_r)
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/multiprocessing/process.py", line 314, in _bootstrap
self.run()
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/utils/process.py", line 999, in wrapped_run_func
return run_func()
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/master.py", line 927, in run
self.__bind()
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/master.py", line 916, in __bind
self.process_manager.add_process(
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/utils/process.py", line 532, in add_process
process.start()
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/utils/process.py", line 1120, in start
super().start()
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/multiprocessing/process.py", line 121, in start
self._popen = self._Popen(self)
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/multiprocessing/context.py", line 224, in _Popen
return _default_context.get_context().Process._Popen(process_obj)
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/multiprocessing/context.py", line 281, in _Popen
return Popen(process_obj)
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/multiprocessing/popen_fork.py", line 19, in init
self._launch(process_obj)
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/multiprocessing/popen_fork.py", line 71, in _launch
code = process_obj._bootstrap(parent_sentinel=child_r)
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/multiprocessing/process.py", line 314, in _bootstrap
self.run()
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/utils/process.py", line 999, in wrapped_run_func
return run_func()
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/master.py", line 1158, in run
self.__bind()
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/master.py", line 1012, in __bind
self.io_loop.start()
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/ext/tornado/ioloop.py", line 865, in start
event_pairs = self._impl.poll(poll_timeout)
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/master.py", line 987, in _handle_signals
channel.close()
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/channel/server.py", line 733, in close
self.transport.close()
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/transport/zeromq.py", line 365, in close
log.info("MWorkerQueue under PID %s is closing", os.getpid())
File "/home/dan/.pyenv/versions/3.10.15/lib/python3.10/logging/init.py", line 1477, in info
self._log(INFO, msg, args, **kwargs)
File "/home/dan/.pyenv/versions/salt/lib/python3.10/site-packages/salt/_logging/impl.py", line 294, in _log
LOGGING_LOGGER_CLASS._log(
Message: 'MWorkerQueue under PID %s is closing'
Arguments: (34962,)
[DEBUG ] MWorker received a SIGINT. Exiting
[DEBUG ] ReqServer received a SIGINT. Exiting
[DEBUG ] FileserverUpdate received a SIGINT. Exiting
[WARNING ] Master received a SIGINT. Exiting.
[INFO ] The Salt Master is shut down
The salt master is shutdown. Master received a SIGINT. Exited.

Expected behavior
There should be a clean shutdown of the salt-master without any logging execeptions

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

Versions Report

salt --versions-report

Salt Version:
          Salt: 3006.9+453.g9e82700d97
 
Python Version:
        Python: 3.10.15 (main, Jan 12 2025, 17:52:40) [GCC 13.3.0]
 
Dependency Versions:
          cffi: 1.17.1
      cherrypy: 18.10.0
  cryptography: 44.0.0
      dateutil: 2.9.0.post0
     docker-py: Not Installed
         gitdb: Not Installed
     gitpython: Not Installed
        Jinja2: 3.1.5
       libgit2: Not Installed
  looseversion: 1.3.0
      M2Crypto: Not Installed
          Mako: Not Installed
       msgpack: 1.1.0
  msgpack-pure: Not Installed
  mysql-python: Not Installed
     packaging: 24.2
     pycparser: 2.22
      pycrypto: Not Installed
  pycryptodome: 3.21.0
        pygit2: Not Installed
  python-gnupg: 0.5.4
        PyYAML: 6.0.2
         PyZMQ: 26.2.0
        relenv: Not Installed
         smmap: Not Installed
       timelib: 0.3.0
       Tornado: 4.5.3
           ZMQ: 4.3.5
 
System Versions:
          dist: linuxmint 22 wilma
        locale: utf-8
       machine: x86_64
       release: 6.8.0-51-generic
        system: Linux
       version: Linux Mint 22 wilma

Additional context
I attempted to analyze the problem, but found myself in parts of the code that I did not understand. However, here is what I discovered. I used Eclipse/PyDev to get some context. The failure occured when some of the MWorkerQueue processes received the control-c. From the logging failure message (see gist referenced below), it appears the MWorkerQueue process is running FileserverUpdate. The failure occured in salt/utils/process.py in the kill_children method of the ProcessManager class. In this gist salt-master-control-c-failure I have included the place in which the kill_children method starts the logging logic, the stack when the emit fails and the logging message that would have been output by the emit if it had not failed . By the way, I discovered this problem while working on bug #67214.