Logging configuration and handle_uncaught_exception

156 views
Skip to first unread message

Matt Bennett

unread,
Jun 10, 2011, 9:05:55 AM6/10/11
to django-d...@googlegroups.com
For the background to this problem please see my Stack Overflow
question here [1].

I recently had to do some head-scratching over Django 1.3's logging
configuration, because with DEBUG=True the 'django.request' logger
isn't called when an uncaught exception occurs during a request.

It wasn't obvious at all to me that 500 errors are only processed by
the logger when not in debug mode. This behaviour made sense when the
only error processing was to send an email to the site admins, but now
we're free to add more handlers to the logger and may want some of
them to be enabled in development as well as in production.

Is there a reason the call to logger.error can't come before we return
the technical_500_response when DEBUG=True? It seems to me that the
debug level should be checked in each individual handler, rather than
determining whether the error is passed to the logger at all.

Regards,
Matt.


[1] http://stackoverflow.com/questions/6305132/django-1-3-logging-500-errors-are-not-logged

Vinay Sajip

unread,
Jun 13, 2011, 4:53:18 PM6/13/11
to Django developers
On Jun 10, 2:05 pm, Matt Bennett <m...@bennett.name> wrote:

> Is there a reason the call to logger.error can't come before we return
> the technical_500_response when DEBUG=True? It seems to me that the
> debug level should be checked in each individual handler, rather than
> determining whether the error is passed to the logger at all.

Aren't these two separate things? It makes sense to have the logging
of errors occur in all code paths, but that isn't connected with
levels on handlers. The first requires the logging call to be added to
the code, whereas levels on handlers can be configured to be as
verbose (or not) as you like, independently of logging calls in the
code.

Regards,

Vinay Sajip

Matt Bennett

unread,
Jun 14, 2011, 7:33:34 AM6/14/11
to django-d...@googlegroups.com

I think we're saying the same thing - my point is that the logging of
errors should occur in call code paths. Currently, an unhandled view
error is *not* logged if settings.DEBUG is True. To be clear, this has
nothing to do with the log levels on the handlers.

I've attached a patch which modifies
django.core.handlers.base.handle_uncaught_exception to log the error,
and stops AdminEmailHandler sending email if settings.DEBUG is True.
Hopefully this makes it clear what I was proposing above.

Curiously, the modification to AdminEmailHandler causes several tests
in regressiontests.views to fail. The tests that fail are trying to
validate that the contents of emails sent conform to the various
configured settings, and they expect email to be sent even if
settings.DEBUG is True - which isn't what happens when django
processes a real view.

For my patch to pass, I could simply drop the modification to
AdminEmailHandler, or update the tests so that email is not expected
if settings.DEBUG is True (which arguably should be changed anyway).

Matt.


> You received this message because you are subscribed to the Google Groups "Django developers" group.
> To post to this group, send email to django-d...@googlegroups.com.
> To unsubscribe from this group, send email to django-develop...@googlegroups.com.
> For more options, visit this group at http://groups.google.com/group/django-developers?hl=en.
>
>

debug-logging.diff

Russell Keith-Magee

unread,
Jun 16, 2011, 9:47:56 AM6/16/11
to django-d...@googlegroups.com
On Tue, Jun 14, 2011 at 7:33 PM, Matt Bennett <ma...@bennett.name> wrote:
> On Mon, Jun 13, 2011 at 9:53 PM, Vinay Sajip <vinay...@yahoo.co.uk> wrote:
>> On Jun 10, 2:05 pm, Matt Bennett <m...@bennett.name> wrote:
>>
>>> Is there a reason the call to logger.error can't come before we return
>>> the technical_500_response when DEBUG=True? It seems to me that the
>>> debug level should be checked in each individual handler, rather than
>>> determining whether the error is passed to the logger at all.
>>
>> Aren't these two separate things? It makes sense to have the logging
>> of errors occur in all code paths, but that isn't connected with
>> levels on handlers. The first requires the logging call to be added to
>> the code, whereas levels on handlers can be configured to be as
>> verbose (or not) as you like, independently of logging calls in the
>> code.
>>
>
> I think we're saying the same thing - my point is that the logging of
> errors should occur in call code paths. Currently, an unhandled view
> error is *not* logged if settings.DEBUG is True. To be clear, this has
> nothing to do with the log levels on the handlers.

