Salt: Problem in salt-api with runner client: Could not deserialize msgpack message

[Hitamashi]

Description of Issue/Question

I have problem when use salt-api with runner client.
It is well excuted with the command line but it cannot use with the api
I think it some how related to this issue #19349

Setup

Salt api config:

rest_cherrypy:
  port: 8000
  debug: True
  webhook_disable_auth: True
  webhook_url: /hook
  disable_ssl: True
external_auth:
  sharedsecret:
    salt:
      - .*
      - '@wheel'
      - '@jobs'
      - '@runner'

Steps to Reproduce Issue

I have the the issue with salt-run. But it only occurs when I use salt api with runner client.

It is ok when I run:
salt-run manage.up
It returns a list of active minions.

But when I try run it via api:

curl -X POST \
  http://127.0.0.1:8000/run \
  -H 'accept: application/json' \
  -H 'content-type: application/json' \
  -d '[
    { 
        "client": "runner", 
        "username": "salt", 
        "sharedsecret": "testpw", 
        "eauth": "sharedsecret",
        "tgt": "*", 
        "fun": "manage.up"
    }
]'

It return 503 error:

503 Service Unavailable

Message timed out

Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/cherrypy/_cprequest.py", line 670, in respond
    response.body = self.handler()
  File "/usr/lib/python2.7/site-packages/cherrypy/lib/encoding.py", line 217, in __call__
    self.body = self.oldhandler(*args, **kwargs)
  File "/usr/lib/python2.7/site-packages/salt/netapi/rest_cherrypy/app.py", line 752, in hypermedia_handler
    raise cherrypy.HTTPError(503, exc.strerror)
HTTPError: (503, 'Message timed out')
Powered by CherryPy 5.6.0

In the salt api log:

2018-01-05 11:45:26,131 [salt.payload     ][CRITICAL][6187] 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.
2018-01-05 11:45:26,146 [tornado.general  ][ERROR   ][6187] Uncaught exception, closing connection.
Traceback (most recent call last):
  File "/usr/lib64/python2.7/site-packages/zmq/eventloop/zmqstream.py", line 414, in _run_callback
    callback(*args, **kwargs)
  File "/usr/lib64/python2.7/site-packages/tornado/stack_context.py", line 274, in null_wrapper
    return fn(*args, **kwargs)
  File "/usr/lib/python2.7/site-packages/salt/transport/zeromq.py", line 969, in mark_future
    data = self.serial.loads(msg[0])
  File "/usr/lib/python2.7/site-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.
2018-01-05 11:45:26,147 [tornado.general  ][ERROR   ][6187] Uncaught exception, closing connection.
Traceback (most recent call last):
  File "/usr/lib64/python2.7/site-packages/zmq/eventloop/zmqstream.py", line 440, in _handle_events
    self._handle_recv()
  File "/usr/lib64/python2.7/site-packages/zmq/eventloop/zmqstream.py", line 472, in _handle_recv
    self._run_callback(callback, msg)
  File "/usr/lib64/python2.7/site-packages/zmq/eventloop/zmqstream.py", line 414, in _run_callback
    callback(*args, **kwargs)
  File "/usr/lib64/python2.7/site-packages/tornado/stack_context.py", line 274, in null_wrapper
    return fn(*args, **kwargs)
  File "/usr/lib/python2.7/site-packages/salt/transport/zeromq.py", line 969, in mark_future
    data = self.serial.loads(msg[0])
  File "/usr/lib/python2.7/site-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.
2018-01-05 11:45:26,147 [tornado.application][ERROR   ][6187] Exception in callback None
Traceback (most recent call last):
  File "/usr/lib64/python2.7/site-packages/tornado/ioloop.py", line 865, in start
    handler_func(fd_obj, events)
  File "/usr/lib64/python2.7/site-packages/tornado/stack_context.py", line 274, in null_wrapper
    return fn(*args, **kwargs)
  File "/usr/lib64/python2.7/site-packages/zmq/eventloop/zmqstream.py", line 440, in _handle_events
    self._handle_recv()
  File "/usr/lib64/python2.7/site-packages/zmq/eventloop/zmqstream.py", line 472, in _handle_recv
    self._run_callback(callback, msg)
  File "/usr/lib64/python2.7/site-packages/zmq/eventloop/zmqstream.py", line 414, in _run_callback
    callback(*args, **kwargs)
  File "/usr/lib64/python2.7/site-packages/tornado/stack_context.py", line 274, in null_wrapper
    return fn(*args, **kwargs)
  File "/usr/lib/python2.7/site-packages/salt/transport/zeromq.py", line 969, in mark_future
    data = self.serial.loads(msg[0])
  File "/usr/lib/python2.7/site-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.

Note: I have tried other api and it works well with 'local', 'wheel' and 'jobs' client

Versions Report

Salt Version:
           Salt: 2017.7.2

Dependency Versions:
           cffi: Not Installed
       cherrypy: unknown
       dateutil: 1.5
      docker-py: Not Installed
          gitdb: Not Installed
      gitpython: Not Installed
          ioflo: Not Installed
         Jinja2: 2.7.2
        libgit2: Not Installed
        libnacl: Not Installed
       M2Crypto: 0.21.1
           Mako: Not Installed
   msgpack-pure: Not Installed
 msgpack-python: 0.4.6
   mysql-python: Not Installed
      pycparser: Not Installed
       pycrypto: 2.6.1
   pycryptodome: Not Installed
         pygit2: Not Installed
         Python: 2.7.5 (default, May  3 2017, 07:55:04)
   python-gnupg: Not Installed
         PyYAML: 3.11
          PyZMQ: 15.3.0
           RAET: Not Installed
          smmap: Not Installed
        timelib: Not Installed
        Tornado: 4.2.1
            ZMQ: 4.1.4

System Versions:
           dist: redhat 7.4 Maipo
         locale: UTF-8
        machine: x86_64
        release: 3.10.0-693.5.2.el7.x86_64
         system: Linux
        version: Red Hat Enterprise Linux Server 7.4 Maipo

[PierreR]

I have the same issue (also with redhat 7.4).

The same curl command works nicely in 2016.11.5 but fails in 2016.11.9 :

curl -ssik https://salt.sta.srv.cirb.lan:8000/run  \
         -H 'content-type: application/json' -H 'Accept: application/x-yaml'  -d '[{
      "username": "xxx",
      "password": "xxxxxx",
      "eauth": "ldap",
      "client": "runner",
      "fun": "doc.execution"
     }]'

I guess I will have to downgrade the salt-master ... (once again). Does someone know if the problem exists in 2017.7.4 as I might consider upgrading to the latest instead ?

[PierreR]

Does it need to be P1 to be solve urgently ? Does seem quite immature to go on releasing new versions before fixing such kind of serious regression. The Salt-API is effectively broken !

[PierreR]

I would like to plan a salt update for next year but this issue is preventing it.
@Hitamashi are you still using salt ?

[Hitamashi]

@PierreR I'm still using salt. But I've given up on manage.up. Good new is I can use the rest api for functions in salt.runners.jobs. Recently, I'm using 2017.7.7