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

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