Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[BUG]Communication problem between salt-master and minion under redhat8.6 of Azure #63945

Open
nicktianxozz opened this issue Mar 24, 2023 · 8 comments
Labels
Bug broken, incorrect, or confusing behavior info-needed waiting for more info Pending-Discussion The issue or pull request needs more discussion before it can be closed or merged
Milestone

Comments

@nicktianxozz
Copy link

We deployed salt-master3003.3 and salt-minion3003.3 on the same virtual machine redhat8.6 system on Azure, and the communication is often interrupted automatically. I want to know the reason and how to fix this problem. The specific situation is as follows:
Both master and minion have debug logs enabled. We named the minion: serverip-redhattest.
The configuration of the master:

auto_accept:False                                                                                                                                                                
file_recv: True
file_recv_max_size: 100
log_file: /var/log/salt/master
log_level: debug
log_level_logfile: debug
default_include: /etc/salt/master.d/*.conf
publish_port: 6715
worker_threads: 50
ret_port: 6716
expire_responses: False
pidfile: /var/run/salt-master.pid
keep_jobs: 24
timeout: 30
sock_dir: /var/run/salt/master
job_cache: True
minion_data_cache: True
open_mode: True
file_roots:
  base:
    - /srv/salt
pillar_roots:
  base:
    - /srv/pillar

The configuration of the minion:

master: PUBLIC-NETWORK-IP
master_port: 6716
id: serverip-redhattest
log_level: debug	

Try to test whether the communication is normal through "salt serverip-redhattest test.ping", everything is normal at the beginning, and this command can get normal return information:

serverip-redhattest:
     True

However, after a period of time, if the test is carried out again, the normal communication will not be possible, and the returned information is as follows:

[DEBUG   ] Configuration file path: /etc/salt/master
[WARNING ] Insecure logging configuration detected! Sensitive data may be logged.
[DEBUG   ] Reading configuration from /etc/salt/master
[DEBUG   ] Missing configuration file: /root/.saltrc
[DEBUG   ] MasterEvent PUB socket URI: /var/run/salt/master/master_event_pub.ipc
[DEBUG   ] MasterEvent PULL socket URI: /var/run/salt/master/master_event_pull.ipc
[DEBUG   ] Connecting the Minion to the Master URI (for the return server): tcp://127.0.0.1:6716
[DEBUG   ] Trying to connect to: tcp://127.0.0.1:6716
[DEBUG   ] Closing AsyncZeroMQReqChannel instance
[DEBUG   ] LazyLoaded local_cache.get_load
[DEBUG   ] Reading minion list from /var/cache/salt/master/jobs/22/4ab0303dc983fa6dba6cf571da26ca8040c663c43530c1c79eed2ebbb9d7c3/.minions.p
[DEBUG   ] get_iter_returns for jid 20230324083232386921 sent to {'serverip-redhattest'} will timeout at 08:33:02.394947
[DEBUG   ] Checking whether jid 20230324083232386921 is still running
[DEBUG   ] Connecting the Minion to the Master URI (for the return server): tcp://127.0.0.1:6716
[DEBUG   ] Trying to connect to: tcp://127.0.0.1:6716
[DEBUG   ] Closing AsyncZeroMQReqChannel instance
[DEBUG   ] retcode missing from client return
[DEBUG   ] return event: {'serverip-redhattest': {'failed': True}}
[DEBUG   ] Using importlib_metadata to load entry points
[DEBUG   ] LazyLoaded localfs.init_kwargs
[DEBUG   ] LazyLoaded localfs.init_kwargs
[DEBUG   ] LazyLoaded no_return.output
serverip-redhattest:
    Minion did not return. [No response]
    The minions may not have all finished running and any remaining minions will return upon completion. To look up the return data for this job later, run the following command:
    
    salt-run jobs.lookup_jid 20230324083232386921
[DEBUG   ] Closing IPCMessageSubscriber instance
ERROR: Minions returned with non-zero exit code

At this time, the minion does not have any logs, and the log of the master shows:

2023-03-24 08:31:29,955 [salt.config      :1913][DEBUG   ][283912] Reading configuration from /etc/salt/master
2023-03-24 08:31:29,957 [salt.config      :3511][DEBUG   ][283912] Guessing ID. The id can be explicitly set in /etc/salt/minion
2023-03-24 08:31:29,975 [salt.config      :3535][DEBUG   ][283912] Found minion id from generate_minion_id(): test-saltclient.internal.cloudapp.net
2023-03-24 08:31:29,977 [salt.loader      :847 ][DEBUG   ][283912] Grains refresh requested. Refreshing grains.
2023-03-24 08:31:29,977 [salt.config      :1913][DEBUG   ][283912] Reading configuration from /etc/salt/master
2023-03-24 08:31:29,979 [salt.utils.entrypoints:53  ][DEBUG   ][283912] Using importlib_metadata to load entry points
2023-03-24 08:31:29,993 [salt.utils.entrypoints:53  ][DEBUG   ][283912] Using importlib_metadata to load entry points
2023-03-24 08:31:30,004 [salt.utils.entrypoints:53  ][DEBUG   ][283912] Using importlib_metadata to load entry points
2023-03-24 08:31:30,019 [salt.loader      :1923][DEBUG   ][283912] Override  __utils__: <module 'salt.loaded.int.grains.zfs' from '/usr/local/python3/lib/python3.6/site-packages/salt/grains/zfs.py'>
2023-03-24 08:31:30,235 [salt.modules.network:2116][DEBUG   ][283912] Elapsed time getting FQDNs: 0.20460104942321777 seconds
2023-03-24 08:31:30,432 [salt.utils.lazy  :102 ][DEBUG   ][283912] LazyLoaded zfs.is_supported
2023-03-24 08:31:30,458 [salt.utils.entrypoints:53  ][DEBUG   ][283912] Using importlib_metadata to load entry points
2023-03-24 08:31:30,473 [salt.utils.entrypoints:53  ][DEBUG   ][283912] Using importlib_metadata to load entry points
2023-03-24 08:31:30,503 [salt.utils.entrypoints:53  ][DEBUG   ][283912] Using importlib_metadata to load entry points
2023-03-24 08:31:30,507 [salt.utils.entrypoints:53  ][DEBUG   ][283912] Using importlib_metadata to load entry points
2023-03-24 08:31:30,513 [salt.utils.entrypoints:53  ][DEBUG   ][283912] Using importlib_metadata to load entry points
2023-03-24 08:31:30,518 [salt.utils.lazy  :102 ][DEBUG   ][283912] LazyLoaded local_cache.clean_old_jobs
2023-03-24 08:31:30,521 [salt.utils.entrypoints:53  ][DEBUG   ][283912] Using importlib_metadata to load entry points
2023-03-24 08:31:30,525 [salt.utils.entrypoints:53  ][DEBUG   ][283912] Using importlib_metadata to load entry points
2023-03-24 08:31:30,556 [salt.utils.entrypoints:53  ][DEBUG   ][283912] Using importlib_metadata to load entry points
2023-03-24 08:31:30,560 [salt.utils.lazy  :102 ][DEBUG   ][283912] LazyLoaded localfs.list_tokens
2023-03-24 08:31:30,560 [salt.utils.verify:452 ][DEBUG   ][283912] This salt-master instance has accepted 2 minion keys.
2023-03-24 08:31:49,334 [salt.client      :293 ][DEBUG   ][307804] Checking whether jid 20230324083119307014 is still running
2023-03-24 08:31:49,335 [salt.transport.zeromq:161 ][DEBUG   ][307804] Connecting the Minion to the Master URI (for the return server): tcp://127.0.0.1:6716
2023-03-24 08:31:49,335 [salt.transport.zeromq:1237][DEBUG   ][307804] Trying to connect to: tcp://127.0.0.1:6716
2023-03-24 08:31:49,337 [salt.utils.event :805 ][DEBUG   ][284009] Sending event: tag = 20230324083149337532; data = {'minions': ['serverip-redhattest'], '_stamp': '2023-03-24T08:31:49.337822'}
2023-03-24 08:31:49,338 [salt.utils.event :805 ][DEBUG   ][284009] Sending event: tag = salt/job/20230324083149337532/new; data = {'jid': '20230324083149337532', 'tgt_type': 'list', 'tgt': ['serverip-redhattest'], 'user': 'sudo_azureuser', 'fun': 'saltutil.find_job', 'arg': ['20230324083119307014'], 'minions': ['serverip-redhattest'], 'missing': [], '_stamp': '2023-03-24T08:31:49.338815'}
2023-03-24 08:31:49,339 [salt.loaded.int.returner.local_cache:256 ][DEBUG   ][284009] Adding minions for job 20230324083149337532: ['serverip-redhattest']
2023-03-24 08:31:49,340 [salt.master      :2496][INFO    ][284009] User sudo_azureuser Published command saltutil.find_job with jid 20230324083149337532
2023-03-24 08:31:49,340 [salt.master      :2503][DEBUG   ][284009] Published command details {'fun': 'saltutil.find_job', 'arg': ['20230324083119307014'], 'tgt': ['serverip-redhattest'], 'jid': '20230324083149337532', 'ret': '', 'tgt_type': 'list', 'user': 'sudo_azureuser'}
2023-03-24 08:31:49,340 [salt.transport.zeromq:1151][DEBUG   ][284009] Signing data packet
2023-03-24 08:31:49,340 [salt.crypt       :210 ][DEBUG   ][284009] salt.crypt.get_rsa_key: Loading private key
2023-03-24 08:31:49,340 [salt.crypt       :235 ][DEBUG   ][284009] salt.crypt.sign_message: Signing message.
2023-03-24 08:31:49,341 [salt.transport.zeromq:1173][DEBUG   ][284009] Sending payload to publish daemon. jid=20230324083149337532 size=536
2023-03-24 08:31:49,341 [salt.transport.zeromq:1178][DEBUG   ][284009] Sent payload to publish daemon.
2023-03-24 08:31:49,342 [salt.transport.zeromq:1021][DEBUG   ][283908] Publish daemon received payload. size=536
2023-03-24 08:31:49,342 [salt.transport.zeromq:1019][DEBUG   ][283908] Publish daemon getting data from puller ipc:///var/run/salt/master/publish_pull.ipc
2023-03-24 08:31:49,343 [salt.transport.zeromq:180 ][DEBUG   ][307804] Closing AsyncZeroMQReqChannel instance
2023-03-24 08:31:49,355 [salt.client      :1291][DEBUG   ][307804] retcode missing from client return
2023-03-24 08:31:59,471 [salt.client      :1659][DEBUG   ][307804] return event: {'serverip-redhattest': {'failed': True}}
2023-03-24 08:31:59,471 [salt.utils.entrypoints:57  ][DEBUG   ][307804] Using importlib_metadata to load entry points
2023-03-24 08:31:59,491 [salt.utils.lazy  :99  ][DEBUG   ][307804] LazyLoaded localfs.init_kwargs
2023-03-24 08:31:59,500 [salt.utils.lazy  :99  ][DEBUG   ][307804] LazyLoaded localfs.init_kwargs
2023-03-24 08:31:59,503 [salt.utils.lazy  :99  ][DEBUG   ][307804] LazyLoaded no_return.output
2023-03-24 08:31:59,503 [salt.transport.ipc:370 ][DEBUG   ][307804] Closing IPCMessageSubscriber instance
2023-03-24 08:31:59,629 [salt.master      :478 ][DEBUG   ][307456] Performing fileserver updates for items with an update interval of 60
2023-03-24 08:31:59,629 [salt.master      :457 ][DEBUG   ][307456] Updating roots fileserver cache
2023-03-24 08:31:59,630 [salt.master      :485 ][DEBUG   ][307456] Completed fileserver updates for items with an update interval of 60, waiting 60 seconds

Executing “salt-call test.ping” can get the return normally:

[root@test-saltclient azureuser]# salt-call test.ping
[DEBUG   ] Configuration file path: /etc/salt/minion
[WARNING ] Insecure logging configuration detected! Sensitive data may be logged.
[DEBUG   ] Grains refresh requested. Refreshing grains.
[DEBUG   ] Reading configuration from /etc/salt/minion
[DEBUG   ] Including configuration from '/etc/salt/minion.d/_schedule.conf'
[DEBUG   ] Reading configuration from /etc/salt/minion.d/_schedule.conf
[DEBUG   ] Using importlib_metadata to load entry points
[DEBUG   ] Using importlib_metadata to load entry points
[DEBUG   ] Using importlib_metadata to load entry points
[DEBUG   ] Override  __utils__: <module 'salt.loaded.int.grains.zfs' from '/usr/local/python3/lib/python3.6/site-packages/salt/grains/zfs.py'>
[DEBUG   ] Elapsed time getting FQDNs: 0.11094045639038086 seconds
[DEBUG   ] LazyLoaded zfs.is_supported
[DEBUG   ] Connecting to master. Attempt 1 of 1
[DEBUG   ] Master URI: tcp://PUBLIC-NETWORK-IP:6716
[DEBUG   ] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'serverip-redhattest', 'tcp://PUBLIC-NETWORK-IP:6716')
[DEBUG   ] Generated random reconnect delay between '1000ms' and '11000ms' (8007)
[DEBUG   ] Setting zmq_reconnect_ivl to '8007ms'
[DEBUG   ] Setting zmq_reconnect_ivl_max to '11000ms'
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/minion', 'serverip-redhattest', 'tcp://PUBLIC-NETWORK-IP:6716', 'clear')
[DEBUG   ] Connecting the Minion to the Master URI (for the return server): tcp://PUBLIC-NETWORK-IP:6716
[DEBUG   ] Trying to connect to: tcp://PUBLIC-NETWORK-IP:6716
[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: /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://PUBLIC-NETWORK-IP:6715
[DEBUG   ] salt.crypt.get_rsa_key: Loading private key
[DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
[DEBUG   ] Determining pillar cache
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/minion', 'serverip-redhattest', 'tcp://PUBLIC-NETWORK-IP:6716', 'aes')
[DEBUG   ] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'serverip-redhattest', 'tcp://PUBLIC-NETWORK-IP:6716')
[DEBUG   ] Connecting the Minion to the Master URI (for the return server): tcp://PUBLIC-NETWORK-IP:6716
[DEBUG   ] Trying to connect to: tcp://PUBLIC-NETWORK-IP:6716
[DEBUG   ] salt.crypt.get_rsa_key: Loading private key
[DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
[DEBUG   ] Closing AsyncZeroMQReqChannel instance
[DEBUG   ] Using importlib_metadata to load entry points
[DEBUG   ] Using importlib_metadata to load entry points
[DEBUG   ] Using importlib_metadata to load entry points
[DEBUG   ] Using importlib_metadata to load entry points
[DEBUG   ] Using importlib_metadata to load entry points
[DEBUG   ] Using importlib_metadata to load entry points
[DEBUG   ] Using importlib_metadata to load entry points
[DEBUG   ] LazyLoaded jinja.render
[DEBUG   ] LazyLoaded yaml.render
[DEBUG   ] Using importlib_metadata to load entry points
[DEBUG   ] Using importlib_metadata to load entry points
[DEBUG   ] LazyLoaded test.ping
[DEBUG   ] LazyLoaded direct_call.execute
[DEBUG   ] test.ping received for minion 'serverip-redhattest'
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/minion', 'serverip-redhattest', 'tcp://PUBLIC-NETWORK-IP:6716', 'aes')
[DEBUG   ] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'serverip-redhattest', 'tcp://PUBLIC-NETWORK-IP:6716')
[DEBUG   ] Connecting the Minion to the Master URI (for the return server): tcp://PUBLIC-NETWORK-IP:6716
[DEBUG   ] Trying to connect to: tcp://PUBLIC-NETWORK-IP:6716
[DEBUG   ] Closing AsyncZeroMQReqChannel instance
[DEBUG   ] Using importlib_metadata to load entry points
[DEBUG   ] LazyLoaded nested.output
local:
    True

Executing “salt-call test.ping” time, the minion's log is as follows:

2023-03-24 08:36:25,637 [salt.utils.verify:588 ][WARNING ][309655] Insecure logging configuration detected! Sensitive data may be logged.
2023-03-24 08:36:25,637 [salt.loader      :847 ][DEBUG   ][309655] Grains refresh requested. Refreshing grains.
2023-03-24 08:36:25,637 [salt.config      :1913][DEBUG   ][309655] Reading configuration from /etc/salt/minion
2023-03-24 08:36:25,638 [salt.config      :2076][DEBUG   ][309655] Including configuration from '/etc/salt/minion.d/_schedule.conf'
2023-03-24 08:36:25,638 [salt.config      :1913][DEBUG   ][309655] Reading configuration from /etc/salt/minion.d/_schedule.conf
2023-03-24 08:36:25,638 [salt.utils.entrypoints:53  ][DEBUG   ][309655] Using importlib_metadata to load entry points
2023-03-24 08:36:25,652 [salt.utils.entrypoints:53  ][DEBUG   ][309655] Using importlib_metadata to load entry points
2023-03-24 08:36:25,663 [salt.utils.entrypoints:53  ][DEBUG   ][309655] Using importlib_metadata to load entry points
2023-03-24 08:36:25,693 [salt.loader      :1923][DEBUG   ][309655] Override  __utils__: <module 'salt.loaded.int.grains.zfs' from '/usr/local/python3/lib/python3.6/site-packages/salt/grains/zfs.py'>
2023-03-24 08:36:25,915 [salt.modules.network:2116][DEBUG   ][309655] Elapsed time getting FQDNs: 0.21129941940307617 seconds
2023-03-24 08:36:26,123 [salt.utils.lazy  :102 ][DEBUG   ][309655] LazyLoaded zfs.is_supported
2023-03-24 08:36:26,151 [salt.minion      :789 ][DEBUG   ][309655] Connecting to master. Attempt 1 of 1
2023-03-24 08:36:26,153 [salt.minion      :234 ][DEBUG   ][309655] Master URI: tcp://PUBLIC-NETWORK-IP:6716
2023-03-24 08:36:26,153 [salt.crypt       :498 ][DEBUG   ][309655] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'serverip-redhattest', 'tcp://PUBLIC-NETWORK-IP:6716')
2023-03-24 08:36:26,154 [salt.transport.zeromq:524 ][DEBUG   ][309655] Generated random reconnect delay between '1000ms' and '11000ms' (8752)
2023-03-24 08:36:26,155 [salt.transport.zeromq:527 ][DEBUG   ][309655] Setting zmq_reconnect_ivl to '8752ms'
2023-03-24 08:36:26,155 [salt.transport.zeromq:533 ][DEBUG   ][309655] Setting zmq_reconnect_ivl_max to '11000ms'
2023-03-24 08:36:26,155 [salt.transport.zeromq:162 ][DEBUG   ][309655] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/minion', 'serverip-redhattest', 'tcp://PUBLIC-NETWORK-IP:6716', 'clear')
2023-03-24 08:36:26,156 [salt.transport.zeromq:261 ][DEBUG   ][309655] Connecting the Minion to the Master URI (for the return server): tcp://PUBLIC-NETWORK-IP:6716
2023-03-24 08:36:26,156 [salt.transport.zeromq:1305][DEBUG   ][309655] Trying to connect to: tcp://PUBLIC-NETWORK-IP:6716
2023-03-24 08:36:26,156 [salt.crypt       :218 ][DEBUG   ][309655] salt.crypt.get_rsa_pub_key: Loading public key
2023-03-24 08:36:26,175 [salt.crypt       :935 ][DEBUG   ][309655] Decrypting the current master AES key
2023-03-24 08:36:26,175 [salt.crypt       :210 ][DEBUG   ][309655] salt.crypt.get_rsa_key: Loading private key
2023-03-24 08:36:26,175 [salt.crypt       :190 ][DEBUG   ][309655] salt.crypt._get_key_with_evict: Loading private key
2023-03-24 08:36:26,176 [salt.crypt       :862 ][DEBUG   ][309655] Loaded minion key: /etc/salt/pki/minion/minion.pem
2023-03-24 08:36:26,181 [salt.crypt       :218 ][DEBUG   ][309655] salt.crypt.get_rsa_pub_key: Loading public key
2023-03-24 08:36:26,186 [salt.transport.zeromq:288 ][DEBUG   ][309655] Closing AsyncZeroMQReqChannel instance
2023-03-24 08:36:26,187 [salt.transport.zeromq:590 ][DEBUG   ][309655] Connecting the Minion to the Master publish port, using the URI: tcp://PUBLIC-NETWORK-IP:6715
2023-03-24 08:36:26,187 [salt.crypt       :210 ][DEBUG   ][309655] salt.crypt.get_rsa_key: Loading private key
2023-03-24 08:36:26,187 [salt.crypt       :862 ][DEBUG   ][309655] Loaded minion key: /etc/salt/pki/minion/minion.pem
2023-03-24 08:36:26,192 [salt.pillar      :72  ][DEBUG   ][309655] Determining pillar cache
2023-03-24 08:36:26,193 [salt.transport.zeromq:162 ][DEBUG   ][309655] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/minion', 'serverip-redhattest', 'tcp://PUBLIC-NETWORK-IP:6716', 'aes')
2023-03-24 08:36:26,193 [salt.crypt       :498 ][DEBUG   ][309655] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'serverip-redhattest', 'tcp://PUBLIC-NETWORK-IP:6716')
2023-03-24 08:36:26,193 [salt.transport.zeromq:261 ][DEBUG   ][309655] Connecting the Minion to the Master URI (for the return server): tcp://PUBLIC-NETWORK-IP:6716
2023-03-24 08:36:26,193 [salt.transport.zeromq:1305][DEBUG   ][309655] Trying to connect to: tcp://PUBLIC-NETWORK-IP:6716
2023-03-24 08:36:26,304 [salt.crypt       :210 ][DEBUG   ][309655] salt.crypt.get_rsa_key: Loading private key
2023-03-24 08:36:26,304 [salt.crypt       :862 ][DEBUG   ][309655] Loaded minion key: /etc/salt/pki/minion/minion.pem
2023-03-24 08:36:26,310 [salt.transport.zeromq:288 ][DEBUG   ][309655] Closing AsyncZeroMQReqChannel instance
2023-03-24 08:36:26,311 [salt.utils.entrypoints:53  ][DEBUG   ][309655] Using importlib_metadata to load entry points
2023-03-24 08:36:26,325 [salt.utils.entrypoints:53  ][DEBUG   ][309655] Using importlib_metadata to load entry points
2023-03-24 08:36:26,358 [salt.utils.entrypoints:53  ][DEBUG   ][309655] Using importlib_metadata to load entry points
2023-03-24 08:36:26,362 [salt.utils.entrypoints:53  ][DEBUG   ][309655] Using importlib_metadata to load entry points
2023-03-24 08:36:26,367 [salt.utils.entrypoints:53  ][DEBUG   ][309655] Using importlib_metadata to load entry points
2023-03-24 08:36:26,372 [salt.utils.entrypoints:53  ][DEBUG   ][309655] Using importlib_metadata to load entry points
2023-03-24 08:36:26,393 [salt.utils.entrypoints:53  ][DEBUG   ][309655] Using importlib_metadata to load entry points
2023-03-24 08:36:26,399 [salt.utils.lazy  :102 ][DEBUG   ][309655] LazyLoaded jinja.render
2023-03-24 08:36:26,400 [salt.utils.lazy  :102 ][DEBUG   ][309655] LazyLoaded yaml.render
2023-03-24 08:36:26,400 [salt.utils.entrypoints:53  ][DEBUG   ][309655] Using importlib_metadata to load entry points
2023-03-24 08:36:26,406 [salt.utils.entrypoints:53  ][DEBUG   ][309655] Using importlib_metadata to load entry points
2023-03-24 08:36:26,410 [salt.utils.lazy  :102 ][DEBUG   ][309655] LazyLoaded test.ping
2023-03-24 08:36:26,412 [salt.utils.lazy  :102 ][DEBUG   ][309655] LazyLoaded direct_call.execute
2023-03-24 08:36:26,412 [salt.loaded.int.module.test:120 ][DEBUG   ][309655] test.ping received for minion 'serverip-redhattest'
2023-03-24 08:36:26,412 [salt.transport.zeromq:162 ][DEBUG   ][309655] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/minion', 'serverip-redhattest', 'tcp://PUBLIC-NETWORK-IP:6716', 'aes')
2023-03-24 08:36:26,412 [salt.crypt       :498 ][DEBUG   ][309655] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'serverip-redhattest', 'tcp://PUBLIC-NETWORK-IP:6716')
2023-03-24 08:36:26,413 [salt.transport.zeromq:261 ][DEBUG   ][309655] Connecting the Minion to the Master URI (for the return server): tcp://PUBLIC-NETWORK-IP:6716
2023-03-24 08:36:26,413 [salt.transport.zeromq:1305][DEBUG   ][309655] Trying to connect to: tcp://PUBLIC-NETWORK-IP:6716
2023-03-24 08:36:26,422 [salt.transport.zeromq:288 ][DEBUG   ][309655] Closing AsyncZeroMQReqChannel instance
2023-03-24 08:36:26,422 [salt.utils.entrypoints:53  ][DEBUG   ][309655] Using importlib_metadata to load entry points
2023-03-24 08:36:26,429 [salt.utils.lazy  :102 ][DEBUG   ][309655] LazyLoaded nested.output

And the master's log is as follows:

2023-03-24 08:36:26,160 [salt.transport.mixins.auth:187 ][INFO    ][283992] Authentication request from serverip-redhattest
2023-03-24 08:36:26,161 [salt.transport.mixins.auth:424 ][INFO    ][283992] Authentication accepted from serverip-redhattest
2023-03-24 08:36:26,162 [salt.crypt       :218 ][DEBUG   ][283992] salt.crypt.get_rsa_pub_key: Loading public key
2023-03-24 08:36:26,173 [salt.utils.event :805 ][DEBUG   ][283992] Sending event: tag = salt/auth; data = {'result': True, 'act': 'accept', 'id': 'serverip-redhattest', 'pub': '-----BEGIN PUBLIC KEY-----\nMIIBIjANBgkqhkiG9w0BAQEFAAOCAQ8AMIIBCgKCAQEAsJ2JGp3luBN88gEkpchL\nc5EldeVja34gf0YYhJxRrZX7GmDxR8JFAqQr4LyYWBBn4hrEa+7CYYL2giHLV/pr\neuYCDdWtxtPMo/NR/HopdDBwGDD+7Ix9jZ7xHwmS6JNsSNh4669a7wL8t4JVQsfa\nHOm6DKEnwgLxmWHPTEdc6nq3S33aFtj37RbJVoxrkzckVlBTRac+dVdFS7kFuzWq\nFwgO8N93hZcnUxGOMdxLWI7uiCOlgWkatM9hfCmlig/quYxTwGcqcDVwt0vtXwgY\n96dgZ1JZLaaP+G4bNozMw16pf1M3L+C+yrbef8GT1ChYrn15KLVq0UW4WFSB7qLo\npQIDAQAB\n-----END PUBLIC KEY-----\n', '_stamp': '2023-03-24T08:36:26.173396'}
2023-03-24 08:36:26,197 [salt.pillar      :72  ][DEBUG   ][284020] Determining pillar cache
2023-03-24 08:36:26,198 [salt.utils.entrypoints:53  ][DEBUG   ][284020] Using importlib_metadata to load entry points
2023-03-24 08:36:26,212 [salt.utils.entrypoints:53  ][DEBUG   ][284020] Using importlib_metadata to load entry points
2023-03-24 08:36:26,227 [salt.utils.entrypoints:53  ][DEBUG   ][284020] Using importlib_metadata to load entry points
2023-03-24 08:36:26,256 [salt.utils.entrypoints:53  ][DEBUG   ][284020] Using importlib_metadata to load entry points
2023-03-24 08:36:26,261 [salt.utils.entrypoints:53  ][DEBUG   ][284020] Using importlib_metadata to load entry points
2023-03-24 08:36:26,265 [salt.utils.lazy  :102 ][DEBUG   ][284020] LazyLoaded jinja.render
2023-03-24 08:36:26,267 [salt.utils.lazy  :102 ][DEBUG   ][284020] LazyLoaded yaml.render
2023-03-24 08:36:26,268 [salt.utils.entrypoints:53  ][DEBUG   ][284020] Using importlib_metadata to load entry points
2023-03-24 08:36:26,281 [salt.utils.entrypoints:53  ][DEBUG   ][284020] Using importlib_metadata to load entry points
2023-03-24 08:36:26,293 [salt.utils.entrypoints:53  ][DEBUG   ][284020] Using importlib_metadata to load entry points
2023-03-24 08:36:26,299 [salt.utils.lazy  :102 ][DEBUG   ][284020] LazyLoaded localfs.init_kwargs
2023-03-24 08:36:26,301 [salt.utils.event :805 ][DEBUG   ][284020] Sending event: tag = minion/refresh/serverip-redhattest; data = {'Minion data cache refresh': 'serverip-redhattest', '_stamp': '2023-03-24T08:36:26.301142'}
2023-03-24 08:36:26,302 [salt.crypt       :218 ][DEBUG   ][284020] salt.crypt.get_rsa_pub_key: Loading public key
2023-03-24 08:36:26,418 [salt.loaded.int.returner.local_cache:256 ][DEBUG   ][284041] Adding minions for job 20230324083626417995: ['serverip-redhattest']
2023-03-24 08:36:26,419 [salt.utils.job   :88  ][INFO    ][284041] Got return from serverip-redhattest for job 20230324083626417995
2023-03-24 08:36:26,419 [salt.utils.event :805 ][DEBUG   ][284041] Sending event: tag = salt/job/20230324083626417995/ret/serverip-redhattest; data = {'cmd': '_return', 'id': 'serverip-redhattest', 'jid': '20230324083626417995', 'return': True, 'retcode': 0, 'fun': 'test.ping', 'fun_args': [], 'arg': [], 'tgt_type': 'glob', 'tgt': 'serverip-redhattest', '_stamp': '2023-03-24T08:36:26.419383'}
2023-03-24 08:36:32,926 [salt.config      :1913][DEBUG   ][283912] Reading configuration from /etc/salt/master
2023-03-24 08:36:32,927 [salt.config      :3511][DEBUG   ][283912] Guessing ID. The id can be explicitly set in /etc/salt/minion
2023-03-24 08:36:32,946 [salt.config      :3535][DEBUG   ][283912] Found minion id from generate_minion_id(): test-saltclient.internal.cloudapp.net
2023-03-24 08:36:32,948 [salt.loader      :847 ][DEBUG   ][283912] Grains refresh requested. Refreshing grains.
2023-03-24 08:36:32,948 [salt.config      :1913][DEBUG   ][283912] Reading configuration from /etc/salt/master
2023-03-24 08:36:32,950 [salt.utils.entrypoints:53  ][DEBUG   ][283912] Using importlib_metadata to load entry points
2023-03-24 08:36:32,963 [salt.utils.entrypoints:53  ][DEBUG   ][283912] Using importlib_metadata to load entry points
2023-03-24 08:36:32,975 [salt.utils.entrypoints:53  ][DEBUG   ][283912] Using importlib_metadata to load entry points
2023-03-24 08:36:32,990 [salt.loader      :1923][DEBUG   ][283912] Override  __utils__: <module 'salt.loaded.int.grains.zfs' from '/usr/local/python3/lib/python3.6/site-packages/salt/grains/zfs.py'>
2023-03-24 08:36:33,310 [salt.modules.network:2116][DEBUG   ][283912] Elapsed time getting FQDNs: 0.3086857795715332 seconds
2023-03-24 08:36:33,509 [salt.utils.lazy  :102 ][DEBUG   ][283912] LazyLoaded zfs.is_supported
2023-03-24 08:36:33,535 [salt.utils.entrypoints:53  ][DEBUG   ][283912] Using importlib_metadata to load entry points
2023-03-24 08:36:33,550 [salt.utils.entrypoints:53  ][DEBUG   ][283912] Using importlib_metadata to load entry points
2023-03-24 08:36:33,581 [salt.utils.entrypoints:53  ][DEBUG   ][283912] Using importlib_metadata to load entry points
2023-03-24 08:36:33,585 [salt.utils.entrypoints:53  ][DEBUG   ][283912] Using importlib_metadata to load entry points
2023-03-24 08:36:33,591 [salt.utils.entrypoints:53  ][DEBUG   ][283912] Using importlib_metadata to load entry points
2023-03-24 08:36:33,596 [salt.utils.lazy  :102 ][DEBUG   ][283912] LazyLoaded local_cache.clean_old_jobs
2023-03-24 08:36:33,599 [salt.utils.entrypoints:53  ][DEBUG   ][283912] Using importlib_metadata to load entry points
2023-03-24 08:36:33,603 [salt.utils.entrypoints:53  ][DEBUG   ][283912] Using importlib_metadata to load entry points
2023-03-24 08:36:33,634 [salt.utils.entrypoints:53  ][DEBUG   ][283912] Using importlib_metadata to load entry points
2023-03-24 08:36:33,638 [salt.utils.lazy  :102 ][DEBUG   ][283912] LazyLoaded localfs.list_tokens
2023-03-24 08:36:33,638 [salt.utils.verify:452 ][DEBUG   ][283912] This salt-master instance has accepted 2 minion keys.

We also asked Microsoft Azure engineers for help, and basically ruled out system and network problems. How to solve this problem?

@nicktianxozz nicktianxozz added Bug broken, incorrect, or confusing behavior needs-triage labels Mar 24, 2023
@welcome
Copy link

welcome bot commented Mar 24, 2023

Hi there! Welcome to the Salt Community! Thank you for making your first contribution. We have a lengthy process for issues and PRs. Someone from the Core Team will follow up as soon as possible. In the meantime, here’s some information that may help as you continue your Salt journey.
Please be sure to review our Code of Conduct. Also, check out some of our community resources including:

There are lots of ways to get involved in our community. Every month, there are around a dozen opportunities to meet with other contributors and the Salt Core team and collaborate in real time. The best way to keep track is by subscribing to the Salt Community Events Calendar.
If you have additional questions, email us at saltproject@vmware.com. We’re glad you’ve joined our community and look forward to doing awesome things with you!

@OrangeDog
Copy link
Contributor

Why are you using 3003.3 and not at least 3003.5?

The latest version is 3005.1.

@garethgreenaway garethgreenaway added Pending-Discussion The issue or pull request needs more discussion before it can be closed or merged and removed needs-triage labels Mar 27, 2023
@garethgreenaway garethgreenaway added this to the Blocked milestone Mar 27, 2023
@garethgreenaway garethgreenaway added the info-needed waiting for more info label Mar 27, 2023
@KentWang810
Copy link

[root@test-saltclient minion]# salt-master --version
salt-master 3005.1
[root@test-saltclient minion]# salt-minion --version
salt-minion 3005.1
[root@test-saltclient minion]#salt 20.205.139.63-redhattest test.ping
[DEBUG ] Configuration file path: /etc/salt/master
[DEBUG ] Reading configuration from /etc/salt/master
[DEBUG ] Missing configuration file: /root/.saltrc
[DEBUG ] MasterEvent PUB socket URI: /var/run/salt/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /var/run/salt/master/master_event_pull.ipc
[DEBUG ] Closing AsyncReqChannel instance
[DEBUG ] The functions from module 'local_cache' are being loaded by dir() on the loaded module
[DEBUG ] LazyLoaded local_cache.get_load
[DEBUG ] Reading minion list from /var/cache/salt/master/jobs/2a/4f9008ffaae2b3c04d7a27124ad2978d89a2c53a71ed11d8c4a895b106b0ff/.minions.p
[DEBUG ] get_iter_returns for jid 20230328011905938317 sent to {'20.205.139.63-redhattest'} will timeout at 01:19:35.948335
[DEBUG ] Checking whether jid 20230328011905938317 is still running
[DEBUG ] Closing AsyncReqChannel instance
[DEBUG ] retcode missing from client return
[DEBUG ] return event: {'20.205.139.63-redhattest': {'failed': True}}
[DEBUG ] The functions from module 'localfs' are being loaded by dir() on the loaded module
[DEBUG ] LazyLoaded localfs.init_kwargs
[DEBUG ] The functions from module 'localfs' are being loaded by dir() on the loaded module
[DEBUG ] LazyLoaded localfs.init_kwargs
[DEBUG ] The functions from module 'no_return' are being loaded by dir() on the loaded module
[DEBUG ] LazyLoaded no_return.output
20.205.139.63-redhattest:
Minion did not return. [No response]
The minions may not have all finished running and any remaining minions will return upon completion. To look up the return data for this job later, run the following command:

salt-run jobs.lookup_jid 20230328011905938317

[DEBUG ] Closing IPCMessageSubscriber instance
ERROR: Minions returned with non-zero exit code

@OrangeDog
Copy link
Contributor

What do the minions logs say?

@KentWang810
Copy link

the minions logs content is empty

@OrangeDog
Copy link
Contributor

Even when set to debug there's nothing at all, not even startup logging?
That probably means you're looking in the wrong place.

@KentWang810
Copy link

KentWang810 commented Mar 28, 2023 via email

@KentWang810
Copy link

Before you execute this ‘’slat XXX test.ping‘’ The minion‘s log as follows:
(when you execute this ‘’slat XXX test.ping‘’ The minion‘s log no new content is generated)
2023-03-28 23:12:31,948 [salt.loader.lazy :963 ][DEBUG ][620665] The functions from module 'config' are being loaded by dir() on the loaded module
2023-03-28 23:12:31,948 [salt.utils.lazy :99 ][DEBUG ][620665] LazyLoaded config.merge
2023-03-28 23:12:31,948 [salt.utils.schedule:924 ][DEBUG ][620665] schedule.handle_func: Removing /var/cache/salt/minion/proc/20230328231231875339
2023-03-28 23:12:32,874 [salt.utils.process:1155][DEBUG ][515962] Subprocess Schedule(name=__mine_interval, jid=20230328231231875339) cleaned up
2023-03-29 00:12:31,874 [salt.utils.schedule:1724][DEBUG ][515962] schedule: Job __mine_interval was scheduled with jid_include, adding to cache (jid_include defaults to True)
2023-03-29 00:12:31,875 [salt.utils.schedule:1731][DEBUG ][515962] schedule: Job __mine_interval was scheduled with a max number of 2
2023-03-29 00:12:31,875 [salt.utils.schedule:1755][INFO ][515962] Running scheduled job: __mine_interval with jid 20230329001231875252
2023-03-29 00:12:31,878 [salt.utils.process:1144][DEBUG ][515962] Subprocess Schedule(name=__mine_interval, jid=20230329001231875252) added
2023-03-29 00:12:31,945 [salt.loader.lazy :963 ][DEBUG ][625429] The functions from module 'mine' are being loaded by dir() on the loaded module
2023-03-29 00:12:31,945 [salt.utils.lazy :99 ][DEBUG ][625429] LazyLoaded mine.update
2023-03-29 00:12:31,945 [salt.utils.schedule:785 ][DEBUG ][625429] schedule.handle_func: adding this job to the jobcache with data {'id': '20.205.139.63-redhattest', 'fun': 'mine.update', 'fun_args': [], 'schedule': '__mine_interval', 'jid': '20230329001231875252', 'pid': 625429}
2023-03-29 00:12:31,948 [salt.loader.lazy :963 ][DEBUG ][625429] The functions from module 'config' are being loaded by dir() on the loaded module
2023-03-29 00:12:31,948 [salt.utils.lazy :99 ][DEBUG ][625429] LazyLoaded config.merge
2023-03-29 00:12:31,948 [salt.utils.schedule:924 ][DEBUG ][625429] schedule.handle_func: Removing /var/cache/salt/minion/proc/20230329001231875252
2023-03-29 00:12:32,874 [salt.utils.process:1155][DEBUG ][515962] Subprocess Schedule(name=__mine_interval, jid=20230329001231875252) cleaned up
2023-03-29 01:12:31,874 [salt.utils.schedule:1724][DEBUG ][515962] schedule: Job __mine_interval was scheduled with jid_include, adding to cache (jid_include defaults to True)
2023-03-29 01:12:31,874 [salt.utils.schedule:1731][DEBUG ][515962] schedule: Job __mine_interval was scheduled with a max number of 2
2023-03-29 01:12:31,874 [salt.utils.schedule:1755][INFO ][515962] Running scheduled job: __mine_interval with jid 20230329011231874512
2023-03-29 01:12:31,877 [salt.utils.process:1144][DEBUG ][515962] Subprocess Schedule(name=__mine_interval, jid=20230329011231874512) added
2023-03-29 01:12:31,949 [salt.loader.lazy :963 ][DEBUG ][630119] The functions from module 'mine' are being loaded by dir() on the loaded module
2023-03-29 01:12:31,949 [salt.utils.lazy :99 ][DEBUG ][630119] LazyLoaded mine.update
2023-03-29 01:12:31,949 [salt.utils.schedule:785 ][DEBUG ][630119] schedule.handle_func: adding this job to the jobcache with data {'id': '20.205.139.63-redhattest', 'fun': 'mine.update', 'fun_args': [], 'schedule': '__mine_interval', 'jid': '20230329011231874512', 'pid': 630119}
2023-03-29 01:12:31,951 [salt.loader.lazy :963 ][DEBUG ][630119] The functions from module 'config' are being loaded by dir() on the loaded module
2023-03-29 01:12:31,952 [salt.utils.lazy :99 ][DEBUG ][630119] LazyLoaded config.merge
2023-03-29 01:12:31,952 [salt.utils.schedule:924 ][DEBUG ][630119] schedule.handle_func: Removing /var/cache/salt/minion/proc/20230329011231874512
2023-03-29 01:12:32,874 [salt.utils.process:1155][DEBUG ][515962] Subprocess Schedule(name=__mine_interval, jid=20230329011231874512) cleaned up

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Bug broken, incorrect, or confusing behavior info-needed waiting for more info Pending-Discussion The issue or pull request needs more discussion before it can be closed or merged
Projects
None yet
Development

No branches or pull requests

4 participants