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

/*-
 * ============LICENSE_START=======================================================
 * openECOMP : APP-C
 * ================================================================================
 * Copyright (C) 2017 AT&T Intellectual Property. All rights
 * 						reserved.
 * ================================================================================
 * Licensed under the Apache License, Version 2.0 (the "License");
 * you may not use this file except in compliance with the License.
 * You may obtain a copy of the License at
 * 
 *      http://www.apache.org/licenses/LICENSE-2.0
 * 
 * Unless required by applicable law or agreed to in writing, software
 * distributed under the License is distributed on an "AS IS" BASIS,
 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
 * See the License for the specific language governing permissions and
 * limitations under the License.
 * ============LICENSE_END=========================================================
 */

package org.openecomp.appc.requesthandler.impl;

import org.apache.commons.lang.ObjectUtils;
import org.openecomp.appc.common.constant.Constants;
import org.openecomp.appc.configuration.Configuration;
import org.openecomp.appc.configuration.ConfigurationFactory;
import org.openecomp.appc.domainmodel.lcm.*;
import org.openecomp.appc.exceptions.APPCException;
import org.openecomp.appc.executor.CommandExecutor;
import org.openecomp.appc.executor.UnstableVNFException;
import org.openecomp.appc.executor.objects.CommandExecutorInput;
import org.openecomp.appc.executor.objects.LCMCommandStatus;
import org.openecomp.appc.executor.objects.Params;
import org.openecomp.appc.executor.objects.UniqueRequestIdentifier;
import org.openecomp.appc.i18n.Msg;
import org.openecomp.appc.lifecyclemanager.objects.LifecycleException;
import org.openecomp.appc.lifecyclemanager.objects.NoTransitionDefinedException;
import org.openecomp.appc.lockmanager.api.LockException;
import org.openecomp.appc.lockmanager.api.LockManager;
import org.openecomp.appc.logging.LoggingConstants;
import org.openecomp.appc.logging.LoggingUtils;
import org.openecomp.appc.messageadapter.MessageAdapter;
import org.openecomp.appc.messageadapter.impl.MessageAdapterDmaapImpl;
import org.openecomp.appc.metricservice.MetricRegistry;
import org.openecomp.appc.metricservice.MetricService;
import org.openecomp.appc.metricservice.metric.DispatchingFuntionMetric;
import org.openecomp.appc.metricservice.metric.Metric;
import org.openecomp.appc.metricservice.metric.MetricType;
import org.openecomp.appc.metricservice.policy.PublishingPolicy;
import org.openecomp.appc.metricservice.publisher.LogPublisher;
import org.openecomp.appc.requesthandler.RequestHandler;
import org.openecomp.appc.requesthandler.exceptions.*;
import org.openecomp.appc.requesthandler.helper.RequestRegistry;
import org.openecomp.appc.requesthandler.helper.RequestValidator;
import org.openecomp.appc.requesthandler.objects.RequestHandlerInput;
import org.openecomp.appc.requesthandler.objects.RequestHandlerOutput;
import org.openecomp.appc.transactionrecorder.TransactionRecorder;
import org.openecomp.appc.transactionrecorder.objects.TransactionRecord;
import org.openecomp.appc.workingstatemanager.WorkingStateManager;
import org.openecomp.appc.workingstatemanager.objects.VNFWorkingState;
import com.att.eelf.configuration.EELFLogger;
import com.att.eelf.configuration.EELFManager;
import com.att.eelf.i18n.EELFResourceManager;
import org.openecomp.sdnc.sli.SvcLogicContext;
import org.openecomp.sdnc.sli.SvcLogicException;
import org.openecomp.sdnc.sli.SvcLogicResource.QueryStatus;
import org.openecomp.sdnc.sli.aai.AAIService;
import org.osgi.framework.BundleContext;
import org.osgi.framework.FrameworkUtil;
import org.osgi.framework.ServiceReference;
import org.slf4j.MDC;

import static com.att.eelf.configuration.Configuration.*;

import java.net.InetAddress;
import java.util.Date;
import java.util.HashMap;
import java.util.Map;
import java.util.Properties;

/**
 * This class provides application logic for the Request/Response Handler Component.
 *
 */
public class RequestHandlerImpl implements RequestHandler {

    /**
     * APP-C VNF lock idle timeout in milliseconds. Applied only when locking VNF using northbound API "lock"
     */
    private static final String PROP_IDLE_TIMEOUT = "org.openecomp.appc.lock.idleTimeout";

    private CommandExecutor commandExecutor;

    private TransactionRecorder transactionRecorder;
    private MessageAdapter messageAdapter;
    private RequestValidator requestValidator;
    private static MetricRegistry metricRegistry;
    private boolean isMetricEnabled = false;
    private RequestRegistry requestRegistry;
    private LockManager lockManager;
    private WorkingStateManager workingStateManager;
    private AAIService aaiService;

    private static final EELFLogger logger = EELFManager.getInstance().getLogger(RequestHandlerImpl.class);

    public void setAaiService(AAIService aaiService) {
        this.aaiService = aaiService;
    }

    public void setTransactionRecorder(TransactionRecorder transactionRecorder) {
        this.transactionRecorder = transactionRecorder;
    }

    public void setLockManager(LockManager lockManager) {
        this.lockManager = lockManager;
    }

    public void setRequestValidator(RequestValidator requestValidator) {
        this.requestValidator = requestValidator;
    }

