Chapter 7. Logging

Twisted has its own logging systems that we’ve already seen used under the hood by twistd. This system plays nicely with Twisted-specific concepts like Failures but is also compatible with Python’s standard library logging facilities.

Basic In-Application Logging

The simplest way to add logging to your Twisted application is to import twisted.python.log, start logging to a file or stdout, and log events at particular log levels as you would with the Python standard logging module. For instance, Example 7-1 adds logging to a file for our echo server from Chapter 2.

Example 7-1. logging_echoserver.py
from twisted.internet import protocol, reactor
from twisted.python import log

class Echo(protocol.Protocol):
    def dataReceived(self, data):
        log.msg(data)
        self.transport.write(data)

class EchoFactory(protocol.Factory):
    def buildProtocol(self, addr):
        return Echo()

log.startLogging(open('echo.log', 'w'))
reactor.listenTCP(8000, EchoFactory())
reactor.run()

Logging starts once log.startLogging has been called. After that, information can be logged with log.msg or log.err; use log.msg to log strings and use log.err to log exceptions and failures. The default logging format produces output like this log of the echo server starting up, echoing one message, and terminating:

2012-11-15 20:26:37-0500 [-] Log opened.
2012-11-15 20:26:37-0500 [-] EchoFactory starting on 8000
2012-11-15 20:26:37-0500 [-] Starting factory <__main__.EchoFactory ...
2012-11-15 20:26:40-0500 [Echo,0,127.0.0.1] Hello, world!
2012-11-15 20:26:43-0500 [-] Received SIGINT, shutting down.
2012-11-15 20:26:43-0500 [__main__.EchoFactory] (TCP Port 8000 Closed)
2012-11-15 20:26:43-0500 [__main__.EchoFactory] Stopping factory <__...
2012-11-15 20:26:43-0500 [-] Main loop terminated.

To log to stdout, call startLogging with sys.stdout, as in Example 7-2.

Example 7-2. logging_test.py
import sys
from twisted.python import log

log.startLogging(sys.stdout)
log.msg("Starting experiment")

log.msg("Logging an exception")

try:
    1 / 0
except ZeroDivisionError, e:
    log.err(e)

log.msg("Ending experiment")

By default, in addition to logging messages when you invoke log.msg and log.err, the logging facilities will log stdout (e.g., print statements) as well as tracebacks for uncaught exceptions. They will also listen for and log events emitted by Twisted modules. That’s why we see various EchoFactory events in the preceding logs.

Twisted has some convenience classes for customizing your log file management. One example is twisted.python.logfile.LogFile, which can be rotated manually or when a specified log size has been reached. Example 7-3 illustrates both features.

Example 7-3. log_rotation.py
from twisted.python import log
from twisted.python import logfile

# Log to /tmp/test.log ... test.log.N, rotating every 100 bytes.
f = logfile.LogFile("test.log", "/tmp", rotateLength=100)
log.startLogging(f)

log.msg("First message")

# Rotate manually.
f.rotate()

for i in range(5):
    log.msg("Test message", i)

log.msg("Last message")

As log_rotation.py runs, messages will be logged to /tmp/test.log. When the logs are rotated manually or rotateLength is met, the existing log numbers are incremented (e.g., /tmp/test.log.1 becomes /tmp/test.log.2, and /tmp/test.log becomes /tmp/test.log.1) and a fresh /tmp/test.log is produced. By the end, “First message” is in the oldest log, /tmp/test.log.2, and “Last message” is in /tmp/test.log.

Since daily log rotation is such a common action, Twisted also has a DailyLogFile class that will auto-rotate logs each day.

twistd Logging

As we saw in Chapter 6, Twisted applications run with twistd utilize Twisted’s logging by default, printing to twistd.log if daemonized or to stdout if not.

twistd’s built-in logging can be customized through command-line arguments: specify a log file with --logfile (use - for stdout) and pass --syslog to log to syslog instead of a log file.

For further customization of logging, including changing the log prefix (by default, a timestamp like 2012-08-20 22:08:34-0400), we’ll need to implement our own LogObserver.

Custom Loggers

As an example, what if we wanted a logger that logged to stdout and colored error messages red? Example 7-4 demonstrates how to subclass FileLogObserver and override the emit method to achieve this.

Example 7-4. log_colorizer.py
import sys

from twisted.python.log import FileLogObserver

class ColorizedLogObserver(FileLogObserver):
    def emit(self, eventDict):
        # Reset text color.
        self.write("\033[0m")

        if eventDict["isError"]:
            # ANSI escape sequence to color text red.
            self.write("\033[91m")

        FileLogObserver.emit(self, eventDict)

def logger():
    return ColorizedLogObserver(sys.stdout).emit

FileLogObserver.emit is an observer. Whenever log.msg or log.err is called, observers registered through log.addObserver receive that event. You can register as many observers as you want, so a single event can be processed in many ways.

startLogging and twistd call log.addObserver under the hood. As an example of registering your own observer, we can add ColorizedLogObserver’s colorized alert logging to our logging test from Example 7-2, as shown in Example 7-5.

Example 7-5. colorized_logging_test.py
import sys
from twisted.python import log
from log_colorizer import ColorizedLogObserver

observer = ColorizedLogObserver(sys.stdout)
log.addObserver(observer.emit)

log.msg("Starting experiment")

log.msg("Logging an exception")

try:
    1 / 0
except ZeroDivisionError, e:
    log.err(e)

log.msg("Ending experiment")

The only change we had to make to use our custom logger was registering an instance of ColorizedLogObserver with log.addObserver.

We can also use ColorizedLogObserver as a custom logger for twistd programs by passing a log observer factory (i.e., the emit method of an instance of a LogObserver) through the --logger command-line option. For example, to run our echo_server.tac from Chapter 6 with colorized logging to stdout, we could use this command line:

twistd -ny echo_server.tac --logger=log_colorizer.logger --logfile=-

The hyphen at the end of --logfile=- specifies logging to stdout. -n says don’t daemonize.

Key Facts and Caveats About Logging

Here are some things to keep in mind regarding logging in Twisted: