[Do Not Merge] [Example] Add per-request logging context

api/api.py

@@ -21,6 +21,7 @@
 from .handlers import searchhandler
 from .handlers import schemahandler
 from .handlers import reporthandler
+from .request import SciTranRequest, set_current_request
 
 log = config.log
 
@@ -190,6 +191,7 @@ def _format(route):
 
 
 def dispatcher(router, request, response):
+    set_current_request(request)
     try:
         rv = router.default_dispatcher(request, response)
         if rv is not None:
@@ -198,18 +200,22 @@ def dispatcher(router, request, response):
     except webapp2.HTTPException as e:
         util.send_json_http_exception(response, str(e), e.code)
     except Exception as e: # pylint: disable=broad-except
+        request.logger.error("Error dispatching request", exc_info=True)
         if config.get_item('core', 'debug'):
             message = traceback.format_exc()
         else:
             message = 'Internal Server Error'
         util.send_json_http_exception(response, message, 500)
+    finally:
+        set_current_request(None)
 
 def app_factory(*_, **__):
     # pylint: disable=protected-access,unused-argument
 
     # don't use config.get_item() as we don't want to require the database at startup
     application = webapp2.WSGIApplication(routes, debug=config.__config['core']['debug'])
     application.router.set_dispatcher(dispatcher)
+    application.request_class = SciTranRequest
 
     # configure new relic
     if config.__config['core']['newrelic']:

api/auth/containerauth.py

@@ -3,10 +3,6 @@
 """
 
 from . import _get_access, INTEGER_ROLES
-from .. import config
-
-log = config.log
-
 
 def default_container(handler, container=None, target_parent_container=None):
     """

api/auth/groupauth.py

@@ -1,7 +1,5 @@
 from . import _get_access, INTEGER_ROLES
-from .. import config
-
-log = config.log
+from ..request import get_current_request
 
 
 def default(handler, group=None):
@@ -41,8 +39,9 @@ def f(method, query=None, projection=None):
                         query['roles'] = {'$elemMatch': {'_id': handler.uid, 'access': 'admin'}}
                     else:
                         query['roles._id'] = handler.uid
-            log.debug(query)
-            log.debug(projection)
+            request = get_current_request()
+            request.logger.debug(query)
+            request.logger.debug(projection)
             return exec_op(method, query=query, projection=projection)
         return f
     return g

api/auth/listauth.py

@@ -5,11 +5,8 @@
 
 import sys
 
-from .. import config
 from . import _get_access, INTEGER_ROLES
-
-log = config.log
-
+from ..request import get_current_request
 
 def default_sublist(handler, container):
     """
@@ -75,7 +72,8 @@ def permissions_sublist(handler, container):
     access = _get_access(handler.uid, handler.user_site, container)
     def g(exec_op):
         def f(method, _id, query_params = None, payload = None, exclude_params=None):
-            log.debug(query_params)
+            request = get_current_request()
+            request.logger.debug(query_params)
             if method in ['GET', 'DELETE']  and query_params.get('_id') == handler.uid and query_params.get('site') == handler.user_site:
                 return exec_op(method, _id, query_params, payload, exclude_params)
             elif access >= INTEGER_ROLES['admin']:

api/auth/userauth.py

@@ -1,8 +1,3 @@
-from .. import config
-
-log = config.log
-
-
 def default(handler, user=None):
     def g(exec_op):
         def f(method, _id=None, query=None, payload=None, projection=None):

api/base.py

@@ -15,19 +15,17 @@
 from . import validators
 from .dao import APIConsistencyException, APIConflictException, APINotFoundException
 
-log = config.log
-
 class RequestHandler(webapp2.RequestHandler):
 
     json_schema = None
 
     def __init__(self, request=None, response=None): # pylint: disable=super-init-not-called
+        """Set uid, source_site, public_request, and superuser"""
         self.initialize(request, response)
         self.debug = config.get_item('core', 'insecure')
-
-        # set uid, source_site, public_request, and superuser
         self.uid = None
         self.source_site = None
+
         drone_request = False
 
         user_agent = self.request.headers.get('User-Agent', '')
@@ -101,6 +99,10 @@ def __init__(self, request=None, response=None): # pylint: disable=super-init-no
 
         self.set_origin(drone_request)
 
+    def initialize(self, request, response):
+        super(RequestHandler, self).initialize(request, response)
+        request.logger.info("Initialized request")
+
     def authenticate_user_api_key(self, key):
         """
         AuthN for user accounts via api key. Calls self.abort on failure.
