From ea5e654e9e19aab5089f9a71e679bcca11581e86 Mon Sep 17 00:00:00 2001
From: Armin Ronacher <armin.ronacher@active-4.com>
Date: Mon, 17 May 2010 22:46:35 +0200
Subject: [PATCH] Added a documentation chapter about logging

---
 docs/_templates/sidebarintro.html |   5 +-
 docs/_themes                      |   2 +-
 docs/conf.py                      |   2 +
 docs/contents.rst.inc             |   1 +
 docs/errorhandling.rst            | 232 ++++++++++++++++++++++++++++++
 docs/patterns/fileuploads.rst     |   2 +
 docs/quickstart.rst               |  28 ++++
 flask.py                          |  24 ++--
 tests/flask_tests.py              |  22 +++
 9 files changed, 307 insertions(+), 11 deletions(-)
 create mode 100644 docs/errorhandling.rst

diff --git a/docs/_templates/sidebarintro.html b/docs/_templates/sidebarintro.html
index c281d3a9..f2aecc74 100644
--- a/docs/_templates/sidebarintro.html
+++ b/docs/_templates/sidebarintro.html
@@ -5,7 +5,10 @@
   not stable yet, but if you have some feedback,
   <a href="mailto:armin.ronacher@active-4.com">let me know</a>.
 </p>
-<h3>Download Documentation</h3>
+<h3>Other Formats</h3>
+<p>
+  You can download the documentation in other formats as well:
+</p>
 <ul>
   <li><a href="http://flask.pocoo.org/docs/flask-docs.pdf">as PDF</a>
   <li><a href="http://flask.pocoo.org/docs/flask-docs.zip">as zipped HTML</a>
diff --git a/docs/_themes b/docs/_themes
index 11cb6b51..991997d6 160000
--- a/docs/_themes
+++ b/docs/_themes
@@ -1 +1 @@
-Subproject commit 11cb6b51c9ea3bc8f94afa3d7411b617f9db2570
+Subproject commit 991997d6d63a0cdcf7f4557a2dae5afa9b38b904
diff --git a/docs/conf.py b/docs/conf.py
index 2048ab6e..b4731fff 100644
--- a/docs/conf.py
+++ b/docs/conf.py
@@ -50,6 +50,8 @@ import pkg_resources
 # built documents.
 release = __import__('pkg_resources').get_distribution('Flask').version
 version = '.'.join(release.split('.')[:2])
+if 'dev' in version:
+    version = version.split('dev')[0]
 
 # The language for content autogenerated by Sphinx. Refer to documentation
 # for a list of supported languages.
diff --git a/docs/contents.rst.inc b/docs/contents.rst.inc
index 1e9e7df9..2e341107 100644
--- a/docs/contents.rst.inc
+++ b/docs/contents.rst.inc
@@ -13,6 +13,7 @@ web development.
    quickstart
    tutorial/index
    testing
+   errorhandling
    patterns/index
    deploying/index
    becomingbig