For the benefit of the archive: there is some method to the madness here :-)

The behavior that is implemented in the 500 handler is a bit
convoluted, but it was designed to be a drop-in replacement for the
behavior that existed in 1.2 -- i.e., server error emails were not
sent in DEBUG mode. I remember looking at this exact problem; as I
recall, I was faced with the option of filtering in the handler (which
would mean providing a email handler that wouldn't send emails under
certain circumstances) or filtering at the logging call level. In the
interest of making the admin email handler general purpose, I opted
for the second option.

Now, I'm not absolutely bound to this specific implementation, only to
the preservation of existing behavior without hobbling the email
handler as a general purpose tool.

Yours,
Russ Magee %-)

Carl Meyer

unread,
Jun 16, 2011, 10:03:20 AM6/16/11
to django-d...@googlegroups.com

On 06/16/2011 08:47 AM, Russell Keith-Magee wrote:
> The behavior that is implemented in the 500 handler is a bit
> convoluted, but it was designed to be a drop-in replacement for the
> behavior that existed in 1.2 -- i.e., server error emails were not
> sent in DEBUG mode. I remember looking at this exact problem; as I
> recall, I was faced with the option of filtering in the handler (which
> would mean providing a email handler that wouldn't send emails under
> certain circumstances) or filtering at the logging call level. In the
> interest of making the admin email handler general purpose, I opted
> for the second option.
>
> Now, I'm not absolutely bound to this specific implementation, only to
> the preservation of existing behavior without hobbling the email
> handler as a general purpose tool.

This is a case for a custom Filter object [1]. The filter object
implementation would only be a few lines, to reject logging when DEBUG
is True, and can be attached to the admin email handler in the default
logging configuration. [2] This way the logging call can occur in all
code paths, and the admin email handler itself can remain
general-purpose, but the backwards-compatible behavior can be maintained.

Matt, if you'd be willing to open a ticket for this, that'd be helpful.
If you feel like putting together a patch using the Filter approach,
that'd be even better ;-)

Carl

[1] http://docs.python.org/library/logging.html#filter-objects
[2]
http://docs.python.org/library/logging.config.html#dictionary-schema-details

Matt Bennett

unread,
Jun 17, 2011, 8:48:17 AM6/17/11
to django-d...@googlegroups.com
> This is a case for a custom Filter object [1]. The filter object
> implementation would only be a few lines, to reject logging when DEBUG
> is True, and can be attached to the admin email handler in the default
> logging configuration. [2] This way the logging call can occur in all
> code paths, and the admin email handler itself can remain
> general-purpose, but the backwards-compatible behavior can be maintained.
>
> Matt, if you'd be willing to open a ticket for this, that'd be helpful.
> If you feel like putting together a patch using the Filter approach,
> that'd be even better ;-)

Here you are: https://code.djangoproject.com/ticket/16288

Since logging Filters are not specific to an individual logger or
handler, I've just called it DebugFalseFilter. It's not a pretty name,
but I couldn't come up with anything better - I decided it should
convey what the filter allows through, but AFAIK there's no name for
"not debug mode".

Matt.

Carl Meyer

unread,
Jun 17, 2011, 11:08:29 AM6/17/11
to django-d...@googlegroups.com
Hi Matt,

On 06/17/2011 07:48 AM, Matt Bennett wrote:
> Since logging Filters are not specific to an individual logger or
> handler, I've just called it DebugFalseFilter. It's not a pretty name,
> but I couldn't come up with anything better - I decided it should
> convey what the filter allows through, but AFAIK there's no name for
> "not debug mode".

The name is fine - thanks for the patch! I realized there's still a bit
of a back-compat issue, I've commented on the ticket with a possible
solution. I'd like to get Russ' take on it, if he's ok with the plan I
can take it from here.

Carl

Julien Phalip

