diff --git a/docs/topics/development/logging.rst b/docs/topics/development/logging.rst index 72c691d308d3..175ad7c47fd0 100644 --- a/docs/topics/development/logging.rst +++ b/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 diff --git a/requirements/prod.txt b/requirements/prod.txt index c6369ece7bab..59df4a914a12 100644 --- a/requirements/prod.txt +++ b/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 diff --git a/settings.py b/settings.py index a1f0ed95b55c..baa4764be490 100644 --- a/settings.py +++ b/settings.py @@ -5,7 +5,6 @@ """ import os -import re from urlparse import urlparse from olympia.lib.settings_base import * # noqa @@ -40,7 +39,9 @@ } } -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 diff --git a/src/olympia/amo/middleware.py b/src/olympia/amo/middleware.py index 73c1cf7a0cb1..2e6c2861e802 100644 --- a/src/olympia/amo/middleware.py +++ b/src/olympia/amo/middleware.py @@ -20,6 +20,7 @@ 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 @@ def process_exception(self, request, exception): # 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 = [] diff --git a/src/olympia/conf/dev/settings.py b/src/olympia/conf/dev/settings.py index f72321cd2545..74e38286bd57 100644 --- a/src/olympia/conf/dev/settings.py +++ b/src/olympia/conf/dev/settings.py @@ -65,6 +65,7 @@ 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" diff --git a/src/olympia/core/logger.py b/src/olympia/core/logger.py index a8b98f763c28..3dfd3915ce1d 100644 --- a/src/olympia/core/logger.py +++ b/src/olympia/core/logger.py @@ -1,5 +1,7 @@ import logging +import dockerflow.logging + from olympia import core @@ -11,7 +13,12 @@ def getLogger(name=None): class AmoLoggerAdapter(logging.LoggerAdapter): - """Adds the REMOTE_ADDR and USERNAME to every logging message's kwargs.""" + """ + Adapter adding the REMOTE_ADDR and USERNAME to every logging message's + kwargs extra dict, which in return will automatically be merged in every + LogRecord nstance, making those properties available for the formatter(s) + to use. + """ def __init__(self, logger, extra=None): super(AmoLoggerAdapter, self).__init__(logger, extra or {}) @@ -25,9 +32,24 @@ def process(self, msg, kwargs): class Formatter(logging.Formatter): - """Formatter that makes sure REMOTE_ADDR and USERNAME are available.""" + """Formatter that makes sure REMOTE_ADDR and USERNAME are available. + + Relies on AmoLoggerAdapter to make sure those variables will be set.""" def format(self, record): 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) diff --git a/src/olympia/core/tests/test_logger.py b/src/olympia/core/tests/test_logger.py index 690887cc5018..381299a6b77b 100644 --- a/src/olympia/core/tests/test_logger.py +++ b/src/olympia/core/tests/test_logger.py @@ -50,3 +50,13 @@ def test_formatter(self): 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' diff --git a/src/olympia/lib/log_settings_base.py b/src/olympia/lib/log_settings_base.py index f253759fe1e7..4f50e43b3823 100644 --- a/src/olympia/lib/log_settings_base.py +++ b/src/olympia/lib/log_settings_base.py @@ -18,23 +18,27 @@ 'datefmt': '%H:%M:%S', 'format': '%(asctime)s ' + base_fmt, }, - 'prod': { + 'error': { '()': olympia.core.logger.Formatter, 'datefmt': '%H:%M:%S', 'format': ('%s %s: [%%(USERNAME)s][%%(REMOTE_ADDR)s] %s' - % (settings.HOSTNAME, settings.SYSLOG_TAG, base_fmt)), + % (settings.HOSTNAME, settings.SYSLOG_TAG, error_fmt)), }, - 'prod2': { + 'json': { + '()': olympia.core.logger.JsonFormatter, + 'logger_name': settings.MOZLOG_NAME + }, + 'prod': { '()': olympia.core.logger.Formatter, 'datefmt': '%H:%M:%S', 'format': ('%s %s: [%%(USERNAME)s][%%(REMOTE_ADDR)s] %s' - % (settings.HOSTNAME, settings.SYSLOG_TAG2, base_fmt)), + % (settings.HOSTNAME, settings.SYSLOG_TAG, base_fmt)), }, - 'error': { + 'prod2': { '()': olympia.core.logger.Formatter, 'datefmt': '%H:%M:%S', 'format': ('%s %s: [%%(USERNAME)s][%%(REMOTE_ADDR)s] %s' - % (settings.HOSTNAME, settings.SYSLOG_TAG, error_fmt)), + % (settings.HOSTNAME, settings.SYSLOG_TAG2, base_fmt)), }, } @@ -43,6 +47,18 @@ '()': 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,41 +69,34 @@ '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': { + 'amo.validator': { 'handlers': ['statsd'], 'level': 'ERROR', 'propagate': True, }, - 'z.celery': { - 'handlers': ['statsd'], + 'caching': { 'level': 'ERROR', - 'propagate': True, }, - 'amo.validator': { + 'django.request': { 'handlers': ['statsd'], 'level': 'ERROR', 'propagate': True, }, - 'caching': { - 'level': 'ERROR', + 'elasticsearch': { + 'level': 'WARNING', }, 'newrelic': { 'level': 'WARNING', }, - 'elasticsearch': { - 'level': 'WARNING', + 'z': {}, + 'z.celery': { + 'handlers': ['statsd'], + 'level': 'ERROR', + 'propagate': True, }, } @@ -102,22 +111,40 @@ 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: diff --git a/src/olympia/lib/settings_base.py b/src/olympia/lib/settings_base.py index dc8a6caedaf1..af1b8dd1d171 100644 --- a/src/olympia/lib/settings_base.py +++ b/src/olympia/lib/settings_base.py @@ -378,18 +378,22 @@ def JINJA_CONFIG(): 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 @@ def JINJA_CONFIG(): '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 @@ def JINJA_CONFIG(): # Logging LOG_LEVEL = logging.DEBUG -HAS_SYSLOG = True # syslog is used if HAS_SYSLOG and NOT DEBUG. +USE_SYSLOG = True +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