Logging messages

As of Pylons 0.9.6, Pylons controllers (created via paster controller/restcontroller) and websetup.py create their own Logger objects via Python's logging module.

For example, in the helloworld project's hello controller (helloworld/controllers/hello.py):

import logging

from helloworld.lib.base import *

log = logging.getLogger(__name__)

class HelloController(BaseController):

    def index(self):
        # Return a...

Python's special __name__ variable refers to the current module's fully qualified name; in this case, helloworld.controllers.hello.

To log messages, simply use methods available on that Logger object:

import logging

from helloworld.lib.base import *

log = logging.getLogger(__name__)

class HelloController(BaseController):

    def index(self):
        content_type = 'text/plain'
        content = 'Hello World!'

        log.debug('Returning: %s (content-type: %s)', content, content_type)
        response.content_type = content_type
        return content

Which will result in the following printed to the console, on stderr:

1	16:20:20,440 DEBUG [helloworld.controllers.hello] Returning: Hello World! (content-type: text/plain)

Basic Logging configuration

As of Pylons 0.9.6, the default ini files include a basic configuration for the logging module. Paste ini files use the Python standard ConfigParser format; the same format used for the Python logging module's Configuration file format.

paster, when loading an application via the paster serve, shell or setup-app commands, calls the logging.fileConfig function on that specified ini file if it contains a 'loggers' entry. logging.fileConfig reads the logging configuration from a ConfigParser file.

Logging configuration is provided in both the default development.ini and the production ini file (created via paster make-config <package_name> <ini_file>). The production ini's logging setup is a little simpler than the development.ini's, and is as follows:

# Logging configuration
[loggers]
keys = root

[handlers]
keys = console

[formatters]
keys = generic

[logger_root]
level = INFO
handlers = console

[handler_console]
class = StreamHandler
args = (sys.stderr,)
level = NOTSET
formatter = generic

[formatter_generic]
format = %(asctime)s %(levelname)-5.5s [%(name)s] %(message)s

One root Logger is created that logs only messages at a level above or equal to the INFO level to stderr, with the following format:

1	2007-08-17 15:04:08,704 INFO [helloworld.controllers.hello] Loading resource, id: 86

For those familiar with the logging.basicConfig function, this configuration is equivalent to the code:

1 2	logging.basicConfig(level=logging.INFO, format='%(asctime)s %(levelname)-5.5s [%(name)s] %(message)s')

The default development.ini's logging section has a couple of differences: it uses a less verbose timestamp, and defaults your application's log messages to the DEBUG level (described in the next section).

Pylons and many other libraries (such as Beaker, SQLAlchemy, Paste) log a number of messages for debugging purposes. Switching the root Logger level to DEBUG reveals them:

[logger_root]
#level = INFO
level = DEBUG
handlers = console

Filtering log messages

Often times 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:

1 2	[loggers] keys = root, 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:

1
2
3

# Logging configuration
[loggers]
keys = root, helloworld

[logger_helloworld]
level = DEBUG
handlers =
qualname = helloworld

All of the child Loggers of the helloworld Logger will inherit the DEBUG level unless they're explicitly set differently. Meaning the helloworld.controllers.hello, helloworld.websetup (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_accesslog]
class = FileHandler
args = ('access.log','a')
level = INFO
formatter = generic

Before it's recognized, it needs to be added to the list of Handlers:

1 2	[handlers] keys = console, accesslog

and finally utilized by a Logger.

1
2
3

[logger_root]
level = INFO
handlers = console, accesslog

These final 3 lines of configuration directs all of the root Logger's output to the access.log as well as the console; we'll want to disable this for the next section.

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 in the [app:main] section of the ini file:

filter-with = translogger

[filter:translogger]
use = egg:Paste#translogger
setup_console_handler = False

This is equivalent to wrapping your app in a TransLogger instance via the bottom of your project's config/middleware.py file:

1
2
3

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:

1
2
3

