Log to console using mozlog json format in dev/stage/prod

docs/topics/development/logging.rst

@@ -16,9 +16,9 @@ production, we're piping everything into ``syslog``.
 Configuration
 -------------
 
-The root logger is set up from ``log_settings.py`` in the ``src/olympia/lib``
-directory of addons-server. It sets up sensible defaults, but you can twiddle
-with these settings:
+The root logger is set up from ``log_settings_base.py`` in the
+``src/olympia/lib`` of addons-server. It sets up sensible defaults, but you can
+twiddle with these settings:
 
 ``LOG_LEVEL``
     This setting is required, and defaults to ``logging.DEBUG``, which will let
@@ -28,9 +28,12 @@ with these settings:
         import logging
         LOG_LEVEL = logging.WARN
 
-``HAS_SYSLOG``
-    Set this to ``False`` if you don't want logging sent to syslog when
-    ``DEBUG`` is ``False``.
+``USE_SYSLOG``
+    Set this to ``True`` if you want logging sent to syslog.
+
+``USE_MOZLOG``
+    Set this to ``True`` if you want logging sent to the console using mozlog
+    format.
 
 ``LOGGING``
     See PEP 391 and log_settings.py for formatting help.  Each section of LOGGING

requirements/prod.txt

@@ -197,6 +197,9 @@ djangorestframework==3.6.2 \
 djangorestframework-jwt==1.10.0 \
     --hash=sha256:46453744249526f5754112e0ccc8f63f57b9e9c2f8cb40ebc1e7a75bd8d9c8d7 \
     --hash=sha256:0322f7f15fad47f31263cbba123a18bffc374b81ed5a8714192478f8dcd24965
+dockerflow==2017.4.0 \
+    --hash=sha256:9e790b0217ec8d049d0752ce375face26c758e72a983e8afc9f1428b9c3d2fa7 \
+    --hash=sha256:e327835f7dc9c4ea7d0b7a2d3a654660c06f4d3001c244627e554c3d00af556f
 drf-nested-routers==0.90.0 \
     --hash=sha256:818fcc37b6cafff52f4afae012b8de85970a1b931f1e47c2f07a24fd141eb476 \
     --hash=sha256:3346bcfb151d221d499b3b7932cc6e5cee005ea50f1343a2f5cd2f85e7b1d77f

settings.py

