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

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