django.request logger not propagated to root?

Question

Using Django 1.5.1:

DEBUG = False

LOGGING = {
    'version': 1,
    'disable_existing_loggers': True,
    'formatters': {
        'verbose': {
            'format': '%(levelname)s %(asctime)s %(module)s %(message)s'
        },
    },
    'handlers': {
        'console': {
            'level': 'DEBUG',
            'class': 'logging.StreamHandler',
            'formatter': 'verbose',
        },
    },
    'loggers': {
        # root logger
        '': {
            'handlers': ['console'],
        },
        #'django.request': {
        #    'handlers': ['console'],
        #    'level': 'DEBUG',
        #    'propagate': False,
        #},
    }
}

If I uncomment the commented lines and call a view which has 1/0, the traceback is printed to the console:

ERROR 2013-11-29 13:33:23,102 base Internal Server Error: /comment/*******/
Traceback (most recent call last):
  ...
  File "*****/comments/views.py", line 10, in post
    1/0
ZeroDivisionError: integer division or modulo by zero
WARNING 2013-11-29 13:33:23,103 csrf Forbidden (CSRF cookie not set.): /comment/******/
[29/Nov/2013 13:33:23] "POST /comment/******/ HTTP/1.0" 500 27

But if the lines stay commented, no traceback is printed to the console, just:

[29/Nov/2013 13:33:23] "POST /comment/******/ HTTP/1.0" 500 27

I thought if django.request logger is not configured, it would propagate to the root logger, which prints everything to console.

I didn't find any information that django.request is special.

Why it doesn't work?

Here I read:

Prior to Django 1.5, the LOGGING setting always overwrote the default Django logging configuration. From Django 1.5 forward, it is possible to get the project’s logging configuration merged with Django’s defaults, hence you can decide if you want to add to, or replace the existing configuration.

If the disable_existing_loggers key in the LOGGING dictConfig is set to True (which is the default) the default configuration is completely overridden. Alternatively you can redefine some or all of the loggers by setting disable_existing_loggers to False.

In django/utils/log.py:

# Default logging for Django. This sends an email to the site admins on every
# HTTP 500 error. Depending on DEBUG, all other log records are either sent to
# the console (DEBUG=True) or discarded by mean of the NullHandler (DEBUG=False).
DEFAULT_LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'filters': {
        'require_debug_false': {
            '()': 'django.utils.log.RequireDebugFalse',
        },
        'require_debug_true': {
            '()': 'django.utils.log.RequireDebugTrue',
        },
    },
    'handlers': {
        'console':{
            'level': 'INFO',
            'filters': ['require_debug_true'],
            'class': 'logging.StreamHandler',
        },
        'null': {
            'class': 'django.utils.log.NullHandler',
        },
        'mail_admins': {
            'level': 'ERROR',
            'filters': ['require_debug_false'],
            'class': 'django.utils.log.AdminEmailHandler'
        }
    },
    'loggers': {
        'django': {
            'handlers': ['console'],
        },
        'django.request': {
            'handlers': ['mail_admins'],
            'level': 'ERROR',
            'propagate': False,
        },
        'py.warnings': {
            'handlers': ['console'],
        },
    }
}

So by default django.request has propagate = False. But In my case I have 'disable_existing_loggers': True.

Answer 1

Ok, so the behavior is "correct", but not expected. django/conf/__init__.py:65:

def _configure_logging(self):
    ...
    if self.LOGGING_CONFIG:
        from django.utils.log import DEFAULT_LOGGING
        # First find the logging configuration function ...
        logging_config_path, logging_config_func_name = self.LOGGING_CONFIG.rsplit('.', 1)
        logging_config_module = importlib.import_module(logging_config_path)
        logging_config_func = getattr(logging_config_module, logging_config_func_name)

        logging_config_func(DEFAULT_LOGGING)

        if self.LOGGING:
            # Backwards-compatibility shim for #16288 fix
            compat_patch_logging_config(self.LOGGING)

            # ... then invoke it with the logging settings
            logging_config_func(self.LOGGING)

What is happening is that default logging configuration is applied and django.request logger is created. Then my custom LOGGING configuration is applied with disable_existing_loggers = True, but Python doesn't delete already existing logger django.request, but only disables it.

