diff --git a/apps/amo/views.py b/apps/amo/views.py index 5ec68a4258..90565ed0e6 100644 --- a/apps/amo/views.py +++ b/apps/amo/views.py @@ -12,7 +12,6 @@ from django.views.decorators.http import require_POST import commonware.log import jingo import waffle -from django_arecibo.tasks import post from django_statsd.views import record as django_statsd_record from django_statsd.clients import statsd @@ -90,9 +89,6 @@ def handler404(request): def handler500(request): webapp = settings.APP_PREVIEW template = 'amo/500%s.html' % ('_apps' if webapp else '') - arecibo = getattr(settings, 'ARECIBO_SERVER_URL', '') - if arecibo: - post(request, 500) if request.path_info.startswith('/api/'): return api.views.handler500(request) else: diff --git a/lib/log_settings_base.py b/lib/log_settings_base.py index a7cc539f94..9d5a43b4b3 100644 --- a/lib/log_settings_base.py +++ b/lib/log_settings_base.py @@ -1,43 +1,11 @@ import logging import logging.handlers -import socket from django.conf import settings import commonware.log import dictconfig - -class NullHandler(logging.Handler): - - def emit(self, record): - pass - - -class UnicodeLogger(logging.handlers.SysLogHandler): - - def emit(self, record): - msg = self.format(record) + '\000' - prio = '<%d>' % self.encodePriority(self.facility, - self.mapPriority(record.levelname)) - if type(msg) is unicode: - msg = msg.encode('utf-8') - msg = prio + msg - try: - if self.unixsocket: - try: - self.socket.send(msg) - except socket.error: - self._connect_unixsocket(self.address) - self.socket.send(msg) - else: - self.socket.sendto(msg, self.address) - except (KeyboardInterrupt, SystemExit): - raise - except: - self.handleError(record) - - base_fmt = ('%(name)s:%(levelname)s %(message)s ' ':%(pathname)s:%(lineno)s') @@ -69,29 +37,44 @@ cfg = { 'formatter': 'debug', }, 'syslog': { - '()': UnicodeLogger, + 'class': 'lib.misc.admin_log.UnicodeHandler', 'facility': logging.handlers.SysLogHandler.LOG_LOCAL7, 'formatter': 'prod', }, 'syslog2': { - '()': UnicodeLogger, + 'class': 'lib.misc.admin_log.UnicodeHandler', 'facility': logging.handlers.SysLogHandler.LOG_LOCAL7, 'formatter': 'prod2', }, 'null': { - '()': NullHandler, + 'class': 'lib.misc.admin_log.NullHandler', }, 'mail_admins': { 'level': 'ERROR', 'class': 'lib.misc.admin_log.AdminEmailHandler' }, + 'statsd': { + 'level': 'ERROR', + 'class': 'lib.misc.admin_log.StatsdHandler', + }, + 'arecibo': { + 'level': 'ERROR', + 'class': 'lib.misc.admin_log.AreciboHandler', + }, + 'errortype_syslog': { + 'class': 'lib.misc.admin_log.ErrorSyslogHandler', + 'facility': logging.handlers.SysLogHandler.LOG_LOCAL7, + 'formatter': 'prod', + }, }, 'loggers': { 'z': {}, 'django.request': { - 'handlers': ['mail_admins'], + # Note these handlers will choose what they want to emit and when. + 'handlers': ['mail_admins', 'errortype_syslog', + 'statsd', 'arecibo'], 'level': 'ERROR', - 'propagate': False, + 'propagate': True, }, }, 'root': {}, diff --git a/lib/misc/admin_log.py b/lib/misc/admin_log.py index f782af53e3..e02f3440f1 100644 --- a/lib/misc/admin_log.py +++ b/lib/misc/admin_log.py @@ -1,47 +1,42 @@ -""" -This is from Django utils/log.py 3fe4e7a2~1. -""" +import re + +NO_EMAIL_PATTERNS = { + 'IOError': re.compile(r'IOError: request data read error'), + 'TimeoutError': + re.compile(r'TimeoutError: Request timed out after 5.000000 seconds'), + 'OperationError': + re.compile(r'''OperationalError: (2006, 'MySQL server ''' + '''has gone away')'''), + 'OperationError': + re.compile(r'''OperationalError: (2013, 'Lost connection to ''' + '''MySQL server during query')'''), + 'OperationError': + re.compile(r'''OperationalError: (2013, "Lost connection to ''' + '''MySQL server at 'reading initial communication ''' + '''packet', system error: 0")'''), + 'OperationError': + re.compile(r'''OperationalError: (1205, 'Lock wait timeout ''' + '''exceeded; try restarting transaction')'''), +} + import logging -import sys +import socket +import traceback + +from django.conf import settings from django.core import mail -# Make sure a NullHandler is available -# This was added in Python 2.7/3.2 -try: - from logging import NullHandler -except ImportError: - class NullHandler(logging.Handler): - def emit(self, record): - pass +from django_arecibo.tasks import post +from django_statsd.clients import statsd -# Make sure that dictConfig is available -# This was added in Python 2.7/3.2 -try: - from logging.config import dictConfig -except ImportError: - from django.utils.dictconfig import dictConfig -if sys.version_info < (2, 5): - class LoggerCompat(object): - def __init__(self, logger): - self._logger = logger +getLogger = logging.getLogger - def __getattr__(self, name): - val = getattr(self._logger, name) - if callable(val): - def _wrapper(*args, **kwargs): - # Python 2.4 logging module doesn't support 'extra' parameter to - # methods of Logger - kwargs.pop('extra', None) - return val(*args, **kwargs) - return _wrapper - else: - return val - def getLogger(name=None): - return LoggerCompat(logging.getLogger(name=name)) -else: - getLogger = logging.getLogger +class NullHandler(logging.Handler): + + def emit(self, record): + pass # Ensure the creation of the Django logger # with a null handler. This ensures we don't get any @@ -50,40 +45,136 @@ logger = getLogger('django') if not logger.handlers: logger.addHandler(NullHandler()) -class AdminEmailHandler(logging.Handler): - """An exception log handler that emails log entries to site admins - If the request is passed as the first argument to the log record, - request data will be provided in the - """ +class UnicodeHandler(logging.handlers.SysLogHandler): + def emit(self, record): - import traceback - from django.conf import settings + msg = self.format(record) + '\000' + prio = '<%d>' % self.encodePriority(self.facility, + self.mapPriority(record.levelname)) + if type(msg) is unicode: + msg = msg.encode('utf-8') + msg = prio + msg + try: + if self.unixsocket: + try: + self.socket.send(msg) + except socket.error: + self._connect_unixsocket(self.address) + self.socket.send(msg) + else: + self.socket.sendto(msg, self.address) + except (KeyboardInterrupt, SystemExit): + raise + except: + self.handleError(record) + + +class ErrorTypeHandler(logging.Handler): + """A base class for a logging handler that examines the error.""" + + def should_email(self, record): + # Examines the record and adds an attribute to see if the + # error should be mailed or not. Only does this once. It's up to + # other handlers to decide to use this information. + if getattr(record, 'should_email', None) is None: + tb = '\n'.join(traceback.format_exception(*record.exc_info)) + record.should_email = True + for name, pattern in NO_EMAIL_PATTERNS.iteritems(): + if re.search(pattern, tb): + record.should_email = False + break + + return record.should_email + + def emitted(self, name): + # This is currently in place for the tests. Patches welcome. + pass + + +class StatsdHandler(ErrorTypeHandler): + """Send error to statsd, we'll send this every time.""" + + def emit(self, record): + statsd.incr('error.%s' % record.exc_info[0].__name__.lower()) + self.emitted(self.__class__.__name__.lower()) + + +class AreciboHandler(ErrorTypeHandler): + """Send error to Arecibo, only if we are also emailing it.""" + + def emit(self, record): + arecibo = getattr(settings, 'ARECIBO_SERVER_URL', '') + if not self.should_email(record) or not arecibo: + return + + post(record.request, 500) + self.emitted(self.__class__.__name__.lower()) + + +class ErrorSyslogHandler(UnicodeHandler, ErrorTypeHandler): + """Send error to syslog, only if we aren't mailing it.""" + + def emit(self, record): + if self.should_email(record): + return + + super(ErrorSyslogHandler, self).emit(record) + self.emitted(self.__class__.__name__.lower()) + + +class AdminEmailHandler(ErrorTypeHandler): + """An exception log handler that emails log entries to site admins.""" + + def __init__(self, include_html=False): + logging.Handler.__init__(self) + self.include_html = include_html + + def emit(self, record): + if not self.should_email(record): + return try: - if sys.version_info < (2,5): - # A nasty workaround required because Python 2.4's logging - # module doesn't support passing in extra context. - # For this handler, the only extra data we need is the - # request, and that's in the top stack frame. - request = record.exc_info[2].tb_frame.f_locals['request'] - else: - request = record.request - - subject = '%s (%s IP): %s' % ( - record.levelname, - (request.META.get('REMOTE_ADDR') in settings.INTERNAL_IPS and 'internal' or 'EXTERNAL'), - request.path + request = record.request + subject = '%s (%s IP): %s' % (record.levelname, + (request.META.get('REMOTE_ADDR') in settings.INTERNAL_IPS and + 'internal' or 'EXTERNAL'), + record.msg ) request_repr = repr(request) except: - subject = 'Error: Unknown URL' - request_repr = "Request repr() unavailable" + subject = '%s: %s' % (record.levelname, record.getMessage()) + request = None + request_repr = "Request repr() unavailable." if record.exc_info: - stack_trace = '\n'.join(traceback.format_exception(*record.exc_info)) + stack_trace = '\n'.join(traceback + .format_exception(*record.exc_info)) else: stack_trace = 'No stack trace available' message = "%s\n\n%s" % (stack_trace, request_repr) mail.mail_admins(subject, message, fail_silently=True) + + self.emitted(self.__class__.__name__.lower()) + + +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 + + +class RequireDebugFalse(logging.Filter): + def filter(self, record): + return not settings.DEBUG diff --git a/lib/misc/tests/__init__.py b/lib/misc/tests/__init__.py new file mode 100644 index 0000000000..e69de29bb2 diff --git a/lib/misc/tests/test_log.py b/lib/misc/tests/test_log.py new file mode 100644 index 0000000000..db64229f5c --- /dev/null +++ b/lib/misc/tests/test_log.py @@ -0,0 +1,106 @@ +import dictconfig +import logging +import sys + +from django.conf import settings +from django.core import mail + +from mock import Mock, patch +from nose.tools import eq_ + +import amo.tests +from lib.misc.admin_log import ErrorTypeHandler +from test_utils import RequestFactory + +cfg = { + 'version': 1, + 'handlers': { + 'test_syslog': { + 'class': 'lib.misc.admin_log.ErrorSyslogHandler', + }, + 'test_mail_admins': { + 'class': 'lib.misc.admin_log.AdminEmailHandler' + }, + 'test_statsd_handler': { + 'class': 'lib.misc.admin_log.StatsdHandler', + }, + 'test_arecibo_handler': { + 'class': 'lib.misc.admin_log.AreciboHandler', + } + }, + 'loggers': { + 'test.lib.misc.logging': { + 'handlers': ['test_mail_admins', + 'test_syslog', + 'test_statsd_handler', + 'test_arecibo_handler'], + 'level': 'ERROR', + 'propagate': False, + }, + }, +} + + +class TestErrorLog(amo.tests.TestCase): + + def setUp(self): + dictconfig.dictConfig(cfg) + self.log = logging.getLogger('test.lib.misc.logging') + + def division_error(self): + try: + 1 / 0 + except: + return sys.exc_info() + + def io_error(self): + class IOError(Exception): + pass + try: + raise IOError('request data read error') + except: + return sys.exc_info() + + def fake_record(self, exc_info): + record = Mock() + record.exc_info = exc_info + record.should_email = None + return record + + def test_email(self): + self.log.error('blargh!', + exc_info=self.division_error(), + extra={'request': RequestFactory().get('/')}) + eq_(len(mail.outbox), 1) + + def test_no_email(self): + self.log.error('blargh!', + exc_info=self.io_error(), + extra={'request': RequestFactory().get('/')}) + eq_(len(mail.outbox), 0) + + def test_should_email(self): + et = ErrorTypeHandler() + assert et.should_email(self.fake_record(self.division_error())) + + def test_should_not_email(self): + et = ErrorTypeHandler() + assert not et.should_email(self.fake_record(self.io_error())) + + @patch('lib.misc.admin_log.ErrorTypeHandler.emitted') + @patch.object(settings, 'ARECIBO_SERVER_URL', 'something') + def test_called_email(self, emitted): + self.log.error('blargh!', + exc_info=self.division_error(), + extra={'request': RequestFactory().get('/')}) + eq_(set([n[0][0] for n in emitted.call_args_list]), + set(['adminemailhandler', 'statsdhandler', 'arecibohandler'])) + + @patch('lib.misc.admin_log.ErrorTypeHandler.emitted') + @patch.object(settings, 'ARECIBO_SERVER_URL', 'something') + def test_called_no_email(self, emitted): + self.log.error('blargh!', + exc_info=self.io_error(), + extra={'request': RequestFactory().get('/')}) + eq_(set([n[0][0] for n in emitted.call_args_list]), + set(['errorsysloghandler', 'statsdhandler'])) diff --git a/lib/settings_base.py b/lib/settings_base.py index 1760f24f47..e45a85351f 100644 --- a/lib/settings_base.py +++ b/lib/settings_base.py @@ -1268,11 +1268,6 @@ DEFAULT_MINVER = COMPAT[4]['main'] # URL for reporting arecibo errors too. If not set, won't be sent. ARECIBO_SERVER_URL = "" -# Make AMO group posts and wait for 60 seconds when we get lots of errors. -ARECIBO_SETTINGS = { - 'GROUP_POSTS': True, - 'GROUP_WAIT': 60, -} # A whitelist of domains that the authentication script will redirect to upon # successfully logging in or out.