From: Ben Darnell <ben@bendarnell.com>
Date: Wed, 7 Dec 2011 08:36:33 +0000 (-0800)
Subject: A different approach to template stack traces:
X-Git-Tag: v2.2.0~70
X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=597f70b31815f64ca382089b012d9eb0277e6cc1;p=thirdparty%2Ftornado.git

A different approach to template stack traces:

Include the template source line as a comment in the generated code,
and add the magic necessary for python's normal stack traces to print
the (generated) source.
---

diff --git a/tornado/template.py b/tornado/template.py
index fda7e5fdf..01927d60c 100644
--- a/tornado/template.py
+++ b/tornado/template.py
@@ -173,16 +173,15 @@ from __future__ import with_statement
 
 import cStringIO
 import datetime
+import linecache
 import logging
 import os.path
 import posixpath
 import re
 import threading
-import sys
-import traceback
 
 from tornado import escape
-from tornado.util import bytes_type
+from tornado.util import bytes_type, ObjectDict
 
 _DEFAULT_AUTOESCAPE = "xhtml_escape"
 _UNSET = object()
@@ -195,7 +194,6 @@ class Template(object):
     """
     def __init__(self, template_string, name="<string>", loader=None,
                  compress_whitespace=None, autoescape=_UNSET):
-        self.template_string = template_string
         self.name = name
         if compress_whitespace is None:
             compress_whitespace = name.endswith(".html") or \
@@ -207,14 +205,17 @@ class Template(object):
         else:
             self.autoescape = _DEFAULT_AUTOESCAPE
         self.namespace = loader.namespace if loader else {}
-        reader = _TemplateReader(name, escape.native_str(self.template_string))
+        reader = _TemplateReader(name, escape.native_str(template_string))
         self.file = _File(self, _parse(reader, self))
-        self.code, self.line_numbers = self._generate_python(
-                                                  loader, compress_whitespace)
+        self.code = self._generate_python(loader, compress_whitespace)
         self.loader = loader
         try:
-            self.compiled = compile(escape.to_unicode(self.code),
-                                    "<template %s>" % self.name, "exec")
+            # Under python2.5, the fake filename used here must match
+            # the module name used in __name__ below.
+            self.compiled = compile(
+                escape.to_unicode(self.code),
+                "%s.generated.py" % self.name.replace('.','_'),
+                "exec")
         except Exception:
             formatted_code = _format_code(self.code).rstrip()
             logging.error("%s code:\n%s", self.name, formatted_code)
@@ -232,39 +233,25 @@ class Template(object):
             "datetime": datetime,
             "_utf8": escape.utf8,  # for internal use
             "_string_types": (unicode, bytes_type),
+            # __name__ and __loader__ allow the traceback mechanism to find
+            # the generated source code.
+            "__name__": self.name.replace('.', '_'),
+            "__loader__": ObjectDict(get_source=lambda name: self.code),
         }
         namespace.update(self.namespace)
         namespace.update(kwargs)
         exec self.compiled in namespace
         execute = namespace["_execute"]
+        # Clear the traceback module's cache of source data now that
+        # we've generated a new template (mainly for this module's
+        # unittests, where different tests reuse the same name).
+        linecache.clearcache()
         try:
             return execute()
         except Exception:
-            exc_type, exc_value, exc_traceback = sys.exc_info()
-            if self.loader and not hasattr(exc_value, "_logged"):
-                frame = exc_traceback.tb_next.tb_frame
-                code_msg = ""
-                code_args = []
-                trace_msg = ""
-                trace_args = []
-                while frame is not None:
-                    match = re.match(r"\<template ([^\>]+)\>", frame.f_code.co_filename)
-                    if match:
-                        template = self.loader.templates[match.groups()[0]]
-                        code_msg = "%s code:\n%s\n\n" + code_msg
-                        code_args = [template.name, _format_code(self.code).rstrip()] + code_args
-                        include_trace_msg = ""
-                        include_trace_args = []
-                        for file, line_number in template.line_numbers[frame.f_lineno]:
-                            lines = self.loader.templates[file.name].template_string.split("\n")
-                            include_trace_msg += "%s:%i:%s\n"
-                            include_trace_args.extend([file.name, line_number, lines[line_number-1]])
-                        trace_msg = include_trace_msg + trace_msg
-                        trace_args = include_trace_args + trace_args
-                    frame = frame.f_back
-                logging.error("\n" + code_msg + trace_msg, *(code_args + trace_args))
-            exc_value._logged = None
-            raise exc_type, exc_value, exc_traceback
+            formatted_code = _format_code(self.code).rstrip()
+            logging.error("%s code:\n%s", self.name, formatted_code)
+            raise
 
     def _generate_python(self, loader, compress_whitespace):
         buffer = cStringIO.StringIO()
@@ -279,7 +266,7 @@ class Template(object):
             writer = _CodeWriter(buffer, named_blocks, loader, ancestors[0].template,
                                  compress_whitespace)
             ancestors[0].generate(writer)
-            return buffer.getvalue(), writer.line_numbers
+            return buffer.getvalue()
         finally:
             buffer.close()
 
@@ -580,8 +567,6 @@ class _CodeWriter(object):
         self.compress_whitespace = compress_whitespace
         self.apply_counter = 0
         self.include_stack = []
-        self.line_numbers = {}
-        self._current_line = 1
         self._indent = 0
 
     def indent_size(self):
@@ -600,7 +585,7 @@ class _CodeWriter(object):
         return Indenter()
 
     def include(self, template, line):
-        self.include_stack.append((self.current_template, line+1))
+        self.include_stack.append((self.current_template, line))
         self.current_template = template
 
         class IncludeTemplate(object):
@@ -615,17 +600,19 @@ class _CodeWriter(object):
     def write_line(self, line, line_number, indent=None):
         if indent == None:
             indent = self._indent
-        print >> self.file, "    "*indent + line
-
-        self.line_numbers[self._current_line] = self.include_stack[:]+[(self.current_template, line_number+1)]
-        self._current_line += 1
+        line_comment = '  # %s:%d' % (self.current_template.name, line_number)
+        if self.include_stack:
+            ancestors = ["%s:%d" % (tmpl.name, lineno)
+                         for (tmpl, lineno) in self.include_stack]
+            line_comment += ' (via %s)' % ', '.join(reversed(ancestors))
+        print >> self.file, "    "*indent + line + line_comment
 
 
 class _TemplateReader(object):
     def __init__(self, name, text):
         self.name = name
         self.text = text
-        self.line = 0
+        self.line = 1
         self.pos = 0
 
     def find(self, needle, start=0, end=None):
diff --git a/tornado/test/template_test.py b/tornado/test/template_test.py
index a48dd6884..30acf1b21 100644
--- a/tornado/test/template_test.py
+++ b/tornado/test/template_test.py
@@ -1,12 +1,13 @@
+from __future__ import with_statement
+
+import traceback
+
 from tornado.escape import utf8, native_str
 from tornado.template import Template, DictLoader, ParseError
-from tornado.testing import LogCaptureTestCase, LogTrapTestCase
-from tornado.util import b, bytes_type, ObjectDict, LogCaptureHandler
+from tornado.testing import LogTrapTestCase
+from tornado.util import b, bytes_type, ObjectDict
 
-def _error_log(loader, name, line_number):
-    return (name, line_number, loader.templates[name].template_string.split('\n')[line_number-1])
-
-class TemplateTest(LogTrapTestCase, LogCaptureTestCase):
+class TemplateTest(LogTrapTestCase):
     def test_simple(self):
         template = Template("Hello {{ name }}!")
         self.assertEqual(template.generate(name="Ben"),
@@ -96,72 +97,61 @@ class TemplateTest(LogTrapTestCase, LogCaptureTestCase):
         template = Template(utf8("{% comment blah blah %}foo"))
         self.assertEqual(template.generate(), b("foo"))
 
+class StackTraceTest(LogTrapTestCase):
     def test_error_line_number_expression(self):
         loader = DictLoader({"test.html": """one
 two{{1/0}}
 three
         """})
-        with LogCaptureHandler() as handler:
-            try:
-                loader.load("test.html").generate()
-            except ZeroDivisionError:
-                pass
-            self.assertInLog(handler, lambda record: self.assertEqual(record.args[2:], _error_log(loader, "test.html", 2)))
+        try:
+            loader.load("test.html").generate()
+        except ZeroDivisionError:
+            self.assertTrue("# test.html:2" in traceback.format_exc())
 
     def test_error_line_number_directive(self):
         loader = DictLoader({"test.html": """one
 two{%if 1/0%}
 three{%end%}
         """})
-        with LogCaptureHandler() as handler:
-            try:
-                loader.load("test.html").generate()
-            except ZeroDivisionError:
-                pass
-            self.assertInLog(handler, lambda record: self.assertEqual(record.args[2:], _error_log(loader, "test.html", 2)))
+        try:
+            loader.load("test.html").generate()
+        except ZeroDivisionError:
+            self.assertTrue("# test.html:2" in traceback.format_exc())
 
     def test_error_line_number_module(self):
         loader = DictLoader({
             "base.html": "{% module Template('sub.html') %}",
             "sub.html": "{{1/0}}",
         }, namespace={"_modules": ObjectDict({"Template": lambda path, **kwargs: loader.load(path).generate(**kwargs)})})
-        with LogCaptureHandler() as handler:
-            try:
-                loader.load("base.html").generate()
-            except ZeroDivisionError:
-                pass
-            self.assertInLog(handler, lambda record: self.assertEqual(record.args[0], "base.html") and
-                                self.assertEqual(record.args[2], "sub.html") and
-                                self.assertEqual(record.args[4:],
-                                    _error_log(loader, "base.html", 1) +
-                                    _error_log(loader, "sub.html", 1)))
+        try:
+            loader.load("base.html").generate()
+        except ZeroDivisionError:
+            exc_stack = traceback.format_exc()
+            self.assertTrue('# base.html:1' in exc_stack)
+            self.assertTrue('# sub.html:1' in exc_stack)
 
     def test_error_line_number_include(self):
         loader = DictLoader({
             "base.html": "{% include 'sub.html' %}",
             "sub.html": "{{1/0}}",
         })
-        with LogCaptureHandler() as handler:
-            try:
-                loader.load("base.html").generate()
-            except ZeroDivisionError:
-                pass
-            self.assertInLog(handler, lambda record: self.assertEqual(record.args[2:],
-                                _error_log(loader, "base.html", 1) +
-                                _error_log(loader, "sub.html", 1)))
+        try:
+            loader.load("base.html").generate()
+        except ZeroDivisionError:
+            self.assertTrue("# sub.html:1 (via base.html:1)" in
+                            traceback.format_exc())
 
     def test_error_line_number_extends_base_error(self):
         loader = DictLoader({
             "base.html": "{{1/0}}",
             "sub.html": "{% extends 'base.html' %}",
         })
-        with LogCaptureHandler() as handler:
-            try:
-                loader.load("sub.html").generate()
-            except ZeroDivisionError:
-                pass
-            self.assertInLog(handler, lambda record: self.assertEqual(record.args[2:],
-                                _error_log(loader, "base.html", 1)))
+        try:
+            loader.load("sub.html").generate()
+        except ZeroDivisionError:
+            exc_stack = traceback.format_exc()
+        self.assertTrue("# base.html:1" in exc_stack)
+
 
     def test_error_line_number_extends_sub_error(self):
         loader = DictLoader({
@@ -172,14 +162,23 @@ three{%end%}
 {{1/0}}
 {% end %}
             """})
