Fixed #18773 -- Add logging for template variable resolving

django/template/base.py

@@ -1,5 +1,6 @@
 from __future__ import unicode_literals
 
+import logging
 import re
 from functools import partial
 from importlib import import_module
@@ -142,6 +143,7 @@ def _render(self, context):
         return self.nodelist.render(context)
 
     def render(self, context):
+        context.template_name = self.name
         "Display stage -- can be called many times"
         context.render_context.push()
         try:
@@ -794,6 +796,13 @@ def _resolve_lookup(self, context):
                             else:
                                 raise
         except Exception as e:
+            logger = logging.getLogger('django.template')
+
+            template_name = "Unknown"
+            if hasattr(context, "template_name"):
+                template_name = context.template_name
+            logger.warning("%s - %s" % (template_name, e))
+
             if getattr(e, 'silent_variable_failure', False):
                 current = settings.TEMPLATE_STRING_IF_INVALID
             else:

django/template/context.py

@@ -127,6 +127,7 @@ def __init__(self, dict_=None, autoescape=True, current_app=None,
         self.current_app = current_app
         self.use_l10n = use_l10n
         self.use_tz = use_tz
+        self.template_name = "Unknown"
         self.render_context = RenderContext()
         super(Context, self).__init__(dict_)
 

django/utils/log.py

@@ -53,6 +53,11 @@
             'level': 'ERROR',
             'propagate': False,
         },
