Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[BUG] Minions running 3002+ throw a JSONDecodeError when called from master #60365

Closed
sebastianreloaded opened this issue Jun 12, 2021 · 18 comments · Fixed by #62903
Closed

[BUG] Minions running 3002+ throw a JSONDecodeError when called from master #60365

sebastianreloaded opened this issue Jun 12, 2021 · 18 comments · Fixed by #62903
Assignees
Labels
Bug broken, incorrect, or confusing behavior
Milestone

Comments

@sebastianreloaded
Copy link

sebastianreloaded commented Jun 12, 2021

Description
Minions running with Saltstack 3002.6 or 3003 throw an exception when called from master also running on 3002.6 or 3003.

Setup
Fresh installation of saltstack 3003 on Ubuntu 20.04

Steps to Reproduce the behavior

sudo salt -t 300 'vm-api-server' test.ping
or
sudo salt -t 300 'vm-api-server' state.apply
vm-api-server:
    The minion function caused an exception: Traceback (most recent call last):
      File "/usr/lib/python3/dist-packages/salt/minion.py", line 1904, in _thread_return
        return_data = minion_instance._execute_job_function(
      File "/usr/lib/python3/dist-packages/salt/minion.py", line 1861, in _execute_job_function
        return_data = self.executors[fname](opts, data, func, args, kwargs)
      File "/usr/lib/python3/dist-packages/salt/loader.py", line 1235, in __call__
        return self.loader.run(run_func, *args, **kwargs)
      File "/usr/lib/python3/dist-packages/salt/loader.py", line 2268, in run
        return self._last_context.run(self._run_as, _func_or_method, *args, **kwargs)
      File "/usr/lib/python3/dist-packages/salt/loader.py", line 2283, in _run_as
        return _func_or_method(*args, **kwargs)
      File "/usr/lib/python3/dist-packages/salt/executors/sudo.py", line 77, in execute
        cmd_meta = salt.utils.json.loads(cmd_ret["stdout"])["local"]
      File "/usr/lib/python3/dist-packages/salt/utils/json.py", line 97, in loads
        return json_module.loads(s, **kwargs)
      File "/usr/lib/python3.8/json/__init__.py", line 357, in loads
        return _default_decoder.decode(s)
      File "/usr/lib/python3.8/json/decoder.py", line 337, in decode
        obj, end = self.raw_decode(s, idx=_w(s, 0).end())
      File "/usr/lib/python3.8/json/decoder.py", line 355, in raw_decode
        raise JSONDecodeError("Expecting value", s, err.value) from None
    json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

Expected behavior

sudo salt -t 300 'vm-api-server' test.ping
vm-api-server:
    True

Versions Report
master:

sudo salt -V
Salt Version:
          Salt: 3003

Dependency Versions:
          cffi: Not Installed
      cherrypy: Not Installed
      dateutil: 2.7.3
     docker-py: Not Installed
         gitdb: 2.0.6
     gitpython: 3.0.7
        Jinja2: 2.10.1
       libgit2: 0.28.3
      M2Crypto: Not Installed
          Mako: Not Installed
       msgpack: 0.6.2
  msgpack-pure: Not Installed
  mysql-python: Not Installed
     pycparser: Not Installed
      pycrypto: Not Installed
  pycryptodome: 3.6.1
        pygit2: 1.0.3
        Python: 3.8.5 (default, May 27 2021, 13:30:53)
  python-gnupg: 0.4.5
        PyYAML: 5.3.1
         PyZMQ: 18.1.1
         smmap: 2.0.5
       timelib: Not Installed
       Tornado: 4.5.3
           ZMQ: 4.3.2

System Versions:
          dist: ubuntu 20.04 focal
        locale: utf-8
       machine: x86_64
       release: 5.4.0-1047-azure
        system: Linux
       version: Ubuntu 20.04 focal

minion:

Salt Version:
          Salt: 3003

Dependency Versions:
          cffi: Not Installed
      cherrypy: Not Installed
      dateutil: 2.7.3
     docker-py: Not Installed
         gitdb: Not Installed
     gitpython: Not Installed
        Jinja2: 2.10.1
       libgit2: Not Installed
      M2Crypto: Not Installed
          Mako: Not Installed
       msgpack: 0.6.2
  msgpack-pure: Not Installed
  mysql-python: Not Installed
     pycparser: Not Installed
      pycrypto: Not Installed
  pycryptodome: 3.6.1
        pygit2: Not Installed
        Python: 3.8.5 (default, May 27 2021, 13:30:53)
  python-gnupg: 0.4.5
        PyYAML: 5.3.1
         PyZMQ: 18.1.1
         smmap: Not Installed
       timelib: Not Installed
       Tornado: 4.5.3
           ZMQ: 4.3.2

System Versions:
          dist: ubuntu 20.04 focal
        locale: utf-8
       machine: x86_64
       release: 5.4.0-1046-azure
        system: Linux
       version: Ubuntu 20.04 focal

Additional context
When i downgrade the minion on Ubuntu 20.04 to 3001.7 the call from master works just fine.
Also running sudo salt-call state.highstate on the minion itself with 3002.6 or 3003 works fine too.

Also when using Ubuntu 20.04 on the master and using Ubuntu 18.04 as the minion it only works with 3001.7.
Using Ubuntu 18.04 with 3002.6 as the master and Ubuntu 18.04 with 3002.6 or 3003 as the minion works too.
Using Ubuntu 18.04 with 3002.6 as the master and Ubuntu 20.04 with 3002.6 on the minion doesn't work.
Using Ubuntu 18.04 with 3002.6 as the master and Ubuntu 18.04 with 3002.6 on the minion doesn't work.
I also have some Servers using the same combination without problems.

Is this a locale problem, because the servers it works on are locale: ISO-8859-1while the others are locale: UTF-8?
Even though it doesn't make sense that old version of saltstack on the minion work just fine.

------ Update
Doesn't seem to be the locale.

Working minion:

Salt Version:
          Salt: 3002.6

Dependency Versions:
          cffi: Not Installed
      cherrypy: Not Installed
      dateutil: 2.6.1
     docker-py: Not Installed
         gitdb: Not Installed
     gitpython: Not Installed
        Jinja2: 2.10
       libgit2: Not Installed
      M2Crypto: Not Installed
          Mako: Not Installed
       msgpack: 0.5.6
  msgpack-pure: Not Installed
  mysql-python: 1.3.10
     pycparser: Not Installed
      pycrypto: 2.6.1
  pycryptodome: 3.4.7
        pygit2: Not Installed
        Python: 3.6.9 (default, Jan 26 2021, 15:33:00)
  python-gnupg: 0.4.1
        PyYAML: 3.12
         PyZMQ: 17.1.2
         smmap: Not Installed
       timelib: Not Installed
       Tornado: 4.5.3
           ZMQ: 4.2.5

System Versions:
          dist: ubuntu 18.04 Bionic Beaver
        locale: ISO-8859-1
       machine: x86_64
       release: 4.15.0-136-generic
        system: Linux
       version: Ubuntu 18.04 Bionic Beaver

Not working minion:

Salt Version:
          Salt: 3002.6

Dependency Versions:
          cffi: Not Installed
      cherrypy: Not Installed
      dateutil: 2.6.1
     docker-py: Not Installed
         gitdb: Not Installed
     gitpython: Not Installed
        Jinja2: 2.10
       libgit2: Not Installed
      M2Crypto: Not Installed
          Mako: Not Installed
       msgpack: 0.5.6
  msgpack-pure: Not Installed
  mysql-python: Not Installed
     pycparser: Not Installed
      pycrypto: Not Installed
  pycryptodome: 3.4.7
        pygit2: Not Installed
        Python: 3.6.9 (default, Jan 26 2021, 15:33:00)
  python-gnupg: 0.4.1
        PyYAML: 3.12
         PyZMQ: 17.1.2
         smmap: Not Installed
       timelib: Not Installed
       Tornado: 4.5.3
           ZMQ: 4.2.5

System Versions:
          dist: ubuntu 18.04 Bionic Beaver
        locale: ISO-8859-1
       machine: x86_64
       release: 5.4.0-1048-azure
        system: Linux
       version: Ubuntu 18.04 Bionic Beaver
@sebastianreloaded sebastianreloaded added Bug broken, incorrect, or confusing behavior needs-triage labels Jun 12, 2021
@sebastianreloaded
Copy link
Author

I tried to debug a little bit, and for some reason it seems in /usr/lib/python3/dist-packages/salt/executors/sudo.pyLine 74 the call doesn't return stdout.

code:

    cmd_ret = __salt__["cmd.run_all"](cmd, use_vt=True, python_shell=False)

    import sys
    import logging
    logger2 = logging.getLogger('')
    logger2.warning(cmd)
    logger2.warning(cmd_ret)

    if cmd_ret["retcode"] == 0:

log:

2021-06-14 05:27:52,142 [root             :79  ][WARNING ][763680] ['sudo', '-u', 'root', 'salt-call', '--out', 'json', '--metadata', '-c', '/etc/salt', '--', 'test.ping']
2021-06-14 05:27:52,143 [root             :80  ][WARNING ][763680] {'pid': 763687, 'stdout': '', 'stderr': '', 'retcode': 0}

@sebastianreloaded
Copy link
Author

On a minion that works, the log looks like this:

2021-06-14 05:34:18,942 [root             :79  ][WARNING ][2766520] ['sudo', '-u', 'root', 'salt-call', '--out', 'json', '--metadata', '-c', '/etc/salt', '--', 'test.ping']
2021-06-14 05:34:18,942 [root             :80  ][WARNING ][2766520] {'pid': 2766521, 'stdout': '{\n    "local": {\n        "jid": "20210614053417990085",\n        "return": true,\n        "retcode": 0,\n        "id": "vm-api-server",\n        "fun": "test.ping",\n        "fun_args": []\n    }\n}\n', 'stderr': '', 'retcode': 0}

@sebastianreloaded
Copy link
Author

sebastianreloaded commented Jun 14, 2021

For me, it looks like it is a problem with any minion running salt 3002+ in azure.
Because running the minion on bare metal with 3002+ doesn't produce the problem.
Not sure about any other VM infrastructure, since i don't have any test servers available.

@waynew
Copy link
Contributor

waynew commented Jun 15, 2021

Hey @sebastianreloaded Can you try setting your locale for your master/minion to UTF-8?
edit: ah, just saw that you had tried? Did it work when you changed locate to utf-8 for both of them? Or still failed?

@waynew
Copy link
Contributor

waynew commented Jun 15, 2021

Oh, actually looking at this a little closer -

File "/usr/lib/python3/dist-packages/salt/executors/sudo.py", line 77, in execute
        cmd_meta = salt.utils.json.loads(cmd_ret["stdout"])["local"]

Would you be comfortable editing that file? If you add a breakpoint and run your minion manually (with salt-minion) in the foreground, it will should drop there and you can inspect the actual output (print(cmd_ret))

I'm guessing that there will be something extra in that stdout. Might also be some logging in place there and changing to debug logging and inspecting the log may reveal the other output.

@sebastianreloaded
Copy link
Author

I don't seem to get breakpoints to work. I see the following:

> /usr/lib/python3/dist-packages/salt/executors/sudo.py(75)execute()
-> cmd_ret = __salt__["cmd.run_all"](cmd, use_vt=True, python_shell=False)
(Pdb)

But i get an exception:

return self.dispatch_line(frame)\n  File "/usr/lib/python3.8/bdb.py", line 113, in dispatch_line\n    if self.quitting: raise BdbQuit\nbdb.BdbQuit\n

I can prettyprint the cmd_ret, but that just looks like what i wrote earlier:

{'pid': 822391, 'retcode': 0, 'stderr': '', 'stdout': ''}

Do i have to configure the salt-minion differently to get pdb working?

@waynew
Copy link
Contributor

waynew commented Jun 21, 2021

Okay, that's actually kind of interesting, because this line:

 cmd_meta = salt.utils.json.loads(cmd_ret["stdout"])["local"]

expects cmd_ret["stdout"] to contain JSON. Looking at your sample - that ain't it. There's nothing in there but an empty string which is not valid JSON. I wonder if this is an azure thing. Can you log into the broken minion directly and report the output of:

sudo -u root salt-call --out json --metadata -c /etc/salt/ -- test.ping

May also try

sudo -u root salt-call --out json --metadata -c /etc/salt/ -- test.ping > /dev/null

and

sudo -u root salt-call --out json --metadata -c /etc/salt/ -- test.ping 2>/dev/null

I'm wondering if there's something going on with Azure where their sudo is... different 🤔 (seems weird, but at the moment I don't have a better theory)

@sebastianreloaded
Copy link
Author

Hi, yeah thats what i figured, but i gave up trying to dig into /usr/lib/python3/dist-packages/salt/modules/cmdmod.py, because its way to complex.

The calls directly on the minion all succeeded. But they don't seem to use the /usr/lib/python3/dist-packages/salt/executors/sudo.py because i don't get the pprint output.

vm-api-server:~$ sudo -u root salt-call --out json --metadata -c /etc/salt/ -- test.ping
{
    "local": {
        "jid": "20210623060544741036",
        "return": true,
        "retcode": 0,
        "id": "vm-api-server",
        "fun": "test.ping",
        "fun_args": []
    }
}


vm-api-server:~$ sudo -u root salt-call --out json --metadata -c /etc/salt/ -- test.ping > /dev/null
vm-api-server:~$ echo $?
0

vm-api-server:~$ sudo -u root salt-call --out json --metadata -c /etc/salt/ -- test.ping 2>/dev/null
{
    "local": {
        "jid": "20210623060840377960",
        "return": true,
        "retcode": 0,
        "id": "vm-api-server",
        "fun": "test.ping",
        "fun_args": []
    }
}

@waynew
Copy link
Contributor

waynew commented Jun 24, 2021

That may be because in some places in Salt we actually just eat stdout. That might be one of those places. Rather than a simple pretty print, try:

with open('/tmp/out.txt', 'a') as f:
    print(pprint.pformat(cmd_ret), file=f)

If it is actually hitting that point, that command will get the output written to the file for sure. assert False is another way to ensure a line of code is being hit - that will just straight-up break execution 🙂

@sebastianreloaded
Copy link
Author

sebastianreloaded commented Jun 27, 2021

I tried logging to file and assert False, but i'm pretty sure executing those commands directly on the minion won't use /usr/lib/python3/dist-packages/salt/executors/sudo.py. I can even remove the file without problems.

i tried something into the blue instead:
i set use_vt to False in /usr/lib/python3/dist-packages/salt/executors/sudo.py.

cmd_ret = __salt__["cmd.run_all"](cmd, use_vt=False, python_shell=False)

and then it works. And someting like sudo salt vm-api-server state.apply works too.

sudo salt -t 300 'vm-api-server' test.ping
vm-api-server:
    True

BUT by using "use_vt=False" i can't use arguments like "test=True" anymore e.g. sudo salt vm-api-server state.apply test=True.

I'm not sure what use_vt does exactly yet, except executing the commands differently via /usr/lib/python3/dist-packages/salt/utils/vt.py.
I'm also not sure, this has anything todo with each other.

@sebastianreloaded
Copy link
Author

@waynew do you have any more ideas?

@waynew
Copy link
Contributor

waynew commented Jul 27, 2021

That's very weird that use_vt=False makes test=True problematic. Let me look at this a bit and see what I can see 🤔

@waynew
Copy link
Contributor

waynew commented Jul 27, 2021

Looking at the code I don't see how that would prevent test=True from working -- it should do the exact same thing as it would otherwise do.

It's a bit promising that use_vt=False appears to have an effect.... oh. Actually, I bet I know what's happening here. I've seen this error before, in a different way. I can almost guarantee if you add a breakpoint, or in salt/executors/sudo before the cmd_meta = salt.utils.json.loads(...) line add import logging; log = logging.getLogger(__name__), log.warning(cmd_ret["stdout"]) what you'll see is something like

 We trust you have received the usual lecture from the local System Administrator. It usually boils down to these three things:

#1) Respect the privacy of others.

#2) Think before you type.

#3) With great power comes great responsibility.
{ salt output goes here }

Might be something different as the preamble, but I'm almost positive that's what's happening and why we aren't seeing it across the board. Basically, cmd_ret is getting more than just the Salt output 🤔

@waynew waynew added this to the Approved milestone Jul 27, 2021
@waynew
Copy link
Contributor

waynew commented Jul 27, 2021

I think this is definitely a bug within Salt, but I'm not 100% sure where the bug is. Assuming my theory is correct (if you can provide the logging output, that would be 👍 - another place would be in salt.utils.json making loads look like this:

def loads(s, **kwargs):
    """
    .. versionadded:: 2018.3.0

    Wraps json.loads and prevents a traceback in the event that a bytestring is
    passed to the function. (Python < 3.6 cannot load bytestrings)

    You can pass an alternate json module (loaded via import_json() above)
    using the _json_module argument)
    """
    json_module = kwargs.pop("_json_module", json)
    try:
        return json_module.loads(s, **kwargs)
    except TypeError as exc:
        # json.loads cannot load bytestrings in Python < 3.6
        if isinstance(s, bytes):
            return json_module.loads(salt.utils.stringutils.to_unicode(s), **kwargs)
        else:
            log.warning("Failed parsing json from %r", s)   # <---   just add this line
            raise

)

If my theory is correct and we're getting extra output, one of the following should be true:

  1. When producing json output, we should be directing it somewhere else rather than just blindly reading stdout
  2. When getting salt output instead of blindly reading stdout (i.e. json.loads) we should be using the find_json functionality

In either case, this is probably a more broad issue than the title indicates, we'll probably create another more broad issue and close this in favor of that 🤔

@sebastianreloaded
Copy link
Author

Hi, concerning the cmd_ret["stdout"], this is just empty, as i wrote earlier.
And in the json loads function the variable "s" is just an empty string ''
pprint just gives "None"

@vladimir-incountry
Copy link

We have the same issue with Salt Minion 3004 running on Ubuntu 18.04 (AWS).

@dorschs57
Copy link

I'm seeing the same issue with Salt Minion and Master 3003.2 on REHL 8.4. In my setup I'm running the minion as a non-privileged user using the user config setting and setting the sudo_user setting to root. A salt-call pkg.install works fine on the Minion, but calling it with salt from the master fails with the same errors as above. I've logged the cmd_ret in the sudo.py file and the stdout is empty as stated, and manually setting use_vt=False fixes the issue.

@roelvanmeer
Copy link
Contributor

We're seeing the same issue with Salt 3002.6+dfsg1-4+deb11u1 on Debian 11.5. Manually setting use_vt=False fixes the issue for me as well.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Bug broken, incorrect, or confusing behavior
Projects
None yet
Development

Successfully merging a pull request may close this issue.

6 participants