salt-ssh swallows exceptions in custom modules

[guettli]

Description of Issue/Question

Setup

salt:/srv # cat salt/_modules/foo.py
def bar():
    raise Exception()

salt:/srv # cat salt/t.sls
{% if salt['foo.bar']() %}
  errTrue
{% else %}
  errFalse
{% endif %}

salt:/srv # salt-ssh foohost state.sls t
foohost:
    - SLS t does not render to a dictionary
    - Error when rendering state with contents: errTrue

salt-ssh --log-level=all foohost state.sls t 2> tmp/o

relevant part of tmp/o

Traceback (most recent call last):
  File "/var/tmp/.root_dcdf8c_salt/salt-call", line 15, in <module>
    salt_call()
  File "/var/tmp/.root_dcdf8c_salt/py2/salt/scripts.py", line 400, in salt_call
    client.run()
  File "/var/tmp/.root_dcdf8c_salt/py2/salt/cli/call.py", line 57, in run
    caller.run()
  File "/var/tmp/.root_dcdf8c_salt/py2/salt/cli/caller.py", line 134, in run
    ret = self.call()
  File "/var/tmp/.root_dcdf8c_salt/py2/salt/cli/caller.py", line 212, in call
    ret['return'] = func(*args, **kwargs)
  File "/var/tmp/.root_dcdf8c_salt/running_data/var/cache/salt/minion/extmods/modules/foo.py", line 2, in bar
    raise Exception()
Exception

You see: an exception in the custom module does silently get a boolean True.

At least on my system: salt 2018.3.2 (Oxygen)

Versions Report

salt:/srv # salt --versions-report
Salt Version:
           Salt: 2018.3.4
 
Dependency Versions:
           cffi: 1.1.0
       cherrypy: 3.6.0
       dateutil: 2.1
      docker-py: Not Installed
          gitdb: 0.6.4
      gitpython: 1.0.1
          ioflo: Not Installed
         Jinja2: 2.10
        libgit2: 0.22.0
        libnacl: Not Installed
       M2Crypto: 0.22
           Mako: Not Installed
   msgpack-pure: Not Installed
 msgpack-python: 0.6.1
   mysql-python: Not Installed
      pycparser: 2.12
       pycrypto: 2.6.1
   pycryptodome: Not Installed
         pygit2: 0.22.0
         Python: 2.7.3 (default, Apr 14 2012, 08:58:41) [GCC]
   python-gnupg: Not Installed
         PyYAML: 3.13
          PyZMQ: 17.1.2
           RAET: Not Installed
          smmap: 0.9.0
        timelib: Not Installed
        Tornado: 4.5.3
            ZMQ: 4.2.5
 
System Versions:
           dist: SuSE 12.3 x86_64
         locale: UTF-8
        machine: x86_64
        release: 4.4.114-42.1-default
         system: Linux
        version: openSUSE  12.3 x86_64

Related discussion on the user mailing list: https://groups.google.com/forum/#!topic/salt-users/jbtZ5T92xCY

[guettli]

I tested it on version 2019.2.0. It is the same.

The important stacktrace is even not visible if you use -l debug.

Just for the records. To get 2019.2.0 working, I had to work-around #51768.

[waynew]

Someone may be able to correct me, but I'm not sure that's what modules are for.

Modules are typically executed either like:

salt foohost foo.bar

Or, using states:

do some foo:
  module.run:
    - name: foo.bar

Just for some further information, could you try using the test state like so:

{% if salt['foo.bar']() %}
truthy:
  test.fail_without_changes:
    - name: should_not_be_here
{% else %}
falsey:
  test.nop:
    - comment: Okay, that call was false
{% endif %}

You might also try:

test things:
  test.nop:
    - comment: {{ salt['foo.bar']() }}

HTH!

[Ch3LL]

it is possible to use execution modules in a state like the original poster is doing. The problem here is when you run it with salt-call you can see the exception, but not in salt-ssh. This is because of here: https://github.com/saltstack/salt/blob/v2018.3.4/salt/client/ssh/ssh_py_shim.py#L281

