From: Alek Storm <alek.storm@gmail.com>
Date: Mon, 12 Sep 2011 18:18:35 +0000 (+0000)
Subject: Log "stacktrace" of templace source lines when an exception is raised for more conven... 
X-Git-Tag: v2.2.0~71^2~1
X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=abcac64c377c2af47d54ef03fb216694fff34fca;p=thirdparty%2Ftornado.git

Log "stacktrace" of templace source lines when an exception is raised for more convenient debugging
---

diff --git a/tornado/template.py b/tornado/template.py
index f28f40355..bc131fb17 100644
--- a/tornado/template.py
+++ b/tornado/template.py
@@ -177,6 +177,8 @@ import logging
 import os.path
 import posixpath
 import re
+import sys
+import traceback
 
 from tornado import escape
 from tornado.util import bytes_type
@@ -192,6 +194,7 @@ 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 \
@@ -203,13 +206,14 @@ class Template(object):
         else:
             self.autoescape = _DEFAULT_AUTOESCAPE
         self.namespace = loader.namespace if loader else {}
-        reader = _TemplateReader(name, escape.native_str(template_string))
-        self.file = _File(_parse(reader, self))
-        self.code = self._generate_python(loader, compress_whitespace)
+        reader = _TemplateReader(name, escape.native_str(self.template_string))
+        self.file = _File(self, _parse(reader, self))
+        self.code, self.line_numbers = self._generate_python(
+                                                  loader, compress_whitespace)
+        self.loader = loader
         try:
             self.compiled = compile(escape.to_unicode(self.code),
-                                    "<template %s>" % self.name,
-                                    "exec")
+                                    "<template %s>" % self.name, "exec")
         except Exception:
             formatted_code = _format_code(self.code).rstrip()
             logging.error("%s code:\n%s", self.name, formatted_code)
@@ -235,8 +239,20 @@ class Template(object):
         try:
             return execute()
         except Exception:
-            formatted_code = _format_code(self.code).rstrip()
-            logging.error("%s code:\n%s", self.name, formatted_code)
+            error_msg = "\n%s\n\n"
+            error_args = [_format_code(self.code).rstrip()]
+            if self.loader:
+                frames = traceback.extract_tb(sys.exc_info()[2])
+                line_number = None
+                for filename, cur_line_number, function, text in frames:
+                    match = re.match(r"\<template ([^\>]+)\>", filename)
+                    if match:
+                        template = self.loader.templates[match.groups()[0]]
+                        for file, line_number in template.line_numbers[cur_line_number]:
+                            error_msg += "%s:%i:%s\n"
+                            lines = self.loader.templates[file.name].template_string.split("\n")
+                            error_args.extend([file.name, line_number, lines[line_number-1]])
+            logging.error(error_msg, *error_args)
             raise
 
     def _generate_python(self, loader, compress_whitespace):
@@ -249,10 +265,10 @@ class Template(object):
             for ancestor in ancestors:
                 ancestor.find_named_blocks(loader, named_blocks)
             self.file.find_named_blocks(loader, named_blocks)