-        with LogCaptureHandler() as handler:
-            try:
-                loader.load("sub.html").generate()
-            except ZeroDivisionError:
-                pass
-            self.assertInLog(handler, lambda record: self.assertEqual(record.args[2:],
-                                _error_log(loader, "base.html", 1) +
-                                _error_log(loader, "sub.html", 4)))
+        try:
+            loader.load("sub.html").generate()
+        except ZeroDivisionError:
+            self.assertTrue("# sub.html:4 (via base.html:1)" in
+                            traceback.format_exc())
+
+    def test_multi_includes(self):
+        loader = DictLoader({
+                "a.html": "{% include 'b.html' %}",
+                "b.html": "{% include 'c.html' %}",
+                "c.html": "{{1/0}}",
+                })
+        try:
+            loader.load("a.html").generate()
+        except ZeroDivisionError:
+            self.assertTrue("# c.html:1 (via b.html:1, a.html:1)" in
+                            traceback.format_exc())
 
 
 class AutoEscapeTest(LogTrapTestCase):
diff --git a/tornado/testing.py b/tornado/testing.py
index 019cf3d16..1cbabe599 100644
--- a/tornado/testing.py
+++ b/tornado/testing.py
@@ -301,28 +301,6 @@ class LogTrapTestCase(unittest.TestCase):
         finally:
             handler.stream = old_stream
 
