improving debug logging in development

234 views
Skip to first unread message

Tim Graham

unread,
Mar 21, 2015, 2:24:06 PM3/21/15
to django-d...@googlegroups.com
I think the lack of an obvious way to get a useful logging config for local development is a pain point we could address.

Here's a patch from a contributor based on a blog post by Dan Poirier [1]:
https://github.com/django/django/pull/4362

Do you think this is a good suggestion or do you have a different way of getting useful logging in development?

I experimented a little with using an environment variable to modify parts of django.utils.log.DEFAULT_LOGGING to get a useful output if the env var is set to DEBUG, but it didn't seem so simple, besides a solution in django/utils/log.py like:

if os.environ.get('DJANGO_CONSOLE_DEBUG'):
   DEFAULT_LOGGING = (default logging from pull request above)
else:
  DEFAULT_LOGGING = (existing django.utils.log.DEFAULT_LOGGING)

[1] http://www.caktusgroup.com/blog/2015/01/27/Django-Logging-Configuration-logging_config-default-settings-logger/

Aymeric Augustin

unread,
Mar 21, 2015, 2:56:53 PM3/21/15
to django-d...@googlegroups.com
The lack of a fathomable way to get a functional logging config is a huge pain point :-)

In this case, I wish we improve Django’s logging tools rather than document how to bypass them :-/

-- 
Aymeric.



--
You received this message because you are subscribed to the Google Groups "Django developers (Contributions to Django itself)" group.
To unsubscribe from this group and stop receiving emails from it, send an email to django-develop...@googlegroups.com.
To post to this group, send email to django-d...@googlegroups.com.
Visit this group at http://groups.google.com/group/django-developers.
To view this discussion on the web visit https://groups.google.com/d/msgid/django-developers/f76b4626-754f-4256-acb2-31799606f880%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

Carl Meyer

unread,
Mar 22, 2015, 10:24:08 PM3/22/15
to django-d...@googlegroups.com
On 03/21/2015 12:56 PM, Aymeric Augustin wrote:
> The lack of a fathomable way to get a functional logging config is a
> huge pain point :-)
>
> In this case, I wish we improve Django’s logging tools rather than
> document how to bypass them :-/

I agree. The current behavior is pretty bad in several ways, and we
should fix it.

