Fixed after_request handlers being called twice in some cases and improved logging system

CHANGES

@@ -16,6 +16,8 @@ Release date to be announced, codename to be selected.
 - test client has not the ability to preserve the request context
   for a little longer.  This can also be used to trigger custom
   requests that do not pop the request stack for testing.
+- because the Python standard library caches loggers, the name of
+  the logger is configurable now to better support unittests.
 
 Version 0.3.1
 -------------

flask.py

@@ -16,6 +16,7 @@ import mimetypes
 from datetime import datetime, timedelta
 
 from itertools import chain
+from threading import Lock
 from jinja2 import Environment, PackageLoader, FileSystemLoader
 from werkzeug import Request as RequestBase, Response as ResponseBase, \
      LocalStack, LocalProxy, create_environ, SharedDataMiddleware, \
@@ -50,6 +51,9 @@ try:
 except (ImportError, AttributeError):
     pkg_resources = None
 
+# a lock used for logger initialization
+_logger_lock = Lock()
+
 
 class Request(RequestBase):
     """The request object used by default in flask.  Remembers the
@@ -839,6 +843,12 @@ class Flask(_PackageBoundObject):
     #: `USE_X_SENDFILE` configuration key.  Defaults to `False`.
     use_x_sendfile = ConfigAttribute('USE_X_SENDFILE')
 
+    #: the name of the logger to use.  By default the logger name is the
+    #: package name passed to the constructor.
+    #:
+    #: .. versionadded:: 0.4
+    logger_name = ConfigAttribute('LOGGER_NAME')
+
     #: the logging format used for the debug logger.  This is only used when
     #: the application is in debug mode, otherwise the attached logging
     #: handler does the formatting.
@@ -863,7 +873,8 @@ class Flask(_PackageBoundObject):
         'SECRET_KEY':                           None,
         'SESSION_COOKIE_NAME':                  'session',
         'PERMANENT_SESSION_LIFETIME':           timedelta(days=31),
-        'USE_X_SENDFILE':                       False
+        'USE_X_SENDFILE':                       False,
+        'LOGGER_NAME':                          None
     })
 
     def __init__(self, import_name):
@@ -874,6 +885,10 @@ class Flask(_PackageBoundObject):
         #: to load a config from files.
         self.config = Config(self.root_path, self.default_config)
 
+        #: prepare the deferred setup of the logger
+        self._logger = None
+        self.logger_name = self.import_name
+
         #: a dictionary of all view functions registered.  The keys will
         #: be function names which are also used to generate URLs and
         #: the values are the function objects themselves.
@@ -952,7 +967,7 @@ class Flask(_PackageBoundObject):
         )
         self.jinja_env.filters['tojson'] = _tojson_filter
 
-    @cached_property
+    @property
     def logger(self):
         """A :class:`logging.Logger` object for this application.  The
         default configuration is to log to stderr if the application is
@@ -965,17 +980,23 @@ class Flask(_PackageBoundObject):
 
         .. versionadded:: 0.3
         """
-        from logging import getLogger, StreamHandler, Formatter, DEBUG
+        if self._logger and self._logger.name == self.logger_name:
-        class DebugHandler(StreamHandler):
+            return self._logger
-            def emit(x, record):
+        with _logger_lock:
-                if self.debug:
+            if self._logger and self._logger.name == self.logger_name:
-                    StreamHandler.emit(x, record)
+                return self._logger
-        handler = DebugHandler()
+            from logging import getLogger, StreamHandler, Formatter, DEBUG
-        handler.setLevel(DEBUG)
+            class DebugHandler(StreamHandler):
-        handler.setFormatter(Formatter(self.debug_log_format))
+                def emit(x, record):
-        logger = getLogger(self.import_name)
+                    if self.debug:
-        logger.addHandler(handler)
+                        StreamHandler.emit(x, record)
-        return logger
+            handler = DebugHandler()
+            handler.setLevel(DEBUG)
+            handler.setFormatter(Formatter(self.debug_log_format))
+            logger = getLogger(self.logger_name)
+            logger.addHandler(handler)
+            self._logger = logger
+            return logger
 
     def create_jinja_loader(self):
         """Creates the Jinja loader.  By default just a package loader for
@@ -1412,16 +1433,12 @@ class Flask(_PackageBoundObject):
                 if rv is None:
                     rv = self.dispatch_request()
                 response = self.make_response(rv)
+            except Exception, e:
+                response = self.make_response(self.handle_exception(e))
+            try:
                 response = self.process_response(response)
             except Exception, e:
                 response = self.make_response(self.handle_exception(e))
-                try:
-                    response = self.process_response(response)
-                except Exception, e:
-                    self.logger.exception('after_request handler failed '
-                                          'to postprocess error response. '
-                                          'Depending on uncertain state?')
-
             return response(environ, start_response)
 
     def request_context(self, environ):

tests/flask_tests.py

@@ -288,11 +288,11 @@ class BasicFunctionalityTestCase(unittest.TestCase):
         assert len(called) == 1
 
     def test_after_request_handler_error(self):
-        error_out = StringIO()
+        called = []
         app = flask.Flask(__name__)
-        app.logger.addHandler(StreamHandler(error_out))
         @app.after_request
         def after_request(response):
+            called.append(True)
             1/0
             return response
         @app.route('/')
@@ -301,7 +301,7 @@ class BasicFunctionalityTestCase(unittest.TestCase):
         rv = app.test_client().get('/')
         assert rv.status_code == 500
         assert 'Internal Server Error' in rv.data
-        assert 'after_request handler failed' in error_out.getvalue()
+        assert len(called) == 1
 
     def test_error_handling(self):
         app = flask.Flask(__name__)
@@ -707,6 +707,14 @@ class SendfileTestCase(unittest.TestCase):
 
 class LoggingTestCase(unittest.TestCase):
 
+    def test_logger_cache(self):
+        app = flask.Flask(__name__)
+        logger1 = app.logger
+        assert app.logger is logger1
+        assert logger1.name == __name__
+        app.logger_name = __name__ + '/test_logger_cache'
+        assert app.logger is not logger1
+
     def test_debug_log(self):
         app = flask.Flask(__name__)
         app.debug = True
@@ -736,9 +744,9 @@ class LoggingTestCase(unittest.TestCase):
                 assert False, 'debug log ate the exception'
 
     def test_exception_logging(self):
-        from logging import StreamHandler
         out = StringIO()
         app = flask.Flask(__name__)
+        app.logger_name = 'flask_tests/test_exception_logging'
         app.logger.addHandler(StreamHandler(out))
 
         @app.route('/')