From: Uwe Werler Subject: saltstack and publish.publish To: ports Date: Wed, 3 Jan 2024 10:28:54 +0100 Hi list, first of all I wish you all a Happy New Year. I post it first here and hopefully someone has an idea or could guide me into the proper direction because it doesn't seem to be a problem with Saltstack as is (see below). I try to use publish.publish with salt master on OpenBSD - but it doesn't work. I try to get salt as a CA running and follow https://docs.saltproject.io/en/latest/ref/modules/all/salt.modules.x509_v2.html#x509-setup. To get it working publish must be enabled. For testing I use "salt saltminion01\* publish.publish \* test.ping". Here's the trace output from salt-master (3006.5 and also tried 3006.3): ############################################################################## [TRACE ] IPCServer: Handling connection to address: [TRACE ] Clear payload received with command publish [DEBUG ] The functions from module 'local_cache' are being loaded by dir() on the loaded module [DEBUG ] LazyLoaded local_cache.prep_jid [TRACE ] IPCClient: Connecting to socket: /var/run/salt/master/master_event_pull.ipc [TRACE ] IPCServer: Handling connection to address: [DEBUG ] Sending event: tag = 20240103085119096806; data = {'minions': ['saltminion01.dev.home.arpa'], '_stamp': '2024-01-03T08:51:19.110294'} [DEBUG ] Sending event: tag = salt/job/20240103085119096806/new; data = {'jid': '20240103085119096806', 'tgt_type': 'glob', 'tgt': 'saltminion01*', 'user': 'root', 'fun': ' publish.publish', 'arg': ['*', 'test.ping'], 'minions': ['saltminion01.dev.home.arpa'], 'missing': [], '_stamp': '2024-01-03T08:51:19.111658'} [DEBUG ] Adding minions for job 20240103085119096806: ['saltminion01.dev.home.arpa'] [INFO ] User root Published command publish.publish with jid 20240103085119096806 [DEBUG ] Published command details {'fun': 'publish.publish', 'arg': ['*', 'test.ping'], 'tgt': 'saltminion01*', 'jid': '20240103085119096806', 'ret': '', 'tgt_type': 'glob ', 'user': 'root'} [DEBUG ] Sending payload to publish daemon. jid=20240103085119096806 load={'fun': 'publish.publish', 'arg': ['*', [DEBUG ] Connecting to pub server: ipc:///var/run/salt/master/publish_pull.ipc [DEBUG ] Sent payload to publish daemon. [DEBUG ] Using selector: KqueueSelector [DEBUG ] Signing data packet [DEBUG ] salt.crypt.get_rsa_key: Loading private key [DEBUG ] salt.crypt.sign_message: Signing message. [TRACE ] Sending ZMQ-unfiltered data over publisher tcp://0.0.0.0:4505 [TRACE ] Unfiltered data has been sent [TRACE ] AES payload received with command minion_pub [DEBUG ] salt.crypt.get_rsa_pub_key: Loading public key [TRACE ] ReqChannel send clear load={'cmd': 'publish', 'tgt': '*', 'fun': 'test.ping', 'arg': [], 'key': '+myW/ReuYSTE0+oOLzuF/Vr9d8Y3DQF0q6OmWT075TpE4XN8s1qLlzZVj71ibA4eKq Dw/M9fCw8=', 'tgt_type': 'glob', 'ret': '', 'jid': '', 'kwargs': {'id': 'saltminion01.dev.home.arpa'}, 'user': '_salt'} [TRACE ] Failed to send msg SaltReqTimeoutError('Message timed out') [TRACE ] ReqChannel send clear load={'cmd': 'publish', 'tgt': '*', 'fun': 'test.ping', 'arg': [], 'key': '+myW/ReuYSTE0+oOLzuF/Vr9d8Y3DQF0q6OmWT075TpE4XN8s1qLlzZVj71ibA4eKq Dw/M9fCw8=', 'tgt_type': 'glob', 'ret': '', 'jid': '', 'kwargs': {'id': 'saltminion01.dev.home.arpa'}, 'user': '_salt'} [TRACE ] Clear payload received with command publish [DEBUG ] The functions from module 'local_cache' are being loaded by dir() on the loaded module [DEBUG ] LazyLoaded local_cache.prep_jid [TRACE ] IPCClient: Connecting to socket: /var/run/salt/master/master_event_pull.ipc 09:51:34 [321/23978] [TRACE ] IPCServer: Handling connection to address: [DEBUG ] Sending event: tag = 20240103085124360412; data = {'minions': ['saltminion01.dev.home.arpa'], '_stamp': '2024-01-03T08:51:24.376912'} [DEBUG ] Sending event: tag = salt/job/20240103085124360412/new; data = {'jid': '20240103085124360412', 'tgt_type': 'list', 'tgt': ['saltminion01.dev.home.arpa'], 'user': ' root', 'fun': 'saltutil.find_job', 'arg': ['20240103085119096806'], 'minions': ['saltminion01.dev.home.arpa'], 'missing': [], '_stamp': '2024-01-03T08:51:24.383486'} [DEBUG ] Adding minions for job 20240103085124360412: ['saltminion01.dev.home.arpa'] [INFO ] User root Published command saltutil.find_job with jid 20240103085124360412 [DEBUG ] Published command details {'fun': 'saltutil.find_job', 'arg': ['20240103085119096806'], 'tgt': ['saltminion01.dev.home.arpa'], 'jid': '20240103085124360412', 'ret' : '', 'tgt_type': 'list', 'user': 'root'} [DEBUG ] Sending payload to publish daemon. jid=20240103085124360412 load={'fun': 'saltutil.find_job', 'arg': ['20 [DEBUG ] Connecting to pub server: ipc:///var/run/salt/master/publish_pull.ipc [DEBUG ] Sent payload to publish daemon. [DEBUG ] Using selector: KqueueSelector [DEBUG ] Signing data packet [DEBUG ] salt.crypt.get_rsa_key: Loading private key [DEBUG ] salt.crypt.sign_message: Signing message. [TRACE ] Sending ZMQ-unfiltered data over publisher tcp://0.0.0.0:4505 [TRACE ] Unfiltered data has been sent [TRACE ] AES payload received with command _return [INFO ] Got return from saltminion01.dev.home.arpa for job 20240103085124360412 [DEBUG ] Sending event: tag = salt/job/20240103085124360412/ret/saltminion01.dev.home.arpa; data = {'cmd': '_return', 'id': 'saltminion01.dev.home.arpa', 'success': True, ' return': {'pid': 21357, 'fun': 'publish.publish', 'arg': ['*', 'test.ping'], 'tgt': 'saltminion01*', 'jid': '20240103085119096806', 'ret': '', 'tgt_type': 'glob', 'user': 'ro ot'}, 'retcode': 0, 'jid': '20240103085124360412', 'fun': 'saltutil.find_job', 'fun_args': ['20240103085119096806'], 'user': 'root', '_stamp': '2024-01-03T08:51:24.564867'} [DEBUG ] Reading minion list from /var/cache/salt/master/jobs/d2/a10e40a1cd48fa0d3b516ee19269378a0cf00544bb910008c92ca827c0a9aa/.minions.p [TRACE ] Process manager iteration [TRACE ] Master function call _return took 0.004743814468383789 seconds [TRACE ] Process manager iteration [TRACE ] Failed to send msg SaltReqTimeoutError('Message timed out') [TRACE ] ReqChannel send clear load={'cmd': 'publish', 'tgt': '*', 'fun': 'test.ping', 'arg': [], 'key': '+myW/ReuYSTE0+oOLzuF/Vr9d8Y3DQF0q6OmWT075TpE4XN8s1qLlzZVj71ibA4eKq Dw/M9fCw8=', 'tgt_type': 'glob', 'ret': '', 'jid': '', 'kwargs': {'id': 'saltminion01.dev.home.arpa'}, 'user': '_salt'} [TRACE ] Failed to send msg SaltReqTimeoutError('Message timed out') [ERROR ] Message timed out [DEBUG ] Closing AsyncReqChannel instance [ERROR ] Error in function minion_pub: Traceback (most recent call last): File "/usr/local/lib/python3.10/site-packages/salt/client/__init__.py", line 1910, in pub payload = channel.send(payload_kwargs, timeout=timeout) File "/usr/local/lib/python3.10/site-packages/salt/utils/asynchronous.py", line 125, in wrap raise exc_info[1].with_traceback(exc_info[2]) File "/usr/local/lib/python3.10/site-packages/salt/utils/asynchronous.py", line 131, in _target result = io_loop.run_sync(lambda: getattr(self.obj, key)(*args, **kwargs)) File "/usr/local/lib/python3.10/site-packages/salt/ext/tornado/ioloop.py", line 459, in run_sync return future_cell[0].result() File "/usr/local/lib/python3.10/site-packages/salt/ext/tornado/concurrent.py", line 249, in result raise_exc_info(self._exc_info) File "", line 4, in raise_exc_info File "/usr/local/lib/python3.10/site-packages/salt/ext/tornado/gen.py", line 1064, in run yielded = self.gen.throw(*exc_info) File "/usr/local/lib/python3.10/site-packages/salt/channel/client.py", line 338, in send ret = yield self._uncrypted_transfer(load, timeout=timeout) File "/usr/local/lib/python3.10/site-packages/salt/ext/tornado/gen.py", line 1056, in run value = future.result() File "/usr/local/lib/python3.10/site-packages/salt/ext/tornado/concurrent.py", line 249, in result raise_exc_info(self._exc_info) File "", line 4, in raise_exc_info File "/usr/local/lib/python3.10/site-packages/salt/ext/tornado/gen.py", line 1064, in run yielded = self.gen.throw(*exc_info) File "/usr/local/lib/python3.10/site-packages/salt/channel/client.py", line 309, in _uncrypted_transfer ret = yield self.transport.send( File "/usr/local/lib/python3.10/site-packages/salt/ext/tornado/gen.py", line 1056, in run value = future.result() File "/usr/local/lib/python3.10/site-packages/salt/ext/tornado/concurrent.py", line 249, in result raise_exc_info(self._exc_info) File "", line 4, in raise_exc_info File "/usr/local/lib/python3.10/site-packages/salt/ext/tornado/gen.py", line 1064, in run yielded = self.gen.throw(*exc_info) File "/usr/local/lib/python3.10/site-packages/salt/transport/zeromq.py", line 909, in send ret = yield self.message_client.send(load, timeout=timeout) File "/usr/local/lib/python3.10/site-packages/salt/ext/tornado/gen.py", line 1056, in run value = future.result() File "/usr/local/lib/python3.10/site-packages/salt/ext/tornado/concurrent.py", line 249, in result raise_exc_info(self._exc_info) File "", line 4, in raise_exc_info File "/usr/local/lib/python3.10/site-packages/salt/ext/tornado/gen.py", line 1064, in run yielded = self.gen.throw(*exc_info) File "/usr/local/lib/python3.10/site-packages/salt/transport/zeromq.py", line 589, in send recv = yield future File "/usr/local/lib/python3.10/site-packages/salt/ext/tornado/gen.py", line 1056, in run value = future.result() File "/usr/local/lib/python3.10/site-packages/salt/ext/tornado/concurrent.py", line 249, in result raise_exc_info(self._exc_info) File "", line 4, in raise_exc_info salt.exceptions.SaltReqTimeoutError: Message timed out During handling of the above exception, another exception occurred: Traceback (most recent call last): File "/usr/local/lib/python3.10/site-packages/salt/client/__init__.py", line 387, in run_job pub_data = self.pub( File "/usr/local/lib/python3.10/site-packages/salt/client/__init__.py", line 1913, in pub raise SaltReqTimeoutError( salt.exceptions.SaltReqTimeoutError: Salt request timed out. The master is not responding. You may need to run your command with `--async` in order to bypass the congested ev ent bus. With `--async`, the CLI tool will print the job id (jid) and exit immediately without listening for responses. You can then use `salt-run jobs.lookup_jid` to look up the results of the job in the job cache later. During handling of the above exception, another exception occurred: Traceback (most recent call last): File "/usr/local/lib/python3.10/site-packages/salt/master.py", line 1918, in run_func ret = getattr(self, func)(load) File "/usr/local/lib/python3.10/site-packages/salt/master.py", line 1839, in minion_pub return self.masterapi.minion_pub(clear_load) File "/usr/local/lib/python3.10/site-packages/salt/daemons/masterapi.py", line 952, in minion_pub ret["jid"] = self.local.cmd_async(**pub_load) File "/usr/local/lib/python3.10/site-packages/salt/client/__init__.py", line 494, in cmd_async pub_data = self.run_job( File "/usr/local/lib/python3.10/site-packages/salt/client/__init__.py", line 409, in run_job raise SaltClientError(general_exception) salt.exceptions.SaltClientError: Salt request timed out. The master is not responding. You may need to run your command with `--async` in order to bypass the congested event bus. With `--async`, the CLI tool will print the job id (jid) and exit immediately without listening for responses. You can then use `salt-run jobs.lookup_jid` to look up the results of the job in the job cache later. [DEBUG ] Using selector: KqueueSelector [TRACE ] AES payload received with command _return [INFO ] Got return from saltminion01.dev.home.arpa for job 20240103085119096806 [DEBUG ] Sending event: tag = salt/job/20240103085119096806/ret/saltminion01.dev.home.arpa; data = {'cmd': '_return', 'id': 'saltminion01.dev.home.arpa', 'success': True, ' return': {}, 'retcode': 0, 'jid': '20240103085119096806', 'fun': 'publish.publish', 'fun_args': ['*', 'test.ping'], 'user': 'root', '_stamp': '2024-01-03T08:51:34.338020'} [DEBUG ] Reading minion list from /var/cache/salt/master/jobs/9a/18bdd2d7c6911863b6944d6e71eeaaa5ac83d0a43a4790718061e27d949ef6/.minions.p ############################################################################## To verify that this isn't a problem with salt as is I installed 3006.4 on an Alpine Linux - and there it works, so it must be something OpenBSD specific (and probably something with zmq): ############################################################################## [DEBUG ] Performing fileserver updates for items with an update interval of 60 [DEBUG ] Updating roots fileserver cache [DEBUG ] Completed fileserver updates for items with an update interval of 60, waiting 60 seconds [TRACE ] Process manager iteration [TRACE ] Process manager iteration [INFO ] Authentication request from alpine.dev.home.arpa [INFO ] Authentication accepted from alpine.dev.home.arpa [DEBUG ] salt.crypt.get_rsa_pub_key: Loading public key [TRACE ] IPCClient: Connecting to socket: /var/run/salt/master/master_event_pull.ipc [TRACE ] IPCServer: Handling connection to address: [DEBUG ] Sending event: tag = salt/auth; data = {'result': True, 'act': 'accept', 'id': 'alpine.dev.home.arpa', 'pub': '-----BEGIN PUBLIC KEY-----\nMIIBIjANBgkqhkiG9w0BAQEF AAOCAQ8AMIIBCgKCAQEA4Eq8Rv2REb/Gi+j6kFll\nZA9viZIQ6jIARvq78u7DkmqnpqE3nuiyNmwmDxWInQhclK4p7jVIucEFn5WvZZcM\nIL8RmoLvGQiDwjrPtlzYKglNafyqR0kCr+jZ2IZyg6uZ0b8C9GezbwfRhU7pirLK\n 9oJQh3F9DNllggrh3M7NqROSWCQ9dvbO8+pNArov5EGyy+I14gLD5xWx1P9IuHQ0\nn6ZoiMCsu7ytCLs0YtLG1JokhhnfdGJzA2crOYbRBKGmGDe/c1+EQQSTtIQQrbQY\nuJlo2lhyFYyTNqlJO2UNUIz1sliEnKQvAhhqHSwgw7 e1P0zMCrHX3YZG6VA/ptKB\n9wIDAQAB\n-----END PUBLIC KEY-----', '_stamp': '2024-01-03T07:56:43.560429'} [DEBUG ] salt.crypt.get_rsa_key: Loading private key [DEBUG ] salt.crypt.sign_message: Signing message. [DEBUG ] ZeroMQ event: {'event': , 'value': , 'endpoint': b'tcp://127.0.0.1:4505', 'descri ption': 'EVENT_ACCEPTED'} [DEBUG ] ZeroMQ event: {'event': , 'value': , 'endpoint': b'tcp://127.0.0.1:4505', 'description': 'EVENT_HANDSHAKE_SUCCEEDED'} [TRACE ] AES payload received with command _pillar [DEBUG ] Determining pillar cache [DEBUG ] The functions from module 'jinja' are being loaded by dir() on the loaded module [DEBUG ] LazyLoaded jinja.render [DEBUG ] The functions from module 'yaml' are being loaded by dir() on the loaded module [DEBUG ] LazyLoaded yaml.render [DEBUG ] The functions from module 'roots' are being loaded by dir() on the loaded module [DEBUG ] The functions from module 's3fs' are being loaded by dir() on the loaded module [DEBUG ] The functions from module 'localfs' are being loaded by dir() on the loaded module [DEBUG ] LazyLoaded localfs.init_kwargs [TRACE ] IPCClient: Connecting to socket: /var/run/salt/master/master_event_pull.ipc [TRACE ] IPCServer: Handling connection to address: [DEBUG ] Sending event: tag = minion/refresh/alpine.dev.home.arpa; data = {'Minion data cache refresh': 'alpine.dev.home.arpa', '_stamp': '2024-01-03T07:56:43.636137'} [TRACE ] Master function call _pillar took 0.04756474494934082 seconds [DEBUG ] salt.crypt.get_rsa_pub_key: Loading public key [DEBUG ] salt.crypt.get_rsa_key: Loading private key [DEBUG ] salt.crypt.sign_message: Signing message. [TRACE ] AES payload received with command minion_pub [DEBUG ] salt.crypt.get_rsa_pub_key: Loading public key [TRACE ] ReqChannel send clear load={'cmd': 'publish', 'tgt': 'alpine*', 'fun': 'test.ping', 'arg': [], 'key': 'jzsb0YPajyIy30UwR8NBGRcPu3qv5zfs31sJqi1jHMmYBZ4zKIsmZA+7q/I+ NBjC1l4l0mbfJCs=', 'tgt_type': 'glob', 'ret': '', 'jid': '', 'kwargs': {'id': 'alpine.dev.home.arpa'}, 'user': 'root'} [TRACE ] Clear payload received with command publish ############################################################################## alpine# salt-call publish.publish alpine\* test.ping local: ---------- alpine.dev.home.arpa: True Anyone an idea? publish.runner with an OpenBSD master works as expected: salt saltminion01\* publish.runner manage.reaped saltminion01.dev.home.arpa: - saltminion01.dev.home.arpa The main error occurs somewhere here: [TRACE ] Failed to send msg SaltReqTimeoutError('Message timed out') [ERROR ] Message timed out [DEBUG ] Closing AsyncReqChannel instance [ERROR ] Error in function minion_pub: I would like to trace that down but I'm lost a little bit atm. Many thanks in advance and with best regards. Uwe