Add request IDs in command-executor log
[ccsdk/cds.git] / ms / blueprintsprocessor / functions / python-executor / src / main / kotlin / org / onap / ccsdk / cds / blueprintsprocessor / functions / python / executor / ComponentRemotePythonExecutor.kt
1 /*
2  *  Copyright Â© 2019 IBM.
3  *  Modifications Copyright © 2020 Bell Canada.
4  *
5  *  Licensed under the Apache License, Version 2.0 (the "License");
6  *  you may not use this file except in compliance with the License.
7  *  You may obtain a copy of the License at
8  *
9  *      http://www.apache.org/licenses/LICENSE-2.0
10  *
11  *  Unless required by applicable law or agreed to in writing, software
12  *  distributed under the License is distributed on an "AS IS" BASIS,
13  *  WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
14  *  See the License for the specific language governing permissions and
15  *  limitations under the License.
16  */
17
18 package org.onap.ccsdk.cds.blueprintsprocessor.functions.python.executor
19
20 import com.fasterxml.jackson.databind.JsonNode
21 import kotlinx.coroutines.GlobalScope
22 import kotlinx.coroutines.TimeoutCancellationException
23 import kotlinx.coroutines.async
24 import kotlinx.coroutines.withTimeout
25 import org.onap.ccsdk.cds.blueprintsprocessor.core.BluePrintPropertiesService
26 import org.onap.ccsdk.cds.blueprintsprocessor.core.api.data.ExecutionServiceInput
27 import org.onap.ccsdk.cds.blueprintsprocessor.core.api.data.PrepareRemoteEnvInput
28 import org.onap.ccsdk.cds.blueprintsprocessor.core.api.data.RemoteIdentifier
29 import org.onap.ccsdk.cds.blueprintsprocessor.core.api.data.RemoteScriptExecutionInput
30 import org.onap.ccsdk.cds.blueprintsprocessor.core.api.data.StatusType
31 import org.onap.ccsdk.cds.blueprintsprocessor.services.execution.AbstractComponentFunction
32 import org.onap.ccsdk.cds.blueprintsprocessor.services.execution.ExecutionServiceConstant
33 import org.onap.ccsdk.cds.blueprintsprocessor.services.execution.RemoteScriptExecutionService
34 import org.onap.ccsdk.cds.controllerblueprints.core.BluePrintProcessorException
35 import org.onap.ccsdk.cds.controllerblueprints.core.asJsonPrimitive
36 import org.onap.ccsdk.cds.controllerblueprints.core.checkFileExists
37 import org.onap.ccsdk.cds.controllerblueprints.core.checkNotBlank
38 import org.onap.ccsdk.cds.controllerblueprints.core.data.OperationAssignment
39 import org.onap.ccsdk.cds.controllerblueprints.core.normalizedFile
40 import org.onap.ccsdk.cds.controllerblueprints.core.returnNullIfMissing
41 import org.onap.ccsdk.cds.controllerblueprints.core.rootFieldsToMap
42 import org.onap.ccsdk.cds.controllerblueprints.core.utils.JacksonUtils
43 import org.slf4j.LoggerFactory
44 import org.springframework.beans.factory.config.ConfigurableBeanFactory
45 import org.springframework.boot.autoconfigure.condition.ConditionalOnBean
46 import org.springframework.context.annotation.Scope
47 import org.springframework.stereotype.Component
48
49 @ConditionalOnBean(name = [ExecutionServiceConstant.SERVICE_GRPC_REMOTE_SCRIPT_EXECUTION])
50 @Component("component-remote-python-executor")
51 @Scope(value = ConfigurableBeanFactory.SCOPE_PROTOTYPE)
52 open class ComponentRemotePythonExecutor(
53     private val remoteScriptExecutionService: RemoteScriptExecutionService,
54     private var bluePrintPropertiesService: BluePrintPropertiesService
55 ) : AbstractComponentFunction() {
56
57     private val log = LoggerFactory.getLogger(ComponentRemotePythonExecutor::class.java)!!
58
59     companion object {
60         const val SELECTOR_CMD_EXEC = "blueprintsprocessor.remote-script-command"
61         const val INPUT_ENDPOINT_SELECTOR = "endpoint-selector"
62         const val INPUT_DYNAMIC_PROPERTIES = "dynamic-properties"
63         const val INPUT_ARGUMENT_PROPERTIES = "argument-properties"
64
65         const val INPUT_COMMAND = "command"
66         const val INPUT_PACKAGES = "packages"
67         const val DEFAULT_SELECTOR = "remote-python"
68         const val INPUT_ENV_PREPARE_TIMEOUT = "env-prepare-timeout"
69         const val INPUT_EXECUTE_TIMEOUT = "execution-timeout"
70
71         const val STEP_PREPARE_ENV = "prepare-env"
72         const val STEP_EXEC_CMD = "execute-command"
73         const val ATTRIBUTE_EXEC_CMD_STATUS = "status"
74         const val ATTRIBUTE_PREPARE_ENV_LOG = "prepare-environment-logs"
75         const val ATTRIBUTE_EXEC_CMD_LOG = "execute-command-logs"
76         const val ATTRIBUTE_RESPONSE_DATA = "response-data"
77         const val DEFAULT_ENV_PREPARE_TIMEOUT_IN_SEC = 120
78         const val DEFAULT_EXECUTE_TIMEOUT_IN_SEC = 180
79         const val TIMEOUT_DELTA = 100L
80     }
81
82     override suspend fun processNB(executionRequest: ExecutionServiceInput) {
83
84         log.debug("Processing : $operationInputs")
85
86         val isLogResponseEnabled = bluePrintPropertiesService.propertyBeanType("$SELECTOR_CMD_EXEC.response.log.enabled", Boolean::class.java)
87
88         val bluePrintContext = bluePrintRuntimeService.bluePrintContext()
89         val blueprintName = bluePrintContext.name()
90         val blueprintVersion = bluePrintContext.version()
91
92         val operationAssignment: OperationAssignment = bluePrintContext
93             .nodeTemplateInterfaceOperation(nodeTemplateName, interfaceName, operationName)
94
95         val artifactName: String = operationAssignment.implementation?.primary
96             ?: throw BluePrintProcessorException("missing primary field to get artifact name for node template ($nodeTemplateName)")
97
98         val artifactDefinition =
99             bluePrintRuntimeService.resolveNodeTemplateArtifactDefinition(nodeTemplateName, artifactName)
100
101         checkNotBlank(artifactDefinition.file) { "couldn't get python script path($artifactName)" }
102
103         val pythonScript = normalizedFile(bluePrintContext.rootPath, artifactDefinition.file)
104
105         checkFileExists(pythonScript) { "python script(${pythonScript.absolutePath}) doesn't exists" }
106
107         val endPointSelector = getOperationInput(INPUT_ENDPOINT_SELECTOR)
108         val dynamicProperties = getOptionalOperationInput(INPUT_DYNAMIC_PROPERTIES)
109         val packages = getOptionalOperationInput(INPUT_PACKAGES)?.returnNullIfMissing()
110
111         val argsNode = getOptionalOperationInput(INPUT_ARGUMENT_PROPERTIES)?.returnNullIfMissing()
112
113         // This prevents unescaping values, as well as quoting the each parameter, in order to allow for spaces in values
114         val args = getOptionalOperationInput(INPUT_ARGUMENT_PROPERTIES)?.returnNullIfMissing()
115             ?.rootFieldsToMap()?.toSortedMap()?.values?.joinToString(" ") { formatNestedJsonNode(it) }
116
117         val command = getOperationInput(INPUT_COMMAND).asText()
118
119         /**
120          * Timeouts that are specific to the command executor.
121          * Note: the interface->input->timeout is the component level timeout.
122          */
123         val envPrepTimeout = getOptionalOperationInput(INPUT_ENV_PREPARE_TIMEOUT)?.asInt()
124             ?: DEFAULT_ENV_PREPARE_TIMEOUT_IN_SEC
125         val executionTimeout = getOptionalOperationInput(INPUT_EXECUTE_TIMEOUT)?.asInt()
126             ?: DEFAULT_EXECUTE_TIMEOUT_IN_SEC
127
128         // component level timeout should be => env_prep_timeout + execution_timeout
129         val timeout = implementation.timeout
130
131         var scriptCommand = command.replace(pythonScript.name, pythonScript.absolutePath)
132         if (args != null && args.isNotEmpty()) {
133             scriptCommand = scriptCommand.plus(" ").plus(args)
134         }
135
136         try {
137             // Open GRPC Connection
138             if (DEFAULT_SELECTOR == endPointSelector.asText()) {
139                 remoteScriptExecutionService.init(endPointSelector.asText())
140             } else {
141                 // Get endpoint from DSL
142                 val endPointSelectorJson = bluePrintRuntimeService.resolveDSLExpression(endPointSelector.asText())
143                 remoteScriptExecutionService.init(endPointSelectorJson)
144             }
145
146             // If packages are defined, then install in remote server
147             if (packages != null) {
148                 val prepareEnvInput = PrepareRemoteEnvInput(
149                     originatorId = executionServiceInput.commonHeader.originatorId,
150                     requestId = processId,
151                     subRequestId = executionServiceInput.commonHeader.subRequestId,
152                     remoteIdentifier = RemoteIdentifier(
153                         blueprintName = blueprintName,
154                         blueprintVersion = blueprintVersion),
155                     packages = packages,
156                     timeOut = envPrepTimeout.toLong()
157
158                 )
159                 val prepareEnvOutput = remoteScriptExecutionService.prepareEnv(prepareEnvInput)
160                 log.info("$ATTRIBUTE_PREPARE_ENV_LOG - ${prepareEnvOutput.response}")
161                 val logs = JacksonUtils.jsonNodeFromObject(prepareEnvOutput.response)
162                 setAttribute(ATTRIBUTE_PREPARE_ENV_LOG, logs)
163
164                 // there are no artifacts for env. prepare, but we reuse it for err_log...
165                 if (prepareEnvOutput.status != StatusType.SUCCESS) {
166                     setNodeOutputErrors(STEP_PREPARE_ENV, "[]".asJsonPrimitive(), prepareEnvOutput.payload, isLogResponseEnabled)
167                     addError(StatusType.FAILURE.name, STEP_PREPARE_ENV, logs.toString())
168                 } else {
169                     setNodeOutputProperties(prepareEnvOutput.status, STEP_PREPARE_ENV, logs, prepareEnvOutput.payload, isLogResponseEnabled)
170                 }
171             } else {
172                 // set env preparation log to empty...
173                 setAttribute(ATTRIBUTE_PREPARE_ENV_LOG, "".asJsonPrimitive())
174             }
175             // in cases where the exception is caught in BP side due to timeout, we do not have `err_msg` returned by cmd-exec (inside `payload`),
176             // hence `artifact` field will be empty
177         } catch (grpcEx: io.grpc.StatusRuntimeException) {
178             val componentLevelWarningMsg = if (timeout < envPrepTimeout) "Note: component-level timeout ($timeout) is shorter than env-prepare timeout ($envPrepTimeout). " else ""
179             val grpcErrMsg = "Command failed during env. preparation... timeout($envPrepTimeout) requestId ($processId).$componentLevelWarningMsg grpcError: (${grpcEx.cause?.message})"
180             // no execution log in case of timeout (as cmd-exec side hasn't finished to transfer output)
181             // set prepare-env-log to the error msg, and cmd-exec-log to empty
182             setAttribute(ATTRIBUTE_PREPARE_ENV_LOG, grpcErrMsg.asJsonPrimitive())
183             setNodeOutputErrors(STEP_PREPARE_ENV, "[]".asJsonPrimitive(), "{}".asJsonPrimitive(), isLogResponseEnabled)
184             addError(StatusType.FAILURE.name, STEP_PREPARE_ENV, grpcErrMsg)
185             log.error(grpcErrMsg, grpcEx)
186         } catch (e: Exception) {
187             val catchallErrMsg = "Command executor failed during env. preparation.. catch-all case. timeout($envPrepTimeout) requestId ($processId). exception msg: ${e.message}"
188             // no environment prepare log from executor in case of timeout (as cmd-exec side hasn't finished to transfer output), set it to error msg. Execution logs is empty.
189             setAttribute(ATTRIBUTE_PREPARE_ENV_LOG, catchallErrMsg.asJsonPrimitive())
190             setNodeOutputErrors(STEP_PREPARE_ENV, "[]".asJsonPrimitive(), "{}".asJsonPrimitive(), isLogResponseEnabled)
191             addError(StatusType.FAILURE.name, STEP_PREPARE_ENV, catchallErrMsg)
192             log.error(catchallErrMsg, e)
193         }
194         // if Env preparation was successful, then proceed with command execution in this Env
195         if (bluePrintRuntimeService.getBluePrintError().errors.isEmpty()) {
196             try {
197                 // Populate command execution properties and pass it to the remote server
198                 val properties = dynamicProperties?.returnNullIfMissing()?.rootFieldsToMap() ?: hashMapOf()
199
200                 val remoteExecutionInput = RemoteScriptExecutionInput(
201                     originatorId = executionServiceInput.commonHeader.originatorId,
202                     requestId = processId,
203                     subRequestId = executionServiceInput.commonHeader.subRequestId,
204                     remoteIdentifier = RemoteIdentifier(blueprintName = blueprintName, blueprintVersion = blueprintVersion),
205                     command = scriptCommand,
206                     properties = properties,
207                     timeOut = executionTimeout.toLong())
208
209                 val remoteExecutionOutputDeferred = GlobalScope.async {
210                     remoteScriptExecutionService.executeCommand(remoteExecutionInput)
211                 }
212
213                 val remoteExecutionOutput = withTimeout(executionTimeout * 1000L + TIMEOUT_DELTA) {
214                     remoteExecutionOutputDeferred.await()
215                 }
216
217                 checkNotNull(remoteExecutionOutput) {
218                     "Error: Request-id $processId did not return a result from remote command execution."
219                 }
220                 val logs = JacksonUtils.jsonNodeFromObject(remoteExecutionOutput.response)
221                 val returnedPayload = remoteExecutionOutput.payload
222                 // In case of execution, `payload` (dictionary from Python execution) is preserved in `remoteExecutionOutput.payload`;
223                 // It would contain `err_msg` key. It is valid to return it.
224                 if (remoteExecutionOutput.status != StatusType.SUCCESS) {
225                     setNodeOutputErrors(STEP_EXEC_CMD, logs, returnedPayload, isLogResponseEnabled)
226                     addError(StatusType.FAILURE.name, STEP_EXEC_CMD, logs.toString())
227                 } else {
228                     setNodeOutputProperties(remoteExecutionOutput.status, STEP_EXEC_CMD, logs, returnedPayload, isLogResponseEnabled)
229                 } // In timeout exception cases, we don't have payload, hence `payload` is empty value.
230             } catch (timeoutEx: TimeoutCancellationException) {
231                 val componentLevelWarningMsg = if (timeout < executionTimeout) "Note: component-level timeout ($timeout) is shorter than execution timeout ($executionTimeout). " else ""
232                 val timeoutErrMsg = "Command executor execution timeout. DetailedMessage: (${timeoutEx.message}) requestId ($processId). $componentLevelWarningMsg"
233                 setNodeOutputErrors(STEP_EXEC_CMD, listOf(timeoutErrMsg).asJsonPrimitive(), logging = isLogResponseEnabled)
234                 addError(StatusType.FAILURE.name, STEP_EXEC_CMD, timeoutErrMsg)
235                 log.error(timeoutErrMsg, timeoutEx)
236             } catch (grpcEx: io.grpc.StatusRuntimeException) {
237                 val timeoutErrMsg = "Command executor timed out executing after $executionTimeout seconds requestId ($processId) grpcErr: ${grpcEx.status}"
238                 setNodeOutputErrors(STEP_EXEC_CMD, listOf(timeoutErrMsg).asJsonPrimitive(), logging = isLogResponseEnabled)
239                 addError(StatusType.FAILURE.name, STEP_EXEC_CMD, timeoutErrMsg)
240                 log.error(timeoutErrMsg, grpcEx)
241             } catch (e: Exception) {
242                 val catchAllErrMsg = "Command executor failed during process catch-all case requestId ($processId) timeout($envPrepTimeout) exception msg: ${e.message}"
243                 setNodeOutputErrors(STEP_PREPARE_ENV, listOf(catchAllErrMsg).asJsonPrimitive(), logging = isLogResponseEnabled)
244                 addError(StatusType.FAILURE.name, STEP_EXEC_CMD, catchAllErrMsg)
245                 log.error(catchAllErrMsg, e)
246             }
247         }
248         log.debug("Trying to close GRPC channel. request ($processId)")
249         remoteScriptExecutionService.close()
250     }
251
252     override suspend fun recoverNB(runtimeException: RuntimeException, executionRequest: ExecutionServiceInput) {
253         bluePrintRuntimeService.getBluePrintError()
254             .addError("Failed in ComponentRemotePythonExecutor : ${runtimeException.message}")
255     }
256
257     private fun formatNestedJsonNode(node: JsonNode): String {
258         val sb = StringBuilder()
259         if (node.isValueNode) {
260             sb.append(" $node")
261         } else {
262             node.forEach { sb.append(" $it") }
263         }
264         return sb.toString()
265     }
266
267     /**
268      * Utility function to set the output properties of the executor node
269      */
270     private fun setNodeOutputProperties(
271         status: StatusType,
272         step: String,
273         executionLogs: JsonNode,
274         artifacts: JsonNode,
275         logging: Boolean = true
276     ) {
277
278         setAttribute(ATTRIBUTE_EXEC_CMD_STATUS, status.name.asJsonPrimitive())
279         setAttribute(ATTRIBUTE_EXEC_CMD_LOG, executionLogs)
280         setAttribute(ATTRIBUTE_RESPONSE_DATA, artifacts)
281
282         if (logging) {
283             log.info("Executor status : $step : $status")
284             log.info("Executor logs   : $step : $executionLogs")
285             log.info("Executor artifacts: $step : $artifacts")
286         }
287     }
288
289     /**
290      * Utility function to set the output properties and errors of the executor node, in case of errors
291      */
292     private fun setNodeOutputErrors(
293         step: String,
294         executionLogs: JsonNode = "[]".asJsonPrimitive(),
295         artifacts: JsonNode = "{}".asJsonPrimitive(),
296         logging: Boolean = true
297     ) {
298         val status = StatusType.FAILURE.name
299         setAttribute(ATTRIBUTE_EXEC_CMD_STATUS, status.asJsonPrimitive())
300         setAttribute(ATTRIBUTE_EXEC_CMD_LOG, executionLogs)
301         setAttribute(ATTRIBUTE_RESPONSE_DATA, artifacts)
302
303         if (logging) {
304             log.info("Executor status : $step : $status")
305             log.info("Executor logs   : $step : $executionLogs")
306             log.info("Executor artifacts: $step : $artifacts")
307         }
308     }
309 }