Today I realized something else cool I can do in Python that is very useful for developing programs that are not necessarily command-line interactive. For daemons, servers, and GUI applications, it is often the case that some logging of program events needs to be done.

Okay, let's take a concrete example. Say you're playing a game...

(Not actually written in Python)

And suddenly... it crashes. Why? Was it that new mod you added? Did someone hack you? Was it completely unrelated, and your computer ran out of memory? Did you forget to feed the kids and they unplugged your computer? Who knows?

Diagnosing a problem without a log of what happened can be frustrating. It's like solving a math problem, then being told that you got the wrong answer and you can't look at the solution to see where you went wrong. That is why most programs implement some way to log significant events, and especially errors. For example, the Apache webserver logs all access requests along with the IP accessing, and other relevant information. It also simplifies tech support calls by a lot: "Can you attach the file named 'errors.log' at this such-and-such' location?"

For most simple Python applications or scripts, it suffices to print out the output to the terminal, and to let the errors print themselves there if they need to, as well. But, what if you have a background process, like a daemon or server? My blog currently uses a weird piping mechanism to report errors. However, I've had trouble with it because it's not timestamped. When did I fail to parse this Unicode? Oops!

So, today I realized that the system stdout and stderr values in Python are mutable. That is, you can just set them to whatever you want. This means that if I do:

>>> import sys
>>> sys.stdout = open('foobar.txt', 'w')
>>> print "Hello, World!"

The text "Hello, World!" will appear in the foobar.txt file instead on the terminal prompt. Similarly, if I do:

>>> sys.stderr = open('errors.txt', 'w')
>>> Hello, World!

The contents of errors.txt will be:

File "<stdin>", line 1
  Hello, World!
              ^
SyntaxError: invalid syntax

That's useful, but it overwrites the system's setting for the output and error streams. It also doesn't timestamp the errors. But that's not hard to do. I whipped up a quick script to create a logger class that can bind and unbind itself from the system stdin and stdout, can optionally not print anything that's not an error message, and passes all output through a time-sensitive stream that inserts timestamps when appropriate.

Here's some sample usage:

import logger
log = logger.Logger(silent=False)

print("Hello, world!")
print("How are you today?")
print("I'm going to sleep for a few seconds")

from time import sleep
sleep(5)

print("Ahh, I'm all rested.")
print("Let's try to do some math!")

def do_some_math():
    raise ZeroDivisionError('OH, SHI-')

do_some_math()

The results are, in messages.log (the default stdout redirect):

-- 2010-07-03 20:06:50.269831 UTC --
Hello, world!
How are you today?
I'm going to sleep for a few seconds


-- 2010-07-03 20:06:55.275901 UTC --
Ahh, I'm all rested.
Let's try to do some math!

And, in error.log (default stderr redirect):

-- 2010-07-03 20:06:55.286658 UTC --
Traceback (most recent call last):
  File "logger-test.py", line 18, in <module>
    do_some_math()
  File "logger-test.py", line 16, in do_some_math
    raise ZeroDivisionError('OH, SHI-')
ZeroDivisionError: OH, SHI-

Of course, for less than an hour of coding, this is not a module ready to be deployed to everyone, nor is it very customizable. However, as usual, I share my source code in hopes that you can grab it and adapt it as you wish. The logger.py file is here. (Make sure to rename it to have a .py extension.)

And, as I get to the end of this blog entry, I realize that there already exists a Python logging module.

Sigh. Oh well. I hope this was educational anyway!