Opened 9 years ago

Closed 8 years ago

#25321 closed Cleanup/optimization (fixed)

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

Reported by: netpositive36 Owned by: Markus Holtermann
Component: Documentation Version: 1.8
Severity: Normal Keywords: logging, db
Cc: Triage Stage: Ready for checkin
Has patch: yes Needs documentation: no
Needs tests: no Patch needs improvement: no
Easy pickings: yes UI/UX: no

Description

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

Change History (12)

comment:1 by Tim Graham, 9 years ago

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?

in reply to:  1 comment:2 by netpositive36, 9 years ago

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.

comment:3 by Tim Graham, 9 years ago

Component: Database layer (models, ORM)Documentation
Easy pickings: set
Summary: Logging throws exception because of the formatter string for django.db.backends loggerMake it clear that django.db.backends.schema messages (which can propogate to django.db.backends) don't include 'duration'
Triage Stage: UnreviewedAccepted
Type: BugCleanup/optimization

comment:4 by Roman Fuentes, 8 years ago

Owner: changed from nobody to Roman Fuentes
Status: newassigned

comment:5 by Tim Graham, 8 years ago

Owner: Roman Fuentes removed
Status: assignednew

comment:6 by Damir Rakhimov, 8 years ago

Owner: set to Damir Rakhimov
Status: newassigned

comment:7 by Tim Graham, 8 years ago

Owner: Damir Rakhimov removed
Status: assignednew

comment:8 by Akshesh Doshi, 8 years ago

Has patch: set
Owner: set to Akshesh Doshi
Status: newassigned

comment:9 by Tim Graham, 8 years ago

Patch needs improvement: set

comment:10 by Markus Holtermann, 8 years ago

Owner: changed from Akshesh Doshi to Markus Holtermann
Patch needs improvement: unset

comment:11 by Tim Graham, 8 years ago

Triage Stage: AcceptedReady for checkin

comment:12 by Markus Holtermann <info@…>, 8 years ago

Resolution: fixed
Status: assignedclosed

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

Note: See TracTickets for help on using tickets.
Back to Top