    public void setMessageAdapter(MessageAdapter messageAdapter) {
        this.messageAdapter = messageAdapter;
    }

    private static final Configuration configuration = ConfigurationFactory.getConfiguration();

    public void setWorkingStateManager(WorkingStateManager workingStateManager) {
        this.workingStateManager = workingStateManager;
    }

    public RequestHandlerImpl() {
        requestRegistry = new RequestRegistry();
        messageAdapter = new MessageAdapterDmaapImpl();
        messageAdapter.init();
        Properties properties = configuration.getProperties();
        if (properties != null && properties.getProperty("metric.enabled") != null) {
            isMetricEnabled = Boolean.valueOf(properties.getProperty("metric.enabled"));
        }
        if (isMetricEnabled) {
            initMetric();
        }
    }

    public void setCommandExecutor(CommandExecutor commandExecutor) {
        this.commandExecutor = commandExecutor;
    }


    /**
     * It receives requests from the north-bound REST API (Communication) Layer and
     * performs following validations.
     * 1. VNF exists in A&AI for the given targetID (VnfID)
     * 2. For the current VNF  Orchestration Status, the command can be executed
     * 3. For the given VNF type and Operation, there exists work-flow definition in the APPC database
     * If any of the validation fails, it returns appropriate response
     *
     * @param input RequestHandlerInput object which contains request header and  other request parameters like command , target Id , payload etc.
     * @return response for request as enum with Return code and message.
     */
    @Override
    public RequestHandlerOutput handleRequest(RequestHandlerInput input) {
        if (logger.isTraceEnabled())
            logger.trace("Entering to handleRequest with RequestHandlerInput = " + ObjectUtils.toString(input) + ")");
        Params params = null;
        String vnfId = null, vnfType = null, errorMessage = null;
        Date startTime = new Date(System.currentTimeMillis());
        RequestHandlerOutput output = null;
        setInitialLogProperties(input.getRequestContext());

        RuntimeContext runtimeContext = new RuntimeContext();
        runtimeContext.setRequestContext(input.getRequestContext());
        runtimeContext.setTimeStart(startTime);
        runtimeContext.setRpcName(input.getRpcName());

        final ResponseContext responseContext = new ResponseContext();
        responseContext.setStatus(new Status());
        responseContext.setAdditionalContext(new HashMap<String, String>(4));
        responseContext.setCommonHeader(input.getRequestContext().getCommonHeader());
        runtimeContext.setResponseContext(responseContext);
        runtimeContext.getResponseContext().setStatus(new Status());

        vnfId = runtimeContext.getRequestContext().getActionIdentifiers().getVnfId();

        try {

            requestValidator.validateRequest(runtimeContext);

            handleRequest(runtimeContext);

            final int statusCode = runtimeContext.getResponseContext().getStatus().getCode();
            if (statusCode % 100 == 2 || statusCode % 100 == 3) {
                createTransactionRecord(runtimeContext);
            }
            output = new RequestHandlerOutput();
            output.setResponseContext(runtimeContext.getResponseContext());

        } catch (VNFNotFoundException e) {
            errorMessage = e.getMessage();
            String logMessage = EELFResourceManager.format(Msg.APPC_NO_RESOURCE_FOUND, vnfId);
            storeErrorMessageToLog(runtimeContext, LoggingConstants.TargetNames.AAI, "", logMessage);
            params = new Params().addParam("vnfId", vnfId);
            output = buildRequestHandlerOutput(LCMCommandStatus.VNF_NOT_FOUND, params);
        } catch (NoTransitionDefinedException e) {
            errorMessage = e.getMessage();
            String logMessage = EELFResourceManager.format(Msg.VF_UNDEFINED_STATE, input.getRequestContext().getCommonHeader().getOriginatorId(), input.getRequestContext().getAction().name());
            params = new Params().addParam("actionName", input.getRequestContext().getAction()).addParam("currentState", e.currentState);
            output = buildRequestHandlerOutput(LCMCommandStatus.NO_TRANSITION_DEFINE, params);
            storeErrorMessageToLog(runtimeContext,
                    LoggingConstants.TargetNames.APPC,
                    LoggingConstants.TargetNames.STATE_MACHINE,
                    logMessage);
        } catch (LifecycleException e) {
            errorMessage = e.getMessage();
            params = new Params().addParam("actionName", input.getRequestContext().getAction()).addParam("currentState", e.currentState);
            output = buildRequestHandlerOutput(LCMCommandStatus.ACTION_NOT_SUPPORTED, params);
        } catch (UnstableVNFException e) {
            errorMessage = e.getMessage();
            params = new Params().addParam("vnfId", vnfId);
            output = buildRequestHandlerOutput(LCMCommandStatus.UNSTABLE_VNF, params);
        } catch (WorkflowNotFoundException e) {
            errorMessage = e.getMessage();
            String vnfTypeVersion = e.vnfTypeVersion;
            params = new Params().addParam("actionName", input.getRequestContext().getAction()).addParam("vnfTypeVersion", vnfTypeVersion);
            output = buildRequestHandlerOutput(LCMCommandStatus.WORKFLOW_NOT_FOUND, params);
        } catch (DGWorkflowNotFoundException e) {
            errorMessage = e.getMessage();
            String logMessage = EELFResourceManager.format(Msg.APPC_WORKFLOW_NOT_FOUND, vnfType, input.getRequestContext().getAction().name());
            storeErrorMessageToLog(runtimeContext,
                    LoggingConstants.TargetNames.APPC,
                    LoggingConstants.TargetNames.WORKFLOW_MANAGER,
                    logMessage);
            params = new Params().addParam("actionName", input.getRequestContext().getAction().name())
                    .addParam("dgModule", e.workflowModule).addParam("dgName", e.workflowName).addParam("dgVersion", e.workflowVersion);
            output = buildRequestHandlerOutput(LCMCommandStatus.DG_WORKFLOW_NOT_FOUND, params);
        } catch (RequestExpiredException e) {
            errorMessage = e.getMessage();
            params = new Params().addParam("actionName", input.getRequestContext().getAction().name());
            output = buildRequestHandlerOutput(LCMCommandStatus.EXPIRED_REQUEST, params);
        } catch (InvalidInputException e) {
            errorMessage = e.getMessage() != null ? e.getMessage() : e.toString();
            params = new Params().addParam("errorMsg", errorMessage);
            output = buildRequestHandlerOutput(LCMCommandStatus.INVALID_INPUT_PARAMETER, params);
        } catch (DuplicateRequestException e) {
            errorMessage = e.getMessage();
            output = buildRequestHandlerOutput(LCMCommandStatus.DUPLICATE_REQUEST, null);
        } catch (Exception e) {
            storeErrorMessageToLog(runtimeContext, "", "", "Exception = " + e.getMessage());
            errorMessage = e.getMessage() != null ? e.getMessage() : e.toString();
            params = new Params().addParam("errorMsg", errorMessage);
            output = buildRequestHandlerOutput(LCMCommandStatus.UNEXPECTED_ERROR, params);
        } finally {
            try {
                if (logger.isDebugEnabled() && errorMessage != null)
                    logger.debug("error occurred in handleRequest " + errorMessage);
                logger.debug("output.getResponse().getResponseCode().equals(LCMCommandStatus.ACCEPTED.getResponseCode():  " + (output.getResponseContext().getStatus().getCode() == LCMCommandStatus.ACCEPTED.getResponseCode()));
                logger.debug("output.getResponse().getResponseCode().equals(LCMCommandStatus.SUCCESS.getResponseCode():  " + (output.getResponseContext().getStatus().getCode() == LCMCommandStatus.SUCCESS.getResponseCode()));

                runtimeContext.setResponseContext(output.getResponseContext());
                if ((null == output) || !(output.getResponseContext().getStatus().getCode() == LCMCommandStatus.ACCEPTED.getResponseCode())) {
                    if (isMetricEnabled) {
                        ((DispatchingFuntionMetric) metricRegistry.metric("DISPATCH_FUNCTION")).incrementRejectedRequest();
                    }
                    removeRequestFromRegistry(input.getRequestContext().getCommonHeader());
                }
            } finally {
                storeAuditLogRecord(runtimeContext);
                storeMetricLogRecord(runtimeContext);
                clearRequestLogProperties();
            }
        }
        if (logger.isTraceEnabled()) {
            logger.trace("Exiting from handleRequest with (RequestHandlerOutput = " + ObjectUtils.toString(output.getResponseContext()) + ")");
        }
        return output;
    }

