Strange behaviour in Django logging (Django 1.3 RC)

I'm getting a strange behaviour when setting up logging. Here's my logging configuration:

LOGGING =
{
    'version': 1,
    'disable_existing_loggers': True,
    'formatters': {
        'admin_configuration': {
            'format': '%(asctime)s %(levelname)s %(category)s % (sub_category)s %(type_id)s %(message)s',
            'datefmt': LOG_DATE_FORMAT,
        },
    },
    'handlers': {
        'admin_console': {
            'level':'DEBUG',
            'class':'logging.StreamHandler',
            'formatter': 'admin_configuration'
        },
        'db': {
            'level':'DEBUG',
            'class':'apps.history.handlers.DatabaseHandler',
            'formatter': 'admin_configuration'
        },
    },
    'loggers': {
        'db_logger': {
            'handlers': [ 'admin_console', 'db' ],
            'level': 'DEBUG',
            'propagate': False,
        },
    }    
}

I then created a Database log handler and the log record will be created using signals (e.g. on model save/delete) because I'm trying to keep track of model changes. As you can see from my config, the logger has 2 handlers, 1 for DB and 1 for stdout (stream handler).

I use the logger this way:

logging.getLogger('db_logger').log(level, msg, extra=extras)

where extras are extra attributes I'm passing to the logger.

Now the weird thing is, when I change the order of 'handlers' definition under 'db_logger' to ['db', 'admin_console'], the logger raises this error inside my DatabaseHandler (see below for definition):

LogRecord instance has no attribute 'asctime'

After checking the record instance, 'message' attribute was not generated either, but all of my extra attributes were there. The same error happens if I remove 'admin_console' handler. The only way I can get the logger to work is that the handler must be in the original order: 'handlers': [ 'admin_console', 'db' ]

Traceback:

File "/usr/local/lib/python2.6/dist-packages/django/core/handlers/
base.py" in get_response
  89.                     response = middleware_method(request)
File "/home/user/projects/django/../django/common/middleware.py" in
process_request
  27.             return login(request, **defaults)
File "/usr/local/lib/python2.6/dist-packages/django/utils/
decorators.py" in _wrapped_view
  93.                     response = view_func(request, *args,
**kwargs)
File "/usr/local/lib/python2.6/dist-packages/django/views/decorators/
cache.py" in _wrapped_view_func
  79.         response = view_func(request, *args, **kwargs)
File "/home/user/projects/django/../django/apps/django_extra_auth/
views.py" in login
  57.             auth_login(request, form.get_user())
File "/usr/local/lib/python2.6/dist-packages/django/contrib/auth/
__init__.py" in login
  85.     user_logged_in.send(sender=user.__class__, request=request,
user=user)
File "/usr/local/lib/python2.6/dist-packages/django/dispatch/
dispatcher.py" in send
  172.             response = receiver(signal=self, sender=sender,
**named)
File "/usr/local/lib/python2.6/dist-packages/django/contrib/auth/
models.py" in update_last_login
  50.     user.save()
File "/usr/local/lib/python2.6/dist-packages/django/db/models/base.py"
in save
  460.         self.save_base(using=using, force_insert=force_insert,
force_update=force_update)
File "/usr/local/lib/python2.6/dist-packages/django/db/models/base.py"
in save_base
  570.                 created=(not record_exists), raw=raw,
using=using)
File "/usr/local/lib/python2.6/dist-packages/django/dispatch/
dispatcher.py" in send
  172.             response = receiver(signal=self, sender=sender,
**named)
File "/home/user/projects/django/apps/history/audit.py" in
post_save_handler
  102.             logging.log_to_db(logging.INFO, msg, log_type)
File "/home/user/projects/django/apps/history/__init__.py" in
log_to_db
  61.         db_logger.log(level, msg, extra=extras)
File "/usr/lib/python2.6/logging/__init__.py" in log
  1119.             self._log(level, msg, args, **kwargs)
File "/usr/lib/python2.6开发者_高级运维/logging/__init__.py" in _log
  1173.         self.handle(record)
File "/usr/lib/python2.6/logging/__init__.py" in handle
  1183.             self.callHandlers(record)
File "/usr/lib/python2.6/logging/__init__.py" in callHandlers
  1220.                     hdlr.handle(record)
File "/usr/lib/python2.6/logging/__init__.py" in handle
  679.                 self.emit(record)
File "/home/user/projects/django/apps/history/handlers.py" in emit
  11.         timestamp = datetime.strptime(record.asctime,
settings.LOG_DATE_FORMAT)

DB Logger Wrapper

def log_to_db(self, level, msg, log_type, extra={}):
    db_logger = logging.getLogger('db_logger')
    extras = {
        'category': log_type.category.name,
        'sub_category': log_type.sub_category.name,
        'type_id': log_type.type_id,
    }
    extras.update(extra)
    db_logger.log(level, msg, extra=extras)

DB Handler

class DatabaseHandler(logging.Handler):
    def emit(self, record):
        user = getattr(record, 'user', None)
        category = getattr(record, 'category', None)
        sub_category = getattr(record, 'sub_category', None)
        type_id = getattr(record, 'type_id', None)
        timestamp = datetime.strptime(record.asctime, settings.LOG_DATE_FORMAT)
        from history.models import LogRecord
        LogRecord.objects.create(timestamp=timestamp, level=record.levelname,
            category=category, sub_category=sub_category, type_id=type_id,
            message=record.message, user=user) 

Any idea why this is happening?

You have to call self.format(record) in DatabaseHandler.emit() and formatter will set these variables for you.

You may want to check this app: https://github.com/zain/jogging