[BUG] State cmd.script with parallel set to true hangs in 3006.5

[johje349]

Description
After upgrading from 3006.3 to 3006.5 we started seeing hanging minion processes consuming 100% CPU.
Narrowed it down to salt.script states with parallel: True.

Setup
SLS:

test:
  cmd.script:
    - source: salt://scripts/test.sh
    - name: test.sh 
    - shell: /bin/bash
    - parallel: True

Script:

#!/bin/bash

echo "test"

exit 0

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
salt 'asx-test' state.apply test

Relevant minion log on asx-test:

2023-12-15 15:57:17,948 [salt.fileclient  :1363][INFO    ][270247] Fetching file from saltenv 'base', ** done ** 'test/init.sls'
2023-12-15 15:57:17,948 [salt.template    :53  ][DEBUG   ][270247] compile template: /var/cache/salt/minion/files/base/test/init.sls
2023-12-15 15:57:17,949 [salt.utils.jinja :79  ][DEBUG   ][270247] Jinja search path: ['/var/cache/salt/minion/files/base']
2023-12-15 15:57:17,952 [salt.template    :23  ][PROFILE ][270247] Time (in seconds) to render '/var/cache/salt/minion/files/base/test/init.sls' using 'jinja' renderer: 0.003893613815307617
2023-12-15 15:57:17,953 [salt.template    :116 ][DEBUG   ][270247] Rendered data from file: /var/cache/salt/minion/files/base/test/init.sls:
test:
  cmd.script:
    - source: salt://scripts/test.sh
    - name: test.sh 
    - shell: /bin/bash
    - parallel: True

2023-12-15 15:57:17,954 [salt.template    :23  ][PROFILE ][270247] Time (in seconds) to render '/var/cache/salt/minion/files/base/test/init.sls' using 'yaml' renderer: 0.0012822151184082031
2023-12-15 15:57:17,955 [salt.loader.lazy :977 ][DEBUG   ][270247] The functions from module 'config' are being loaded by dir() on the loaded module
2023-12-15 15:57:17,955 [salt.utils.lazy  :99  ][DEBUG   ][270247] LazyLoaded config.option
2023-12-15 15:57:17,956 [salt.loader.lazy :977 ][DEBUG   ][270247] The functions from module 'cmd' are being loaded by dir() on the loaded module
2023-12-15 15:57:17,956 [salt.utils.lazy  :99  ][DEBUG   ][270247] LazyLoaded cmd.script
2023-12-15 15:57:17,956 [salt.state       :2295][INFO    ][270247] Running state [test.sh] at time 15:57:17.956921
2023-12-15 15:57:17,957 [salt.state       :2326][INFO    ][270247] Executing state cmd.script for [test.sh]
2023-12-15 15:57:17,961 [salt.state       :321 ][INFO    ][270247] Started in a separate process
2023-12-15 15:57:17,962 [salt.state       :2493][INFO    ][270247] Completed state [test.sh] at time 15:57:17.962736 (duration_in_ms=5.81)
2023-12-15 15:57:17,968 [salt.loaded.int.log_handlers.fluent_mod:32  ][TRACE   ][270261] The required configuration section, 'fluent_handler', was not found the in the configuration. Not loading the fluent logging handlers module.
2023-12-15 15:57:17,971 [salt.loaded.int.log_handlers.logstash_mod:32  ][TRACE   ][270261] 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.
2023-12-15 15:57:17,972 [salt.loader.lazy :32  ][TRACE   ][270261] Error loading log_handlers.sentry_mod: Cannot find 'raven' python library, 'sentry_handler' config is empty or not defined
2023-12-15 15:57:17,975 [salt.loader.lazy :32  ][TRACE   ][270261] Loaded cmdmod as virtual cmd
2023-12-15 15:57:17,976 [salt.loader.lazy :977 ][DEBUG   ][270261] The functions from module 'cmd' are being loaded by dir() on the loaded module
2023-12-15 15:57:17,976 [salt.utils.lazy  :99  ][DEBUG   ][270261] LazyLoaded cmd.script
2023-12-15 15:57:17,977 [salt.loader.lazy :977 ][DEBUG   ][270261] The functions from module 'cp' are being loaded by dir() on the loaded module
2023-12-15 15:57:17,978 [salt.utils.lazy  :99  ][DEBUG   ][270261] LazyLoaded cp.cache_file
2023-12-15 15:57:17,979 [salt.channel.client:32  ][TRACE   ][270261] ReqChannel send crypt load={'path': 'scripts/test.sh', 'saltenv': 'base', 'cmd': '_file_hash'}

