Update Logging

Add CXF interceptor for SOAP based logging
Clean up extra logging statements
Add UT to ensure MDC properly populated
Change package name on Jax-RS Filter to be more accurate

Issue-ID: SO-947

Change-Id: I3a2afc58de3bf370675658ce3d19cf899b90def7


Change-Id: I3a2afc58de3bf370675658ce3d19cf899b90def7
Signed-off-by: Smokowski, Steve (ss835w) <ss835w@us.att.com>

5 files changed, 177 insertions, 50 deletions

diff --git a/adapters/mso-requests-db-adapter/src/test/java/org/onap/so/adapters/requestsdb/InfraActiveRequestsRepositoryCustomControllerTest.java b/adapters/mso-requests-db-adapter/src/test/java/org/onap/so/adapters/requestsdb/InfraActiveRequestsRepositoryCustomControllerTest.java
index 58eb0085ad..11f8ff0c36 100644
--- a/adapters/mso-requests-db-adapter/src/test/java/org/onap/so/adapters/requestsdb/InfraActiveRequestsRepositoryCustomControllerTest.java
+++ b/adapters/mso-requests-db-adapter/src/test/java/org/onap/so/adapters/requestsdb/InfraActiveRequestsRepositoryCustomControllerTest.java
@@ -8,6 +8,7 @@ import org.junit.runner.RunWith;
 import org.onap.so.adapters.requestsdb.application.MSORequestDBApplication;
 import org.onap.so.db.request.beans.InfraActiveRequests;
 import org.onap.so.db.request.data.controller.InstanceNameDuplicateCheckRequest;
+import org.springframework.beans.factory.annotation.Value;
 import org.springframework.boot.context.embedded.LocalServerPort;
 import org.springframework.boot.test.context.SpringBootTest;
 import org.springframework.boot.test.web.client.TestRestTemplate;
