Enabling 'django.request' logger when DEBUG is True

[mattbennett]

django.core.handers.base.handle_uncaught_exception doesn't pass errors to the 'django.request' logger if settings.DEBUG is True.

The attached patch enables the logger in debug mode, and adds a filter to the default logging configuration to maintain the current behaviour of AdminEmailHandler (not to send email if DEBUG is True).

Discussed on the developers group here: ​http://groups.google.com/group/django-developers/browse_thread/thread/d96e0121dad4476a

[Carl Meyer]

Just realized that we still have a bit of a backwards-compatibility issue here. Because the default logging config is in the project template, not in the base default settings, projects created prior to this change being applied will suddenly start trying to send admin emails in DEBUG mode when they upgrade, because they don't have the filter set up in their logging config.

The only solution that comes to mind is a temporary shim to check if LOGGING["handlers"]["mail_admins"]["filters"] is set, and if not, set it to an instance of DebugFalseFilter with a pending-deprecation warning to add the filter explicitly in your logging config. If someone actually does want admin emails sent in DEBUG mode, they would just add "filters": [] to their mail_admins handler config, and that would prevent the back-compat shim from taking effect.

Russell, does this sound reasonable to you?

(Also, I'm wondering if this patch ought to come with a test verifying the new behavior, that django.request loggings calls are fired in DEBUG=True, too. We don't currently seem to have any direct tests for the logging calls in Django, at least that I can find.)

[anonymous]

A more general solution would be something like this:

class ConditionFilter(logging.Filter):
    def __init__(self, condition):
        self.condition = condition

    def filter(self, record):
        return self.condition

which you can then use in the logging configuration using something like

'require_debug_false': {
    '()': 'django.utils.log.ConditionFilter',
    'condition': not DEBUG,
}

This will allow the filter to be used in more places, e.g. you could use a more complex settings-time condition.

Regards,

Vinay Sajip

[Russell Keith-Magee]

Replying to carljm:

The only solution that comes to mind is a temporary shim to check if LOGGING["handlers"]["mail_admins"]["filters"] is set, and if not, set it to an instance of DebugFalseFilter with a pending-deprecation warning to add the filter explicitly in your logging config. If someone actually does want admin emails sent in DEBUG mode, they would just add "filters": [] to their mail_admins handler config, and that would prevent the back-compat shim from taking effect.

Russell, does this sound reasonable to you?

Broadly speaking, this sounds ok; but where are you suggesting that we put this shim? Off the top of my head, I can think of three options:

1. As part of the logging startup code. This would be fairly noisy, but would be guaranteed to be executed
2. As a baked-in filtering step on the admin email logging handler. This would effectively be duplicating the behavior of the proposed filter, but raising a PendingDeprecationWarning as it made use of the shim. The downside is that you won't get the PendingDeprecationWarning unless you actually raise an error.
3. Same as (2), but do it in the 500 handler instead of the admin email logging handler. This has the same problems as (2), but addresses the problem at the source.

(Also, I'm wondering if this patch ought to come with a test verifying the new behavior, that django.request loggings calls are fired in DEBUG=True, too. We don't currently seem to have any direct tests for the logging calls in Django, at least that I can find.)

No, we don't -- mostly because the logging code is vanilla usage of Python standard logging. All a test would verify is that the appropriate logging calls exist where they should. There are some loose and indirect tests of the admin email handler in regressiontests/views/tests/debug.py and regressiontests/views/views.py, but these are really validating that error emails contain (or don't contain) the information they should (or shouldn't). Given that we're making the logic around the email handler more complex, it might be worth adding some tests to make sure error emails are sent at all.

[Carl Meyer]

Replying to russellm:

Broadly speaking, this sounds ok; but where are you suggesting that we put this shim? Off the top of my head, I can think of three options:

1. As part of the logging startup code. This would be fairly noisy, but would be guaranteed to be executed
2. As a baked-in filtering step on the admin email logging handler. This would effectively be duplicating the behavior of the proposed filter, but raising a PendingDeprecationWarning as it made use of the shim. The downside is that you won't get the PendingDeprecationWarning unless you actually raise an error.
3. Same as (2), but do it in the 500 handler instead of the admin email logging handler. This has the same problems as (2), but addresses the problem at the source.

I had assumed (1). I think this is actually addressing the problem nearest the source, as the problem is the default LOGGING config has changed and they may want to update theirs. I'm not sure why it would be noisy; it means the warning would only occur once, at settings-loading time, rather than repeatedly on every error (and wouldn't require an error to occur), which seems much preferable to me. And it doesn't require that we duplicate any logic.

(Also, I'm wondering if this patch ought to come with a test verifying the new behavior, that django.request loggings calls are fired in DEBUG=True, too. We don't currently seem to have any direct tests for the logging calls in Django, at least that I can find.)

