Salt: minion does not return chocolatey.list

[haodeon]

Description of Issue

Trying to execute salt module chocolatey to list installed packages on Windows minions.

salt -G 'os:Windows' chocolatey.list local_only=True

Minions never return anything, I just get [No Reponse] on master.

If I run

salt-call --local chocolatey.list local_only=True

on the minion itself, I get expected output, which is the list of chocolatey packages currently installed on the minion.

Setup

There is nothing particular about my setup. I have a master running on Ubuntu 18.04 (Py3) and two Windows minions, Server 2016 and Server 2019.

Steps to Reproduce Issue

As per above

salt -G 'os:Windows' chocolatey.list local_only=True

Versions Report

Master and minions both running latest 2019.2.1

[haodeon]

I found this in the minion logs.

2019-10-05 15:27:46,818 [salt.utils.process:754 ][ERROR   ][3812] An un-handled exception from the multiprocessing process 'SignalHandlingMultiprocessingProcess-1' was caught:
Traceback (most recent call last):
  File "c:\salt\bin\lib\site-packages\salt\utils\process.py", line 747, in run
    return super(MultiprocessingProcess, self).run()
  File "c:\salt\bin\lib\multiprocessing\process.py", line 93, in run
    self._target(*self._args, **self._kwargs)
  File "c:\salt\bin\lib\site-packages\salt\minion.py", line 1593, in _target
    run_func(minion_instance, opts, data)
  File "c:\salt\bin\lib\site-packages\salt\minion.py", line 1588, in run_func
    return Minion._thread_return(minion_instance, opts, data)
  File "c:\salt\bin\lib\site-packages\salt\minion.py", line 1775, in _thread_return
    timeout=minion_instance._return_retry_timer()
  File "c:\salt\bin\lib\site-packages\salt\minion.py", line 1996, in _return_pub
    ret_val = self._send_req_sync(load, timeout=timeout)
  File "c:\salt\bin\lib\site-packages\salt\minion.py", line 1410, in _send_req_sync
    return channel.send(load, timeout=timeout)
  File "c:\salt\bin\lib\site-packages\salt\utils\asynchronous.py", line 64, in wrap
    ret = self._block_future(ret)
  File "c:\salt\bin\lib\site-packages\salt\utils\asynchronous.py", line 74, in _block_future
    return future.result()
  File "c:\salt\bin\lib\site-packages\tornado\concurrent.py", line 238, in result
    raise_exc_info(self._exc_info)
  File "<string>", line 4, in raise_exc_info
  File "c:\salt\bin\lib\site-packages\tornado\gen.py", line 1063, in run
    yielded = self.gen.throw(*exc_info)
  File "c:\salt\bin\lib\site-packages\salt\transport\zeromq.py", line 383, in send
    ret = yield self._crypted_transfer(load, tries=tries, timeout=timeout, raw=raw)
  File "c:\salt\bin\lib\site-packages\tornado\gen.py", line 1055, in run
    value = future.result()
  File "c:\salt\bin\lib\site-packages\tornado\concurrent.py", line 238, in result
    raise_exc_info(self._exc_info)
  File "<string>", line 4, in raise_exc_info
  File "c:\salt\bin\lib\site-packages\tornado\gen.py", line 1063, in run
    yielded = self.gen.throw(*exc_info)
  File "c:\salt\bin\lib\site-packages\salt\transport\zeromq.py", line 351, in _crypted_transfer
    ret = yield _do_transfer()
  File "c:\salt\bin\lib\site-packages\tornado\gen.py", line 1055, in run
    value = future.result()
  File "c:\salt\bin\lib\site-packages\tornado\concurrent.py", line 238, in result
    raise_exc_info(self._exc_info)
  File "<string>", line 4, in raise_exc_info
  File "c:\salt\bin\lib\site-packages\tornado\gen.py", line 307, in wrapper
    yielded = next(result)
  File "c:\salt\bin\lib\site-packages\salt\transport\zeromq.py", line 333, in _do_transfer
    self._package_load(self.auth.crypticle.dumps(load)),
  File "c:\salt\bin\lib\site-packages\salt\crypt.py", line 1470, in dumps
    return self.encrypt(self.PICKLE_PAD + self.serial.dumps(obj))
  File "c:\salt\bin\lib\site-packages\salt\payload.py", line 240, in dumps
    return msgpack.dumps(msg, default=ext_type_encoder, use_bin_type=use_bin_type)
  File "c:\salt\bin\lib\site-packages\msgpack\__init__.py", line 47, in packb
    return Packer(**kwargs).pack(o)
  File "msgpack/_packer.pyx", line 284, in msgpack._packer.Packer.pack
  File "msgpack/_packer.pyx", line 290, in msgpack._packer.Packer.pack
  File "msgpack/_packer.pyx", line 287, in msgpack._packer.Packer.pack
  File "msgpack/_packer.pyx", line 234, in msgpack._packer.Packer._pack
  File "msgpack/_packer.pyx", line 281, in msgpack._packer.Packer._pack
TypeError: can't serialize {'saltminion': ['2019.2.1'], 'vcredist2008': ['9.0.21022.8']}