and even if you were to change that to debug you still will not see it, because we are not currently adding the ssh logs from the salt-call log output. We could probably grab the stream from the logs and add it to the log output on the salt-ssh original host and change quiet to what the user sets.

[guettli]

@Ch3LL to grab the stream from the logs and add it to the log output is no solution for me. If there is an exception the whole thing should stop. See Zen of Python line 10.

[guettli]

@waynew If I use this:

{% if salt['foo.bar']() %}
truthy:
  test.fail_without_changes:
    - name: should_not_be_here
{% else %}
falsey:
  test.nop:
    - comment: Okay, that call was false
{% endif %}

The output is:

          ID: truthy
    Function: test.fail_without_changes
        Name: should_not_be_here
      Result: False
     Comment: Failure!

Sorry: no new insights.

[waynew]

If there is an exception the whole thing should stop.

That's definitely not an acceptable approach for Salt. We especially do not want a user's custom (and potentially poorly tested code) to crash Salt.

The error should be reported, potentially including the stack trace, but completely halting the execution on failure is not what most people need or want.

[Ch3LL]

to follow up on the idea of grabbing the debug logs. looks like i was not correct about that. When you run the module with salt-call even with quiet it does include the exception where salt-ssh does not. So the solution for salt-ssh to show the exception would be somewhere else.

[guettli]

I really would like to see my salt-ssh command to fail if there is an exception in a custom module.

I want it very much. Maybe there is an alternative solution, an alternative way, an alternative tool.

[waynew]

Fail or stop?

Where fail means something like:

fail.py

raise Exception('We failed')

And stop means something like

stop.py

import sys
try:
    raise Exception('oh no!')
    print('We should never be here')
except Exception:
    sys.exit('Uh oh, failure in processing')

[guettli]

@waynew you ask: "fail or stop?". I think "fail" would fit.

[waynew]

Then Salt is definitely not the tool you're looking for - that goal is completely antithetical to a tool like Salt. Fabric may be more to your liking.

That being said, this state file:

{% if salt['foo.bar']() %}
truthy:
  test.fail_without_changes:
    - name: should_not_be_here
{% else %}
falsey:
  test.nop:
    - comment: Okay, that call was false
{% endif %}

With this custom module (foo.py):

def bar():
    raise Exception

Should most certainly never be truthy. Ideally we would fail similar to something like this:

local:
    Data failed to compile:
----------
    Rendering SLS 'base:fail' failed: mapping values are not allowed here; line 3

---
test1:
 test.nop
  - prereq:    <======================
    - module: test2

test2:
 module.run:
  - name: test.ping
[...]
---

But something like Rendering SLS 'base:fail' failed: unhandled exception in module foo.bar.

[guettli]

Today I came across this swallowing of exceptions again. But I am deeply relaxed. I will switch my job in one week, and then I don't need to work with salt any more. I am relieved. Ansible is coming.

[stale]

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.

[xuhcc]

.

[stale]

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

[lkubb]

I think the previous conversation misses the point of this bug.

This behavior is not specific to custom modules. Try running the following via salt-ssh:

This should fail being rendered:
  test.show_notification:
    - text: {{ salt["disk.usage"]("c") | yaml_dquote }}

The output of salt["disk_usage"]("c") (which throws an exception because "c" is not a valid flag) is:
{"_error": "Failed to return clean data", "stderr": "Error running "disk.usage": Invalid flag passed to disk.usage", "stdout": "", "retcode": 1}

This is caused by the FunctionWrapper, which imitates the usual __salt__ function dict during state rendering, not raising an exception for errors, but returning a result dict: https://github.com/saltstack/salt/blob/master/salt/client/ssh/wrapper/__init__.py#L121-L141

The usual (expected) behavior is that rendering is aborted, while this bug can result in surprising outcomes.