I think the PR (with some modifications; I've commented on it) could be
a stopgap improvement until that happens, though - it at least corrects
some of the misinformation about `disable_existing_loggers` that our
current docs contain.

>> On 21 mars 2015, at 19:24, Tim Graham <timog...@gmail.com
>> <mailto:timog...@gmail.com>> wrote:
>>
>> I think the lack of an obvious way to get a useful logging config for
>> local development is a pain point we could address.
>>
>> Here's a patch from a contributor based on a blog post by Dan Poirier [1]:
>> https://github.com/django/django/pull/4362
>>
>> Do you think this is a good suggestion or do you have a different way
>> of getting useful logging in development?
>>
>> I experimented a little with using an environment variable to modify
>> parts of django.utils.log.DEFAULT_LOGGING to get a useful output if
>> the env var is set to DEBUG, but it didn't seem so simple, besides a
>> solution in django/utils/log.py like:
>>
>> if os.environ.get('DJANGO_CONSOLE_DEBUG'):
>> DEFAULT_LOGGING = (default logging from pull request above)
>> else:
>> DEFAULT_LOGGING = (existing django.utils.log.DEFAULT_LOGGING)
>>
>> [1]
>> http://www.caktusgroup.com/blog/2015/01/27/Django-Logging-Configuration-logging_config-default-settings-logger/

I think there are two mostly-separate questions being intertwined here.

The first, more complex and more important question is: how do we fix
Django's logging config process to be less broken, so that the best
advice for getting it to do what you what isn't "disable Django's
interference entirely and do it yourself."? I don't have a
fully-packaged solution ready to propose here; someone will need to dig
into it. Probably the biggest sticking point to get around will be
backwards compatibility.

I'm pretty sure that a good solution will include an optional way to
prevent Django from ever installing its default logging config in the
first place, since it seems there's no way to tell logging to "clear out
everything and start fresh" once some configuration has been set.

And I think it will also mean that we stop ever recommending the use of
"disable_existing_loggers" (and probably even include a callout in our
docs warning users against it). It seems that "disable_existing_loggers"
is a bad feature with surprising behavior, and our current docs were
written based on a misunderstanding of what it does.

The second question is "how do I get useful logging for development?" I
think that's actually a pretty easy question to answer, and the example
config in the PR is basically correct (but currently located in the
wrong section of the docs, IMO). We could easily make such a
configuration the default behavior when `DEBUG` is on; I think that's
worth exploring.

Carl

signature.asc

Carl Meyer

unread,
Mar 23, 2015, 12:31:06 PM3/23/15
to django-d...@googlegroups.com
On 03/22/2015 08:23 PM, Carl Meyer wrote:
> The first, more complex and more important question is: how do we fix
> Django's logging config process to be less broken, so that the best
> advice for getting it to do what you what isn't "disable Django's
> interference entirely and do it yourself."? I don't have a
> fully-packaged solution ready to propose here; someone will need to dig
> into it. Probably the biggest sticking point to get around will be
> backwards compatibility.
>
> I'm pretty sure that a good solution will include an optional way to
> prevent Django from ever installing its default logging config in the
> first place, since it seems there's no way to tell logging to "clear out
> everything and start fresh" once some configuration has been set.
>
> And I think it will also mean that we stop ever recommending the use of
> "disable_existing_loggers" (and probably even include a callout in our
> docs warning users against it). It seems that "disable_existing_loggers"
> is a bad feature with surprising behavior, and our current docs were
> written based on a misunderstanding of what it does.

After giving this a bit more thought, I think at least the first step of
a better solution may not be too hard, and could be integrated
immediately along with the doc changes.

The problem is that the current system always installs the default
logging config, and expects that you can use `disable_existing_loggers:
True` to undo that if you want, but `disable_existing_loggers: True`
doesn't do the right thing at all. So really we just need a way to skip
installing Django's default logging config, if you don't want it. I
think the simplest solution is to just add a `LOGGING_SKIP_DEFAULTS`
setting which can be set to `True` to prevent Django from ever
installing its default logging config. Aside from that, the rest of the
`LOGGING_CONFIG/LOGGING` system is functional and fine as is, I think.

The harder problem is figuring out how to have new projects default to
good in-development console logging in DEBUG mode, without breaking
back-compat for older projects. But I don't think we should hold up
incremental improvement while waiting for a solution to that -- having a
proper way to bypass Django's default logging, and fixing our
documentation to be accurate, would be a big step forward.

Carl

signature.asc

Tim Graham

unread,
Mar 23, 2015, 1:48:26 PM3/23/15
to django-d...@googlegroups.com
The alternative to a new setting would be to revert the "merging" behavior of the django.utils.log.DEFAULT_LOGGING and settings.LOGGING entirely. This original design was proposed by Claude in https://code.djangoproject.com/ticket/18993#comment:7, but now we realize disable_existing_loggers=True doesn't work as expected in that proposal. I also find that writing a nice configuration that uses disable_existing_loggers=False and that merges nicely with Django's defaults to be difficult (for example, in trying to output all log entries to the console, some as simple as the config below [1] won't work because Django's DEFAULT_LOGGING has handlers for 'django.request' and 'django.security' which don't propagate their entries (I couldn't tell the reason for this from https://github.com/django/django/commit/f0f327bbfe1caae6d11fbe20a3b5b96eed1704cf#diff-246800ac266982b8ad12f505352a662eR63)

I would like to ask if anyone who is using settings.LOGGING could share their config so we can get a sense of different use cases?

[1] An attempt to write a LOGGING config that outputs all entires to stdout, but doesn't entirely work as stated above.

LOGGING = {
    'version': 1,
    'handlers': {
        'console': {
            'level': 'DEBUG',
            'class': 'logging.StreamHandler',
        }, 
    },
    # A catch-all root logger.
    'root': {
        'handlers': ['console'],
        'level': 'DEBUG',
    },

Carl Meyer

unread,
Mar 23, 2015, 2:19:23 PM3/23/15
to django-d...@googlegroups.com
On 03/23/2015 11:48 AM, Tim Graham wrote:
> The alternative to a new setting would be to revert the "merging"
> behavior of the django.utils.log.DEFAULT_LOGGING and settings.LOGGING
> entirely. This original design was proposed by Claude in
> https://code.djangoproject.com/ticket/18993#comment:7, but now we
> realize disable_existing_loggers=True doesn't work as expected in that
> proposal. I also find that writing a nice configuration that uses
> disable_existing_loggers=False and that merges nicely with Django's
> defaults to be difficult (for example, in trying to output all log
> entries to the console, some as simple as the config below [1] won't
> work because Django's DEFAULT_LOGGING has handlers for 'django.request'
> and 'django.security' which don't propagate their entries (I couldn't
> tell the reason for this from
> https://github.com/django/django/commit/f0f327bbfe1caae6d11fbe20a3b5b96eed1704cf#diff-246800ac266982b8ad12f505352a662eR63)

I'm also not clear why 'django.security' and 'django.request' should
have `propagate: False`. Seems to me we should maybe just remove that?
Does anyone know why it's there?

If we removed the `propagate: False` from those two loggers, then I
think it would be a lot more feasible to get sane behavior by layering
additional config atop the default config. It seems useful to continue
to support that approach as an option, for people who want "defaults
plus", and want to get any future updates to the default config
automatically.

ISTM that "layer atop the default config" is a better default behavior
if you add a LOGGING setting than "replace the default config", to avoid
people losing their mail-admins config accidentally. (But we definitely
need first-class support for "replace the default config" as an option,
too.)

> I would like to ask if anyone who is using settings.LOGGING could share
> their config so we can get a sense of different use cases?

For my personal use cases, I wouldn't have a problem with reverting the
merged-config approach. The default logging config consists of
mail-admins (I use Sentry instead) and a console handler for 'django.*'
(which I replace with a root console handler in dev). And I also read
release notes, so if there were future changes to the default logging
config that I might want to adopt in my own config, I'm confident I'd
see them.

Carl

signature.asc

Carl Meyer

unread,
Mar 23, 2015, 2:21:25 PM3/23/15
to django-d...@googlegroups.com
On 03/23/2015 12:18 PM, Carl Meyer wrote:
> On 03/23/2015 11:48 AM, Tim Graham wrote:
>> The alternative to a new setting would be to revert the "merging"
>> behavior of the django.utils.log.DEFAULT_LOGGING and settings.LOGGING
>> entirely. This original design was proposed by Claude in
>> https://code.djangoproject.com/ticket/18993#comment:7, but now we
>> realize disable_existing_loggers=True doesn't work as expected in that
>> proposal. I also find that writing a nice configuration that uses
>> disable_existing_loggers=False and that merges nicely with Django's
>> defaults to be difficult (for example, in trying to output all log
>> entries to the console, some as simple as the config below [1] won't
>> work because Django's DEFAULT_LOGGING has handlers for 'django.request'
>> and 'django.security' which don't propagate their entries (I couldn't
>> tell the reason for this from
>> https://github.com/django/django/commit/f0f327bbfe1caae6d11fbe20a3b5b96eed1704cf#diff-246800ac266982b8ad12f505352a662eR63)

[...]

> ISTM that "layer atop the default config" is a better default behavior
> if you add a LOGGING setting than "replace the default config", to avoid
> people losing their mail-admins config accidentally. (But we definitely
> need first-class support for "replace the default config" as an option,
> too.)

Also worth noting that reverting to "always replace the default config
if you have settings.LOGGING set" at this point would be a significant
backwards-incompatible change, that could result in people suddenly and
silently losing their admin error emails on upgrade.

Carl

signature.asc

Chris Foresman

unread,
Mar 23, 2015, 2:27:41 PM3/23/15
to django-d...@googlegroups.com
This is what we're using to send to loggly. I'm not honestly 100% sure it works as intended but it gets the job done. It would be great if we could conditionally log to console when running in a local dev environment. 

LOGGING = {
   
'version': 1,
   
'disable_existing_loggers': True,
   
'formatters': {
       
'simple': {
           
'format': '%(asctime)s %(levelname)s %(message)s',
       
},
       
'request': {
           
'format': '%(asctime)s %(levelname)s %(status_code)d %(message)s -> %(request)s',
       
},
       
'sql': {
           
'format': '%(asctime)s %(levelname)s duration: %(duration)d SQL: %(sql)s',
       
},
   
},
   
'handlers': {
       
'simple.SysLogHandler': {
           
'level': 'DEBUG',
           
'class': 'logging.handlers.SysLogHandler',
           
'facility': 'local5',
           
'formatter': 'simple',
       
},
       
'request.SysLogHandler': {
           
'level': 'DEBUG',
           
'class': 'logging.handlers.SysLogHandler',
           
'facility': 'local5',
           
'formatter': 'request',
       
},
       
'db.SysLogHandler': {
           
'level': 'DEBUG',
           
'class': 'logging.handlers.SysLogHandler',
           
'facility': 'local5',
           
'formatter': 'sql',
       
},
   
},
   
'loggers': {
       
'django.request': {
           
'handlers': ['request.SysLogHandler'],
           
'level': 'DEBUG',
           
'propagate': True,
       
},
       
'django.db.backends': {
           
'handlers': ['db.SysLogHandler'],
           
'level': 'DEBUG',
           
'propagate': True,
       
},
       
'django.db.backends.schema': {
           
'handlers': ['simple.SysLogHandler'],
           
'level': 'DEBUG',
           
'propagate': False,
       
},
       
'loggly_logs': {
           
'handlers': ['simple.SysLogHandler'],
           
'propagate': True,
           
'format': 'django: %(message)s',

           
'level': 'DEBUG',
       
},
   
},
}

Wim Feijen

unread,
Mar 23, 2015, 4:45:12 PM3/23/15
to django-d...@googlegroups.com
This may sound stupid, but I actually use Logbook for logging because I find it easy to use.

Florian Apolloner

unread,
Mar 23, 2015, 5:06:39 PM3/23/15
to django-d...@googlegroups.com
On Monday, March 23, 2015 at 9:45:12 PM UTC+1, Wim Feijen wrote:
This may sound stupid, but I actually use Logbook for logging because I find it easy to use.

Why would this sound stupid? Logbook is a nice library and actually worth thinking about if we start using dependencies in Django.

Tim Graham

unread,
Mar 23, 2015, 7:07:46 PM3/23/15
to django-d...@googlegroups.com
Hm, now I wonder if that blog post in my initial post is entirely correct. This config seems to send all Django logging to stdout (regardless of the value of disable_existing_loggers). The difference from the initially proposed doc patch is that this config redefines the 'django' logger instead of the 'root' logger. Investigation to continue tomorrow...

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'handlers': {
        'console': {

            'class': 'logging.StreamHandler',
        },
    },
    'loggers': {
        'django': {

            'handlers': ['console'],
            'level': 'DEBUG',
        },
    }
}

Carl Meyer

unread,
Mar 23, 2015, 9:16:34 PM3/23/15
to django-d...@googlegroups.com
I played around with this a bit, and it seems that if you
`disable_existing_loggers` but mention a specific pre-existing logger in
your new config, that logger (and its children) are not disabled. So in
your example here, because you're including the 'django' logger in your
new config, it and its children are not silenced. But the blog post is
correct that any existing loggers which aren't mentioned in the new
config are silenced, and anything logged to them doesn't propagate anymore.

For reference, here's the test script I used to experiment:
https://gist.github.com/carljm/6bd0b1b87590b1429ce7

Even mentioning a logger but not providing any config for it (as shown
in the gist) is apparently enough to preserve it from being disabled.
But if you remove mention of the `foo` logger from the `new` dict,
anything logged to `foo` or any of its children thereafter will silently
disappear.

I think this is interesting and good to know, but it doesn't change the
conclusion that we should avoid `disable_existing_loggers`.

It means that we _could_ provide a working "send all Django's logs to
stdout" example config without the LOGGING_CONFIG=None workaround. But
we still can't provide a working "send all logs to stdout" without
either that or another way to bypass Django's default logging config.

And it still seems to me that it's bad for Django's default config to
set `level: ERROR` and `propagate: False` on the django.request and
django.security loggers, as that prevents those logs from propagating to
higher-level handlers someone may want to install.

Carl
> --
> You received this message because you are subscribed to the Google
> Groups "Django developers (Contributions to Django itself)" group.
> To unsubscribe from this group and stop receiving emails from it, send
> an email to django-develop...@googlegroups.com
> <mailto:django-develop...@googlegroups.com>.
> To post to this group, send email to django-d...@googlegroups.com
> <mailto:django-d...@googlegroups.com>.
> Visit this group at http://groups.google.com/group/django-developers.
> To view this discussion on the web visit
> https://groups.google.com/d/msgid/django-developers/8030352a-f072-4646-8b3a-a1a2fcad1b35%40googlegroups.com
> <https://groups.google.com/d/msgid/django-developers/8030352a-f072-4646-8b3a-a1a2fcad1b35%40googlegroups.com?utm_medium=email&utm_source=footer>.
signature.asc

Aron Griffis

unread,
Mar 23, 2015, 10:18:26 PM3/23/15
to django-d...@googlegroups.com
On Mon, 2015-03-23 at 19:16 -0600, Carl Meyer wrote:
> And it still seems to me that it's bad for Django's default config to
> set `level: ERROR` and `propagate: False` on the django.request and
> django.security loggers, as that prevents those logs from propagating to
> higher-level handlers someone may want to install.

My fix for this has been the following snippet in settings.py:

# The DEFAULT_LOGGING dict is unhelpful and resides even with
# disable_existing_loggers=True. This prevents propagation to the root
# logger for loggers defined in DEFAULT_LOGGING.
from django.utils.log import DEFAULT_LOGGING
DEFAULT_LOGGING['loggers'] = {}

-Aron

Hanne Moa

unread,
Mar 26, 2015, 5:58:43 AM3/26/15
to django-d...@googlegroups.com
What about the yellow 500 error-page when in debug-mode? I'd like to have a copy of the complete thing *somewhere* now that what's sent by email is sanitized. Cloning a running system, turning DEBUG on and attempting to trigger the same error isn't always easy. Is the 500-data loggable at all?

--
You received this message because you are subscribed to the Google Groups "Django developers  (Contributions to Django itself)" group.
To unsubscribe from this group and stop receiving emails from it, send an email to django-develop...@googlegroups.com.
To post to this group, send email to django-d...@googlegroups.com.

Collin Anderson

unread,
Mar 26, 2015, 8:16:52 AM3/26/15
to django-d...@googlegroups.com
Hi All,

A little off topic, but here's what I do to generate "yellow" html tracebacks in production behind the scenes:

from django.views import debug
html
= debug.ExceptionReporter(request, is_email=False, *sys.exc_info()).get_traceback_html()

Though, I do that within the got_request_exception signal; not sure if it would work in the logging framework.

Collin
Reply all
Reply to author
Forward
0 new messages