Add log JSON formatter

app.py

@@ -1,3 +1,4 @@
+import hashlib
 import json
 import logging
 import os
@@ -13,7 +14,7 @@ from jwkest.jwk import RSAKey
 from werkzeug.routing import BaseConverter
 
 import features
-
+from auth.auth_context import get_authenticated_user
 from avatars.avatars import Avatar
 from buildman.manager.buildcanceller import BuildCanceller
 from data import database
@@ -31,6 +32,7 @@ from oauth.services.github import GithubOAuthService
 from oauth.services.gitlab import GitLabOAuthService
 from oauth.loginmanager import OAuthLoginManager
 from storage import Storage
+from util.log import filter_logs
 from util import get_app_url
 from util.saas.analytics import Analytics
 from util.saas.useranalytics import UserAnalytics
@@ -49,6 +51,7 @@ from util.tufmetadata.api import TUFMetadataAPI
 from util.security.instancekeys import InstanceKeys
 from util.security.signing import Signer
 
+
 OVERRIDE_CONFIG_DIRECTORY = 'conf/stack/'
 OVERRIDE_CONFIG_YAML_FILENAME = 'conf/stack/config.yaml'
 OVERRIDE_CONFIG_PY_FILENAME = 'conf/stack/config.py'
@@ -102,6 +105,10 @@ if (app.config['PREFERRED_URL_SCHEME'] == 'https' and
 # Load features from config.
 features.import_features(app.config)
 
+CONFIG_DIGEST = hashlib.sha256(json.dumps(app.config, default=str)).hexdigest()[0:8]
+
+logger.debug("Loaded config", extra={"config": app.config})
+
 
 class RequestWithId(Request):
   request_gen = staticmethod(urn_generator(['request']))
@@ -114,26 +121,60 @@ class RequestWithId(Request):
 @app.before_request
 def _request_start():
   logger.debug('Starting request: %s', request.path)
+  logger.info("request-start", extra={"request_id": request.request_id})
+
+
+DEFAULT_FILTER = lambda x: '[FILTERED]'
+FILTERED_VALUES = [
+  {'key': ['password'], 'fn': DEFAULT_FILTER},
+  {'key': ['user', 'password'], 'fn': DEFAULT_FILTER},
+  {'key': ['blob'], 'fn': lambda x: x[0:8]}
+]
 
 
 @app.after_request
-def _request_end(r):
+def _request_end(resp):
+  jsonbody = request.get_json(force=True, silent=True)
+  values = request.values.to_dict()
+
+  if jsonbody and not isinstance(jsonbody, dict):
+    jsonbody = {'_parsererror': jsonbody}
+
+  if isinstance(values, dict):
+    filter_logs(values, FILTERED_VALUES)
+
+  extra = {
+    "endpoint": request.endpoint,
+    "request_id" : request.request_id,
+    "remote_addr": request.remote_addr,
+    "http_method": request.method,
+    "original_url": request.url,
+    "path": request.path,
+    "parameters":  values,
+    "json_body": jsonbody,
+    "confsha": CONFIG_DIGEST,
+  }
+
+  if request.user_agent is not None:
+    extra["user-agent"] = request.user_agent.string
+
+  user = get_authenticated_user()
+
+  if user:
+    extra['user'] = {'email': user.email,
+                     'uuid': user.uuid,
+                     'org': user.organization,
+                     'robot': user.robot}
+
+  logger.info("request-end", extra=extra)
+
   logger.debug('Ending request: %s', request.path)
-  return r
+  return resp
 
 
-class InjectingFilter(logging.Filter):
-  def filter(self, record):
-    if _request_ctx_stack.top is not None:
-      record.msg = '[%s] %s' % (request.request_id, record.msg)
-    return True
 
 root_logger = logging.getLogger()
 
-# Add the request id filter to all handlers of the root logger
-for handler in root_logger.handlers:
-  handler.addFilter(InjectingFilter())
-
 app.request_class = RequestWithId
 
 # Register custom converters.