[arizvisa]

The maintainers will probably ask you this, but can you include the output of salt-call --versions-report from the minion?

That option will dump out the versions of the python modules that salt is using other than just its own version. This will help people narrow it down since this is an issue potentially related to msgpack, and there can be any number of different versions that are used by salt.

[wh1te909]

I'm also getting the same error on all of my windows minions (server 2008, win 7, win 10, server2012r2 and server2019). Both minions and master are 2019.2.1

Salt Version:
           Salt: 2019.2.1

Dependency Versions:
           cffi: 1.12.2
       cherrypy: 17.4.1
       dateutil: 2.8.0
      docker-py: Not Installed
          gitdb: 2.0.5
      gitpython: Not Installed
          ioflo: Not Installed
         Jinja2: 2.10.1
        libgit2: Not Installed
        libnacl: 1.6.1
       M2Crypto: Not Installed
           Mako: 1.0.7
   msgpack-pure: Not Installed
 msgpack-python: 0.5.6
   mysql-python: Not Installed
      pycparser: 2.19
       pycrypto: Not Installed
   pycryptodome: 3.8.1
         pygit2: Not Installed
         Python: 3.5.4 (v3.5.4:3f56838, Aug  8 2017, 02:17:05) [MSC v.1900 64 bit (AMD64)]
   python-gnupg: 0.4.4
         PyYAML: 3.13
          PyZMQ: 18.0.1
           RAET: Not Installed
          smmap: 2.0.5
        timelib: 0.2.4
        Tornado: 4.5.3
            ZMQ: 4.3.1

System Versions:
           dist:   
         locale: cp1252
        machine: AMD64
        release: 2012ServerR2
         system: Windows
        version: 2012ServerR2 6.3.9600 SP0 Multiprocessor Free

[waynew]

Hi @haodeon, thanks for the report!

Does your --versions-report output look similar? We'll look into it and see what we can find out!

[arizvisa]

@waynew, I did a little bit of digging, and although I haven't checked it myself. It seems that it's because that version of msgpack is using PyDict_Check to determine whether something is a dictionary in order to serialize it. I found a stack overflow article that mentions that PyDict_Check returns 0 with a MutableMapping which could result in this TypeError occurring.

The one issue is that I can't reproduce on my setup, despite the logic being the same..but maybe there's something here.

So, the following code is the list_() implementation from salt.modules.chocolatey, which returns the result as a CaseInsensitiveDict.

def list_(narrow=None,
          all_versions=False,
          pre_versions=False,
          source=None,
          local_only=False,
          exact=False):
...
    ret = CaseInsensitiveDict({})
    pkg_re = re.compile(r'(\S+)\|(\S+)')
    for line in result['stdout'].split('\n'):
...

The salt.utils.data module contains the definition of CaseInsensitiveDict which uses a MutableMapping.

class CaseInsensitiveDict(MutableMapping):
    '''
    Inspired by requests' case-insensitive dict implementation, but works with
    non-string keys as well.
    '''

However, salt.modules.chocolatey is importing the CaseInsensitiveDict from the requests.structure module which is defined similarly as:

from .compat import OrderedDict, Mapping, MutableMapping

class CaseInsensitiveDict(MutableMapping):

Now looking at msgack 0.5.6, specifically in msgpack/_packer.pyx, the function literally hits a number of if-tests (recursively) to determine how to serialize each type. This is using PyDict_Check to identify a dict. The only way to hit this "else" case is by each of these failing. Still, I'm not hitting this particular situation when I try to repro the same case with a newer version of msgpack (despite the logic being unchanged).

    cdef int _pack(self, object o, int nest_limit=DEFAULT_RECURSE_LIMIT) except -1:
...
        while True:
            if o is None:
...
            elif PyDict_CheckExact(o):
...
            elif not strict_types and PyDict_Check(o):
...
            else:
                PyErr_Format(TypeError, b"can not serialize '%.200s' object", Py_TYPE(o).tp_name)
            return ret

So this results in PyDict_Check being used to determine whether something is a dict otherwise the TypeError is raised.

Then there's this article confirming a similar problem: https://stackoverflow.com/questions/52314186/extended-dict-like-subclass-to-support-casting-and-json-dumping-without-extras

So, assuming that is article is right that construction of CaseInsensitiveDict is potentially not serializeable. Although I haven't personally checked PyDict_Check, so again this just a theory.

[haodeon]

@waynew Here is my --versions-report

PS D:\> C:\salt\salt-call.bat --versions-report
Salt Version:
           Salt: 2019.2.2

