Salt: Returner throws Traceback when done on master side

Created on 26 Sep 2016 · 12Comments · Source: saltstack/salt

Description of Issue/Question

On my master, when I run:

salt 'two' test.ping --return slack

I get:

[CRITICAL] Could not deserialize msgpack message.This often happens when trying to read a file not in binary modeTo see message payload, enable debug logging and retry. Exception: unpack(b) received extra data.
[ERROR   ] Uncaught exception, closing connection.
Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/zmq/eventloop/zmqstream.py", line 414, in _run_callback
    callback(*args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/tornado/stack_context.py", line 275, in null_wrapper
    return fn(*args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/salt/transport/zeromq.py", line 910, in mark_future
    future.set_result(self.serial.loads(msg[0]))
  File "/usr/lib/python2.7/dist-packages/salt/payload.py", line 117, in loads
    return msgpack.loads(msg, use_list=True)
  File "msgpack/_unpacker.pyx", line 143, in msgpack._unpacker.unpackb (msgpack/_unpacker.cpp:143)
ExtraData: unpack(b) received extra data.
[ERROR   ] Uncaught exception, closing connection.
Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/zmq/eventloop/zmqstream.py", line 440, in _handle_events
    self._handle_recv()
  File "/usr/lib/python2.7/dist-packages/zmq/eventloop/zmqstream.py", line 472, in _handle_recv
    self._run_callback(callback, msg)
  File "/usr/lib/python2.7/dist-packages/zmq/eventloop/zmqstream.py", line 414, in _run_callback
    callback(*args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/tornado/stack_context.py", line 275, in null_wrapper
    return fn(*args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/salt/transport/zeromq.py", line 910, in mark_future
    future.set_result(self.serial.loads(msg[0]))
  File "/usr/lib/python2.7/dist-packages/salt/payload.py", line 117, in loads
    return msgpack.loads(msg, use_list=True)
  File "msgpack/_unpacker.pyx", line 143, in msgpack._unpacker.unpackb (msgpack/_unpacker.cpp:143)
ExtraData: unpack(b) received extra data.
[ERROR   ] Exception in callback None
Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/tornado/ioloop.py", line 866, in start
    handler_func(fd_obj, events)
  File "/usr/lib/python2.7/dist-packages/tornado/stack_context.py", line 275, in null_wrapper
    return fn(*args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/zmq/eventloop/zmqstream.py", line 440, in _handle_events
    self._handle_recv()
  File "/usr/lib/python2.7/dist-packages/zmq/eventloop/zmqstream.py", line 472, in _handle_recv
    self._run_callback(callback, msg)
  File "/usr/lib/python2.7/dist-packages/zmq/eventloop/zmqstream.py", line 414, in _run_callback
    callback(*args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/tornado/stack_context.py", line 275, in null_wrapper
    return fn(*args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/salt/transport/zeromq.py", line 910, in mark_future
    future.set_result(self.serial.loads(msg[0]))
  File "/usr/lib/python2.7/dist-packages/salt/payload.py", line 117, in loads
    return msgpack.loads(msg, use_list=True)
  File "msgpack/_unpacker.pyx", line 143, in msgpack._unpacker.unpackb (msgpack/_unpacker.cpp:143)
ExtraData: unpack(b) received extra data.

Here is a more verbose output with:
salt 'two' test.ping --return slack -ldebug

Output:
https://paste.debian.net/842136/

Interestingly enough, if I comment that snippet about

master_job_cache: slack
slack.channel: "#saltbuilds"
slack.api_key: "nuked"
slack.username: "me"
slack.as_user: "true"

And move the config off to minion (ext_job_cache), I see the output on Slack with no problems whatsoever.

Setup

(Please provide relevant configs and/or SLS files (Be sure to remove sensitive info).)

Master config:

user: saltuser
color: True
file_roots: base: - /srv/salt
master_job_cache: slack
slack.channel: "#saltbuilds"
slack.api_key: "nuked"
slack.username: "me"
slack.as_user: "true"

Minion config:

master: mymaster.ip.com
cache_jobs: True
returner_dirs: ["/etc/salt/minion.d/"]
file_roots: base: - /srv/salt

Steps to Reproduce Issue

(Include debug logs if possible and relevant.)
_with -ldebug: _ https://paste.debian.net/842136/

salt 'two' test.versions_report --return slack

With NO ext_job_cache. Instead use this on /etc/salt/master:

master_job_cache: slack
slack.channel: "#saltbuilds"
slack.api_key: "nuked"
slack.username: "me"
slack.as_user: "true"

Versions Report

(Provided by running salt --versions-report. Please also mention any differences in master/minion versions.)

Master:

Salt Version:
           Salt: 2016.3.3

Dependency Versions:
           cffi: Not Installed
       cherrypy: Not Installed
       dateutil: 2.5.3
          gitdb: 0.6.4
      gitpython: 2.0.5
          ioflo: Not Installed
         Jinja2: 2.8
        libgit2: Not Installed
        libnacl: Not Installed
       M2Crypto: Not Installed
           Mako: 1.0.4
   msgpack-pure: Not Installed
 msgpack-python: 0.4.7
   mysql-python: 1.3.7
      pycparser: Not Installed
       pycrypto: 2.6.1
         pygit2: Not Installed
         Python: 2.7.12+ (default, Sep  1 2016, 20:27:38)
   python-gnupg: Not Installed
         PyYAML: 3.11
          PyZMQ: 15.1.0
           RAET: Not Installed
          smmap: 0.9.0
        timelib: Not Installed
        Tornado: 4.2.1
            ZMQ: 4.0.5

System Versions:
           dist: debian stretch/sid 
        machine: x86_64
        release: 4.3.0-1-amd64
         system: Linux
        version: debian stretch/sid

Minion:

    Salt Version:
               Salt: 2016.3.3

    Dependency Versions:
               cffi: Not Installed
           cherrypy: Not Installed
           dateutil: 1.5
              gitdb: 0.5.4
          gitpython: 0.3.2 RC1
              ioflo: Not Installed
             Jinja2: 2.7.2
            libgit2: Not Installed
            libnacl: Not Installed
           M2Crypto: 0.21.1
               Mako: 0.9.1
       msgpack-pure: Not Installed
     msgpack-python: 0.4.6
       mysql-python: 1.2.3
          pycparser: Not Installed
           pycrypto: 2.6.1
             pygit2: Not Installed
             Python: 2.7.6 (default, Jun 22 2015, 17:58:13)
       python-gnupg: Not Installed
             PyYAML: 3.10
              PyZMQ: 14.0.1
               RAET: Not Installed
              smmap: 0.8.2
            timelib: Not Installed
            Tornado: 4.2.1
                ZMQ: 4.0.4

    System Versions:
               dist: Ubuntu 14.04 trusty
            machine: x86_64
            release: 3.13.0-76-generic
             system: Linux
            version: Ubuntu 14.04 trusty

Bug P4 RIoT Returners fixed-pending-your-verification severity-medium

Source

evan-ty

Most helpful comment

Actually, I am getting the same error again:

Salt Version:
Salt: 2016.3.3

With this version

evan-ty on 8 Feb 2017

👍2

All 12 comments

@evan-ty just to clarify the issue is when you try to use slack alongside the master_job_cache correct?

If so, according to the documentation here it states that in order for a returner to use the master_job-cache it needs the following functions:

prep_jid
save_load
get_load

Which are not included in the slack returner here So I'm assuming that those will need to be adding in order for this functionality to work.

Ch3LL on 27 Sep 2016

@Ch3LL

Thanks for looking into thi sfor me.

Yes, I am trying to use this with Slack, along the master_job_cache option in the config (/etc/salt/master)

From what I understand after reading this, these options aren't recognized in the config with the verison 2016.3.3, correct? (Since I am not writing my own returner).

evan-ty on 28 Sep 2016

apologies i don't think i was clear what i meant is we would have to add those (prep_jid, save_load, get_load) functions to the actual returner according to the documentation. They would not be configurations added to the config

But to ensure this is the case that it would need those functions ping @garethgreenaway looks like you helped implement this returner. Do you know if you have ever been able to use it as a master_job_cache? From what I can see it would need functions added but maybe this is actually a documentation error. Thanks

Ch3LL on 5 Oct 2016

Hi @Ch3LL.

Gotcha, so this is something from the saltstack developers side.

Thanks!

evan-ty on 6 Oct 2016

Yes, apologies for not making that clear. We will need to get this fixed up. Thanks

Ch3LL on 7 Oct 2016

Hey I can see these functions are implemented in influxdb returner. However I get this same error when using master_job_cache.

tyagiprince on 18 Oct 2016

@tyagiprince thanks for clarifying that this might not be an issue with those functions then. Since this is a different returner this might be a seperate issue or the same but I would like to keep track in a sepearte issue. Would you mind opening another issue while referencing this one so they are linked. Ad we can troubleshoot from there and it seems this might not be an issue with the functions missing. Also in the issue please include any relevant sanitized configs, and test case. thanks.

Ch3LL on 18 Oct 2016

I think this is a duplicate of #36713, which was likely fixed recently by #37503. See this comment.

While the returner does need to be fixed up by adding those functions, the actual stack trace you're seeing here should be resolved.

rallytime on 7 Nov 2016

@evan-ty were you able to validate that #37503 resolved this issue as well?

meggiebot on 5 Dec 2016

@meggiebot I was having this same issue and verified that applying the fix in #37503 solved the issue.

vschumaker on 14 Dec 2016

This still breaks for me in 2016.11.1:

root@salt-001:~# salt virt-010* test.versions_report --return slack
[CRITICAL] Could not deserialize msgpack message.This often happens when trying to read a file not in binary modeTo see message payload, enable debug logging and retry. Exception: unpack(b) received extra data.
[ERROR   ] Uncaught exception, closing connection.
Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/zmq/eventloop/zmqstream.py", line 414, in _run_callback
    callback(*args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/tornado/stack_context.py", line 275, in null_wrapper
    return fn(*args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/salt/transport/zeromq.py", line 962, in mark_future
    data = self.serial.loads(msg[0])
  File "/usr/lib/python2.7/dist-packages/salt/payload.py", line 137, in loads
    ret = msgpack.loads(msg, use_list=True, encoding=encoding)
  File "msgpack/_unpacker.pyx", line 142, in msgpack._unpacker.unpackb (msgpack/_unpacker.cpp:142)
ExtraData: unpack(b) received extra data.
[ERROR   ] Uncaught exception, closing connection.
Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/zmq/eventloop/zmqstream.py", line 440, in _handle_events
    self._handle_recv()
  File "/usr/lib/python2.7/dist-packages/zmq/eventloop/zmqstream.py", line 472, in _handle_recv
    self._run_callback(callback, msg)
  File "/usr/lib/python2.7/dist-packages/zmq/eventloop/zmqstream.py", line 414, in _run_callback
    callback(*args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/tornado/stack_context.py", line 275, in null_wrapper
    return fn(*args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/salt/transport/zeromq.py", line 962, in mark_future
    data = self.serial.loads(msg[0])
  File "/usr/lib/python2.7/dist-packages/salt/payload.py", line 137, in loads
    ret = msgpack.loads(msg, use_list=True, encoding=encoding)
  File "msgpack/_unpacker.pyx", line 142, in msgpack._unpacker.unpackb (msgpack/_unpacker.cpp:142)
ExtraData: unpack(b) received extra data.
[ERROR   ] Exception in callback None
Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/tornado/ioloop.py", line 866, in start
    handler_func(fd_obj, events)
  File "/usr/lib/python2.7/dist-packages/tornado/stack_context.py", line 275, in null_wrapper
    return fn(*args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/zmq/eventloop/zmqstream.py", line 440, in _handle_events
    self._handle_recv()
  File "/usr/lib/python2.7/dist-packages/zmq/eventloop/zmqstream.py", line 472, in _handle_recv
    self._run_callback(callback, msg)
  File "/usr/lib/python2.7/dist-packages/zmq/eventloop/zmqstream.py", line 414, in _run_callback
    callback(*args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/tornado/stack_context.py", line 275, in null_wrapper
    return fn(*args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/salt/transport/zeromq.py", line 962, in mark_future
    data = self.serial.loads(msg[0])
  File "/usr/lib/python2.7/dist-packages/salt/payload.py", line 137, in loads
    ret = msgpack.loads(msg, use_list=True, encoding=encoding)
  File "msgpack/_unpacker.pyx", line 142, in msgpack._unpacker.unpackb (msgpack/_unpacker.cpp:142)
ExtraData: unpack(b) received extra data.
Salt request timed out. The master is not responding. If this error persists after verifying the master is up, worker_threads may need to be increased.
root@salt-001:~#