From dc5b01ad05e50ccde688c73c2ed3334a956076b0 Mon Sep 17 00:00:00 2001 From: Caroline Simpson Date: Mon, 14 Apr 2014 17:18:03 -0400 Subject: [PATCH] Fixed #18773 -- Added logging for template variable resolving Added a django.template logger without a default handler. Added logging if there is an exception while resolving variables in a template. --- django/contrib/admin/helpers.py | 1 + django/template/base.py | 7 +++ django/template/context.py | 1 + docs/releases/1.9.txt | 3 ++ docs/topics/logging.txt | 10 ++++ tests/template_tests/test_logging.py | 71 ++++++++++++++++++++++++++++ 6 files changed, 93 insertions(+) create mode 100644 tests/template_tests/test_logging.py diff --git a/django/contrib/admin/helpers.py b/django/contrib/admin/helpers.py index b44d411828..a841a5e6a8 100644 --- a/django/contrib/admin/helpers.py +++ b/django/contrib/admin/helpers.py @@ -121,6 +121,7 @@ class AdminField(object): self.field = form[field] # A django.forms.BoundField instance self.is_first = is_first # Whether this field is first on the line self.is_checkbox = isinstance(self.field.field.widget, forms.CheckboxInput) + self.is_readonly = False def label_tag(self): classes = [] diff --git a/django/template/base.py b/django/template/base.py index c008ac623d..a29f1332a8 100644 --- a/django/template/base.py +++ b/django/template/base.py @@ -51,6 +51,7 @@ u'' from __future__ import unicode_literals +import logging import re import warnings from functools import partial @@ -125,6 +126,8 @@ libraries = {} # global list of libraries to load by default for a new parser builtins = [] +logger = logging.getLogger('django.template') + class TemplateSyntaxError(Exception): pass @@ -209,6 +212,7 @@ class Template(object): try: if context.template is None: with context.bind_template(self): + context.template_name = self.name return self._render(context) else: return self._render(context) @@ -893,6 +897,9 @@ class Variable(object): else: raise except Exception as e: + template_name = getattr(context, 'template_name', 'unknown') + logger.debug('{} - {}'.format(template_name, e)) + if getattr(e, 'silent_variable_failure', False): current = context.template.engine.string_if_invalid else: diff --git a/django/template/context.py b/django/template/context.py index 2c30181927..2434b31a68 100644 --- a/django/template/context.py +++ b/django/template/context.py @@ -141,6 +141,7 @@ class Context(BaseContext): self._current_app = current_app self.use_l10n = use_l10n self.use_tz = use_tz + self.template_name = "unknown" self.render_context = RenderContext() # Set to the original template -- as opposed to extended or included # templates -- during rendering, see bind_template. diff --git a/docs/releases/1.9.txt b/docs/releases/1.9.txt index 4c27230d10..16a9e9d5f8 100644 --- a/docs/releases/1.9.txt +++ b/docs/releases/1.9.txt @@ -188,6 +188,9 @@ Templates * Added a :meth:`Context.setdefault() ` method. +* A warning will now be logged for missing context variables. These messages + will be logged to the :ref:`django.template ` logger. + Requests and Responses ^^^^^^^^^^^^^^^^^^^^^^ diff --git a/docs/topics/logging.txt b/docs/topics/logging.txt index 0e167871ab..89de6d56a4 100644 --- a/docs/topics/logging.txt +++ b/docs/topics/logging.txt @@ -478,6 +478,16 @@ Messages to this logger have the following extra context: * ``request``: The request object that generated the logging message. +.. _django-template-logger: + +``django.template`` +~~~~~~~~~~~~~~~~~~~ + +.. versionadded:: 1.9 + +Log messages related to the rendering of templates. Missing context variables +are logged as ``DEBUG`` messages if :setting:`DEBUG` is `True`. + .. _django-db-logger: ``django.db.backends`` diff --git a/tests/template_tests/test_logging.py b/tests/template_tests/test_logging.py new file mode 100644 index 0000000000..a8ac82ecba --- /dev/null +++ b/tests/template_tests/test_logging.py @@ -0,0 +1,71 @@ +from __future__ import unicode_literals + +import logging + +from django.template import Template, Variable, VariableDoesNotExist +from django.test import SimpleTestCase + + +class TestHandler(logging.Handler): + def __init__(self): + super(TestHandler, self).__init__() + self.log_record = None + + def emit(self, record): + self.log_record = record + + +class VariableResolveLoggingTests(SimpleTestCase): + def setUp(self): + self.test_handler = TestHandler() + self.logger = logging.getLogger('django.template') + self.original_level = self.logger.level + self.logger.addHandler(self.test_handler) + self.logger.setLevel(logging.DEBUG) + + def tearDown(self): + self.logger.removeHandler(self.test_handler) + self.logger.level = self.original_level + + def test_log_on_variable_does_not_exist_silent(self): + class TestObject(object): + class SilentDoesNotExist(Exception): + silent_variable_failure = True + + @property + def template_name(self): + return "template" + + @property + def template(self): + return Template('') + + @property + def article(self): + raise TestObject.SilentDoesNotExist("Attribute does not exist.") + + def __iter__(self): + return iter(attr for attr in dir(TestObject) if attr[:2] != "__") + + def __getitem__(self, item): + return self.__dict__[item] + + Variable('article').resolve(TestObject()) + self.assertEqual( + self.test_handler.log_record.msg, + 'template - Attribute does not exist.' + ) + + def test_log_on_variable_does_not_exist_not_silent(self): + with self.assertRaises(VariableDoesNotExist): + Variable('article.author').resolve({'article': {'section': 'News'}}) + + self.assertEqual( + self.test_handler.log_record.msg, + 'unknown - Failed lookup for key [author] in %r' % + ("{%r: %r}" % ('section', 'News'), ) + ) + + def test_no_log_when_variable_exists(self): + Variable('article.section').resolve({'article': {'section': 'News'}}) + self.assertIsNone(self.test_handler.log_record)