P2P Research Institute Blog

Here at P2P Research, we have numerous long-running software agents written mostly in Python, which crawl BitTorrent and perform various types of analysis. While these agents are relatively robust, every few months they might hiccup – perhaps not even from a condition within their control, like a full disk.

In any case, we want these agents to be running as much as possible. If any of the agents exits for some reason, we want to know about it. One of the most important pieces in any production software system is robust logging. Long-running daemon processes should at a minimum log to an on-disk file in a clean, consistent format with timestamps. After very basic logging, the next requirement is some log rotation scheme, to prevent the disk from filling up with logs, and perhaps the introduction of log levels, to make it easy to distinguish warnings from critical events from debug events and so on.

Fortunately with Python’s logging module makes this trivial to implement. Where you might usually use a print statement in debugging, you just use one of the logging functions. Instead of

1

print >> stderr, "message"

you probably want

1

logging.warn("message")

or

1

logging.critical("message")

Setting up rotated logging is very easy, since Python has the RotatedFileHandler already implemented in its standard library. To set it up for use in your program, you can add something like the following snippet:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16

# Rotated logging setup snippet
import logging
from logging.handlers import RotatingFileHandler
 
LOG_FILE='/path/to/logfile'
LOG_FORMAT='%(asctime)s %(levelname)s %(message)s'
MAX_BYTES=1024 * 100 # 100KB
BACKUP_COUNT=10
 
# ...
 
rotating_handler = RotatingFileHandler(LOG_FILE, 'a',MAX_BYTES, BACKUP_COUNT)
rotating_handler.setFormatter(logging.Formatter(LOG_FORMAT))
logging.getLogger().addHandler(rotating_handler)
 
logging.info("Logging setup complete")

Logging to disk is a great start. But what if you want to notify a human if something goes horribly wrong? We can define “horribly wrong” as logging.crit(), and set up a SMTPHandler to send email whenever this happens:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20

# Email logging setup snippet
import logging
from logging.handlers import SMTPHandler
LOG_FORMAT='%(asctime)s %(levelname)s %(message)s'
# who do we send the log email to
TO_LIST=['admin@example.com', 'me@mydomain.com']
# who is it from
FROM='agent@example.com'
# subject template
SUBJECT='[my agent] Critical event'
# SMTP server
SMTP_SERVER='localhost'
 
# ...
 
# smtp handler, only logs on CRITICAL level messages
smtp_handler = logging.handlers.SMTPHandler(SMTP_SERVER, FROM, TO_LIST, SUBJECT)
smtp_handler.setLevel(logging.CRITICAL)
smtp_handler.setFormatter(logging.Formatter(LOG_FORMAT))
logging.getLogger().addHandler(smtp_handler)

Now we are configured to send notices via email on any critical event. However, what do we do about uncaught exceptions which don’t have a logging.critical() handler, and the interpreter just exits? We install our own uncaught exception handler, which calls logging.critical(), of course!

1
2
3
4
5
6
7
8

# Snippet to setup custom uncaught exception handler
import sys
def except_hook(type, value, tb):
    ''' handler for exceptions which would cause the interpreter to exit '''
    logging.critical("Uncaught exception of type `%s' with value '%s'" %(type, value))
    os._exit(1)
 
sys.excepthook = except_hook

And there you have it!