Django logging in version 1.4: How to correctly remove the require_debug_false filter from the mail_admin handler

There you are, configuring some shiny new django website of yours, and you want to test some of the logging features. And because you're testing in a development environment, you have DEBUG=True in your settings.py file. But the problem is, you're not seeing the admin logging emails you are expecting. So, you check the LOGGING variable in settings.py to see if you missed something. It looks something like this by default: 

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'filters': {
        'require_debug_false': {
            '()': 'django.utils.log.RequireDebugFalse',
        }
    },
    'handlers': {
        'mail_admins': {
            'level': 'ERROR',
            'filters': ['require_debug_false'],
            'class': 'django.utils.log.AdminEmailHandler'
        }
    },
    'loggers': {
        'django.request': {
            'handlers': ['mail_admins'],
            'level': 'ERROR',
            'propagate': True,
        },
    }
}

And there you see it. This section:

'handlers': {
    'mail_admins': {
        'level': 'ERROR',
        'filters': ['require_debug_false'],
        'class': 'django.utils.log.AdminEmailHandler'
    }
},

It looks like that handler is configured to do jack squat if DEBUG=True. "Ha!", you think to yourself. There's the problem. You just need to comment out that filter and all will be right with the world, cancer will be cured, and there will be no global warming apocalypse. So, you do something like this: 

'handlers': {
    'mail_admins': {
        'level': 'ERROR',
        #'filters': ['require_debug_false'],
        'class': 'django.utils.log.AdminEmailHandler'
    }
},

And when you retest the logging code that should send you an admin email, you get nothing. No change. Not one thing.

And then, you contemplate changing careers.

Well, don't worry, and step away from that thirteenth floor ledge...

If you do a little digging into the LOGGING dictionary while your Django site is running, you'll notice something interesting about that filter. It's extremely pernicious. If you remove it, it will refuse to go away. You can remove the filter from the handler (as above), and you can even remove the whole filter itself from the LOGGING dictionary, and it won't matter. In fact, depending on what you try, you may even find two or more of the same exact filter at run-time with slightly altered names. It's like a zombie filter. The thing just won't die.

The calm, rational, and rather banal reason for this sanity-eroding voodoo can be found here.

In short, Django 1.4 is coded to stick the filter back in if it's missing. This is done to mimic version 1.3, which didn't provide this optional filter, and instead simply never sent admin emails when DEBUG=True. This is great news for anyone with existing version 1.3 projects, because their websites work the same when they upgrade. It's probably not the best news for you, though, if you found this blog post only after creating a forehead-shaped dent in your desk.

If you want to see the bit of code responsible for your self-inflicted head injuries, check out the compat_patch_logging_config() function located in /path/to/python/site-packages/django/conf/__init__.py: 

def compat_patch_logging_config(logging_config):
    """
    Backwards-compatibility shim for #16288 fix. Takes initial value of
    ``LOGGING`` setting and patches it in-place (issuing deprecation warning)
    if "mail_admins" logging handler is configured but has no filters.

    """
    #  Shim only if LOGGING["handlers"]["mail_admins"] exists,
    #  but has no "filters" key
    if "filters" not in logging_config.get(
        "handlers", {}).get(
        "mail_admins", {"filters": []}):

        warnings.warn(
            "You have no filters defined on the 'mail_admins' logging "
            "handler: adding implicit debug-false-only filter. "
            "See http://docs.djangoproject.com/en/dev/releases/1.4/"
            "#request-exceptions-are-now-always-logged",
            PendingDeprecationWarning)

        filter_name = "require_debug_false"

        filters = logging_config.setdefault("filters", {})
        while filter_name in filters:
            filter_name = filter_name + "_"

        filters[filter_name] = {
            "()": "django.utils.log.RequireDebugFalse",
        }

        logging_config["handlers"]["mail_admins"]["filters"] = [filter_name]

Now take a moment of remorseful silence for yourself.

The Solution

Luckily, this problem is dead easy to fix. If you want to remove the filter (for real), you just need to specify an empty list of filters, instead of removing the whole line. It will look like this: 

'handlers': {
    'mail_admins': {
        'level': 'ERROR',
        'filters': [],
        'class': 'django.utils.log.AdminEmailHandler'
    }
},

That's it. Django will not second-guess your LOGGING configuration, and you'll get the behavior you expect.

But wait just one razzin-frazzin minute here...

I know. By this point, there are a few of you (the detail-oriented ones) who did actually read the bit of Django documentation or the function code above. And you noticed something which would have made this problem a lot simpler to figure out. In fact, I can almost guarantee you wouldn't even be here if it weren't for one other missing tidbit of information. In this case, information about Python, not Django.

What may have caught your eye is that the Django developers were looking out for you. They provided a very nice DeprecationWarning message that gets printed under exactly this situation. The message explains that the filter you removed will be added back in, and it gives you a website link containing all the low-down on why that is. Isn't that great? Doesn't that make you happy?

Wait, what's that? You didn't see that warning message ever print up in any console anywhere? Yeah, I know.

The Ultimate Reason You Are Here

It's because of Python version 2.7 and higher. If you've gotten this far in this blog, I'm betting that's what you are using. As of version 2.7, Python changed the default behavior so that DeprecationWarning messages and a few other similar kinds of messages are no longer displayed by default. This makes sense, since lots of people use Python today that aren't developers. If end users see weird messages, they probably complain to developers. Those developers then have to stop coding (or napping) long enough to tell them to just ignore it. Which, let's face it, just creates a world of suspicious and skeptical end users who could turn against us at any moment.

Anyway, it's an easy thing to change:

Create a global environment variable called PYTHONWARNINGS and set it to default (or just d works too, if you're in that much of a rush). Now you will see all those (sometimes important) warning messages again. If you are using Linux, one way to permanently create this environment variable is to add this line to the end of your ~/.profile or ~/.bashrc or ~/.zshrc or similar file: 

export PYTHONWARNINGS="default"

Log out and back in, and you're all set.

If you're using Windows rather than Linux, then you're probably used to paying money for things that are otherwise available for free, so send me a check and I'll tell you what to do on your operating system.

Posted 1/3/2013