From f7cb11a5d53d4964c236a6ecb2e2f4264f2437fd Mon Sep 17 00:00:00 2001 From: sourabh_sourabh Date: Tue, 8 Feb 2022 23:02:27 +0530 Subject: 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 Change-Id: I93a556fe0fb7ca05a42e84eb5ec4f84afaa8fd92 --- .../org/onap/cps/aop/CpsLoggingAspectService.java | 42 ++++++++++++---------- .../cps/aop/CpsLoggingAspectServiceSpec.groovy | 33 ++++++++++------- 2 files changed, 43 insertions(+), 32 deletions(-) (limited to 'cps-service') 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 } } -- cgit 1.2.3-korg