+        'django.template':{
+            'handlers':['null'],
+            'level': 'WARNING',
+            'propagate': False,
+        },
         'django.security': {
             'handlers': ['mail_admins'],
             'level': 'ERROR',

docs/topics/logging.txt

@@ -413,7 +413,7 @@ requirements of logging in Web server environment.
 Loggers
 -------
 
-Django provides four built-in loggers.
+Django provides five built-in loggers.
 
 ``django``
 ~~~~~~~~~~
@@ -438,6 +438,15 @@ Messages to this logger have the following extra context:
 * ``request``: The request object that generated the logging
   message.
 
+.. _django-template-logger:
+
+``django.template``
+~~~~~~~~~~~~~~~~~~
+
+Log messages related to the rendering of templates. missing
+variables are raised as ``WARNING`` messages. By default this logger uses
+the null handler.
+
 ``django.db.backends``
 ~~~~~~~~~~~~~~~~~~~~~~
 

tests/admin_scripts/tests.py

@@ -179,6 +179,11 @@ def safe_remove(path):
 
         return self.run_test('./manage.py', args, settings_file)
 
+    def assertTemplateLogHandlerMissingOutput(self, stream):
+        message = 'No handlers could be found for logger "django.template"'
+        stream = force_text(stream)
+        self.assertTrue(message in stream, "'%s' does not match actual output text '%s'" % (message, stream))
+
     def assertNoOutput(self, stream):
         "Utility assertion: assert that the given stream is empty"
         self.assertEqual(len(stream), 0, "Stream should be empty: actually contains '%s'" % stream)
@@ -1698,7 +1703,7 @@ def test_custom_project_template(self):
         self.addCleanup(shutil.rmtree, testproject_dir, True)
 
         out, err = self.run_django_admin(args)
-        self.assertNoOutput(err)
+        self.assertTemplateLogHandlerMissingOutput(err)
         self.assertTrue(os.path.isdir(testproject_dir))
         self.assertTrue(os.path.exists(os.path.join(testproject_dir, 'additional_dir')))
 
@@ -1710,7 +1715,7 @@ def test_template_dir_with_trailing_slash(self):
         self.addCleanup(shutil.rmtree, testproject_dir, True)
 
         out, err = self.run_django_admin(args)
-        self.assertNoOutput(err)
+        self.assertTemplateLogHandlerMissingOutput(err)
         self.assertTrue(os.path.isdir(testproject_dir))
         self.assertTrue(os.path.exists(os.path.join(testproject_dir, 'additional_dir')))
 
@@ -1773,7 +1778,7 @@ def test_file_without_extension(self):
         self.addCleanup(shutil.rmtree, testproject_dir, True)
 
         out, err = self.run_django_admin(args)
-        self.assertNoOutput(err)
+        self.assertTemplateLogHandlerMissingOutput(err)
         self.assertTrue(os.path.isdir(testproject_dir))
         self.assertTrue(os.path.exists(os.path.join(testproject_dir, 'additional_dir')))
         base_path = os.path.join(testproject_dir, 'additional_dir')
@@ -1791,7 +1796,7 @@ def test_custom_project_template_context_variables(self):
         os.mkdir(testproject_dir)
         self.addCleanup(shutil.rmtree, testproject_dir)
         out, err = self.run_django_admin(args)
-        self.assertNoOutput(err)
+        self.assertTemplateLogHandlerMissingOutput(err)
         test_manage_py = os.path.join(testproject_dir, 'manage.py')
         with open(test_manage_py, 'r') as fp:
             content = force_text(fp.read())
@@ -1836,7 +1841,7 @@ def test_custom_project_template_with_non_ascii_templates(self):
         self.addCleanup(shutil.rmtree, testproject_dir, True)
 
         out, err = self.run_django_admin(args)
-        self.assertNoOutput(err)
+        self.assertTemplateLogHandlerMissingOutput(err)
         self.assertTrue(os.path.isdir(testproject_dir))
         path = os.path.join(testproject_dir, 'ticket-18091-non-ascii-template.txt')
         with codecs.open(path, 'r', encoding='utf-8') as f:

tests/template_tests/tests.py

@@ -12,7 +12,7 @@
 from django.conf import settings
 from django.core import urlresolvers
 from django.template import (base as template_base, loader, Context,
-    RequestContext, Template, TemplateSyntaxError)
+    RequestContext, Template, TemplateSyntaxError, Variable, VariableDoesNotExist)
 from django.template.loaders import app_directories, filesystem, cached
 from django.test import RequestFactory, TestCase
 from django.test.utils import (setup_test_template_loader,
@@ -1962,3 +1962,70 @@ def test_relative_include_exploit(self):
         with override_settings(ALLOWED_INCLUDE_ROOTS=(self.ssi_dir,)):
             for path in disallowed_paths:
                 self.assertEqual(self.render_ssi(path), '')
+
+
+class VariableResolveLoggingTests(unittest.TestCase):
+    def setUp(self):
+        import logging
+        from logging import Handler
+
+        class TestHandler(Handler):
+            def __init__(self):
+                super(TestHandler, self).__init__()
+                from django.utils.six import StringIO
+                self.log_record = None
+
+            def emit(self, record):
+                self.log_record = record
+
+        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.WARNING)
+
+    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 article(self):
+                raise TestObject.SilentDoesNotExist("Attribute does not exist.")
+
+            def __iter__(self):
+                return iter([attr for attr in dir(TestObject) if attr[:2] != "__"])
+
+        c = TestObject()
+        Variable('article').resolve(c)
+        self.assertEqual(self.test_handler.log_record.msg,
+                         'template - Attribute does not exist.')
+
+    def test_log_on_variable_does_not_exist_not_silent(self):
+        c = {'article': {'section':u'News'}}
+
+        with self.assertRaises(VariableDoesNotExist):
+            Variable('article.author').resolve(c)
+
+        self.assertEqual(self.test_handler.log_record.msg,
+                         'Unknown - Failed lookup for key [author] in u"{u\'section\': u\'News\'}"')
+
+    def test_no_log_when_variable_exists(self):
+        c = {'article': {'section':u'News'}}
+        Variable('article.section').resolve(c)
+        self.assertIsNone(self.test_handler.log_record)
+
+    def test_default_null_handler_for_template_logging(self):
+        from logging import NullHandler
+        self.logger.removeHandler(self.test_handler)
+
+        self.assertEqual(len(self.logger.handlers), 1)
+        self.assertEqual(type(self.logger.handlers[0]), NullHandler)