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: I31c26b269ef6db9ebf44eb381eb6745ce40fc4ea

entrypoint.sh

@@ -23,7 +23,9 @@ if [ "$1" = 'server' ]; then
         --paste config:/etc/promenade/api-paste.ini \
         --enable-threads \
         --threads "${PROMENADE_THREADS}" \
-        --workers "${PROMENADE_WORKERS}"
+        --workers "${PROMENADE_WORKERS}" \
+        --logger "null file:/dev/null" \
+        --log-route "null health"
 fi
 
 exec ${@}

promenade/config.py

@@ -60,8 +60,8 @@ class Configuration:
         return cls(documents=documents, **kwargs)
 
     @classmethod
-    def from_design_ref(cls, design_ref, **kwargs):
+    def from_design_ref(cls, design_ref, ctx=None, **kwargs):
-        documents, use_dh_engine = dr.get_documents(design_ref)
+        documents, use_dh_engine = dr.get_documents(design_ref, ctx)
 
         return cls(
             documents=documents,

promenade/control/base.py

@@ -95,10 +95,10 @@ class PromenadeRequestContext(context.RequestContext):
     Context object for promenade resource requests
     """
 
-    def __init__(self, external_marker=None, policy_engine=None, **kwargs):
+    def __init__(self, context_marker=None, policy_engine=None, **kwargs):
         self.log_level = 'error'
         self.request_id = str(uuid.uuid4())
-        self.external_marker = external_marker
+        self.context_marker = context_marker
         self.policy_engine = policy_engine
         self.is_admin_project = False
         self.authenticated = False
@@ -123,8 +123,14 @@ class PromenadeRequestContext(context.RequestContext):
     def remove_role(self, role):
         self.roles = [x for x in self.roles if x != role]
 
-    def set_external_marker(self, marker):
+    def set_context_marker(self, context_marker):
-        self.external_marker = marker
+        self.context_marker = context_marker
+
+    def set_request_id(self, request_id):
+        self.request_id = request_id
+
+    def set_end_user(self, end_user):
+        self.end_user = end_user
 
     def set_policy_engine(self, engine):
         self.policy_engine = engine
@@ -144,9 +150,10 @@ class PromenadeRequestContext(context.RequestContext):
     def to_log_context(self):
         result = {}
 
-        result['request_id'] = self.request_id
+        result['request_id'] = getattr(self, 'request_id', None)
-        result['external_id'] = self.external_marker
+        result['context_marker'] = getattr(self, 'context_marker', None)
-        result['user'] = self.user
+        result['end_user'] = getattr(self, 'end_user', None)
+        result['user'] = getattr(self, 'user', None)
 
         return result
 

promenade/control/middleware.py

@@ -26,8 +26,10 @@ class AuthMiddleware(object):
         ctx = req.context
         ctx.set_policy_engine(policy.policy_engine)
 
-        for k, v in req.headers.items():
+        # don't spam log with headers for health checks
-            LOG.debug("Request with header %s: %s" % (k, v))
+        if not req.url.endswith('/health'):
+            for k, v in req.headers.items():
+                LOG.debug("Request with header %s: %s" % (k, v))
 
         auth_status = req.get_header(
             'X-SERVICE-IDENTITY-STATUS')  # will be set to Confirmed or Invalid
@@ -100,21 +102,69 @@ class ContextMiddleware(object):
 
     def process_request(self, req, resp):
         ctx = req.context
-        ext_marker = req.get_header('X-Context-Marker')
+        context_marker = req.get_header('X-CONTEXT-MARKER')
-        if ext_marker is not None and self._is_uuid_like(ext_marker):
+        end_user = req.get_header('X-END-USER')
-            # external passed in an ok context marker
+        if context_marker is not None:
-            ctx.set_external_marker(ext_marker)
+            ctx.set_context_marker(context_marker)
         else:
-            # use the request id
+            ctx.set_context_marker(ctx.request_id)
-            ctx.set_external_marker(ctx.request_id)
+        if end_user is not None:
+            ctx.set_end_user(end_user)
+        else:
+            ctx.set_end_user(ctx.user)
 
 
 class LoggingMiddleware(object):
+    def process_request(self, req, resp):
+        # don't log health checks
+        if not req.url.endswith('/health'):
+            ctx = req.context
+            LOG.info(
+                "Request: %s %s %s",
+                req.method,
+                req.uri,
+                req.query_string,
+                ctx=ctx)
+
     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,
+                    ctx=ctx)
+        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,
+                ctx=ctx)
 
-        resp.append_header('X-Promenade-Req', ctx.request_id)
+    def _get_resp_code(self, resp):
-        LOG.info('%s %s - %s', req.method, req.uri, resp.status, ctx=ctx)
+        # 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
 
 
 class NoAuthFilter(object):

promenade/control/validatedesign.py

@@ -28,10 +28,11 @@ class ValidateDesignResource(base.BaseResource):
     def on_post(self, req, resp):
         result = ValidationMessage()
         try:
+            ctx = req.context
             json_data = self.req_json(req)
             href = json_data.get('href', None)
             config = Configuration.from_design_ref(
-                href, allow_missing_substitutions=False)
+                href, allow_missing_substitutions=False, ctx=ctx)
             result = validation.validate_all(config)
         except exceptions.InvalidFormatError as e:
             msg = "Invalid JSON Format: %s" % str(e)

promenade/design_ref.py

@@ -14,15 +14,15 @@ _DECKHAND_PREFIX = 'deckhand+'
 DH_TIMEOUT = 10 * 60  # 10 Minute timeout for fetching from Deckhand.
 
 
-def get_documents(design_ref):
+def get_documents(design_ref, ctx=None):
-    LOG.debug('Fetching design_ref="%s"', design_ref)
+    LOG.debug('Fetching design_ref="%s"', design_ref, ctx=ctx)
     if design_ref.startswith(_DECKHAND_PREFIX):
-        response = _get_from_deckhand(design_ref)
+        response = _get_from_deckhand(design_ref, ctx)
         use_dh_engine = False
     else:
         response = _get_from_basic_web(design_ref)
         use_dh_engine = True
-    LOG.debug('Got response for design_ref="%s"', design_ref)
+    LOG.debug('Got response for design_ref="%s"', design_ref, ctx=ctx)
 
     response.raise_for_status()
 
@@ -33,12 +33,20 @@ def _get_from_basic_web(design_ref):
     return requests.get(design_ref)
 
 
-def _get_from_deckhand(design_ref):
+def _get_from_deckhand(design_ref, ctx=None):
     keystone_args = {}
     for attr in ('auth_url', 'password', 'project_domain_name', 'project_name',
                  'username', 'user_domain_name'):
         keystone_args[attr] = cfg.CONF.get('keystone_authtoken', {}).get(attr)
+    if ctx is not None:
+        addl_headers = {
+            'X-CONTEXT-MARKER': ctx.context_marker,
+            'X-END-USER': ctx.end_user
+        }
+    else:
+        addl_headers = {}
     auth = keystoneauth1.identity.v3.Password(**keystone_args)
-    session = keystoneauth1.session.Session(auth=auth)
+    session = keystoneauth1.session.Session(
+        auth=auth, additional_headers=addl_headers)
 
     return session.get(design_ref[len(_DECKHAND_PREFIX):], timeout=DH_TIMEOUT)

promenade/logging.py

@@ -4,12 +4,16 @@ import logging.config
 
 __all__ = ['getLogger', 'setup']
 
-LOG_FORMAT = '%(asctime)s %(levelname)-8s %(request_id)s %(external_id)s %(user)s %(name)s:%(filename)s:%(lineno)3d:%(funcName)s %(message)s'  # noqa
+LOG_FORMAT = '%(asctime)s %(levelname)-8s ' \
+             'req_id=%(request_id)s ctx=%(context_marker)s ' \
+             'end_user=%(end_user)s user=%(user)s ' \
+             '%(name)s:%(filename)s:%(lineno)3d:%(funcName)s %(message)s'
 
 BLANK_CONTEXT_VALUES = [
-    'external_id',
+    'context_marker',
     'request_id',
     'user',
+    'end_user',
 ]
 
 DEFAULT_CONFIG = {

requirements-direct.txt

@@ -14,4 +14,4 @@ pbr==3.0.1
 pyyaml==3.12
 requests==2.18.4
 uwsgi==2.0.15
-git+https://git.openstack.org/openstack/airship-deckhand@2f596fd62713bfd4149757a77a4943dd60b64cca
+git+https://git.openstack.org/openstack/airship-deckhand@c1d0ff683ee94626b709954ad442b4f202f714d5