Python Cookbook

Logging and Tracing Across Platforms

Credit: Luther Blissett

Problem

You have a program that needs to run on both Windows and Unix, and you want to trace and/or log output (typically for debugging) simply and flexibly.

Solution

You can rebind sys.stdout so that print statements will be logged and use a sophisticated class for the rebinding to ensure that auxiliary functionality such as automatic timestamping is done in a platform-independent way:

# tweakable timestamper callable
import time
class Timestamper:
    msg_format = "%y%m%d %H%M%S", time.localtime, "%s: %s"
    def _ _call_ _(self, msg):
        tfmt, tfun, gfmt = self.msg_format
        return gfmt%(time.strftime(tfmt,tfun(  )), msg)

# Bind name 'syslogger' to an output-to-system-log function (if any)
try: import syslog
except ImportError:
    try: import servicemanager
    except ImportError:
        # no logging available -- maybe OutputDebugString?
        try: import win32api
        except ImportError: # none, give up and use a dummy function
            def syslogger(msg): pass
        else:
            timestamp = Timestamper(  )
            def syslogger(msg): win32api.OutputDebugString(timestamp(msg))
    else: syslogger = servicemanager.LogInfoMsg
else: syslogger = syslog.syslog

class FunctionFilelikeWrapper:
    def _ _init_ _(self, func):
        self.func = func
    def write(self, msg):
        self.func(msg)

syslogfile = FunctionFilelikeWrapper(syslogger)

class TeeFilelikeWrapper:
    def _ _init_ _(self, *files):
        self.files = files
    def write(self, msg):
        for f in self.files: f.write(msg)

class FlushingWrapper:
    def _ _init_ _(self, *files):
        self.files = files
    def write(self, msg):
        for f in self.files:
            f.write(msg)
            f.flush(  )

def logto(*files):
    sys.stdout = TeeFilelikeWrapper(*files)

Discussion

When you write a Windows NT service, you can log information to the system log with calls to functions in the servicemanager module. But servicemanager is a peculiar module that lives only in the special PythonService.Exe interpreter, so it’s not even available to nonservice programs on Windows, let alone non-Windows platforms. On Unix-like platforms, any Python program can do logging with the syslog module, but there is no such thing on Windows.

Another Windows possibility is OutputDebugString. For this, you need to have a system debugger running, but it can get debug strings from multiple sources and serialize them to a log display window and/or file. Of course, on any platform, you can also write to a file, as long as you make sure the file is unbuffered. According to the Python documentation, this works only if the underlying C library has setvbuf, or if you ensure that flush is called with each write (to avoid wondering if setvbuf is there).

Besides, I really like to use print statements, because they’re good for debugging. And sometimes, I like to see the tracing information that I’m logging for debugging purposes also appear on a terminal window or console (when my program has one of those, of course) in real time. I also like to send the information to a more permanent log (or file) for later analysis (and I want it timestamped, unless it’s going to a logging service, such as syslog, which will timestamp it for me).

This might seem like a tall order, but not with Python. The module in this recipe gives you all the bricks you need to build the debug-oriented output you need. Most of the time, I import logger, then call:

logger.logto(sys.stderr, logger.syslogfile, open("/tmp/mylog.txt","w"))

(Maybe I should be more punctilious and use the tempfile module to get the temporary file’s directory instead.) But the logger module also gives me all the tools for fine-tuning when I want them. Now, whenever I print something, it goes to the terminal (standard error) if one exists; to the syslog, if one exists (possibly OutputDebugString); and to a text file in the temporary directory, just in case.

When I want to call another function automatically to display something I print, I wrap it in a logger.FunctionFilelikeWrapper. And, of course, it’s easy to tweak and customize this recipe, since it is so utterly simple, adding whatever other bricks I frequently use.

The recipe shows how to use quite a few important Pythonic idioms:

• Using try/except around an import for conditional import purposes

• Using a do-nothing function that is callable without harm, rather than using None, which you have to test for before each call

• A Timestamper class that offers usable default class attributes (for such things as format strings) but accesses them via self, so they’re tweakable per instance, if needed

• File-like objects that wrap other objects, such as a function or a collection of other file-like objects.

Some of the idioms used in this recipe are generalized or explained further in other recipes in this book. For example, the do-nothing function is vastly generalized and extended in the Null Object design pattern (see Recipe 5.24). But seeing the various Pythonic pieces work together like this, albeit in a more restricted setting, can help understand them better. Besides, this recipe does make logging and tracing much easier and more pleasant.

This discussion concludes with a few principles of operation. Starting from the end, the logto function accepts any number of arguments, passes them to the constructor of a new instance of the TeeFilelikeWrapper class, and assigns that instance as the new value of the sys.stdout system variable, which is the standard output of any Python program. The print statement emits what you are printing to whatever object is referenced by sys.stdout, and all it asks of that object is that it expose a callable attribute (method) named write, which takes a string argument. (It also requires that an attribute named softspace be settable and gettable for print’s own internal purposes, but that’s no problem as long as you use normal instance objects, since arbitrary attributes can be set and retrieved from such instances).

The TeeFilelikeWrapper class has an instance constructor that accepts an arbitrary sequence of files (arbitrary objects with a write method, as above) and saves the sequence as the self.files instance member. The write method loops on self.files, making identical write calls on each. We could use an amusing variation on this theme by extracting the write methods at initialization and calling them in write. This has two advantages: earlier failure if we pass an object to _ _init_ _ without a write method by mistake, and better performance by avoiding the method extraction on each write call. Neither is a huge advantage, and a beginner might find the approach confusing, so I’ve stuck with the obvious approach in the recipe, but for completeness, here is the alternative:

class TeeFilelikeWrapper:
    def _ _init_ _(self, *files):
        self.write_methods = [ f.write for f in files ]
    def write(self, msg):
        for w in self.write_methods: w(msg)

The FlushingWrapper class is just like TeeFilelikeWrapper, but after write, it also calls flush on each of the file objects it’s wrapping to ensure that output has actually occurred.

The FunctionFilelikeWrapper class wraps a function (actually any callable object), which it receives in the instance constructor, as a file-like object, translating each call to write into a call to the function it wraps. The code in the recipe just before the definition of this class tries to determine the best function to use as syslogger. The try/except statements around import statements ensure that we use syslog.syslog on a Unix-like platform that supplies it, servicemanager.LogInfoMsg if the current program is a Python-coded Win32 service, OutputDebugString for other Win32 programs, or nothing at all (a do-nothing function, to be precise) if none of these conditions is satisfied.

With OutputDebugString, a timestamp object is also used, specifically to ensure that a timestamp accompanies each message being logged (not needed if we’re using a real logging system, be it syslog or one of Win32’s, since the timestamping will be done by the system). For this purpose, we also have a Timestamper class that we instantiate. Alternatively, a simple timestamp function might be defined and used, but a class has the added value of being tweakable. If elsewhere we need other timestamping but with a different format, or a different way to obtain the time, we can still use Timestamper by setting an instance’s value for msg_format appropriately.

See Also

Recipe 5.24 for a much more generalized version of the do-nothing function; documentation for the syslog module in the Library Reference; the manpages for syslog on your system; documentation for servicemanager and win32api in win32all (http://starship.python.net/crew/mhammond/win32/Downloads.html) or ActivePython (http://www.activestate.com/ActivePython/); Windows API documentation available from Microsoft (http://msdn.microsoft.com).