00:50:53,694 INFO  [helloworld.controllers.hello] Returning: Hello World! (content-type: text/plain)
00:50:53,695 INFO  [wsgi] 192.168.1.111 - - [11/Aug/2007: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 the access.log FileHandler defined above, we need to add that FileHandler to the wsgi Logger's list of Handlers:

1
2
3

# Logging configuration
[loggers]
keys = root, wsgi

[logger_wsgi]
level = INFO
handlers = accesslog
qualname = wsgi
propagate = 0

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:

1 2	[formatters] keys = generic, accesslog

1 2	[formatter_accesslog] format = %(message)s

Then wire this new accesslog Formatter into the FileHandler:

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

Logging to wsgi.errors

Pylons provides a custom logging Handler class, pylons.log.WSGIErrorsHandler, for logging output to environ['wsgi.errors']: the WSGI server's error stream (see the WSGI Spefification, PEP 333 for more information). wsgi.errors can be useful to log to in certain situations, such as when deployed under Apache mod_wsgi/mod_python, where the wsgi.errors stream is the Apache error log.

To configure logging of only ERROR (and CRITICAL) messages to wsgi.errors, add the following to the ini file:

1 2	[handlers] keys = console, wsgierrors

[handler_wsgierrors]
class = pylons.log.WSGIErrorsHandler
args = ()
level = ERROR
format = generic

then add the new Handler name to the list of Handlers used by the root Logger:

1
2
3

[logger_root]
level = INFO
handlers = console, wsgierrors

Warning

WSGIErrorsHandler does not receive log messages created during application startup. This is due to the wsgi.errors stream only being available through the environ dictionary; which isn't available until a request is made.

Lumberjacking with log4j's Chainsaw

Java's log4j project provides the Java GUI application Chainsaw for viewing and managing log messages. Among its features are the ability to filter log messages on the fly, and customizable color highlighting of log messages.

We can configure Python's logging module to output to a format parsable by Chainsaw, log4j's XMLLayout format.

To do so, we first need to install the Python XMLLayout package:

1	$ easy_install XMLLayout

It provides a log Formatter that generates XMLLayout XML. It also provides RawSocketHandler; like the logging module's SocketHandler, it sends log messages across the network, but does not pickle them.

The following is an example configuration for sending XMLLayout log messages across the network to Chainsaw, if it were listening on localhost port 4448:

[handlers]
keys = console, chainsaw

[formatters]
keys = generic, xmllayout

[logger_root]
level = INFO
handlers = console, chainsaw

[handler_chainsaw]
class = xmllayout.RawSocketHandler
args = ('localhost', 4448)
level = NOTSET
formatter = xmllayout

1 2	[formatter_xmllayout] class = xmllayout.XMLLayout

This configures any log messages handled by the root Logger to also be sent to Chainsaw. The default development.ini configures the root Logger to the INFO level, however in the case of using Chainsaw, it is preferable to configure the root Logger to NOTSET so all log messages are sent to Chainsaw. Instead, we can restrict the console handler to the INFO level:

[logger_root]
level = NOTSET
handlers = console

[handler_console]
class = StreamHandler
args = (sys.stderr,)
level = INFO
formatter = generic

Chainsaw can be downloaded from its home page, but can also be launched directly from a Java-enabled browser via the link: Chainsaw web start.

It can be configured from the GUI, but it also supports reading its configuration from a log4j.xml file.

The following log4j.xml file configures Chainsaw to listen on port 4448 for XMLLayout style log messages. It also hides Chainsaw's own logging messages under the WARN level, so only your app's log messages are displayed:

<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE configuration>
<configuration xmlns="http://logging.apache.org/">

  <plugin name="XMLSocketReceiver" class="org.apache.log4j.net.XMLSocketReceiver">
    <param name="decoder" value="org.apache.log4j.xml.XMLDecoder"/>
    <param name="port" value="4448"/>
  </plugin>

  <logger name="org.apache.log4j">
    <level value="warn"/>
  </logger>

  <root>
    <level value="debug"/>
  </root>

</configuration>

Chainsaw will prompt for a configuration file upon startup. The configuration can also be loaded later by clicking File/Load Log4J File.... You should see an XMLSocketReceiver instance loaded in Chainsaw's Receiver list, configured at port 4448, ready to receive log messages.

Here's how the Pylons stack's log messages can look with colors defined (using Chainsaw on OS X):

/download/attachments/6684828/Pylons_Stack-Chainsaw-OSX.png

PylonsHQ.

Logging

Logging messages

Basic Logging configuration

Filtering log messages

Advanced Configuration

Request logging with Paste's TransLogger

Logging to wsgi.errors

Lumberjacking with log4j's Chainsaw

Labels

Comments (2)

Jorge Vargas says:

Philip Jenvey says: