User context tracing through logging

This PS adds entry in log for user id and passes on the context
maker to other Airship components from Shipyard during API call.

This will ensure easy tracing of user and context through log
tracing.

Change-Id: Ib9bfa8f20b641f8bb6c2dca967d9388e30d5735c

src/bin/shipyard_airflow/shipyard_airflow/control/action/action_validators.py

@@ -29,10 +29,34 @@ from shipyard_airflow.control.validators.validate_target_nodes import \
     ValidateTargetNodes
 from shipyard_airflow.control.validators.validate_test_cleanup import \
     ValidateTestCleanup
+from shipyard_airflow.shipyard_const import CustomHeaders
 
 LOG = logging.getLogger(__name__)
 
 
+addl_headers_map = {
+    'context_marker': CustomHeaders.CONTEXT_MARKER.value,
+    'user': CustomHeaders.END_USER.value
+}
+
+
+def _get_additional_headers(action):
+    """
+    Populates additional headers from action dict. The headers sets
+    context_marker and end_user for audit trace logging
+    :param dict action: action info available
+    :returns: dict additional_headers
+    """
+    addl_headers = {}
+
+    for key, header in addl_headers_map.items():
+        header_value = action.get(key)
+        if header_value:
+            addl_headers.update({header: header_value})
+
+    return addl_headers
+
+
 def validate_committed_revision(action, **kwargs):
     """Invokes a validation that the committed revision of site design exists
     """
@@ -50,8 +74,9 @@ def validate_deployment_action_full(action, **kwargs):
           - If the deployment strategy is specified, but is missing, error.
           - Check that there are no cycles in the groups
     """
+    addl_headers = _get_additional_headers(action)
     validator = ValidateDeploymentAction(
-        dh_client=service_clients.deckhand_client(),
+        dh_client=service_clients.deckhand_client(addl_headers=addl_headers),
         action=action,
         full_validation=True
     )
@@ -65,8 +90,9 @@ def validate_deployment_action_basic(action, **kwargs):
       - The deployment configuration from Deckhand using the design version
           - If the deployment configuration is missing, error
     """
+    addl_headers = _get_additional_headers(action)
     validator = ValidateDeploymentAction(
-        dh_client=service_clients.deckhand_client(),
+        dh_client=service_clients.deckhand_client(addl_headers=addl_headers),
         action=action,
         full_validation=False
     )

src/bin/shipyard_airflow/shipyard_airflow/control/action/actions_api.py

@@ -145,6 +145,8 @@ class ActionsResource(BaseResource):
         action['user'] = context.user
         # add current timestamp (UTC) to the action.
         action['timestamp'] = str(datetime.utcnow())
+        # add external marker that is the passed with request context
+        action['context_marker'] = context.request_id
         # validate that action is supported.
         LOG.info("Attempting action: %s", action['name'])
         action_mappings = _action_mappings()
@@ -187,10 +189,11 @@ class ActionsResource(BaseResource):
         action['dag_execution_date'] = dag_execution_date
         action['dag_status'] = 'SCHEDULED'
 
-        # context_marker is the uuid from the request context
-        action['context_marker'] = context.request_id
-
         # insert the action into the shipyard db