    private void storeErrorMessageToLog(RuntimeContext runtimeContext, String targetEntity, String targetServiceName, String additionalMessage) {
        LoggingUtils.logErrorMessage(runtimeContext.getResponseContext().getStatus() != null ?
                        String.valueOf(runtimeContext.getResponseContext().getStatus().getCode()) : "",
                runtimeContext.getResponseContext().getStatus() != null ?
                        String.valueOf(runtimeContext.getResponseContext().getStatus().getMessage()) : "",
                targetEntity,
                targetServiceName,
                additionalMessage,
                this.getClass().getCanonicalName());
    }

    private void createTransactionRecord(RuntimeContext runtimeContext) {
        TransactionRecord transactionRecord = new TransactionRecord();
        transactionRecord.setTimeStamp(runtimeContext.getResponseContext().getCommonHeader().getTimeStamp());
        transactionRecord.setRequestID(runtimeContext.getResponseContext().getCommonHeader().getRequestId());
        transactionRecord.setStartTime(runtimeContext.getTimeStart());
        transactionRecord.setEndTime(new Date(System.currentTimeMillis()));
        transactionRecord.setTargetID(runtimeContext.getVnfContext().getId());
        transactionRecord.setTargetType(runtimeContext.getVnfContext().getType());
        transactionRecord.setOperation(runtimeContext.getRequestContext().getAction().name());
        transactionRecord.setResultCode(String.valueOf(runtimeContext.getResponseContext().getStatus().getCode()));
        transactionRecord.setDescription(runtimeContext.getResponseContext().getStatus().getMessage());
        transactionRecorder.store(transactionRecord);
    }

