Skip to content

Commit

Permalink
A different approach to template stack traces:
Browse files Browse the repository at this point in the history 
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.
  • Loading branch information
@bdarnell
bdarnell committed Dec 7, 2011
1 parent 45ca697 commit 597f70b
Show file tree
Hide file tree
Showing 4 changed files with 80 additions and 137 deletions.
73 changes: 30 additions & 43 deletions tornado/template.py
View file
Expand Up @@ -173,16 +173,15 @@ def add(x, y):

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()
Expand All @@ -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 \
Expand All @@ -207,14 +205,17 @@ def __init__(self, template_string, name="<string>", loader=None,
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)
Expand All @@ -232,39 +233,25 @@ def generate(self, **kwargs):
"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()
Expand All @@ -279,7 +266,7 @@ def _generate_python(self, loader, compress_whitespace):
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()

Expand Down Expand Up @@ -580,8 +567,6 @@ def __init__(self, file, named_blocks, loader, 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_size(self):
Expand All @@ -600,7 +585,7 @@ def __exit__(_, *args):
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):
Expand All @@ -615,17 +600,19 @@ def __exit__(_, *args):
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):
Expand Down
101 changes: 50 additions & 51 deletions tornado/test/template_test.py
View file
@@ -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"),
Expand Down Expand Up @@ -96,72 +97,61 @@ def test_comment(self):
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({
Expand All @@ -172,14 +162,23 @@ def test_error_line_number_extends_sub_error(self):
{{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):
Expand Down
22 changes: 0 additions & 22 deletions tornado/testing.py
View file
Expand Up @@ -301,28 +301,6 @@ def run(self, result=None):
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.
Expand Down
21 changes: 0 additions & 21 deletions tornado/util.py
View file
@@ -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):
Expand All @@ -16,23 +12,6 @@ def __setattr__(self, name, value):
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.
Expand Down

0 comments on commit 597f70b

Please sign in to comment.