Different behavior of python logging module when using mod_python

Question

We have a nasty problem where we see that the python logging module is behaving differently when running with mod_python on our servers. When executing the same code in the shell, or in django with the runserver command or with mod_wsgi, the behavior is correct:

import logging
logger = logging.getLogger('site-errors')
logging.debug('logger=%s' % (logger.__dict__))
logging.debug('logger.parent=%s' % (logger.parent.__dict__))
logger.error('some message that is not logged.')

We then the following logging:

2009-05-28 10:36:43,740,DEBUG,error_middleware.py:31,[logger={'name': 'site-errors', 'parent': <logging.RootLogger instance at 0x85f8aac>, 'handlers': [], 'level': 0, 'disabled': 0, 'manager': <logging.Manager instance at 0x85f8aec>, 'propagate': 1, 'filters': []}]

2009-05-28 10:36:43,740,DEBUG,error_middleware.py:32,[logger.parent={'name': 'root', 'parent': None, 'handlers': [<logging.StreamHandler instance at 0x8ec612c>, <logging.handlers.RotatingFileHandler instance at 0x8ec616c>], 'level': 10, 'disabled': 0, 'propagate': 1, 'filters': []}]

As one can see, no handlers or level is set for the child logger 'site-errors'.

The logging configuration is done in the settings.py:

MONITOR_LOGGING_CONFIG = ROOT + 'error_monitor_logging.conf'

import logging
import logging.config

logging.config.fileConfig(MONITOR_LOGGING_CONFIG)

if CONFIG == CONFIG_DEV:
   DB_LOGLEVEL = logging.INFO
else:
   DB_LOGLEVEL = logging.WARNING

The second problem is that we also add a custom handler in the __init__.py that resides that in the folder as error_middleware.py:

import logging
from django.conf import settings
from db_log_handler import DBLogHandler

handler = DBLogHandler()
handler.setLevel(settings.DB_LOGLEVEL)
logging.root.addHandler(handler)

The custom handler cannot be seen in the logging!

If someone has idea where the problem lies, please let us know! Don't hesistate to ask for additonal information. That will certainly help to solve the problem.

Answer 1

It may be better if you do not configure logging in settings.py.

We configure your logging in our root urls.py. This seems to work out better. I haven't read enough Django source to know why, precisely, it's better, but it's working out well for us. I would add custom handlers here, also.

Also, look closely at mod_wsgi. It seems to behave much better than mod_python.

Answer 2

The problem is not solved by using mod_wsgi.

I could solve the problem by placing the complete configuration into one file. Mixing file and code configuration seems to create problems with apache (whether using mod_wsgi or mod_python).

To use a custom logging handler with file configuration, I had to do the following:

import logging
import logging.config
logging.custhandlers = sitemonitoring.db_log_handler
logging.config.fileConfig(settings.MONITORING_FILE_CONFIG)

From the settings.py I cannot import the sitemonitoring.db_log_handler, so I have to place this code in the root urls.py.

In the config file, I refer to the DBLogHandler with the following statement

[handler_db]
class=custhandlers.DBLogHandler()
level=ERROR
args=(,)

PS: Note that the custhandler 'attribute' is created dynamically and can have another name. This is an advantage of using a dynamic language.

Answer 3

You don't appear to have posted all the relevant information - for example, where is your logging configuration file?

You say that:

When executing the same code in the shell, or in django with the runserver command or with mod_wsgi, the behavior is correct

You don't make clear whether the logging output you showed is from one of these environments, or whether it's from a mod_python run. It doesn't look wrong - in your code you added handlers to the root, not to logger 'site-errors'. You also set a level on the handler, not the logger - so you wouldn't expect to see a level set for the 'site-errors' logger in the logging output, neh? Levels can be set on both loggers and handlers and they are not the same, though they filter out events in the same way.

The issue about custom handlers is easily explained if you look at the logging documentation for configuration, see

http://docs.python.org/library/logging.html (search for "the class entry indicates")

This explains that any handler class described in the configuration file is eval()'d in the logging packages namespace. So, by binding logging.custhandlers to your custom handlers module and then stating "custhandlers.MyCustomClass" in the config file, the eval() produces the expected result. You could just as well have done

logging.sitemonitoring = sitemonitoring

and specified the handler class as

sitemonitoring.db_log_handler.DBLogHandler

which would work just as well (as long as the db_log_handler subpackage has been imported already).

BTW the reason why people sometimes have problems configuring logging in settings.py is due to Django's import magic causing circular import problems. I generally configure logging in settings.py and it works fine unless you want to import certain bits of Django (e.g. in django.db - because the app import logic is in django.db, you can run into circular import issues if you try to import django.db.x in settings.py).