-            writer = _CodeWriter(buffer, named_blocks, loader, self,
+            writer = _CodeWriter(buffer, named_blocks, loader, ancestors[0].template,
                                  compress_whitespace)
             ancestors[0].generate(writer)
-            return buffer.getvalue()
+            return buffer.getvalue(), writer.line_numbers
         finally:
             buffer.close()
 
@@ -362,16 +378,18 @@ class _Node(object):
 
 
 class _File(_Node):
-    def __init__(self, body):
+    def __init__(self, template, body):
+        self.template = template
         self.body = body
+        self.line = 0
 
     def generate(self, writer):
-        writer.write_line("def _execute():")
+        writer.write_line("def _execute():", self.line)
         with writer.indent():
-            writer.write_line("_buffer = []")
-            writer.write_line("_append = _buffer.append")
+            writer.write_line("_buffer = []", self.line)
+            writer.write_line("_append = _buffer.append", self.line)
             self.body.generate(writer)
-            writer.write_line("return _utf8('').join(_buffer)")
+            writer.write_line("return _utf8('').join(_buffer)", self.line)
 
     def each_child(self):
         return (self.body,)
@@ -391,20 +409,19 @@ class _ChunkList(_Node):
 
 
 class _NamedBlock(_Node):
-    def __init__(self, name, body, template):
+    def __init__(self, name, body, template, line):
         self.name = name
         self.body = body
         self.template = template
+        self.line = line
 
     def each_child(self):
         return (self.body,)
 
     def generate(self, writer):
         block = writer.named_blocks[self.name]
-        old = writer.current_template
-        writer.current_template = block.template
-        block.body.generate(writer)
-        writer.current_template = old
+        with writer.include(block.template, self.line):
+            block.body.generate(writer)
 
     def find_named_blocks(self, loader, named_blocks):
         named_blocks[self.name] = self
@@ -417,9 +434,10 @@ class _ExtendsBlock(_Node):
 
 
 class _IncludeBlock(_Node):
-    def __init__(self, name, reader):
+    def __init__(self, name, reader, line):
         self.name = name
         self.template_name = reader.name
+        self.line = line
 
     def find_named_blocks(self, loader, named_blocks):
         included = loader.load(self.name, self.template_name)
@@ -427,15 +445,14 @@ class _IncludeBlock(_Node):
 
     def generate(self, writer):
         included = writer.loader.load(self.name, self.template_name)
-        old = writer.current_template
-        writer.current_template = included
-        included.file.body.generate(writer)
-        writer.current_template = old
+        with writer.include(included, self.line):
+            included.file.body.generate(writer)
 
 
 class _ApplyBlock(_Node):
-    def __init__(self, method, body=None):
+    def __init__(self, method, line, body=None):
         self.method = method
+        self.line = line
         self.body = body
 
     def each_child(self):
@@ -444,71 +461,76 @@ class _ApplyBlock(_Node):
     def generate(self, writer):
         method_name = "apply%d" % writer.apply_counter
         writer.apply_counter += 1
-        writer.write_line("def %s():" % method_name)
+        writer.write_line("def %s():" % method_name, self.line)
         with writer.indent():
-            writer.write_line("_buffer = []")
-            writer.write_line("_append = _buffer.append")
+            writer.write_line("_buffer = []", self.line)
+            writer.write_line("_append = _buffer.append", self.line)
             self.body.generate(writer)
-            writer.write_line("return _utf8('').join(_buffer)")
+            writer.write_line("return _utf8('').join(_buffer)", self.line)
         writer.write_line("_append(%s(%s()))" % (
-            self.method, method_name))
+            self.method, method_name), self.line)
 
 
 class _ControlBlock(_Node):
-    def __init__(self, statement, body=None):
+    def __init__(self, statement, line, body=None):
         self.statement = statement
+        self.line = line
         self.body = body
 
     def each_child(self):
         return (self.body,)
 
     def generate(self, writer):
-        writer.write_line("%s:" % self.statement)
+        writer.write_line("%s:" % self.statement, self.line)
         with writer.indent():
             self.body.generate(writer)
 
 
 class _IntermediateControlBlock(_Node):
-    def __init__(self, statement):
+    def __init__(self, statement, line):
         self.statement = statement
+        self.line = line
 
     def generate(self, writer):
-        writer.write_line("%s:" % self.statement, writer.indent_size() - 1)
+        writer.write_line("%s:" % self.statement, self.line, writer.indent_size() - 1)
 
 
 class _Statement(_Node):
-    def __init__(self, statement):
+    def __init__(self, statement, line):
         self.statement = statement
+        self.line = line
 
     def generate(self, writer):
-        writer.write_line(self.statement)
+        writer.write_line(self.statement, self.line)
 
 
 class _Expression(_Node):
-    def __init__(self, expression, raw=False):
+    def __init__(self, expression, line, raw=False):
         self.expression = expression
