Compound commands don't work.

[UtahDave]

Compound commands fail in 0.17.4

[boucha@dasalt ~]$ sudo salt \* cmd.run,cmd.run 'ls /tmp', 'ls /'
dasalt:
    'cmd.run,cmd.run' is not available.

My versions report

[boucha@dasalt salt (develop u=)]$ sudo salt \* test.versions_report

dasalt:
               Salt: 2014.1.0-379-ga2de041
             Python: 2.7.3 (default, Sep 26 2013, 20:03:06)
             Jinja2: 2.7.1
           M2Crypto: 0.21.1
     msgpack-python: 0.1.10
       msgpack-pure: Not Installed
           pycrypto: 2.6
             PyYAML: 3.10
              PyZMQ: 13.0.0
                ZMQ: 3.2.2

This was discovered during a SaltStack training course.

[UtahDave]

@s0undt3ch or @thatch45 any idea what might have caused this? It was working a few weeks ago when I was training the JPL

[s0undt3ch]

Honestly! .... I never tried compound commands :smile: We should add tests for this, but I don't remember, of the top of my head, a change in the parser that could trigger this failure...

[tedski]

What I've found so far is that the functions were being sent to the minion as a string due to a bug in salt.util.parsers. With that fixed, the commands are ran properly and minion debug logs show the proper output. However, the minions don't return the command output to the master properly. I'll continue to dig in.

[tedski]

I think the problem might be in minion.py. Now that I have the minion running the command separately, I get the following error in the minion log:

Process Process-9:
Traceback (most recent call last):
  File "/usr/lib/python2.7/multiprocessing/process.py", line 258, in _bootstrap
    self.run()
  File "/usr/lib/python2.7/multiprocessing/process.py", line 114, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/local/lib/python2.7/dist-packages/salt/minion.py", line 896, in _thread_multi_return
    minion_instance._return_pub(ret)
  File "/usr/local/lib/python2.7/dist-packages/salt/minion.py", line 945, in _return_pub
    oput = self.functions[fun].__outp

The relevant bits of the minion log:

[INFO    ] User sudo_tedski Executing command ['cmd.run', 'cmd.run'] with jid 20140205000815977312
[DEBUG   ] Command details {'tgt_type': 'glob', 'jid': '20140205000815977312', 'tgt': '*', 'ret': '', 'user': 'sudo_tedski', 'arg': [['ls'], ['uptime']], 'fun': ['cmd.run', 'cmd.run']}
[WARNING ] /usr/local/lib/python2.7/dist-packages/salt/minion.py:166: DeprecationWarning: This minion recieved a job where kwargs were passed asstring'd args, which has been deprecated. This functionality willbe removed in Salt Boron.
  'This minion recieved a job where kwargs were passed as'

[INFO    ] Executing command 'ls' in directory '/home/tedski'
[INFO    ] output: bin
salt
[INFO    ] Executing command 'uptime' in directory '/home/tedski'
[INFO    ] output:  00:08:16 up 13:24,  2 users,  load average: 0.00, 0.01, 0.05
[INFO    ] Returning information for job: 20140205000815977312
Process Process-9:
Traceback (most recent call last):
  File "/usr/lib/python2.7/multiprocessing/process.py", line 258, in _bootstrap
    self.run()
  File "/usr/lib/python2.7/multiprocessing/process.py", line 114, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/local/lib/python2.7/dist-packages/salt/minion.py", line 896, in _thread_multi_return
    minion_instance._return_pub(ret)
  File "/usr/local/lib/python2.7/dist-packages/salt/minion.py", line 945, in _return_pub
    oput = self.functions[fun].__outputter__
TypeError: unhashable type: 'list'
[INFO    ] User sudo_tedski Executing command saltutil.find_job with jid 20140205001801343338
[DEBUG   ] Command details {'tgt_type': 'glob', 'jid': '20140205001801343338', 'tgt': '*', 'ret': '', 'user': 'sudo_tedski', 'arg': ['20140205001755297541'], 'fun': 'saltutil.find_job'}
[WARNING ] /usr/local/lib/python2.7/dist-packages/salt/minion.py:166: DeprecationWarning: This minion recieved a job where kwargs were passed asstring'd args, which has been deprecated. This functionality willbe removed in Salt Boron.
  'This minion recieved a job where kwargs were passed as'

[INFO    ] Returning information for job: 20140205001801343338

I'm not sure I understand the outputter bits yet, so I'll keep learning.

[tedski]

tl;dr - Help! (alternatively: "I give up.")

I'm definitely beginning to think I'm in over my head on fixing this one, so I hope that my forensics can help someone else. I thought the following diff was the problem, because it sent a proper list of functions to the minion, called the proper function for multi_return and even executed the commands properly! Silly me. Here's the diff:

diff --git a/salt/utils/parsers.py b/salt/utils/parsers.py
index def74cf..a6287f0 100644
--- a/salt/utils/parsers.py
+++ b/salt/utils/parsers.py
@@ -1663,13 +1663,13 @@ class SaltCMDOptionParser(OptionParser, ConfigDirMixIn, MergeConfigMixIn,
                         if len(self.config['fun']) != len(self.config['arg']):
                             self.exit(42, 'Cannot execute compound command without '
                                           'defining all arguments.')
+                else:
+                    self.config['fun'] = self.args[1]
+                    self.config['arg'] = self.args[2:]
+
             except IndexError:
                 self.exit(42, '\nIncomplete options passed.\n\n')

-            else:
-                self.config['fun'] = self.args[1]
-                self.config['arg'] = self.args[2:]
-
     def setup_config(self):
         return config.client_config(self.get_config_file_path())

Then, I started to see the TypeError in my previous comment. Digging into that, I noticed that salt.minion._thread_multi_return() overwrites entries in the ret dict if the compound command includes identical commands, in the case of:

salt \* cmd.run,cmd.run ls,uptime

The ret dict looks like this as a result:

{'fun': ['cmd.run', 'cmd.run'], 'fun_args': [['ls'], ['uptime']], 'jid': '20140205202857699088', 'return': {'cmd.run': 'bin\n\nsalt'}, 'success': {'cmd.run': True}}

versus the following with different commands:

{'fun': ['cmd.run', 'cmd.run_all'], 'fun_args': [['ls'], ['uptime']], 'jid': '20140205204532086809', 'return': {'cmd.run_all': {'pid': 23924, 'retcode': 0, 'stderr': '', 'stdout': ' 20:45:32 up 1 day, 10:01,  2 users,  load average: 0.00, 0.01, 0.05'}, 'cmd.run': 'bin\nsalt'}, 'success': {'cmd.run_all': True, 'cmd.run': True}}

That obviously doesn't help with the TypeError in salt.minion._return_pub() one bit, but it sure is interesting. So, then I begin to think, "You might actually be breaking things and not solving them. Maybe that change way back in parsers wasn't an issue at all." Then I quickly get lost.

Part of finding this bug requires knowing the expected behavior of the system and I don't have that kind of situational awareness at this point. I hate to give up on it, so any guidance would be greatly appreciated. I am having fun learning the end-to-end flow using this bug, but I fear introducing more problems by "fixing" this one.

[tedski]

Testing with each release, this seems to be broken since 0.17.3 however, I don't see anything obvious in the diffs from v0.17.2 and v0.17.3.

[basepi]

Wow, thanks for the extensive detective work, @tedski! I don't have time to go through it right now, but I'm sure it will be useful to whoever ends up fixing this. It may be a job for @thatch45.

[basepi]

According to @thatch45, doing cmd.run,cmd.run has never worked. The commands must be distinct. I'm going to close this, as the distinct commands case has been fixed by @cachedout.