[BUG] salt.utils.event get_event on master receiving missing data
@dwoz is already working on this.
Since Jan 16, 2025.
- Dominant language
- Python
- Stars
- 15.7k
- Forks
- 5.6k
- Avg merge
- 2d 44m
- Merged PRs (30d)
- 80
Description
Description
This has been happening only recently, starting about one month ago.
There is an intermittent situation on our salt-hubs (masters), two out of our three environments are affected.
Salt jobs are sent out to the minions from the hub, the jobs are received and performed on the minion and on the final send back to the hub, we can see the job is successful from the minion & the hub is receiving the event, but the data needed is missing.
The minion & hub will error on timeouts then.
Setup
# HUB config #
worker_threads: 24
gather_job_timeout: 15
user: service-user
show_jid: True
timeout: 60
roots_update_interval: 30
top_file_merging_strategy: same
pillarenv_from_saltenv: true
pillar_source_merging_strategy: none
gitfs_provider: gitpython
gitfs_global_lock: False
git_pillar_global_lock: False
gitfs_saltenv_whitelist:
- dev
- qa
fileserver_backend:
- gitfs
- roots
# Filesystem locations #
file_roots:
base:
- /srv/salt
qa:
- /srv/salt/qa
- /mnt/environment/qa
dev:
- /srv/salt/dev
- /mnt/environment/dev
# Pillar file locations #
pillar_roots:
base:
- /srv/pillar
qa:
- /srv/pillar/qa
dev:
- /srv/pillar/dev
ext_pillar:
- git:
- dev git@github.com:salt/pillar.git:
- env: dev
# Salt file locations #
gitfs_remotes:
- git@github.com:salt/salt.git
# ACL's #
publisher_acl:
service-user:
- test.*
- state.apply
# LOGGING #
# The level of messages to send to the log file.
# One of 'garbage', 'trace', 'debug', 'info', 'warning', 'error', 'critical'.
log_granular_levels:
'salt.loaded.int.returner.appoptics_return': 'critical'
log_level: info
log_level_logfile: trace
log_fmt_console: '%(colorlevel)s %(colormsg)s %(colorname)s %(colorprocess)s'
log_fmt_logfile: '%(asctime)s,%(msecs)03d %(colorname)s %(colorlevel)s %(colormsg)s'
# Minion config #
master: salt-hub
grains:
owner: devOps
top_file_merging_strategy: same
pillarenv_from_saltenv: true
saltenv: dev
Please be as specific as possible and give set-up details.
- [X ] on-prem machine
- [X ] VM (Virtualbox, KVM, etc. please specify) KVM
- 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
- [X ] onedir packaging
- used bootstrap to install
Steps to Reproduce the behavior
While its an intermittent issue, here is a simple output of a test.ping from the hub to the minion.
Minion gets and performs the job:
2024-12-10 15:22:50,819 [salt.minion ] [INFO ] Returning information for job: 20241210212250747583
2024-12-10 15:22:50,819 [salt.minion ] [TRACE ] Return data: {'success': True, 'return': True, 'retcode': 0, 'jid': '20241210212250747583', 'fun': 'test.ping', 'fun_args': [], 'user': 'sudo_user'}
2024-12-10 15:22:50,820 [salt.utils.event ] [DEBUG ] SaltEvent PUB socket URI: /var/run/salt/minion/minion_event_66df7bdfff_pub.ipc
2024-12-10 15:22:50,820 [salt.utils.event ] [DEBUG ] SaltEvent PULL socket URI: /var/run/salt/minion/minion_event_66df7bdfff_pull.ipc
2024-12-10 15:22:50,821 [salt.transport.ipc] [TRACE ] IPCClient: Connecting to socket: /var/run/salt/minion/minion_event_66df7bdfff_pull.ipc
2024-12-10 15:22:50,821 [salt.transport.ipc] [TRACE ] IPCServer: Handling connection to address: <socket.socket fd=48, family=AddressFamily.AF_UNIX, type=SocketKind.SOCK_STREAM, proto=0, laddr=/var/run/salt/minion/minion_event_66df7bdfff_pull.ipc>
2024-12-10 15:22:50,822 [salt.utils.event ] [DEBUG ] Sending event: tag = __master_req_channel_payload/salt-hub; data = {'cmd': '_return', 'id': 'salt-minion', 'success': True, 'return': True, 'retcode': 0, 'jid': '20241210212250747583', 'fun': 'test.ping', 'fun_args': [], 'user': 'sudo_user', '_stamp': '2024-12-10T21:22:50.821984'}
2024-12-10 15:22:50,822 [salt.transport.ipc] [DEBUG ] Closing IPCMessageClient instance
2024-12-10 15:22:50,822 [salt.minion ] [TRACE ] ret_val = True
2024-12-10 15:22:50,823 [salt.minion ] [DEBUG ] minion return: {'success': True, 'return': True, 'retcode': 0, 'jid': '20241210212250747583', 'fun': 'test.ping', 'fun_args': [], 'user': 'sudo_user'}
2024-12-10 15:22:50,823 [salt.transport.ipc] [TRACE ] Client disconnected from IPC /var/run/salt/minion/minion_event_66df7bdfff_pull.ipc
2024-12-10 15:22:50,823 [salt.minion ] [DEBUG ] Minion of 'salt-hub' is handling event tag '__master_req_channel_payload/salt-hub'
2024-12-10 15:22:50,823 [salt.minion ] [DEBUG ] Minion return retry timer set to 7 seconds (randomized)
2024-12-10 15:22:50,823 [salt.channel.client] [TRACE ] ReqChannel send crypt load={'cmd': '_return', 'id': 'salt-minion', 'success': True, 'return': True, 'retcode': 0, 'jid': '20241210212250747583', 'fun': 'test.ping', 'fun_args': [], 'user': 'sudo_user', '_stamp': '2024-12-10T21:22:50.821984'}
2024-12-10 15:22:51,622 [salt.utils.schedule] [TRACE ] ==== evaluating schedule now None =====
2024-12-10 15:22:51,622 [salt.utils.process] [DEBUG ] Subprocess ProcessPayload(jid=20241210212250747583) cleaned up
2024-12-10 15:22:52,622 [salt.utils.schedule] [TRACE ] ==== evaluating schedule now None =====
2024-12-10 15:22:53,622 [salt.utils.schedule] [TRACE ] ==== evaluating schedule now None =====
2024-12-10 15:22:54,622 [salt.utils.schedule] [TRACE ] ==== evaluating schedule now None =====
2024-12-10 15:22:55,622 [salt.utils.schedule] [TRACE ] ==== evaluating schedule now None =====
2024-12-10 15:22:56,622 [salt.utils.schedule] [TRACE ] ==== evaluating schedule now None =====
2024-12-10 15:22:57,622 [salt.utils.schedule] [TRACE ] ==== evaluating schedule now None =====
2024-12-10 15:22:57,825 [salt.channel.client] [TRACE ] Failed to send msg SaltReqTimeoutError('Message timed out')
2024-12-10 15:22:57,825 [salt.channel.client] [TRACE ] ReqChannel send crypt load={'cmd': '_return', 'id': 'salt-minion', 'success': True, 'return': True, 'retcode': 0, 'jid': '20241210212250747583', 'fun': 'test.ping', 'fun_args': [], 'user': 'sudo_user', '_stamp': '2024-12-10T21:22:50.821984', 'nonce': '8af1100041c04d4f9b082f05b01e667c'}
Hubs receiving of the event but with the missing data:
2024-12-10 15:22:50,875 [salt.client ] [DEBUG ] get_iter_returns for jid 20241210212250747583 sent to {'salt-minion'} will timeout at 15:23:50.875442
2024-12-10 15:22:50,875 [salt.utils.event ] [TRACE ] Get event. tag: salt/job/20241210212250747583
2024-12-10 15:22:50,876 [salt.utils.event ] [TRACE ] _get_event() waited 0 seconds and received nothing
2024-12-10 15:22:50,886 [salt.utils.event ] [TRACE ] Get event. tag: salt/job/20241210212250747583
2024-12-10 15:22:50,888 [salt.utils.event ] [TRACE ] get_event() received = {'data': {'jid': '20241210212250747583', 'tgt_type': 'glob', 'tgt': 'salt-minion', 'user': 'sudo_user', 'fun': 'test.ping', 'arg': [], 'minions': ['salt-minion'], 'missing': [], '_stamp': '2024-12-10T21:22:50.748600'}, 'tag': 'salt/job/20241210212250747583/new'}
We also noticed this can cause minions to lose a connection with the hub at some point (testing with auth_safemode: True ping_interval: 1 on the minions
Setting the --batch-size 1 on the hub at least helps only target the minions that are connected, (but timeout issues still occur)
Expected behavior
That the:
Minions 'ReqChannel send' is the same as the hubs 'get_event() received'
Screenshots
NA
Versions Report
salt --versions-report
(Provided by running salt --versions-report. Please also mention any differences in master/minion versions.)Salt Version:
Salt: 3006.9
Python Version:
Python: 3.10.14 (main, Jun 26 2024, 11:44:37) [GCC 11.2.0]
Dependency Versions:
cffi: 1.16.0
cherrypy: 18.6.1
cryptography: 42.0.5
dateutil: 2.8.1
docker-py: Not Installed
gitdb: 4.0.11
gitpython: 3.1.40
Jinja2: 3.1.4
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.19.1
pygit2: Not Installed
python-gnupg: 0.4.8
PyYAML: 6.0.1
PyZMQ: 23.2.0
relenv: 0.17.0
smmap: 5.0.1
timelib: 0.2.4
Tornado: 4.5.3
ZMQ: 4.3.4
System Versions:
dist: rhel 9.5 Plow
locale: utf-8
machine: x86_64
release: 5.14.0-503.16.1.el9_5.x86_64
system: Linux
version: Red Hat Enterprise Linux 9.5 Plow
Additional context
We are really just trying to understand how we can debug this any further and uncover the issue.
Contributor guide
First steps
- Read the whole issue, then the project's contributing guide.
- Comment on the issue to say you are picking it up — it saves two people doing the same work.
- Fork the repository and make your change on a branch.
- Open a pull request that references the issue number.
Assessment
This issue has not been assessed yet.