    private void handleRequest(RuntimeContext runtimeContext) {

        switch (runtimeContext.getRequestContext().getAction()) {
            case Lock:
                try {
                    lockWithTimeout(runtimeContext.getVnfContext().getId(), runtimeContext.getRequestContext().getCommonHeader().getRequestId());
                    fillStatus(runtimeContext,LCMCommandStatus.SUCCESS, null);
                } catch (LockException e) {
                    Params params = new Params().addParam("errorMsg", e.getMessage());
                    fillStatus(runtimeContext, LCMCommandStatus.LOCKING_FAILURE, params);
                    storeErrorMessageToLog(runtimeContext,
                            LoggingConstants.TargetNames.APPC,
                            LoggingConstants.TargetNames.LOCK_MANAGER,
                            EELFResourceManager.format(Msg.VF_SERVER_BUSY, runtimeContext.getVnfContext().getId()));
                }

                break;

            case Unlock:
                try {
                    releaseVNFLock(runtimeContext.getVnfContext().getId(), runtimeContext.getRequestContext().getCommonHeader().getRequestId());
                    fillStatus(runtimeContext,LCMCommandStatus.SUCCESS, null);
                } catch (LockException e) {
                    //TODO add proper error code and message
                    //  logger.error(EELFResourceManager.format(Msg.VF_SERVER_BUSY, runtimeContext.getVnfContext().getId()));
                    Params params = new Params().addParam("errorMsg", e.getMessage());
                    fillStatus(runtimeContext, LCMCommandStatus.LOCKING_FAILURE, params);
                }
                break;

            case CheckLock:
                boolean isLocked = lockManager.isLocked(runtimeContext.getVnfContext().getId());
                fillStatus(runtimeContext,LCMCommandStatus.SUCCESS, null);
                runtimeContext.getResponseContext().addKeyValueToAdditionalContext("locked", String.valueOf(isLocked).toUpperCase());
                break;
            default:
                try {
                    boolean lockAcquired = acquireVNFLock(runtimeContext.getVnfContext().getId(), runtimeContext.getRequestContext().getCommonHeader().getRequestId(), 0);
                    runtimeContext.setIsLockAcquired(lockAcquired);
                    callWfOperation(runtimeContext);
                } catch (LockException e) {
                    Params params = new Params().addParam("errorMsg", e.getMessage());
                    fillStatus(runtimeContext, LCMCommandStatus.LOCKING_FAILURE, params);
                } finally {
                    if (runtimeContext.isLockAcquired()) {
                        final int statusCode = runtimeContext.getResponseContext().getStatus().getCode();
                        if (statusCode % 100 == 2 || statusCode % 100 == 3) {
                            try {
                                releaseVNFLock(runtimeContext.getVnfContext().getId(), runtimeContext.getRequestContext().getCommonHeader().getRequestId());
                                //TODO add logger call
                            } catch (LockException e) {
                                //ignore
                            }
                        }
                    }
                }
        }

    }

    private void callWfOperation(RuntimeContext runtimeContext) {
        int remainingTTL = calculateRemainingTTL(runtimeContext.getRequestContext().getCommonHeader());
        if (remainingTTL > 0) {
            if (logger.isDebugEnabled()) {
                logger.debug("Calling command Executor with remaining TTL value: " + remainingTTL);
            }

            RuntimeContext clonedContext = cloneContext(runtimeContext);

            CommandExecutorInput commandExecutorInput = new CommandExecutorInput();
            commandExecutorInput.setRuntimeContext(clonedContext);
            commandExecutorInput.setTtl(remainingTTL);

            try {
                commandExecutor.executeCommand(commandExecutorInput);
                if(logger.isTraceEnabled()) {
                    logger.trace("Command was added to queue successfully for vnfID = " + ObjectUtils.toString(runtimeContext.getRequestContext().getActionIdentifiers().getVnfId()));
                }
                fillStatus(runtimeContext, LCMCommandStatus.ACCEPTED, null);
                if (isMetricEnabled) {
                    ((DispatchingFuntionMetric) metricRegistry.metric("DISPATCH_FUNCTION")).incrementAcceptedRequest();
                }
            } catch (APPCException e) {
                String errorMessage = e.getMessage() != null ? e.getMessage() : e.toString();
                Params params = new Params().addParam("errorMsg", errorMessage);
                fillStatus(runtimeContext, LCMCommandStatus.UNEXPECTED_ERROR, params);
            }

        } else {
            fillStatus(runtimeContext, LCMCommandStatus.EXPIRED_REQUEST, null);
            storeErrorMessageToLog(runtimeContext,
                    LoggingConstants.TargetNames.APPC,
                    LoggingConstants.TargetNames.REQUEST_HANDLER,
                    EELFResourceManager.format(Msg.APPC_EXPIRED_REQUEST,
                            runtimeContext.getRequestContext().getCommonHeader().getOriginatorId(),
                            runtimeContext.getRequestContext().getActionIdentifiers().getVnfId(),
                            String.valueOf(runtimeContext.getRequestContext().getCommonHeader().getFlags().getTtl())));
        }
    }

    private void fillStatus(RuntimeContext runtimeContext, LCMCommandStatus lcmCommandStatus, Params params) {
        runtimeContext.getResponseContext().getStatus().setCode(lcmCommandStatus.getResponseCode());
        runtimeContext.getResponseContext().getStatus().setMessage(lcmCommandStatus.getFormattedMessage(params));
    }

    /*
     * Workaround to clone context in order to prevent sharing of ResponseContext by two threads (one to set Accepted
     * status code and other - depending on DG status). Other properties should not be a problem
     */
    private RuntimeContext cloneContext(RuntimeContext runtimeContext) {
        RuntimeContext other = new RuntimeContext();
        other.setRequestContext(runtimeContext.getRequestContext());
        other.setResponseContext(new ResponseContext());
        other.getResponseContext().setStatus(new Status());
        other.getResponseContext().setCommonHeader(runtimeContext.getRequestContext().getCommonHeader());
        other.setVnfContext(runtimeContext.getVnfContext());
        other.setRpcName(runtimeContext.getRpcName());
        other.setTimeStart(runtimeContext.getTimeStart());
        other.setIsLockAcquired(runtimeContext.isLockAcquired());
        return other;
    }


