Environment and Macro are None in compiled template

[jkrebs]

I'm using Jinja 2.8 and occasionally get errors with similar traces to the following:

Traceback (most recent call last):
  File "/base/data/home/apps/e~application-eu/1.386436435848170777/application/model/email_message.py", line 285, in render_async
    self.body_html = template_html.render(data).strip()
  File "/base/data/home/apps/e~application-eu/1.386436435848170777/application/../lib/jinja2/environment.py", line 989, in render
    return self.environment.handle_exception(exc_info, True)
  File "/base/data/home/apps/e~application-eu/1.386436435848170777/application/../lib/jinja2/environment.py", line 754, in handle_exception
    reraise(exc_type, exc_value, tb)
  File "/base/data/home/apps/e~application-eu/1.386436435848170777/templates_compiled/tmpl_cd5a12bffa62f259cfa2354d4ed29273b71c4447.py", line 12, in root
    t_1 = environment.filters['safe']
AttributeError: 'NoneType' object has no attribute 'filters'

Traceback (most recent call last):
  File "/base/data/home/apps/e~application-eu/1.385550924811387008/templates_compiled/tmpl_77327e04a7c6bffaabad217ef966c68fefc9bdca.py", line 15, in root
    context.vars['header'] = l_header = Macro(environment, macro, 'header', (), (), False, False, False)
TypeError: 'NoneType' object is not callable

I took a look at the Jinja2 source code, but wasn't able to see at quick glance where the environment variable is being set in the globals of the compiled template module.

The errors happen infrequently and I haven't been able to find the particular conditions to reproduce the problem. However, it happens on a regular basis.

Can you please suggest how I can debug the problem? Are there any debug switches I can use to figure out what's going on?

[squfrans]

i see the same issue and because of this we cannot use compiled templates
in production. a fraction of the requests would fail with exceptions about
not finding finalize, get_templates and other attributes.

unfortunately i can reproduce it only in our live environment (maybe because
of the request volume) and that is not the best debugging environment.

[mitsuhiko]

I will close this because I can't reproduce it at all. If someone has more information please make a new ticket with more information.

[jkrebs]

@mitsuhiko Can you suggest any debug code I can add to diagnose or create a test case?

I am lost because it only happens in a fraction of requests and in a way that I have not been able to reproduce.

[mitsuhiko]

If the environment is None the only real explanation I have is that the interpreter initiated a module shutdown which means that the last reference to the module was cleared. I am not sure what would cause this.

[mitsuhiko]

I assume this always happens with Environment.compile_templates?

[mitsuhiko]

So just looking at the code the module package reference in sys.modules is a weak reference. If for whatever reason the Environment (or the attached loader) would get garbage collected then modules would also tear down which can cause this.

I imagine that this could happen if you have an application that shuts down execution but outstanding HTTP requests are still in the air.

[mitsuhiko]

To investigate if this is the case you could do this:

import sys
env = Environment(loader=ModuleLoader(...))
sys.modules[env.loader.package_name] = env.loader.module

This changes the weak reference to a strong reference. If that stops the problem then your issue is that requests are in flight while the environment was already collected.

[jkrebs]

I assume this always happens with Environment.compile_templates?

I have never experienced the problem during Environment.compile_templates.

I imagine that this could happen if you have an application that shuts down execution but outstanding HTTP requests are still in the air.

This may well be the case. I am deploying to the Google App Engine environment which can shut down application instances at any time.

I will deploy your suggestion and report back if the exception reoccurs.

[squfrans]

i am sorry this is getting closed, but as i am not able to provide more information, can't really complain.

however, as it was 100% reproducible in our live environment, it seems a bit dangerous to keep this feature without any kind of caveat for the users. it's not big fun to deploy this to 100k live users and start seeing mysterious 500s.

[mitsuhiko]

@squfrans which feature are you referring to here? The compiled template loader is working just fine for the vast majority of users from what I can tell. I assume this is most likely in combination with a specific setup.

[mitsuhiko]

For what it's worth the X becomes None behavior is not at all unique to Jinja. This is a core Python problem for many years related to module shutdown.

[squfrans]

i am referring to the feature of compiled templates (not necessarily the template loader, the errors were runtime errors while the template was being rendered).

judging by the fact that there is only 2 people experiencing this issue, i am inclined to agree that it must be working for the majority of the users :} unfortunately i cannot use them, exactly in a high traffic website where the gain would be the biggest.

[bool-dev]

Just started seeing this as well. Flask app is deployed through uWSGI. I keep getting this:

t_1 = environment.filters['int']
AttributeError: 'NoneType' object has no attribute 'filters'

and always on the same precompiled template.

Update 1:
Did a fresh pre compile of the templates, and restarted app. Haven't seen the error again since. I will update in another 24 hours again.

Update 2:
So, looks like the error is gone. Has not occurred even once since the fresh pre compile.