l2 management maturity pdp-d

configurable log location
metric/audit log for transaction metrics conforming to
new field definition.
support metrics/audits records with custom logback filters
so they are not intrusive with developer log testing.

Change-Id: I7a4dcc6790b85539e613ad8705e731e7298ce106
Issue-ID: POLICY-533
Signed-off-by: Jorge Hernandez <jh1730@att.com>

5 files changed, 141 insertions, 62 deletions

diff --git a/policy-management/src/main/java/org/onap/policy/drools/server/restful/RestManager.java b/policy-management/src/main/java/org/onap/policy/drools/server/restful/RestManager.java
index cd1edca5..15c97237 100644
--- a/policy-management/src/main/java/org/onap/policy/drools/server/restful/RestManager.java
+++ b/policy-management/src/main/java/org/onap/policy/drools/server/restful/RestManager.java
@@ -64,7 +64,7 @@ import org.onap.policy.drools.protocol.configuration.ControllerConfiguration;
 import org.onap.policy.drools.protocol.configuration.PdpdConfiguration;
 import org.onap.policy.drools.system.PolicyController;
 import org.onap.policy.drools.system.PolicyEngine;
-import org.onap.policy.drools.utils.LoggerUtil;
+import org.onap.policy.drools.utils.logging.LoggerUtil;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
 
diff --git a/policy-management/src/main/java/org/onap/policy/drools/system/Main.java b/policy-management/src/main/java/org/onap/policy/drools/system/Main.java
index 314bbc04..43216000 100644
--- a/policy-management/src/main/java/org/onap/policy/drools/system/Main.java
+++ b/policy-management/src/main/java/org/onap/policy/drools/system/Main.java
@@ -2,7 +2,7 @@
  * ============LICENSE_START=======================================================
  * policy-management
  * ================================================================================
- * Copyright (C) 2017 AT&T Intellectual Property. All rights reserved.
+ * Copyright (C) 2017-2018 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.
@@ -20,14 +20,14 @@
 
 package org.onap.policy.drools.system;
 
-import java.io.IOException;
 import java.nio.file.Files;
 import java.nio.file.Paths;
 import java.util.Properties;
 
 import org.onap.policy.drools.persistence.SystemPersistence;
 import org.onap.policy.drools.properties.PolicyProperties;
-import org.onap.policy.drools.utils.LoggerUtil;
+import org.onap.policy.drools.utils.logging.LoggerUtil;
+import org.onap.policy.drools.utils.logging.MDCTransaction;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
 