Dependency Versions:
           cffi: 1.12.2
       cherrypy: 17.4.1
       dateutil: 2.8.0
      docker-py: Not Installed
          gitdb: 2.0.6
      gitpython: Not Installed
          ioflo: Not Installed
         Jinja2: 2.10.1
        libgit2: Not Installed
        libnacl: 1.6.1
       M2Crypto: Not Installed
           Mako: 1.0.7
   msgpack-pure: Not Installed
 msgpack-python: 0.5.6
   mysql-python: Not Installed
      pycparser: 2.19
       pycrypto: Not Installed
   pycryptodome: 3.8.1
         pygit2: Not Installed
         Python: 3.5.4 (v3.5.4:3f56838, Aug  8 2017, 02:17:05) [MSC v.1900 64 bit (AMD64)]
   python-gnupg: 0.4.4
         PyYAML: 3.13
          PyZMQ: 18.0.1
           RAET: Not Installed
          smmap: 2.0.5
        timelib: 0.2.4
        Tornado: 4.5.3
            ZMQ: 4.3.1

System Versions:
           dist:
         locale: cp1252
        machine: AMD64
        release: 2019Server
         system: Windows
        version: 2019Server 10.0.17763 SP0 Multiprocessor Free

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

If this issue is closed prematurely, please leave a comment and we will gladly reopen the issue.

[arizvisa]

This issue still occurs with MsgPack v0.5.6 and it was explained with code references why it would have issues. The requirements as listed in salt still reference v0.5.6, until this is updated or the issue I pointed out is fixed, this doesn't deserve to be closed.

[stale[bot]]

Thank you for updating this issue. It is no longer marked as stale.

[waynew]

@arizvisa are you hitting this error? I'm having a heck of a time trying to reproduce - I've tried a number of different methods, to no avail. That is, it succeeds.

If someone is having it fail, could you try this?

  File "c:\salt\bin\lib\site-packages\salt\payload.py", line 240, in dumps
    return msgpack.dumps(msg, default=ext_type_encoder, use_bin_type=use_bin_type)

Just before that line, add log.trace('type: %s repr: %s', type(msg), repr(msg))? That would get some more information that would be worthwhile.

[wh1te909]

@waynew mine is failing. added that line, here is output from log

https://pastebin.com/Dktjkzkh

[arizvisa]

@waynew, I definitely have encountered this error before but as it takes so long for issues to go through their lifecycle, I just abuse your guys extmods to fix the issues until you guys get around to them. So, in my project the copy of salt.modules.chocolatey that I deploy converts that CaseInsensitiveDict back to a regular dict so that both msgpack and json can deal with it. So at the moment, no I unfortunately don't have that error anymore and am really hesitant to break things now that all my fuzzers are actually working, heh. ;)

But this is literally the exact same bug pattern as #55708 which isn't specifically an issue with msgpack but with serialization in general. You just can't return non-serializeable data from these functions and it should be documented as a policy when writing salt modules. Same deal with #55757, #52361, #49206.

If you're trying to reproduce this particular issue _exactly_, you have a ton of layers to go through, and really it's just hella easier to check if you can serialize the result that's returned from the executor. So to reproduce, you'll need a transport that uses msgpack 0.5.6 and and then you'll need to set options that prevent the cache from touching anything as the cache tends to change types which will prevent the MutableMapping from propagating to msgpack.dumps (hiding the error). So you'll need a full master-minion setup w/ working returner that will publish results back to the master bus.

Again though, as the goal would be to find a path that will execute salt.modules.chocolatey.list_ and then pass its result to msgpack.dumps without tampering with the result. You might be able to track down this non-serialization pattern by adding a function to the salt.modules.test module that guarantees a set() being returned or (better yet, a list() with a set() inside it) to get something that's guaranteed non-serializeable by msgpack/json/etc. and then running it on some master-minion setups to see what exceptions get raised. I can almost guarantee you'll find more paths where this pattern will manifest.

[waynew]

That'll do it - it looks like msgpack 0.5.6 dumped a repr, where 0.6.1 will do something like this:

>>> msgpack.dumps(d)
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/usr/local/lib/python3.7/site-packages/msgpack/__init__.py", line 46, in packb
    return Packer(**kwargs).pack(o)
  File "msgpack/_packer.pyx", line 282, in msgpack._cmsgpack.Packer.pack
  File "msgpack/_packer.pyx", line 288, in msgpack._cmsgpack.Packer.pack
  File "msgpack/_packer.pyx", line 285, in msgpack._cmsgpack.Packer.pack
  File "msgpack/_packer.pyx", line 279, in msgpack._cmsgpack.Packer._pack
TypeError: can not serialize 'CaseInsensitiveDict' object

Tricksy.

We have some efforts to unify the way we're wrapping msgpack, so it should be possible for us to put a try/except around there to confirm that we're properly passing serializable types to msgpack. Which we're clearly not doing here 😞

[arizvisa]

Awesome! Glad you were able to track it down.

One thing to be concerned about is that on Python2 try-except is actually pretty non-performant when hitting the exception case (not sure about the benchmarks on Python3 though), so we just need to be careful with patterns where the default path is the exception being raised when it's in an inner loop or similar. Probably not too relevant here, but yeah..something to consider for similar bugs in the future.

[arizvisa]

Tricksy.

We have some efforts to unify the way we're wrapping msgpack, so it _should_ be possible for us to put a try/except around there to confirm that we're properly passing serializable types to msgpack. Which we're clearly not doing here disappointed

Don't forget json.dumps too as it's used by the mysql returner and likely others.