unread,
Jun 17, 2011, 1:08:39 PM6/17/11
to Django developers
Hi,

Just noting that another "filtering" functionality has recently been
added to trunk [1]. It is a different kind of filtering than what's
being discussed here -- it is to filter out sensitive information from
error reports when they're being produced. Maybe the naming of one of
those functionalities might need to be reconsidered in order to avoid
confusion in the docs and APIs. I'm not sure. Just thought I'd point
it out ;)

(By the way, "production" is a common generic term used for when DEBUG
is False)

Julien

[1] https://docs.djangoproject.com/en/dev/howto/error-reporting/#filtering-error-reports

Carl Meyer

unread,
Jun 17, 2011, 1:31:07 PM6/17/11
to django-d...@googlegroups.com
Hi Julien,

On 06/17/2011 12:08 PM, Julien Phalip wrote:
> Just noting that another "filtering" functionality has recently been
> added to trunk [1]. It is a different kind of filtering than what's
> being discussed here -- it is to filter out sensitive information from
> error reports when they're being produced. Maybe the naming of one of
> those functionalities might need to be reconsidered in order to avoid
> confusion in the docs and APIs. I'm not sure. Just thought I'd point
> it out ;)

Since "filters" are already a built-in feature of the logging package in
Python's standard library, and we're just making use of that existing
feature, we don't have the option of changing naming here: i.e., the
keys in LOGGING must be named "filters" or they just won't work with
logging.dictConfig. (Even if we could do it, it'd be a mistake to try to
impose alternate Django terminology on a feature of a Python standard
library component).

In any case, we already have plenty of uses of "filter" in Django:
there's the ORM .filter() method, and ModelAdmin.list_filter, just off
the top of my head. I don't think there's a problem here: "filter" is a
generic term, and if there's any potential for confusion it must be
qualified. "Error filtering" vs "logging filters" vs "admin changelist
filters", etc.

> (By the way, "production" is a common generic term used for when DEBUG
> is False)

True that it's used for that, but it doesn't exclusively mean that;
therefore I think DebugFalseFilter is a clearer name than
ProductionFilter. I would have to look at docs or implementation to be
confident I knew what the latter did; not so for the former.

Carl

Vinay Sajip

unread,
Jun 17, 2011, 1:45:37 PM6/17/11
to django-d...@googlegroups.com
Matt Bennett <matt@...> writes:

>
> > This is a case for a custom Filter object [1]. The filter object
> > implementation would only be a few lines, to reject logging when DEBUG
> > is True, and can be attached to the admin email handler in the default
> > logging configuration. [2] This way the logging call can occur in all
> > code paths, and the admin email handler itself can remain
> > general-purpose, but the backwards-compatible behavior can be maintained.
> >
> > Matt, if you'd be willing to open a ticket for this, that'd be helpful.
> > If you feel like putting together a patch using the Filter approach,
> > that'd be even better
>

> Here you are: https://code.djangoproject.com/ticket/16288
>
> Since logging Filters are not specific to an individual logger or
> handler, I've just called it DebugFalseFilter. It's not a pretty name,
> but I couldn't come up with anything better - I decided it should
> convey what the filter allows through, but AFAIK there's no name for
> "not debug mode".

Reposting this, after Google swallowed my earlier response. Sorry if it
eventually turns up, making this a double post ...

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

Matt Bennett

unread,
Jun 17, 2011, 4:02:30 PM6/17/11
to django-d...@googlegroups.com

+1. Perhaps the reason I don't like DebugFalseFilter as a name is that
it's so specific.

Vinay Sajip

unread,
Jun 17, 2011, 1:25:46 PM6/17/11
to Django developers

Carl Meyer

unread,
Jun 19, 2011, 4:53:42 AM6/19/11
to Django developers
In case anyone's interested in this but isn't following the ticket,
I've attached an updated patch there using a variant of Vinay's
suggestion, and with some shim code to address backwards-compatibility
concerns. Reviews welcome.

Ticket is at https://code.djangoproject.com/ticket/16288

Carl
Reply all
Reply to author
Forward
0 new messages