Tuesday, November 2, 2010

Python and Django Logging That Will Make Your Operations Staff Happy

Python’s "batteries included" mentality means Python comes with a great logging facility. Unfortunately, not enough people use it, or dig deep enough into it. I have put some mileage on it in my time, so I would like to share all my tips for making your lives – and those of your system administrators – a lot easier.

First, a little primer. The logging module is essentially a singleton that you fetch (not instantiate) and configure with pluggable handlers for log message routing. You can set any logging level (DEBUG, INFO, WARNING, ERROR, and CRITICAL) you want for each handler, and you can set a global level that encompasses all handlers.

# First you get it and give it a name
logger = logging.getLogger('whatever_name_you_want')
# Give it a global logging level
logger.setLevel(logging.DEBUG)
# Now a formatter, let's make it look good, see docs for more information
formatter = logging.Formatter('%(asctime)s %(levelname)s %(message)s')
# Create a file handler that receives warnings or worse
file_handler = logging.FileHandler('error_log.txt')
file_handler.setFormatter(formatter)
file_handler.setLevel(logging.DEBUG)
logger.addHandler(file_handler)

# Now we use it
logger.debug('Config file loaded A-OK!')
logger.info('New user added perfectly!')
logger.warning('We are running out of space, get the junior admin with the peach fuzz beard.')
logger.error('Find me a sys admin with at least a neck beard.')
logger.critical('Big beard required immediately. Get Gandalf the Admin!')
# Works that same as logger.error but format's exceptions
try:
    exception_throwing_function()
except Exception, e:
    logger.exception(e)

Now you have logging, but it doesn't really go anywhere. This will anger the admins, I know, I have worked with a lot of them. Difficulty tracking down errors is one of the number reasons why you end up fixing it yourself. If you give them the heads up, and a way to look inside to see what's happening, then they will do what they do best: fixing things. Remember, maintenance staff are users to. Fortunately, those great logging handlers come in lots of different flavors. By combining the right ones together you can get all the functionality you ever dreamed off:
  1. StreamHandler instances send error messages to streams (file-like objects).
  2. FileHandler instances send error messages to disk files.
  3. BaseRotatingHandler is the base class for handlers that rotate log files at a certain point. It is not meant to be instantiated directly. Instead, use RotatingFileHandler or TimedRotatingFileHandler.
  4. RotatingFileHandler instances send error messages to disk files, with support for maximum log file sizes and log file rotation.
  5. TimedRotatingFileHandler instances send error messages to disk files rotating the log file at certain timed intervals.
  6. SocketHandler instances send error messages to TCP/IP sockets.
  7. DatagramHandler instances send error messages to UDP sockets.
  8. SMTPHandler instances send error messages to a designated email address.
  9. SysLogHandler instances send error messages to a Unix syslog daemon, possibly on a remote machine.
  10. NTEventLogHandler instances send error messages to a Windows NT/2000/XP event log.
  11. MemoryHandler instances send error messages to a buffer in memory, which is flushed whenever specific criteria are met.
  12. HTTPHandler instances send error messages to an HTTP server using either "GET" or "POST” semantics.
I find most operations have the same requirements when it comes to error management:
  1. Logging of errors.
  2. A feed of debugging information.
  3. Notifications of serious errors.
  4. Don't fill the disk with logs!
I find these needs can best be met with the FileHandler, RotatingFileHandler, and the SMTPHandler. So lets add them:

# Permanent logging of serious errors
file_handler = logging.FileHandler('error_log.txt')
file_handler.setFormatter(formatter)
file_handler.setLevel(logging.WARN)
logger.addHandler(file_handler)

# A rolling file handler with a lower threshold so you can listen in
# Set a maximum size so you don't fill the disk
rolling_handler = logging.handlers.RotatingFileHandler('rolling_log.txt', maxBytes=52428800)
rolling_handler.setFormatter(formatter)
rolling_handler.setLevel(logging.DEBUG)
logger.addHandler(rolling_handler)

# Email serious errors
smtp_handler = logging.handlers.SMTPHandler('localhost', 'from_server_10@domain.com', 'to_neck_beard@ops.com', 'Subject: Error')
smtp_handler.setFormatter(formatter)
smtp_handler.setLevel(logging.WARN)
logger.addHandler(smtp_handler)

Now all the serious errors get routed to a permanent file and mailed to operations staff, and debugging info goes to a size managed log that admins can follow (tail –f):

2010-06-28 16:18:1,434 DEBUG Config file loaded A-OK!
2010-06-28 16:18:1,964 INFO New user added perfectly!
2010-06-28 16:18:1,970 WARNING Could not connect to application server
2010-06-28 16:18:2,239 WARNING Could not connect to application server
2010-06-28 16:18:2,339 WARNING Could not connect to application server
2010-06-28 16:18:2,439 WARNING Could not connect to application server

Uh oh, looks like we have a problem. Someone changed the hostname of a service. Go-go Unix beard!

2010-06-28 16:18:2,445 DEBUG SIGHUP Trapped, reloading config file
2010-06-28 16:18:3,434 DEBUG Config file loaded A-OK!
2010-06-28 16:18:4,434 DEBUG Successfully connected to application server

Fixed!

“Now, what about Django? The title has Django in it, and I know it has a built in error mailer?” Well, it does, but it just mails you the exception and gives the user a 500 error. If you want to give your users' nicer errors, or if you are exposing an XML-RPC/SOAP/REST API, then you are going to want to handle it better than a 500 page. You need to trap and log your exceptions, and throw out there something that is prettier, like an appropriate SOAP fault if this were a SOAP server.

This is done best in two ways: right in your views or by setting up some middleware with a process_exception() method. For our purposes, I will keep it simple and do it right in the view. You do exactly the same as you would above, with one exception. Django is multithreaded, while the logging module behaves like a singleton. This means you can end up setting too many handlers and getting duplicate log entries. The best way around this is to take advantage of the log modules singleton behavior:

# Check inside the module itself if you have set it up already
if not hasattr(logging, 'set_up_done’):
    logging.set_up_done = False
# Get your reference 
logger = logging.getLogger('whatever_name_you_want ')
if not logging.set_up_done:
    # Set levels, create handlers like above
    .
    .
    .
    # Make sure you tell it you have set it up already
    logging.set_up_done = True

Another Django tip: add a console handler so you can get a tail like feed of what is happening during development right in the development server console.

console_handler = logging.StreamHandler()
console_handler.setFormatter(formatter)
console_handler.setLevel(logging.DEBUG)
logger.addHandler(console_handler)

Finally, one the major advantages of using the logging module is that you not only see the messages from your code, but all the Python modules you import. This is due to the logging modules previously mentioned singleton behavior and “batteries included” approach of Python. A lot modules (native and third party) use it, so you see their errors show up in your logs to, and you get a much better clue of what is going wrong.

1 comment:

  1. log = logging.getLogger(__name__) # insta-profit.

    ReplyDelete