@@ -5,7 +5,6 @@ won't be tracked in git).
 
 """
 import os
-import re
 from urlparse import urlparse
 
 from olympia.lib.settings_base import *  # noqa
@@ -40,7 +39,9 @@ CACHES = {
     }
 }
 
-HAS_SYSLOG = False  # syslog is used if HAS_SYSLOG and NOT DEBUG.
+# For local development, we don't need syslog and mozlog loggers.
+USE_SYSLOG = False
+USE_MOZLOG = False
 
 # If you're not running on SSL you'll want this to be False.
 SESSION_COOKIE_SECURE = False

src/olympia/amo/middleware.py

@@ -20,6 +20,7 @@ from django.utils.encoding import iri_to_uri, force_bytes
 from django.utils.translation import activate
 
 import MySQLdb as mysql
+from dockerflow.django.middleware import DockerflowMiddleware
 
 from olympia import amo
 from olympia.amo.utils import render
@@ -249,3 +250,9 @@ class ScrubRequestOnException(object):
             # Clearing out all cookies in request.META. They will already
             # be sent with request.COOKIES.
             request.META['HTTP_COOKIE'] = '******'
+
+
+class DockerflowMiddlewareWithoutViews(DockerflowMiddleware):
+    """Like DockerflowMiddleware, but without hijacking any views, because at
+    the moment we have our own."""
+    viewpatterns = []

src/olympia/conf/dev/settings.py

@@ -65,6 +65,7 @@ INBOUND_EMAIL_VALIDATION_KEY = env('INBOUND_EMAIL_VALIDATION_KEY', default='')
 INBOUND_EMAIL_DOMAIN = env('INBOUND_EMAIL_DOMAIN', default=DOMAIN)
 
 SYSLOG_TAG = "http_app_addons_dev"
+MOZLOG_NAME = SYSLOG_TAG
 SYSLOG_TAG2 = "http_app_addons_dev_timer"
 SYSLOG_CSP = "http_app_addons_dev_csp"
 

src/olympia/core/logger.py

@@ -1,5 +1,7 @@
 import logging
 
+import dockerflow.logging
+
 from olympia import core
 
 
@@ -31,3 +33,15 @@ class Formatter(logging.Formatter):
         for name in 'REMOTE_ADDR', 'USERNAME':
             record.__dict__.setdefault(name, '')
         return super(Formatter, self).format(record)
+
+
+class JsonFormatter(dockerflow.logging.JsonLogFormatter):
+    """Like JsonLogFormatter, but with uid and remoteAddressChain set from
+    current user and ip, following mozlog format.
+
+    See Formatter above for the legacy, console version of this."""
+    def format(self, record):
+        record.__dict__['uid'] = record.__dict__.pop('USERNAME', '')
+        record.__dict__['remoteAddressChain'] = record.__dict__.pop(
+            'REMOTE_ADDR', '')
+        return super(JsonFormatter, self).format(record)

src/olympia/core/tests/test_logger.py

@@ -50,3 +50,13 @@ class LoggerTests(TestCase):
         formatter.format(record)
         assert 'USERNAME' in record.__dict__
         assert 'REMOTE_ADDR' in record.__dict__
+
+    def test_json_formatter(self):
+        formatter = olympia.core.logger.JsonFormatter()
+        record = logging.makeLogRecord({})
+        # These would be set by the adapter.
+        record.__dict__['USERNAME'] = 'foo'
+        record.__dict__['REMOTE_ADDR'] = '127.0.0.1'
+        formatter.format(record)
+        assert record.__dict__['uid'] == 'foo'
+        assert record.__dict__['remoteAddressChain'] == '127.0.0.1'

src/olympia/lib/log_settings_base.py

@@ -18,6 +18,16 @@ formatters = {
         'datefmt': '%H:%M:%S',
         'format': '%(asctime)s ' + base_fmt,
     },
+    'error': {
+        '()': olympia.core.logger.Formatter,
+        'datefmt': '%H:%M:%S',
+        'format': ('%s %s: [%%(USERNAME)s][%%(REMOTE_ADDR)s] %s'
+                   % (settings.HOSTNAME, settings.SYSLOG_TAG, error_fmt)),
+    },
+    'json': {
+        '()': olympia.core.logger.JsonFormatter,
+        'logger_name': settings.MOZLOG_NAME
+    },
     'prod': {
         '()': olympia.core.logger.Formatter,
         'datefmt': '%H:%M:%S',
@@ -30,12 +40,6 @@ formatters = {
         'format': ('%s %s: [%%(USERNAME)s][%%(REMOTE_ADDR)s] %s'
                    % (settings.HOSTNAME, settings.SYSLOG_TAG2, base_fmt)),
     },
-    'error': {
-        '()': olympia.core.logger.Formatter,
-        'datefmt': '%H:%M:%S',
-        'format': ('%s %s: [%%(USERNAME)s][%%(REMOTE_ADDR)s] %s'
-                   % (settings.HOSTNAME, settings.SYSLOG_TAG, error_fmt)),
-    },
 }
 
 handlers = {
@@ -43,6 +47,18 @@ handlers = {
         '()': logging.StreamHandler,
         'formatter': 'debug',
     },
+    'mozlog': {
+        'level': 'DEBUG',
+        'class': 'logging.StreamHandler',
+        'formatter': 'json'
+    },
+    'null': {
+        'class': 'logging.NullHandler',
+    },
+    'statsd': {
+        'level': 'ERROR',
+        'class': 'django_statsd.loggers.errors.StatsdHandler',
+    },
     'syslog': {
         'class': 'mozilla_logger.log.UnicodeHandler',
         'facility': logging.handlers.SysLogHandler.LOG_LOCAL7,
@@ -53,28 +69,10 @@ handlers = {
         'facility': logging.handlers.SysLogHandler.LOG_LOCAL7,
         'formatter': 'prod2',
     },
-    'null': {
-        'class': 'logging.NullHandler',
-    },
-    'statsd': {
-        'level': 'ERROR',
-        'class': 'django_statsd.loggers.errors.StatsdHandler',
-    },
 }
 
 loggers = {
-    'z': {},
     'amo': {},
-    'django.request': {
-        'handlers': ['statsd'],
-        'level': 'ERROR',
-        'propagate': True,
-    },
-    'z.celery': {
-        'handlers': ['statsd'],
-        'level': 'ERROR',
-        'propagate': True,
-    },
     'amo.validator': {
         'handlers': ['statsd'],
         'level': 'ERROR',
@@ -83,12 +81,23 @@ loggers = {
     'caching': {
         'level': 'ERROR',
     },
-    'newrelic': {
-        'level': 'WARNING',
+    'django.request': {
+        'handlers': ['statsd'],
+        'level': 'ERROR',
+        'propagate': True,
     },
     'elasticsearch': {
         'level': 'WARNING',
     },
+    'newrelic': {
+        'level': 'WARNING',
+    },
+    'z': {},
+    'z.celery': {
+        'handlers': ['statsd'],
+        'level': 'ERROR',
+        'propagate': True,
+    },
 }
 
 cfg = {
@@ -102,22 +111,40 @@ cfg = {
 
 
 def log_configure():
-    """You have to explicitly call this to configure logging."""
+    """Configure logging by augmenting settings.LOGGING with our custom
+    dynamic configuration.
+
+    This needs to be called explicitely before doing any logging."""
     for key, value in settings.LOGGING.items():
         if isinstance(cfg[key], dict):
             cfg[key].update(value)
         else:
             cfg[key] = value
 
-    USE_SYSLOG = settings.HAS_SYSLOG and not settings.DEBUG
-
-    if USE_SYSLOG:
+    if settings.USE_SYSLOG:
         cfg['loggers']['z.timer'] = {'handlers': ['syslog2']}
+    if settings.USE_MOZLOG:
+        # MozLog Application Request Summary. This is the logger
+        # DockerflowMiddleware uses on every request - we only enable it when
+        # USE_MOZLOG is True.
+        cfg['loggers']['request.summary'] = {
+            'handlers': ['mozlog'],
+            'level': 'DEBUG',
+        }
+    # Enable syslog or mozlog handlers by default if the corresponding settings
+    # are set, otherwise default to the raw basic console.
+    default_handlers = []
+    if settings.USE_MOZLOG:
+        default_handlers.append('mozlog')
+    if settings.USE_SYSLOG:
+        default_handlers.append('syslog')
+    if not default_handlers:
+        default_handlers = ['console']
 
     # Set the level and handlers for all loggers.
     for logger in cfg['loggers'].values() + [cfg['root']]:
         if 'handlers' not in logger:
-            logger['handlers'] = ['syslog' if USE_SYSLOG else 'console']
+            logger['handlers'] = default_handlers
         if 'level' not in logger:
             logger['level'] = settings.LOG_LEVEL
         if logger is not cfg['root'] and 'propagate' not in logger:

src/olympia/lib/settings_base.py

@@ -378,18 +378,22 @@ SECURE_CONTENT_TYPE_NOSNIFF = True
 SECURE_HSTS_SECONDS = 31536000
 
 MIDDLEWARE_CLASSES = (
-    # AMO URL middleware comes first so everyone else sees nice URLs.
+    # Statsd and logging come first to get timings etc. Munging REMOTE_ADDR
+    # must come before middlewares potentially using REMOTE_ADDR, so it's
+    # also up there.
     'django_statsd.middleware.GraphiteRequestTimingMiddleware',
     'django_statsd.middleware.GraphiteMiddleware',
+    'olympia.amo.middleware.SetRemoteAddrFromForwardedFor',
+    'olympia.amo.middleware.DockerflowMiddlewareWithoutViews',
+
+    # AMO URL middleware is as high as possible to get locale/app aware URLs.
     'olympia.amo.middleware.LocaleAndAppURLMiddleware',
+
     # Mobile detection should happen in Zeus.
     'mobility.middleware.DetectMobileMiddleware',
     'mobility.middleware.XMobileMiddleware',
     'olympia.amo.middleware.RemoveSlashMiddleware',
 
-    # Munging REMOTE_ADDR must come before ThreadRequest.
-    'olympia.amo.middleware.SetRemoteAddrFromForwardedFor',
-
     'django.middleware.security.SecurityMiddleware',
     'django.middleware.clickjacking.XFrameOptionsMiddleware',
 
@@ -408,8 +412,9 @@ MIDDLEWARE_CLASSES = (
     'olympia.search.middleware.ElasticsearchExceptionMiddleware',
     'session_csrf.CsrfMiddleware',
 
-    # This should come after AuthenticationMiddlewareWithoutAPI and after
-    # SetRemoteAddrFromForwardedFor.
+    # This should come after AuthenticationMiddlewareWithoutAPI (to get the
+    # current user) and after SetRemoteAddrFromForwardedFor (to get the correct
+    # IP).
     'olympia.access.middleware.UserAndAddrMiddleware',
 
     'olympia.amo.middleware.ScrubRequestOnException',
@@ -1252,12 +1257,14 @@ CELERYD_TASK_SOFT_TIME_LIMIT = 60 * 30
 
 # Logging
 LOG_LEVEL = logging.DEBUG
-HAS_SYSLOG = True  # syslog is used if HAS_SYSLOG and NOT DEBUG.
+USE_SYSLOG = True  # syslog is used if HAS_SYSLOG and NOT DEBUG.
+USE_MOZLOG = True
 SYSLOG_TAG = "http_app_addons"
 SYSLOG_TAG2 = "http_app_addons2"
-# See PEP 391 and log_settings.py for formatting help.  Each section of
+MOZLOG_NAME = SYSLOG_TAG
+# See PEP 391 and log_settings_base.py for formatting help.  Each section of
 # LOGGING will get merged into the corresponding section of
-# log_settings.py. Handlers and log levels are set up automatically based
+# log_settings_base.py. Handlers and log levels are set up automatically based
 # on LOG_LEVEL and DEBUG unless you set them here.  Messages will not
 # propagate through a logger unless propagate: True is set.
 LOGGING_CONFIG = None