    private void clearRequestLogProperties() {
        try {
            MDC.remove(MDC_KEY_REQUEST_ID);
            MDC.remove(MDC_SERVICE_INSTANCE_ID);
            MDC.remove(MDC_SERVICE_NAME);
            MDC.remove(LoggingConstants.MDCKeys.PARTNER_NAME);
            MDC.remove(LoggingConstants.MDCKeys.TARGET_VIRTUAL_ENTITY);
        } catch (Exception e) {

        }
    }

    private void removeRequestFromRegistry(CommonHeader commonHeader) {
        if (logger.isTraceEnabled())
            logger.trace("Entering to removeRequestFromRegistry with RequestHeader = " + ObjectUtils.toString(commonHeader));
        requestRegistry.removeRequest(
                new UniqueRequestIdentifier(commonHeader.getOriginatorId(),
                        commonHeader.getRequestId(),
                        commonHeader.getSubRequestId()));
    }

    private boolean acquireVNFLock(String vnfID, String requestId, long timeout) throws LockException {
        if (logger.isTraceEnabled())
            logger.trace("Entering to acquireVNFLock with vnfID = " + vnfID);
        boolean lockAcquired = lockManager.acquireLock(vnfID, requestId, timeout);
        if (lockAcquired) {
            logger.info("Lock acquired for vnfID = " + vnfID);
        } else {
            logger.info("vnfID = " + vnfID + " was already locked");
        }
        return lockAcquired;
    }

    private void lockWithTimeout(String vnfId, String requestId) throws LockException {
        long timeout = configuration.getLongProperty(PROP_IDLE_TIMEOUT, Constants.DEFAULT_IDLE_TIMEOUT);
        acquireVNFLock(vnfId, requestId, timeout);
    }

    private void resetLock(String vnfId, String requestId, boolean lockAcquired, boolean resetLockTimeout) {
        if (lockAcquired) {
            try {
                releaseVNFLock(vnfId, requestId);
            } catch (LockException e) {
                logger.error("Unlock VNF [" + vnfId + "] failed. Request id: [" + requestId + "]", e);


            }
        } else if (resetLockTimeout) {
            try {
                // reset timeout to previous value
                lockWithTimeout(vnfId, requestId);
            } catch (LockException e) {
                logger.error("Reset lock idle timeout for VNF [" + vnfId + "] failed. Request id: [" + requestId + "]", e);
            }
        }
    }

    private void releaseVNFLock(String vnfId, String transactionId) throws LockException {
        lockManager.releaseLock(vnfId, transactionId);
        logger.info("Lock released for vnfID = " + vnfId);
    }

    private void setInitialLogProperties(RequestContext requestContext) {

        try {
            MDC.put(MDC_KEY_REQUEST_ID, requestContext.getCommonHeader().getRequestId());
            if (requestContext.getActionIdentifiers().getServiceInstanceId() != null) {
                MDC.put(MDC_SERVICE_INSTANCE_ID, requestContext.getActionIdentifiers().getServiceInstanceId());
            }
            MDC.put(LoggingConstants.MDCKeys.PARTNER_NAME, requestContext.getCommonHeader().getOriginatorId());
            MDC.put(MDC_INSTANCE_UUID, ""); // value should be created in the future
            try {
                MDC.put(MDC_SERVER_FQDN, InetAddress.getLocalHost().getCanonicalHostName()); //Don't change it to a .getHostName() again please. It's wrong!
                MDC.put(MDC_SERVER_IP_ADDRESS, InetAddress.getLocalHost().getHostAddress());
                MDC.put(LoggingConstants.MDCKeys.SERVER_NAME, InetAddress.getLocalHost().getHostName());
                MDC.put(MDC_SERVICE_NAME, requestContext.getAction().name());
                MDC.put(LoggingConstants.MDCKeys.TARGET_VIRTUAL_ENTITY, requestContext.getActionIdentifiers().getVnfId());

            } catch (Exception e) {
                logger.debug(e.getMessage());
            }
        } catch (RuntimeException e) {
            //ignore
        }
    }


    private int calculateRemainingTTL(CommonHeader commonHeader) {
        if (logger.isTraceEnabled()) {
            logger.trace("Entering to calculateRemainingTTL with RequestHeader = " + ObjectUtils.toString(commonHeader));
        }
        long usedTimeInMillis = (System.currentTimeMillis() - commonHeader.getTimeStamp().getTime());
        logger.debug("usedTimeInMillis = " + usedTimeInMillis);
        int usedTimeInSeconds = Math.round(usedTimeInMillis / 1000);
        logger.debug("usedTimeInSeconds = " + usedTimeInSeconds);
        Integer inputTTL = this.getInputTTL(commonHeader);
        logger.debug("inputTTL = " + inputTTL);
        Integer remainingTTL = inputTTL - usedTimeInSeconds;
        logger.debug("Remaining TTL = " + remainingTTL);
        if (logger.isTraceEnabled())
            logger.trace("Exiting from calculateRemainingTTL with (remainingTTL = " + ObjectUtils.toString(remainingTTL) + ")");
        return remainingTTL;
    }