@@ -129,10 +131,10 @@ def authenticate_user(self, access_token):
 
         if cached_token:
             uid = cached_token['uid']
-            log.debug('looked up cached token in %dms', ((datetime.datetime.utcnow() - timestamp).total_seconds() * 1000.))
+            self.request.logger.debug('looked up cached token in %dms', ((datetime.datetime.utcnow() - timestamp).total_seconds() * 1000.))
         else:
             uid = self.validate_oauth_token(access_token, timestamp)
-            log.debug('looked up remote token in %dms', ((datetime.datetime.utcnow() - timestamp).total_seconds() * 1000.))
+            self.request.logger.debug('looked up remote token in %dms', ((datetime.datetime.utcnow() - timestamp).total_seconds() * 1000.))
 
             # Cache the token for future requests
             config.db.authtokens.replace_one({'_id': access_token}, {'uid': uid, 'timestamp': timestamp}, upsert=True)
@@ -153,7 +155,7 @@ def validate_oauth_token(self, access_token, timestamp):
             err_msg = 'Invalid OAuth2 token.'
             site_id = config.get_item('site', 'id')
             headers = {'WWW-Authenticate': 'Bearer realm="{}", error="invalid_token", error_description="{}"'.format(site_id, err_msg)}
-            log.warn('{} Request headers: {}'.format(err_msg, str(self.request.headers.items())))
+            self.request.logger.warning('{} Request headers: {}'.format(err_msg, str(self.request.headers.items())))
             self.abort(401, err_msg, headers=headers)
 
         identity = json.loads(r.content)
@@ -271,7 +273,7 @@ def handle_exception(self, exception, debug):
             code = exception.code
         elif isinstance(exception, validators.InputValidationException):
             code = 400
-            log.warn(str(exception))
+            self.request.logger.warning(str(exception))
         elif isinstance(exception, APIConsistencyException):
             code = 400
         elif isinstance(exception, APINotFoundException):
@@ -285,7 +287,7 @@ def handle_exception(self, exception, debug):
 
         if code == 500:
             tb = traceback.format_exc()
-            log.error(tb)
+            self.request.logger.error(tb)
 
         util.send_json_http_exception(self.response, str(exception), code)
 
@@ -295,7 +297,7 @@ def dispatch(self):
         site_id = config.get_item('site', 'id')
         target_site = self.get_param('site', site_id)
         if target_site == site_id:
-            log.debug('from %s %s %s %s %s', self.source_site, self.uid, self.request.method, self.request.path, str(self.request.GET.mixed()))
+            self.request.logger.debug('from %s %s %s %s %s', self.source_site, self.uid, self.request.method, self.request.path, str(self.request.GET.mixed()))
             return super(RequestHandler, self).dispatch()
         else:
             if not site_id:
@@ -317,7 +319,7 @@ def dispatch(self):
             params = self.request.GET.mixed()
             if 'user' in params: del params['user']
             del params['site']
-            log.debug(' for %s %s %s %s %s', target_site, self.uid, self.request.method, self.request.path, str(self.request.GET.mixed()))
+            self.request.logger.debug(' for %s %s %s %s %s', target_site, self.uid, self.request.method, self.request.path, str(self.request.GET.mixed()))
             target_uri = target['api_uri'] + self.request.path.split('/api')[1]
             r = requests.request(
                     self.request.method,
@@ -342,5 +344,5 @@ def abort(self, code, detail=None, **kwargs):
                 'validator': detail.validator,
                 'validator_value': detail.validator_value,
             }