So I have to manually reconfigure django.request logger in my configuration. :(

Answer 2

For Django-2.1 I found that the logging configuration is more concise:

$ ./manage.py shell

>>> import logging
>>> # Grub all Django loggers
>>> loggers = [
        name for name in logging.root.manager.loggerDict 
        if 'django' in name
    ]
>>> for each in loggers:
        logger = logging.getLogger(each)
        print(
            'Logger Name: {0}\nLogger Handlers: {1}\n'
            'Logger Propagates: {2}\n\n'.format(
                each, 
                logger.handlers, 
                logger.propagate
            )
        )

Logger Name: django.db
Logger Handlers: []
Logger Propagates: True


Logger Name: django.request
Logger Handlers: []
Logger Propagates: True


Logger Name: django.template
Logger Handlers: []
Logger Propagates: True


Logger Name: django.db.backends
Logger Handlers: []
Logger Propagates: True


Logger Name: django.db.backends.schema
Logger Handlers: []
Logger Propagates: True


Logger Name: django.security.csrf
Logger Handlers: []
Logger Propagates: True


Logger Name: django
Logger Handlers: [<logging.StreamHandler object at 0x7f706d5dd780>, <django.utils.log.AdminEmailHandler object at 0x7f706d740cf8>]
Logger Propagates: True


Logger Name: django.contrib.gis
Logger Handlers: []
Logger Propagates: True


Logger Name: django.contrib
Logger Handlers: []
Logger Propagates: True


Logger Name: django.security
Logger Handlers: []
Logger Propagates: True


Logger Name: django.server
Logger Handlers: [<logging.StreamHandler object at 0x7f706d59eba8>]
Logger Propagates: False

As quoted in the docs:

All loggers except django.server propagate logging to their parents, up to the root django logger. The console and mail_admins handlers are attached to the root logger to provide the behavior described above.

This is in accordance with the docs of propagate which state that:

Note

If you attach a handler to a logger and one or more of its ancestors, it may emit the same record multiple times. In general, you should not need to attach a handler to more than one logger - if you just attach it to the appropriate logger which is highest in the logger hierarchy, then it will see all events logged by all descendant loggers, provided that their propagate setting is left set to True. A common scenario is to attach handlers only to the root logger, and to let propagation take care of the rest.

Therefore I decided not to prevent Django from configuring logging. I wanted to stop sending emails to the admins because I use sentry, and I just configured the root logger to use the console and file handlers, according to the django docs examples:

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'verbose': {
            'format': '{levelname} {asctime} {module} {process:d} {thread:d} {message}',
            'style': '{',
        },
        'simple': {
            'format': '{levelname} {message}',
            'style': '{',
        },
    },
    'filters': {
        'require_debug_false': {
            '()': 'django.utils.log.RequireDebugFalse',
        },
        'require_debug_true': {
            '()': 'django.utils.log.RequireDebugTrue',
        },
    },
    'handlers': {
        'console': {
            'level': 'INFO',
            'filters': ['require_debug_true'],
            'class': 'logging.StreamHandler',
            'formatter': 'simple'
        },
        'file': {
            'level': 'INFO',
            'filters': ['require_debug_false'],
            'class': 'logging.FileHandler',
            'filename': os.path.join(LOGGING_DIR, 'django.log'),
            'formatter': 'verbose'
        },
    },
    'loggers': {
        'django': {
            'handlers': ['file', 'console'],
            'level': 'INFO',
            'propagate': True,
        },
    }
}

Which results in:

Logger Name: django
Logger Handlers: [<logging.FileHandler object at 0x7f5aa0fd1cc0>, <logging.StreamHandler object at 0x7f5aa0fd1ef0>]
Logger Propagates: True

Not tested in production yet, but it seems that it will work as expected.

Answer 3

The solution is to prevent Django from configuring logging and handle it ourselves. Fortunately this is easy. In settings.py:

LOGGING_CONFIG = None
LOGGING = {...}  # whatever you want, as you already have

import logging.config
logging.config.dictConfig(LOGGING)

UPDATE ~March 2015: Django has clarified their documentation:

If the disable_existing_loggers key in the LOGGING dictConfig is set to True then all loggers from the default configuration will be disabled. Disabled loggers are not the same as removed; the logger will still exist, but will silently discard anything logged to it, not even propagating entries to a parent logger. Thus you should be very careful using 'disable_existing_loggers': True; it’s probably not what you want. Instead, you can set disable_existing_loggers to False and redefine some or all of the default loggers; or you can set LOGGING_CONFIG to None and handle logging config yourself.

For posterity and detail: The explanation? Most of the confusion I think comes down to Django's poor explanation of disable_existing_loggers, which says that when True, "the default configuration is completely overridden". In your own answer you discovered that is not correct; what's happening is that the existing loggers, which Django already configures, are disabled not replaced.

The Python logging documentation explains it better (emphasis added):

disable_existing_loggers – If specified as False, loggers which exist when this call is made are left alone. The default is True because this enables old behaviour in a backward-compatible way. This behaviour is to disable any existing loggers unless they or their ancestors are explicitly named in the logging configuration.

Based on Django docs we think, "override the defaults with my own LOGGING configuration and anything I don't specify will bubble up". I've tripped over this expectation as well. The behavior we expect is along the lines of replace_existing_loggers (which isn't a real thing). Instead the Django loggers are shut up not bubbled up.

We need to prevent the setup of these Django loggers in the first place and here the Django docs are more helpful:

If you don’t want to configure logging at all (or you want to manually configure logging using your own approach), you can set LOGGING_CONFIG to None. This will disable the configuration process.

Note: Setting LOGGING_CONFIG to None only means that the configuration process is disabled, not logging itself. If you disable the configuration process, Django will still make logging calls, falling back to whatever default logging behavior is defined.

Django will still use its loggers but since they are not handled (and then disabled) by the configuration, those loggers will bubble up as expected. A simple test with the above settings:

manage.py shell
>>> import logging
>>> logging.warning('root logger')
WARNING 2014-03-11 13:35:08,832 root root logger
>>> l = logging.getLogger('django.request')
>>> l.warning('request logger')
WARNING 2014-03-11 13:38:22,000 django.request request logger
>>> l.propagate, l.disabled
(1, 0)