    private Integer getInputTTL(CommonHeader header) {
        if (logger.isTraceEnabled())
            logger.trace("Entering in getInputTTL with RequestHeader = " + ObjectUtils.toString(header));
        if (!isValidTTL(String.valueOf(header.getFlags().getTtl()))) {
            String defaultTTLStr = configuration.getProperty("org.openecomp.appc.workflow.default.ttl", String.valueOf(Constants.DEFAULT_TTL));
            Integer defaultTTL = Integer.parseInt(defaultTTLStr);
            if (logger.isTraceEnabled())
                logger.trace("Exiting from getInputTTL with (defaultTTL = " + ObjectUtils.toString(defaultTTL) + ")");
            return defaultTTL;
        }
        if (logger.isTraceEnabled())
            logger.trace("Exiting from getInputTTL with (inputTTL = " + ObjectUtils.toString(header.getFlags().getTtl()) + ")");

        return header.getFlags().getTtl();
    }

    private boolean isValidTTL(String ttl) {
        if (ttl == null || ttl.length() == 0) {
            if (logger.isTraceEnabled())
                logger.trace("Exiting from getInputTTL with (result = false)");
            return false;
        }
        try {
            Integer i = Integer.parseInt(ttl);
            return (i > 0);
        } catch (NumberFormatException e) {
            if (logger.isTraceEnabled())
                logger.trace("Exiting from getInputTTL with (result = false)");
            return false;
        }
    }

    private Boolean isLoggingEnabled() {
        String defaultFlagStr = configuration.getProperty("org.openecomp.appc.localTransactionRecorder.enable", String.valueOf(Constants.DEFAULT_LOGGING_FLAG));
        Boolean defaultFlag = Boolean.parseBoolean(defaultFlagStr);
        return defaultFlag;
    }

    private static RequestHandlerOutput buildRequestHandlerOutput(LCMCommandStatus response, Params params) {
        RequestHandlerOutput output = new RequestHandlerOutput();
        ResponseContext responseContext = new ResponseContext();
        org.openecomp.appc.domainmodel.lcm.Status status = new org.openecomp.appc.domainmodel.lcm.Status();
        status.setCode(response.getResponseCode());
        status.setMessage(response.getFormattedMessage(params));
        responseContext.setStatus(status);
        output.setResponseContext(responseContext);
        return output;
    }

    /**
     * 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.
     *
     * @return true in case AAI updates are successful. false for any error or exception.
     */
    @Override
    public void onRequestExecutionStart(String vnfId, boolean readOnlyActivity, String requestIdentifierString, boolean forceFlag) throws UnstableVNFException {
        if (logger.isTraceEnabled()) {
            logger.trace("Entering to onRequestExecutionStart with vnfId = " + vnfId + "and requestIdentifierString = " + requestIdentifierString);
        }
        try {
            boolean updated = workingStateManager.setWorkingState(vnfId, VNFWorkingState.UNSTABLE, requestIdentifierString, forceFlag);
            if (!updated) {
                throw new UnstableVNFException("VNF is not stable for vnfID = " + vnfId);
            }
        } catch (Exception e) {
            logger.error("Error updating working state for vnf " + vnfId + e);
            throw new RuntimeException(e);
        }

        if (logger.isTraceEnabled())
            logger.trace("Exiting from onRequestExecutionStart ");
    }

    /**
     * This method perform following operations required after execution of workflow.
     * It posts asynchronous response to message bus (DMaaP).
     * Unlock VNF Id
     * Removes request from request registry.
     * Generate audit logs.
     * Adds transaction record to database id if transaction logging is enabled.
     *
     * @param isAAIUpdated boolean flag which indicate AAI upodate status after request completion.
     */
    @Override
    public void onRequestExecutionEnd(RuntimeContext runtimeContext, boolean isAAIUpdated) {
        if (logger.isTraceEnabled()) {
            logger.trace("Entering to onRequestExecutionEnd with runtimeContext = " + ObjectUtils.toString(runtimeContext));
        }

        postMessageToDMaaP(runtimeContext.getRequestContext().getAction(), runtimeContext.getRpcName(), runtimeContext.getResponseContext());
        requestRegistry.removeRequest(
                new UniqueRequestIdentifier(runtimeContext.getResponseContext().getCommonHeader().getOriginatorId(),
                        runtimeContext.getResponseContext().getCommonHeader().getRequestId(),
                        runtimeContext.getResponseContext().getCommonHeader().getSubRequestId()));
        resetLock(runtimeContext.getVnfContext().getId(), runtimeContext.getResponseContext().getCommonHeader().getRequestId(), runtimeContext.isLockAcquired(), true);
        Status status = runtimeContext.getResponseContext().getStatus();

        VNFWorkingState workingState;
        if (status.getCode() == LCMCommandStatus.SUCCESS.getResponseCode() || isReadOnlyAction(runtimeContext.getRequestContext().getAction())) {
            workingState = VNFWorkingState.STABLE;
        } else {
            workingState = VNFWorkingState.UNKNOWN;
        }

        UniqueRequestIdentifier requestIdentifier = new UniqueRequestIdentifier(runtimeContext.getResponseContext().getCommonHeader().getOriginatorId(),
                runtimeContext.getResponseContext().getCommonHeader().getRequestId(),
                runtimeContext.getResponseContext().getCommonHeader().getSubRequestId());

        String requestIdentifierString = requestIdentifier.toIdentifierString();
        workingStateManager.setWorkingState(runtimeContext.getVnfContext().getId(), workingState, requestIdentifierString, false);


        storeAuditLogRecord(runtimeContext);

        if (isLoggingEnabled()) {
            createTransactionRecord(runtimeContext);
        }
    }

