Logging

Pyramid allows you to make use of the Python standard library 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 scaffold to create a project which contains development.ini and production.ini files which help configure logging. All of the scaffolds which ship along with 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 will not be applicable.

Logging Configuration

A Pyramid project created from a scaffold is configured to allow you to send messages to Python standard library logging package loggers from within your application. In particular, the PasteDeploy development.ini and production.ini files created when you use a scaffold include a basic configuration for the Python logging package.

PasteDeploy .ini files use the Python standard library ConfigParser format; this the same format used as the Python logging module’s Configuration file format. 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 paster serve.

The paster serve command calls the logging.fileConfig function using the specified ini file if it contains a [loggers] section (all of the scaffold-generated .ini files do). logging.fileConfig reads the logging configuration from the ini file upon which paster serve 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:

# 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 package, which is derived from the name you provide to your project. For instance, if you do:

paster create -t pyramid_starter MyApp

The logging configuration will literally be:

# 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:

  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 Pyramid application. Its existence means that you can log to a known logging location from any Pyramid application generated via a scaffold.

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:

[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.

 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:

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.

An 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:

[logger_sqlalchemy.pool]
level = DEBUG
handlers =
qualname = sqlalchemy.pool

then add it to the list of loggers:

[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:

# Begin logging configuration

[loggers]
keys = root, myapp

[logger_myapp]
level = DEBUG
handlers =
qualname = helloworld

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 Filter object; however it cannot be used directly from the configuration file.

Advanced Configuration

To capture log output to a separate file, use a FileHandler (or a RotatingFileHandler):

[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:

[handlers]
keys = console, myapp, filelog

and finally utilized by a logger.

[logger_root]
level = INFO
handlers = console, filelog

These final 3 lines of configuration directs 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 Pyramid application, use the pyramid_exclog package. Details about its configuration are in its documentation.

Request Logging with Paste’s TransLogger

Paste provides the TransLogger middleware for logging requests using the Apache Combined Log Format. TransLogger combined with a FileHandler can be used to create an access.log file similar to Apache’s.

Like any standard 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:

[app:main]
use = egg:MyProject

To this:

[app:mypyramidapp]
use = egg:MyProject

[filter:translogger]
paste.filter_app_factory = 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 the main function of your project’s __init__ file:

...
app = config.make_wsgi_app()
from paste.translogger import TransLogger
app = TransLogger(app, setup_console_handler=False)
return app

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 we’ve configured our own logging handlers, we need to disable that option 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:

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 to add that FileHandler to the wsgi logger’s list of handlers:

# Begin logging configuration

[loggers]
keys = root, myapp, wsgi

[logger_wsgi]
level = INFO
handlers = handler_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:

[formatters]
keys = generic, accesslog

[formatter_accesslog]
format = %(message)s

Then wire this new accesslog formatter into the FileHandler:

[handler_accesslog]
class = FileHandler
args = ('%(here)s/access.log','a')
level = INFO
formatter = accesslog