Add request IDs in command-executor log

* Update gRPC interface to handle SubRequestID and Originator ID
* Update command-executor log format to handle request IDs in the log statement
* Add SubRequest ID and Originator ID in BP log statement

Issue-ID: CCSDK-2687
Change-Id: If261bb0912df5800ed2fc65371c5ee784d6a45fb
Signed-off-by: Julien Fontaine <julien.fontaine@bell.ca>

12 files changed, 156 insertions, 80 deletions

diff --git a/components/model-catalog/proto-definition/proto/CommandExecutor.proto b/components/model-catalog/proto-definition/proto/CommandExecutor.proto
index ac6921965..bad6a01c3 100644
--- a/components/model-catalog/proto-definition/proto/CommandExecutor.proto
+++ b/components/model-catalog/proto-definition/proto/CommandExecutor.proto
@@ -17,6 +17,8 @@ message ExecutionInput {
     google.protobuf.Struct properties = 6;
     // Request Time Stamp
     google.protobuf.Timestamp timestamp = 7;
+    string subRequestId = 8;
+    string originatorId = 9;
 }
 
 message PrepareEnvInput {
@@ -28,6 +30,8 @@ message PrepareEnvInput {
     int32 timeOut = 5;
     google.protobuf.Struct properties = 6;
     google.protobuf.Timestamp timestamp = 7;
+    string subRequestId = 8;
+    string originatorId = 9;
 }
 
 message Identifiers {
diff --git a/ms/blueprintsprocessor/application/src/main/resources/logback.xml b/ms/blueprintsprocessor/application/src/main/resources/logback.xml
index aceea4327..b905b7da4 100644
--- a/ms/blueprintsprocessor/application/src/main/resources/logback.xml
+++ b/ms/blueprintsprocessor/application/src/main/resources/logback.xml
@@ -1,5 +1,6 @@
 <!--
   ~  Copyright © 2017-2018 AT&T Intellectual Property.
+  ~  Modifications Copyright © 2020 Bell Canada.
   ~
   ~  Licensed under the Apache License, Version 2.0 (the "License");
   ~  you may not use this file except in compliance with the License.
@@ -18,7 +19,7 @@
 
     <property name="localPattern" value="%d{HH:mm:ss.SSS} [%thread] %-5level %logger{50} - %msg%n"/>
     <property name="defaultPattern"
-              value="%date{ISO8601,UTC}|%X{RequestID}|%X{InvocationID}|%thread|%X{ServiceName}|%X{ClientIPAddress}|%logger{50}| %msg%n"/>
+              value="%date{ISO8601,UTC}|%X{RequestID}|%X{SubRequestID}|%X{OriginatorID}|%X{InvocationID}|%thread|%X{ServiceName}|%X{ClientIPAddress}|%logger{50}|%msg%n"/>
     <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
         <encoder>
             <pattern>${defaultPattern}</pattern>
diff --git a/ms/blueprintsprocessor/functions/python-executor/src/main/kotlin/org/onap/ccsdk/cds/blueprintsprocessor/functions/python/executor/ComponentRemotePythonExecutor.kt b/ms/blueprintsprocessor/functions/python-executor/src/main/kotlin/org/onap/ccsdk/cds/blueprintsprocessor/functions/python/executor/ComponentRemotePythonExecutor.kt
index 9ed13c146..b06da3810 100644
--- a/ms/blueprintsprocessor/functions/python-executor/src/main/kotlin/org/onap/ccsdk/cds/blueprintsprocessor/functions/python/executor/ComponentRemotePythonExecutor.kt
+++ b/ms/blueprintsprocessor/functions/python-executor/src/main/kotlin/org/onap/ccsdk/cds/blueprintsprocessor/functions/python/executor/ComponentRemotePythonExecutor.kt
@@ -1,5 +1,6 @@
 /*
  *  Copyright © 2019 IBM.
+ *  Modifications Copyright © 2020 Bell Canada.
  *
  *  Licensed under the Apache License, Version 2.0 (the "License");
  *  you may not use this file except in compliance with the License.
@@ -145,7 +146,9 @@ open class ComponentRemotePythonExecutor(
             // If packages are defined, then install in remote server
             if (packages != null) {
                 val prepareEnvInput = PrepareRemoteEnvInput(
+                    originatorId = executionServiceInput.commonHeader.originatorId,
                     requestId = processId,
+                    subRequestId = executionServiceInput.commonHeader.subRequestId,
                     remoteIdentifier = RemoteIdentifier(
                         blueprintName = blueprintName,
                         blueprintVersion = blueprintVersion),
@@ -195,7 +198,9 @@ open class ComponentRemotePythonExecutor(
                 val properties = dynamicProperties?.returnNullIfMissing()?.rootFieldsToMap() ?: hashMapOf()
 
                 val remoteExecutionInput = RemoteScriptExecutionInput(
+                    originatorId = executionServiceInput.commonHeader.originatorId,
                     requestId = processId,
+                    subRequestId = executionServiceInput.commonHeader.subRequestId,
                     remoteIdentifier = RemoteIdentifier(blueprintName = blueprintName, blueprintVersion = blueprintVersion),
                     command = scriptCommand,
                     properties = properties,
diff --git a/ms/blueprintsprocessor/modules/blueprints/blueprint-core/src/main/kotlin/org/onap/ccsdk/cds/controllerblueprints/core/BluePrintConstants.kt b/ms/blueprintsprocessor/modules/blueprints/blueprint-core/src/main/kotlin/org/onap/ccsdk/cds/controllerblueprints/core/BluePrintConstants.kt
index 76662d4ee..8290167cd 100644
--- a/ms/blueprintsprocessor/modules/blueprints/blueprint-core/src/main/kotlin/org/onap/ccsdk/cds/controllerblueprints/core/BluePrintConstants.kt
+++ b/ms/blueprintsprocessor/modules/blueprints/blueprint-core/src/main/kotlin/org/onap/ccsdk/cds/controllerblueprints/core/BluePrintConstants.kt
@@ -1,6 +1,6 @@
 /*
  * Copyright © 2017-2018 AT&T Intellectual Property.
- * Modifications Copyright © 2018 - 2019 IBM, Bell Canada
+ * Modifications Copyright © 2018 - 2020 IBM, Bell Canada
  *
  * Licensed under the Apache License, Version 2.0 (the "License");
  * you may not use this file except in compliance with the License.
@@ -34,6 +34,8 @@ object BluePrintConstants {
     const val RESPONSE_HEADER_LATEST_VERSION: String = "X-LatestVersion"
 
     const val ONAP_REQUEST_ID = "X-ONAP-RequestID"
+    const val ONAP_SUBREQUEST_ID = "X-ONAP-SubRequestID"
+    const val ONAP_ORIGINATOR_ID = "X-ONAP-OriginatorID"
     const val ONAP_INVOCATION_ID = "X-ONAP-InvocationID"
     const val ONAP_PARTNER_NAME = "X-ONAP-PartnerName"
 
diff --git a/ms/blueprintsprocessor/modules/commons/processor-core/src/main/kotlin/org/onap/ccsdk/cds/blueprintsprocessor/core/api/data/BlueprintRemoteProcessorData.kt b/ms/blueprintsprocessor/modules/commons/processor-core/src/main/kotlin/org/onap/ccsdk/cds/blueprintsprocessor/core/api/data/BlueprintRemoteProcessorData.kt
index 628b65ea4..6baf261fb 100644
--- a/ms/blueprintsprocessor/modules/commons/processor-core/src/main/kotlin/org/onap/ccsdk/cds/blueprintsprocessor/core/api/data/BlueprintRemoteProcessorData.kt
+++ b/ms/blueprintsprocessor/modules/commons/processor-core/src/main/kotlin/org/onap/ccsdk/cds/blueprintsprocessor/core/api/data/BlueprintRemoteProcessorData.kt
@@ -1,5 +1,6 @@
 /*
  *  Copyright © 2019 IBM.
+ *  Modifications Copyright © 2020 Bell Canada.
  *
  *  Licensed under the Apache License, Version 2.0 (the "License");
  *  you may not use this file except in compliance with the License.
@@ -29,7 +30,9 @@ data class RemoteIdentifier(
 )
 
 data class RemoteScriptExecutionInput(
+    var originatorId: String,
     var requestId: String,
+    var subRequestId: String,
     var correlationId: String? = null,
     var remoteIdentifier: RemoteIdentifier? = null,
     var command: String,
@@ -46,7 +49,9 @@ data class RemoteScriptExecutionOutput(
 )
 
 data class PrepareRemoteEnvInput(
+    var originatorId: String,
     var requestId: String,
+    var subRequestId: String,
     var correlationId: String? = null,
     var remoteIdentifier: RemoteIdentifier? = null,
     var packages: JsonNode,
diff --git a/ms/blueprintsprocessor/modules/commons/rest-lib/src/main/kotlin/org/onap/ccsdk/cds/blueprintsprocessor/rest/service/RestLoggerService.kt b/ms/blueprintsprocessor/modules/commons/rest-lib/src/main/kotlin/org/onap/ccsdk/cds/blueprintsprocessor/rest/service/RestLoggerService.kt
index 846a94a09..dc45e3545 100644
--- a/ms/blueprintsprocessor/modules/commons/rest-lib/src/main/kotlin/org/onap/ccsdk/cds/blueprintsprocessor/rest/service/RestLoggerService.kt
+++ b/ms/blueprintsprocessor/modules/commons/rest-lib/src/main/kotlin/org/onap/ccsdk/cds/blueprintsprocessor/rest/service/RestLoggerService.kt
@@ -1,5 +1,6 @@
 /*
  * Copyright © 2018-2019 AT&T Intellectual Property.
+ * Modifications Copyright © 2020 Bell Canada.
  *
  * Licensed under the Apache License, Version 2.0 (the "License");
  * you may not use this file except in compliance with the License.
@@ -30,8 +31,10 @@ import kotlinx.coroutines.withContext
 import org.apache.http.message.BasicHeader
 import org.onap.ccsdk.cds.controllerblueprints.core.BluePrintConstants
 import org.onap.ccsdk.cds.controllerblueprints.core.BluePrintConstants.ONAP_INVOCATION_ID
+import org.onap.ccsdk.cds.controllerblueprints.core.BluePrintConstants.ONAP_ORIGINATOR_ID
 import org.onap.ccsdk.cds.controllerblueprints.core.BluePrintConstants.ONAP_PARTNER_NAME
 import org.onap.ccsdk.cds.controllerblueprints.core.BluePrintConstants.ONAP_REQUEST_ID
+import org.onap.ccsdk.cds.controllerblueprints.core.BluePrintConstants.ONAP_SUBREQUEST_ID
 import org.onap.ccsdk.cds.controllerblueprints.core.MDCContext
 import org.onap.ccsdk.cds.controllerblueprints.core.defaultToEmpty
 import org.onap.ccsdk.cds.controllerblueprints.core.defaultToUUID
@@ -68,10 +71,14 @@ class RestLoggerService {
         val localhost = InetAddress.getLocalHost()
         val headers = request.headers
         val requestID = headers.getFirst(ONAP_REQUEST_ID).defaultToUUID()
+        val subrequestID = headers.getFirst(ONAP_SUBREQUEST_ID).defaultToEmpty()
+        val originatorID = headers.getFirst(ONAP_ORIGINATOR_ID).defaultToEmpty()
         val invocationID = headers.getFirst(ONAP_INVOCATION_ID).defaultToUUID()
         val partnerName = headers.getFirst(ONAP_PARTNER_NAME).defaultToEmpty()
         MDC.put("InvokeTimestamp", ZonedDateTime.now(ZoneOffset.UTC).format(DateTimeFormatter.ISO_INSTANT))
         MDC.put("RequestID", requestID)
+        MDC.put("SubRequestID", subrequestID)
+        MDC.put("OriginatorID", originatorID)
         MDC.put("InvocationID", invocationID)
         MDC.put("PartnerName", partnerName)
         MDC.put("ClientIPAddress", request.remoteAddress?.address?.hostAddress.defaultToEmpty())
@@ -86,6 +93,8 @@ class RestLoggerService {
             val reqHeaders = request.headers
             val resHeaders = response.headers
             resHeaders[ONAP_REQUEST_ID] = MDC.get("RequestID")
+            resHeaders[ONAP_SUBREQUEST_ID] = MDC.get("SubRequestID")
+            resHeaders[ONAP_ORIGINATOR_ID] = MDC.get("OriginatorID")
             resHeaders[ONAP_INVOCATION_ID] = MDC.get("InvocationID")
             resHeaders[ONAP_PARTNER_NAME] = BluePrintConstants.APP_NAME
         } catch (e: Exception) {
diff --git a/ms/blueprintsprocessor/modules/services/execution-service/src/main/kotlin/org/onap/ccsdk/cds/blueprintsprocessor/services/execution/RemoteScriptExecutionService.kt b/ms/blueprintsprocessor/modules/services/execution-service/src/main/kotlin/org/onap/ccsdk/cds/blueprintsprocessor/services/execution/RemoteScriptExecutionService.kt
index 861a95507..35f156707 100644
--- a/ms/blueprintsprocessor/modules/services/execution-service/src/main/kotlin/org/onap/ccsdk/cds/blueprintsprocessor/services/execution/RemoteScriptExecutionService.kt
+++ b/ms/blueprintsprocessor/modules/services/execution-service/src/main/kotlin/org/onap/ccsdk/cds/blueprintsprocessor/services/execution/RemoteScriptExecutionService.kt
@@ -1,5 +1,6 @@
 /*
  *  Copyright © 2019 IBM.
+ *  Modifications Copyright © 2020 Bell Canada.
  *
  *  Licensed under the Apache License, Version 2.0 (the "License");
  *  you may not use this file except in compliance with the License.
@@ -129,6 +130,8 @@ class GrpcRemoteScriptExecutionService(private val bluePrintGrpcLibPropertyServi
         return PrepareEnvInput.newBuilder()
             .setIdentifiers(this.remoteIdentifier!!.asGrpcData())
             .setRequestId(this.requestId)
+            .setSubRequestId(this.subRequestId)
+            .setOriginatorId(this.originatorId)
             .setCorrelationId(correlationId)
             .setTimeOut(this.timeOut.toInt())
             .addAllPackages(packageList)
@@ -140,6 +143,8 @@ class GrpcRemoteScriptExecutionService(private val bluePrintGrpcLibPropertyServi
         val correlationId = this.correlationId ?: this.requestId
         return ExecutionInput.newBuilder()
             .setRequestId(this.requestId)
+            .setSubRequestId(this.subRequestId)
+            .setOriginatorId(this.originatorId)
             .setCorrelationId(correlationId)
             .setIdentifiers(this.remoteIdentifier!!.asGrpcData())
             .setCommand(this.command)
diff --git a/ms/command-executor/src/main/python/command_executor_handler.py b/ms/command-executor/src/main/python/command_executor_handler.py
index 06004b551..b7d3eec0d 100644
--- a/ms/command-executor/src/main/python/command_executor_handler.py
+++ b/ms/command-executor/src/main/python/command_executor_handler.py
@@ -1,5 +1,5 @@
 #
-# Copyright (C) 2019 Bell Canada.
+# Copyright (C) 2019 - 2020 Bell Canada.
 #
 # Licensed under the Apache License, Version 2.0 (the "License");
 # you may not use this file except in compliance with the License.
@@ -38,6 +38,7 @@ class CommandExecutorHandler():
         self.execution_timeout = utils.get_blueprint_timeout(request)
         self.venv_home = '/opt/app/onap/blueprints/deploy/' + self.blueprint_id
         self.installed = self.venv_home + '/.installed'
+        self.extra = utils.getExtraLogData(request)
 
     def is_installed(self):
         return os.path.exists(self.installed)
@@ -48,13 +49,13 @@ class CommandExecutorHandler():
             create_venv_status = self.create_venv()
             if not create_venv_status[utils.CDS_IS_SUCCESSFUL_KEY]:
                 err_msg = "ERROR: failed to prepare environment for request {} due to error in creating virtual Python env. Original error {}".format(self.blueprint_id, create_venv_status[utils.ERR_MSG_KEY])
-                self.logger.error(err_msg)
+                self.logger.error(err_msg, extra=self.extra)
                 return utils.build_ret_data(False, error=err_msg)
 
             activate_venv_status = self.activate_venv()
             if not activate_venv_status[utils.CDS_IS_SUCCESSFUL_KEY]:
                 err_msg = "ERROR: failed to prepare environment for request {} due Python venv_activation. Original error {}".format(self.blueprint_id, activate_venv_status[utils.ERR_MSG_KEY])
-                self.logger.error(err_msg)
+                self.logger.error(err_msg, extra=self.extra)
                 return utils.build_ret_data(False, error=err_msg)
             try:
                 with open(self.installed, "w+") as f:
@@ -68,7 +69,7 @@ class CommandExecutorHandler():
                         return utils.build_ret_data(False, results_log=results_log, error=err_msg)
             except Exception as ex:
                 err_msg = "ERROR: failed to prepare environment for request {} during installing packages. Exception: {}".format(self.blueprint_id, ex)
-                self.logger.error(err_msg)
+                self.logger.error(err_msg, extra=self.extra)
                 return utils.build_ret_data(False, error=err_msg)
         else:
             try:
@@ -119,10 +120,14 @@ class CommandExecutorHandler():
             ### RequestID
             request_id = request.requestId
             ### Sub-requestID
-            subrequest_id = request.correlationId
-            request_id_map = {'CDS_REQUEST_ID':request_id, 'CDS_CORRELATION_ID':subrequest_id}
+            subrequest_id = request.subRequestId
+            ### OriginatorID
+            originator_id = request.originatorId
+            ### CorrelationID
+            correlation_id = request.correlationId
+            request_id_map = {'CDS_REQUEST_ID':request_id, 'CDS_SUBREQUEST_ID':subrequest_id, 'CDS_ORIGINATOR_ID': originator_id, 'CDS_CORRELATION_ID': correlation_id}
             updated_env =  { **os.environ, **request_id_map }
-            self.logger.info("Running blueprint {} with timeout: {}".format(self.blueprint_id, self.execution_timeout))
+            self.logger.info("Running blueprint {} with timeout: {}".format(self.blueprint_id, self.execution_timeout), extra=self.extra)
 
             with tempfile.TemporaryFile(mode="w+") as tmp:
                 try:
@@ -130,11 +135,11 @@ class CommandExecutorHandler():
                                                 env=updated_env, timeout=self.execution_timeout)
                 except TimeoutExpired:
                     timeout_err_msg = "Running command {} failed due to timeout of {} seconds.".format(self.blueprint_id, self.execution_timeout)
-                    self.logger.error(timeout_err_msg)
-                    utils.parse_cmd_exec_output(tmp, self.logger, result, results_log)
+                    self.logger.error(timeout_err_msg, extra=self.extra)
+                    utils.parse_cmd_exec_output(tmp, self.logger, result, results_log, self.extra)
                     return utils.build_ret_data(False, results_log=results_log, error=timeout_err_msg)
 
-                utils.parse_cmd_exec_output(tmp, self.logger, result, results_log)
+                utils.parse_cmd_exec_output(tmp, self.logger, result, results_log, self.extra)
                 rc = completed_subprocess.returncode
         except Exception as e:
             err_msg = "{} - Failed to execute command. Error: {}".format(self.blueprint_id, e)
@@ -143,7 +148,7 @@ class CommandExecutorHandler():
 
         # deactivate_venv(blueprint_id)
         #Since return code is only used to check if it's zero (success), we can just return success flag instead.
-        self.logger.debug("python return_code : {}".format(rc))
+        self.logger.debug("python return_code : {}".format(rc), extra=self.extra)
         is_execution_successful = rc == 0
         result.update(utils.build_ret_data(is_execution_successful, results_log=results_log))
         return result
@@ -168,7 +173,7 @@ class CommandExecutorHandler():
 
     def install_python_packages(self, package, results):
         self.logger.info(
-            "{} - Install Python package({}) in Python Virtual Environment".format(self.blueprint_id, package))
+            "{} - Install Python package({}) in Python Virtual Environment".format(self.blueprint_id, package), extra=self.extra)
 
         if REQUIREMENTS_TXT == package:
             command = ["pip", "install", "-r", self.venv_home + "/Environments/" + REQUIREMENTS_TXT]
@@ -181,21 +186,21 @@ class CommandExecutorHandler():
         env = dict(os.environ)
         if "https_proxy" in os.environ:
             env['https_proxy'] = os.environ['https_proxy']
-            self.logger.info("Using https_proxy: ", env['https_proxy'])
+            self.logger.info("Using https_proxy: ", env['https_proxy'], extra=self.extra)
 
         try:
             results.append(subprocess.run(command, check=True, stdout=PIPE, stderr=PIPE, env=env).stdout.decode())
             results.append("\n")
-            self.logger.info("install_python_packages {} succeeded".format(package))
+            self.logger.info("install_python_packages {} succeeded".format(package), extra=self.extra)
             return True
         except CalledProcessError as e:
             results.append(e.stderr.decode())
-            self.logger.error("install_python_packages {} failed".format(package))
+            self.logger.error("install_python_packages {} failed".format(package), extra=self.extra)
             return False
 
     def install_ansible_packages(self, package, results):
         self.logger.info(
-            "{} - Install Ansible Role package({}) in Python Virtual Environment".format(self.blueprint_id, package))
+            "{} - Install Ansible Role package({}) in Python Virtual Environment".format(self.blueprint_id, package), extra=self.extra)
         command = ["ansible-galaxy", "install", package, "-p", self.venv_home + "/Scripts/ansible/roles"]
 
         env = dict(os.environ)
@@ -216,23 +221,23 @@ class CommandExecutorHandler():
     # 'err_msg' indicates an error occurred. The presence of err_msg may not be fatal,
     # status should be set to False for fatal errors.
     def create_venv(self):
-        self.logger.info("{} - Create Python Virtual Environment".format(self.blueprint_id))
+        self.logger.info("{} - Create Python Virtual Environment".format(self.blueprint_id), extra=self.extra)
         try:
             bin_dir = self.venv_home + "/bin"
             # venv doesn't populate the activate_this.py script, hence we use from virtualenv
             venv.create(self.venv_home, with_pip=True, system_site_packages=True)
             virtualenv.writefile(os.path.join(bin_dir, "activate_this.py"), virtualenv.ACTIVATE_THIS)
-            self.logger.info("{} - Creation of Python Virtual Environment finished.".format(self.blueprint_id))
+            self.logger.info("{} - Creation of Python Virtual Environment finished.".format(self.blueprint_id), extra=self.extra)
             return utils.build_ret_data(True)
         except Exception as err:
             err_msg = "{} - Failed to provision Python Virtual Environment. Error: {}".format(self.blueprint_id, err)
-            self.logger.info(err_msg)
+            self.logger.info(err_msg, extra=self.extra)
             return utils.build_ret_data(False, error=err_msg)
 
     # return map cds_is_successful and err_msg. Status is True on success. err_msg may existence doesn't necessarily indicate fatal condition.
     # the 'status' should be set to False to indicate error.
     def activate_venv(self):
-        self.logger.info("{} - Activate Python Virtual Environment".format(self.blueprint_id))
+        self.logger.info("{} - Activate Python Virtual Environment".format(self.blueprint_id), extra=self.extra)
 
         # Fix: The python generated activate_this.py script concatenates the env bin dir to PATH on every call
         #      eventually this process PATH variable was so big (128Kb) that no child process could be spawn
@@ -244,20 +249,20 @@ class CommandExecutorHandler():
             with open(path) as activate_this_script:
                 exec (activate_this_script.read(), {'__file__': path})
             exec (fixpathenvvar)
-            self.logger.info("Running with PATH : {}".format(os.environ['PATH']))
+            self.logger.info("Running with PATH : {}".format(os.environ['PATH']), extra=self.extra)
             return utils.build_ret_data(True)
         except Exception as err:
             err_msg ="{} - Failed to activate Python Virtual Environment. Error: {}".format(self.blueprint_id, err)
-            self.logger.info( err_msg)
+            self.logger.info( err_msg, extra=self.extra)
             return utils.build_ret_data(False, error=err_msg)
 
     def deactivate_venv(self):
-        self.logger.info("{} - Deactivate Python Virtual Environment".format(self.blueprint_id))
+        self.logger.info("{} - Deactivate Python Virtual Environment".format(self.blueprint_id), extra=self.extra)
         command = ["deactivate"]
         try:
             subprocess.run(command, check=True)
         except Exception as err:
             self.logger.info(
-                "{} - Failed to deactivate Python Virtual Environment. Error: {}".format(self.blueprint_id, err))
+                "{} - Failed to deactivate Python Virtual Environment. Error: {}".format(self.blueprint_id, err), extra=self.extra)
 
 
diff --git a/ms/command-executor/src/main/python/command_executor_server.py b/ms/command-executor/src/main/python/command_executor_server.py
index aa666ee24..175ddc7d3 100644
--- a/ms/command-executor/src/main/python/command_executor_server.py
+++ b/ms/command-executor/src/main/python/command_executor_server.py
@@ -1,7 +1,7 @@
 #!/usr/bin/python
 
 #
-# Copyright (C) 2019 Bell Canada.
+# Copyright (C) 2019 - 2020 Bell Canada.
 #
 # Licensed under the Apache License, Version 2.0 (the "License");
 # you may not use this file except in compliance with the License.
@@ -29,32 +29,34 @@ class CommandExecutorServer(CommandExecutor_pb2_grpc.CommandExecutorServiceServi
 
     def prepareEnv(self, request, context):
         blueprint_id = utils.get_blueprint_id(request)
-        self.logger.info("{} - Received prepareEnv request".format(blueprint_id))
-        self.logger.info(request)
+        extra = utils.getExtraLogData(request)
+        self.logger.info("{} - Received prepareEnv request".format(blueprint_id), extra=extra)
+        self.logger.info(request, extra=extra)
 
         handler = CommandExecutorHandler(request)
         prepare_env_response = handler.prepare_env(request)
         if prepare_env_response[utils.CDS_IS_SUCCESSFUL_KEY]:
-            self.logger.info("{} - Package installation logs {}".format(blueprint_id, prepare_env_response[utils.RESULTS_LOG_KEY]))
+            self.logger.info("{} - Package installation logs {}".format(blueprint_id, prepare_env_response[utils.RESULTS_LOG_KEY]), extra=extra)
         else:
-            self.logger.info("{} - Failed to prepare python environment. {}".format(blueprint_id, prepare_env_response[utils.ERR_MSG_KEY]))
-        self.logger.info("Prepare Env Response returned : %s" % prepare_env_response)
+            self.logger.info("{} - Failed to prepare python environment. {}".format(blueprint_id, prepare_env_response[utils.ERR_MSG_KEY]), extra=extra)
+        self.logger.info("Prepare Env Response returned : %s" % prepare_env_response, extra=extra)
         return utils.build_grpc_response(request.requestId, prepare_env_response)
 
     def executeCommand(self, request, context):
         blueprint_id = utils.get_blueprint_id(request)
-        self.logger.info("{} - Received executeCommand request".format(blueprint_id))
+        extra = utils.getExtraLogData(request)
+        self.logger.info("{} - Received executeCommand request".format(blueprint_id), extra=extra)
         if os.environ.get('CE_DEBUG','false') == "true":
-            self.logger.info(request)
+            self.logger.info(request, extra=extra)
 
         handler = CommandExecutorHandler(request)
         exec_cmd_response = handler.execute_command(request)
         if exec_cmd_response[utils.CDS_IS_SUCCESSFUL_KEY]:
-            self.logger.info("{} - Execution finished successfully.".format(blueprint_id))
+            self.logger.info("{} - Execution finished successfully.".format(blueprint_id), extra=extra)
         else:
-            self.logger.info("{} - Failed to executeCommand. {}".format(blueprint_id, exec_cmd_response[utils.RESULTS_LOG_KEY]))
+            self.logger.info("{} - Failed to executeCommand. {}".format(blueprint_id, exec_cmd_response[utils.RESULTS_LOG_KEY]), extra=extra)
 
         ret = utils.build_grpc_response(request.requestId, exec_cmd_response)
-        self.logger.info("Payload returned : {}".format(exec_cmd_response))
+        self.logger.info("Payload returned : {}".format(exec_cmd_response), extra=extra)
 
         return ret
\ No newline at end of file
diff --git a/ms/command-executor/src/main/python/proto/CommandExecutor_pb2.py b/ms/command-executor/src/main/python/proto/CommandExecutor_pb2.py
index 4edfc6cd5..5ee04927e 100644
--- a/ms/command-executor/src/main/python/proto/CommandExecutor_pb2.py
+++ b/ms/command-executor/src/main/python/proto/CommandExecutor_pb2.py
@@ -23,7 +23,7 @@ DESCRIPTOR = _descriptor.FileDescriptor(
   package='org.onap.ccsdk.cds.controllerblueprints.command.api',
   syntax='proto3',
   serialized_options=_b('P\001'),
-  serialized_pb=_b('\n\x15\x43ommandExecutor.proto\x12\x33org.onap.ccsdk.cds.controllerblueprints.command.api\x1a\x1cgoogle/protobuf/struct.proto\x1a\x1fgoogle/protobuf/timestamp.proto\"\x8f\x02\n\x0e\x45xecutionInput\x12\x11\n\trequestId\x18\x01 \x01(\t\x12\x15\n\rcorrelationId\x18\x02 \x01(\t\x12U\n\x0bidentifiers\x18\x03 \x01(\x0b\x32@.org.onap.ccsdk.cds.controllerblueprints.command.api.Identifiers\x12\x0f\n\x07\x63ommand\x18\x04 \x01(\t\x12\x0f\n\x07timeOut\x18\x05 \x01(\x05\x12+\n\nproperties\x18\x06 \x01(\x0b\x32\x17.google.protobuf.Struct\x12-\n\ttimestamp\x18\x07 \x01(\x0b\x32\x1a.google.protobuf.Timestamp\"\xd0\x02\n\x0fPrepareEnvInput\x12U\n\x0bidentifiers\x18\x01 \x01(\x0b\x32@.org.onap.ccsdk.cds.controllerblueprints.command.api.Identifiers\x12\x11\n\trequestId\x18\x02 \x01(\t\x12\x15\n\rcorrelationId\x18\x03 \x01(\t\x12O\n\x08packages\x18\x04 \x03(\x0b\x32=.org.onap.ccsdk.cds.controllerblueprints.command.api.Packages\x12\x0f\n\x07timeOut\x18\x05 \x01(\x05\x12+\n\nproperties\x18\x06 \x01(\x0b\x32\x17.google.protobuf.Struct\x12-\n\ttimestamp\x18\x07 \x01(\x0b\x32\x1a.google.protobuf.Timestamp\">\n\x0bIdentifiers\x12\x15\n\rblueprintName\x18\x01 \x01(\t\x12\x18\n\x10\x62lueprintVersion\x18\x02 \x01(\t\"\xcb\x01\n\x0f\x45xecutionOutput\x12\x11\n\trequestId\x18\x01 \x01(\t\x12\x10\n\x08response\x18\x02 \x03(\t\x12S\n\x06status\x18\x03 \x01(\x0e\x32\x43.org.onap.ccsdk.cds.controllerblueprints.command.api.ResponseStatus\x12-\n\ttimestamp\x18\x04 \x01(\x0b\x32\x1a.google.protobuf.Timestamp\x12\x0f\n\x07payload\x18\x05 \x01(\t\"k\n\x08Packages\x12N\n\x04type\x18\x01 \x01(\x0e\x32@.org.onap.ccsdk.cds.controllerblueprints.command.api.PackageType\x12\x0f\n\x07package\x18\x02 \x03(\t**\n\x0eResponseStatus\x12\x0b\n\x07SUCCESS\x10\x00\x12\x0b\n\x07\x46\x41ILURE\x10\x01*9\n\x0bPackageType\x12\x07\n\x03pip\x10\x00\x12\x12\n\x0e\x61nsible_galaxy\x10\x01\x12\r\n\tutilities\x10\x02\x32\xd1\x02\n\x16\x43ommandExecutorService\x12\x98\x01\n\nprepareEnv\x12\x44.org.onap.ccsdk.cds.controllerblueprints.command.api.PrepareEnvInput\x1a\x44.org.onap.ccsdk.cds.controllerblueprints.command.api.ExecutionOutput\x12\x9b\x01\n\x0e\x65xecuteCommand\x12\x43.org.onap.ccsdk.cds.controllerblueprints.command.api.ExecutionInput\x1a\x44.org.onap.ccsdk.cds.controllerblueprints.command.api.ExecutionOutputB\x02P\x01\x62\x06proto3')
+  serialized_pb=_b('\n\x15\x43ommandExecutor.proto\x12\x33org.onap.ccsdk.cds.controllerblueprints.command.api\x1a\x1cgoogle/protobuf/struct.proto\x1a\x1fgoogle/protobuf/timestamp.proto\"\xbb\x02\n\x0e\x45xecutionInput\x12\x11\n\trequestId\x18\x01 \x01(\t\x12\x15\n\rcorrelationId\x18\x02 \x01(\t\x12U\n\x0bidentifiers\x18\x03 \x01(\x0b\x32@.org.onap.ccsdk.cds.controllerblueprints.command.api.Identifiers\x12\x0f\n\x07\x63ommand\x18\x04 \x01(\t\x12\x0f\n\x07timeOut\x18\x05 \x01(\x05\x12+\n\nproperties\x18\x06 \x01(\x0b\x32\x17.google.protobuf.Struct\x12-\n\ttimestamp\x18\x07 \x01(\x0b\x32\x1a.google.protobuf.Timestamp\x12\x14\n\x0csubRequestId\x18\x08 \x01(\t\x12\x14\n\x0coriginatorId\x18\t \x01(\t\"\xfc\x02\n\x0fPrepareEnvInput\x12U\n\x0bidentifiers\x18\x01 \x01(\x0b\x32@.org.onap.ccsdk.cds.controllerblueprints.command.api.Identifiers\x12\x11\n\trequestId\x18\x02 \x01(\t\x12\x15\n\rcorrelationId\x18\x03 \x01(\t\x12O\n\x08packages\x18\x04 \x03(\x0b\x32=.org.onap.ccsdk.cds.controllerblueprints.command.api.Packages\x12\x0f\n\x07timeOut\x18\x05 \x01(\x05\x12+\n\nproperties\x18\x06 \x01(\x0b\x32\x17.google.protobuf.Struct\x12-\n\ttimestamp\x18\x07 \x01(\x0b\x32\x1a.google.protobuf.Timestamp\x12\x14\n\x0csubRequestId\x18\x08 \x01(\t\x12\x14\n\x0coriginatorId\x18\t \x01(\t\">\n\x0bIdentifiers\x12\x15\n\rblueprintName\x18\x01 \x01(\t\x12\x18\n\x10\x62lueprintVersion\x18\x02 \x01(\t\"\xcb\x01\n\x0f\x45xecutionOutput\x12\x11\n\trequestId\x18\x01 \x01(\t\x12\x10\n\x08response\x18\x02 \x03(\t\x12S\n\x06status\x18\x03 \x01(\x0e\x32\x43.org.onap.ccsdk.cds.controllerblueprints.command.api.ResponseStatus\x12-\n\ttimestamp\x18\x04 \x01(\x0b\x32\x1a.google.protobuf.Timestamp\x12\x0f\n\x07payload\x18\x05 \x01(\t\"k\n\x08Packages\x12N\n\x04type\x18\x01 \x01(\x0e\x32@.org.onap.ccsdk.cds.controllerblueprints.command.api.PackageType\x12\x0f\n\x07package\x18\x02 \x03(\t**\n\x0eResponseStatus\x12\x0b\n\x07SUCCESS\x10\x00\x12\x0b\n\x07\x46\x41ILURE\x10\x01*9\n\x0bPackageType\x12\x07\n\x03pip\x10\x00\x12\x12\n\x0e\x61nsible_galaxy\x10\x01\x12\r\n\tutilities\x10\x02\x32\xd1\x02\n\x16\x43ommandExecutorService\x12\x98\x01\n\nprepareEnv\x12\x44.org.onap.ccsdk.cds.controllerblueprints.command.api.PrepareEnvInput\x1a\x44.org.onap.ccsdk.cds.controllerblueprints.command.api.ExecutionOutput\x12\x9b\x01\n\x0e\x65xecuteCommand\x12\x43.org.onap.ccsdk.cds.controllerblueprints.command.api.ExecutionInput\x1a\x44.org.onap.ccsdk.cds.controllerblueprints.command.api.ExecutionOutputB\x02P\x01\x62\x06proto3')
   ,
   dependencies=[google_dot_protobuf_dot_struct__pb2.DESCRIPTOR,google_dot_protobuf_dot_timestamp__pb2.DESCRIPTOR,])
 
@@ -44,8 +44,8 @@ _RESPONSESTATUS = _descriptor.EnumDescriptor(
   ],
   containing_type=None,
   serialized_options=None,
-  serialized_start=1133,
-  serialized_end=1175,
+  serialized_start=1221,
+  serialized_end=1263,
 )
 _sym_db.RegisterEnumDescriptor(_RESPONSESTATUS)
 
@@ -71,8 +71,8 @@ _PACKAGETYPE = _descriptor.EnumDescriptor(
   ],
   containing_type=None,
   serialized_options=None,
-  serialized_start=1177,
-  serialized_end=1234,
+  serialized_start=1265,
+  serialized_end=1322,
 )
 _sym_db.RegisterEnumDescriptor(_PACKAGETYPE)
 
@@ -141,6 +141,20 @@ _EXECUTIONINPUT = _descriptor.Descriptor(
       message_type=None, enum_type=None, containing_type=None,
       is_extension=False, extension_scope=None,
       serialized_options=None, file=DESCRIPTOR),
+    _descriptor.FieldDescriptor(
+      name='subRequestId', full_name='org.onap.ccsdk.cds.controllerblueprints.command.api.ExecutionInput.subRequestId', index=7,
+      number=8, type=9, cpp_type=9, label=1,
+      has_default_value=False, default_value=_b("").decode('utf-8'),
+      message_type=None, enum_type=None, containing_type=None,
+      is_extension=False, extension_scope=None,
+      serialized_options=None, file=DESCRIPTOR),
+    _descriptor.FieldDescriptor(
+      name='originatorId', full_name='org.onap.ccsdk.cds.controllerblueprints.command.api.ExecutionInput.originatorId', index=8,
+      number=9, type=9, cpp_type=9, label=1,
+      has_default_value=False, default_value=_b("").decode('utf-8'),
+      message_type=None, enum_type=None, containing_type=None,
+      is_extension=False, extension_scope=None,
+      serialized_options=None, file=DESCRIPTOR),
   ],
   extensions=[
   ],
@@ -154,7 +168,7 @@ _EXECUTIONINPUT = _descriptor.Descriptor(
   oneofs=[
   ],
   serialized_start=142,
-  serialized_end=413,
+  serialized_end=457,
 )
 
 
@@ -214,6 +228,20 @@ _PREPAREENVINPUT = _descriptor.Descriptor(
       message_type=None, enum_type=None, containing_type=None,
       is_extension=False, extension_scope=None,
       serialized_options=None, file=DESCRIPTOR),
+    _descriptor.FieldDescriptor(
+      name='subRequestId', full_name='org.onap.ccsdk.cds.controllerblueprints.command.api.PrepareEnvInput.subRequestId', index=7,
+      number=8, type=9, cpp_type=9, label=1,
+      has_default_value=False, default_value=_b("").decode('utf-8'),
+      message_type=None, enum_type=None, containing_type=None,
+      is_extension=False, extension_scope=None,
+      serialized_options=None, file=DESCRIPTOR),
+    _descriptor.FieldDescriptor(
+      name='originatorId', full_name='org.onap.ccsdk.cds.controllerblueprints.command.api.PrepareEnvInput.originatorId', index=8,
+      number=9, type=9, cpp_type=9, label=1,
+      has_default_value=False, default_value=_b("").decode('utf-8'),
+      message_type=None, enum_type=None, containing_type=None,
+      is_extension=False, extension_scope=None,
+      serialized_options=None, file=DESCRIPTOR),
   ],
   extensions=[
   ],
@@ -226,8 +254,8 @@ _PREPAREENVINPUT = _descriptor.Descriptor(
   extension_ranges=[],
   oneofs=[
   ],
-  serialized_start=416,
-  serialized_end=752,
+  serialized_start=460,
+  serialized_end=840,
 )
 
 
@@ -264,8 +292,8 @@ _IDENTIFIERS = _descriptor.Descriptor(
   extension_ranges=[],
   oneofs=[
   ],
-  serialized_start=754,
-  serialized_end=816,
+  serialized_start=842,
+  serialized_end=904,
 )
 
 
@@ -323,8 +351,8 @@ _EXECUTIONOUTPUT = _descriptor.Descriptor(
   extension_ranges=[],
   oneofs=[
   ],
-  serialized_start=819,
-  serialized_end=1022,
+  serialized_start=907,
+  serialized_end=1110,
 )
 
 
@@ -361,8 +389,8 @@ _PACKAGES = _descriptor.Descriptor(
   extension_ranges=[],
   oneofs=[
   ],
-  serialized_start=1024,
-  serialized_end=1131,
+  serialized_start=1112,
+  serialized_end=1219,
 )
 
 _EXECUTIONINPUT.fields_by_name['identifiers'].message_type = _IDENTIFIERS
@@ -384,39 +412,39 @@ DESCRIPTOR.enum_types_by_name['ResponseStatus'] = _RESPONSESTATUS
 DESCRIPTOR.enum_types_by_name['PackageType'] = _PACKAGETYPE
 _sym_db.RegisterFileDescriptor(DESCRIPTOR)
 
-ExecutionInput = _reflection.GeneratedProtocolMessageType('ExecutionInput', (_message.Message,), {
-  'DESCRIPTOR' : _EXECUTIONINPUT,
-  '__module__' : 'CommandExecutor_pb2'
+ExecutionInput = _reflection.GeneratedProtocolMessageType('ExecutionInput', (_message.Message,), dict(
+  DESCRIPTOR = _EXECUTIONINPUT,
+  __module__ = 'CommandExecutor_pb2'
   # @@protoc_insertion_point(class_scope:org.onap.ccsdk.cds.controllerblueprints.command.api.ExecutionInput)
-  })
+  ))
 _sym_db.RegisterMessage(ExecutionInput)
 
-PrepareEnvInput = _reflection.GeneratedProtocolMessageType('PrepareEnvInput', (_message.Message,), {
-  'DESCRIPTOR' : _PREPAREENVINPUT,
-  '__module__' : 'CommandExecutor_pb2'
+PrepareEnvInput = _reflection.GeneratedProtocolMessageType('PrepareEnvInput', (_message.Message,), dict(
+  DESCRIPTOR = _PREPAREENVINPUT,
+  __module__ = 'CommandExecutor_pb2'
   # @@protoc_insertion_point(class_scope:org.onap.ccsdk.cds.controllerblueprints.command.api.PrepareEnvInput)
-  })
+  ))
 _sym_db.RegisterMessage(PrepareEnvInput)
 
-Identifiers = _reflection.GeneratedProtocolMessageType('Identifiers', (_message.Message,), {
-  'DESCRIPTOR' : _IDENTIFIERS,
-  '__module__' : 'CommandExecutor_pb2'
+Identifiers = _reflection.GeneratedProtocolMessageType('Identifiers', (_message.Message,), dict(
+  DESCRIPTOR = _IDENTIFIERS,
+  __module__ = 'CommandExecutor_pb2'
   # @@protoc_insertion_point(class_scope:org.onap.ccsdk.cds.controllerblueprints.command.api.Identifiers)
-  })
+  ))
 _sym_db.RegisterMessage(Identifiers)
 
-ExecutionOutput = _reflection.GeneratedProtocolMessageType('ExecutionOutput', (_message.Message,), {
-  'DESCRIPTOR' : _EXECUTIONOUTPUT,
-  '__module__' : 'CommandExecutor_pb2'
+ExecutionOutput = _reflection.GeneratedProtocolMessageType('ExecutionOutput', (_message.Message,), dict(
+  DESCRIPTOR = _EXECUTIONOUTPUT,
+  __module__ = 'CommandExecutor_pb2'
   # @@protoc_insertion_point(class_scope:org.onap.ccsdk.cds.controllerblueprints.command.api.ExecutionOutput)
-  })
+  ))
 _sym_db.RegisterMessage(ExecutionOutput)
 
-Packages = _reflection.GeneratedProtocolMessageType('Packages', (_message.Message,), {
-  'DESCRIPTOR' : _PACKAGES,
-  '__module__' : 'CommandExecutor_pb2'
+Packages = _reflection.GeneratedProtocolMessageType('Packages', (_message.Message,), dict(
+  DESCRIPTOR = _PACKAGES,
+  __module__ = 'CommandExecutor_pb2'
   # @@protoc_insertion_point(class_scope:org.onap.ccsdk.cds.controllerblueprints.command.api.Packages)
-  })
+  ))
 _sym_db.RegisterMessage(Packages)
 
 
@@ -428,8 +456,8 @@ _COMMANDEXECUTORSERVICE = _descriptor.ServiceDescriptor(
   file=DESCRIPTOR,
   index=0,
   serialized_options=None,
-  serialized_start=1237,
-  serialized_end=1574,
+  serialized_start=1325,
+  serialized_end=1662,
   methods=[
   _descriptor.MethodDescriptor(
     name='prepareEnv',
@@ -454,4 +482,4 @@ _sym_db.RegisterServiceDescriptor(_COMMANDEXECUTORSERVICE)
 
 DESCRIPTOR.services_by_name['CommandExecutorService'] = _COMMANDEXECUTORSERVICE
 
-# @@protoc_insertion_point(module_scope)
+# @@protoc_insertion_point(module_scope)
\ No newline at end of file
diff --git a/ms/command-executor/src/main/python/server.py b/ms/command-executor/src/main/python/server.py
index c136bd8cc..d506d096b 100644
--- a/ms/command-executor/src/main/python/server.py
+++ b/ms/command-executor/src/main/python/server.py
@@ -2,7 +2,7 @@
 #!/usr/bin/python
 
 #
-# Copyright (C) 2019 Bell Canada.
+# Copyright (C) 2019 - 2020 Bell Canada.
 #
 # Licensed under the Apache License, Version 2.0 (the "License");
 # you may not use this file except in compliance with the License.
@@ -21,6 +21,7 @@ from concurrent import futures
 import logging
 import time
 import sys
+import utils
 
 import grpc
 
@@ -52,7 +53,7 @@ def serve():
     server.add_insecure_port('[::]:' + port)
     server.start()
 
-    logger.info("Command Executor Server started on %s" % port)
+    logger.info("Command Executor Server started on %s" % port, extra=utils.getExtraLogData())
 
     try:
         while True:
@@ -62,7 +63,7 @@ def serve():
 
 
 if __name__ == '__main__':
-    logging_formater = '%(asctime)s - %(name)s - %(threadName)s - %(levelname)s - %(message)s'
+    logging_formater = '%(asctime)s|%(request_id)s|%(subrequest_id)s|%(originator_id)s|%(threadName)s|%(name)s|%(levelname)s|%(message)s'
     logging.basicConfig(filename='/opt/app/onap/logs/application.log', level=logging.DEBUG,
                         format=logging_formater)
     console = logging.StreamHandler()
diff --git a/ms/command-executor/src/main/python/utils.py b/ms/command-executor/src/main/python/utils.py
index 54c5ceafa..c624a3d2e 100644
--- a/ms/command-executor/src/main/python/utils.py
+++ b/ms/command-executor/src/main/python/utils.py
@@ -1,5 +1,5 @@
 #
-# Copyright (C) 2019 Bell Canada.
+# Copyright (C) 2019 - 2020 Bell Canada.
 #
 # Licensed under the Apache License, Version 2.0 (the "License");
 # you may not use this file except in compliance with the License.
@@ -79,7 +79,7 @@ def truncate_execution_output(execution_output):
 
 
 # Read temp file 'outputfile' into results_log and split out the returned payload into payload_result
-def parse_cmd_exec_output(outputfile, logger, payload_result, results_log):
+def parse_cmd_exec_output(outputfile, logger, payload_result, results_log, extra):
   payload_section = []
   is_payload_section = False
   outputfile.seek(0)
@@ -98,8 +98,17 @@ def parse_cmd_exec_output(outputfile, logger, payload_result, results_log):
       for part in msg.get_payload():
         payload_result.update(json.loads(part.get_payload()))
     if output and not is_payload_section:
-      logger.info(output.strip())
+      logger.info(output.strip(), extra=extra)
       results_log.append(output.strip())
     else:
       payload_section.append(output.strip())
 
+def getExtraLogData(request=None):
+    extra = {'request_id' : '', 'subrequest_id' : '', 'originator_id': ''}
+    if request is not None:
+        extra = {
+            'request_id' : request.requestId,
+            'subrequest_id' : request.subRequestId,
+            'originator_id': request.originatorId
+        }
+    return extra
\ No newline at end of file