.. _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:`cookiecutter` to create a project
|
which contains ``development.ini`` and ``production.ini`` files which help
|
configure logging. All of the Pyramid cookiecutters provided by the Pylons Project do
|
this. If you're not using a cookiecutter, or if you've used a third-party
|
cookiecutter 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:`cookiecutter` 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 cookiecutter 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
|
cookiecutter-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`` files. If you use ``pyramid-cookiecutter-starter`` to generate a Pyramid project with the name of the package as ``hello_world``, then the logging configuration
|
in the ``development.ini`` file is as follows:
|
|
.. literalinclude:: myproject/development.ini
|
:language: ini
|
:lineno-match:
|
:lines: 29-
|
|
The ``production.ini`` file uses the ``WARN`` level in its logger
|
configuration instead of ``DEBUG``, but it is otherwise identical.
|
|
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 ``myproject`` 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., ``myproject``). 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 cookiecutter.
|
|
: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 cookiecutters 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 cookiecutter.
|
|
Sending Logging Messages
|
------------------------
|
|
Python's special ``__name__`` variable refers to the current module's fully
|
qualified name. From any module in a package named ``myproject``, the ``__name__``
|
builtin variable will always be something like ``myproject``, or
|
``myproject.subpackage`` or ``myproject.package.subpackage`` if your project is named
|
``myproject``. Sending a message to this logger will send it to the ``myproject``
|
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 [myproject.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, myproject, 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, myproject
|
|
[logger_myproject]
|
level = DEBUG
|
handlers =
|
qualname = myproject
|
|
All of the child loggers of the ``myproject`` logger will inherit the ``DEBUG``
|
level unless they're explicitly set differently. Meaning the ``myproject.views``,
|
``myproject.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/myproject.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, myproject, 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 ``myproject.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
|
<https://docs.pylonsproject.org/projects/pyramid_exclog/en/latest/>`_.
|
|
.. 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 [myproject.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, myproject, 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
|
