2010-10-04 23:12:39 +08:00
|
|
|
import logging
|
2015-05-08 00:11:39 +08:00
|
|
|
import logging.config # needed when logging_config doesn't start with logging.config
|
2015-07-09 23:27:07 +08:00
|
|
|
from copy import copy
|
2011-06-09 06:18:46 +08:00
|
|
|
|
|
|
|
from django.conf import settings
|
2010-10-04 23:12:39 +08:00
|
|
|
from django.core import mail
|
2012-11-20 01:57:40 +08:00
|
|
|
from django.core.mail import get_connection
|
2015-11-07 00:19:41 +08:00
|
|
|
from django.core.management.color import color_style
|
2014-01-21 04:15:14 +08:00
|
|
|
from django.utils.module_loading import import_string
|
2010-10-04 23:12:39 +08:00
|
|
|
|
2017-07-13 12:09:18 +08:00
|
|
|
request_logger = logging.getLogger('django.request')
|
|
|
|
|
2012-09-27 01:56:21 +08:00
|
|
|
# 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
|
2015-11-07 23:07:21 +08:00
|
|
|
# the console (DEBUG=True) or discarded (DEBUG=False) by means of the
|
|
|
|
# require_debug_true filter.
|
2012-09-25 04:30:38 +08:00
|
|
|
DEFAULT_LOGGING = {
|
|
|
|
'version': 1,
|
|
|
|
'disable_existing_loggers': False,
|
|
|
|
'filters': {
|
|
|
|
'require_debug_false': {
|
|
|
|
'()': 'django.utils.log.RequireDebugFalse',
|
2012-09-27 01:56:21 +08:00
|
|
|
},
|
|
|
|
'require_debug_true': {
|
|
|
|
'()': 'django.utils.log.RequireDebugTrue',
|
|
|
|
},
|
2012-09-25 04:30:38 +08:00
|
|
|
},
|
2015-11-07 00:19:41 +08:00
|
|
|
'formatters': {
|
|
|
|
'django.server': {
|
|
|
|
'()': 'django.utils.log.ServerFormatter',
|
2017-11-19 08:15:08 +08:00
|
|
|
'format': '[{server_time}] {message}',
|
|
|
|
'style': '{',
|
2015-11-07 00:19:41 +08:00
|
|
|
}
|
|
|
|
},
|
2012-09-25 04:30:38 +08:00
|
|
|
'handlers': {
|
2012-11-13 04:19:11 +08:00
|
|
|
'console': {
|
2012-09-27 01:56:21 +08:00
|
|
|
'level': 'INFO',
|
2012-09-30 05:45:28 +08:00
|
|
|
'filters': ['require_debug_true'],
|
2012-09-27 01:56:21 +08:00
|
|
|
'class': 'logging.StreamHandler',
|
|
|
|
},
|
2015-11-07 00:19:41 +08:00
|
|
|
'django.server': {
|
|
|
|
'level': 'INFO',
|
|
|
|
'class': 'logging.StreamHandler',
|
|
|
|
'formatter': 'django.server',
|
|
|
|
},
|
2012-09-25 04:30:38 +08:00
|
|
|
'mail_admins': {
|
|
|
|
'level': 'ERROR',
|
|
|
|
'filters': ['require_debug_false'],
|
|
|
|
'class': 'django.utils.log.AdminEmailHandler'
|
|
|
|
}
|
|
|
|
},
|
|
|
|
'loggers': {
|
|
|
|
'django': {
|
2015-03-24 06:17:43 +08:00
|
|
|
'handlers': ['console', 'mail_admins'],
|
2015-09-16 02:13:34 +08:00
|
|
|
'level': 'INFO',
|
2012-09-25 04:30:38 +08:00
|
|
|
},
|
2015-11-07 00:19:41 +08:00
|
|
|
'django.server': {
|
|
|
|
'handlers': ['django.server'],
|
|
|
|
'level': 'INFO',
|
|
|
|
'propagate': False,
|
|
|
|
},
|
2012-09-25 04:30:38 +08:00
|
|
|
}
|
|
|
|
}
|
2010-10-04 23:12:39 +08:00
|
|
|
|
2011-09-17 00:41:38 +08:00
|
|
|
|
2013-12-31 19:28:01 +08:00
|
|
|
def configure_logging(logging_config, logging_settings):
|
|
|
|
if logging_config:
|
2014-03-31 03:11:05 +08:00
|
|
|
# First find the logging configuration function ...
|
2014-01-21 04:15:14 +08:00
|
|
|
logging_config_func = import_string(logging_config)
|
2013-12-31 19:28:01 +08:00
|
|
|
|
2015-02-06 07:30:11 +08:00
|
|
|
logging.config.dictConfig(DEFAULT_LOGGING)
|
2013-12-31 19:28:01 +08:00
|
|
|
|
|
|
|
# ... then invoke it with the logging settings
|
|
|
|
if logging_settings:
|
|
|
|
logging_config_func(logging_settings)
|
|
|
|
|
|
|
|
|
2010-10-04 23:12:39 +08:00
|
|
|
class AdminEmailHandler(logging.Handler):
|
2011-04-02 00:10:22 +08:00
|
|
|
"""An exception log handler that emails log entries to site admins.
|
2010-10-04 23:12:39 +08:00
|
|
|
|
|
|
|
If the request is passed as the first argument to the log record,
|
2011-06-09 06:18:46 +08:00
|
|
|
request data will be provided in the email report.
|
2010-10-04 23:12:39 +08:00
|
|
|
"""
|
2011-09-02 11:04:02 +08:00
|
|
|
|
2019-02-24 23:10:14 +08:00
|
|
|
def __init__(self, include_html=False, email_backend=None, reporter_class=None):
|
2017-12-07 22:10:32 +08:00
|
|
|
super().__init__()
|
2011-09-02 11:04:02 +08:00
|
|
|
self.include_html = include_html
|
2012-11-20 01:57:40 +08:00
|
|
|
self.email_backend = email_backend
|
2019-09-08 01:08:12 +08:00
|
|
|
self.reporter_class = import_string(reporter_class or settings.DEFAULT_EXCEPTION_REPORTER)
|
2011-09-02 11:04:02 +08:00
|
|
|
|
2010-10-04 23:12:39 +08:00
|
|
|
def emit(self, record):
|
|
|
|
try:
|
2011-03-28 10:11:19 +08:00
|
|
|
request = record.request
|
2010-10-04 23:12:39 +08:00
|
|
|
subject = '%s (%s IP): %s' % (
|
|
|
|
record.levelname,
|
2013-05-27 10:47:50 +08:00
|
|
|
('internal' if request.META.get('REMOTE_ADDR') in settings.INTERNAL_IPS
|
|
|
|
else 'EXTERNAL'),
|
2012-02-12 20:19:02 +08:00
|
|
|
record.getMessage()
|
2010-10-04 23:12:39 +08:00
|
|
|
)
|
2012-02-11 17:31:18 +08:00
|
|
|
except Exception:
|
2011-03-17 18:33:08 +08:00
|
|
|
subject = '%s: %s' % (
|
|
|
|
record.levelname,
|
2011-09-02 11:04:02 +08:00
|
|
|
record.getMessage()
|
2011-03-17 18:33:08 +08:00
|
|
|
)
|
2010-12-06 22:21:51 +08:00
|
|
|
request = None
|
2012-02-11 17:31:18 +08:00
|
|
|
subject = self.format_subject(subject)
|
2010-10-04 23:12:39 +08:00
|
|
|
|
2015-07-09 23:27:07 +08:00
|
|
|
# Since we add a nicely formatted traceback on our own, create a copy
|
|
|
|
# of the log record without the exception data.
|
|
|
|
no_exc_record = copy(record)
|
|
|
|
no_exc_record.exc_info = None
|
|
|
|
no_exc_record.exc_text = None
|
|
|
|
|
2010-10-04 23:12:39 +08:00
|
|
|
if record.exc_info:
|
2010-12-06 22:21:51 +08:00
|
|
|
exc_info = record.exc_info
|
2010-10-04 23:12:39 +08:00
|
|
|
else:
|
2011-09-02 11:04:02 +08:00
|
|
|
exc_info = (None, record.getMessage(), None)
|
2010-10-04 23:12:39 +08:00
|
|
|
|
2019-02-24 23:10:14 +08:00
|
|
|
reporter = self.reporter_class(request, is_email=True, *exc_info)
|
2015-07-09 23:27:07 +08:00
|
|
|
message = "%s\n\n%s" % (self.format(no_exc_record), reporter.get_traceback_text())
|
2013-05-17 22:33:36 +08:00
|
|
|
html_message = reporter.get_traceback_html() if self.include_html else None
|
2014-11-11 05:21:31 +08:00
|
|
|
self.send_mail(subject, message, fail_silently=True, html_message=html_message)
|
|
|
|
|
|
|
|
def send_mail(self, subject, message, *args, **kwargs):
|
|
|
|
mail.mail_admins(subject, message, *args, connection=self.connection(), **kwargs)
|
2012-11-20 01:57:40 +08:00
|
|
|
|
|
|
|
def connection(self):
|
2013-01-22 03:27:38 +08:00
|
|
|
return get_connection(backend=self.email_backend, fail_silently=True)
|
2011-06-22 14:01:44 +08:00
|
|
|
|
2012-02-11 17:31:18 +08:00
|
|
|
def format_subject(self, subject):
|
|
|
|
"""
|
2016-05-04 00:22:46 +08:00
|
|
|
Escape CR and LF characters.
|
2012-02-11 17:31:18 +08:00
|
|
|
"""
|
2016-05-04 00:22:46 +08:00
|
|
|
return subject.replace('\n', '\\n').replace('\r', '\\r')
|
2012-02-11 17:31:18 +08:00
|
|
|
|
2011-06-22 14:01:44 +08:00
|
|
|
|
|
|
|
class CallbackFilter(logging.Filter):
|
|
|
|
"""
|
|
|
|
A logging filter that checks the return value of a given callable (which
|
|
|
|
takes the record-to-be-logged as its only parameter) to decide whether to
|
|
|
|
log a record.
|
|
|
|
"""
|
|
|
|
def __init__(self, callback):
|
|
|
|
self.callback = callback
|
|
|
|
|
|
|
|
def filter(self, record):
|
|
|
|
if self.callback(record):
|
|
|
|
return 1
|
|
|
|
return 0
|
2011-09-17 00:41:38 +08:00
|
|
|
|
|
|
|
|
|
|
|
class RequireDebugFalse(logging.Filter):
|
|
|
|
def filter(self, record):
|
|
|
|
return not settings.DEBUG
|
2012-09-27 01:56:21 +08:00
|
|
|
|
|
|
|
|
|
|
|
class RequireDebugTrue(logging.Filter):
|
|
|
|
def filter(self, record):
|
2012-12-25 05:32:41 +08:00
|
|
|
return settings.DEBUG
|
2015-11-07 00:19:41 +08:00
|
|
|
|
|
|
|
|
|
|
|
class ServerFormatter(logging.Formatter):
|
|
|
|
def __init__(self, *args, **kwargs):
|
|
|
|
self.style = color_style()
|
2017-01-21 21:13:44 +08:00
|
|
|
super().__init__(*args, **kwargs)
|
2015-11-07 00:19:41 +08:00
|
|
|
|
|
|
|
def format(self, record):
|
|
|
|
msg = record.msg
|
2016-09-26 06:25:38 +08:00
|
|
|
status_code = getattr(record, 'status_code', None)
|
2015-11-07 00:19:41 +08:00
|
|
|
|
2016-09-26 06:25:38 +08:00
|
|
|
if status_code:
|
|
|
|
if 200 <= status_code < 300:
|
2015-11-07 00:19:41 +08:00
|
|
|
# Put 2XX first, since it should be the common case
|
|
|
|
msg = self.style.HTTP_SUCCESS(msg)
|
2016-09-26 06:25:38 +08:00
|
|
|
elif 100 <= status_code < 200:
|
2015-11-07 00:19:41 +08:00
|
|
|
msg = self.style.HTTP_INFO(msg)
|
2016-09-26 06:25:38 +08:00
|
|
|
elif status_code == 304:
|
2015-11-07 00:19:41 +08:00
|
|
|
msg = self.style.HTTP_NOT_MODIFIED(msg)
|
2016-09-26 06:25:38 +08:00
|
|
|
elif 300 <= status_code < 400:
|
2015-11-07 00:19:41 +08:00
|
|
|
msg = self.style.HTTP_REDIRECT(msg)
|
2016-09-26 06:25:38 +08:00
|
|
|
elif status_code == 404:
|
2015-11-07 00:19:41 +08:00
|
|
|
msg = self.style.HTTP_NOT_FOUND(msg)
|
2016-09-26 06:25:38 +08:00
|
|
|
elif 400 <= status_code < 500:
|
2015-11-07 00:19:41 +08:00
|
|
|
msg = self.style.HTTP_BAD_REQUEST(msg)
|
|
|
|
else:
|
2016-09-26 06:25:38 +08:00
|
|
|
# Any 5XX, or any other status code
|
2015-11-07 00:19:41 +08:00
|
|
|
msg = self.style.HTTP_SERVER_ERROR(msg)
|
|
|
|
|
2016-09-26 06:25:38 +08:00
|
|
|
if self.uses_server_time() and not hasattr(record, 'server_time'):
|
|
|
|
record.server_time = self.formatTime(record, self.datefmt)
|
|
|
|
|
2015-11-07 00:19:41 +08:00
|
|
|
record.msg = msg
|
2017-01-21 21:13:44 +08:00
|
|
|
return super().format(record)
|
2016-09-26 06:25:38 +08:00
|
|
|
|
|
|
|
def uses_server_time(self):
|
2017-11-19 08:15:08 +08:00
|
|
|
return self._fmt.find('{server_time}') >= 0
|
2017-07-13 12:09:18 +08:00
|
|
|
|
|
|
|
|
|
|
|
def log_response(message, *args, response=None, request=None, logger=request_logger, level=None, exc_info=None):
|
|
|
|
"""
|
|
|
|
Log errors based on HttpResponse status.
|
|
|
|
|
|
|
|
Log 5xx responses as errors and 4xx responses as warnings (unless a level
|
|
|
|
is given as a keyword argument). The HttpResponse status_code and the
|
|
|
|
request are passed to the logger's extra parameter.
|
|
|
|
"""
|
|
|
|
# Check if the response has already been logged. Multiple requests to log
|
|
|
|
# the same response can be received in some cases, e.g., when the
|
|
|
|
# response is the result of an exception and is logged at the time the
|
|
|
|
# exception is caught so that the exc_info can be recorded.
|
|
|
|
if getattr(response, '_has_been_logged', False):
|
|
|
|
return
|
|
|
|
|
|
|
|
if level is None:
|
|
|
|
if response.status_code >= 500:
|
|
|
|
level = 'error'
|
|
|
|
elif response.status_code >= 400:
|
|
|
|
level = 'warning'
|
|
|
|
else:
|
|
|
|
level = 'info'
|
|
|
|
|
|
|
|
getattr(logger, level)(
|
|
|
|
message, *args,
|
|
|
|
extra={
|
|
|
|
'status_code': response.status_code,
|
|
|
|
'request': request,
|
|
|
|
},
|
|
|
|
exc_info=exc_info,
|
|
|
|
)
|
|
|
|
response._has_been_logged = True
|