new log handlers which log to multiple places diverting common errors to the log files, emailing less common errors (bug 719234)

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:

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': {},

lib/misc/admin_log.py

@@ -1,47 +1,42 @@
-"""
+import re
-This is from Django utils/log.py 3fe4e7a2~1.
+
-"""
+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
+from django_arecibo.tasks import post
-# This was added in Python 2.7/3.2
+from django_statsd.clients import statsd
-try:
-    from logging import NullHandler
-except ImportError:
-    class NullHandler(logging.Handler):
-        def emit(self, record):
-            pass
 
-# 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):
+getLogger = logging.getLogger
-    class LoggerCompat(object):
-        def __init__(self, logger):
-            self._logger = logger
 
-        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):
+class NullHandler(logging.Handler):
-        return LoggerCompat(logging.getLogger(name=name))
+
-else:
+    def emit(self, record):
-    getLogger = logging.getLogger
+        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,
+class UnicodeHandler(logging.handlers.SysLogHandler):
-    request data will be provided in the
+
-    """
     def emit(self, record):
-        import traceback
+        msg = self.format(record) + '\000'
-        from django.conf import settings
+        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):
+            request = record.request
-                # A nasty workaround required because Python 2.4's logging
+            subject = '%s (%s IP): %s' % (record.levelname,
-                # module doesn't support passing in extra context.
+                (request.META.get('REMOTE_ADDR') in settings.INTERNAL_IPS and
-                # For this handler, the only extra data we need is the
+                 'internal' or 'EXTERNAL'),
-                # request, and that's in the top stack frame.
+                record.msg
-                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_repr = repr(request)
         except:
-            subject = 'Error: Unknown URL'
+            subject = '%s: %s' % (record.levelname, record.getMessage())
-            request_repr = "Request repr() unavailable"
+            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

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']))

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.