Failed to send msg TypeError("can't serialize {'minion_hostname'}",) when tcp transport enabled

werwaznadn commented 9 months ago

Problem description

Hello

I enabled tcp communication for salt minion-master. After that action remote commands execution via uyuni Ui stopped working. Ui is not able to get existing minions.

The same problem occurs during any highstate execution via uyuni UI. Commands executed via salt cli works fine. When tcp transport is disabled everything works fine from UI.

Setup Uyuni VM running on a public cloud

/etc/salt/master.d/ssl.conf transport: tcp

Steps to reproduce

UyuniUI -> Salt -> Remote Commands -> Find targets on master VM: journalctl --follow -u salt-master

Uyuni version

2024.01-230900.212.1.uyuni3

Salt Version:
          Salt: 3006.0

Python Version:
        Python: 3.6.15 (default, Sep 23 2021, 15:41:43) [GCC]

Dependency Versions:
          cffi: 1.13.2
      cherrypy: unknown
      dateutil: 2.8.1
     docker-py: Not Installed
         gitdb: Not Installed
     gitpython: Not Installed
        Jinja2: 2.10.1
       libgit2: 1.3.0
  looseversion: 1.0.2
      M2Crypto: 0.38.0
          Mako: Not Installed
       msgpack: 0.5.6
  msgpack-pure: Not Installed
  mysql-python: Not Installed
     packaging: 21.3
     pycparser: 2.17
      pycrypto: 3.9.0
  pycryptodome: Not Installed
        pygit2: 1.7.0
  python-gnupg: Not Installed
        PyYAML: 5.4.1
         PyZMQ: 17.1.2
        relenv: Not Installed
         smmap: Not Installed
       timelib: Not Installed
       Tornado: 4.5.3
           ZMQ: 4.2.3

System Versions:
          dist: opensuse-leap 15.5
        locale: UTF-8
       machine: x86_64
       release: 5.14.21-150500.55.44-default
        system: Linux
       version: openSUSE Leap 15.5

Uyuni proxy version (if used)

No response

Useful logs

salt-master service logs related to remote command event: 