Silent for process 270261 after that.

top output for process 270261:

PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND                                                                                                                   
270261 root      20   0  627832  58188   6368 S 100.0   0.0   4:29.45 /opt/saltstack/ 

root 270261 270247 99 15:57 ? 00:05:22 /opt/saltstack/salt/bin/python3.10 /usr/bin/salt-minion MultiMinionProcessManager MinionProcessManager ProcessPayload(jid=20231215145716488579) Minion._thread_return ParallelState(test.sh)

Expected behavior
Expect state.apply to return

Versions Report

Salt Version:
          Salt: 3006.5
 
Python Version:
        Python: 3.10.13 (main, Nov 15 2023, 04:34:27) [GCC 11.2.0]
 
Dependency Versions:
          cffi: 1.14.6
      cherrypy: unknown
      dateutil: 2.8.1
     docker-py: Not Installed
         gitdb: Not Installed
     gitpython: Not Installed
        Jinja2: 3.1.2
       libgit2: Not Installed
  looseversion: 1.0.2
      M2Crypto: Not Installed
          Mako: Not Installed
       msgpack: 1.0.2
  msgpack-pure: Not Installed
  mysql-python: Not Installed
     packaging: 22.0
     pycparser: 2.21
      pycrypto: Not Installed
  pycryptodome: 3.9.8
        pygit2: Not Installed
  python-gnupg: 0.4.8
        PyYAML: 6.0.1
         PyZMQ: 23.2.0
        relenv: 0.14.2
         smmap: Not Installed
       timelib: 0.2.4
       Tornado: 4.5.3
           ZMQ: 4.3.4
 
System Versions:
          dist: ubuntu 16.04.3 jammy
        locale: utf-8
       machine: x86_64
       release: 5.15.0-88-generic
        system: Linux
       version: Ubuntu 16.04.3 jammy

[eg-ma]

I can reproduce this, and am having the same problem with file.managed states. Oracle Linux 8.9.

[eg-ma]

Can reproduce in 3006.7. Oracle Linux 8.9.

[dmurphy18]

@johje349 This is on Ubuntu 16.04, can you confirm this is an issue on an OS which is currently supported and not itself EOL or is there a typo here 16.04 and jammy ?? not Xenial - something weird going on there - wonders what other strangeness could be occurring for an OS so EOL

[dmurphy18]

Tried this with latest Salt 3007.0 on Centos 8 and able to reproduce when issuing the command from a salt-master, however the same command using salt-call succeeded before installing a salt-master :

• salt-call --local state.apply test

After running from a salt-master, even the local salt-call now fails (after a Crtl-C of salt command from salt-master)

[DEBUG   ] The functions from module 'config' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded config.option
[DEBUG   ] The functions from module 'saltutil' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded saltutil.is_running
[DEBUG   ] The functions from module 'highstate' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded highstate.output
[TRACE   ] data = {'local': ['The function "state.apply" is running as PID 14127 and was started at 2024, Mar 20 16:56:15.055554 with jid 20240320165615055554']}
local:
    Data failed to compile:
----------
    The function "state.apply" is running as PID 14127 and was started at 2024, Mar 20 16:56:15.055554 with jid 20240320165615055554

even after a long systemctl restart salt-minion, the above command still fails the same

