Make it clear that django.db.backends.schema messages (which can propogate to django.db.backends) don't include 'duration'

[netpositive36]

It fails on everything written in the logging message format (except asctime) so the extra parameters (duration, sql, etc.) mentioned in the documentation doesn't work.

# LOGGING
LOGGING = {
    'version': 1,
    'disable_existing_loggers': True,
    'filters': {
         'require_debug_false': {
             '()': 'django.utils.log.RequireDebugFalse'
         },
         # Temporary SuspiciousOperation filter
         'skip_suspicious_operations': {
             '()': 'django.utils.log.CallbackFilter',
             'callback': skip_suspicious_operations,
         },
     },
    'formatters': {
        'standard': {
            'format': '%(asctime)s [%(levelname)s] %(name)s: %(message)s'
        },
        'simple': {
            'format': '> %(levelname)-8s %(message)s'
        },
        'verbose': {
            'format': '%(levelname)-8s %(message)s [%(asctime)s %(filename)s:%(funcName)s:%(lineno)d]'
        },
        'simple_sql': {
            'format': '%% %(asctime)s %(duration).3f %(sql)s' # 
        },
    },
    'handlers': {
        'null': {
            'level':'DEBUG',
            'class':'django.utils.log.NullHandler',
        },
        'console':{
            'level':'DEBUG',
            'class':'logging.StreamHandler',
            'formatter': 'simple'
        },
        'console_sql':{
            'level':'DEBUG',
            'class':'logging.StreamHandler',
            'formatter': 'simple_sql'
        },
        'sql_log_file': {
            'level':'DEBUG',
            'class':'logging.handlers.RotatingFileHandler',
            'filename': APP_LOG_HOME + 'django_sql_log.log',   
            'maxBytes': 1024*1024*10, # 10 MB
            'backupCount': 10,
            'formatter':'simple_sql',
        },
        'mail_admins': {
            'level': 'ERROR',
            'filters': ['require_debug_false', 'skip_suspicious_operations'],   # Temporary SuspiciousOperation filter
            'class': 'common.log.AdminMultilineEmailHandler'  #'django.utils.log.AdminEmailHandler',
        },
    },
    'loggers': {
        '': {
            'handlers': ['console', 'log_file'],
            'level': 'DEBUG',
            'propagate': False,
        },
        'z.caching': {
            'handlers': ['null'],
            'level': 'DEBUG',
            'propagate': False,
        },
        'django.db.backends': {
            'handlers': ['sql_log_file'],
            'level': 'DEBUG',
            'propagate': False,
        },
        'django': {
            'handlers': ['console'],
            'level': 'DEBUG',
            'propagate': True,
        },
        'django.request': { 
            'handlers': ['console', 'mail_admins'],
            'level': 'DEBUG',
            'propagate': False
        },
    }
}

Traceback (most recent call last):
  File "/usr/local/Cellar/python/2.7.10_1/Frameworks/Python.framework/Versions/2.7/lib/python2.7/logging/handlers.py", line 76, in emit
    if self.shouldRollover(record):
  File "/usr/local/Cellar/python/2.7.10_1/Frameworks/Python.framework/Versions/2.7/lib/python2.7/logging/handlers.py", line 156, in shouldRollover
    msg = "%s\n" % self.format(record)
  File "/usr/local/Cellar/python/2.7.10_1/Frameworks/Python.framework/Versions/2.7/lib/python2.7/logging/__init__.py", line 732, in format
    return fmt.format(record)
  File "/usr/local/Cellar/python/2.7.10_1/Frameworks/Python.framework/Versions/2.7/lib/python2.7/logging/__init__.py", line 474, in format
    s = self._fmt % record.__dict__
KeyError: 'duration'
Logged from file schema.py, line 102

[Tim Graham]

It looks like you are also handling messages from the 'django.db.backends.schema' logger which doesn't include duration. Perhaps a documentation update could clarify this?

[netpositive36]

Replying to timgraham:

It looks like you are also handling messages from the 'django.db.backends.schema' logger which doesn't include duration. Perhaps a documentation update could clarify this?

Yes, it'd be awesome.

[Akshesh Doshi]

PR: ​https://github.com/django/django/pull/6256

[Markus Holtermann]

PR updated: ​https://github.com/django/django/pull/6289

[Markus Holtermann <info@…>]

In 1cb65b8a:

Fixed #26157 #25321 -- Added sql/params to extra context of schema logger

Thanks Akshesh Doshi for the initial patch and Tim Graham for the review