Logging Events and Errors

Server logfiles provide an important way to keep track of what's going on in your application. Logfiles let you see how many users your application has, how frequently it's being used, and what it's being used for. Logfiles also collect errors and debugging information, making it much easier to track down problems.

As Example 11-2 demonstrated, twistd creates a logfile named twistd.log automatically. By default, this logfile will capture several useful kinds of information. First, it will store anything that your application normally writes to stdout, including print statements. Second, it will record tracebacks for any uncaught exceptions. Third, it will capture log messages generated by twisted modules; many of the modules in Twisted automatically log events that you're likely to be interested in.

It's nice that twistd does all this for you, but sometimes you need more control. For example, you might have code in your application that catches exceptions and reports them to the user. twistd won't log these exceptions for you, but you might want to capture the tracebacks for debugging. It can also be a chore to wade through a giant logfile containing a mix of usage reporting, debug messages, and errors. This is especially true for error messages: if everything is in the same file, the only way to tell whether your application is generating errors is to search through the file. It's much better to divert error messages to their own log: that way you can just glance at the file to see whether it has any contents and you'll know immediately whether your application is generating errors.

Twisted included a framework for logging that you can use to generate your own log messages. Using the Twisted logging framework also gives you more control over how log events and logfiles are managed, so you can do things like keep separate logfiles for different types of events.

11.4.1. How Do I Do That?

Use the twisted.python.log module to generate log messages. Use the twisted.python.logfile module to write logfiles to disk and rotate logfiles. Example 11-5 demonstrates a Protocol that logs user activity and exceptions, and shows how to log errors to a separate file.

Example 11-5. logger.py

from twisted.internet import protocol from twisted.protocols import basic from twisted.application import service, internet from twisted.python import log, logfile import time class ChatProtocol(basic.LineReceiver): def lineReceived(self, line): log.msg("Got command:", line) parts = line.split( ) cmd = parts[0] args = parts[1:] if hasattr(self, 'do_'+cmd): try: getattr(self, 'do_'+cmd)(*args) except Exception, e: log.err(e) self.sendLine("Error: %s" % e) else: log.msg("User sent invalid command", cmd, args) self.sendLine("Invalid command '%s'" % cmd) def do_time(self): self.sendLine(str(time.strftime("%x %X"))) def do_echo(self, *strings): self.sendLine(" ".join(strings)) def do_quit(self): self.transport.loseConnection( ) class ErrorLog(log.FileLogObserver): def emit(self, logEntryDict): if not logEntryDict.get('isError'): return log.FileLogObserver.emit(self, logEntryDict) class ErrLogService(service.Service): def _ _init_ _(self, logName, logDir): self.logName = logName self.logDir = logDir self.maxLogSize = 1000000 def startService(self): # logfile is a file-like object that supports rotation self.logFile = logfile.LogFile( self.logName, self.logDir, rotateLength=self.maxLogSize) self.logFile.rotate( ) # force rotation each time restarted self.errlog = ErrorLog(self.logFile) self.errlog.start( ) def stopService(self): self.errlog.stop( ) self.logFile.close( ) del(self.logFile) application = service.Application("LogDemo") # quick and dirty way to create a service from a protocol chatFactory = protocol.ServerFactory( ) chatFactory.protocol = ChatProtocol chatService = internet.TCPServer(2323, chatFactory) chatService.setServiceParent(application) ERR_LOG_DIR = "." # use an absolute path for real apps ERR_LOG_NAME = "chaterrors.log" ErrLogService(ERR_LOG_NAME, ERR_LOG_DIR).setServiceParent(application)

Run the logger.py application in Example 11-5 using twistd:

$ twistd -noy logger.py 2005/06/23 15:27 PDT [-] Log opened. 2005/06/23 15:27 PDT [-] twistd 2.0.0 (/usr/bin/python2.3 2.3.5) starting up 2005/06/23 15:27 PDT [-] reactor class: twisted.internet.selectreactor.SelectReactor 2005/06/23 15:27 PDT [-] Loading logger.py... 2005/06/23 15:27 PDT [-] Loaded. 2005/06/23 15:27 PDT [-] twisted.internet.protocol.ServerFactory starting on 2323 2005/06/23 15:27 PDT [-] Starting factory

It will start a server on port 2323. You can connect to this server using Telnet and issue the commands time, echo, and quit. If you attempt to call a command with the wrong syntax, the server will raise an exception, and you'll get an error message:

$ telnet localhost 2323 Trying 127.0.0.1... Connected to sparky. Escape character is '^]'. time 06/23/05 15:22:41 echo hello hello time time Error: do_time( ) takes exactly 1 argument (2 given) quit Connection closed by foreign host.

Meanwhile, the server will be printing its log to stdout for you to see:

2005/06/23 15:27 PDT [ChatProtocol,0,127.0.0.1] Got command: time 2005/06/23 15:27 PDT [ChatProtocol,0,127.0.0.1] Got command: echo hello 2005/06/23 15:27 PDT [ChatProtocol,0,127.0.0.1] Got command: time time 2005/06/23 15:27 PDT [ChatProtocol,0,127.0.0.1] Traceback (most recent call last): Failure: exceptions.TypeError: do_time( ) takes exactly 1 argument (2 given) 2005/06/23 15:27 PDT [ChatProtocol,0,127.0.0.1] Got command: quit

Shut down the server, and there should be a file in the same directory named chaterrors.log. This file will contain only the exceptions that were logged:

$ cat chaterrors.log 2005/06/23 15:25 PDT [ChatProtocol,0,127.0.0.1] Traceback (most recent call last): Failure: exceptions.TypeError: do_time( ) takes exactly 1 argument (2 given)

11.4.2. How Does That Work?

The ChatProtocol class in Example 11-5 uses the functions twisted.python.log.msg and twisted.python.log.err. These are used to write log messages to the default log. log.msg takes a series of strings and writes them on a single line; log.err takes an Exception or twisted.python.Failure object and writes the traceback.

The lineReceived method of chatProtocol tries to perform a method call based on the command sent from the client. If this method call raises an exception, it sends an error message to the client. But it also calls log.err with the exception. This step creates a record in the logfile containing the exception and a full traceback.

The ErrorLog class in Example 11-5 is a subclass of log.FileLogObserver. FileLogObserver is an object that observes log events and writes them to a file. The emit method is called with a dictionary containing information about the log message. If the log message is an error, it will have a true value for the key isError. ErrorLog uses the isError key to filter out log messages that aren't errors.

The ErrLogService class implements a service that uses the ErrorLog class to get any errors being logged and write them to a separate file. Instead of just passing an open file handle to ErrorLog, ErrorLogService passes a twisted.python.logfile.LogFile object. A LogFile object represents a rotating logfile. When the logfile reaches a certain size, or when you call LogFile.rotate, LogFile moves the current logfile to a file named filename.1, and starts using a fresh file. If filename.1 exists, the current filename.1 will be renamed filename.2, and so on. You initialize a LogFile object with two arguments: the directory where the logfiles should be stored and the name of the logfile. You can also pass an optional rotateLength keyword argument to set the size at which the logfile should be rotated.