appc-dispatcher/appc-request-handler/appc-request-handler-core/src/main/java/org/openecomp/appc/requesthandler/impl/RequestHandlerImpl.java

   1 /*-
   2  * ============LICENSE_START=======================================================
   3  * openECOMP : APP-C
   4  * ================================================================================
   5  * Copyright (C) 2017 AT&T Intellectual Property. All rights
   6  *                                              reserved.
   7  * ================================================================================
   8  * Licensed under the Apache License, Version 2.0 (the "License");
   9  * you may not use this file except in compliance with the License.
  10  * You may obtain a copy of the License at
  11  *
  12  *      http://www.apache.org/licenses/LICENSE-2.0
  13  *
  14  * Unless required by applicable law or agreed to in writing, software
  15  * distributed under the License is distributed on an "AS IS" BASIS,
  16  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
  17  * See the License for the specific language governing permissions and
  18  * limitations under the License.
  19  * ============LICENSE_END=========================================================
  20  */
  21
  22 package org.openecomp.appc.requesthandler.impl;
  23
  24 import org.apache.commons.lang.ObjectUtils;
  25 import org.openecomp.appc.common.constant.Constants;
  26 import org.openecomp.appc.configuration.Configuration;
  27 import org.openecomp.appc.configuration.ConfigurationFactory;
  28 import org.openecomp.appc.domainmodel.lcm.*;
  29 import org.openecomp.appc.exceptions.APPCException;
  30 import org.openecomp.appc.executor.CommandExecutor;
  31 import org.openecomp.appc.executor.UnstableVNFException;
  32 import org.openecomp.appc.executor.objects.LCMCommandStatus;
  33 import org.openecomp.appc.executor.objects.Params;
  34 import org.openecomp.appc.executor.objects.UniqueRequestIdentifier;
  35 import org.openecomp.appc.i18n.Msg;
  36 import org.openecomp.appc.lifecyclemanager.objects.LifecycleException;
  37 import org.openecomp.appc.lifecyclemanager.objects.NoTransitionDefinedException;
  38 import org.openecomp.appc.lockmanager.api.LockException;
  39 import org.openecomp.appc.lockmanager.api.LockManager;
  40 import org.openecomp.appc.logging.LoggingConstants;
  41 import org.openecomp.appc.logging.LoggingUtils;
  42 import org.openecomp.appc.messageadapter.MessageAdapter;
  43 import org.openecomp.appc.messageadapter.impl.MessageAdapterImpl;
  44 import org.openecomp.appc.metricservice.MetricRegistry;
  45 import org.openecomp.appc.metricservice.MetricService;
  46 import org.openecomp.appc.metricservice.metric.DispatchingFuntionMetric;
  47 import org.openecomp.appc.metricservice.metric.Metric;
  48 import org.openecomp.appc.metricservice.metric.MetricType;
  49 import org.openecomp.appc.metricservice.policy.PublishingPolicy;
  50 import org.openecomp.appc.metricservice.publisher.LogPublisher;
  51 import org.openecomp.appc.requesthandler.RequestHandler;
  52 import org.openecomp.appc.requesthandler.exceptions.*;
  53 import org.openecomp.appc.requesthandler.helper.RequestRegistry;
  54 import org.openecomp.appc.requesthandler.helper.RequestValidator;
  55 import org.openecomp.appc.requesthandler.objects.RequestHandlerInput;
  56 import org.openecomp.appc.requesthandler.objects.RequestHandlerOutput;
  57 import org.openecomp.appc.transactionrecorder.TransactionRecorder;
  58 import org.openecomp.appc.transactionrecorder.objects.TransactionRecord;
  59 import org.openecomp.appc.workingstatemanager.WorkingStateManager;
  60 import org.openecomp.appc.workingstatemanager.objects.VNFWorkingState;
  61 import com.att.eelf.configuration.EELFLogger;
  62 import com.att.eelf.configuration.EELFManager;
  63 import com.att.eelf.i18n.EELFResourceManager;
  64 import org.openecomp.sdnc.sli.SvcLogicContext;
  65 import org.openecomp.sdnc.sli.SvcLogicException;
  66 import org.openecomp.sdnc.sli.SvcLogicResource.QueryStatus;
  67 import org.openecomp.sdnc.sli.aai.AAIService;
  68 import org.osgi.framework.BundleContext;
  69 import org.osgi.framework.FrameworkUtil;
  70 import org.osgi.framework.ServiceReference;
  71 import org.slf4j.MDC;
  72
  73 import static com.att.eelf.configuration.Configuration.*;
  74
  75 import java.net.InetAddress;
  76 import java.time.Instant;
  77 import java.time.temporal.ChronoUnit;
  78 import java.util.Date;
  79 import java.util.HashMap;
  80 import java.util.Map;
  81 import java.util.Properties;
  82
  83 /**
  84  * This class provides application logic for the Request/Response Handler Component.
  85  *
  86  */
  87 public class RequestHandlerImpl implements RequestHandler {
  88
  89     /**
  90      * APP-C VNF lock idle timeout in milliseconds. Applied only when locking VNF using northbound API "lock"
  91      */
  92     private static final String PROP_IDLE_TIMEOUT = "org.openecomp.appc.lock.idleTimeout";
  93
  94     private CommandExecutor commandExecutor;
  95
  96     private TransactionRecorder transactionRecorder;
  97     private MessageAdapter messageAdapter;
  98     private RequestValidator requestValidator;
  99     private static MetricRegistry metricRegistry;
 100     private boolean isMetricEnabled = false;
 101     private RequestRegistry requestRegistry;
 102     private LockManager lockManager;
 103     private WorkingStateManager workingStateManager;
 104     private AAIService aaiService;
 105
 106     private static final EELFLogger logger = EELFManager.getInstance().getLogger(RequestHandlerImpl.class);
 107
 108     public void setAaiService(AAIService aaiService) {
 109         this.aaiService = aaiService;
 110     }
 111
 112     public void setTransactionRecorder(TransactionRecorder transactionRecorder) {
 113         this.transactionRecorder = transactionRecorder;
 114     }
 115
 116     public void setLockManager(LockManager lockManager) {
 117         this.lockManager = lockManager;
 118     }
 119
 120     public void setRequestValidator(RequestValidator requestValidator) {
 121         this.requestValidator = requestValidator;
 122     }
 123
 124     public void setMessageAdapter(MessageAdapter messageAdapter) {
 125         this.messageAdapter = messageAdapter;
 126     }
 127
 128     private static final Configuration configuration = ConfigurationFactory.getConfiguration();
 129
 130     public void setWorkingStateManager(WorkingStateManager workingStateManager) {
 131         this.workingStateManager = workingStateManager;
 132     }
 133
 134     public RequestHandlerImpl() {
 135         requestRegistry = new RequestRegistry();
 136         messageAdapter = new MessageAdapterImpl();
 137         messageAdapter.init();
 138         Properties properties = configuration.getProperties();
 139         if (properties != null && properties.getProperty("metric.enabled") != null) {
 140             isMetricEnabled = Boolean.valueOf(properties.getProperty("metric.enabled"));
 141         }
 142         if (isMetricEnabled) {
 143             initMetric();
 144         }
 145     }
 146
 147     public void setCommandExecutor(CommandExecutor commandExecutor) {
 148         this.commandExecutor = commandExecutor;
 149     }
 150
 151
 152     /**
 153      * It receives requests from the north-bound REST API (Communication) Layer and
 154      * performs following validations.
 155      * 1. VNF exists in A&AI for the given targetID (VnfID)
 156      * 2. For the current VNF  Orchestration Status, the command can be executed
 157      * 3. For the given VNF type and Operation, there exists work-flow definition in the APPC database
 158      * If any of the validation fails, it returns appropriate response
 159      *
 160      * @param input RequestHandlerInput object which contains request header and  other request parameters like command , target Id , payload etc.
 161      * @return response for request as enum with Return code and message.
 162      */
 163     @Override
 164     public RequestHandlerOutput handleRequest(RequestHandlerInput input) {
 165         if (logger.isTraceEnabled())
 166             logger.trace("Entering to handleRequest with RequestHandlerInput = " + ObjectUtils.toString(input) + ")");
 167         Params params = null;
 168         String vnfId = null, vnfType = null, errorMessage = null;
 169         Instant startTime = Instant.now();
 170         RequestHandlerOutput output = null;
 171         setInitialLogProperties(input.getRequestContext());
 172
 173         RuntimeContext runtimeContext = new RuntimeContext();
 174         runtimeContext.setRequestContext(input.getRequestContext());
 175         runtimeContext.setTimeStart(startTime);
 176         runtimeContext.setRpcName(input.getRpcName());
 177
 178         final ResponseContext responseContext = new ResponseContext();
 179         responseContext.setStatus(new Status(0, null));
 180         responseContext.setAdditionalContext(new HashMap<String, String>(4));
 181         responseContext.setCommonHeader(input.getRequestContext().getCommonHeader());
 182         runtimeContext.setResponseContext(responseContext);
 183         runtimeContext.getResponseContext().setStatus(new Status(0, null));
 184
 185         vnfId = runtimeContext.getRequestContext().getActionIdentifiers().getVnfId();
 186
 187         try {
 188
 189             requestValidator.validateRequest(runtimeContext);
 190
 191             handleRequest(runtimeContext);
 192
 193             final int statusCode = runtimeContext.getResponseContext().getStatus().getCode();
 194             if (statusCode % 100 == 2 || statusCode % 100 == 3) {
 195                 createTransactionRecord(runtimeContext);
 196             }
 197             output = new RequestHandlerOutput();
 198             output.setResponseContext(runtimeContext.getResponseContext());
 199
 200         } catch (VNFNotFoundException e) {
 201             errorMessage = e.getMessage();
 202             String logMessage = EELFResourceManager.format(Msg.APPC_NO_RESOURCE_FOUND, vnfId);
 203             storeErrorMessageToLog(runtimeContext, LoggingConstants.TargetNames.AAI, "", logMessage);
 204             params = new Params().addParam("vnfId", vnfId);
 205             output = buildRequestHandlerOutput(LCMCommandStatus.VNF_NOT_FOUND, params);
 206         } catch (NoTransitionDefinedException e) {
 207             errorMessage = e.getMessage();
 208             String logMessage = EELFResourceManager.format(Msg.VF_UNDEFINED_STATE, input.getRequestContext().getCommonHeader().getOriginatorId(), input.getRequestContext().getAction().name());
 209             params = new Params().addParam("actionName", input.getRequestContext().getAction()).addParam("currentState", e.currentState);
 210             output = buildRequestHandlerOutput(LCMCommandStatus.NO_TRANSITION_DEFINE, params);
 211             storeErrorMessageToLog(runtimeContext,
 212                     LoggingConstants.TargetNames.APPC,
 213                     LoggingConstants.TargetNames.STATE_MACHINE,
 214                     logMessage);
 215         } catch (LifecycleException e) {
 216             errorMessage = e.getMessage();
 217             params = new Params().addParam("actionName", input.getRequestContext().getAction()).addParam("currentState", e.currentState);
 218             output = buildRequestHandlerOutput(LCMCommandStatus.INVALID_VNF_STATE, params);
 219         } catch (UnstableVNFException e) {
 220             errorMessage = e.getMessage();
 221             params = new Params().addParam("vnfId", vnfId);
 222             output = buildRequestHandlerOutput(LCMCommandStatus.UNSTABLE_VNF, params);
 223         } catch (WorkflowNotFoundException e) {
 224             errorMessage = e.getMessage();
 225             String vnfTypeVersion = e.vnfTypeVersion;
 226             params = new Params().addParam("actionName", input.getRequestContext().getAction()).addParam("vnfTypeVersion", vnfTypeVersion);
 227             output = buildRequestHandlerOutput(LCMCommandStatus.WORKFLOW_NOT_FOUND, params);
 228         } catch (DGWorkflowNotFoundException e) {
 229             errorMessage = e.getMessage();
 230             String logMessage = EELFResourceManager.format(Msg.APPC_WORKFLOW_NOT_FOUND, vnfType, input.getRequestContext().getAction().name());
 231             storeErrorMessageToLog(runtimeContext,
 232                     LoggingConstants.TargetNames.APPC,
 233                     LoggingConstants.TargetNames.WORKFLOW_MANAGER,
 234                     logMessage);
 235             params = new Params().addParam("actionName", input.getRequestContext().getAction().name())
 236                     .addParam("dgModule", e.workflowModule).addParam("dgName", e.workflowName).addParam("dgVersion", e.workflowVersion);
 237             output = buildRequestHandlerOutput(LCMCommandStatus.DG_WORKFLOW_NOT_FOUND, params);
 238         } catch (RequestExpiredException e) {
 239             errorMessage = e.getMessage();
 240             params = new Params().addParam("actionName", input.getRequestContext().getAction().name());
 241             output = buildRequestHandlerOutput(LCMCommandStatus.EXPIRED_REQUEST, params);
 242         } catch (InvalidInputException e) {
 243             errorMessage = e.getMessage() != null ? e.getMessage() : e.toString();
 244             params = new Params().addParam("errorMsg", errorMessage);
 245             output = buildRequestHandlerOutput(LCMCommandStatus.INVALID_INPUT_PARAMETER, params);
 246         } catch (DuplicateRequestException e) {
 247             errorMessage = e.getMessage();
 248             output = buildRequestHandlerOutput(LCMCommandStatus.DUPLICATE_REQUEST, null);
 249         } catch (MissingVNFDataInAAIException e) {
 250             params = new Params().addParam("attributeName",e.getMissingAttributeName())
 251                     .addParam("vnfId",vnfId);
 252             output = buildRequestHandlerOutput(LCMCommandStatus.MISSING_VNF_DATA_IN_AAI,params);
 253             errorMessage = output.getResponseContext().getStatus().getMessage();
 254         } catch (LCMOperationsDisabledException e) {
 255             errorMessage = e.getMessage();
 256             params = new Params().addParam("errorMsg", errorMessage);
 257             output = buildRequestHandlerOutput(LCMCommandStatus.REJECTED, params);
 258         } catch (Exception e) {
 259             storeErrorMessageToLog(runtimeContext, "", "", "Exception = " + e.getMessage());
 260             errorMessage = e.getMessage() != null ? e.getMessage() : e.toString();
 261             params = new Params().addParam("errorMsg", errorMessage);
 262             output = buildRequestHandlerOutput(LCMCommandStatus.UNEXPECTED_ERROR, params);
 263         } finally {
 264             try {
 265                 if (logger.isDebugEnabled() && errorMessage != null)
 266                     logger.debug("error occurred in handleRequest " + errorMessage);
 267                 logger.debug("output.getResponse().getResponseCode().equals(LCMCommandStatus.ACCEPTED.getResponseCode():  " + (output.getResponseContext().getStatus().getCode() == LCMCommandStatus.ACCEPTED.getResponseCode()));
 268                 logger.debug("output.getResponse().getResponseCode().equals(LCMCommandStatus.SUCCESS.getResponseCode():  " + (output.getResponseContext().getStatus().getCode() == LCMCommandStatus.SUCCESS.getResponseCode()));
 269
 270                 runtimeContext.setResponseContext(output.getResponseContext());
 271                 if ((null == output) || !(output.getResponseContext().getStatus().getCode() == LCMCommandStatus.ACCEPTED.getResponseCode())) {
 272                     if (isMetricEnabled) {
 273                         if((output.getResponseContext().getStatus().getCode() == LCMCommandStatus.SUCCESS.getResponseCode())) {
 274                             ((DispatchingFuntionMetric) metricRegistry.metric("DISPATCH_FUNCTION")).incrementAcceptedRequest();
 275                         }else {
 276                             ((DispatchingFuntionMetric) metricRegistry.metric("DISPATCH_FUNCTION")).incrementRejectedRequest();
 277                         }
 278                     }
 279                     removeRequestFromRegistry(input.getRequestContext().getCommonHeader());
 280                 }
 281             } finally {
 282                 storeAuditLogRecord(runtimeContext);
 283                 storeMetricLogRecord(runtimeContext);
 284                 clearRequestLogProperties();
 285             }
 286         }
 287         if (logger.isTraceEnabled()) {
 288             logger.trace("Exiting from handleRequest with (RequestHandlerOutput = " + ObjectUtils.toString(output.getResponseContext()) + ")");
 289         }
 290         return output;
 291     }
 292
 293     private void storeErrorMessageToLog(RuntimeContext runtimeContext, String targetEntity, String targetServiceName, String additionalMessage) {
 294         LoggingUtils.logErrorMessage(runtimeContext.getResponseContext().getStatus() != null ?
 295                         String.valueOf(runtimeContext.getResponseContext().getStatus().getCode()) : "",
 296                 runtimeContext.getResponseContext().getStatus() != null ?
 297                         String.valueOf(runtimeContext.getResponseContext().getStatus().getMessage()) : "",
 298                 targetEntity,
 299                 targetServiceName,
 300                 additionalMessage,
 301                 this.getClass().getCanonicalName());
 302     }
 303
 304     private void createTransactionRecord(RuntimeContext runtimeContext) {
 305         TransactionRecord transactionRecord = new TransactionRecord();
 306         transactionRecord.setTimeStamp(runtimeContext.getResponseContext().getCommonHeader().getTimeStamp());
 307         transactionRecord.setRequestID(runtimeContext.getResponseContext().getCommonHeader().getRequestId());
 308         transactionRecord.setStartTime(runtimeContext.getTimeStart());
 309         transactionRecord.setEndTime(Instant.now());
 310         transactionRecord.setTargetID(runtimeContext.getVnfContext().getId());
 311         transactionRecord.setTargetType(runtimeContext.getVnfContext().getType());
 312         transactionRecord.setOperation(runtimeContext.getRequestContext().getAction().name());
 313         transactionRecord.setResultCode(String.valueOf(runtimeContext.getResponseContext().getStatus().getCode()));
 314         transactionRecord.setDescription(runtimeContext.getResponseContext().getStatus().getMessage());
 315         transactionRecorder.store(transactionRecord);
 316     }
 317
 318     private void handleRequest(RuntimeContext runtimeContext) {
 319
 320         switch (runtimeContext.getRequestContext().getAction()) {
 321             case Lock:
 322                 try {
 323                     lockWithTimeout(runtimeContext.getVnfContext().getId(), runtimeContext.getRequestContext().getCommonHeader().getRequestId());
 324                     fillStatus(runtimeContext,LCMCommandStatus.SUCCESS, null);
 325                 } catch (LockException e) {
 326                     Params params = new Params().addParam("errorMsg", e.getMessage());
 327                     fillStatus(runtimeContext, LCMCommandStatus.LOCKING_FAILURE, params);
 328                     storeErrorMessageToLog(runtimeContext,
 329                             LoggingConstants.TargetNames.APPC,
 330                             LoggingConstants.TargetNames.LOCK_MANAGER,
 331                             EELFResourceManager.format(Msg.VF_SERVER_BUSY, runtimeContext.getVnfContext().getId()));
 332                 }
 333
 334                 break;
 335
 336             case Unlock:
 337                 try {
 338                     releaseVNFLock(runtimeContext.getVnfContext().getId(), runtimeContext.getRequestContext().getCommonHeader().getRequestId());
 339                     fillStatus(runtimeContext,LCMCommandStatus.SUCCESS, null);
 340                 } catch (LockException e) {
 341                     //TODO add proper error code and message
 342                     //  logger.error(EELFResourceManager.format(Msg.VF_SERVER_BUSY, runtimeContext.getVnfContext().getId()));
 343                     Params params = new Params().addParam("errorMsg", e.getMessage());
 344                     fillStatus(runtimeContext, LCMCommandStatus.LOCKING_FAILURE, params);
 345                 }
 346                 break;
 347
 348             case CheckLock:
 349                 boolean isLocked = lockManager.isLocked(runtimeContext.getVnfContext().getId());
 350                 fillStatus(runtimeContext,LCMCommandStatus.SUCCESS, null);
 351                 runtimeContext.getResponseContext().addKeyValueToAdditionalContext("locked", String.valueOf(isLocked).toUpperCase());
 352                 break;
 353             default:
 354                 try {
 355                     boolean lockAcquired = acquireVNFLock(runtimeContext.getVnfContext().getId(), runtimeContext.getRequestContext().getCommonHeader().getRequestId(), 0);
 356                     runtimeContext.setIsLockAcquired(lockAcquired);
 357                     callWfOperation(runtimeContext);
 358                 } catch (LockException e) {
 359                     Params params = new Params().addParam("errorMsg", e.getMessage());
 360                     fillStatus(runtimeContext, LCMCommandStatus.LOCKING_FAILURE, params);
 361                 } finally {
 362                     if (runtimeContext.isLockAcquired()) {
 363                         final int statusCode = runtimeContext.getResponseContext().getStatus().getCode();
 364                         if (statusCode % 100 == 2 || statusCode % 100 == 3) {
 365                             try {
 366                                 releaseVNFLock(runtimeContext.getVnfContext().getId(), runtimeContext.getRequestContext().getCommonHeader().getRequestId());
 367                                 //TODO add logger call
 368                             } catch (LockException e) {
 369                                 //ignore
 370                             }
 371                         }
 372                     }
 373                 }
 374         }
 375
 376     }
 377
 378     private void callWfOperation(RuntimeContext runtimeContext) {
 379         int remainingTTL = calculateRemainingTTL(runtimeContext.getRequestContext().getCommonHeader());
 380         if (remainingTTL > 0) {
 381             if (logger.isDebugEnabled()) {
 382                 logger.debug("Calling command Executor with remaining TTL value: " + remainingTTL);
 383             }
 384
 385             RuntimeContext commandExecutorInput = cloneContext(runtimeContext);
 386
 387             try {
 388                 commandExecutor.executeCommand(commandExecutorInput);
 389                 if(logger.isTraceEnabled()) {
 390                     logger.trace("Command was added to queue successfully for vnfID = " + ObjectUtils.toString(runtimeContext.getRequestContext().getActionIdentifiers().getVnfId()));
 391                 }
 392                 fillStatus(runtimeContext, LCMCommandStatus.ACCEPTED, null);
 393                 if (isMetricEnabled) {
 394                     ((DispatchingFuntionMetric) metricRegistry.metric("DISPATCH_FUNCTION")).incrementAcceptedRequest();
 395                 }
 396             } catch (APPCException e) {
 397                 String errorMessage = e.getMessage() != null ? e.getMessage() : e.toString();
 398                 Params params = new Params().addParam("errorMsg", errorMessage);
 399                 fillStatus(runtimeContext, LCMCommandStatus.UNEXPECTED_ERROR, params);
 400             }
 401
 402         } else {
 403             fillStatus(runtimeContext, LCMCommandStatus.EXPIRED_REQUEST, null);
 404             storeErrorMessageToLog(runtimeContext,
 405                     LoggingConstants.TargetNames.APPC,
 406                     LoggingConstants.TargetNames.REQUEST_HANDLER,
 407                     EELFResourceManager.format(Msg.APPC_EXPIRED_REQUEST,
 408                             runtimeContext.getRequestContext().getCommonHeader().getOriginatorId(),
 409                             runtimeContext.getRequestContext().getActionIdentifiers().getVnfId(),
 410                             String.valueOf(runtimeContext.getRequestContext().getCommonHeader().getFlags().getTtl())));
 411         }
 412     }
 413
 414     private void fillStatus(RuntimeContext runtimeContext, LCMCommandStatus lcmCommandStatus, Params params) {
 415         runtimeContext.getResponseContext().setStatus(lcmCommandStatus.toStatus(params));
 416     }
 417
 418     /*
 419      * Workaround to clone context in order to prevent sharing of ResponseContext by two threads (one to set Accepted
 420      * status code and other - depending on DG status). Other properties should not be a problem
 421      */
 422     private RuntimeContext cloneContext(RuntimeContext runtimeContext) {
 423         RuntimeContext other = new RuntimeContext();
 424         other.setRequestContext(runtimeContext.getRequestContext());
 425         other.setResponseContext(new ResponseContext());
 426         other.getResponseContext().setStatus(new Status(0, null));
 427         other.getResponseContext().setCommonHeader(runtimeContext.getRequestContext().getCommonHeader());
 428         other.setVnfContext(runtimeContext.getVnfContext());
 429         other.setRpcName(runtimeContext.getRpcName());
 430         other.setTimeStart(runtimeContext.getTimeStart());
 431         other.setIsLockAcquired(runtimeContext.isLockAcquired());
 432         return other;
 433     }
 434
 435
 436     private void clearRequestLogProperties() {
 437         try {
 438             MDC.remove(MDC_KEY_REQUEST_ID);
 439             MDC.remove(MDC_SERVICE_INSTANCE_ID);
 440             MDC.remove(MDC_SERVICE_NAME);
 441             MDC.remove(LoggingConstants.MDCKeys.PARTNER_NAME);
 442             MDC.remove(LoggingConstants.MDCKeys.TARGET_VIRTUAL_ENTITY);
 443         } catch (Exception e) {
 444
 445         }
 446     }
 447
 448     private void removeRequestFromRegistry(CommonHeader commonHeader) {
 449         if (logger.isTraceEnabled())
 450             logger.trace("Entering to removeRequestFromRegistry with RequestHeader = " + ObjectUtils.toString(commonHeader));
 451         requestRegistry.removeRequest(
 452                 new UniqueRequestIdentifier(commonHeader.getOriginatorId(),
 453                         commonHeader.getRequestId(),
 454                         commonHeader.getSubRequestId()));
 455     }
 456
 457     private boolean acquireVNFLock(String vnfID, String requestId, long timeout) throws LockException {
 458         if (logger.isTraceEnabled())
 459             logger.trace("Entering to acquireVNFLock with vnfID = " + vnfID);
 460         boolean lockAcquired = lockManager.acquireLock(vnfID, requestId, timeout);
 461         if (lockAcquired) {
 462             logger.info("Lock acquired for vnfID = " + vnfID);
 463         } else {
 464             logger.info("vnfID = " + vnfID + " was already locked");
 465         }
 466         return lockAcquired;
 467     }
 468
 469     private void lockWithTimeout(String vnfId, String requestId) throws LockException {
 470         long timeout = configuration.getLongProperty(PROP_IDLE_TIMEOUT, Constants.DEFAULT_IDLE_TIMEOUT);
 471         acquireVNFLock(vnfId, requestId, timeout);
 472     }
 473
 474     private void resetLock(String vnfId, String requestId, boolean lockAcquired, boolean resetLockTimeout) {
 475         if (lockAcquired) {
 476             try {
 477                 releaseVNFLock(vnfId, requestId);
 478             } catch (LockException e) {
 479                 logger.error("Unlock VNF [" + vnfId + "] failed. Request id: [" + requestId + "]", e);
 480
 481
 482             }
 483         } else if (resetLockTimeout) {
 484             try {
 485                 // reset timeout to previous value
 486                 lockWithTimeout(vnfId, requestId);
 487             } catch (LockException e) {
 488                 logger.error("Reset lock idle timeout for VNF [" + vnfId + "] failed. Request id: [" + requestId + "]", e);
 489             }
 490         }
 491     }
 492
 493     private void releaseVNFLock(String vnfId, String transactionId) throws LockException {
 494         lockManager.releaseLock(vnfId, transactionId);
 495         logger.info("Lock released for vnfID = " + vnfId);
 496     }
 497
 498     private void setInitialLogProperties(RequestContext requestContext) {
 499
 500         try {
 501             MDC.put(MDC_KEY_REQUEST_ID, requestContext.getCommonHeader().getRequestId());
 502             if (requestContext.getActionIdentifiers().getServiceInstanceId() != null) {
 503                 MDC.put(MDC_SERVICE_INSTANCE_ID, requestContext.getActionIdentifiers().getServiceInstanceId());
 504             }
 505             MDC.put(LoggingConstants.MDCKeys.PARTNER_NAME, requestContext.getCommonHeader().getOriginatorId());
 506             MDC.put(MDC_INSTANCE_UUID, ""); // value should be created in the future
 507             try {
 508                 MDC.put(MDC_SERVER_FQDN, InetAddress.getLocalHost().getCanonicalHostName()); //Don't change it to a .getHostName() again please. It's wrong!
 509                 MDC.put(MDC_SERVER_IP_ADDRESS, InetAddress.getLocalHost().getHostAddress());
 510                 MDC.put(LoggingConstants.MDCKeys.SERVER_NAME, InetAddress.getLocalHost().getHostName());
 511                 MDC.put(MDC_SERVICE_NAME, requestContext.getAction().name());
 512                 MDC.put(LoggingConstants.MDCKeys.TARGET_VIRTUAL_ENTITY, requestContext.getActionIdentifiers().getVnfId());
 513
 514             } catch (Exception e) {
 515                 logger.debug(e.getMessage());
 516             }
 517         } catch (RuntimeException e) {
 518             //ignore
 519         }
 520     }
 521
 522
 523     private int calculateRemainingTTL(CommonHeader commonHeader) {
 524         if (logger.isTraceEnabled()) {
 525             logger.trace("Entering to calculateRemainingTTL with RequestHeader = " + ObjectUtils.toString(commonHeader));
 526         }
 527         long usedTimeInMillis = ChronoUnit.MILLIS.between(commonHeader.getTimeStamp(), Instant.now());
 528         logger.debug("usedTimeInMillis = " + usedTimeInMillis);
 529         int usedTimeInSeconds = Math.round(usedTimeInMillis / 1000);
 530         logger.debug("usedTimeInSeconds = " + usedTimeInSeconds);
 531         Integer inputTTL = this.getInputTTL(commonHeader);
 532         logger.debug("inputTTL = " + inputTTL);
 533         Integer remainingTTL = inputTTL - usedTimeInSeconds;
 534         logger.debug("Remaining TTL = " + remainingTTL);
 535         if (logger.isTraceEnabled())
 536             logger.trace("Exiting from calculateRemainingTTL with (remainingTTL = " + ObjectUtils.toString(remainingTTL) + ")");
 537         return remainingTTL;
 538     }
 539
 540     private Integer getInputTTL(CommonHeader header) {
 541         if (logger.isTraceEnabled())
 542             logger.trace("Entering in getInputTTL with RequestHeader = " + ObjectUtils.toString(header));
 543         if (!isValidTTL(String.valueOf(header.getFlags().getTtl()))) {
 544             String defaultTTLStr = configuration.getProperty("org.openecomp.appc.workflow.default.ttl", String.valueOf(Constants.DEFAULT_TTL));
 545             Integer defaultTTL = Integer.parseInt(defaultTTLStr);
 546             if (logger.isTraceEnabled())
 547                 logger.trace("Exiting from getInputTTL with (defaultTTL = " + ObjectUtils.toString(defaultTTL) + ")");
 548             return defaultTTL;
 549         }
 550         if (logger.isTraceEnabled())
 551             logger.trace("Exiting from getInputTTL with (inputTTL = " + ObjectUtils.toString(header.getFlags().getTtl()) + ")");
 552
 553         return header.getFlags().getTtl();
 554     }
 555
 556     private boolean isValidTTL(String ttl) {
 557         if (ttl == null || ttl.length() == 0) {
 558             if (logger.isTraceEnabled())
 559                 logger.trace("Exiting from getInputTTL with (result = false)");
 560             return false;
 561         }
 562         try {
 563             Integer i = Integer.parseInt(ttl);
 564             return (i > 0);
 565         } catch (NumberFormatException e) {
 566             if (logger.isTraceEnabled())
 567                 logger.trace("Exiting from getInputTTL with (result = false)");
 568             return false;
 569         }
 570     }
 571
 572     private Boolean isLoggingEnabled() {
 573         String defaultFlagStr = configuration.getProperty("org.openecomp.appc.localTransactionRecorder.enable", String.valueOf(Constants.DEFAULT_LOGGING_FLAG));
 574         Boolean defaultFlag = Boolean.parseBoolean(defaultFlagStr);
 575         return defaultFlag;
 576     }
 577
 578     private static RequestHandlerOutput buildRequestHandlerOutput(LCMCommandStatus response, Params params) {
 579         RequestHandlerOutput output = new RequestHandlerOutput();
 580         ResponseContext responseContext = new ResponseContext();
 581         responseContext.setStatus(response.toStatus(params));
 582         output.setResponseContext(responseContext);
 583         return output;
 584     }
 585
 586     /**
 587      * This method perform operations required before execution of workflow starts. It retrieves next state for current operation from Lifecycle manager and update it in AAI.
 588      *
 589      * @return true in case AAI updates are successful. false for any error or exception.
 590      */
 591     @Override
 592     public void onRequestExecutionStart(String vnfId, boolean readOnlyActivity, String requestIdentifierString, boolean forceFlag) throws UnstableVNFException {
 593         if (logger.isTraceEnabled()) {
 594             logger.trace("Entering to onRequestExecutionStart with vnfId = " + vnfId + "and requestIdentifierString = " + requestIdentifierString);
 595         }
 596
 597         if(!readOnlyActivity || !forceFlag || workingStateManager.isVNFStable(vnfId)) {
 598             boolean updated = false;
 599             try {
 600                 updated = workingStateManager.setWorkingState(vnfId, VNFWorkingState.UNSTABLE, requestIdentifierString, forceFlag);
 601             }  catch (Exception e) {
 602                 logger.error("Error updating working state for vnf " + vnfId + e);
 603                 throw new RuntimeException(e);
 604             }
 605             if (!updated) {
 606                 throw new UnstableVNFException("VNF is not stable for vnfID = " + vnfId);
 607             }
 608         }
 609
 610         if (logger.isTraceEnabled())
 611             logger.trace("Exiting from onRequestExecutionStart ");
 612     }
 613
 614     /**
 615      * This method perform following operations required after execution of workflow.
 616      * It posts asynchronous response to message bus (DMaaP).
 617      * Unlock VNF Id
 618      * Removes request from request registry.
 619      * Generate audit logs.
 620      * Adds transaction record to database id if transaction logging is enabled.
 621      *
 622      * @param isAAIUpdated boolean flag which indicate AAI upodate status after request completion.
 623      */
 624     @Override
 625     public void onRequestExecutionEnd(RuntimeContext runtimeContext, boolean isAAIUpdated) {
 626         if (logger.isTraceEnabled()) {
 627             logger.trace("Entering to onRequestExecutionEnd with runtimeContext = " + ObjectUtils.toString(runtimeContext));
 628         }
 629
 630         postMessageToDMaaP(runtimeContext.getRequestContext().getAction(), runtimeContext.getRpcName(), runtimeContext.getResponseContext());
 631         requestRegistry.removeRequest(
 632                 new UniqueRequestIdentifier(runtimeContext.getResponseContext().getCommonHeader().getOriginatorId(),
 633                         runtimeContext.getResponseContext().getCommonHeader().getRequestId(),
 634                         runtimeContext.getResponseContext().getCommonHeader().getSubRequestId()));
 635         resetLock(runtimeContext.getVnfContext().getId(), runtimeContext.getResponseContext().getCommonHeader().getRequestId(), runtimeContext.isLockAcquired(), true);
 636         Status status = runtimeContext.getResponseContext().getStatus();
 637
 638         VNFWorkingState workingState;
 639         if (status.getCode() == LCMCommandStatus.SUCCESS.getResponseCode() || isReadOnlyAction(runtimeContext.getRequestContext().getAction())) {
 640             workingState = VNFWorkingState.STABLE;
 641         } else {
 642             workingState = VNFWorkingState.UNKNOWN;
 643         }
 644
 645         UniqueRequestIdentifier requestIdentifier = new UniqueRequestIdentifier(runtimeContext.getResponseContext().getCommonHeader().getOriginatorId(),
 646                 runtimeContext.getResponseContext().getCommonHeader().getRequestId(),
 647                 runtimeContext.getResponseContext().getCommonHeader().getSubRequestId());
 648
 649         String requestIdentifierString = requestIdentifier.toIdentifierString();
 650         workingStateManager.setWorkingState(runtimeContext.getVnfContext().getId(), workingState, requestIdentifierString, false);
 651
 652
 653         storeAuditLogRecord(runtimeContext);
 654
 655         if (isLoggingEnabled()) {
 656             createTransactionRecord(runtimeContext);
 657         }
 658     }
 659
 660     private void storeAuditLogRecord(RuntimeContext runtimeContext) {
 661         LoggingUtils.logAuditMessage(runtimeContext.getTimeStart(),
 662                 Instant.now(),
 663                 String.valueOf(runtimeContext.getResponseContext().getStatus().getCode()),
 664                 runtimeContext.getResponseContext().getStatus().getMessage(),
 665                 this.getClass().getCanonicalName());
 666     }
 667
 668     private void storeMetricLogRecord(RuntimeContext runtimeContext) {
 669         LoggingUtils.logMetricsMessage(runtimeContext.getTimeStart(),
 670                 Instant.now(),
 671                 LoggingConstants.TargetNames.APPC,
 672                 runtimeContext.getRequestContext().getAction().name(),
 673                 runtimeContext.getResponseContext().getStatus().getCode() == LCMCommandStatus.ACCEPTED.getResponseCode() ? LoggingConstants.StatusCodes.COMPLETE : LoggingConstants.StatusCodes.ERROR,
 674                 String.valueOf(runtimeContext.getResponseContext().getStatus().getCode()),
 675                 runtimeContext.getResponseContext().getStatus().getMessage(),
 676                 this.getClass().getCanonicalName());
 677     }
 678
 679     private boolean isReadOnlyAction(VNFOperation action) {
 680         return VNFOperation.Sync == action
 681                 || VNFOperation.Audit == action;
 682     }
 683
 684
 685     //returns null if asyncResponse was not modified otherwise reutrns the updated asyncResponse
 686     private void postMessageToDMaaP(VNFOperation operation, String rpcName, ResponseContext responseContext/*, boolean isTTLEnd, boolean aaiUpdateSuccess*/) {
 687         if (logger.isTraceEnabled()) {
 688             logger.trace("Entering to postMessageToDMaaP with AsyncResponse = " + ObjectUtils.toString(responseContext));
 689         }
 690         boolean callbackResponse = messageAdapter.post(operation, rpcName, responseContext);
 691         if (!callbackResponse) {
 692             logger.error("DMaaP posting status: " + callbackResponse, "dmaapMessage: " + responseContext);
 693         }
 694         if (logger.isTraceEnabled())
 695             logger.trace("Exiting from postMessageToDMaaP with (callbackResponse = " + ObjectUtils.toString(callbackResponse) + ")");
 696     }
 697
 698     /**
 699      * This method perform following operations required if TTL ends when request still waiting in execution queue .
 700      * It posts asynchronous response to message bus (DMaaP).
 701      * Unlock VNF Id
 702      * Removes request from request registry.
 703      *
 704      * @param runtimeContext AsyncResponse object which contains VNF Id         , timestamp , apiVersion, responseId, executionSuccess, payload, isExpired, action, startTime, vnfType, originatorId, subResponseId;
 705      * @param updateAAI      boolean flag which indicate AAI upodate status after request completion.
 706      */
 707     @Override
 708     public void onRequestTTLEnd(RuntimeContext runtimeContext, boolean updateAAI) {
 709         if (logger.isTraceEnabled()) {
 710             logger.trace("Entering to onRequestTTLEnd with " +
 711                     "AsyncResponse = " + ObjectUtils.toString(runtimeContext) +
 712                     ", updateAAI = " + ObjectUtils.toString(updateAAI));
 713         }
 714         logger.error(LCMCommandStatus.EXPIRED_REQUEST_FAILURE.getResponseMessage());
 715         fillStatus(runtimeContext, LCMCommandStatus.EXPIRED_REQUEST_FAILURE, null);
 716         postMessageToDMaaP(runtimeContext.getRequestContext().getAction(), runtimeContext.getRpcName(), runtimeContext.getResponseContext());
 717         resetLock(runtimeContext.getVnfContext().getId(), runtimeContext.getResponseContext().getCommonHeader().getRequestId(), runtimeContext.isLockAcquired(), true);
 718         requestRegistry.removeRequest(
 719                 new UniqueRequestIdentifier(runtimeContext.getResponseContext().getCommonHeader().getOriginatorId(),
 720                         runtimeContext.getResponseContext().getCommonHeader().getRequestId(),
 721                         runtimeContext.getResponseContext().getCommonHeader().getSubRequestId()));
 722     }
 723
 724     private SvcLogicContext getVnfdata(String vnf_id, String prefix, SvcLogicContext ctx) throws VNFNotFoundException {
 725         String key = "vnf-id = '" + vnf_id + "'";
 726         if (logger.isTraceEnabled()) {
 727             logger.trace("Entering to getVnfdata with " +
 728                     "vnfId = " + vnf_id +
 729                     ", prefix = " + prefix +
 730                     ", SvcLogicContex = " + ObjectUtils.toString(ctx));
 731         }
 732         try {
 733             QueryStatus response = aaiService.query("generic-vnf", false, null, key, prefix, null, ctx);
 734             if (QueryStatus.NOT_FOUND.equals(response)) {
 735                 throw new VNFNotFoundException("VNF not found for vnf_id = " + vnf_id);
 736             } else if (QueryStatus.FAILURE.equals(response)) {
 737                 throw new RuntimeException("Error Querying AAI with vnfID = " + vnf_id);
 738             }
 739             logger.info("AAIResponse: " + response.toString());
 740         } catch (SvcLogicException e) {
 741             logger.error("Error in getVnfdata " + e);
 742             throw new RuntimeException(e);
 743         }
 744         if (logger.isTraceEnabled()) {
 745             logger.trace("Exiting from getVnfdata with (SvcLogicContext = " + ObjectUtils.toString(ctx) + ")");
 746         }
 747         return ctx;
 748     }
 749
 750     private boolean postVnfdata(String vnf_id, String status, String prefix, SvcLogicContext ctx) throws VNFNotFoundException {
 751         if (logger.isTraceEnabled()) {
 752             logger.trace("Entering to postVnfdata with " +
 753                     "vnfId = " + vnf_id +
 754                     ", status = " + status +
 755                     ", prefix = " + prefix +
 756                     ", SvcLogicContext = " + ObjectUtils.toString(ctx));
 757         }
 758         String key = "vnf-id = '" + vnf_id + "'";
 759         Map<String, String> data = new HashMap<>();
 760         data.put("orchestration-status", status);
 761         try {
 762             QueryStatus response = aaiService.update("generic-vnf", key, data, prefix, ctx);
 763             if (QueryStatus.NOT_FOUND.equals(response)) {
 764                 throw new VNFNotFoundException("VNF not found for vnf_id = " + vnf_id);
 765             }
 766             logger.info("AAIResponse: " + response.toString());
 767             if (response.toString().equals("SUCCESS")) {
 768                 if (logger.isTraceEnabled()) {
 769                     logger.trace("Exiting from postVnfdata with (Result = " + ObjectUtils.toString(true) + ")");
 770                 }
 771                 return true;
 772             }
 773
 774         } catch (SvcLogicException e) {
 775             logger.error("Error in postVnfdata " + e);
 776             throw new RuntimeException(e);
 777         }
 778         if (logger.isTraceEnabled()) {
 779             logger.trace("Exiting from postVnfdata with (Result = " + ObjectUtils.toString(false) + ")");
 780         }
 781         return false;
 782     }
 783
 784     private void initMetric() {
 785         if (logger.isDebugEnabled())
 786             logger.debug("Metric getting initialized");
 787         MetricService metricService = getMetricservice();
 788         metricRegistry = metricService.createRegistry("APPC");
 789         DispatchingFuntionMetric dispatchingFuntionMetric = metricRegistry.metricBuilderFactory().
 790                 dispatchingFunctionCounterBuilder().
 791                 withName("DISPATCH_FUNCTION").withType(MetricType.COUNTER).
 792                 withAcceptRequestValue(0)
 793                 .withRejectRequestValue(0)
 794                 .build();
 795         if (metricRegistry.register(dispatchingFuntionMetric)) {
 796             Metric[] metrics = new Metric[]{dispatchingFuntionMetric};
 797             LogPublisher logPublisher = new LogPublisher(metricRegistry, metrics);
 798             LogPublisher[] logPublishers = new LogPublisher[1];
 799             logPublishers[0] = logPublisher;
 800             PublishingPolicy manuallyScheduledPublishingPolicy = metricRegistry.policyBuilderFactory().
 801                     scheduledPolicyBuilder().withPublishers(logPublishers).
 802                     withMetrics(metrics).
 803                     build();
 804             if (logger.isDebugEnabled())
 805                 logger.debug("Policy getting initialized");
 806             manuallyScheduledPublishingPolicy.init();
 807             if (logger.isDebugEnabled())
 808                 logger.debug("Metric initialized");
 809         }
 810     }
 811
 812
 813     private MetricService getMetricservice() {
 814         BundleContext bctx = FrameworkUtil.getBundle(MetricService.class).getBundleContext();
 815         ServiceReference sref = bctx.getServiceReference(MetricService.class.getName());
 816         if (sref != null) {
 817             logger.info("Metric Service from bundlecontext");
 818             return (MetricService) bctx.getService(sref);
 819         } else {
 820             logger.info("Metric Service error from bundlecontext");
 821             logger.warn("Cannot find service reference for org.openecomp.appc.metricservice.MetricService");
 822             return null;
 823         }
 824     }
 825
 826     /**
 827      * This method returns the count of in progress requests
 828      * * @return in progress requests count
 829      */
 830     @Override
 831     public int getInprogressRequestCount() {
 832         if (logger.isTraceEnabled()) {
 833             logger.trace("Entering to getInprogressRequestCount");
 834         }
 835         return requestRegistry.getRegisteredRequestCount();
 836     }
 837 }