The following (PoC) patch causes exceptions to be thrown and rendering to be aborted, as expected:

--- a/salt/client/ssh/wrapper/__init.py
+++ b/salt/client/ssh/wrapper/__init.py
@@ -9,6 +9,7 @@
 import copy
 
 import salt.client.ssh
+import salt.exceptions
 import salt.loader
 import salt.utils.data
 import salt.utils.json
@@ -126,6 +127,8 @@
                     "stderr": stderr,
                     "retcode": retcode,
                 }
+            if retcode:
+                raise salt.exceptions.CommandExecutionError(stderr)
             try:
                 ret = salt.utils.json.loads(stdout)
                 if len(ret) < 2 and "local" in ret:

Since the patched class is also used for running any module via salt-ssh, this simple patch will probably break other expectations not related to template rendering. I will see if I can come up with a proper patch.

Edit:

For reference, here is what happens with salt-call:

$ salt-call state.apply render_fail
[ERROR   ] Rendering exception occurred
Traceback (most recent call last):
  File "/opt/saltstack/salt/lib/python3.10/site-packages/salt/utils/templates.py", line 476, in render_jinja_tmpl
    output = template.render(**decoded_context)
  File "/opt/saltstack/salt/lib/python3.10/site-packages/jinja2/environment.py", line 1301, in render
    self.environment.handle_exception()
  File "/opt/saltstack/salt/lib/python3.10/site-packages/jinja2/environment.py", line 936, in handle_exception
    raise rewrite_traceback_stack(source=source)
  File "<template>", line 3, in top-level template code
  File "/opt/saltstack/salt/lib/python3.10/site-packages/jinja2/sandbox.py", line 393, in call
    return __context.call(__obj, *args, **kwargs)
  File "/opt/saltstack/salt/lib/python3.10/site-packages/salt/loader/lazy.py", line 149, in __call__
    return self.loader.run(run_func, *args, **kwargs)
  File "/opt/saltstack/salt/lib/python3.10/site-packages/salt/loader/lazy.py", line 1232, in run
    return self._last_context.run(self._run_as, _func_or_method, *args, **kwargs)
  File "/opt/saltstack/salt/lib/python3.10/site-packages/salt/loader/lazy.py", line 1247, in _run_as
    return _func_or_method(*args, **kwargs)
  File "/opt/saltstack/salt/lib/python3.10/site-packages/salt/modules/disk.py", line 92, in usage
    flags = _clean_flags(args, "disk.usage")
  File "/opt/saltstack/salt/lib/python3.10/site-packages/salt/modules/disk.py", line 74, in _clean_flags
    raise CommandExecutionError("Invalid flag passed to {}".format(caller))
salt.exceptions.CommandExecutionError: Invalid flag passed to disk.usage

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/saltstack/salt/lib/python3.10/site-packages/salt/utils/templates.py", line 218, in render_tmpl
    output = render_str(tmplstr, context, tmplpath)
  File "/opt/saltstack/salt/lib/python3.10/site-packages/salt/utils/templates.py", line 500, in render_jinja_tmpl
    raise SaltRenderError(
salt.exceptions.SaltRenderError: Problem running salt function in Jinja template: Invalid flag passed to disk.usage; line 3

---
This should fail being rendered:
  test.show_notification:
    - text: {{ salt["disk.usage"]("c") | yaml_dquote }}    <======================
---
[CRITICAL] Rendering SLS 'base:render_fail' failed: Problem running salt function in Jinja template: Invalid flag passed to disk.usage; line 3

---
This should fail being rendered:
  test.show_notification:
    - text: {{ salt["disk.usage"]("c") | yaml_dquote }}    <======================
---
local:
    Data failed to compile:
----------
    Rendering SLS 'base:render_fail' failed: Problem running salt function in Jinja template: Invalid flag passed to disk.usage; line 3

---
This should fail being rendered:
  test.show_notification:
    - text: {{ salt["disk.usage"]("c") | yaml_dquote }}    <======================
---