Wednesday, January 03, 2024

saltstack and publish.publish

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: <socket.socket fd=32, family=AddressFamily.AF_UNIX, type=SocketKind.SOCK_STREAM, proto=0, laddr=/var/run/salt/master/mas
ter_event_pull.ipc>
[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: <socket.socket fd=33, family=AddressFamily.AF_UNIX, type=SocketKind.SOCK_STREAM, proto=0, laddr=/var/run/salt/master/mas
ter_event_pull.ipc>
[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 "<string>", 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 "<string>", 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 "<string>", 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 "<string>", 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 "<string>", 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: <socket.socket fd=31, family=1, type=1, proto=0, laddr=/var/run/salt/master/master_event_pull.ipc>
[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': <Event.ACCEPTED: 32>, 'value': <Event.CONNECTED|CONNECT_DELAYED|CONNECT_RETRIED|ACCEPTED: 39>, 'endpoint': b'tcp://127.0.0.1:4505', 'descri
ption': 'EVENT_ACCEPTED'}
[DEBUG ] ZeroMQ event: {'event': <Event.HANDSHAKE_SUCCEEDED: 4096>, 'value': <Event: 0>, '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: <socket.socket fd=32, family=1, type=1, proto=0, laddr=/var/run/salt/master/master_event_pull.ipc>
[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

No comments:

Post a Comment