Feb 20 15:42:43 uyuni salt-master[2198]: [DEBUG   ] Could not LazyLoad file.acl: 'file.acl' is not available.
Feb 20 15:42:43 uyuni salt-master[2198]: [DEBUG   ] Could not LazyLoad file.groups: 'file.groups' is not available.
Feb 20 15:42:43 uyuni salt-master[2198]: [DEBUG   ] Could not LazyLoad file.process_acl: 'file.process_acl' is not available.
Feb 20 15:42:43 uyuni salt-master[2198]: [DEBUG   ] Reading configuration from /etc/salt/master
Feb 20 15:42:43 uyuni salt-master[2198]: [DEBUG   ] Including configuration from '/etc/salt/master.d/autosign-key.conf'
Feb 20 15:42:43 uyuni salt-master[2198]: [DEBUG   ] Reading configuration from /etc/salt/master.d/autosign-key.conf
Feb 20 15:42:43 uyuni salt-master[2198]: [DEBUG   ] Including configuration from '/etc/salt/master.d/salt-ssh-logging.conf'
Feb 20 15:42:43 uyuni salt-master[2198]: [DEBUG   ] Reading configuration from /etc/salt/master.d/salt-ssh-logging.conf
Feb 20 15:42:43 uyuni salt-master[2198]: [DEBUG   ] Including configuration from '/etc/salt/master.d/security.conf'
Feb 20 15:42:43 uyuni salt-master[2198]: [DEBUG   ] Reading configuration from /etc/salt/master.d/security.conf
Feb 20 15:42:43 uyuni salt-master[2198]: [DEBUG   ] Including configuration from '/etc/salt/master.d/susemanager.conf'
Feb 20 15:42:43 uyuni salt-master[2198]: [DEBUG   ] Reading configuration from /etc/salt/master.d/susemanager.conf
Feb 20 15:42:43 uyuni salt-master[2198]: [DEBUG   ] Including configuration from '/etc/salt/master.d/susemanager_db.conf'
Feb 20 15:42:43 uyuni salt-master[2198]: [DEBUG   ] Reading configuration from /etc/salt/master.d/susemanager_db.conf
Feb 20 15:42:43 uyuni salt-master[2198]: [DEBUG   ] Including configuration from '/etc/salt/master.d/susemanager_engine.conf'
Feb 20 15:42:43 uyuni salt-master[2198]: [DEBUG   ] Reading configuration from /etc/salt/master.d/susemanager_engine.conf
Feb 20 15:42:43 uyuni salt-master[2198]: [DEBUG   ] Including configuration from '/etc/salt/master.d/uyuni_roster.conf'
Feb 20 15:42:43 uyuni salt-master[2198]: [DEBUG   ] Reading configuration from /etc/salt/master.d/uyuni_roster.conf
Feb 20 15:42:43 uyuni salt-master[2198]: [DEBUG   ] Including configuration from '/etc/salt/master.d/virtualization-host-formula.conf'
Feb 20 15:42:43 uyuni salt-master[2198]: [DEBUG   ] Reading configuration from /etc/salt/master.d/virtualization-host-formula.conf
Feb 20 15:42:43 uyuni salt-master[2198]: [DEBUG   ] Using cached minion ID from /etc/salt/minion_id: minion_hostname
Feb 20 15:42:43 uyuni salt-master[2198]: [DEBUG   ] Missing configuration file: /var/lib/salt/.saltrc
Feb 20 15:42:43 uyuni salt-master[2198]: [DEBUG   ] MasterEvent PUB socket URI: /var/run/salt/master/master_event_pub.ipc
Feb 20 15:42:43 uyuni salt-master[2198]: [DEBUG   ] MasterEvent PULL socket URI: /var/run/salt/master/master_event_pull.ipc
Feb 20 15:42:43 uyuni salt-master[2198]: [DEBUG   ] MasterEvent PUB socket URI: /var/run/salt/master/master_event_pub.ipc
Feb 20 15:42:43 uyuni salt-master[2198]: [DEBUG   ] MasterEvent PULL socket URI: /var/run/salt/master/master_event_pull.ipc
Feb 20 15:42:43 uyuni salt-master[2194]: [DEBUG   ] Could not LazyLoad file.acl: 'file.acl' is not available.
Feb 20 15:42:43 uyuni salt-master[2194]: [DEBUG   ] Could not LazyLoad file.groups: 'file.groups' is not available.
Feb 20 15:42:43 uyuni salt-master[2194]: [DEBUG   ] Could not LazyLoad file.process_acl: 'file.process_acl' is not available.
Feb 20 15:42:43 uyuni salt-master[2194]: [DEBUG   ] Sending event: tag = 20240220154243435550; data = {'minions': ['minion_hostname'], '_stamp': '2024-02-20T15:42:43.449226'}
Feb 20 15:42:43 uyuni salt-master[2194]: [DEBUG   ] Sending event: tag = salt/job/20240220154243435550/new; data = {'jid': '20240220154243435550', 'tgt_type': 'list', 'tgt': ['minion_hostname'], 'user': 'admin', 'fun': 'test.ping', 'arg': [], 'minions': ['minion_hostname'], 'missing': [], '_stamp': '2024-02-20T15:42:43.451411'}
Feb 20 15:42:43 uyuni salt-master[2184]: [DEBUG   ] salt.loaded.ext.engines.mgr_events: Discarding event -> 20240220154243435550
Feb 20 15:42:43 uyuni salt-master[2187]: [DEBUG   ] Gathering reactors for tag 20240220154243435550
Feb 20 15:42:43 uyuni salt-master[2184]: [DEBUG   ] salt.loaded.ext.engines.mgr_events: Discarding event -> salt/job/20240220154243435550/new
Feb 20 15:42:43 uyuni salt-master[2187]: [DEBUG   ] Gathering reactors for tag salt/job/20240220154243435550/new
Feb 20 15:42:43 uyuni salt-master[2194]: [DEBUG   ] Adding minions for job 20240220154243435550: ['minion_hostname']
Feb 20 15:42:43 uyuni salt-master[2194]: [INFO    ] User admin Published command test.ping with jid 20240220154243435550
Feb 20 15:42:43 uyuni salt-master[2194]: [DEBUG   ] Published command details {'fun': 'test.ping', 'arg': [], 'tgt': ['minion_hostname'], 'jid': '20240220154243435550', 'ret': '', 'tgt_type': 'list', 'metadata': {'suma-action-id': 0, 'suma-force-pkg-list-refresh': False, 'suma-action-chain': False, 'batch-mode': True, 'suma-minion-startup': False}, 'user': 'admin'}
Feb 20 15:42:43 uyuni salt-master[2194]: [DEBUG   ] Sending payload to publish daemon. jid=20240220154243435550 load={'fun': 'test.ping', 'arg': [], 'tgt': [
Feb 20 15:42:43 uyuni salt-master[2182]: [DEBUG   ] Signing data packet
Feb 20 15:42:43 uyuni salt-master[2182]: [DEBUG   ] salt.crypt.get_rsa_key: Loading private key
Feb 20 15:42:43 uyuni salt-master[2198]: [DEBUG   ] Closing AsyncReqChannel instance
Feb 20 15:42:43 uyuni salt-master[2182]: [DEBUG   ] salt.crypt.sign_message: Signing message.
Feb 20 15:42:43 uyuni salt-master[2198]: [DEBUG   ] Could not LazyLoad file.acl: 'file.acl' is not available.
Feb 20 15:42:43 uyuni salt-master[2198]: [DEBUG   ] Could not LazyLoad file.groups: 'file.groups' is not available.
Feb 20 15:42:43 uyuni salt-master[2198]: [DEBUG   ] Could not LazyLoad file.process_acl: 'file.process_acl' is not available.
Feb 20 15:42:43 uyuni salt-master[2197]: [INFO    ] Got return from minion_hostname for job 20240220154243435550
Feb 20 15:42:43 uyuni salt-master[2197]: [DEBUG   ] Sending event: tag = salt/job/20240220154243435550/ret/minion_hostname; data = {'cmd': '_return', 'id': 'minion_hostname', 'success': True, 'return': True, 'retcode': 0, 'jid': '20240220154243435550', 'fun': 'test.ping', 'fun_args': [], 'metadata': {'suma-action-id': 0, 'suma-force-pkg-list-refresh': False, 'suma-action-chain': False, 'batch-mode': True, 'suma-minion-startup': False}, '_stamp': '2024-02-20T15:42:43.618614'}
Feb 20 15:42:43 uyuni salt-master[2187]: [DEBUG   ] Gathering reactors for tag salt/job/20240220154243435550/ret/minion_hostname
Feb 20 15:42:43 uyuni salt-master[2184]: [DEBUG   ] salt.loaded.ext.engines.mgr_events: Discarding event -> salt/job/20240220154243435550/ret/minion_hostname
Feb 20 15:42:43 uyuni salt-master[2198]: [DEBUG   ] Sending event: tag = salt/batch/20240220154243435934/start; data = {'available_minions': {'minion_hostname'}, 'down_minions': set(), 'metadata': {'suma-action-id': 0, 'suma-force-pkg-list-refresh': False, 'suma-action-chain': False, 'batch-mode': True, 'suma-minion-startup': False}, '_stamp': '2024-02-20T15:42:43.621027'}
Feb 20 15:42:43 uyuni salt-master[2198]: [ERROR   ] Failed to send msg TypeError("can't serialize {'minion_hostname'}",)
Feb 20 15:42:43 uyuni salt-master[2198]: [ERROR   ] Failed to send msg TypeError("can't serialize {'minion_hostname'}",)
Feb 20 15:42:43 uyuni salt-master[2198]: [ERROR   ] Failed to send msg TypeError("can't serialize {'minion_hostname'}",)
Feb 20 15:42:43 uyuni salt-master[2198]: [DEBUG   ] Closing AsyncReqChannel instance
Feb 20 15:42:43 uyuni salt-master[2198]: [ERROR   ] Error in scheduling next batch: can't serialize {'minion_hostname'}. Aborting execution
Feb 20 15:42:43 uyuni salt-master[2198]: [DEBUG   ] Closing IPCMessageSubscriber instance
Feb 20 15:42:43 uyuni salt-master[2198]: [DEBUG   ] Closing IPCMessageClient instance
Feb 20 15:42:43 uyuni salt-master[2198]: [DEBUG   ] Closing IPCMessageSubscriber instance
Feb 20 15:42:43 uyuni salt-master[2198]: [ERROR   ] Future <salt.ext.tornado.concurrent.Future object at 0x7f55a4bfdf98> exception was never retrieved: Traceback (most recent call last):
Feb 20 15:42:43 uyuni salt-master[2198]:   File "/usr/lib/python3.6/site-packages/salt/transport/ipc.py", line 342, in _connect
Feb 20 15:42:43 uyuni salt-master[2198]:     yield self.stream.connect(sock_addr)
Feb 20 15:42:43 uyuni salt-master[2198]:   File "/usr/lib/python3.6/site-packages/salt/ext/tornado/gen.py", line 1056, in run
Feb 20 15:42:43 uyuni salt-master[2198]:     value = future.result()
Feb 20 15:42:43 uyuni salt-master[2198]:   File "/usr/lib/python3.6/site-packages/salt/ext/tornado/concurrent.py", line 249, in result
Feb 20 15:42:43 uyuni salt-master[2198]:     raise_exc_info(self._exc_info)
Feb 20 15:42:43 uyuni salt-master[2198]:   File "<string>", line 4, in raise_exc_info
Feb 20 15:42:43 uyuni salt-master[2198]: salt.ext.tornado.iostream.StreamClosedError: Stream is closed
Feb 20 15:42:43 uyuni salt-master[2198]: During handling of the above exception, another exception occurred:
Feb 20 15:42:43 uyuni salt-master[2198]: Traceback (most recent call last):
Feb 20 15:42:43 uyuni salt-master[2198]:   File "/usr/lib/python3.6/site-packages/salt/ext/tornado/gen.py", line 1064, in run
Feb 20 15:42:43 uyuni salt-master[2198]:     yielded = self.gen.throw(*exc_info)
Feb 20 15:42:43 uyuni salt-master[2198]:   File "/usr/lib/python3.6/site-packages/salt/transport/ipc.py", line 353, in _connect
Feb 20 15:42:43 uyuni salt-master[2198]:     self._connecting_future.set_exception(e)
Feb 20 15:42:43 uyuni salt-master[2198]: AttributeError: 'NoneType' object has no attribute 'set_exception'
Feb 20 15:42:44 uyuni salt-master[2184]: [DEBUG   ] salt.loaded.ext.engines.mgr_events: Discarding event -> salt/run/20240220154243469864/new
Feb 20 15:42:44 uyuni salt-master[2187]: [DEBUG   ] Gathering reactors for tag salt/run/20240220154243469864/new
Feb 20 15:42:45 uyuni salt-master[2184]: [DEBUG   ] salt.loaded.ext.engines.mgr_events: Discarding event -> salt/run/20240220154243469864/ret
Feb 20 15:42:45 uyuni salt-master[2187]: [DEBUG   ] Gathering reactors for tag salt/run/20240220154243469864/ret

Events monitored during remote_command execution:

[DEBUG   ] The functions from module 'winrepo' are being loaded by dir() on the loaded module
[DEBUG   ] Sending event: tag = salt/run/20240220154224294339/new; data = {'fun': 'runner.state.event', 'jid': '20240220154224294339', 'user': 'salt', 'fun_args': [{'pretty': True}], '_stamp': '2024-02-20T15:42:25.319040'}
[DEBUG   ] The functions from module 'state' are being loaded by dir() on the loaded module
[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
20240220154243435550    {
    "_stamp": "2024-02-20T15:42:43.449226",
    "minions": [
        "minion_hostname"
    ]
}
salt/job/20240220154243435550/new       {
    "_stamp": "2024-02-20T15:42:43.451411",
    "arg": [],
    "fun": "test.ping",
    "jid": "20240220154243435550",
    "minions": [
        "minion_hostname"
    ],
    "missing": [],
    "tgt": [
        "minion_hostname"
    ],
    "tgt_type": "list",
    "user": "admin"
}
salt/job/20240220154243435550/ret/minion_hostname {
    "_stamp": "2024-02-20T15:42:43.618614",
    "cmd": "_return",
    "fun": "test.ping",
    "fun_args": [],
    "id": "minion_hostname",
    "jid": "20240220154243435550",
    "metadata": {
        "batch-mode": true,
        "suma-action-chain": false,
        "suma-action-id": 0,
        "suma-force-pkg-list-refresh": false,
        "suma-minion-startup": false
    },
    "retcode": 0,
    "return": true,
    "success": true
}
salt/run/20240220154243469864/new       {
    "_stamp": "2024-02-20T15:42:44.456899",
    "fun": "runner.jobs.lookup_jid",
    "fun_args": [
        {
            "jid": "20240220154243435934"
        }
    ],
    "jid": "20240220154243469864",
    "user": "admin"
}
salt/run/20240220154243469864/ret       {
    "_stamp": "2024-02-20T15:42:45.608033",
    "fun": "runner.jobs.lookup_jid",
    "fun_args": [
        {
            "jid": "20240220154243435934"
        }
    ],
    "jid": "20240220154243469864",
    "return": {},
    "success": true,
    "user": "admin"
}

Communication between master and minion works fine. tasks executed via cli works:

>>salt --batch 1 "*" cmd.run 'sleep 5'

[DEBUG   ] Marking 'yaml_dquote' as a jinja filter
[DEBUG   ] Marking 'yaml_squote' as a jinja filter
[DEBUG   ] Marking 'yaml_encode' as a jinja filter
[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/3a/99d702464aa0080f598d180e74d907aae61a78aac3f992a67d378768c41262/.minions.p
[DEBUG   ] get_iter_returns for jid 20240220155632390020 sent to {'minion_hostname'} will timeout at 15:58:32.398173
[DEBUG   ] jid 20240220155632390020 return from minion_hostname
[DEBUG   ] jid 20240220155632390020 found all minions {'minion_hostname'}

Executing run on ['minion_hostname']

[DEBUG   ] Closing AsyncReqChannel instance
[DEBUG   ] Reading minion list from /var/cache/salt/master/jobs/e8/2cacc5875bd4a895b9b4c36c1b704a2e20f2d9ff0ae0f669b285dce1d42933/.minions.p
[DEBUG   ] get_iter_returns for jid 20240220155632629469 sent to {'minion_hostname'} will timeout at 15:58:32.635335
[DEBUG   ] jid 20240220155632629469 return from minion_hostname
[DEBUG   ] jid 20240220155632629469 found all minions {'minion_hostname'}
[DEBUG   ] The functions from module 'nested' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded nested.output
jid:
    20240220155632629469
minion_hostname:
retcode:
    0
[DEBUG   ] Closing IPCMessageSubscriber instance

Additional information

No response

szymonsypula commented 8 months ago

Hey,

I have tried some time ago same configuration and experienced the same result. Looking forward to see resolution.

Bump.

agraul commented 8 months ago

Thank you for the detailed bug report. We currently don't test with the tcp transport backend, only with zeromq. It's clearly a bug we need to look at.

Can you share more information on why you want to use tcp over zeromq? Having more background information will help us with prioritizing this bug appropriately.

shivamsaraiya commented 8 months ago

Thank you for the detailed bug report. We currently don't test with the tcp transport backend, only with zeromq. It's clearly a bug we need to look at.

Can you share more information on why you want to use tcp over zeromq? Having more background information will help us with prioritizing this bug appropriately.

Hi @agraul, In order to secure the traffic between minion and Master, we wanted to implement mutual TLS cert verification. Hence, this was only possible if we change the protocol to TCP as we found that zeromq does not support TLS client cert verification.

agraul commented 8 months ago

That's correct, Salt with zeromq does not use TLS client cert verification. What advantages do you expect from mTLS over the built-in authentication with self-generated public/private key-pairs?

shivamsaraiya commented 8 months ago

That's correct, Salt with zeromq does not use TLS client cert verification. What advantages do you expect from mTLS over the built-in authentication with self-generated public/private key-pairs?

Hi @agraul in order to secure minion - master communication when used on public internet.

cFabij commented 8 months ago

Hi @shivamsaraiya!

To elaborate agraul's answer a bit further:

When you onboard a (future) Salt minion it will send its public key to the Salt master.
The Salt master must accept this public key in order to onboard the (future) minion.
By accepting, the Salt master will in return send its own public key to the Salt minion.
Salt master will also send an AES key, which is used to encrypt and decrypt messages sent by Salt master.
This AES key is encrypted using the public key initially sent by the Salt minion, and can therefore be decrypted only by the same Salt minion.
The AES key rotates (at least) daily for every minion.

In short: Communication between Salt master and minion is already encrypted (afaik, you cannot even disable this).

Source: https://docs.saltproject.io/salt/user-guide/en/latest/topics/security.html

uyuni-project / uyuni