Issue #145 feat:Performance logging added

java/middleware/registry-middleware/authorization/src/main/java/io/opensaber/registry/authorization/AuthorizationFilter.java

@@ -20,6 +20,8 @@
 import io.opensaber.registry.middleware.MiddlewareHaltException;
 import io.opensaber.registry.middleware.util.Constants;
 import org.apache.commons.codec.binary.Base64;
+import org.perf4j.StopWatch;
+import org.perf4j.LoggingStopWatch;
 
 public class AuthorizationFilter implements BaseMiddleware {
 
@@ -31,6 +33,7 @@ public class AuthorizationFilter implements BaseMiddleware {
 
     public KeyCloakServiceImpl keyCloakServiceImpl;
 
+
     public AuthorizationFilter() {}
 
     public AuthorizationFilter(KeyCloakServiceImpl keyCloakServiceImpl) {
@@ -50,7 +53,9 @@ public Map<String, Object> execute(Map<String, Object> mapObject) throws Middlew
           }
           String token = tokenObject.toString();
           try {
+              StopWatch stopWatch = new LoggingStopWatch();
               if (!keyCloakServiceImpl.verifyToken(token).trim().isEmpty()) {
+                  stopWatch.stop("KeyCloak Authentication","Performance Monitoring !");
                   if (mapObject.containsKey("userName")) {
                       logger.info("Access token for user {} verified successfully with KeyCloak server !", mapObject.get("userName"));
                   } else {

java/registry/src/main/java/io/opensaber/registry/app/OpenSaberApplication.java

@@ -1,5 +1,7 @@
 package io.opensaber.registry.app;
 
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 import org.springframework.boot.SpringApplication;
 import org.springframework.boot.autoconfigure.SpringBootApplication;
 import org.springframework.context.annotation.ComponentScan;
@@ -8,8 +10,16 @@
 @ComponentScan({"io.opensaber.registry"})
 public class OpenSaberApplication {
 
+    private static Logger logger = LoggerFactory.getLogger(OpenSaberApplication.class);
     public static void main(String[] args) {
+        logger.info("****************************************************");
+        logger.info("         Welcome to Opensaber Application                     ");
+        logger.info("****************************************************");
+
         SpringApplication.run(OpenSaberApplication.class, args);
     }
 
+
+
+
 }

java/registry/src/main/java/io/opensaber/registry/service/impl/EncryptionServiceImpl.java

@@ -44,7 +44,6 @@ public String encrypt(Object propertyValue) throws EncryptionException {
 		HttpEntity<MultiValueMap<String, Object>> request = new HttpEntity<MultiValueMap<String, Object>>(map);
 		try {
 			ResponseEntity<String> response = new RestTemplate().postForEntity(encryptionUri, request, String.class);
-			logger.info("Property encrypted successfully !");
 		   	return response.getBody();
 		}catch(ResourceAccessException e) {
 			logger.error("ResourceAccessException while connecting enryption service : ", e);
@@ -59,14 +58,13 @@ public String encrypt(Object propertyValue) throws EncryptionException {
 	}
 
 	@Override
-     public String decrypt(Object propertyValue) throws EncryptionException {		
-						
+     public String decrypt(Object propertyValue) throws EncryptionException {
+
 		MultiValueMap<String, Object> map= new LinkedMultiValueMap<String, Object>();
 		map.add("value", propertyValue);
 		HttpEntity<MultiValueMap<String, Object>> request = new HttpEntity<MultiValueMap<String, Object>>(map);
 		try {
 			ResponseEntity<String>  response = new RestTemplate().postForEntity(decryptionUri, request, String.class);
-			logger.info("Property decrypted successfully !");
 			return response.getBody();
 		}catch(ResourceAccessException e) {
 	    	logger.error("ResourceAccessException while connecting dcryption service : ", e);

java/registry/src/main/java/io/opensaber/registry/service/impl/RegistryServiceImpl.java

@@ -89,21 +89,13 @@ public String addEntity(Model rdfModel) throws DuplicateRecordException, EntityC
 	@Override
 	public String addEntity(Model rdfModel, String subject, String property) throws DuplicateRecordException, EntityCreationException,
 	EncryptionException, AuditFailedException, MultipleEntityException, RecordNotFoundException {
-		try {
-			String label = getRootLabel(rdfModel);
-			Graph graph = generateGraphFromRDF(rdfModel);
-
-			// Append _: to the root node label to create the entity as Apache Jena removes the _: for the root node label
-			// if it is a blank node
-			logger.debug("RegistryServiceImpl : adding subject : {} with property : {}",subject,property);
-			return registryDao.addEntity(graph, label, subject, property);
+		String label = getRootLabel(rdfModel);
+		Graph graph = generateGraphFromRDF(rdfModel);
 
-		} catch (EntityCreationException | EncryptionException | AuditFailedException ex) {
-			throw ex;
-		} catch (Exception ex) {
-			logger.error("RegistryServiceImpl : Exception when creating entity: ", ex);
-			throw ex;
-		}
+		// Append _: to the root node label to create the entity as Apache Jena removes the _: for the root node label
+		// if it is a blank node
+		logger.debug("RegistryServiceImpl : adding subject : {} with property : {}", subject, property);
+		return registryDao.addEntity(graph, label, subject, property);
 	}
 
 	@Override

java/registry/src/main/resources/logback.xml

@@ -1,8 +1,6 @@
 <configuration>
 
     <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
-        <!-- encoders are assigned the type
-     ch.qos.logback.classic.encoder.PatternLayoutEncoder by default -->
         <encoder>
             <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
         </encoder>
@@ -19,7 +17,18 @@
         </rollingPolicy>
 
         <encoder>
-            <pattern>%d{HH:mm:ss.SSS}  %-4relative [%thread] %-5level %logger{35} - %msg%n</pattern>
+            <pattern>%d{HH:mm:ss.SSS} %-4relative [%thread] %-5level %logger{35} - %msg%n</pattern>
+        </encoder>
+    </appender>
+
+    <appender name="PERF_FILE_OUT" class="ch.qos.logback.core.FileAppender">
+        <file>logs/performance_instrumentation.log</file>
+        <append>true</append>
+        <immediateFlush>true</immediateFlush>
+        <encoder>
+            # Pattern of log message for file appender
+            <!--<pattern>%d{yyyy-MM-dd HH:mm:ss} %-5p %m%n</pattern>-->
+             <pattern>%-4relative [%thread] %-5level %logger{35} - %msg%n</pattern>
         </encoder>
     </appender>
 
@@ -29,6 +38,11 @@
     <logger name="io.opensaber.registry.dao.impl.RegistryDaoImpl" level="ERROR"/>
     <logger name="org.springframework" level="ERROR"/>
 
+
+    <logger name="PERFORMANCE_INSTRUMENTATION" level="TRACE" additivity="false">
+        <appender-ref ref="PERF_FILE_OUT"/>
+    </logger>
+
     <root level="info" additivity="false">
         <appender-ref ref="STDOUT"/>
         <appender-ref ref="FILE"/>

java/registry/src/test/java/io/opensaber/registry/dao/impl/EncryptionDaoImplTest.java

@@ -26,6 +26,8 @@
 import org.mockito.Mock;
 import org.mockito.Mockito;
 import org.mockito.MockitoAnnotations;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 import org.springframework.beans.factory.annotation.Autowired;
 import org.springframework.beans.factory.annotation.Value;
 import org.springframework.boot.test.context.SpringBootTest;
@@ -75,7 +77,7 @@
 @FixMethodOrder(MethodSorters.NAME_ASCENDING)
 @ActiveProfiles(Constants.TEST_ENVIRONMENT)
 public class EncryptionDaoImplTest extends RegistryTestBase {
-
+	private static Logger logger = LoggerFactory.getLogger(EncryptionDaoImplTest.class);
 	@Rule
 	public ExpectedException expectedEx = ExpectedException.none();
 
@@ -108,17 +110,17 @@ public class EncryptionDaoImplTest extends RegistryTestBase {
 	public TestRule watcher = new TestWatcher() {
 		@Override
 		protected void starting(Description description) {
-			System.out.println("Executing test: " + description.getMethodName());
+			logger.debug("Executing test: " + description.getMethodName());
 		}
 
 		@Override
 		protected void succeeded(Description description) {
-			System.out.println("Successfully executed test: " + description.getMethodName());
+			logger.debug("Successfully executed test: " + description.getMethodName());
 		}
 
 		@Override
 		protected void failed(Throwable e, Description description) {
-			System.out.println(String.format("Test %s failed. Error message: %s", description.getMethodName(), e.getMessage()));
+			logger.debug(String.format("Test %s failed. Error message: %s", description.getMethodName(), e.getMessage()));
 		}
 	};
 

java/registry/src/test/java/io/opensaber/registry/dao/impl/RegistryDaoImplTest.java

@@ -26,6 +26,8 @@
 import org.mockito.Mock;
 import org.mockito.Mockito;
 import org.mockito.MockitoAnnotations;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 import org.springframework.beans.factory.annotation.Autowired;
 import org.springframework.beans.factory.annotation.Value;
 import org.springframework.boot.test.context.SpringBootTest;
@@ -75,7 +77,7 @@
 @FixMethodOrder(MethodSorters.NAME_ASCENDING)
 @ActiveProfiles(Constants.TEST_ENVIRONMENT)
 public class RegistryDaoImplTest extends RegistryTestBase {
-
+	private static Logger logger = LoggerFactory.getLogger(RegistryDaoImplTest.class);
 	@Rule
 	public ExpectedException expectedEx = ExpectedException.none();
 
@@ -111,17 +113,17 @@ public class RegistryDaoImplTest extends RegistryTestBase {
 	public TestRule watcher = new TestWatcher() {
 		@Override
 		protected void starting(Description description) {
-			System.out.println("Executing test: " + description.getMethodName());
+			logger.debug("Executing test: " + description.getMethodName());
 		}
 
 		@Override
 		protected void succeeded(Description description) {
-			System.out.println("Successfully executed test: " + description.getMethodName());
+			logger.debug("Successfully executed test: " + description.getMethodName());
 		}
 
 		@Override
 		protected void failed(Throwable e, Description description) {
-			System.out.println(String.format("Test %s failed. Error message: %s", description.getMethodName(), e.getMessage()));
+			logger.debug(String.format("Test %s failed. Error message: %s", description.getMethodName(), e.getMessage()));
 		}
 	};
 
@@ -299,14 +301,14 @@ public void test_adding_shared_nodes_with_new_properties() throws DuplicateRecor
 		Model rdfModel = getNewValidRdf();
 		TinkerGraph graph = TinkerGraph.open();
 		String rootLabel = updateGraphFromRdf(rdfModel, graph);
-		System.out.println("PRINTING MODEL TO ADD");
+		logger.debug("-------- MODEL TO ADD----------");
         printModel(rdfModel);
         String newEntityResponse;
         newEntityResponse = registryDao.addEntity(graph, String.format("_:%s", rootLabel));
         Graph entity = registryDao.getEntityById(newEntityResponse);
-        System.out.println("CHECKING AUDIT RECORDS");
+        logger.debug("-------- CHECKING AUDIT RECORDS-------");
         int count1 = checkIfAuditRecordsAreRight(entity, null);
-        System.out.println("AUDIT RECORDS "+count1);
+        logger.debug("--------- AUDIT RECORDS -------"+count1);
 		// Create a new TinkerGraph with the existing jsonld
 		Graph newEntityGraph = TinkerGraph.open();
 		Model newRdfModel = getNewValidRdf();
@@ -326,7 +328,7 @@ public void test_adding_shared_nodes_with_new_properties() throws DuplicateRecor
 		newEntityResponse = registryDao.addEntity(newEntityGraph, String.format("_:%s", newRootLabel));
 		entity = registryDao.getEntityById(newEntityResponse);
         int count2 = checkIfAuditRecordsAreRight(entity, null);
-        System.out.println("AUDIT RECORDS "+count2);
+        logger.debug("------- AUDIT RECORDS ------"+count2);
 		String propertyValue = (String) entity.traversal().clone().V()
 			.properties("http://example.com/voc/teacher/1.0.0/districtAlias")
 			.next()
@@ -339,7 +341,7 @@ public void test_adding_shared_nodes_with_new_properties() throws DuplicateRecor
     private void printModel(Model rdfModel) {
         Iterator iter = rdfModel.listStatements();
         while(iter.hasNext()){
-            System.out.println(iter.next());
+            logger.debug("-------next iterator in printModel() : {} ",iter.next());
 }
     }
 
@@ -519,7 +521,7 @@ public void test_update_single_literal_node()
 
     private Model getModelwithOnlyUpdateFacts(Model rdfModel, Model updateRdfModel, List<String> predicatedToExclude) {
     	Model updatedFacts = updateRdfModel.difference(rdfModel);
-    	System.out.println("UPDATED FACTS are:"+updatedFacts);
+    	logger.debug("-------- UPDATED FACTS are: ----------"+updatedFacts);
        /* Property propertyToRemove;
         propertyToRemove=ResourceFactory.createProperty("http://www.w3.org/1999/02/22-rdf-syntax-ns#type");
         Model updateRdfModelWithoutType = restrictModel(updateRdfModel,propertyToRemove);
@@ -556,12 +558,12 @@ private Model getModelwithDeletedFacts(Model rdfModel, Model updateRdfModel, Mod
     			}
     		}
     	}
-    	System.out.println("DELETED FACTS are:"+deletedFacts);
+    	logger.debug("------- DELETED FACTS are: --------"+deletedFacts);
         return deletedFacts;
     }
 
     private Model restrictModel(Model updateRdfModel,Property property) {
-	    System.out.println("Removing "+property);
+	    logger.debug("--------Removing property :  "+property);
         return updateRdfModel.difference(
                     updateRdfModel.listStatements(
                             null,
@@ -590,7 +592,7 @@ private Map<String, Map<String, Integer>> generateUpdateMapFromRDF(Model updateR
                 map.put(subject,innerMap);
             }
         }
-        System.out.println("generateUpdateMapFromRDF "+map);
+        logger.debug("generateUpdateMapFromRDF "+map);
         return map;
     }
 
@@ -608,7 +610,7 @@ private Map<String, Map<String, Integer>> generateUpdateMapFromRDF(Model updateR
             	encounteredSubPred.put(subject.toString(), predicate.toString());
     			StmtIterator diffIter = deletedFacts.listStatements(subject, predicate, (RDFNode)null);
     			deletedCount = (int)IteratorUtils.count(diffIter);
-    			System.out.println(String.format("Number of facts deleted for %s and %s : %d",subject.toString(), predicate.toString(),deletedCount));
+    			logger.debug(String.format("Number of facts deleted for %s and %s : %d",subject.toString(), predicate.toString(),deletedCount));
             }
             if(map.containsKey(subject.toString())){
                 Map<String, Integer> innerMap = map.get(subject.toString());
@@ -623,7 +625,7 @@ private Map<String, Map<String, Integer>> generateUpdateMapFromRDF(Model updateR
                 map.put(subject.toString(),innerMap);
             }
         }
-        System.out.println("generateUpdateMapFromRDF "+map);
+       logger.debug("generateUpdateMapFromRDF "+map);
         return map;
     }
 
@@ -846,7 +848,7 @@ private String getJsonldFromGraph(Graph entity, String rootLabel) {
 		try {
 			jsonldOutput = RDFUtil.frameEntity(model);
 		} catch (IOException ex) {
-			System.out.println("IO Exception = " + ex);
+			logger.debug("IO Exception = " + ex);
 		}
 		return jsonldOutput;
 	}

java/registry/src/test/java/io/opensaber/registry/service/impl/RegistryEncryptionServiceImplTest.java

@@ -10,7 +10,6 @@
 import org.junit.Test;
 import org.junit.rules.ExpectedException;
 import org.junit.runner.RunWith;
-import org.mockito.InjectMocks;
 import org.mockito.Mock;
 import org.springframework.beans.factory.annotation.Autowired;
 import org.springframework.boot.test.context.SpringBootTest;
@@ -21,7 +20,6 @@
 import io.opensaber.registry.config.GenericConfiguration;
 import io.opensaber.registry.controller.RegistryTestBase;
 import io.opensaber.registry.middleware.util.Constants;
-import io.opensaber.registry.model.AuditRecord;
 import io.opensaber.registry.schema.config.SchemaConfigurator;
 import io.opensaber.registry.service.EncryptionService;