Improve logging in NCMP

- Code to change to apply logs at runtime
- Fix for minor code smell

Issue-ID: CPS-855
Signed-off-by: sourabh_sourabh <sourabh.sourabh@est.tech>
Change-Id: I93a556fe0fb7ca05a42e84eb5ec4f84afaa8fd92

2 files changed, 43 insertions, 32 deletions

diff --git a/cps-service/src/main/java/org/onap/cps/aop/CpsLoggingAspectService.java b/cps-service/src/main/java/org/onap/cps/aop/CpsLoggingAspectService.java
index 20c6af6c3..b5fe0abae 100644
--- a/cps-service/src/main/java/org/onap/cps/aop/CpsLoggingAspectService.java
+++ b/cps-service/src/main/java/org/onap/cps/aop/CpsLoggingAspectService.java
@@ -21,49 +21,53 @@
 package org.onap.cps.aop;
 
 import java.util.Arrays;
-import java.util.Optional;
+import java.util.logging.Level;
+import java.util.logging.Logger;
 import lombok.SneakyThrows;
 import lombok.extern.slf4j.Slf4j;
 import org.aspectj.lang.ProceedingJoinPoint;
 import org.aspectj.lang.annotation.Around;
 import org.aspectj.lang.annotation.Aspect;
 import org.aspectj.lang.reflect.MethodSignature;
-import org.springframework.boot.autoconfigure.condition.ConditionalOnExpression;
 import org.springframework.stereotype.Component;
 import org.springframework.util.StopWatch;
 
 @Aspect
 @Component
 @Slf4j
-@ConditionalOnExpression(
-        "'${logging.level.org.onap.cps}'.equalsIgnoreCase('DEBUG')"
-)
 public class CpsLoggingAspectService {
 
-    private static final String ALL_CPS_METHODS = "execution(* org.onap.cps..*(..)))";
+    private static final String CPS_PACKAGE_NAME = "org.onap.cps";
+    private static final String ALL_CPS_METHODS = "execution(* " + CPS_PACKAGE_NAME + "..*(..)))";
 
     /**
      * To measure method execution time as a logging.
+     *
      * @param proceedingJoinPoint exposes the proceed(..) method in order to support around advice.
      * @return empty in case of void otherwise an object of return type
      */
     @Around(ALL_CPS_METHODS)
     @SneakyThrows
     public Object logMethodExecutionTime(final ProceedingJoinPoint proceedingJoinPoint) {
-        final StopWatch stopWatch = new StopWatch();
-
-        //Calculate method execution time
-        stopWatch.start();
-        final Object logObject = Optional.ofNullable(proceedingJoinPoint.proceed()).orElse("");
-        stopWatch.stop();
-        final MethodSignature methodSignature = (MethodSignature) proceedingJoinPoint.getSignature();
-        //Log method execution time
-        log.debug("Execution time of : {}.{}() with argument[s] = {} having result = {} :: {} ms",
-                methodSignature.getDeclaringType().getSimpleName(),
-                methodSignature.getName(), Arrays.toString(proceedingJoinPoint.getArgs()), logObject,
-                stopWatch.getTotalTimeMillis());
+        if (isSlf4JDebugEnabled()) {
+            final StopWatch stopWatch = new StopWatch();
+            //Calculate method execution time
+            stopWatch.start();
+            final Object returnValue = proceedingJoinPoint.proceed();
+            stopWatch.stop();
+            final MethodSignature methodSignature = (MethodSignature) proceedingJoinPoint.getSignature();
+            //Log method execution time
+            log.debug("Execution time of : {}.{}() with argument[s] = {} having result = {} :: {} ms",
+                    methodSignature.getDeclaringType().getSimpleName(),
+                    methodSignature.getName(), Arrays.toString(proceedingJoinPoint.getArgs()), returnValue,
+                    stopWatch.getTotalTimeMillis());
+            return returnValue;
+        }
+        return proceedingJoinPoint.proceed();
+    }
 
-        return logObject;
+    private static boolean isSlf4JDebugEnabled() {
+        return Logger.getLogger(CPS_PACKAGE_NAME).isLoggable(Level.FINE);
     }
 
 }
diff --git a/cps-service/src/test/groovy/org/onap/cps/aop/CpsLoggingAspectServiceSpec.groovy b/cps-service/src/test/groovy/org/onap/cps/aop/CpsLoggingAspectServiceSpec.groovy
index b15af490e..1308bd729 100644
--- a/cps-service/src/test/groovy/org/onap/cps/aop/CpsLoggingAspectServiceSpec.groovy
+++ b/cps-service/src/test/groovy/org/onap/cps/aop/CpsLoggingAspectServiceSpec.groovy
@@ -24,9 +24,13 @@ import org.aspectj.lang.ProceedingJoinPoint
 import org.aspectj.lang.reflect.MethodSignature
 import org.onap.cps.spi.exceptions.DataValidationException
 import spock.lang.Specification
+import java.util.logging.Level
+import java.util.logging.Logger
 
 class CpsLoggingAspectServiceSpec extends Specification {
 
+    private static final Logger logger = Logger.getLogger("org.onap.cps")
+
     def mockProceedingJoinPoint = Mock(ProceedingJoinPoint)
     def mockMethodSignature = Mock(MethodSignature);
     def objectUnderTest = new CpsLoggingAspectService()
@@ -38,24 +42,27 @@ class CpsLoggingAspectServiceSpec extends Specification {
         mockProceedingJoinPoint.getSignature() >> mockMethodSignature
     }
 
-    def 'Log method execution time.'() {
-        given: 'mock valid arguments'
+    def 'Log method execution time for log level : #logLevel.'() {
+        given: 'mock valid pointcut arguments and set log level to #logLevel'
             mockProceedingJoinPoint.getArgs() >> 'dataspace-name'
-        when: 'aop intercepts cps method and start calculation of time'
+            logger.setLevel(logLevel)
+        when: 'aop intercepts cps method'
             objectUnderTest.logMethodExecutionTime(mockProceedingJoinPoint)
-        then: 'process successfully and log details of executed method'
-            1 * mockProceedingJoinPoint.proceed()
+        then: 'expected number of method execution'
+            expectedNumberOfMethodExecution * mockMethodSignature.getName()
+        where: 'the following log levels are used'
+            logLevel     || expectedNumberOfMethodExecution
+            Level.INFO   || 0
+            Level.FINE   || 1
+            Level.FINEST || 1
     }
 
-    def 'Creating a data validation exception for invalid args.'() {
-        given: 'a data validation exception is created'
-            mockProceedingJoinPoint.getArgs() >> {
-                throw new DataValidationException('invalid args',
-                        'invalid method arg(s) is passed', new Throwable())
-            }
+    def 'Exception thrown during method execution.'() {
+        given: 'some exception is created'
+            mockProceedingJoinPoint.proceed() >> { throw new Exception("some exception") }
         when: 'aop intercepts cps method and start calculation of time'
             objectUnderTest.logMethodExecutionTime(mockProceedingJoinPoint)
-        then: 'data validation exception is thrown'
-            thrown(DataValidationException.class)
+        then: 'some exception is thrown'
+            thrown Exception
     }
 }