    private void storeAuditLogRecord(RuntimeContext runtimeContext) {
        LoggingUtils.logAuditMessage(runtimeContext.getTimeStart(),
                new Date(System.currentTimeMillis()),
                String.valueOf(runtimeContext.getResponseContext().getStatus().getCode()),
                runtimeContext.getResponseContext().getStatus().getMessage(),
                this.getClass().getCanonicalName());
    }

    private void storeMetricLogRecord(RuntimeContext runtimeContext) {
        LoggingUtils.logMetricsMessage(runtimeContext.getTimeStart(),
                new Date(System.currentTimeMillis()),
                LoggingConstants.TargetNames.APPC,
                runtimeContext.getRequestContext().getAction().name(),
                runtimeContext.getResponseContext().getStatus().getCode() == LCMCommandStatus.ACCEPTED.getResponseCode() ? LoggingConstants.StatusCodes.COMPLETE : LoggingConstants.StatusCodes.ERROR,
                String.valueOf(runtimeContext.getResponseContext().getStatus().getCode()),
                runtimeContext.getResponseContext().getStatus().getMessage(),
                this.getClass().getCanonicalName());
    }

    private boolean isReadOnlyAction(VNFOperation action) {
        return VNFOperation.Sync == action
                || VNFOperation.Audit == action;
    }


    //returns null if asyncResponse was not modified otherwise reutrns the updated asyncResponse
    private void postMessageToDMaaP(VNFOperation operation, String rpcName, ResponseContext responseContext/*, boolean isTTLEnd, boolean aaiUpdateSuccess*/) {
        if (logger.isTraceEnabled()) {
            logger.trace("Entering to postMessageToDMaaP with AsyncResponse = " + ObjectUtils.toString(responseContext));
        }
        /*boolean updated = updateAsyncResponseStatus(responseContext, isTTLEnd, aaiUpdateSuccess);
         */
        boolean callbackResponse = messageAdapter.post(operation, rpcName, responseContext);
        if (!callbackResponse) {
            logger.error("DMaaP posting status: " + callbackResponse, "dmaapMessage: " + responseContext);
        }
        if (logger.isTraceEnabled())
            logger.trace("Exiting from postMessageToDMaaP with (callbackResponse = " + ObjectUtils.toString(callbackResponse) + ")");
    }

    //returns true if asyncResponse was modified
    /*    private boolean updateAsyncResponseStatus(ResponseContext asyncResponse, boolean isTTLEnd, boolean aaiUpdateSuccess) {
        boolean updated = false;
        if (logger.isTraceEnabled())
            logger.trace("Entering to updateAsyncResponseStatus with AsyncResponse = "+ObjectUtils.toString(asyncResponse)+ ", isTTLEnd = "+ ObjectUtils.toString(isTTLEnd)+ ", aaiUpdateSuccess = "+ ObjectUtils.toString(aaiUpdateSuccess));
        if(!aaiUpdateSuccess){
                if (asyncResponse.getStatus().getCode() == 0 || asyncResponse.getStatus().getCode() == LCMCommandStatus.SUCCESS.getResponseCode()) {
                    asyncResponse.getStatus().setCode(LCMCommandStatus.UPDATE_AAI_FAILURE.getResponseCode());
                    asyncResponse.getStatus().setMessage(LCMCommandStatus.UPDATE_AAI_FAILURE.getResponseMessage());
                updated = true;
            }
        }else if(isTTLEnd){
                asyncResponse.getStatus().setCode(LCMCommandStatus.EXPIRED_REQUEST_FAILURE.getResponseCode());
                asyncResponse.getStatus().setMessage(LCMCommandStatus.EXPIRED_REQUEST_FAILURE.getResponseMessage());
            updated = true;
        }
        if (logger.isTraceEnabled())
            logger.trace("Exiting from updateAsyncResponseStatus with (asyncResponse = "+ ObjectUtils.toString(asyncResponse)+")");
        return updated;
    }*/


    /**
     * This method perform following operations required if TTL ends when request still waiting in execution queue .
     * It posts asynchronous response to message bus (DMaaP).
     * Unlock VNF Id
     * Removes request from request registry.
     *
     * @param runtimeContext AsyncResponse object which contains VNF Id 	, timestamp , apiVersion, responseId, executionSuccess, payload, isExpired, action, startTime, vnfType, originatorId, subResponseId;
     * @param updateAAI      boolean flag which indicate AAI upodate status after request completion.
     */
    @Override
    public void onRequestTTLEnd(RuntimeContext runtimeContext, boolean updateAAI) {
        if (logger.isTraceEnabled()) {
            logger.trace("Entering to onRequestTTLEnd with " +
                    "AsyncResponse = " + ObjectUtils.toString(runtimeContext) +
                    ", updateAAI = " + ObjectUtils.toString(updateAAI));
        }
        logger.error(LCMCommandStatus.EXPIRED_REQUEST_FAILURE.getResponseMessage());
        fillStatus(runtimeContext, LCMCommandStatus.EXPIRED_REQUEST_FAILURE, null);
        postMessageToDMaaP(runtimeContext.getRequestContext().getAction(), runtimeContext.getRpcName(), runtimeContext.getResponseContext());
        resetLock(runtimeContext.getVnfContext().getId(), runtimeContext.getResponseContext().getCommonHeader().getRequestId(), runtimeContext.isLockAcquired(), true);
        requestRegistry.removeRequest(
                new UniqueRequestIdentifier(runtimeContext.getResponseContext().getCommonHeader().getOriginatorId(),
                        runtimeContext.getResponseContext().getCommonHeader().getRequestId(),
                        runtimeContext.getResponseContext().getCommonHeader().getSubRequestId()));
    }