Interestingly this may be due to a problem, given that systemctl stop salt-minion still leaves processes running, including the PID 14127 which is still running even after the 'stop'

Once killed all salt-minion processes, then the salt-call --local command worked correctly

[DEBUG   ] File /var/cache/salt/minion/accumulator/140237358224416 does not exist, no need to cleanup
[DEBUG   ] The functions from module 'state' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded state.check_result
[DEBUG   ] The functions from module 'highstate' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded highstate.output
[DEBUG   ] The functions from module 'nested' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded nested.output
[TRACE   ] data = {'local': {'cmd_|-test_|-test.sh_|-script': {'name': 'test.sh', 'result': True, 'changes': {'pid': 20610, 'retcode': 0, 'stdout': 'test', 'stderr': ''}, 'comment': "Command 'test.sh' run", '__sls__': 'test', '__run_num__': 0, 'start_time': '11:14:11.568821', 'duration': '24.261 ms', '__id__': 'test', '__parallel__': True}}}
local:
----------
          ID: test
    Function: cmd.script
        Name: test.sh
      Result: True
     Comment: Command 'test.sh' run
     Started: 11:14:11.568821
    Duration: 24.261 ms
     Changes:   
              ----------
              pid:
                  20610
              retcode:
                  0
              stderr:
              stdout:
                  test

Summary for local
------------
Succeeded: 1 (changed=1)
Failed:    0
------------
Total states run:     1
Total run time:  24.261 ms
[root@Unknown salt]# 

[dmurphy18]

looks like hitting the race condition in process killing children (circa line 700) and not handling nicely

[dmurphy18]

problematic code (at the moment) appears to be here

salt/salt/state.py

Lines 2257 to 2288 in 66bb993

	def call_parallel(self, cdata, low):
	"""
	Call the state defined in the given cdata in parallel
	"""
	# There are a number of possibilities to not have the cdata
	# populated with what we might have expected, so just be smart
	# enough to not raise another KeyError as the name is easily
	# guessable and fallback in all cases to present the real
	# exception to the user
	name = (cdata.get("args") or [None])[0] or cdata["kwargs"].get("name")
	if not name:
	name = low.get("name", low.get("__id__"))
	if salt.utils.platform.spawning_platform():
	instance = None
	else:
	instance = self
	proc = salt.utils.process.Process(
	target=self._call_parallel_target,
	args=(instance, self._init_kwargs, name, cdata, low),
	name=f"ParallelState({name})",
	)
	proc.start()
	ret = {
	"name": name,
	"result": None,
	"changes": {},
	"comment": "Started in a separate process",
	"proc": proc,
	}
	return ret

where not returning after the proc.start(), that is, code does not progress

[johje349]

@johje349 This is on Ubuntu 16.04, can you confirm this is an issue on an OS which is currently supported and not itself EOL or is there a typo here 16.04 and jammy ?? not Xenial - something weird going on there - wonders what other strangeness could be occurring for an OS so EOL

Actually this is on Ubuntu 22:
cat /etc/issue
Ubuntu 22.04.3 LTS \n \l