@@ -56,7 +56,6 @@ public class Main {
    * main
    *
    * @param args program arguments
-   * @throws IOException
    */
   public static void main(String[] args) {
 
@@ -110,16 +109,23 @@ public class Main {
 
     /* 2. Start the Engine with the basic services only (no Policy Controllers) */
 
+    MDCTransaction trans =
+        MDCTransaction.newTransaction(null, null).setServiceName(Main.class.getSimpleName()).
+          setTargetEntity("engine").setTargetServiceName("start");
     try {
       final boolean success = PolicyEngine.manager.start();
       if (!success) {
-        logger.warn("Main: {} has been partially started", PolicyEngine.manager);
+        trans.setStatusCode(false).setResponseDescription("partial start").flush();
+        logger.warn(LoggerUtil.TRANSACTION_LOG_MARKER, "Main: {} has been partially started", PolicyEngine.manager);
+      } else {
+        trans.setStatusCode(true).transaction();
       }
     } catch (final IllegalStateException e) {
-      logger.warn("Main: cannot start {} (bad state) because of {}", PolicyEngine.manager,
-          e.getMessage(), e);
+      trans.setStatusCode(false).setResponseCode(e.getClass().getSimpleName()).setResponseDescription(e.getMessage()).flush();
+      logger.warn(LoggerUtil.TRANSACTION_LOG_MARKER, "Main: cannot start {} (bad state) because of {}", PolicyEngine.manager, e.getMessage(), e);
     } catch (final Exception e) {
-      logger.warn("Main: cannot start {} because of {}", PolicyEngine.manager, e.getMessage(), e);
+      trans.setStatusCode(false).setResponseCode(e.getClass().getSimpleName()).setResponseDescription(e.getMessage()).flush();
+      logger.warn(LoggerUtil.TRANSACTION_LOG_MARKER, "Main: cannot start {} because of {}", PolicyEngine.manager, e.getMessage(), e);
       System.exit(1);
     }
 
@@ -130,14 +136,24 @@ public class Main {
       final String controllerName =
           controllerProperties.getProperty(PolicyProperties.PROPERTY_CONTROLLER_NAME);
       try {
+        trans =
+            MDCTransaction.newTransaction(null, null).setServiceName(Main.class.getSimpleName()).
+                setTargetEntity("controller:" + controllerName).setTargetServiceName("start");
+
         final PolicyController controller =
             PolicyEngine.manager.createPolicyController(controllerName, controllerProperties);
         controller.start();
+
+        trans.setStatusCode(true).
+            setResponseDescription(controller.getDrools().getCanonicalSessionNames().toString()).
+            transaction();
       } catch (final Exception e) {
-        logger.error("Main: cannot instantiate policy-controller {} because of {}", controllerName,
-            e.getMessage(), e);
+        trans.setStatusCode(false).setResponseCode(e.getClass().getSimpleName()).setResponseDescription(e.getMessage()).flush();
+        logger.error(LoggerUtil.TRANSACTION_LOG_MARKER, "Main: cannot instantiate policy-controller {} because of {}",
+            controllerName, e.getMessage(), e);
       } catch (final LinkageError e) {
-        logger.warn("Main: cannot instantiate policy-controller {} (linkage) because of {}",
+        trans.setStatusCode(false).setResponseCode(e.getClass().getSimpleName()).setResponseDescription(e.getMessage()).flush();
+        logger.warn(LoggerUtil.TRANSACTION_LOG_MARKER, "Main: cannot instantiate policy-controller {} (linkage) because of {}",
             controllerName, e.getMessage(), e);
       }
     }
diff --git a/policy-management/src/main/java/org/onap/policy/drools/system/PolicyEngine.java b/policy-management/src/main/java/org/onap/policy/drools/system/PolicyEngine.java
index a1fee763..d7275578 100644
--- a/policy-management/src/main/java/org/onap/policy/drools/system/PolicyEngine.java
+++ b/policy-management/src/main/java/org/onap/policy/drools/system/PolicyEngine.java
@@ -44,6 +44,8 @@ import org.onap.policy.drools.protocol.coders.EventProtocolCoder;
 import org.onap.policy.drools.protocol.configuration.ControllerConfiguration;
 import org.onap.policy.drools.protocol.configuration.PdpdConfiguration;
 import org.onap.policy.drools.server.restful.RestManager;
+import org.onap.policy.drools.utils.logging.LoggerUtil;
+import org.onap.policy.drools.utils.logging.MDCTransaction;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
 
@@ -139,7 +141,6 @@ public interface PolicyEngine extends Startable, Lockable, TopicListener {
   /**
    * registers a new Policy Controller with the Policy Engine initialized per properties.
    *
-   * @param controller name
    * @param properties properties to initialize the Policy Controller
    * @throws IllegalArgumentException when invalid or insufficient properties are provided
    * @throws IllegalStateException when the engine is in a state where this operation is not
@@ -276,7 +277,6 @@ public interface PolicyEngine extends Startable, Lockable, TopicListener {
   /**
    * Attempts the dispatching of an "event" object over communication infrastructure "busType"
    *
-   * @param eventBus Communication infrastructure identifier
    * @param topic topic
    * @param event the event object to send
    *
@@ -292,7 +292,6 @@ public interface PolicyEngine extends Startable, Lockable, TopicListener {
   /**
    * Attempts the dispatching of an "event" object over communication infrastructure "busType"
    *
-   * @param eventBus Communication infrastructure enum
    * @param topic topic
    * @param event the event object to send
    *
@@ -308,7 +307,6 @@ public interface PolicyEngine extends Startable, Lockable, TopicListener {
   /**
    * Attempts delivering of an String over communication infrastructure "busType"
    *
-   * @param eventBus Communication infrastructure identifier
    * @param topic topic
    * @param event the event object to send
    *
@@ -591,12 +589,22 @@ private static final String ENGINE_LOCKED_MSG = "Policy Engine is locked";
 
     final String entity = config.getEntity();
 
+    MDCTransaction mdcTrans = MDCTransaction.newTransaction(config.getRequestID(), "brmsgw");
+    if (this.getSources().size() == 1) {
+      Topic topic = this.getSources().get(0);
+      mdcTrans.setServiceName(topic.getTopic()).setRemoteHost(topic.getServers().toString()).
+        setTargetEntity(config.getEntity());
+    }
+
     switch (entity) {
-      case PdpdConfiguration.CONFIG_ENTITY_CONTROLLER:          
-        return controllerConfig(config);
+      case PdpdConfiguration.CONFIG_ENTITY_CONTROLLER:
+        boolean success = controllerConfig(config);
+        mdcTrans.resetSubTransaction().setStatusCode(success).transaction();
+        return success;
       default:
         final String msg = "Configuration Entity is not supported: " + entity;
-        logger.warn(msg);
+        mdcTrans.resetSubTransaction().setStatusCode(false).setResponseDescription(msg).flush();
+        logger.warn(LoggerUtil.TRANSACTION_LOG_MARKER_NAME, msg);
         throw new IllegalArgumentException(msg);
     }
   }
@@ -613,11 +621,18 @@ private static final String ENGINE_LOCKED_MSG = "Policy Engine is locked";
     }
 
     for (final ControllerConfiguration configController : configControllers) {
+      MDCTransaction mdcTrans =
+          MDCTransaction.newSubTransaction(null).setTargetEntity(configController.getName()).
+              setTargetServiceName(configController.getOperation()).
+              setTargetVirtualEntity(configController.getDrools().toString());
       try {
         final PolicyController policyController = this.updatePolicyController(configController);
         policyControllers.add(policyController);
+        mdcTrans.setStatusCode(true).transaction();
       } catch (final Exception e) {
-        logger.error("{}: cannot update-policy-controllers because of {}", this, e.getMessage(), e);
+        mdcTrans.setStatusCode(false).setResponseCode(e.getClass().getName()).
+            setResponseDescription(e.getMessage()).flush();
+        logger.error(LoggerUtil.TRANSACTION_LOG_MARKER_NAME, "{}: cannot update-policy-controllers because of {}", this, e.getMessage(), e);
       }
     }
 
@@ -1423,18 +1438,23 @@ private static final String ENGINE_LOCKED_MSG = "Policy Engine is locked";
       /* only this one supported for now */
       final List<ControllerConfiguration> configControllers = config.getControllers();
       if (configControllers == null || configControllers.isEmpty()) {
-        if (logger.isInfoEnabled())
-          logger.info("No controller configuration provided: " + config);
+        logger.info("No controller configuration provided: {}" + config);
         return false;
       }
-      final List<PolicyController> policyControllers =
-          this.updatePolicyControllers(config.getControllers());
-      if (policyControllers == null || policyControllers.isEmpty())
-        return false;
-      else if (policyControllers.size() == configControllers.size())
-        return true;
 
-      return false;      
+      final List<PolicyController> policyControllers = this.updatePolicyControllers(config.getControllers());
+
+      boolean success;
+
+      if (policyControllers == null || policyControllers.isEmpty()) {
+        success = false;
+      } else if (policyControllers.size() == configControllers.size()) {
+        success = true;
+      } else {
+        success = false;
+      }
+
+      return success;
   }
 
   @Override
diff --git a/policy-management/src/main/server-gen/bin/policy-management-controller b/policy-management/src/main/server-gen/bin/policy-management-controller
index a9f8ce0d..cc6a8c7d 100644
--- a/policy-management/src/main/server-gen/bin/policy-management-controller
+++ b/policy-management/src/main/server-gen/bin/policy-management-controller
@@ -4,7 +4,7 @@
 # ============LICENSE_START=======================================================
 # ONAP POLICY
 # ================================================================================
-# Copyright (C) 2017 AT&T Intellectual Property. All rights reserved.
+# Copyright (C) 2017-2018 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.
@@ -42,11 +42,11 @@ function um_start() {
       RETVAL=0
       return
     fi
-    mkdir -p $_DIR/logs
-    if [ -e $_DIR/logs/$PNAME.out.1 ]; then mv $_DIR/logs/$PNAME.out.1 $_DIR/logs/$PNAME.out.2; fi
-    if [ -e $_DIR/logs/$PNAME.err.1 ]; then mv $_DIR/logs/$PNAME.err.1 $_DIR/logs/$PNAME.err.2; fi
-    if [ -e $_DIR/logs/$PNAME.out ]; then mv $_DIR/logs/$PNAME.out $_DIR/logs/$PNAME.out.1; fi
-    if [ -e $_DIR/logs/$PNAME.err ]; then mv $_DIR/logs/$PNAME.err $_DIR/logs/$PNAME.err.1; fi
+    mkdir -p $_LOGS
+    if [ -e $_LOGS/$PNAME.out.1 ]; then mv $_LOGS/$PNAME.out.1 $_LOGS/$PNAME.out.2; fi
+    if [ -e $_LOGS/$PNAME.err.1 ]; then mv $_LOGS/$PNAME.err.1 $_LOGS/$PNAME.err.2; fi
+    if [ -e $_LOGS/$PNAME.out ]; then mv $_LOGS/$PNAME.out $_LOGS/$PNAME.out.1; fi
+    if [ -e $_LOGS/$PNAME.err ]; then mv $_LOGS/$PNAME.err $_LOGS/$PNAME.err.1; fi
     CP=$(ls $_DIR/lib/*.jar | xargs -I X printf ":%s" X)
 
     # If 'system.properties' exists, convert it into JVM arguments.
@@ -66,7 +66,7 @@ function um_start() {
 	    # to subprocesses
 	    exec {cfg}>&-
 	fi
-	nohup $JAVA_HOME/bin/java -Dkie.maven.settings.custom=$_DIR/config/kie_settings.xml -Dlog4j.configuration=file:$_DIR/config/log4j.properties -cp $_DIR/config:$_DIR/lib:$CP "${systemProperties[@]}" "$@" $CLASS > >( while read line; do echo "$(date): ${line}"; done > $_DIR/logs/$PNAME.out) 2> >( while read line; do echo "$(date): ${line}"; done > $_DIR/logs/$PNAME.err) &
+	nohup $JAVA_HOME/bin/java -Dkie.maven.settings.custom=$_DIR/config/kie_settings.xml -Dlog4j.configuration=file:$_DIR/config/log4j.properties -cp $_DIR/config:$_DIR/lib:$CP "${systemProperties[@]}" "$@" $CLASS > >( while read line; do echo "$(date): ${line}"; done > $_LOGS/$PNAME.out) 2> >( while read line; do echo "$(date): ${line}"; done > $_LOGS/$PNAME.err) &
 
 	_PID=$!
 	echo $_PID > $_PIDFILE
@@ -167,6 +167,12 @@ function update_monitor() {
 # main
 
 _DIR=${POLICY_HOME}
+_LOGS=${POLICY_LOGS}
+
+if [[ -z ${POLICY_LOGS} ]]; then
+	_LOGS="${POLICY_HOME}"/logs
+fi
+
 CONTROLLER=policy-management-controller
 
 RETVAL=0
diff --git a/policy-management/src/main/server/config/logback.xml b/policy-management/src/main/server/config/logback.xml
index 1801c43a..538fcf80 100644
--- a/policy-management/src/main/server/config/logback.xml
+++ b/policy-management/src/main/server/config/logback.xml
@@ -2,7 +2,7 @@
   ============LICENSE_START=======================================================
   policy-management
   ================================================================================
-  Copyright (C) 2017 AT&T Intellectual Property. All rights reserved.
+  Copyright (C) 2017-2018 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.
@@ -20,30 +20,33 @@
 
 <configuration scan="true" scanPeriod="30 seconds" debug="false">
 
-	<property name="logDir" value="logs" />
+	<property name="logDir" value="${POLICY_LOGS}" />
 
 	<property name="errorLog" value="error" />
 	<property name="debugLog" value="debug" />
 	<property name="networkLog" value="network" />
 
-	<property name="debugPattern" value="[%date|%level|%logger{0}|%thread] %msg%n" />
+	<property name="metricLog" value="metric" />
+	<property name="transactionLog" value="audit" />
+
+	<property name="debugPattern" value="[%d{yyyy-MM-dd'T'HH:mm:ss.SSS+00:00, UTC}|%level|%logger{0}|%thread] %msg%n" />
 	<property name="errorPattern" value="${debugPattern}" />
-	<property name="networkPattern" value="[%d|%t]%m%n" />
+	<property name="networkPattern" value="[%d{yyyy-MM-dd'T'HH:mm:ss.SSS+00:00, UTC}|%t]%m%n" />
+
+	<property name="metricPattern" value="%X{RequestID}|%X{InvocationID}|%X{ServiceName}|%X{PartnerName}|%X{BeginTimestamp}|%X{EndTimestamp}|%X{ElapsedTime}|%X{ServiceInstanceID}|%X{VirtualServerName}|%X{StatusCode}|%X{ResponseCode}|%X{ResponseDescription}|%X{InstanceUUID}|%X{Severity}|%X{TargetEntity}|%X{TargetServiceName}|%X{Server}|%X{ServerIPAddress}|%X{ServerFQDN}|%X{ClientIPAddress}|%X{ProcessKey}|%X{RemoteHost}|%X{AlertSeverity}|%X{TargetVirtualEntity}|%level|%thread| %msg%n"/>
+	<property name="transactionPattern" value="${metricPattern}" />
 
 	<appender name="ErrorOut" class="ch.qos.logback.core.rolling.RollingFileAppender">
 		<file>${logDir}/${errorLog}.log</file>
-		<rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
-			<fileNamePattern>${logDir}/${errorLog}.%i.log.zip</fileNamePattern>
-			<minIndex>1</minIndex>
-			<maxIndex>5</maxIndex>
+		<rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
+			<fileNamePattern>${logDir}/${errorLog}.%d{yyyy-MM-dd}.%i.log.zip</fileNamePattern>
+			<maxFileSize>50MB</maxFileSize>
+			<maxHistory>30</maxHistory>
+			<totalSizeCap>10GB</totalSizeCap>
 		</rollingPolicy>
 		<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
 			<level>WARN</level>
 		</filter>
-		<triggeringPolicy
-			class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
-			<maxFileSize>15MB</maxFileSize>
-		</triggeringPolicy>
 		<encoder>
 			<pattern>${errorPattern}</pattern>
 		</encoder>
@@ -55,14 +58,12 @@
 	
 	<appender name="DebugOut" class="ch.qos.logback.core.rolling.RollingFileAppender">
 		<file>${logDir}/${debugLog}.log</file>
-		<rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
-			<fileNamePattern>${logDir}/${debugLog}.%i.log.zip</fileNamePattern>
-			<minIndex>1</minIndex>
-			<maxIndex>9</maxIndex>
+		<rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
+			<fileNamePattern>${logDir}/${debugLog}.%d{yyyy-MM-dd}.%i.log.zip</fileNamePattern>
+			<maxFileSize>50MB</maxFileSize>
+			<maxHistory>30</maxHistory>
+			<totalSizeCap>10GB</totalSizeCap>
 		</rollingPolicy>
-		<triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
-			<maxFileSize>20MB</maxFileSize>
-		</triggeringPolicy>
 		<encoder>
 			<pattern>${debugPattern}</pattern>
 		</encoder>
@@ -74,14 +75,12 @@
 
 	<appender name="NetworkOut" class="ch.qos.logback.core.rolling.RollingFileAppender">
 		<file>${logDir}/${networkLog}.log</file>
-		<rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
-			<fileNamePattern>${logDir}/${networkLog}.%i.log.zip</fileNamePattern>
-			<minIndex>1</minIndex>
-			<maxIndex>9</maxIndex>
+		<rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
+			<fileNamePattern>${logDir}/${networkLog}.%d{yyyy-MM-dd}.%i.log.zip</fileNamePattern>
+			<maxFileSize>50MB</maxFileSize>
+			<maxHistory>30</maxHistory>
+			<totalSizeCap>10GB</totalSizeCap>
 		</rollingPolicy>
-		<triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
-			<maxFileSize>15MB</maxFileSize>
-		</triggeringPolicy>
 		<encoder>
 			<pattern>${networkPattern}</pattern>
 		</encoder>		
@@ -91,6 +90,42 @@
 		<appender-ref ref="NetworkOut" />
 	</appender>
 
+	<appender name="MetricOut" class="ch.qos.logback.core.rolling.RollingFileAppender">
+		<file>${logDir}/${metricLog}.log</file>
+		<rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
+			<fileNamePattern>${logDir}/${metricLog}.%d{yyyy-MM-dd}.%i.log.zip</fileNamePattern>
+			<maxFileSize>50MB</maxFileSize>
+			<maxHistory>30</maxHistory>
+			<totalSizeCap>10GB</totalSizeCap>
+		</rollingPolicy>
+		<filter class="org.onap.policy.drools.utils.logging.LoggerMarkerFilter$MetricLoggerMarkerFilter" />
+		<encoder>
+			<pattern>${metricPattern}</pattern>
+		</encoder>
+	</appender>
+
+	<appender name="AsyncMetricOut" class="ch.qos.logback.classic.AsyncAppender">
+		<appender-ref ref="MetricOut" />
+	</appender>
+
+	<appender name="TransactionOut" class="ch.qos.logback.core.rolling.RollingFileAppender">
+		<file>${logDir}/${transactionLog}.log</file>
+		<rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
+			<fileNamePattern>${logDir}/${transactionLog}.%d{yyyy-MM-dd}.%i.log.zip</fileNamePattern>
+			<maxFileSize>50MB</maxFileSize>
+			<maxHistory>30</maxHistory>
+			<totalSizeCap>10GB</totalSizeCap>
+		</rollingPolicy>
+		<filter class="org.onap.policy.drools.utils.logging.LoggerMarkerFilter$TransactionLoggerMarkerFilter" />
+		<encoder>
+			<pattern>${transactionPattern}</pattern>
+		</encoder>
+	</appender>
+
+	<appender name="AsyncTransactionOut" class="ch.qos.logback.classic.AsyncAppender">
+		<appender-ref ref="TransactionOut" />
+	</appender>
+
 	<logger name="network" level="INFO" additivity="false">
 		<appender-ref ref="AsyncNetworkOut" />		
 	</logger>
@@ -102,6 +137,8 @@
 	<root level="INFO">
 		<appender-ref ref="AsyncDebugOut" />
 		<appender-ref ref="AsyncErrorOut" />
+		<appender-ref ref="AsyncMetricOut" />
+		<appender-ref ref="AsyncTransactionOut" />
 	</root>
 
 </configuration>