TSK-1719: optimized LoggingAspect

This commit is contained in:
Mustapha Zorgati 2021-08-25 10:05:44 +02:00
parent 14baeb8bc1
commit b0569dee8b
6 changed files with 123 additions and 67 deletions

View File

@ -42,6 +42,11 @@
<artifactId>assertj-core</artifactId>
<scope>test</scope>
</dependency>
<dependency>
<groupId>org.mockito</groupId>
<artifactId>mockito-inline</artifactId>
<scope>test</scope>
</dependency>
</dependencies>
<build>

View File

@ -14,9 +14,11 @@ import org.aspectj.lang.reflect.MethodSignature;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
@NoLogging
@Aspect
public class LoggingAspect {
public static final String ENABLE_LOGGING_ASPECT_PROPERTY_KEY = "enableLoggingAspect";
private static final Map<String, Logger> CLASS_TO_LOGGER = new ConcurrentHashMap<>();
@Pointcut(
@ -24,50 +26,61 @@ public class LoggingAspect {
+ " && !within(@pro.taskana.common.internal.logging.NoLogging *)"
+ " && execution(* pro.taskana..*(..))"
+ " && !execution(* lambda*(..))"
+ " && !execution(* access*(..))"
+ " && !execution(String *.toString())"
+ " && !execution(int *.hashCode())"
+ " && !execution(boolean *.canEqual(Object))"
+ " && !execution(boolean *.equals(Object))")
public void traceLogging() {}
// This method exists, so that we can mock the system property during testing.
public static boolean isLoggingAspectEnabled() {
return LazyHolder.LOGGING_ASPECT_ENABLED;
}
@Before("traceLogging()")
public void beforeMethodExecuted(JoinPoint joinPoint) {
MethodSignature methodSignature = (MethodSignature) joinPoint.getSignature();
String declaringTypeName = methodSignature.getDeclaringTypeName();
Logger currentLogger =
CLASS_TO_LOGGER.computeIfAbsent(declaringTypeName, LoggerFactory::getLogger);
if (isLoggingAspectEnabled()) {
MethodSignature methodSignature = (MethodSignature) joinPoint.getSignature();
String declaringTypeName = methodSignature.getDeclaringTypeName();
Logger currentLogger =
CLASS_TO_LOGGER.computeIfAbsent(declaringTypeName, LoggerFactory::getLogger);
if (currentLogger.isTraceEnabled()) {
String methodName = methodSignature.getName();
Object[] values = joinPoint.getArgs();
String[] parameterNames = methodSignature.getParameterNames();
String parametersValues = mapParametersNameValue(parameterNames, values);
if (currentLogger.isTraceEnabled()) {
String methodName = methodSignature.getName();
Object[] values = joinPoint.getArgs();
String[] parameterNames = methodSignature.getParameterNames();
String parametersValues = mapParametersNameValue(parameterNames, values);
currentLogger.trace("entry to {}({})", methodName, parametersValues);
currentLogger.trace("entry to {}({})", methodName, parametersValues);
}
}
}
@AfterReturning(pointcut = "traceLogging()", returning = "returnedObject")
public void afterMethodExecuted(JoinPoint joinPoint, Object returnedObject) {
MethodSignature methodSignature = (MethodSignature) joinPoint.getSignature();
String declaringTypeName = methodSignature.getDeclaringTypeName();
Logger currentLogger =
CLASS_TO_LOGGER.computeIfAbsent(declaringTypeName, LoggerFactory::getLogger);
if (isLoggingAspectEnabled()) {
MethodSignature methodSignature = (MethodSignature) joinPoint.getSignature();
String declaringTypeName = methodSignature.getDeclaringTypeName();
Logger currentLogger =
CLASS_TO_LOGGER.computeIfAbsent(declaringTypeName, LoggerFactory::getLogger);
if (currentLogger.isTraceEnabled()) {
String methodName = methodSignature.getName();
// unfortunately necessary, because this method returns a raw type
Class<?> returnType = methodSignature.getReturnType();
if (returnType.isAssignableFrom(void.class)) {
currentLogger.trace("exit from {}.", methodName);
} else {
currentLogger.trace(
"exit from {}. Returning: '{}'", methodName, Objects.toString(returnedObject, "null"));
if (currentLogger.isTraceEnabled()) {
String methodName = methodSignature.getName();
// unfortunately necessary, because this method returns a raw type
Class<?> returnType = methodSignature.getReturnType();
if (returnType.isAssignableFrom(void.class)) {
currentLogger.trace("exit from {}.", methodName);
} else {
currentLogger.trace(
"exit from {}. Returning: '{}'",
methodName,
Objects.toString(returnedObject, "null"));
}
}
}
}
@NoLogging
private static String mapParametersNameValue(String[] parameterNames, Object[] values) {
Map<String, Object> parametersNameToValue = new HashMap<>();
@ -83,4 +96,13 @@ public class LoggingAspect {
}
return stringBuilder.toString();
}
// This Initialization-on-demand holder idiom is necessary so that the retrieval of the system
// property will be executed during the execution of the first JointPoint.
// This allows us to set the system property during test execution BEFORE retrieving the system
// property.
private static class LazyHolder {
private static final boolean LOGGING_ASPECT_ENABLED =
"true".equals(System.getProperty(ENABLE_LOGGING_ASPECT_PROPERTY_KEY));
}
}

View File

@ -3,8 +3,12 @@ package pro.taskana.common.internal.logging;
import static org.assertj.core.api.Assertions.assertThat;
import org.assertj.core.api.Condition;
import org.junit.jupiter.api.BeforeAll;
import org.junit.jupiter.api.BeforeEach;
import org.junit.jupiter.api.Test;
import org.mockito.MockedStatic;
import org.mockito.Mockito;
import org.mockito.internal.stubbing.answers.CallsRealMethods;
import outside.of.pro.taskana.OutsideOfProTaskanaPackageLoggingTestClass;
import uk.org.lidalia.slf4jext.Level;
import uk.org.lidalia.slf4jtest.LoggingEvent;
@ -13,6 +17,7 @@ import uk.org.lidalia.slf4jtest.TestLoggerFactory;
import pro.taskana.AtProTaskanaRootPackageLoggingTestClass;
@NoLogging
class LoggingAspectTest {
@BeforeEach
@ -20,6 +25,11 @@ class LoggingAspectTest {
TestLoggerFactory.clear();
}
@BeforeAll
public static void setup() {
System.setProperty(LoggingAspect.ENABLE_LOGGING_ASPECT_PROPERTY_KEY, "true");
}
@Test
void should_NotLogMethodCalls_When_ClassDoesNotResideWithinTaskanaPackage() {
OutsideOfProTaskanaPackageLoggingTestClass loggingTestClass =
@ -52,6 +62,20 @@ class LoggingAspectTest {
verifyLoggingStatement(logger, "logInternalMethod", "", null);
}
@Test
void should_NotLogInternalMethod_When_SystemPropertyIsNotSet() {
LoggingTestClass loggingTestClass = new LoggingTestClass();
TestLogger logger = TestLoggerFactory.getTestLogger(loggingTestClass.getClass());
try (MockedStatic<LoggingAspect> loggingAspectMockedStatic =
Mockito.mockStatic(LoggingAspect.class, new CallsRealMethods())) {
loggingAspectMockedStatic.when(LoggingAspect::isLoggingAspectEnabled).thenReturn(false);
loggingTestClass.logInternalMethod();
}
assertThat(logger.getLoggingEvents()).isEmpty();
}
@Test
void should_LogInternalMethodWithReturnValue_When_ClassResidesAtTaskanaSubPackage() {
LoggingTestClass loggingTestClass = new LoggingTestClass();
@ -165,47 +189,4 @@ class LoggingAspectTest {
assertThat(exitLoggingEvent.getArguments()).containsExactly(methodName, returnValue);
}
}
static class LoggingTestClass {
public void logInternalMethod() {}
@SuppressWarnings("UnusedReturnValue")
public String logInternalMethodWithReturnValue() {
return "test string";
}
@SuppressWarnings("UnusedReturnValue")
public String logInternalMethodWithReturnValueNull() {
return null;
}
@SuppressWarnings("unused")
public void logInternalMethodWithArguments(String param) {}
@SuppressWarnings({"UnusedReturnValue", "unused"})
public String logInternalMethodWithReturnValueAndArguments(String param) {
return "return value";
}
public void logInternalMethodWrapper() {
logInternalMethodPrivate();
}
@SuppressWarnings("unused")
public void callsExternalMethod() {
String sum = String.valueOf(5);
}
@NoLogging
public void doNotLogInternalMethod() {}
private void logInternalMethodPrivate() {}
}
@NoLogging
static class NoLoggingTestClass {
public void doNotLogInternalMethod() {}
}
static class NoLoggingTestSubClass extends NoLoggingTestClass {}
}

View File

@ -0,0 +1,38 @@
package pro.taskana.common.internal.logging;
class LoggingTestClass {
public void logInternalMethod() {}
@SuppressWarnings("UnusedReturnValue")
public String logInternalMethodWithReturnValue() {
return "test string";
}
@SuppressWarnings("UnusedReturnValue")
public String logInternalMethodWithReturnValueNull() {
return null;
}
@SuppressWarnings("unused")
public void logInternalMethodWithArguments(String param) {}
@SuppressWarnings({"UnusedReturnValue", "unused"})
public String logInternalMethodWithReturnValueAndArguments(String param) {
return "return value";
}
public void logInternalMethodWrapper() {
logInternalMethodPrivate();
}
@SuppressWarnings("unused")
public void callsExternalMethod() {
String sum = String.valueOf(5);
}
@NoLogging
public void doNotLogInternalMethod() {}
private void logInternalMethodPrivate() {}
}

View File

@ -0,0 +1,7 @@
package pro.taskana.common.internal.logging;
@NoLogging
class NoLoggingTestClass {
public void doNotLogInternalMethod() {}
}

View File

@ -0,0 +1,3 @@
package pro.taskana.common.internal.logging;
class NoLoggingTestSubClass extends NoLoggingTestClass {}