diff --git a/docs/errorhandling.rst b/docs/errorhandling.rst
new file mode 100644
index 00000000..c83acbc7
--- /dev/null
+++ b/docs/errorhandling.rst
@@ -0,0 +1,232 @@
+Handling Application Errors
+===========================
+
+.. versionadded:: 0.5
+
+Applications fail, server fail.  Sooner or later you will see an exception
+in production.  Even if your code is 100% correct, you will still see
+exceptions from time to time.  Why?  Because everything else involved will
+fail.  Here some situations where perfectly fine code can lead to server
+errors:
+
+-   the client terminated the request early and the application was still
+    reading from the incoming data.
+-   the database server was overloaded and could not handle the query.
+-   a filesystem is full
+-   a harddrive crashed
+-   a backend server overloaded
+-   a programming error in a library you are using
+-   network connection of the server to another system failed.
+
+And that's just a small sample of issues you could be facing.  So how to
+deal with that sort of problem?  By default if your application runs in
+production mode, Flask will display a very simple page for you and log the
+exception to the :attr:`~flask.Flask.logger`.
+
+But there is more you can do, and we will cover some better setups to deal
+with errors.
+
+Error Mails
+-----------
+
+If the application runs in production mode (which it will do on your
+server) you won't see any log messages by default.  Why that?  Flask tries
+to be a zero-configuration framework and where should it drop the logs for
+you if there is no configuration.  Guessing is not a good idea because
+changes are, the place it guessed is not the place where the user has the
+permission to create a logfile.  Also, for most small applications nobody
+will look at the logs anyways.
+
+In fact, I promise you right now that if you configure a logfile for the
+application errors you will never look at it except for debugging an issue
+when a user reported it for you.  What you want instead is a mail the
+second the exception happened.  Then you get an alert and you can do
+something about it.
+
+Flask is using the Python builtin logging system and that one can actually
+send you mails for errors which is probably what you want.  Here is how
+you can configure the Flask logger to send you mails for exceptions::
+
+    ADMINS = ['yourname@example.com']
+    if not app.debug:
+        import logging
+        from logging.handlers import SMTPHandler
+        mail_handler = SMTPHandler('127.0.0.1',
+                                   'server-error@example.com',
+                                   ADMINS, 'YourApplication Failed')
+        mail_handler.setLevel(logging.ERROR)
+        app.logger.addHandler(mail_handler)
+
+So what just happened?  We created a new
+:class:`~logging.handlers.SMTPHandler` that will send mails with the mail
+server listening on ``127.0.0.1`` to all the `ADMINS` from the address
+*server-error@example.com* with the subject "YourApplication Failed".  If
+your mail server requires credentials these can also provided, for that
+check out the documentation for the :class:`~logging.handlers.SMTPHandler`.
+
+We also tell the handler to only send errors and more critical messages.
+Because we certainly don't want to get a mail for warnings or other
+useless logs that might happen during request handling.
+
+Before you run that in production, please also look at :ref:`log-format`
+to put more information into that error mail.  That will save you from a
+lot of frustration.
+
+
+Logging to a File
+-----------------
+
+Even if you get mails, you probably also want to log warnings.  It's a
+good idea to keep as much information around that might be required to
+debug a problem.  Please note that Flask itself will not issue any
+warnings in the core system, so it's your responsibility to warn in the
+code if something seems odd.
+
+There are a couple of handlers provided by the logging system out of the
+box but not all of them are useful for basic error logging.  The most
+interesting are probably the following:
+
+-   :class:`~logging.handlers.FileHandler` - logs messages to a file on the
+    filesystem.
+-   :class:`~logging.handlers.RotatingFileHandler` - logs messages to a file
+    on the filesystem and will rotate after a certain number of messages.
+-   :class:`~logging.handlers.NTEventLogHandler` - will log to the system
+    event log of a Windows system.  If you are deploying on a Windows box,
+    this is what you want to use.
+-   :class:`~logging.handlers.SysLogHandler` - sends logs to a UNIX
+    syslog.
+
+Once you picked your log handler, do like you did with the SMTP handler
+above, just make sure to use a lower setting (I would recommend
+`WARNING`)::
+
+    if not app.debug:
+        import logging
+        from logging.handlers import TheHandlerYouWant
+        file_handler = TheHandlerYouWant(...)
+        file_handler.setLevel(logging.WARNING)
+        app.logger.addHandler(file_handler)
+
+.. _log-format:
+
+Controlling the Log Format
+--------------------------
+
+By default a handler will only write the message string into a file or
+send you that message as mail.  But a log record stores more information
+and it makes a lot of sense to configure your logger to also contain that
+information so that you have a better idea of why that error happened, and
+more importantly, where it did.
+
+A formatter can be instanciated with a format string.  Note that
+tracebacks are appended to the log entry automatically.  You don't have to
+do that in the log formatter format string.
+
+Here some example setups:
+
+Email
+`````
+
+::
+
+    from logging import Formatter
+    mail_handler.setFormatter(Formatter('''
+    Message type:       %(levelname)s
+    Location:           %(pathname)s:%(lineno)d
+    Module:             %(module)s
+    Function:           %(funcName)s
+    Time:               %(asctime)s
+
+    Message:
+
+    %(message)s
+    '''))
+
+File logging
+````````````
+
+::
+
+    from logging import Formatter
+    file_handler.setFormatter(Formatter(
+        '%(astime)s %(levelname)s: %(message)s '
+        '[in %(pathname)s:%(lineno)d]'
+    ))
+
+
+Complex Log Formatting
+``````````````````````
+
+Here is a list of useful formatting variables for the format string.  Note
+that this list is not complete, consult the official documentation of the
+:mod:`logging` package for a full list.
+
++------------------+----------------------------------------------------+
+| Format           | Description                                        |
++==================+====================================================+
+| ``%(levelname)s``| Text logging level for the message                 |
+|                  | (``'DEBUG'``, ``'INFO'``, ``'WARNING'``,           |
+|                  | ``'ERROR'``, ``'CRITICAL'``).                      |
++------------------+----------------------------------------------------+
+| ``%(pathname)s`` | Full pathname of the source file where the         |
+|                  | logging call was issued (if available).            |
++------------------+----------------------------------------------------+
+| ``%(filename)s`` | Filename portion of pathname.                      |
++------------------+----------------------------------------------------+
+| ``%(module)s``   | Module (name portion of filename).                 |
++------------------+----------------------------------------------------+
+| ``%(funcName)s`` | Name of function containing the logging call.      |
++------------------+----------------------------------------------------+
+| ``%(lineno)d``   | Source line number where the logging call was      |
+|                  | issued (if available).                             |
++------------------+----------------------------------------------------+
+| ``%(asctime)s``  | Human-readable time when the LogRecord` was        |
+|                  | created.  By default this is of the form           |
+|                  | ``"2003-07-08 16:49:45,896"`` (the numbers after   |
+|                  | the comma are millisecond portion of the time).    |
+|                  | This can be changed by subclassing the formatter   |
+|                  | and overriding the                                 |
+|                  | :meth:`~logging.Formatter.formatTime` method.      |
++------------------+----------------------------------------------------+
+| ``%(message)s``  | The logged message, computed as ``msg % args``     |
++------------------+----------------------------------------------------+
+
+If you want to further customize the formatting, you can subclass the
+formatter.  The formatter has three interesting methods:
+
+:meth:`~logging.Formatter.format`:
+    handles the actual formatting.  It is passed a
+    :class:`~logging.LogRecord` object and has to return the formatted
+    string.
+:meth:`~logging.Formatter.formatTime`:
+    called for `asctime` formatting.  If you want a different time format
+    you can override this method.
+:meth:`~logging.Formatter.formatException`
+    called for exception formatting.  It is passed a :attr:`~sys.exc_info`
+    tuple and has to return a string.  The default is usually fine, you
+    don't have to override it.
+
+For more information, head over to the official documentation.
+
+
+Other Libraries
+---------------
+
+So far we only configured the logger your application created itself.
+Other libraries might log themselves as well.  For example, SQLAlchemy use
+logging heavily in the core.  While there is a method to configure all
+loggers at once in the :mod:`logging` package, I would not recommend using
+it.  There might be a situation in which you want to have multiple
+separate applications running side by side in the same Python interpreter
+and then it becomes impossible to have different logging setups for those.
+
+Instead, I would recommend figuring out which loggers you are interested
+in, getting the loggers with the :func:`~logging.getLogger` function and
+iterating over them to attach handlers::
+
+    from logging import getLogger
+    loggers = [app.logger, getLogger('sqlalchemy'),
+               getLogger('otherlibrary')]
+    for logger in loggers:
+        logger.addHandler(mail_handler)
+        logger.addHandler(file_handler)
diff --git a/docs/patterns/fileuploads.rst b/docs/patterns/fileuploads.rst
index fd94605d..6d0bd0a1 100644
--- a/docs/patterns/fileuploads.rst
+++ b/docs/patterns/fileuploads.rst
@@ -1,3 +1,5 @@
+.. _uploading-files:
+
 Uploading Files
 ===============
 
