From d03e60d0aac4afc33862344908e3e3b833747a72 Mon Sep 17 00:00:00 2001
From: Alek Storm <alek.storm@gmail.com>
Date: Thu, 22 Sep 2011 02:41:37 +0000
Subject: [PATCH] Print only the template trace of the bottommost UI module
 call, move testing.LogHandler to util.LogCaptureHandler, and rename
 testing.LogTestCase to testing.LogCaptureTestCase

---
 tornado/template.py           | 34 ++++++++++++++---------
 tornado/test/template_test.py | 51 ++++++++++++++++++-----------------
 tornado/testing.py            | 21 +--------------
 tornado/util.py               | 21 +++++++++++++++
 4 files changed, 71 insertions(+), 56 deletions(-)

diff --git a/tornado/template.py b/tornado/template.py
index bc131fb17..5d8993ba2 100644
--- a/tornado/template.py
+++ b/tornado/template.py
@@ -239,21 +239,31 @@ class Template(object):
         try:
             return execute()
         except Exception:
-            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)
+            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]]
-                        for file, line_number in template.line_numbers[cur_line_number]:
-                            error_msg += "%s:%i:%s\n"
+                        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")
-                            error_args.extend([file.name, line_number, lines[line_number-1]])
-            logging.error(error_msg, *error_args)
-            raise
+                            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
 
     def _generate_python(self, loader, compress_whitespace):
         buffer = cStringIO.StringIO()
diff --git a/tornado/test/template_test.py b/tornado/test/template_test.py
index f5667ace0..a48dd6884 100644
--- a/tornado/test/template_test.py
+++ b/tornado/test/template_test.py
@@ -1,11 +1,12 @@
-import logging
-
 from tornado.escape import utf8, native_str
 from tornado.template import Template, DictLoader, ParseError
-from tornado.testing import LogHandler, LogTestCase, LogTrapTestCase
-from tornado.util import b, bytes_type, ObjectDict
+from tornado.testing import LogCaptureTestCase, LogTrapTestCase
+from tornado.util import b, bytes_type, ObjectDict, LogCaptureHandler
+
+def _error_log(loader, name, line_number):
+    return (name, line_number, loader.templates[name].template_string.split('\n')[line_number-1])
 
-class TemplateTest(LogTrapTestCase, LogTestCase):
+class TemplateTest(LogTrapTestCase, LogCaptureTestCase):
     def test_simple(self):
         template = Template("Hello {{ name }}!")
         self.assertEqual(template.generate(name="Ben"),
@@ -100,65 +101,67 @@ class TemplateTest(LogTrapTestCase, LogTestCase):
 two{{1/0}}
 three
         """})
-        with LogHandler() as handler:
+        with LogCaptureHandler() 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}}")))
+            self.assertInLog(handler, lambda record: self.assertEqual(record.args[2:], _error_log(loader, "test.html", 2)))
 
     def test_error_line_number_directive(self):
         loader = DictLoader({"test.html": """one
 two{%if 1/0%}
 three{%end%}
         """})
-        with LogHandler() as handler:
+        with LogCaptureHandler() 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%}")))
+            self.assertInLog(handler, lambda record: self.assertEqual(record.args[2:], _error_log(loader, "test.html", 2)))
 
     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:
+        with LogCaptureHandler() 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}}")))
+            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)))
 
     def test_error_line_number_include(self):
         loader = DictLoader({
             "base.html": "{% include 'sub.html' %}",
             "sub.html": "{{1/0}}",
         })
-        with LogHandler() as handler:
+        with LogCaptureHandler() 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}}")))
+            self.assertInLog(handler, lambda record: self.assertEqual(record.args[2:],
+                                _error_log(loader, "base.html", 1) +
+                                _error_log(loader, "sub.html", 1)))
 
     def test_error_line_number_extends_base_error(self):
         loader = DictLoader({
             "base.html": "{{1/0}}",
             "sub.html": "{% extends 'base.html' %}",
         })
-        with LogHandler() as handler:
+        with LogCaptureHandler() 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}}")))
+            self.assertInLog(handler, lambda record: self.assertEqual(record.args[2:],
+                                _error_log(loader, "base.html", 1)))
 
     def test_error_line_number_extends_sub_error(self):
         loader = DictLoader({
@@ -169,14 +172,14 @@ three{%end%}
 {{1/0}}
 {% end %}
             """})
-        with LogHandler() as handler:
+        with LogCaptureHandler() 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}}")))
+            self.assertInLog(handler, lambda record: self.assertEqual(record.args[2:],
+                                _error_log(loader, "base.html", 1) +
+                                _error_log(loader, "sub.html", 4)))
 
 
 class AutoEscapeTest(LogTrapTestCase):
diff --git a/tornado/testing.py b/tornado/testing.py
index d2ea08c62..212cd312a 100644
--- a/tornado/testing.py
+++ b/tornado/testing.py
@@ -21,12 +21,10 @@ 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
@@ -297,7 +295,7 @@ class LogTrapTestCase(unittest.TestCase):
             handler.stream = old_stream
 
 
-class LogTestCase(unittest.TestCase):
+class LogCaptureTestCase(unittest.TestCase):
     def assertInLog(self, handler, asserts):
         for record in handler.buffer:
             try:
@@ -318,23 +316,6 @@ class LogTestCase(unittest.TestCase):
                 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.
 
diff --git a/tornado/util.py b/tornado/util.py
index 6752401af..780307da1 100644
--- a/tornado/util.py
+++ b/tornado/util.py
@@ -1,5 +1,9 @@
 """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):
@@ -12,6 +16,23 @@ 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.
 
-- 
2.47.2