-
-class LogCaptureTestCase(unittest.TestCase):
-    def assertInLog(self, handler, asserts):
-        for record in handler.buffer:
-            try:
-                asserts(record)
-            except AssertionError as err:
-                pass
-            else:
-                return
-        self.fail("No matching record found in log: %s" % handler.prettyPrintBuffer())
-
-    def assertNotInLog(self, handler, asserts):
-        for record in handler.buffer:
-            try:
-                asserts(record)
-            except AssertionError as err:
-                pass
-            else:
-                self.fail("No matching record found in log: %s" % handler.prettyPrintBuffer())
-
-
 def main():
     """A simple test runner.
 
diff --git a/tornado/util.py b/tornado/util.py
index 780307da1..6752401af 100644
--- a/tornado/util.py
+++ b/tornado/util.py
@@ -1,9 +1,5 @@
 """Miscellaneous utility functions."""
 
-from logging.handlers import MemoryHandler
-import json
-import logging
-
 class ObjectDict(dict):
     """Makes a dictionary behave like an object."""
     def __getattr__(self, name):
@@ -16,23 +12,6 @@ class ObjectDict(dict):
         self[name] = value
 
 
-class LogCaptureHandler(MemoryHandler):
-    def __init__(self):
-        MemoryHandler.__init__(self, capacity=0, flushLevel=100)
-        self.logger = logging.getLogger()
-
-    def __enter__(self):
-        self.logger.addHandler(self)
-        return self
-
-    def __exit__(self, type, value, traceback):
-        self.logger.removeHandler(self)
-        self.close()
-
-    def prettyPrintBuffer(self):
-        return json.dumps([record.__dict__ for record in self.buffer], sort_keys=True, indent=4)
-
-
 def import_object(name):
     """Imports an object by name.