Salt versions-report reports Ubuntu 16 for some reason:
salt --versions-report | grep dist
dist: ubuntu 16.04.3 jammy`

[dmurphy18]

The problem appears to be due a request for the cp.cache_file to the master getting lost since the parallel task has different pid etc, and gets lost in woodwork :( , see instrumented log

2024-04-03 14:05:46,852 [salt.state       :2163][WARNING ][43416] DGM _call_parallel_target pre-instance states call, cdata '{'full': 'cmd.script', 'args': ['test.sh'], 'kwargs': {'success_s    tderr': None, 'success_stdout': None, 'success_retcodes': None, 'context': None, 'defaults': None, 'hide_output': False, 'output_loglevel': 'debug', 'use_vt': False, 'timeout': None, 'statef    ul': False, 'env': None, 'shell': '/bin/bash', 'password': None, 'runas': None, 'cwd': None, 'template': None, 'source': 'salt://scripts/test.sh'}}', tag 'cmd_|-test_|-test.sh_|-script'
547 2024-04-03 14:05:46,855 [salt.loader.lazy :32  ][TRACE   ][43416] Loaded cmdmod as virtual cmd
548 2024-04-03 14:05:46,855 [salt.loader.lazy :960 ][DEBUG   ][43416] The functions from module 'cmd' are being loaded by dir() on the loaded module
549 2024-04-03 14:05:46,858 [salt.utils.lazy  :99  ][DEBUG   ][43416] LazyLoaded cmd.script
550 
551 2024-04-03 14:05:46,859 [salt.loaded.int.module.cmdmod:2856][WARNING ][43416] DGM cmd script entry, source 'salt://scripts/test.sh', args 'None', cwd 'None', stdin 'None', runas 'None', grou    p 'None', shell '/bin/bash', python_shell 'True', env 'None', template 'None', umask 'None', output_encoding 'None', output_loglevel 'debug', log_callback 'None', hide_output 'False', timeou    t 'None', reset_system_locale 'True', saltenv 'base', use_vt 'False', bg 'False', password 'None', success_retcodes 'None', success_stdout 'None', success_stderr 'None', kwargs '{'context':     {}}'
552 2024-04-03 14:05:46,859 [salt.loaded.int.module.cmdmod:2880][WARNING ][43416] DGM cmd script 1
553 2024-04-03 14:05:46,859 [salt.loaded.int.module.cmdmod:2890][WARNING ][43416] DGM cmd script 2
554 2024-04-03 14:05:46,860 [salt.loaded.int.module.cmdmod:2896][WARNING ][43416] DGM cmd script 3
555 2024-04-03 14:05:46,860 [salt.loaded.int.module.cmdmod:2916][WARNING ][43416] DGM cmd script - no template, source 'salt://scripts/test.sh', saltenv 'base'
556 2024-04-03 14:05:46,862 [salt.loader.lazy :960 ][DEBUG   ][43416] The functions from module 'cp' are being loaded by dir() on the loaded module
557 2024-04-03 14:05:46,863 [salt.utils.lazy  :99  ][DEBUG   ][43416] LazyLoaded cp.cache_file
558 2024-04-03 14:05:46,865 [salt.channel.client:32  ][TRACE   ][43416] ReqChannel send crypt load={'path': 'scripts/test.sh', 'saltenv': 'base', 'cmd': '_file_hash'}
559 
560 2024-04-03 14:05:47,456 [salt.utils.schedule:32  ][TRACE   ][42691] ==== evaluating schedule now None =====
561 2024-04-03 14:05:48,445 [salt.utils.schedule:32  ][TRACE   ][42691] ==== evaluating schedule now None =====
562 2024-04-03 14:05:49,448 [salt.utils.schedule:32  ][TRACE   ][42691] ==== evaluating schedule now None =====
563 2024-04-03 14:05:50,451 [salt.utils.schedule:32  ][TRACE   ][42691] ==== evaluating schedule now None =====
564 2024-04-03 14:05:50,525 [salt.channel.client:32  ][TRACE   ][42691] Decoding payload: {'enc': 'aes', 'load': b'n`~d\xee\xa1\xees\xcc\xeft\xc7\x0b\x06\x1ert\xb9Q%>\xc1i\xa9\xe1\xf1a\x93\x14\x    ae\x06\x17\xf3\xdd\xe5/\xa8^\xf2^\xb2\xf6\x02\x0e\xe4\xaaHR\xe2\x9c\x8aA|d\xbf\x91\xc8\x0eS\x0f\x17\xfd3\xaa G}M\xf6\xc1\xc7\x9f\xe9\x98\xcf\x80\xc3\xf0Q\x1a8\x13\xb53\x185\x02\x0e\x9d--\x04    \xd8\x97\xf9\x8eC\rw\xad\xba{\xcf@\xdb\xc4\x89\x9b\x99WB\xeb\x03e\x82\xc5\xeeoN&2\xe6Y\x85\xbf\xf5\xb9\xbc2\xb8`\xc6=\xd1Y\x10\x16\xdb\xb4E\xe4\xf3\x00J\xd6~\xe7 \xcf\x92\xc4\x16\xa5\xfe\x0f    \x98\x9e\x13o\x16\x98\x98-\x17s\xf5\xc7zo*\xea\xd8tw\xf8\xda\xb8<.\x9d\x87C\x02a\xa0\x8d\xc1\x03\xc6\xe0q)', 'sig': b'a\xe1\xb3d\x8b\xd0\xe7\xa3\xba\x92\x96\xe3*!\xd1\xfa\x8c\xca\x17pW\xc1~\    xbb<\xb3\xa6\xf4\xb1\x89\xdcn$g\xe2\xa5\x9b.\xaf\x8f\xbeL\x13\xbed\xe0\xad\xfd\xae\xcd\x0c\x9dof\xfa\xf1\xf5s*\x19GL\x1a\xecs\x1d\xa3\x91\x91\xaf\x905\xd4\x18*~\xc1+dQ\x9a\x12\x0fY\xa6\x84\x    a8\r\xd0\xfa\x15t\xd4O\x8bk\xa6&\xf3ok\xac\xf9?U\x95\x84\xc2\xe3A\xf8o_\x1d\xd9\xb6r\xf7\x94\x05\xcd\xda\x02\xbfR\xec\xc0\x02\xbb\xcd\xb4:y\xfa\xa9\x08}\x8c;\x00\xc5\xaa4\x9e\xb5\xd9\xeen,\x    05\x18\x8f\x0f\xaa%[}\x1a\xa3/M\xdf\x11\xf1\\\xa9\xf1P\x04\r\x9e,\x8d\x01\x87rQSM\\^\xceU\xcf\xc4\xd0.\x1d6\xaa\xc1\x18n\xa6\xb3\xce\xd0\x14\x95{\'\x0c\xac&\xea\xf7\xf1c\xce=\xbb>\xbb\x10:.:    a\x89x\xd3\xd3\xe4"\xaa\xc6J\x0b^{=\x9bc`cH[\xccN\xb4N\xe6\x8b\xc8\x12\xc9\xbb\x1b\xcf\x98k\xa2\xcf-\xdd#'}
565 2024-04-03 14:05:50,526 [salt.channel.client:483 ][DEBUG   ][42691] PubChannel received: {'enc': 'aes', 'load': {'fun': 'saltutil.find_job', 'arg': ['20240403200545157394'], 'tgt': ['tc8'],     'jid': '20240403200550254403', 'ret': '', 'tgt_type': 'list', 'user': 'sudo_david'}, 'sig': b'a\xe1\xb3d\x8b\xd0\xe7\xa3\xba\x92\x96\xe3*!\xd1\xfa\x8c\xca\x17pW\xc1~\xbb<\xb3\xa6\xf4\xb1\x89    \xdcn$g\xe2\xa5\x9b.\xaf\x8f\xbeL\x13\xbed\xe0\xad\xfd\xae\xcd\x0c\x9dof\xfa\xf1\xf5s*\x19GL\x1a\xecs\x1d\xa3\x91\x91\xaf\x905\xd4\x18*~\xc1+dQ\x9a\x12\x0fY\xa6\x84\xa8\r\xd0\xfa\x15t\xd4O\x    8bk\xa6&\xf3ok\xac\xf9?U\x95\x84\xc2\xe3A\xf8o_\x1d\xd9\xb6r\xf7\x94\x05\xcd\xda\x02\xbfR\xec\xc0\x02\xbb\xcd\xb4:y\xfa\xa9\x08}\x8c;\x00\xc5\xaa4\x9e\xb5\xd9\xeen,\x05\x18\x8f\x0f\xaa%[}\x1    a\xa3/M\xdf\x11\xf1\\\xa9\xf1P\x04\r\x9e,\x8d\x01\x87rQSM\\^\xceU\xcf\xc4\xd0.\x1d6\xaa\xc1\x18n\xa6\xb3\xce\xd0\x14\x95{\'\x0c\xac&\xea\xf7\xf1c\xce=\xbb>\xbb\x10:.:a\x89x\xd3\xd3\xe4"\xaa\    xc6J\x0b^{=\x9bc`cH[\xccN\xb4N\xe6\x8b\xc8\x12\xc9\xbb\x1b\xcf\x98k\xa2\xcf-\xdd#'} <bound method Minion._handle_payload of <salt.minion.Minion object at 0x7fd642e2f2e0>>
566 2024-04-03 14:05:50,526 [salt.channel.client:485 ][DEBUG   ][42691] DGM PubChannel received decoded: {'enc': 'aes', 'load': {'fun': 'saltutil.find_job', 'arg': ['20240403200545157394'], 'tgt    ': ['tc8'], 'jid': '20240403200550254403', 'ret': '', 'tgt_type': 'list', 'user': 'sudo_david'}, 'sig': b'a\xe1\xb3d\x8b\xd0\xe7\xa3\xba\x92\x96\xe3*!\xd1\xfa\x8c\xca\x17pW\xc1~\xbb<\xb3\xa6    \xf4\xb1\x89\xdcn$g\xe2\xa5\x9b.\xaf\x8f\xbeL\x13\xbed\xe0\xad\xfd\xae\xcd\x0c\x9dof\xfa\xf1\xf5s*\x19GL\x1a\xecs\x1d\xa3\x91\x91\xaf\x905\xd4\x18*~\xc1+dQ\x9a\x12\x0fY\xa6\x84\xa8\r\xd0\xfa    \x15t\xd4O\x8bk\xa6&\xf3ok\xac\xf9?U\x95\x84\xc2\xe3A\xf8o_\x1d\xd9\xb6r\xf7\x94\x05\xcd\xda\x02\xbfR\xec\xc0\x02\xbb\xcd\xb4:y\xfa\xa9\x08}\x8c;\x00\xc5\xaa4\x9e\xb5\xd9\xeen,\x05\x18\x8f\x    0f\xaa%[}\x1a\xa3/M\xdf\x11\xf1\\\xa9\xf1P\x04\r\x9e,\x8d\x01\x87rQSM\\^\xceU\xcf\xc4\xd0.\x1d6\xaa\xc1\x18n\xa6\xb3\xce\xd0\x14\x95{\'\x0c\xac&\xea\xf7\xf1c\xce=\xbb>\xbb\x10:.:a\x89x\xd3\x    d3\xe4"\xaa\xc6J\x0b^{=\x9bc`cH[\xccN\xb4N\xe6\x8b\xc8\x12\xc9\xbb\x1b\xcf\x98k\xa2\xcf-\xdd#'}
567 2024-04-03 14:05:50,526 [salt.channel.client:486 ][DEBUG   ][42691] DGM PubChannel received callback: <bound method Minion._handle_payload of <salt.minion.Minion object at 0x7fd642e2f2e0>>
568 2024-04-03 14:05:50,526 [salt.channel.client:489 ][WARNING ][42691] DGM PubChannel received callback and decode, pre await callback-decode 
569 2024-04-03 14:05:51,539 [salt.loader.lazy :960 ][DEBUG   ][42691] The functions from module 'list_match' are being loaded by dir() on the loaded module
570 2024-04-03 14:05:51,539 [salt.utils.lazy  :99  ][DEBUG   ][42691] LazyLoaded list_match.match
571 2024-04-03 14:05:51,539 [salt.minion      :1746][WARNING ][42691] DGM _handle_decoded_payload entry, data '{'fun': 'saltutil.find_job', 'arg': ['20240403200545157394'], 'tgt': ['tc8'], 'jid'    : '20240403200550254403', 'ret': '', 'tgt_type': 'list', 'user': 'sudo_david'}'
572 2024-04-03 14:05:51,539 [salt.minion      :1750][INFO    ][42691] User sudo_david Executing command saltutil.find_job with jid 20240403200550254403
573 2024-04-03 14:05:51,540 [salt.minion      :1758][DEBUG   ][42691] Command details {'fun': 'saltutil.find_job', 'arg': ['20240403200545157394'], 'tgt': ['tc8'], 'jid': '20240403200550254403',     'ret': '', 'tgt_type': 'list', 'user': 'sudo_david'}
574 2024-04-03 14:05:51,540 [salt.minion      :32  ][TRACE   ][42691] Started JIDs: ['20240403200545157394']
575 2024-04-03 14:05:51,540 [salt.minion      :1810][WARNING ][42691] DGM _handle_decoded_payload, data '{'fun': 'saltutil.find_job', 'arg': ['20240403200545157394'], 'tgt': ['tc8'], 'jid': '202    40403200550254403', 'ret': '', 'tgt_type': 'list', 'user': 'sudo_david'}', name 'ProcessPayload(jid=20240403200550254403)', multiprocessing_enabled 'True'
576 2024-04-03 14:05:51,543 [salt.minion      :1841][WARNING ][42691] DGM _handle_decoded_payload, multiprocessing_enabled 'True', pre-add subprocess_list process pid '43644', name 'ProcessPaylo    ad(jid=20240403200550254403)'
577 2024-04-03 14:05:51,544 [salt.utils.process:1146][DEBUG   ][42691] Subprocess ProcessPayload(jid=20240403200550254403) added
578 2024-04-03 14:05:51,545 [salt.minion      :1843][WARNING ][42691] DGM _handle_decoded_payload, multiprocessing_enabled 'True', post-add subprocess_list process pid '43644', name 'ProcessPayl    oad(jid=20240403200550254403)'
579 2024-04-03 14:05:51,545 [salt.channel.client:495 ][WARNING ][42691] DGM got a typeerror exception 'object NoneType can't be used in 'await' expression'
580 2024-04-03 14:05:51,545 [salt.transport.zeromq:396 ][ERROR   ][42691] Exception while running callback
581 Traceback (most recent call last):
582   File "/opt/saltstack/salt/lib/python3.10/site-packages/salt/transport/zeromq.py", line 394, in consume
583     await callback(msg)
584   File "/opt/saltstack/salt/lib/python3.10/site-packages/salt/channel/client.py", line 491, in wrap_callback
585     await callback(decoded)
586 TypeError: object NoneType can't be used in 'await' expression
587 2024-04-03 14:05:51,547 [salt.utils.schedule:32  ][TRACE   ][42691] ==== evaluating schedule now None =====

see how timestamp 2024-04-03 14:05:46,865 is handled
noting that all of this works fine when no master is involved (salt-call --local state.apply test).

Have a feeling that since the jid is not different, the mapping gets stuff delivered to the wrong pid, that is, the parallel pid is using the originating jid and thus sowing confusion. - At least that is an avenue of investigation.

The line

salt/salt/modules/cmdmod.py

Line 2893 in 1998ba3

fn_ = __salt__["cp.cache_file"](source, saltenv)

is excuted but the following line is never reached, that is, no return from the __salt__["cp.cache_file"](source, saltenv)

[dmurphy18]

This appears to be an issue with the master only recognizing the originating pid, e.g. pid 26942, the parallel pid 26958, but all the master talks about is 26942, for example:

240 2024-04-04 13:55:51,966 [salt.utils.job   :86  ][INFO    ][25886] Got return from tc8 for job 20240404195551601792
241 2024-04-04 13:55:51,967 [salt.utils.event :823 ][DEBUG   ][25886] Sending event: tag = salt/job/20240404195551601792/ret/tc8; data = {'cmd': '_return', 'id': 'tc8', 'success': True, 'return': {'pid': 26942, 'fun': 'state.apply', 'arg': ['test'], 'tgt': 'tc8', 'ji    d': '20240404195546199368', 'ret': '', 'tgt_type': 'glob', 'user': 'sudo_david'}, 'retcode': 0, 'jid': '20240404195551601792', 'fun': 'saltutil.find_job', 'fun_args': ['20240404195546199368'], 'user': 'sudo_david', '_stamp': '2024-04-04T19:55:51.967017'}
242 2024-04-04 13:55:51,976 [salt.loaded.int.returner.local_cache:307 ][DEBUG   ][25886] Reading minion list from /var/cache/salt/master/jobs/bf/47776492ffffb096e5bf47c4369f137e838a8ae5fc45e27d2d1da7778d7053/.minions.p
243 2024-04-04 13:55:51,976 [salt.master      :32  ][TRACE   ][25886] Master function call _return took 0.012319564819335938 seconds
244 2024-04-04 13:55:51,978 [salt.utils.event :32  ][TRACE   ][26924] get_event() caching unwanted event = {'data': {'cmd': '_return', 'id': 'tc8', 'success': True, 'return': {'pid': 26942, 'fun': 'state.apply', 'arg': ['test'], 'tgt': 'tc8', 'jid': '2024040419554619    9368', 'ret': '', 'tgt_type': 'glob', 'user': 'sudo_david'}, 'retcode': 0, 'jid': '20240404195551601792', 'fun': 'saltutil.find_job', 'fun_args': ['20240404195546199368'], 'user': 'sudo_david', '_stamp': '2024-04-04T19:55:51.967017'}, 'tag': 'salt/job/20240404195    551601792/ret/tc8'}
245 2024-04-04 13:55:51,978 [salt.utils.event :32  ][TRACE   ][26924] _get_event() waited 0 seconds and received nothing
246 2024-04-04 13:55:51,979 [salt.utils.event :32  ][TRACE   ][26924] Get event. tag: salt/job/20240404195551601792
247 2024-04-04 13:55:51,979 [salt.utils.event :32  ][TRACE   ][26924] get_event() returning cached event = {'data': {'cmd': '_return', 'id': 'tc8', 'success': True, 'return': {'pid': 26942, 'fun': 'state.apply', 'arg': ['test'], 'tgt': 'tc8', 'jid': '2024040419554619    9368', 'ret': '', 'tgt_type': 'glob', 'user': 'sudo_david'}, 'retcode': 0, 'jid': '20240404195551601792', 'fun': 'saltutil.find_job', 'fun_args': ['20240404195546199368'], 'user': 'sudo_david', '_stamp': '2024-04-04T19:55:51.967017'}, 'tag': 'salt/job/20240404195    551601792/ret/tc8'}

Wondering about that caching unwanted event , could it be due to something from pid 26958
The pid the master is dealing with is due to the class SaltEvent.connect_pub setting self.subscriber, so betting using the connection it has with pid 26942 that it knows about, since the pid 26958 didn't go about make any connections (betting - caching ideas before going on vacation).
Not wanting to have to do a whole new connect_pub etc, perhaps the solution is to have the original pid 26942, check replies to see if it has children that need to receive whatever packet it gets.

Also the systemctl stop salt-minion not working, only killing the initial pid and none of the children, see ProcessManager.kill_children, only getting log.trace("Waiting to kill process manager children") in the logs, see

[dmurphy18]

the process manager kill_children has an empty self._process_map when called, but clearly it should not, except if you remove the parallel part of the state file, and re-run the command and do the systemctl stop salt-minion, it too calls kill_children with and empty self._process_map.

However it does stop all salt-minion processes, which was

[root@localhost salt]# ps -ef | grep salt-minion
root       14832       1  0 13:32 ?        00:00:00 /opt/saltstack/salt/bin/python3.10 /usr/bin/salt-minion
root       14839   14832  2 13:32 ?        00:00:01 /opt/saltstack/salt/bin/python3.10 /usr/bin/salt-minion MultiMinionProcessManager MinionProcessManager