SaltTemplateError: no line numbers

[Mrten]

After #4916 / #4901 were fixed I now get an error, but I still don't know where to look to find it.

mx-1:
----------
    State: - file
    Name:      /etc/exim4/exim4.conf
    Function:  managed
        Result:    False
        Comment:   expected token 'end of print statement', got ':'
        Changes:
----------

(Exact same config as in #4916). I've been digging the code, this is a jinja TemplateSyntaxError, by way of a SaltTemplateError. Jinja logs the filename and linenumber with the exception, but it gets lost somewhere.

[Mrten]

After restarting masters and minions a lot when patching jinja/exceptions.py, it seems that either everything after the \n in the __str__ / __unicode__ from jinja's TemplateSyntaxError is dropped, or TemplateSyntexError's self.translated is set.

mx-1:
----------
    State: - file
    Name:      /etc/exim4/exim4.conf
    Function:  managed
        Result:    False
        Comment:   expected token 'end of print statement', got ':'   line 310     defer condition = ${if and{{def:acl_m9}{!eq{$acl_m9}{$domain}}}}
        Changes:

[thatch45]

Thanks for the info @Mrten, we can track this down.

[basepi]

So the reason you lose the line number is because long before we hit the template, we read the file from disk into a string. We then pass that string around, including to the templating engine. I have done some jinja tests in a python interpreter, and there doesn't seem to be any way to get line numbers when you're sending in a string instead of a file.

Basically, I'm not sure we can fix this, barring writing a tempfile and templating from that, or passing around the path instead of the string (which would require a major rewrite)

[Mrten]

Are you saying these lines aren't hit?

https://github.com/mitsuhiko/jinja2/blob/master/jinja2/exceptions.py#L85-L89

Because I have seen linenumbers while testing! Though I did have some problems with triggering it.

[basepi]

Erm, I guess I'm not sure. They could be being hit and and set to None or similar.

All I know is that when I was doing testing a month or two ago on an issue similar to this I wasn't getting line numbers in my python interpreter, completely separate from Salt. Perhaps I need to do more testing.

[Mrten]

You'll have linenumbers if you apply this patch (to jinja's exception.py).

--- exceptions.py   2010-10-17 15:47:07.000000000 +0200
+++ exceptions.py-new   2013-05-23 19:47:10.643101189 +0200
@@ -91,8 +91,8 @@
     # it override at runtime.
     def __unicode__(self):
         # for translated errors we only return the message
-        if self.translated:
-            return self.message
+        #if self.translated:
+        #    return self.message

         # otherwise attach some stuff
         location = 'line %d' % self.lineno

So that means self.translated is set, but I do not know what that means for salts' invocation of jinja :)

The error:

----------
    State: - file
    Name:      /etc/exim4/exim4.conf
    Function:  managed
        Result:    False
        Comment:   expected token 'end of print statement', got ':'
  line 309
    defer condition = ${if and{{def:acl_m_connectionDomainname}{!eq{$acl_m_connectionDomainname}{$domain}}}}
        Changes:

[Mrten]

To replicate, this is the problematic line in the exim4.conf (see #4916 for the state):

  # als acl_m_connectionDomainname (het domein van de eerste recipient) al gezet is, en we krijgen een
  # ander, doe dan defer
  defer condition = ${if and{{def:acl_m_connectionDomainname}{!eq{$acl_m_connectionDomainname}{$domain}}}}
     message      = Sorry, please deliver one domain at a time.

(the double brace after and should be {{'{{'}}). Exims' config language is full of double braces, they have to be escaped when using jinja.

[basepi]

Unfortunately, patching jinja for salt is probably out of the question, as we would have to start maintaining our patched version ourselves, and distribute it with salt. I'll definitely look into that patch though, when I have time, to see if we can somehow get similar behavior in salt.

[Mrten]

Of course you are not going to patch jinja, the point of the patch is that it points in the direction of the solution. Now the problem is reduced to why self.translated is set, and to fix that. The availability of line numbers in exceptions rather trump localization, in my view (even if localization is the problem).

[Mrten]

OK, so this is way more complicated then I thought. translated has nothing to do with localization. If I read this correctly: Jinja does all kinds of weird things with the exception raised, including generating an empty python file with the correct number of lines ending with 'raise X-Exception', compiling and running that to fake another exception, then fetching the traceback from that (fake_exc_info).

My guess now is that Salt catches jinja's exception and forgets to add the linenumber from the exception back to the string from the exception. Let's see if I'm correct.

[Mrten]

I am:

    except jinja2.exceptions.TemplateSyntaxError as exc:
        raise SaltTemplateRenderError(str(exc))

str(exc) is not putting in the linenumbers from the traceback, salt assumes str() does that. But it doesn't, since this is an artificial exception we're handing and self.translated is set in jinja so the linenumber is missing in the result. However, jinja has just gone through some lengths to create a nice traceback for us!

Here is the traceback, if I add code to write(format_exc(exc)) to a file in /tmp:

Traceback (most recent call last):
  File "/usr/lib/pymodules/python2.7/salt/utils/templates.py", line 98, in render_jinja_tmpl
    output = jinja_env.from_string(tmplstr).render(**context)
  File "/usr/lib/python2.7/dist-packages/jinja2/environment.py", line 769, in from_string
    return cls.from_code(self, self.compile(source), globals, None)
  File "/usr/lib/python2.7/dist-packages/jinja2/environment.py", line 493, in compile
    self.handle_exception(exc_info, source_hint=source)
  File "<unknown>", line 309, in template
TemplateSyntaxError: expected token 'end of print statement', got ':'

A linenumber!

All we have to do now is add it back to the string.

--- templates.py    2013-05-06 20:35:44.000000000 +0200
+++ templates.py-new    2013-05-23 22:13:54.300230364 +0200
@@ -11,6 +11,7 @@
 import logging
 import tempfile
 import traceback
+import sys

 # Import third party libs
 import jinja2
@@ -97,7 +98,8 @@
     try:
         output = jinja_env.from_string(tmplstr).render(**context)
     except jinja2.exceptions.TemplateSyntaxError as exc:
-        raise SaltTemplateRenderError(str(exc))
+        raise SaltTemplateRenderError(str(exc) + '; lineno: ' + str(traceback.extract_tb(sys.exc_info()[2])[-1][1]))

     # Workaround a bug in Jinja that removes the final newline
     # (https://github.com/mitsuhiko/jinja2/issues/75)

Seeing as the next line is a workaround for jinja as well, this should be an easy one to add.

[Mrten]

Reading this back I see that I could be read as a bit condescending, which was not my intent (I was writing down my train of thought that was going to be interrupted by supper). Apologies if harm was done!

[basepi]

Heh, I'm very hard to offend, no worries. =) Great find! Submit a pull request! =)

[Mrten]

Can I leave that as an exercise for the reader? :)

(I hardly know python but I really don't know git)

[basepi]

Heh, I'll put in the request. =) Thanks again!