jinja renderer reports wrong line number

[mgwilliams]

If a jinja template references a subkey of a non existent jinja variable (e.g., {{ foo.bar }} when foo itself is undefined), Salt reports:

        Comment:   Undefined jinja variable; line 375 in template

But line 375 is a line number from jinja2/environment.py

[mgwilliams]

A test formula can be found at https://github.com/mgwilliams/jinja-test-formula

[basepi]

For the record, @mgwilliams verified by changing jinja2/environment.py and watched the line number change.

[mgwilliams]

There's a variation on this issue where a valid, but wrong, line number is presented. E.g.,

        Comment:   Undefined jinja variable; line 3 in template

---
{{ pillar.bar }}
{{ pillar.foo }}
{{ pillar.foo }}    <======================
---

In this case, it's actually pillar.bar that is undefined. See https://github.com/mgwilliams/jinja-test-formula/tree/8418-B

[terminalmage]

@mgwilliams That 2nd issue is a jinja bug. See #8245 (comment).

[terminalmage]

@mgwilliams BTW, good catch that this line number is from jinja2/environment.py. I've seen similar line numbers, like line 373 or so, and had been wondering if that was just due to the template being partially rendered and for loops being expanded. This should help greatly in narrowing this down.

[mgwilliams]

Hopefully a workaround for the jinja2 bug can be found. Otherwise, Salt would be better off just saying "Undefined jinja variable; guess where!".

[terminalmage]

Well, it's getting it from traceback.extract_tb, which is from the traceback module from python core. I'm going to do some poking around in the interactive shell, but my guess is that using this function was the wrong idea in the first place because it's grabbing the line number from the stack rather than the error itself. It's probably something that can be derived from the exception struct rather than looking at the traceback itself, and that's likely where the fix will come from.

[terminalmage]

So, after digging into the docstrings for the jinja2 exceptions, it appears that they are not all that helpful when it comes to providing the line number, probably the reason that the code was looking in the stack in the first place. It appears, however, that an assumption was being made about which offset in the stack contains the line in the template where the undefined variable was found. The most recent (in other words the last) line number in the stack was being used, and it looks like in some circumstances (like this one) the line number we want is in the penultimate step in the traceback, not the last one. I've made some adjustments to the jinja renderer which properly identify the offending line in the template. I added some data to the file from the formula posted by @mgwilliams to make the template bigger than just one line, and was able to generate the following error:

(saltdev)[root@virtucentos saltdev]# salt -c etc/salt virtucentos state.sls jinja-test
virtucentos:
----------
    State: - file
    Name:      /tmp/jinja.test
    Function:  managed
        Result:    False
        Comment:   Jinja variable 'foo' is undefined; line 5 in template

---
Line 1

Hello world!

{{ foo.foo }}    <======================

Line 7

Some more stuff
---
        Changes:
                   ----------

Summary
------------
Succeeded: 0
Failed:    1
------------
Total:     1

I'm going to look at my solution though and see if there's a better way to do this, there were some recent changes that I made to make reporting on rendering errors easier, and I'm not sure if they can or can't be applied to this. I should have a pull request later today.

Thanks again, @mgwilliams, for the concise instructions on how to replicate this issue, you made it much easier to track this one down.

[regilero]

@terminalmage I was working on that issue on my side, I made two commits that were not yet ready for a pull request (tests were not working yet), but if you work on that you may be interested in it:

• regilero@c758e8e
• regilero@f3d9817
• regilero@c021a8a

I saw that the jinja2.exceptions.UndefinedError was actually giving me a good error message, and that the current exception handling removed that message. And then after several bad syntax tests I saw that the StackTrace contained useful template line number only when the last element of the stackTrace third element was None.

[terminalmage]

@regilero I already have this fixed in my branch, it's just a matter of checking (once I get up in the morning) if my recent changes to make reporting on render errors easier can be applied here.

[terminalmage]

I've opened #8475, which will fix this. I also applied the same method to the one other exception type we are catching in the jinja renderer, so this should correct that as well.