+        # TODO(b-str): When invoke_airflow_dag triggers a DAG but fails to
+        #    respond properly, no record is inserted, so there is a running
+        #    process with no tracking in the Shipyard database. This is not
+        #    ideal.
         self.insert_action(action=action)
         notes_helper.make_action_note(
             action_id=action['id'],

src/bin/shipyard_airflow/shipyard_airflow/control/helpers/configdocs_helper.py

@@ -78,7 +78,8 @@ class ConfigdocsHelper(object):
         Sets up this Configdocs helper with the supplied
         request context
         """
-        self.deckhand = DeckhandClient(context.external_marker)
+        self.deckhand = DeckhandClient(context.request_id,
+                                       end_user=context.user)
         self.ctx = context
         # The revision_dict indicates the revisions that are
         # associated with the buffered and committed doc sets. There

src/bin/shipyard_airflow/shipyard_airflow/control/helpers/deckhand_client.py

@@ -24,6 +24,7 @@ import yaml
 from shipyard_airflow.control.service_endpoints import (Endpoints,
                                                         get_endpoint,
                                                         get_token)
+from shipyard_airflow.shipyard_const import CustomHeaders
 
 CONF = cfg.CONF
 LOG = logging.getLogger(__name__)
@@ -49,11 +50,12 @@ class DeckhandClient(object):
     """
     A rudimentary client for deckhand in lieu of a provided client
     """
-    def __init__(self, context_marker):
+    def __init__(self, context_marker, end_user=None):
         """
         Sets up this Deckhand client with the supplied context marker
         """
         self.context_marker = context_marker
+        self.end_user = end_user
 
     _deckhand_svc_url = None
 
@@ -294,6 +296,17 @@ class DeckhandClient(object):
     # content-type: application/x-yaml
     # X-Context-Marker: {the context marker}
     # X-Auth-Token: {a current auth token}
+    # X-End-User: {current Shipyard user}
+
+    def _get_headers(self):
+        # Populate HTTP headers
+        headers = {
+            CustomHeaders.CONTEXT_MARKER.value: self.context_marker,
+            CustomHeaders.END_USER.value: self.end_user,
+            'X-Auth-Token': get_token()
+        }
+
+        return headers
 
     @staticmethod
     def _log_request(method, url, params=None):
@@ -310,10 +323,8 @@ class DeckhandClient(object):
         # invokes a PUT against the specified URL with the
         # supplied document_data body
         try:
-            headers = {
-                'X-Context-Marker': self.context_marker,
-                'X-Auth-Token': get_token()
-            }
+            headers = self._get_headers()
+
             if document_data is not None:
                 headers['content-type'] = 'application/x-yaml'
 
@@ -338,11 +349,8 @@ class DeckhandClient(object):
     def _get_request(self, url, params=None):
         # invokes a GET against the specified URL
         try:
-            headers = {
-                'content-type': 'application/x-yaml',
-                'X-Context-Marker': self.context_marker,
-                'X-Auth-Token': get_token()
-            }
+            headers = self._get_headers()
+            headers['content-type'] = 'application/x-yaml'
 
             if not params:
                 params = None
@@ -368,10 +376,8 @@ class DeckhandClient(object):
         # invokes a POST against the specified URL with the
         # supplied document_data body
         try:
-            headers = {
-                'X-Context-Marker': self.context_marker,
-                'X-Auth-Token': get_token()
-            }
+            headers = self._get_headers()
+
             if document_data is not None:
                 headers['content-type'] = 'application/x-yaml'
 
@@ -396,10 +402,7 @@ class DeckhandClient(object):
     def _delete_request(self, url, params=None):
         # invokes a DELETE against the specified URL
         try:
-            headers = {
-                'X-Context-Marker': self.context_marker,
-                'X-Auth-Token': get_token()
-            }
+            headers = self._get_headers()
 
             DeckhandClient._log_request('DELETE', url, params)
             response = requests.delete(

src/bin/shipyard_airflow/shipyard_airflow/control/helpers/status_helper.py

@@ -130,7 +130,9 @@ class StatusHelper(object):
 
         # get Drydock client
         if not self.drydock:
-            self.drydock = sc.drydock_client()
+            self.drydock = sc.drydock_client(
+                context_marker=self.ctx.request_id,
+                end_user=self.ctx.user)
 
         statuses = {}
         # iterate through filters to invoke required fun

src/bin/shipyard_airflow/shipyard_airflow/control/logging/logging_config.py

@@ -41,7 +41,7 @@ class LoggingConfig():
 
     _default_log_format = (
         "%(asctime)s %(levelname)-8s %(req_id)s %(external_ctx)s %(user)s "
-        "%(module)s(%(lineno)d) %(funcName)s - %(message)s")
+        "%(user_id)s %(module)s(%(lineno)d) %(funcName)s - %(message)s")
 
     def __init__(self,
                  level,

src/bin/shipyard_airflow/shipyard_airflow/control/logging/request_logging.py

@@ -39,7 +39,7 @@ except ImportError:
 # logging - these fields need not be set up independently as opposed to the
 # additional_fields parameter used below, which allows for more fields beyond
 # this default set.
-BASE_ADDL_FIELDS = ['req_id', 'external_ctx', 'user']
+BASE_ADDL_FIELDS = ['req_id', 'external_ctx', 'user', 'user_id']
 LOG = logging.getLogger(__name__)
 
 

src/bin/shipyard_airflow/shipyard_airflow/control/middleware/logging_mw.py

@@ -34,6 +34,7 @@ class LoggingMiddleware(object):
         request_logging.set_logvar('req_id', req.context.request_id)
         request_logging.set_logvar('external_ctx', req.context.external_marker)
         request_logging.set_logvar('user', req.context.user)
+        request_logging.set_logvar('user_id', req.context.user_id)
         if not req.url.endswith(HEALTH_URL):
             # Log requests other than the health check.
             LOG.info("Request %s %s", req.method, req.url)

src/bin/shipyard_airflow/shipyard_airflow/control/service_clients.py

@@ -28,9 +28,13 @@ CONF = cfg.CONF
 #
 # Deckhand Client
 #
-def deckhand_client():
+def deckhand_client(addl_headers=None):
     """Retrieve a Deckhand client"""
-    return dh_client.Client(session=svc_endpoints.get_session(),
+    session = svc_endpoints.get_session()
+    if addl_headers:
+        session.additional_headers.update(addl_headers)
+
+    return dh_client.Client(session=session,
                             endpoint_type='internal')
 
 
@@ -41,7 +45,7 @@ def _auth_gen():
     return [('X-Auth-Token', svc_endpoints.get_token())]
 
 
-def drydock_client():
+def drydock_client(context_marker=None, end_user=None):
     """Retreive a Drydock client"""
     # Setup the drydock session
     endpoint = svc_endpoints.get_endpoint(Endpoints.DRYDOCK)
@@ -50,6 +54,8 @@ def drydock_client():
         dd_url.hostname,
         port=dd_url.port,
         auth_gen=_auth_gen,
+        marker=context_marker,
+        end_user=end_user,
         timeout=(CONF.requests_config.drydock_client_connect_timeout,
                  CONF.requests_config.drydock_client_read_timeout))
     return dd_client.DrydockClient(session)

src/bin/shipyard_airflow/shipyard_airflow/plugins/armada_base_operator.py

@@ -85,11 +85,14 @@ class ArmadaBaseOperator(UcpBaseOperator):
         # Set up armada client
         self.armada_client = self._init_armada_client(
             self.endpoints.endpoint_by_name(service_endpoint.ARMADA),
-            self.svc_token
+            self.svc_token,
+            self.context_marker,
+            self.user
         )
 
     @staticmethod
-    def _init_armada_client(armada_svc_endpoint, svc_token):
+    def _init_armada_client(armada_svc_endpoint, svc_token,
+                            ext_marker, end_user):
 
         LOG.info("Armada endpoint is %s", armada_svc_endpoint)
 
@@ -103,7 +106,8 @@ class ArmadaBaseOperator(UcpBaseOperator):
                                           port=armada_url.port,
                                           scheme='http',
                                           token=svc_token,
-                                          marker=None)
+                                          marker=ext_marker,
+                                          end_user=end_user)
 
         # Raise Exception if we are not able to set up the session
         if a_session:

src/bin/shipyard_airflow/shipyard_airflow/plugins/deckhand_base_operator.py

@@ -28,6 +28,7 @@ except ImportError:
     from shipyard_airflow.plugins import service_endpoint
     from shipyard_airflow.plugins.service_token import shipyard_service_token
     from shipyard_airflow.plugins.ucp_base_operator import UcpBaseOperator
+from shipyard_airflow.shipyard_const import CustomHeaders
 
 LOG = logging.getLogger(__name__)
 
@@ -95,11 +96,22 @@ class DeckhandBaseOperator(UcpBaseOperator):
         LOG.info("Executing Shipyard Action %s",
                  self.action_id)
 
+        # Create additional headers dict to pass context marker
+        # and end user
+        addl_headers = {
+            CustomHeaders.CONTEXT_MARKER.value: self.context_marker,
+            CustomHeaders.END_USER.value: self.user
+        }
+
         # Retrieve Endpoint Information
         self.deckhand_svc_endpoint = self.endpoints.endpoint_by_name(
-            service_endpoint.DECKHAND
+            service_endpoint.DECKHAND,
+            addl_headers=addl_headers
         )
 
+        # update additional headers
+        self.svc_session.additional_headers.update(addl_headers)
+
         LOG.info("Deckhand endpoint is %s",
                  self.deckhand_svc_endpoint)
 

src/bin/shipyard_airflow/shipyard_airflow/plugins/deckhand_client_factory.py

@@ -36,7 +36,7 @@ class DeckhandClientFactory(object):
         self.config = configparser.ConfigParser()
         self.config.read(shipyard_conf)
 
-    def get_client(self):
+    def get_client(self, addl_headers=None):
         """Retrieve a deckhand client"""
 
         """
@@ -57,7 +57,8 @@ class DeckhandClientFactory(object):
 
         # Set up keystone session
         auth = keystone_v3.Password(**keystone_auth)
-        sess = keystone_session.Session(auth=auth)
+        sess = keystone_session.Session(auth=auth,
+                                        additional_headers=addl_headers)
 
         LOG.info("Setting up Deckhand client with parameters")
         for attr in keystone_auth:

src/bin/shipyard_airflow/shipyard_airflow/plugins/deployment_configuration_operator.py

@@ -25,10 +25,13 @@ from airflow.utils.decorators import apply_defaults
 
 try:
     from deckhand_client_factory import DeckhandClientFactory
+    from xcom_puller import XcomPuller
 except ImportError:
     from shipyard_airflow.plugins.deckhand_client_factory import (
         DeckhandClientFactory
     )
+    from shipyard_airflow.plugins.xcom_puller import XcomPuller
+from shipyard_airflow.shipyard_const import CustomHeaders
 
 LOG = logging.getLogger(__name__)
 
@@ -90,6 +93,7 @@ class DeploymentConfigurationOperator(BaseOperator):
         super(DeploymentConfigurationOperator, self).__init__(*args, **kwargs)
         self.main_dag_name = main_dag_name
         self.shipyard_conf = shipyard_conf
+        self.action_info = {}
 
     def execute(self, context):
         """Perform Deployment Configuration extraction"""
@@ -104,13 +108,12 @@ class DeploymentConfigurationOperator(BaseOperator):
         """Get the revision id from xcom"""
         if task_instance:
             LOG.debug("task_instance found, extracting design version")
+            # Get XcomPuller instance
+            self.xcom_puller = XcomPuller(self.main_dag_name, task_instance)
             # Set the revision_id to the revision on the xcom
-            action_info = task_instance.xcom_pull(
-                task_ids='action_xcom',
-                dag_id=self.main_dag_name,
-                key='action')
+            self.action_info = self.xcom_puller.get_action_info()
 
-            revision_id = action_info['committed_rev_id']
+            revision_id = self.action_info['committed_rev_id']
 
             if revision_id:
                 LOG.info("Revision is set to: %s for deployment configuration",
@@ -132,8 +135,21 @@ class DeploymentConfigurationOperator(BaseOperator):
             "schema": "shipyard/DeploymentConfiguration/v1",
             "metadata.name": "deployment-configuration"
         }
+
+        # Create additional headers dict to pass context marker
+        # and end user
+        addl_headers = None
+        if self.action_info:
+            context_marker = self.action_info['context_marker']
+            end_user = self.action_info['user']
+            addl_headers = {
+                CustomHeaders.CONTEXT_MARKER.value: context_marker,
+                CustomHeaders.END_USER.value: end_user
+            }
+
         try:
-            dhclient = DeckhandClientFactory(self.shipyard_conf).get_client()
+            dhclient = DeckhandClientFactory(
+                self.shipyard_conf).get_client(addl_headers=addl_headers)
             LOG.info("Deckhand Client acquired")
             doc = dhclient.revisions.documents(revision_id,
                                                rendered=True,

src/bin/shipyard_airflow/shipyard_airflow/plugins/drydock_base_operator.py

@@ -153,6 +153,8 @@ class DrydockBaseOperator(UcpBaseOperator):
             drydock_url.hostname,
             port=drydock_url.port,
             auth_gen=self._auth_gen,
+            marker=self.context_marker,
+            end_user=self.user,
             timeout=(self.drydock_client_connect_timeout,
                      self.drydock_client_read_timeout))
 

src/bin/shipyard_airflow/shipyard_airflow/plugins/drydock_validate_design.py

@@ -24,6 +24,7 @@ try:
 except ImportError:
     from shipyard_airflow.plugins.drydock_base_operator import \
         DrydockBaseOperator
+from shipyard_airflow.shipyard_const import CustomHeaders
 
 LOG = logging.getLogger(__name__)
 
@@ -48,7 +49,9 @@ class DrydockValidateDesignOperator(DrydockBaseOperator):
         # Define Headers and Payload
         headers = {
             'Content-Type': 'application/json',
-            'X-Auth-Token': self.svc_token
+            'X-Auth-Token': self.svc_token,
+            CustomHeaders.CONTEXT_MARKER.value: self.context_marker,
+            CustomHeaders.END_USER.value: self.user
         }
 
         payload = {

src/bin/shipyard_airflow/shipyard_airflow/plugins/promenade_base_operator.py

@@ -24,6 +24,7 @@ except ImportError:
     from shipyard_airflow.plugins import service_endpoint
     from shipyard_airflow.plugins.service_token import shipyard_service_token
     from shipyard_airflow.plugins.ucp_base_operator import UcpBaseOperator
+from shipyard_airflow.shipyard_const import CustomHeaders
 
 LOG = logging.getLogger(__name__)
 
@@ -64,9 +65,17 @@ class PromenadeBaseOperator(UcpBaseOperator):
         # Logs uuid of Shipyard action
         LOG.info("Executing Shipyard Action %s", self.action_id)
 
+        # Create additional headers dict to pass context marker
+        # and end user
+        addl_headers = {
+            CustomHeaders.CONTEXT_MARKER.value: self.context_marker,
+            CustomHeaders.END_USER.value: self.user
+        }
+
         # Retrieve promenade endpoint
         self.promenade_svc_endpoint = self.endpoints.endpoint_by_name(
-            service_endpoint.PROMENADE
+            service_endpoint.PROMENADE,
+            addl_headers=addl_headers
         )
 
         LOG.info("Promenade endpoint is %s", self.promenade_svc_endpoint)

src/bin/shipyard_airflow/shipyard_airflow/plugins/promenade_validate_site_design.py

@@ -24,6 +24,7 @@ try:
 except ImportError:
     from shipyard_airflow.plugins.promenade_base_operator import \
         PromenadeBaseOperator
+from shipyard_airflow.shipyard_const import CustomHeaders
 
 LOG = logging.getLogger(__name__)
 
@@ -48,7 +49,9 @@ class PromenadeValidateSiteDesignOperator(PromenadeBaseOperator):
         # Define Headers and Payload
         headers = {
             'Content-Type': 'application/json',
-            'X-Auth-Token': self.svc_token
+            'X-Auth-Token': self.svc_token,
+            CustomHeaders.CONTEXT_MARKER.value: self.context_marker,
+            CustomHeaders.END_USER.value: self.user
         }
 
         payload = {

src/bin/shipyard_airflow/shipyard_airflow/plugins/service_endpoint.py

@@ -32,14 +32,15 @@ PROMENADE = 'promenade'
 LOG = logging.getLogger(__name__)
 
 
-def _ucp_service_endpoint(shipyard_conf, svc_type):
+def _ucp_service_endpoint(shipyard_conf, svc_type, addl_headers=None):
 
     # Initialize variables
     retry = 0
     int_endpoint = None
 
     # Retrieve Keystone Session
-    sess = ucp_keystone_session(shipyard_conf)
+    sess = ucp_keystone_session(shipyard_conf,
+                                additional_headers=addl_headers)
 
     # We will allow 1 retry in getting the Keystone Endpoint with a
     # backoff interval of 10 seconds in case there is a temporary
@@ -78,7 +79,7 @@ class ServiceEndpoints():
         self.config = configparser.ConfigParser()
         self.config.read(self.shipyard_conf)
 
-    def endpoint_by_name(self, svc_name):
+    def endpoint_by_name(self, svc_name, addl_headers=None):
         """Return the service endpoint for the named service.
 
         :param svc_name: name of the service from which the service type will
@@ -86,7 +87,12 @@ class ServiceEndpoints():
             module provide names that can be used with an expectation that they
             work with a standard/complete configuration file.
             E.g.: service_endpoint.DRYDOCK
+        :param dict addl_headers: Additional headers that should be attached
+            to every request passing through the session.
+            Headers of the same name specified per request will take priority.
         """
         LOG.info("Looking up service endpoint for: %s", svc_name)
         svc_type = self.config.get(svc_name, 'service_type')
-        return _ucp_service_endpoint(self.shipyard_conf, svc_type)
+        return _ucp_service_endpoint(self.shipyard_conf,
+                                     svc_type,
+                                     addl_headers=addl_headers)

src/bin/shipyard_airflow/shipyard_airflow/plugins/service_session.py

@@ -22,7 +22,7 @@ from keystoneauth1.identity import v3 as keystone_v3
 from keystoneauth1 import session as keystone_session
 
 
-def ucp_keystone_session(shipyard_conf):
+def ucp_keystone_session(shipyard_conf, additional_headers=None):
 
     # Read and parse shiyard.conf
     config = configparser.ConfigParser()
@@ -46,7 +46,8 @@ def ucp_keystone_session(shipyard_conf):
         # Set up keystone session
         logging.info("Get Keystone Session")
         auth = keystone_v3.Password(**keystone_auth)
-        sess = keystone_session.Session(auth=auth)
+        sess = keystone_session.Session(auth=auth,
+                                        additional_headers=additional_headers)
 
         # Retry if we fail to get keystone session
         if sess:

src/bin/shipyard_airflow/shipyard_airflow/plugins/ucp_base_operator.py

@@ -160,6 +160,8 @@ class UcpBaseOperator(BaseOperator):
         self.task_id = self.task_instance.task_id
         self.revision_id = self.action_info['committed_rev_id']
         self.action_params = self.action_info.get('parameters', {})
+        self.context_marker = self.action_info['context_marker']
+        self.user = self.action_info['user']
         self.design_ref = self._deckhand_design_ref()
         self._setup_target_nodes()
 

src/bin/shipyard_airflow/shipyard_airflow/shipyard_const.py

@@ -0,0 +1,28 @@
+# Copyright 2019 AT&T Intellectual Property.  All other rights reserved.
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+#     http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+"""Constants definition module for Shipyard.
+
+"""
+import enum
+
+
+class CustomHeaders(enum.Enum):
+    """
+    Enumerations of Custom HTTP Headers key.
+    """
+    END_USER = 'X-End-User'
+    CONTEXT_MARKER = 'X-Context-Marker'
+
+# TODO: Other constants that are used across modules in Shipyard
+# to be defined here for better maintainability