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

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