diff --git a/docs/quickstart.rst b/docs/quickstart.rst
index 4fc0b68e..745dedb9 100644
--- a/docs/quickstart.rst
+++ b/docs/quickstart.rst
@@ -532,6 +532,8 @@ Werkzeug provides for you::
             f.save('/var/www/uploads/' + secure_filename(f.filename))
         ...
 
+For some better examples, checkout the :ref:`uploading-files` pattern.
+
 Cookies
 ```````
 
@@ -639,3 +641,29 @@ To flash a message use the :func:`~flask.flash` method, to get hold of the
 messages you can use :func:`~flask.get_flashed_messages` which is also
 available in the templates.  Check out the :ref:`message-flashing-pattern`
 for a full example.
+
+Logging
+-------
+
+.. versionadded:: 0.5
+
+Sometimes you might be in the situation where you deal with data that
+should be correct, but actually is not.  For example you have some client
+side code that sends an HTTP request to the server, and it's obviously
+malformed.  This might be caused by a user tempering with the data, or the
+client code failed.  Most the time, it's okay to reply with ``400 Bad
+Request`` in that situation, but other times it is not and the code has to
+continue working.
+
+Yet you want to log that something fishy happened.  This is where loggers
+come in handy.  As of Flask 0.5 a logger is preconfigured for you to use.
+
+Here are some example log calls::
+
+    app.logger.debug('A value for debugging')
+    app.logger.warning('A warning ocurred (%d apples)', 42)
+    app.logger.error('An error occoured')
+
+The attached :attr:`~flask.Flask.logger` is a standard logging
+:class:`~logging.Logger`, so head over to the official stdlib
+documentation for more information.
diff --git a/flask.py b/flask.py
index 72c24029..9a919f7f 100644
--- a/flask.py
+++ b/flask.py
@@ -666,7 +666,7 @@ class Flask(_PackageBoundObject):
     #: .. versionadded:: 0.5
     debug_log_format = (
         '-' * 80 + '\n' +
-        '%(levelname)s in %(module)s, %(filename)s:%(lineno)d]:\n' +
+        '%(levelname)s in %(module)s, %(pathname)s:%(lineno)d]:\n' +
         '%(message)s\n' +
         '-' * 80
     )
@@ -769,7 +769,12 @@ class Flask(_PackageBoundObject):
     def logger(self):
         """A :class:`logging.Logger` object for this application.  The
         default configuration is to log to stderr if the application is
-        in debug mode.
+        in debug mode.  This logger can be used to (surprise) log messages.
+        Here some examples::
+
+            app.logger.debug('A value for debugging')
+            app.logger.warning('A warning ocurred (%d apples)', 42)
+            app.logger.error('An error occoured')
         """
         from logging import getLogger, StreamHandler, Formatter, DEBUG
         class DebugHandler(StreamHandler):
@@ -1085,8 +1090,6 @@ class Flask(_PackageBoundObject):
             return self.view_functions[req.endpoint](**req.view_args)
         except HTTPException, e:
             return self.handle_http_exception(e)
-        except Exception, e:
-            return self.handle_exception(e)
 
     def make_response(self, rv):
         """Converts the return value from a view function to a real
@@ -1176,11 +1179,14 @@ class Flask(_PackageBoundObject):
                                exception context to start the response
         """
         with self.request_context(environ):
-            rv = self.preprocess_request()
-            if rv is None:
-                rv = self.dispatch_request()
-            response = self.make_response(rv)
-            response = self.process_response(response)
+            try:
+                rv = self.preprocess_request()
+                if rv is None:
+                    rv = self.dispatch_request()
+                response = self.make_response(rv)
+                response = self.process_response(response)
+            except Exception, e:
+                response = self.make_response(self.handle_exception(e))
             return response(environ, start_response)
 
     def request_context(self, environ):
diff --git a/tests/flask_tests.py b/tests/flask_tests.py
index 6cde2a3c..762b3913 100644
--- a/tests/flask_tests.py
+++ b/tests/flask_tests.py
@@ -645,6 +645,28 @@ class LoggingTestCase(unittest.TestCase):
         assert '1/0' in err
         assert 'ZeroDivisionError:' in err
 
+    def test_processor_exceptions(self):
+        app = flask.Flask(__name__)
+        @app.before_request
+        def before_request():
+            if trigger == 'before':
+                1/0
+        @app.after_request
+        def after_request(response):
+            if trigger == 'after':
+                1/0
+            return response
+        @app.route('/')
+        def index():
+            return 'Foo'
+        @app.errorhandler(500)
+        def internal_server_error(e):
+            return 'Hello Server Error', 500
+        for trigger in 'before', 'after':
+            rv = app.test_client().get('/')
+            assert rv.status_code == 500
+            assert rv.data == 'Hello Server Error'
+
 
 def suite():
     from minitwit_tests import MiniTwitTestCase