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

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