+        self.line = line
         self.raw = raw
 
     def generate(self, writer):
-        writer.write_line("_tmp = %s" % self.expression)
+        writer.write_line("_tmp = %s" % self.expression, self.line)
         writer.write_line("if isinstance(_tmp, _string_types):"
-                          " _tmp = _utf8(_tmp)")
-        writer.write_line("else: _tmp = _utf8(str(_tmp))")
+                          " _tmp = _utf8(_tmp)", self.line)
+        writer.write_line("else: _tmp = _utf8(str(_tmp))", self.line)
         if not self.raw and writer.current_template.autoescape is not None:
             # In python3 functions like xhtml_escape return unicode,
             # so we have to convert to utf8 again.
             writer.write_line("_tmp = _utf8(%s(_tmp))" %
-                              writer.current_template.autoescape)
-        writer.write_line("_append(_tmp)")
+                              writer.current_template.autoescape, self.line)
+        writer.write_line("_append(_tmp)", self.line)
 
 class _Module(_Expression):
-    def __init__(self, expression):
-        super(_Module, self).__init__("_modules." + expression,
+    def __init__(self, expression, line):
+        super(_Module, self).__init__("_modules." + expression, line,
                                       raw=True)
 
 class _Text(_Node):
-    def __init__(self, value):
+    def __init__(self, value, line):
         self.value = value
+        self.line = line
 
     def generate(self, writer):
         value = self.value
@@ -521,7 +543,7 @@ class _Text(_Node):
             value = re.sub(r"(\s*\n\s*)", "\n", value)
 
         if value:
-            writer.write_line('_append(%r)' % escape.utf8(value))
+            writer.write_line('_append(%r)' % escape.utf8(value), self.line)
 
 
 class ParseError(Exception):
@@ -538,28 +560,46 @@ class _CodeWriter(object):
         self.current_template = current_template
         self.compress_whitespace = compress_whitespace
         self.apply_counter = 0
+        self.include_stack = []
+        self.line_numbers = {}
+        self._current_line = 1
         self._indent = 0
 
-    def indent(self):
-        return self
-
     def indent_size(self):
         return self._indent
 
-    def __enter__(self):
-        self._indent += 1
-        return self
+    def indent(self):
+        class Indenter(object):
+            def __enter__(_):
+                self._indent += 1
+                return self
+
+            def __exit__(_, *args):
+                assert self._indent > 0
+                self._indent -= 1
+
+        return Indenter()
+
+    def include(self, template, line):
+        self.include_stack.append((self.current_template, line+1))
+        self.current_template = template
 
-    def __exit__(self, *args):
-        assert self._indent > 0
-        self._indent -= 1
+        class IncludeTemplate(object):
+            def __enter__(_):
+                return self
 
-    def write_line(self, line, indent=None):
+            def __exit__(_, *args):
+                self.current_template = self.include_stack.pop()[0]
+
+        return IncludeTemplate()
+
+    def write_line(self, line, line_number, indent=None):
         if indent == None:
             indent = self._indent
-        for i in xrange(indent):
-            self.file.write("    ")
-        print >> self.file, line
+        print >> self.file, "    "*indent + line
+
+        self.line_numbers[self._current_line] = self.include_stack[:]+[(self.current_template, line_number+1)]
+        self._current_line += 1
 
 
 class _TemplateReader(object):
@@ -633,7 +673,7 @@ def _parse(reader, template, in_block=None):
                 if in_block:
                     raise ParseError("Missing {%% end %%} block for %s" %
                                      in_block)
-                body.chunks.append(_Text(reader.consume()))
+                body.chunks.append(_Text(reader.consume(), reader.line))
                 return body
             # If the first curly brace is not the start of a special token,
             # start searching from the character after it
@@ -651,7 +691,8 @@ def _parse(reader, template, in_block=None):
 
         # Append any text before the special token
         if curly > 0:
-            body.chunks.append(_Text(reader.consume(curly)))
+            cons = reader.consume(curly)
+            body.chunks.append(_Text(cons, reader.line))
 
         start_brace = reader.consume(2)
         line = reader.line
@@ -662,7 +703,7 @@ def _parse(reader, template, in_block=None):
         # which also use double braces.
         if reader.remaining() and reader[0] == "!":
             reader.consume(1)
-            body.chunks.append(_Text(start_brace))
+            body.chunks.append(_Text(start_brace, line))
             continue
 
         # Expression
@@ -674,7 +715,7 @@ def _parse(reader, template, in_block=None):
             reader.consume(2)
             if not contents:
                 raise ParseError("Empty expression on line %d" % line)
-            body.chunks.append(_Expression(contents))
+            body.chunks.append(_Expression(contents, line))
             continue
 
         # Block
@@ -704,7 +745,7 @@ def _parse(reader, template, in_block=None):
                             (operator, allowed_parents))
             if in_block not in allowed_parents:
                 raise ParseError("%s block cannot be attached to %s block" % (operator, in_block))
