diff options
Diffstat (limited to 'docs/narr/logging.rst')
| -rw-r--r-- | docs/narr/logging.rst | 430 |
1 files changed, 430 insertions, 0 deletions
diff --git a/docs/narr/logging.rst b/docs/narr/logging.rst new file mode 100644 index 000000000..9c6e8a319 --- /dev/null +++ b/docs/narr/logging.rst @@ -0,0 +1,430 @@ +.. _logging_chapter: + +Logging +======= + +:app:`Pyramid` allows you to make use of the Python standard library +:mod:`logging` module. This chapter describes how to configure logging and how +to send log messages to loggers that you've configured. + +.. warning:: + + This chapter assumes you've used a :term:`scaffold` to create a project + which contains ``development.ini`` and ``production.ini`` files which help + configure logging. All of the scaffolds which ship with :app:`Pyramid` do + this. If you're not using a scaffold, or if you've used a third-party + scaffold which does not create these files, the configuration information in + this chapter may not be applicable. + +.. index: + pair: settings; logging + pair: .ini; logging + pair: logging; configuration + +.. _logging_config: + +Logging Configuration +--------------------- + +A :app:`Pyramid` project created from a :term:`scaffold` is configured to allow +you to send messages to :mod:`Python standard library logging package +<logging>` loggers from within your application. In particular, the +:term:`PasteDeploy` ``development.ini`` and ``production.ini`` files created +when you use a scaffold include a basic configuration for the Python +:mod:`logging` package. + +PasteDeploy ``.ini`` files use the Python standard library :mod:`ConfigParser +format <ConfigParser>`. This is the same format used as the Python +:ref:`logging module's Configuration file format <logging-config-fileformat>`. +The application-related and logging-related sections in the configuration file +can coexist peacefully, and the logging-related sections in the file are used +from when you run ``pserve``. + +The ``pserve`` command calls the :func:`pyramid.paster.setup_logging` function, +a thin wrapper around the :func:`logging.config.fileConfig` using the specified +``.ini`` file, if it contains a ``[loggers]`` section (all of the +scaffold-generated ``.ini`` files do). ``setup_logging`` reads the logging +configuration from the ini file upon which ``pserve`` was invoked. + +Default logging configuration is provided in both the default +``development.ini`` and the ``production.ini`` file. The logging configuration +in the ``development.ini`` file is as follows: + +.. code-block:: ini + :linenos: + + # Begin logging configuration + + [loggers] + keys = root, {{package_logger}} + + [handlers] + keys = console + + [formatters] + keys = generic + + [logger_root] + level = INFO + handlers = console + + [logger_{{package_logger}}] + level = DEBUG + handlers = + qualname = {{package}} + + [handler_console] + class = StreamHandler + args = (sys.stderr,) + level = NOTSET + formatter = generic + + [formatter_generic] + format = %(asctime)s %(levelname)-5.5s [%(name)s][%(threadName)s] %(message)s + + # End logging configuration + +The ``production.ini`` file uses the ``WARN`` level in its logger +configuration, but it is otherwise identical. + +The name ``{{package_logger}}`` above will be replaced with the name of your +project's :term:`package`, which is derived from the name you provide to your +project. For instance, if you do: + +.. code-block:: text + :linenos: + + pcreate -s starter MyApp + +The logging configuration will literally be: + +.. code-block:: ini + :linenos: + + # Begin logging configuration + + [loggers] + keys = root, myapp + + [handlers] + keys = console + + [formatters] + keys = generic + + [logger_root] + level = INFO + handlers = console + + [logger_myapp] + level = DEBUG + handlers = + qualname = myapp + + [handler_console] + class = StreamHandler + args = (sys.stderr,) + level = NOTSET + formatter = generic + + [formatter_generic] + format = %(asctime)s %(levelname)-5.5s [%(name)s][%(threadName)s] %(message)s + + # End logging configuration + +In this logging configuration: + +- a logger named ``root`` is created that logs messages at a level above or + equal to the ``INFO`` level to stderr, with the following format: + + .. code-block:: text + + 2007-08-17 15:04:08,704 INFO [packagename] Loading resource, id: 86 + +- a logger named ``myapp`` is configured that logs messages sent at a level + above or equal to ``DEBUG`` to stderr in the same format as the root logger. + +The ``root`` logger will be used by all applications in the Pyramid process +that ask for a logger (via ``logging.getLogger``) that has a name which begins +with anything except your project's package name (e.g., ``myapp``). The logger +with the same name as your package name is reserved for your own usage in your +:app:`Pyramid` application. Its existence means that you can log to a known +logging location from any :app:`Pyramid` application generated via a scaffold. + +:app:`Pyramid` and many other libraries (such as Beaker, SQLAlchemy, Paste) log +a number of messages to the root logger for debugging purposes. Switching the +root logger level to ``DEBUG`` reveals them: + +.. code-block:: ini + + [logger_root] + #level = INFO + level = DEBUG + handlers = console + +Some scaffolds configure additional loggers for additional subsystems they use +(such as SQLALchemy). Take a look at the ``production.ini`` and +``development.ini`` files rendered when you create a project from a scaffold. + +Sending Logging Messages +------------------------ + +Python's special ``__name__`` variable refers to the current module's fully +qualified name. From any module in a package named ``myapp``, the ``__name__`` +builtin variable will always be something like ``myapp``, or +``myapp.subpackage`` or ``myapp.package.subpackage`` if your project is named +``myapp``. Sending a message to this logger will send it to the ``myapp`` +logger. + +To log messages to the package-specific logger configured in your ``.ini`` +file, simply create a logger object using the ``__name__`` builtin and call +methods on it. + +.. code-block:: python + :linenos: + + import logging + log = logging.getLogger(__name__) + + def myview(request): + content_type = 'text/plain' + content = 'Hello World!' + log.debug('Returning: %s (content-type: %s)', content, content_type) + request.response.content_type = content_type + return request.response + +This will result in the following printed to the console, on ``stderr``: + +.. code-block:: text + + 16:20:20,440 DEBUG [myapp.views] Returning: Hello World! + (content-type: text/plain) + +Filtering log messages +---------------------- + +Often there's too much log output to sift through, such as when switching the +root logger's level to ``DEBUG``. + +For example, you're diagnosing database connection issues in your application +and only want to see SQLAlchemy's ``DEBUG`` messages in relation to database +connection pooling. You can leave the root logger's level at the less verbose +``INFO`` level and set that particular SQLAlchemy logger to ``DEBUG`` on its +own, apart from the root logger: + +.. code-block:: ini + + [logger_sqlalchemy.pool] + level = DEBUG + handlers = + qualname = sqlalchemy.pool + +then add it to the list of loggers: + +.. code-block:: ini + + [loggers] + keys = root, myapp, sqlalchemy.pool + +No handlers need to be configured for this logger as by default non-root +loggers will propagate their log records up to their parent logger's handlers. +The root logger is the top level parent of all loggers. + +This technique is used in the default ``development.ini``. The root logger's +level is set to ``INFO``, whereas the application's log level is set to +``DEBUG``: + +.. code-block:: ini + + # Begin logging configuration + + [loggers] + keys = root, myapp + + [logger_myapp] + level = DEBUG + handlers = + qualname = myapp + +All of the child loggers of the ``myapp`` logger will inherit the ``DEBUG`` +level unless they're explicitly set differently. Meaning the ``myapp.views``, +``myapp.models``, and all your app's modules' loggers by default have an +effective level of ``DEBUG`` too. + +For more advanced filtering, the logging module provides a +:class:`logging.Filter` object; however it cannot be used directly from the +configuration file. + +Advanced Configuration +---------------------- + +To capture log output to a separate file, use :class:`logging.FileHandler` (or +:class:`logging.handlers.RotatingFileHandler`): + +.. code-block:: ini + + [handler_filelog] + class = FileHandler + args = ('%(here)s/myapp.log','a') + level = INFO + formatter = generic + +Before it's recognized, it needs to be added to the list of handlers: + +.. code-block:: ini + + [handlers] + keys = console, myapp, filelog + +and finally utilized by a logger. + +.. code-block:: ini + + [logger_root] + level = INFO + handlers = console, filelog + +These final three lines of configuration direct all of the root logger's output +to the ``myapp.log`` as well as the console. + +Logging Exceptions +------------------ + +To log or email exceptions generated by your :app:`Pyramid` application, use +the :term:`pyramid_exclog` package. Details about its configuration are in its +`documentation <http://docs.pylonsproject.org/projects/pyramid_exclog/dev/>`_. + +.. index:: + single: TransLogger + single: middleware; TransLogger + pair: configuration; middleware + single: settings; middleware + pair: .ini; middleware + +.. _request_logging_with_pastes_translogger: + +Request Logging with Paste's TransLogger +---------------------------------------- + +The :term:`WSGI` design is modular. Waitress logs error conditions, debugging +output, etc., but not web traffic. For web traffic logging, Paste provides the +`TransLogger <http://pythonpaste.org/modules/translogger.html>`_ +:term:`middleware`. TransLogger produces logs in the `Apache Combined Log +Format <http://httpd.apache.org/docs/2.2/logs.html#combined>`_. But +TransLogger does not write to files; the Python logging system must be +configured to do this. The Python :class:`logging.FileHandler` logging handler +can be used alongside TransLogger to create an ``access.log`` file similar to +Apache's. + +Like any standard :term:`middleware` with a Paste entry point, TransLogger can +be configured to wrap your application using ``.ini`` file syntax. First +rename your Pyramid ``.ini`` file's ``[app:main]`` section to +``[app:mypyramidapp]``, then add a ``[filter:translogger]`` section, then use a +``[pipeline:main]`` section file to form a WSGI pipeline with both the +translogger and your application in it. For instance, change from this: + +.. code-block:: ini + + [app:main] + use = egg:MyProject + +To this: + +.. code-block:: ini + + [app:mypyramidapp] + use = egg:MyProject + + [filter:translogger] + use = egg:Paste#translogger + setup_console_handler = False + + [pipeline:main] + pipeline = translogger + mypyramidapp + +Using PasteDeploy this way to form and serve a pipeline is equivalent to +wrapping your app in a TransLogger instance via the bottom of the ``main`` +function of your project's ``__init__`` file: + +.. code-block:: python + + ... + app = config.make_wsgi_app() + from paste.translogger import TransLogger + app = TransLogger(app, setup_console_handler=False) + return app + +.. note:: + TransLogger will automatically setup a logging handler to the console when + called with no arguments, so it "just works" in environments that don't + configure logging. Since our logging handlers are configured, we disable + the automation via ``setup_console_handler = False``. + +With the filter in place, TransLogger's logger (named the ``wsgi`` logger) will +propagate its log messages to the parent logger (the root logger), sending its +output to the console when we request a page: + +.. code-block:: text + + 00:50:53,694 INFO [myapp.views] Returning: Hello World! + (content-type: text/plain) + 00:50:53,695 INFO [wsgi] 192.168.1.111 - - [11/Aug/2011:20:09:33 -0700] "GET /hello + HTTP/1.1" 404 - "-" + "Mozilla/5.0 (Macintosh; U; Intel Mac OS X; en-US; rv:1.8.1.6) Gecko/20070725 + Firefox/2.0.0.6" + +To direct TransLogger to an ``access.log`` FileHandler, we need the following +to add a FileHandler (named ``accesslog``) to the list of handlers, and ensure +that the ``wsgi`` logger is configured and uses this handler accordingly: + +.. code-block:: ini + + # Begin logging configuration + + [loggers] + keys = root, myapp, wsgi + + [handlers] + keys = console, accesslog + + [logger_wsgi] + level = INFO + handlers = accesslog + qualname = wsgi + propagate = 0 + + [handler_accesslog] + class = FileHandler + args = ('%(here)s/access.log','a') + level = INFO + formatter = generic + +As mentioned above, non-root loggers by default propagate their log records to +the root logger's handlers (currently the console handler). Setting +``propagate`` to ``0`` (``False``) here disables this; so the ``wsgi`` logger +directs its records only to the ``accesslog`` handler. + +Finally, there's no need to use the ``generic`` formatter with TransLogger as +TransLogger itself provides all the information we need. We'll use a formatter +that passes through the log messages as is. Add a new formatter called +``accesslog`` by including the following in your configuration file: + +.. code-block:: ini + + [formatters] + keys = generic, accesslog + + [formatter_accesslog] + format = %(message)s + +Finally alter the existing configuration to wire this new ``accesslog`` +formatter into the FileHandler: + +.. code-block:: ini + + [handler_accesslog] + class = FileHandler + args = ('%(here)s/access.log','a') + level = INFO + formatter = accesslog |