    private SvcLogicContext getVnfdata(String vnf_id, String prefix, SvcLogicContext ctx) throws VNFNotFoundException {
        String key = "vnf-id = '" + vnf_id + "'";
        if (logger.isTraceEnabled()) {
            logger.trace("Entering to getVnfdata with " +
                    "vnfId = " + vnf_id +
                    ", prefix = " + prefix +
                    ", SvcLogicContex = " + ObjectUtils.toString(ctx));
        }
        try {
            QueryStatus response = aaiService.query("generic-vnf", false, null, key, prefix, null, ctx);
            if (QueryStatus.NOT_FOUND.equals(response)) {
                throw new VNFNotFoundException("VNF not found for vnf_id = " + vnf_id);
            } else if (QueryStatus.FAILURE.equals(response)) {
                throw new RuntimeException("Error Querying AAI with vnfID = " + vnf_id);
            }
            logger.info("AAIResponse: " + response.toString());
        } catch (SvcLogicException e) {
            logger.error("Error in getVnfdata " + e);
            throw new RuntimeException(e);
        }
        if (logger.isTraceEnabled()) {
            logger.trace("Exiting from getVnfdata with (SvcLogicContext = " + ObjectUtils.toString(ctx) + ")");
        }
        return ctx;
    }

    private boolean postVnfdata(String vnf_id, String status, String prefix, SvcLogicContext ctx) throws VNFNotFoundException {
        if (logger.isTraceEnabled()) {
            logger.trace("Entering to postVnfdata with " +
                    "vnfId = " + vnf_id +
                    ", status = " + status +
                    ", prefix = " + prefix +
                    ", SvcLogicContext = " + ObjectUtils.toString(ctx));
        }
        String key = "vnf-id = '" + vnf_id + "'";
        Map<String, String> data = new HashMap<>();
        data.put("orchestration-status", status);
        try {
            QueryStatus response = aaiService.update("generic-vnf", key, data, prefix, ctx);
            if (QueryStatus.NOT_FOUND.equals(response)) {
                throw new VNFNotFoundException("VNF not found for vnf_id = " + vnf_id);
            }
            logger.info("AAIResponse: " + response.toString());
            if (response.toString().equals("SUCCESS")) {
                if (logger.isTraceEnabled()) {
                    logger.trace("Exiting from postVnfdata with (Result = " + ObjectUtils.toString(true) + ")");
                }
                return true;
            }

        } catch (SvcLogicException e) {
            logger.error("Error in postVnfdata " + e);
            throw new RuntimeException(e);
        }
        if (logger.isTraceEnabled()) {
            logger.trace("Exiting from postVnfdata with (Result = " + ObjectUtils.toString(false) + ")");
        }
        return false;
    }

    private void initMetric() {
        if (logger.isDebugEnabled())
            logger.debug("Metric getting initialized");
        MetricService metricService = getMetricservice();
        metricRegistry = metricService.createRegistry("APPC");
        DispatchingFuntionMetric dispatchingFuntionMetric = metricRegistry.metricBuilderFactory().
                dispatchingFunctionCounterBuilder().
                withName("DISPATCH_FUNCTION").withType(MetricType.COUNTER).
                withAcceptRequestValue(0)
                .withRejectRequestValue(0)
                .build();
        if (metricRegistry.register(dispatchingFuntionMetric)) {
            Metric[] metrics = new Metric[]{dispatchingFuntionMetric};
            LogPublisher logPublisher = new LogPublisher(metricRegistry, metrics);
            LogPublisher[] logPublishers = new LogPublisher[1];
            logPublishers[0] = logPublisher;
            PublishingPolicy manuallyScheduledPublishingPolicy = metricRegistry.policyBuilderFactory().
                    scheduledPolicyBuilder().withPublishers(logPublishers).
                    withMetrics(metrics).
                    build();
            if (logger.isDebugEnabled())
                logger.debug("Policy getting initialized");
            manuallyScheduledPublishingPolicy.init();
            if (logger.isDebugEnabled())
                logger.debug("Metric initialized");
        }
    }


    private MetricService getMetricservice() {
        BundleContext bctx = FrameworkUtil.getBundle(MetricService.class).getBundleContext();
        ServiceReference sref = bctx.getServiceReference(MetricService.class.getName());
        if (sref != null) {
            logger.info("Metric Service from bundlecontext");
            return (MetricService) bctx.getService(sref);
        } else {
            logger.info("Metric Service error from bundlecontext");
            logger.warn("Cannot find service reference for org.openecomp.appc.metricservice.MetricService");
            return null;
        }
    }
}