-            body.chunks.append(_IntermediateControlBlock(contents))
+            body.chunks.append(_IntermediateControlBlock(contents, line))
             continue
 
         # End tag
@@ -725,25 +766,25 @@ def _parse(reader, template, in_block=None):
             elif operator in ("import", "from"):
                 if not suffix:
                     raise ParseError("import missing statement on line %d" % line)
-                block = _Statement(contents)
+                block = _Statement(contents, line)
             elif operator == "include":
                 suffix = suffix.strip('"').strip("'")
                 if not suffix:
                     raise ParseError("include missing file path on line %d" % line)
-                block = _IncludeBlock(suffix, reader)
+                block = _IncludeBlock(suffix, reader, line)
             elif operator == "set":
                 if not suffix:
                     raise ParseError("set missing statement on line %d" % line)
-                block = _Statement(suffix)
+                block = _Statement(suffix, line)
             elif operator == "autoescape":
                 fn = suffix.strip()
                 if fn == "None": fn = None
                 template.autoescape = fn
                 continue
             elif operator == "raw":
-                block = _Expression(suffix, raw=True)
+                block = _Expression(suffix, line, raw=True)
             elif operator == "module":
-                block = _Module(suffix)
+                block = _Module(suffix, line)
             body.chunks.append(block)
             continue
 
@@ -753,13 +794,13 @@ def _parse(reader, template, in_block=None):
             if operator == "apply":
                 if not suffix:
                     raise ParseError("apply missing method name on line %d" % line)
-                block = _ApplyBlock(suffix, block_body)
+                block = _ApplyBlock(suffix, line, block_body)
             elif operator == "block":
                 if not suffix:
                     raise ParseError("block missing name on line %d" % line)
-                block = _NamedBlock(suffix, block_body, template)
+                block = _NamedBlock(suffix, block_body, template, line)
             else:
-                block = _ControlBlock(contents, block_body)
+                block = _ControlBlock(contents, line, block_body)
             body.chunks.append(block)
             continue
 
diff --git a/tornado/test/template_test.py b/tornado/test/template_test.py
index 0d5fad9ee..f5667ace0 100644
--- a/tornado/test/template_test.py
+++ b/tornado/test/template_test.py
@@ -1,9 +1,11 @@
+import logging
+
 from tornado.escape import utf8, native_str
 from tornado.template import Template, DictLoader, ParseError
-from tornado.testing import LogTrapTestCase
-from tornado.util import b, bytes_type
+from tornado.testing import LogHandler, LogTestCase, LogTrapTestCase
+from tornado.util import b, bytes_type, ObjectDict
 
