Python logging in Django

Question

I'm developing a Django app, and I'm trying to use Python's logging module for error/trace logging. Ideally I'd like to have different loggers configured for different areas of the site. So far I've got all of this working, but one thing has me scratching my head.

I have the root logger going to sys.stderr, and I have configured another logger to write to a file. This is in my settings.py file:

sviewlog = logging.getLogger('MyApp.views.scans')
view_log_handler = logging.FileHandler('C:\MyApp\logs\scan_log.log')
view_log_handler.setLevel(logging.INFO)
view_log_handler.setFormatter(logging.Formatter('%(asctime)s %(name)-12s %(levelname)-8s %(message)s'))
sviewlog.addHandler(view_log_handler)

Seems pretty simple. Here's the problem, though: whatever I write to the sviewlog gets written to the log file twice. The root logger only prints it once. It's like addHandler() is being called twice. And when I put my code through a debugger, this is exactly what I see. The code in settings.py is getting executed twice, so two FileHandlers are created and added to the same logger instance. But why? And how do I get around this?

Can anyone tell me what's going on here? I've tried moving the sviewlog logger/handler instantiation code to the file where it's used (since that actually seems like the appropriate place to me), but I have the same problem there. Most of the examples I've seen online use only the root logger, and I'd prefer to have multiple loggers.

question from:https://stackoverflow.com/questions/342434/python-logging-in-django

Answer 1

Allow me to answer my own question. The underlying problem here is that settings.py gets imported twice, or maybe even more (See here). (I still don't understand why this is. Maybe some Django expert could explain that to me.) This seems to be true of some other modules as well. At this point I don't think it's wise to make assumptions about how many times settings.py will be imported. For that matter, such assumptions aren't safe in general. I've had this code in places other than settings.py, and the results are similar.

You have to code around this. That is, you have to check your logger for existing handlers before adding additional handlers to it. This is a bit ugly because it's perfectly reasonable to have multiple handlers -- even of the same type -- attached to one logger. There are a few solutions to dealing with this. One is check the handlers property of your logger object. If you only want one handler and your length > 0, then don't add it. Personally I don't love this solution, because it gets messy with more handlers.

I prefer something like this (thanks to Thomas Guettler):

# file logconfig.py
if not hasattr(logging, "set_up_done"):
    logging.set_up_done=False

def set_up(myhome):
    if logging.set_up_done:
        return
    # set up your logging here
    # ...
    logging.set_up_done=True

I must say, I wish the fact that Django imports settings.py multiple times were better documented. And I would imagine that my configuration is somehow cause this multiple import, but I'm having trouble finding out what is causing the problem and why. Maybe I just couldn't find that in their documents, but I would think that's the sort of thing you need to warn your users about.