No, we don't -- mostly because the logging code is vanilla usage of Python standard logging. All a test would verify is that the appropriate logging calls exist where they should. There are some loose and indirect tests of the admin email handler in regressiontests/views/tests/debug.py and regressiontests/views/views.py, but these are really validating that error emails contain (or don't contain) the information they should (or shouldn't). Given that we're making the logic around the email handler more complex, it might be worth adding some tests to make sure error emails are sent at all.

In a way, we're making Django's logic less complex, since the logging call now occurs regardless of DEBUG, and we're making increased use of "vanilla Python logging" with a filter object in the default config. I don't think we really need to test that stdlib logging works as documented. If we had a general policy of testing that logging calls exist at certain places in the Django codebase, then we'd want to update those tests to reflect that this call now occurs regardless of DEBUG. But since we don't...

I think the back-compat shim is the trickiest bit of the whole proposal and probably warrants a test or three, even though those tests would come out again when the deprecation period runs out.

[Carl Meyer]

Replying to anonymous:

A more general solution would be something like this:

class ConditionFilter(logging.Filter):
    def __init__(self, condition):
        self.condition = condition

    def filter(self, record):
        return self.condition

which you can then use in the logging configuration using something like

'require_debug_false': {
    '()': 'django.utils.log.ConditionFilter',
    'condition': not DEBUG,
}

This will allow the filter to be used in more places, e.g. you could use a more complex settings-time condition.

This is certainly more general, and adds some flexibility. My concern about it is that it makes the settings check eager (at the time LOGGING is defined) rather than lazy. I foresee this causing trouble for people who commonly toggle their DEBUG value in an "import local_settings" near the bottom of their settings.py, which, from what I've seen, is a common pattern. Anyone who for any reason is modifying DEBUG after the definition of LOGGING would need to be aware of this and explicitly switch the "condition" argument in LOGGING as well; and they may well not be aware of its use in LOGGING, especially if they just got the LOGGING config as part of the default template settings.py from startproject. This could easily cause someone to stop getting admin error emails in production, if they leave the default "DEBUG = True" at the top of settings.py and tweak it to False in a local_settings.py in production, for example. And it would be quite confusing to sort out the cause.

So I think the current DebugFalseFilter is preferable to this proposal, even though it is more specific and less flexible, unless there is a way to modify this option to get the lazy behavior.

Which, now that I think of it, might be as simple as making condition a callable and changing not DEBUG to lambda: not DEBUG, since closures in Python follow later rebindings of a name in the same scope. Need to test this out...

[Carl Meyer]

patch with back-compat shim, docs, tests

[Carl Meyer]

I've put together a proposed patch including the backward-compat shim, with tests, and using a CallbackFilter (like ConditionFilter but accepts callable rather than plain value so the DEBUG check isn't so eager). Also includes documentation updates. I've also tested it manually under all the conditions (new project template with DEBUG on or off, old project template needing back-compat shim with DEBUG on or off) and it works as expected.

Patch is attached, and in a github branch: ​https://github.com/carljm/django/compare/master...t16288-debug-request-logging

Review and verification welcome; I'll leave this here for a few days at least so anyone interested can review it before I commit; if you'd like to review before it goes in but don't have time in the next day or so, let me know and I'll wait.

[Russell Keith-Magee]

Patch looks good to me. My only feedback would be that the text of the PendingDeprecationWarning is a bit verbose for my taste; historically, we've gone with a terse message that directs attention to the release notes.

Following up on my "noisy" comment -- my concern is that this shim is on a code path that is executed on every single request, so any code overhead needs to be considered carefully. The patch you've proposed falls back to a function call plus an 'in' check for the doing-it-right case, which I think we can live with.

[Carl Meyer]

Replying to russellm:

Patch looks good to me. My only feedback would be that the text of the PendingDeprecationWarning is a bit verbose for my taste; historically, we've gone with a terse message that directs attention to the release notes.

Thanks for the review - I've reduced the verbosity on the deprecation warning, making it primarily a link to the release notes.

Following up on my "noisy" comment -- my concern is that this shim is on a code path that is executed on every single request, so any code overhead needs to be considered carefully. The patch you've proposed falls back to a function call plus an 'in' check for the doing-it-right case, which I think we can live with.

I don't think that's right, unless I'm missing something. The shim code in my patch runs in Settings.__init__, which runs only when settings are first initialized, which is once per server process (twice with manage.py due to its oddities), not once per request. I've played around with it using "python -W all manage.py runserver" and never see the warning any time other than at startup. So I don't think the shim/warning is either noisy or a performance concern.

[Carl Meyer]

In [16444]:

Fixed #16288 -- Enabled django.request exception logger regardless of DEBUG setting.

Thanks Matt Bennett for report and draft patch; Vinay Sajip and Russell Keith-Magee for review.