logging.py

import logging

from django.template.defaultfilters import filesizeformat
from django.utils import log, termcolors

np = termcolors.PALETTES[termcolors.NOCOLOR_PALETTE]
lp = termcolors.PALETTES[termcolors.LIGHT_PALETTE]
dp = termcolors.PALETTES[termcolors.DARK_PALETTE]
lp['HTTP_SUCCESS']['opts'] = ('bold',)
dp['HTTP_SUCCESS']['opts'] = ('bold',)
np['INFO'] = {}
lp['INFO'] = dp['INFO'] = {'opts': ('bold',)}


class Formatter(logging.Formatter):
    def __init__(self, *args, **kwargs):
        self.style = log.color_style()
        super().__init__(*args, **kwargs)

    def format(self, record):
        from django.conf import settings
        for x in ['/site-packages/', settings.REPO_ROOT + '/']:
            record.pathname = record.pathname.split(x)[-1]
        clr = getattr(self.style, record.levelname, None)
        record.levelname = '%-7s' % record.levelname
        if clr:
            record.levelname = clr(record.levelname)
        return super().format(record)


def format_size(size):
    size = filesizeformat(size)
    size = size.replace('\xa0', '')
    return size.replace('bytes', 'B')


class ServerFormatter(log.ServerFormatter):
    def __init__(self, *args, **kwargs):
        super().__init__(*args, **kwargs)

    def format(self, record):
        from proj.wsgi import application
        record.size = record.proto = ''
        record.duration = application.request_duration_str()
        record.request_id = application.request_id()
        if len(record.args) == 3:
            a1, a2 = str(record.args[0]).rsplit(' ', 1)
            if a2 == 'HTTP/1.1':
                record.size = format_size(record.args[2])
                record.proto = a2
                record.msg = '%s'
                record.args = (a1,)
        return super().format(record)

settings.py

from django.utils.log import DEFAULT_LOGGING

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'root': {
        'level': os.environ.get('DJANGO_LOGGING_LEVEL', 'INFO'),
        'handlers': ['console', 'sentry'],
        'formatter': 'verbose',
        'propagate': True,
    },
    'filters': dict(DEFAULT_LOGGING['filters'], **{

    }),
    'formatters': {
        'verbose': {
            '()': 'proj.settings.logging.Formatter',
            'format': '%(asctime)s,%(msecs)03d  %(levelname)s  %(name)s - '
                      '%(message)s - %(pathname)s:%(lineno)d %(funcName)s()',
            'datefmt': '%Y-%b-%d %a %z %H:%M:%S',
        },
        'django.server': {
            '()': 'proj.settings.logging.ServerFormatter',
            'format': '%(asctime)s,%(msecs)03d  %(proto)s %(status_code)s  '
                      '%(message)s ~ %(duration)s %(size)s',
            'datefmt': '%Y-%b-%d %a %z %H:%M:%S',
        },
    },
    'handlers': {
        'mail_admins': {
            'level': 'ERROR',
            'filters': ['require_debug_false'],
            'formatter': 'verbose',
            'class': 'django.utils.log.AdminEmailHandler'
        },
        'console': {
            'level': 'DEBUG',
            'formatter': 'verbose',
            'class': 'logging.StreamHandler'
        },
        'django.server': {
            'level': 'INFO',
            'class': 'logging.StreamHandler',
            'formatter': 'django.server',
        },
        'sentry': {
            'level': 'WARNING',
            'filters': ['require_debug_false'],
            'formatter': 'verbose',
            'class': 'raven.contrib.django.handlers.SentryHandler'
        }
    },
    'loggers': {
        '': {
            'handlers': ['sentry', 'console'],
            'level': 'ERROR',
            'propagate': True,
        },
        'root': {
            'handlers': ['sentry', 'console'],
            'level': 'ERROR',
        },
        'django.server': {
            'handlers': ['django.server'],
            'level': 'DEBUG',
            'propagate': False,
        },
        'django.request': {
            'handlers': ['console'],
            'level': 'DEBUG',
            'propagate': False,
        },
        'proj.wsgi': {
            'handles': ['console'],
            'level': 'INFO',
        },
    },
}

wsgi.py

# coding=utf-8
import logging
import os
import sys
import threading

# Ensure project path first...
sys.path.append(os.path.dirname(os.path.dirname(os.path.abspath(__file__))))

# ...then load django
import django
from django.utils import timezone
from django.core.handlers import wsgi

_local = threading.local()
_log = logging.getLogger(__name__)


class WSGIHandler(wsgi.WSGIHandler):
    def get_response(self, request):
        _local.wsgi_request_started = timezone.now()
        _local.wsgi_request_id = id(request)
        _log.info('Request %d started: %s %s',
                  id(request), request.method, request.get_full_path())
        response = super().get_response(request=request)
        _local.wsgi_request_ended = timezone.now()
        _log.debug('Request %d ended in %s',
                   id(request), self.request_duration_str())
        return response

    def request_started(self):
        return getattr(_local, 'wsgi_request_started', None)

    def request_ended(self):
        return getattr(_local, 'wsgi_request_ended', None)

    def request_id(self):
        return getattr(_local, 'wsgi_request_id', None)

    def request_duration(self):
        # _log.debug('Request %r duration', self.request_id())
        if self.request_started():
            delta = self.request_ended() - self.request_started()
            return delta.seconds + delta.microseconds / 1e6

    def request_duration_str(self):
        s = self.request_duration()
        if s is None:
            return ''
        if s >= 1:
            return '%ds' % s
        ms = s * 1e3
        if ms >= 1:
            return '%dms' % ms
        return '%dus' % (ms * 1e3)


django.setup(set_prefix=False)
application = WSGIHandler()