-        log.warning(str(self.uid) + ' ' + str(code) + ' ' + str(detail))
+        self.request.logger.warning(str(self.uid) + ' ' + str(code) + ' ' + str(detail))
         webapp2.abort(code, detail=detail, **kwargs)

api/dao/consistencychecker.py

@@ -4,8 +4,6 @@
 from .. import config
 from . import APIConsistencyException
 
-log = config.log
-
 def noop(*args, **kwargs): # pylint: disable=unused-argument
     pass
 

api/dao/containerstorage.py

@@ -4,13 +4,11 @@
 
 from .. import util
 from .. import config
+from ..request import get_current_request
 from . import consistencychecker
 from . import APIStorageException, APIConflictException
 from . import hierarchy
 
-log = config.log
-
-
 class ContainerStorage(object):
     """
     This class provides access to mongodb collection elements (called containers).
@@ -50,7 +48,8 @@ def exec_op(self, action, _id=None, payload=None, query=None, user=None,
         raise ValueError('action should be one of GET, POST, PUT, DELETE')
 
     def _create_el(self, payload):
-        log.debug(payload)
+        request = get_current_request()
+        request.logger.debug(payload)
         try:
             result = self.dbc.insert_one(payload)
         except pymongo.errors.DuplicateKeyError:
@@ -103,16 +102,18 @@ def _get_all_el(self, query, user, projection):
                 query['$and'] = [{'permissions': {'$elemMatch': user}}, {'permissions': query.pop('permissions')}]
             else:
                 query['permissions'] = {'$elemMatch': user}
-        log.debug(query)
-        log.debug(projection)
+        request = get_current_request()
+        request.logger.debug(query)
+        request.logger.debug(projection)
         result = self.dbc.find(query, projection)
         return list(result)
 
 
 class GroupStorage(ContainerStorage):
 
     def _create_el(self, payload):
-        log.debug(payload)
+        request = get_current_request()
+        request.logger.debug(payload)
         roles = payload.pop('roles')
         return self.dbc.update_one(
             {'_id': payload['_id']},
@@ -121,4 +122,3 @@ def _create_el(self, payload):
                 '$setOnInsert': {'roles': roles}
             },
             upsert=True)
-

api/dao/hierarchy.py

@@ -10,8 +10,7 @@
 from .. import util
 from .. import config
 from . import APIStorageException, APINotFoundException, containerutil
-
-log = config.log
+from ..request import get_current_request
 
 PROJECTION_FIELDS = ['group', 'name', 'label', 'timestamp', 'permissions', 'public']
 
@@ -280,13 +279,13 @@ def find_existing_hierarchy(metadata):
     project = metadata.get('project', {})
     session = metadata.get('session', {})
     acquisition = metadata.get('acquisition', {})
-
+    request = get_current_request()
     # Fail if some fields are missing
     try:
         acquisition_uid = acquisition['uid']
         session_uid = session['uid']
     except Exception as e:
-        log.error(metadata)
+        request.logger.error(metadata)
         raise APIStorageException(str(e))
 
     # Confirm session and acquisition exist
@@ -320,7 +319,8 @@ def upsert_bottom_up_hierarchy(metadata):
         _ = acquisition['uid']
         session_uid = session['uid']
     except Exception as e:
-        log.error(metadata)
+        request = get_current_request()
+        request.logger.error(metadata)
         raise APIStorageException(str(e))
 
     session_obj = config.db.sessions.find_one({'uid': session_uid}, ['project'])
@@ -411,12 +411,13 @@ def _update_container_nulls(base_query, update, container_type):
         bulk.find(base_query).update_one({'$set': {'metadata': m_update}})
 
     update_dict = util.mongo_dict(update)
+    request = get_current_request()
     for k,v in update_dict.items():
         q = {}
         q.update(base_query)
         q['$or'] = [{k: {'$exists': False}}, {k: None}]
         u = {'$set': {k: v}}
-        log.debug('the query is {} and the update is {}'.format(q,u))
+        request.logger.debug('the query is {} and the update is {}'.format(q,u))
         bulk.find(q).update_one(u)
     bulk.execute()
     return config.db[coll_name].find_one(base_query)