-class TemplateTest(LogTrapTestCase):
+class TemplateTest(LogTrapTestCase, LogTestCase):
     def test_simple(self):
         template = Template("Hello {{ name }}!")
         self.assertEqual(template.generate(name="Ben"),
@@ -93,6 +95,89 @@ class TemplateTest(LogTrapTestCase):
         template = Template(utf8("{% comment blah blah %}foo"))
         self.assertEqual(template.generate(), b("foo"))
 
+    def test_error_line_number_expression(self):
+        loader = DictLoader({"test.html": """one
+two{{1/0}}
+three
+        """})
+        with LogHandler() as handler:
+            try:
+                loader.load("test.html").generate()
+            except ZeroDivisionError:
+                pass
+            self.assertInLog(handler, lambda record: self.assertEqual(record.args[1:], ("test.html", 2, "two{{1/0}}")))
+
+    def test_error_line_number_directive(self):
+        loader = DictLoader({"test.html": """one
+two{%if 1/0%}
+three{%end%}
+        """})
+        with LogHandler() as handler:
+            try:
+                loader.load("test.html").generate()
+            except ZeroDivisionError:
+                pass
+            self.assertInLog(handler, lambda record: self.assertEqual(record.args[1:], ("test.html", 2, "two{%if 1/0%}")))
+
+    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 LogHandler() as handler:
+            try:
+                loader.load("base.html").generate()
+            except ZeroDivisionError:
+                pass
+            self.assertInLog(handler, lambda record: self.assertEqual(record.args[1:],
+                                ("base.html", 1, "{% module Template('sub.html') %}",
+                                 "sub.html", 1, "{{1/0}}")))
+
+    def test_error_line_number_include(self):
+        loader = DictLoader({
+            "base.html": "{% include 'sub.html' %}",
+            "sub.html": "{{1/0}}",
+        })
+        with LogHandler() as handler:
+            try:
+                loader.load("base.html").generate()
+            except ZeroDivisionError:
+                pass
+            self.assertInLog(handler, lambda record: self.assertEqual(record.args[1:],
+                                ("base.html", 1, "{% include 'sub.html' %}",
+                                 "sub.html", 1, "{{1/0}}")))
+
+    def test_error_line_number_extends_base_error(self):
+        loader = DictLoader({
+            "base.html": "{{1/0}}",
+            "sub.html": "{% extends 'base.html' %}",
+        })
+        with LogHandler() as handler:
+            try:
+                loader.load("sub.html").generate()
+            except ZeroDivisionError:
+                pass
+            self.assertInLog(handler, lambda record: self.assertEqual(record.args[1:],
+                                ("base.html", 1, "{{1/0}}")))
+
+    def test_error_line_number_extends_sub_error(self):
+        loader = DictLoader({
+            "base.html": "{% block 'block' %}{% end %}",
+            "sub.html": """
+{% extends 'base.html' %}
+{% block 'block' %}
+{{1/0}}
+{% end %}
+            """})
+        with LogHandler() as handler:
+            try:
+                loader.load("sub.html").generate()
+            except ZeroDivisionError:
+                pass
+            self.assertInLog(handler, lambda record: self.assertEqual(record.args[1:],
+                                ("base.html", 1, "{% block 'block' %}{% end %}",
+                                 "sub.html", 4, "{{1/0}}")))
+
 
 class AutoEscapeTest(LogTrapTestCase):
     def setUp(self):
diff --git a/tornado/testing.py b/tornado/testing.py
index 0ad5bff4c..d2ea08c62 100644
--- a/tornado/testing.py
+++ b/tornado/testing.py
@@ -21,10 +21,12 @@ information.
 from __future__ import with_statement
 
 from cStringIO import StringIO
+from logging.handlers import MemoryHandler
 from tornado.httpclient import AsyncHTTPClient
 from tornado.httpserver import HTTPServer
 from tornado.stack_context import StackContext, NullContext
 import contextlib
+import json
 import logging
 import sys
 import time
@@ -294,6 +296,45 @@ class LogTrapTestCase(unittest.TestCase):
         finally:
             handler.stream = old_stream
 
+
+class LogTestCase(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())
+
+
+class LogHandler(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 main():
     """A simple test runner.