@@ -39,6 +40,9 @@ public class InfraActiveRequestsRepositoryCustomControllerTest {
 
     @LocalServerPort
     private int port;
+    
+    @Value("${mso.adapters.requestDb.auth}")
+    private String msoAdaptersAuth;
 
     private String createURLWithPort(String uri) {
         return "http://localhost:" + port + uri;
@@ -82,6 +86,7 @@ public class InfraActiveRequestsRepositoryCustomControllerTest {
 
         headers.set("Accept", MediaType.APPLICATION_JSON);
         headers.set("Content-Type", MediaType.APPLICATION_JSON);
+        headers.set("Authorization", msoAdaptersAuth);
 
         infraActiveRequests = new InfraActiveRequests();
 
@@ -181,12 +186,13 @@ public class InfraActiveRequestsRepositoryCustomControllerTest {
     @Test
     public void checkVnfIdStatusTest() {
 
-        HttpEntity<List<String>> entityList = new HttpEntity("", headers);
+        
         UriComponentsBuilder builder = UriComponentsBuilder.fromHttpUrl(createURLWithPort("/infraActiveRequests" + "/checkVnfIdStatus/" + infraActiveRequests.getOperationalEnvId()));
+        HttpEntity<String> entity = new HttpEntity(HttpEntity.EMPTY, headers);
 
         ResponseEntity<InfraActiveRequests> response = restTemplate.exchange(
                 builder.toUriString(),
-                HttpMethod.GET, HttpEntity.EMPTY, InfraActiveRequests.class);
+                HttpMethod.GET,entity , InfraActiveRequests.class);
 
         infraActiveRequestsResponse = response.getBody();
 
diff --git a/adapters/mso-requests-db-adapter/src/test/java/org/onap/so/adapters/requestsdb/adapters/MSORequestDBImplTest.java b/adapters/mso-requests-db-adapter/src/test/java/org/onap/so/adapters/requestsdb/adapters/MSORequestDBImplTest.java
index 4d00421e6c..9ac0cce841 100644
--- a/adapters/mso-requests-db-adapter/src/test/java/org/onap/so/adapters/requestsdb/adapters/MSORequestDBImplTest.java
+++ b/adapters/mso-requests-db-adapter/src/test/java/org/onap/so/adapters/requestsdb/adapters/MSORequestDBImplTest.java
@@ -23,15 +23,20 @@ package org.onap.so.adapters.requestsdb.adapters;
 import static com.shazam.shazamcrest.MatcherAssert.assertThat;
 import static com.shazam.shazamcrest.matcher.Matchers.sameBeanAs;
 import static org.junit.Assert.assertEquals;
+import static org.junit.Assert.assertNotNull;
 import static org.junit.Assert.fail;
 
 import java.util.ArrayList;
 import java.util.List;
-
+import java.util.Map;
+import org.apache.cxf.jaxws.JaxWsProxyFactoryBean;
+import org.junit.Before;
 import org.junit.Rule;
 import org.junit.Test;
 import org.junit.rules.ExpectedException;
 import org.junit.runner.RunWith;
+import org.onap.so.adapters.requestsdb.application.TestAppender;
+import org.onap.logging.ref.slf4j.ONAPLogConstants;
 import org.onap.so.adapters.requestsdb.MsoRequestsDbAdapter;
 import org.onap.so.adapters.requestsdb.RequestStatusType;
 import org.onap.so.adapters.requestsdb.application.MSORequestDBApplication;
@@ -41,12 +46,17 @@ import org.onap.so.db.request.beans.OperationStatus;
 import org.onap.so.db.request.beans.ResourceOperationStatus;
 import org.onap.so.db.request.data.repository.OperationStatusRepository;
 import org.onap.so.db.request.data.repository.ResourceOperationStatusRepository;
+import org.onap.so.logger.MsoLogger;
 import org.onap.so.requestsdb.RequestsDbConstant;
 import org.springframework.beans.factory.annotation.Autowired;
+import org.springframework.beans.factory.annotation.Qualifier;
 import org.springframework.boot.context.embedded.LocalServerPort;
 import org.springframework.boot.test.context.SpringBootTest;
+import org.springframework.context.annotation.Bean;
 import org.springframework.test.context.ActiveProfiles;
+import org.springframework.test.context.ContextConfiguration;
 import org.springframework.test.context.junit4.SpringRunner;
+import ch.qos.logback.classic.spi.ILoggingEvent;
 
 @RunWith(SpringRunner.class)
 @SpringBootTest(classes = MSORequestDBApplication.class, webEnvironment = SpringBootTest.WebEnvironment.RANDOM_PORT)
@@ -55,8 +65,7 @@ public class MSORequestDBImplTest {
 
 	@LocalServerPort
 	private int port;
-	
-	@Autowired
+
 	private MsoRequestsDbAdapter dbAdapter;
 		
     @Autowired
@@ -71,6 +80,16 @@ public class MSORequestDBImplTest {
 	public InfraActiveRequests setupTestEntities()   {	
 		return buildTestRequest();
 	}	
+	
+	@Before
+	public void before(){
+        JaxWsProxyFactoryBean jaxWsProxyFactory = new JaxWsProxyFactoryBean();
+        jaxWsProxyFactory.setServiceClass(MsoRequestsDbAdapter.class);
+        jaxWsProxyFactory.setAddress("http://localhost:" + port + "/services/RequestsDbAdapter");
+        jaxWsProxyFactory.setUsername("bpel");
+        jaxWsProxyFactory.setPassword("password1$");
+        dbAdapter = (MsoRequestsDbAdapter) jaxWsProxyFactory.create();
+	}
 
 	private InfraActiveRequests buildTestRequest() {	
 		InfraActiveRequests testRequest= new InfraActiveRequests();
@@ -94,11 +113,9 @@ public class MSORequestDBImplTest {
 		return testRequest;
 	}
 
-	
-
-
 	@Test
 	public void getByRequestId() throws MsoRequestsDbException  {
+	    
 		InfraActiveRequests testRequest = setupTestEntities();
 		// Given
 		String requestId = "00032ab7-3fb3-42e5-965d-8ea592502017";
@@ -121,10 +138,8 @@ public class MSORequestDBImplTest {
 		try {
 			dbAdapter.getInfraRequest(requestId);
 			fail("Expected MsoRequestsDbException to be thrown");
-		} catch (MsoRequestsDbException e) {
-			assertEquals(e.getMessage(),"Error retrieving MSO Infra Requests DB for Request ID invalidRequestId");
 		} catch (Exception e) {
-			fail("Expected MsoRequestsDbException to be thrown, unknown exception thrown");
+		    assertEquals(e.getMessage(),"Error retrieving MSO Infra Requests DB for Request ID invalidRequestId");
 		}		
 	}
 	
@@ -230,11 +245,9 @@ public class MSORequestDBImplTest {
 					null,
 					null,
 					null);
-			fail("Expected MsoRequestsDbException to be thrown");
-		} catch (MsoRequestsDbException e) {
-			assertEquals(e.getMessage(),"Error retrieving MSO Infra Requests DB for Request ID invalidRequestId");
+			fail("Expected MsoRequestsDbException to be thrown");	
 		} catch (Exception e) {
-			fail("Expected MsoRequestsDbException to be thrown, unknown exception thrown");
+		    assertEquals(e.getMessage(),"Error retrieving MSO Infra Requests DB for Request ID invalidRequestId");
 		}		
 	}
 	
@@ -328,6 +341,7 @@ public class MSORequestDBImplTest {
 	
 	@Test 
 	public void updateServiceOperation_Not_Found() throws MsoRequestsDbException{
+	    TestAppender.events.clear();
 		String serviceId = "badserviceId";
 		String operationId = "operationid";
 		String operation = "newOperationType";
@@ -349,12 +363,35 @@ public class MSORequestDBImplTest {
 		updatedOperationStatus.setProgress(progress);
 		updatedOperationStatus.setReason(reason);
 		updatedOperationStatus.setOperationContent(operationContent);
-		
-		thrown.expect(MsoRequestsDbException.class);
-		thrown.expectMessage("Unable to retrieve OperationStatus Object ServiceId: " + serviceId + " operationId: " + operationId);
-		
-		dbAdapter.updateServiceOperationStatus(serviceId, operationId, operation,  userId,
-	             result, operationContent,  progress, reason);		
+
+		try {
+            dbAdapter.updateServiceOperationStatus(serviceId, operationId, operation,  userId,
+                     result, operationContent,  progress, reason);
+            fail("Expected MsoRequestsDbException to be thrown");   
+        } catch (Exception e) {
+            assertEquals("Entity not found. Unable to retrieve OperationStatus Object ServiceId: " + serviceId + " operationId: " + operationId,e.getMessage());
+            for(ILoggingEvent logEvent : TestAppender.events)
+                if(logEvent.getLoggerName().equals("org.onap.so.logging.cxf.interceptor.SOAPLoggingInInterceptor") &&
+                        logEvent.getMarker().getName().equals("ENTRY")
+                        ){
+                    Map<String,String> mdc = logEvent.getMDCPropertyMap();
+                    assertNotNull(mdc.get(ONAPLogConstants.MDCs.INSTANCE_UUID));
+                    assertNotNull(mdc.get(MsoLogger.REQUEST_ID));
+                    assertNotNull(mdc.get(ONAPLogConstants.MDCs.INVOCATION_ID));
+                    assertEquals("",mdc.get(ONAPLogConstants.MDCs.PARTNER_NAME));
+                    assertEquals("/services/RequestsDbAdapter",mdc.get(ONAPLogConstants.MDCs.SERVICE_NAME));
+                    assertEquals("INPROGRESS",mdc.get(ONAPLogConstants.MDCs.RESPONSE_STATUS_CODE));
+                }else if(logEvent.getLoggerName().equals("org.onap.so.logging.cxf.interceptor.SOAPLoggingOutInterceptor") &&
+                        logEvent.getMarker()!= null && logEvent.getMarker().getName().equals("EXIT")){
+                    Map<String,String> mdc = logEvent.getMDCPropertyMap();
+                    assertNotNull(mdc.get(ONAPLogConstants.MDCs.REQUEST_ID));
+                    assertNotNull(mdc.get(ONAPLogConstants.MDCs.INVOCATION_ID));
+                    assertEquals("500",mdc.get(ONAPLogConstants.MDCs.RESPONSE_CODE));
+                    assertEquals("",mdc.get(ONAPLogConstants.MDCs.PARTNER_NAME));
+                    assertEquals("/services/RequestsDbAdapter",mdc.get(ONAPLogConstants.MDCs.SERVICE_NAME));
+                    assertEquals("ERROR",mdc.get(ONAPLogConstants.MDCs.RESPONSE_STATUS_CODE));
+                }
+        }       	
 		
 	}
 	
@@ -423,6 +460,7 @@ public class MSORequestDBImplTest {
 
 	@Test
 	public void updateResourceOperationStatus() throws MsoRequestsDbException{
+	    TestAppender.events.clear();
 		String resourceTemplateUUID = "template1";
 		String serviceId = "serviceId";
 		String operationId = "operationId";
@@ -454,6 +492,28 @@ public class MSORequestDBImplTest {
 
 		ResourceOperationStatus actualResource = dbAdapter.getResourceOperationStatus(serviceId, operationId,"template1");
 		assertThat(actualResource, sameBeanAs(expectedResource));
+		
+		for(ILoggingEvent logEvent : TestAppender.events)
+            if(logEvent.getLoggerName().equals("org.onap.so.logging.cxf.interceptor.SOAPLoggingInInterceptor") &&
+                    logEvent.getMarker().getName().equals("ENTRY")
+                    ){
+                Map<String,String> mdc = logEvent.getMDCPropertyMap();
+                assertNotNull(mdc.get(ONAPLogConstants.MDCs.INSTANCE_UUID));
+                assertNotNull(mdc.get(MsoLogger.REQUEST_ID));
+                assertNotNull(mdc.get(ONAPLogConstants.MDCs.INVOCATION_ID));
+                assertEquals("",mdc.get(ONAPLogConstants.MDCs.PARTNER_NAME));
+                assertEquals("/services/RequestsDbAdapter",mdc.get(ONAPLogConstants.MDCs.SERVICE_NAME));
+                assertEquals("INPROGRESS",mdc.get(ONAPLogConstants.MDCs.RESPONSE_STATUS_CODE));
+            }else if(logEvent.getLoggerName().equals("org.onap.so.logging.cxf.interceptor.SOAPLoggingOutInterceptor") &&
+                    logEvent.getMarker().getName().equals("EXIT")){
+                Map<String,String> mdc = logEvent.getMDCPropertyMap();
+                assertNotNull(mdc.get(ONAPLogConstants.MDCs.REQUEST_ID));
+                assertNotNull(mdc.get(ONAPLogConstants.MDCs.INVOCATION_ID));
+                assertEquals(null,mdc.get(ONAPLogConstants.MDCs.RESPONSE_CODE));
+                assertEquals("",mdc.get(ONAPLogConstants.MDCs.PARTNER_NAME));
+                assertEquals("/services/RequestsDbAdapter",mdc.get(ONAPLogConstants.MDCs.SERVICE_NAME));
+                assertEquals("COMPLETED",mdc.get(ONAPLogConstants.MDCs.RESPONSE_STATUS_CODE));
+            }
 	}
 
 
diff --git a/adapters/mso-requests-db-adapter/src/test/java/org/onap/so/adapters/requestsdb/application/TestAppender.java b/adapters/mso-requests-db-adapter/src/test/java/org/onap/so/adapters/requestsdb/application/TestAppender.java
new file mode 100644
index 0000000000..0da1fd7565
--- /dev/null
+++ b/adapters/mso-requests-db-adapter/src/test/java/org/onap/so/adapters/requestsdb/application/TestAppender.java
@@ -0,0 +1,37 @@
+/*-
+ * ============LICENSE_START=======================================================
+ * ONAP - SO
+ * ================================================================================
+ * 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.onap.so.adapters.requestsdb.application;
+
+import java.util.ArrayList;
+import java.util.List;
+import ch.qos.logback.classic.spi.ILoggingEvent;
+import ch.qos.logback.core.AppenderBase;
+
+
+
+public class TestAppender  extends AppenderBase<ILoggingEvent> {
+    public static List<ILoggingEvent> events = new ArrayList<>();
+ 
+	@Override
+	public void append(ILoggingEvent loggingEvent) {
+		events.add(loggingEvent);		
+	}
+}
diff --git a/adapters/mso-requests-db-adapter/src/test/resources/application-test.yaml b/adapters/mso-requests-db-adapter/src/test/resources/application-test.yaml
index 49582ec513..165b6675dc 100644
--- a/adapters/mso-requests-db-adapter/src/test/resources/application-test.yaml
+++ b/adapters/mso-requests-db-adapter/src/test/resources/application-test.yaml
@@ -1,5 +1,7 @@
 # will be used as entry in DB to say SITE OFF/ON for healthcheck
-
+security:
+  basic:
+    enabled: false
 server:
     port: 8080
     tomcat:
@@ -8,7 +10,7 @@ ssl-enable: false
 mso:
   adapters:
     requestDb:
-      auth: Basic YnBlbDptc28tZGItMTUwNyE=
+      auth: Basic YnBlbDpwYXNzd29yZDEk
       endpoint: http://localhost:8081
   logPath: logs
   site-name: localSite
@@ -34,8 +36,8 @@ spring:
   security:
     usercredentials:
     -  
-      username: test
-      password: '$2a$12$Zi3AuYcZoZO/gBQyUtST2.F5N6HqcTtaNci2Et.ufsQhski56srIu'
+      username: bpel
+      password: '$2a$10$Fh9ffgPw2vnmsghsRD3ZauBL1aKXebigbq3BB1RPWtE62UDILsjke'
       role: BPEL-Client
 mariaDB4j:
   dataDir: 
diff --git a/adapters/mso-requests-db-adapter/src/test/resources/logback-test.xml b/adapters/mso-requests-db-adapter/src/test/resources/logback-test.xml
index 54fa1cdd65..d1596cd374 100644
--- a/adapters/mso-requests-db-adapter/src/test/resources/logback-test.xml
+++ b/adapters/mso-requests-db-adapter/src/test/resources/logback-test.xml
@@ -1,33 +1,55 @@
 <configuration>
-  
-  
-  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
-    <encoder>
-      <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{1024} - %msg%n</pattern>
-    </encoder>
-  </appender>
-
-
-  <logger name="com.att.ecomp.audit" level="info" additivity="false">
-    <appender-ref ref="STDOUT" />
-  </logger>
-  
-  <logger name="com.att.eelf.metrics" level="info" additivity="false">
-        <appender-ref ref="STDOUT" />
-  </logger>
+	<property name="p_tim" value="%d{&quot;yyyy-MM-dd'T'HH:mm:ss.SSSXXX&quot;, UTC}"/>
+    <property name="p_lvl" value="%level"/>
+    <property name="p_log" value="%logger"/>
+    <property name="p_mdc" value="%replace(%replace(%mdc){'\t','\\\\t'}){'\n', '\\\\n'}"/>
+    <property name="p_msg" value="%replace(%replace(%msg){'\t', '\\\\t'}){'\n','\\\\n'}"/>
+    <property name="p_exc" value="%replace(%replace(%rootException){'\t', '\\\\t'}){'\n','\\\\n'}"/>
+    <property name="p_mak" value="%replace(%replace(%marker){'\t', '\\\\t'}){'\n','\\\\n'}"/>
+    <property name="p_thr" value="%thread"/>
+    <property name="pattern" value="%nopexception${p_tim}\t${p_thr}\t${p_lvl}\t${p_log}\t${p_mdc}\t${p_msg}\t${p_exc}\t${p_mak}\t%n"/>
+
+
+	<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
+		<encoder>
+			<pattern>${pattern}</pattern>
+		</encoder>
+	</appender>
+
+	<appender name="test"
+		class="org.onap.so.adapters.requestsdb.application.TestAppender" />
+
+	<logger name="com.att.ecomp.audit" level="info" additivity="false">
+		<appender-ref ref="STDOUT" />
+	</logger>
+
+	<logger name="com.att.eelf.metrics" level="info" additivity="false">
+		<appender-ref ref="STDOUT" />
+	</logger>
+
+	<logger name="com.att.eelf.error" level="WARN" additivity="false">
+		<appender-ref ref="STDOUT" />
+	</logger>
 
-  <logger name="com.att.eelf.error" level="trace" additivity="false">
-    <appender-ref ref="STDOUT" />
-  </logger> 
-  
 	<logger name="org.onap" level="${so.log.level:-DEBUG}" additivity="false">
 		<appender-ref ref="STDOUT" />
+		<appender-ref ref="test" />
 	</logger>
-        <logger name="org.flywaydb" level="DEBUG" additivity="false">
+	
+	<logger name="org.flywaydb" level="DEBUG" additivity="false">
         <appender-ref ref="STDOUT" />
     </logger>
-  <root level="WARN">
-    <appender-ref ref="STDOUT" />
-  </root>
-  
+	
+
+	<logger name="ch.vorburger" level="WARN" additivity="false">
+		<appender-ref ref="STDOUT" />
+	</logger>
+	
+
+	<root level="WARN">
+		<appender-ref ref="STDOUT" />
+		<appender-ref ref="test" />
+	</root>
+
+
 </configuration>
\ No newline at end of file