Log client-id in UCP API endpoints

Adds functionality to read context marker and end-user
from request headers and log that information where
available, to aid in tracing transactions that span
multiple Airship components.

Change-Id: I35c9e56f84f29420c4f3c081453cb81aa892fa7d

charts/deckhand/values.yaml

@@ -272,6 +272,7 @@ conf:
       use_stderr: true
       use_syslog: true
       profiler: false
+      logging_context_format_string: '%(asctime)s,%(msecs)03d %(levelname)-8s req_id=%(request_id)s ctx=%(context_marker)s end_user=%(end_user)s user=%(user_name)s %(name)s:%(filename)s:%(lineno)3d:%(funcName)s %(message)s'
     database:
       connection:
     keystone_authtoken:

deckhand/client/client.py

@@ -194,12 +194,12 @@ class Client(object):
         :param str username: Username
         """
 
+        self.logger = logger or logging.getLogger(__name__)
+
         self.project_id = project_id
         self.project_name = project_name
         self.user_id = user_id
 
-        self.logger = logger or logging.getLogger(__name__)
-
         self.buckets = buckets.BucketManager(self)
         self.revisions = revisions.RevisionManager(self)
         self.tags = tags.RevisionTagManager(self)

deckhand/context.py

@@ -25,15 +25,23 @@ class RequestContext(context.RequestContext):
     accesses the system, as well as additional request information.
     """
 
-    def __init__(self, project=None, **kwargs):
+    def __init__(self,
+                 project=None,
+                 context_marker='-',
+                 end_user='-',
+                 **kwargs):
         if project:
             kwargs['tenant'] = project
         self.project = project
+        self.context_marker = context_marker
+        self.end_user = end_user
         super(RequestContext, self).__init__(**kwargs)
 
     def to_dict(self):
         out_dict = super(RequestContext, self).to_dict()
         out_dict['roles'] = self.roles
+        out_dict['context_marker'] = self.context_marker
+        out_dict['end_user'] = self.end_user
 
         if out_dict.get('tenant'):
             out_dict['project'] = out_dict['tenant']

deckhand/control/middleware.py

@@ -59,6 +59,9 @@ class ContextMiddleware(object):
                 raise falcon.HTTPUnauthorized()
         else:
             req.context = deckhand.context.RequestContext.from_environ(req.env)
+        # set transaction correlation fields in context
+        req.context.end_user = req.headers.get('X-END-USER')
+        req.context.context_marker = req.headers.get('X-CONTEXT-MARKER')
 
 
 class HookableMiddlewareMixin(object):
@@ -178,3 +181,52 @@ class YAMLTranslator(HookableMiddlewareMixin, object):
                 setattr(resp, attr, yaml.safe_dump(resp_attr, **kwargs))
             elif isinstance(resp_attr, (list, tuple)):
                 setattr(resp, attr, yaml.safe_dump_all(resp_attr, **kwargs))
+
+
+class LoggingMiddleware(object):
+    def process_resource(self, req, resp, resource, params):
+        # don't log health checks
+        if not req.url.endswith('/health'):
+            LOG.info(
+                "Request: %s %s %s",
+                req.method,
+                req.uri,
+                req.query_string)
+
+    def process_response(self, req, resp, resource, req_succeeded):
+        ctx = req.context
+        # only log health check responses if the check failed
+        if req.url.endswith('/health'):
+            resp_code = self._get_resp_code(resp)
+            if not resp_code == 204:
+                LOG.error(
+                    'Health check has failed with response status %s',
+                    resp.status)
+        else:
+            context_marker = getattr(ctx, 'context_marker', None)
+            request_id = getattr(ctx, 'request_id', None)
+            user = getattr(ctx, 'user', None)
+            end_user = getattr(ctx, 'end_user', None)
+            if context_marker is not None:
+                resp.append_header('X-Context-Marker', context_marker)
+            if request_id is not None:
+                resp.append_header('X-Deckhand-Req', request_id)
+            if end_user is not None:
+                resp.append_header('X-End-User', end_user)
+            if user is not None:
+                resp.append_header('X-User-Name', user)
+            LOG.info(
+                "Response: %s %s %s",
+                req.method,
+                req.uri,
+                resp.status)
+
+    def _get_resp_code(self, resp):
+        # Falcon response object doesn't have a raw status code.
+        # Splits by the first space
+        try:
+            return int(resp.status.split(" ", 1)[0])
+        except ValueError:
+            # if for some reason this Falcon response doesn't have a valid
+            # status, return a high value sentinel
+            return 9999

deckhand/service.py

@@ -85,7 +85,8 @@ def deckhand_app_factory(global_config, **local_config):
     # method for `YAMLTranslator` should execute after that of any other
     # middleware to convert the response to YAML format.
     middleware_list = [middleware.YAMLTranslator(),
-                       middleware.ContextMiddleware()]
+                       middleware.ContextMiddleware(),
+                       middleware.LoggingMiddleware()]
 
     app = falcon.API(request_type=base.DeckhandRequest,
                      middleware=middleware_list)