Overview

Python's logging capabilities are powerful and flexible, but can be complicated to effectively implement. Moreover, logging in web2py introduces a new problem set. This slice offers an approach for effective logging in web2py, leveraging Python's native logging functionality

Logging in Python

Python's native logging framework uses a logger-handler combination, whereby one or more loggers each logs to one or more handlers. The logging framework uses a singleton model for its loggers, so that logging.getLogger('name') will return a single global Logger instance by that name, instantiating it only on first access. By default, a Python process will start out with a single root logger (name == "") with a single handler logging to stdout.

Logging in web2py

Logging in web2py involves some new issues:

1. We want to be able to configure and control logging at the application level
2. We want to be able to configure a logger once and only once
3. We want a simple syntax to perform logging across the app

1) Application Logging:

Python's native logging framework already maintains a global set of named loggers per process. But in web2py, because applications run within the same process, loggers are shared across apps. We need a different solution if we want to configure and control loggers on an app-specific basis.

An easy way to create app-specific loggers is by including the application name in the name of the logger.

logging.getLogger(request.application)

The same code used across multiple apps will now return separate loggers for each app.

2) One-time configuration:

We want to be able to configure a logger once on start up. However, when accessing a named logger, Python doesn't provide a way to check if the logger already exists.

The simplest way to ensure a logger is configured only once is to check if it has any handlers:

def get_configured_logger(name):
    logger = logging.getLogger(name)
    if (len(logger.handlers) == 0):
        # This logger has no handlers, so we can assume it hasn't yet been configured.
        # (Configure logger)
    return logger

(NOTE: If loggername == "", you will retrieve Python's root logger. The default root logger already has a handler associated with it, so you would check for a handler count of 1. The root logger can't be made app-specific.)

3) Easy syntax:

Of course, we don't want to have to call get_configured_logger everytime we make a log entry. Instead, we can make a global assignment once in the model, and use it throughout our app. The assignment will be executed every time you use the logger in your controller, but instantiation and configuration will only happen on first access.

In model:

import logging, logging.handlers

def get_configured_logger(name):
    logger = logging.getLogger(name)
    if (len(logger.handlers) == 0):
        # This logger has no handlers, so we can assume it hasn't yet been configured
        # (Configure logger)
    return logger

# Assign application logger to a global var  
logger = get_configured_logger(request.application)

In controllers:

logger.debug('debug this')
logger.info('info this')

Examples

Full model code with default configurations:

import logging, logging.handlers

class GAEHandler(logging.Handler):
    """
    Logging handler for GAE DataStore
    """
    def emit(self, record):

        from google.appengine.ext import db

        class Log(db.Model):
            name = db.StringProperty()
            level = db.StringProperty()
            module = db.StringProperty()
            func_name = db.StringProperty()
            line_no = db.IntegerProperty()
            thread = db.IntegerProperty()
            thread_name = db.StringProperty()
            process = db.IntegerProperty()
            message = db.StringProperty(multiline=True)
            args = db.StringProperty(multiline=True)
            date = db.DateTimeProperty(auto_now_add=True)

        log = Log()
        log.name = record.name
        log.level = record.levelname
        log.module = record.module
        log.func_name = record.funcName
        log.line_no = record.lineno
        log.thread = record.thread
        log.thread_name = record.threadName
        log.process = record.process
        log.message = record.msg
        log.args = str(record.args)
        log.put()

def get_configured_logger(name):
    logger = logging.getLogger(name)
    if (len(logger.handlers) == 0):
        # This logger has no handlers, so we can assume it hasn't yet been configured
        # (Configure logger)

        # Create default handler
        if request.env.web2py_runtime_gae:
            # Create GAEHandler
            handler = GAEHandler()
        else:
            # Create RotatingFileHandler
            import os
            formatter="%(asctime)s %(levelname)s %(process)s %(thread)s %(funcName)s():%(lineno)d %(message)s"
            handler = logging.handlers.RotatingFileHandler(os.path.join(request.folder,'private/app.log'),maxBytes=1024,backupCount=2)
            handler.setFormatter(logging.Formatter(formatter))

        handler.setLevel(logging.DEBUG)

        logger.addHandler(handler)
        logger.setLevel(logging.DEBUG)

        # Test entry:
        logger.debug(name + ' logger created')
    else:
        # Test entry:
        logger.debug(name + ' already exists')

    return logger

# Assign application logger to a global var  
logger = get_configured_logger(request.application)

Resources

• Python Logging
• Custom Handlers (GAEHandler, SQLiteHandler)

Acknowlegements

This was derived from code originally submitted to the global logging to file thread in the web2py users group by users Hans and Iceberg. Thanks-