Salt: Jinja Error Handling still doesn't provide enough clues to the source of the issue

[timwsuqld]

Description of Issue/Question

4092 claims to have improved error handling since the original issue. Jinja rendering issues can still throw a Traceback that is less than helpful, and doesn't point to the actual issue.

Setup

Pillar file had incorrect nodegroups as an array instead of list. Error message didn't provide enough clues to a) work out which jinja file was at fault, or b) which pillar variable was at fault.

In the below debugging, you can see the last jinja file referenced was salt/formulas.jinja, when in fact the error was occurring in salt/files/master.d/f_defaults.conf. The jinja variable that was an array instead of list was cfg_master['nodegroups'], but no where in the debugging output was that visible.

Snippit from f_defaults.conf that was failing

#####         Node Groups           ######
##########################################
# Node groups allow for logical groupings of minion nodes. A group consists of a group
# name and a compound target.
#nodegroups:
#  group1: '[email protected],bar.domain.com,baz.domain.com and bl*.domain.com'
#  group2: 'G@os:Debian and foo.domain.com'
{%- if 'nodegroups' in cfg_master %}
{%- do default_keys.append('nodegroups') %}
nodegroups:
  {%- for name, lvl in cfg_master['nodegroups'].items() %}
  {{ name }}: {{ lvl }}
  {%- endfor %}
{%- elif 'nodegroups' in cfg_salt %}
nodegroups:
  {%- for name, lvl in cfg_salt['nodegroups'].items() %}
  {{ name }}: {{ lvl }}
  {%- endfor %}
{%- endif %}

Steps to Reproduce Issue

[INFO    ] Running state [/etc/salt/master.d] at time 08:23:02.700008
[INFO    ] Executing state file.recurse for /etc/salt/master.d
[DEBUG   ] In saltenv 'base', looking at rel_path 'salt/files/master.d/engine.conf' to resolve 'salt://salt/files/master.d/engine.conf'
[DEBUG   ] In saltenv 'base', ** considering ** path '/var/cache/salt/minion/files/base/salt/files/master.d/engine.conf' to resolve 'salt://salt/files/master.d/engine.conf'
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://salt/files/master.d/engine.conf', mode up-to-date
[DEBUG   ] Jinja search path: ['/var/cache/salt/minion/files/base']
[DEBUG   ] In saltenv 'base', looking at rel_path 'salt/files/master.d/f_defaults.conf' to resolve 'salt://salt/files/master.d/f_defaults.conf'
[DEBUG   ] In saltenv 'base', ** considering ** path '/var/cache/salt/minion/files/base/salt/files/master.d/f_defaults.conf' to resolve 'salt://salt/files/master.d/f_defaults.conf'
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://salt/files/master.d/f_defaults.conf', mode up-to-date
[DEBUG   ] Jinja search path: ['/var/cache/salt/minion/files/base']
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/minion', 'suq-config-management', 'tcp://127.0.0.1:4506', 'aes')
[DEBUG   ] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'suq-config-management', 'tcp://127.0.0.1:4506')
[TRACE   ] Inserted key into loop_instance_map id 140330259438192 for key ('/etc/salt/pki/minion', 'suq-config-management', 'tcp://127.0.0.1:4506', 'aes') and process 2663
[DEBUG   ] In saltenv 'base', looking at rel_path 'salt/formulas.jinja' to resolve 'salt://salt/formulas.jinja'
[DEBUG   ] In saltenv 'base', ** considering ** path '/var/cache/salt/minion/files/base/salt/formulas.jinja' to resolve 'salt://salt/formulas.jinja'
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://salt/formulas.jinja', mode up-to-date
[ERROR   ] Rendering exception occurred: Jinja variable 'list object' has no attribute 'items'
[ERROR   ] An exception occurred in this state: Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/salt/state.py", line 1746, in call
    **cdata['kwargs'])
  File "/usr/lib/python2.7/dist-packages/salt/loader.py", line 1703, in wrapper
    return f(*args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/salt/states/file.py", line 2807, in recurse
    manage_file(dest, src)
  File "/usr/lib/python2.7/dist-packages/salt/states/file.py", line 2685, in manage_file
    **pass_kwargs)
  File "/usr/lib/python2.7/dist-packages/salt/states/file.py", line 1793, in managed
    **kwargs
  File "/usr/lib/python2.7/dist-packages/salt/modules/file.py", line 4299, in check_managed_changes
    **kwargs)
  File "/usr/lib/python2.7/dist-packages/salt/modules/file.py", line 3793, in get_managed
    **kwargs)
  File "/usr/lib/python2.7/dist-packages/salt/utils/templates.py", line 178, in render_tmpl
    output = render_str(tmplstr, context, tmplpath)
  File "/usr/lib/python2.7/dist-packages/salt/utils/templates.py", line 386, in render_jinja_tmpl
    buf=tmplstr)
SaltRenderError: Jinja variable 'list object' has no attribute 'items'

[INFO    ] Completed state [/etc/salt/master.d] at time 08:23:03.101925 duration_in_ms=401.916

Versions Report

Salt Version:
           Salt: 2016.11.3

Dependency Versions:
           cffi: 1.5.2
       cherrypy: 3.5.0
       dateutil: 2.4.2
          gitdb: 0.6.4
      gitpython: 1.0.1
          ioflo: Not Installed
         Jinja2: 2.8
        libgit2: 0.24.0
        libnacl: Not Installed
       M2Crypto: Not Installed
           Mako: 1.0.3
   msgpack-pure: Not Installed
 msgpack-python: 0.4.6
   mysql-python: Not Installed
      pycparser: 2.14
       pycrypto: 2.6.1
         pygit2: 0.24.0
         Python: 2.7.12 (default, Nov 19 2016, 06:48:10)
   python-gnupg: Not Installed
         PyYAML: 3.11
          PyZMQ: 15.2.0
           RAET: Not Installed
          smmap: 0.9.0
        timelib: Not Installed
        Tornado: 4.2.1
            ZMQ: 4.1.4

System Versions:
           dist: Ubuntu 16.04 xenial
        machine: x86_64
        release: 4.4.0-64-generic
         system: Linux
        version: Ubuntu 16.04 xenial

[gtmanfred]

Thanks for reporting this.

Daniel

[JohnTheodore]

ipdb> template.render(
resources=resources,
policy=policy,
action=action,
account=account,
region=region)
* UndefinedError: 'dict object' has no attribute u'ec2'
ipdb> jinja2.__version__
'2.9.6'

:(

There are dozens and dozens of variable references in the template. Couldn't it have said what line or what variable name the render fails on?

[ghost]

I definitely agree. The error message should contain the line number, because that should be available from the underlying Jinja engine.

[stale[bot]]

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.

[timwsuqld]

Still an issue

[stale[bot]]

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

[pbusquemdf]

This issue should be increased to Critical. Any tool relying on parsing template should provide information as where a parsing error occurs.

For instance, I got this:

`local:

Data failed to compile:

Rendering SLS 'base:file.server' failed: did not find expected alphabetic or numeric character

`
The file is 120 lines long declaring over 30 functions. Without proper error, the only way to debug is to delete all function and put them back one by one until it crash. This is no way an efficient way to perform testing and debuging.