OZG-808 introduce Aspect Logging

pluto-server/pom.xml

@@ -77,6 +77,16 @@
 			<artifactId>spring-boot-starter-validation</artifactId>
 		</dependency>
 
+		<!-- aspectJ -->
+		<dependency>
+			<groupId>org.aspectj</groupId>
+			<artifactId>aspectjweaver</artifactId>
+		</dependency>
+		<dependency>
+			<groupId>org.aspectj</groupId>
+			<artifactId>aspectjrt</artifactId>
+		</dependency>
+
 
 		<!-- Tools -->
 		<dependency>
@@ -158,11 +168,6 @@
 			<artifactId>junit-jupiter-params</artifactId>
 			<scope>test</scope>
 		</dependency>
-<!-- 		<dependency> -->
-<!-- 			<groupId>de.flapdoodle.embed</groupId> -->
-<!-- 			<artifactId>de.flapdoodle.embed.mongo</artifactId> -->
-<!-- 			<scope>test</scope> -->
-<!-- 		</dependency> -->
 
 		<dependency>
 			<groupId>org.testcontainers</groupId>

pluto-server/src/main/java/de/itvsh/ozg/pluto/PlutoServerApplication.java

@@ -4,10 +4,12 @@ import java.util.TimeZone;
 
 import org.springframework.boot.SpringApplication;
 import org.springframework.boot.autoconfigure.SpringBootApplication;
+import org.springframework.context.annotation.EnableAspectJAutoProxy;
 import org.springframework.scheduling.annotation.EnableAsync;
 
 @SpringBootApplication(scanBasePackages = "de.itvsh.ozg")
 @EnableAsync
+@EnableAspectJAutoProxy(proxyTargetClass = true)
 public class PlutoServerApplication {
 
 	public static void main(String[] args) {

pluto-server/src/main/java/de/itvsh/ozg/pluto/common/logging/AspectLoggingUtils.java

+package de.itvsh.ozg.pluto.common.logging;
+
+import java.util.Collection;
+import java.util.StringJoiner;
+
+import org.apache.commons.lang3.ArrayUtils;
+import org.aspectj.lang.JoinPoint;
+import org.aspectj.lang.reflect.MethodSignature;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
+import de.itvsh.ozg.pluto.common.datatypes.StringBasedValue;
+import lombok.extern.log4j.Log4j2;
+
+@Log4j2
+public class AspectLoggingUtils {
+
+	private static final String LOGGING_TEMPLATE = "%s: %s";
+
+	private static final String LOGGING_CALL_TEMPLATE = "%s(%s)";
+	private static final String LOGGING_RESULT_TEMPLATE = "%s => %s";
+
+	private AspectLoggingUtils() {
+	}
+
+	static void log(final JoinPoint joinPoint) {
+		try {
+			MethodSignature sig = (MethodSignature) joinPoint.getSignature();
+			var log = getLogger(joinPoint);
+			if (log.isDebugEnabled()) {
+				log.debug(String.format(LOGGING_CALL_TEMPLATE, sig.getName(), formatDebuggingParameter(joinPoint)));
+			} else {
+				log.info(String.format(LOGGING_CALL_TEMPLATE, sig.getName(), formatInfoParameters(joinPoint)));
+			}
+		} catch (RuntimeException e) {
+			LOG.error("Error on generating log output for " + joinPoint, e);
+		}
+	}
+
+	static void logException(JoinPoint joinPoint, Exception exception) {
+		try {
+			var log = getLogger(joinPoint);
+			if (log.isWarnEnabled()) {
+				log.warn(String.format(LOGGING_TEMPLATE, exception.getClass().getSimpleName(), exception.getMessage()));
+			}
+			if (log.isDebugEnabled()) {
+				log.debug(exception.getMessage(), exception);
+			}
+		} catch (RuntimeException e) {
+			LOG.error("Error on generating log on exception.", e);
+			LOG.error("Original exception log", exception);
+		}
+	}
+
+	static void logReturnValue(JoinPoint joinPoint, Object returnValue) {
+		try {
+
+			MethodSignature sig = (MethodSignature) joinPoint.getSignature();
+			var log = getLogger(joinPoint);
+			if (log.isInfoEnabled()) {
+				log.info(String.format(LOGGING_RESULT_TEMPLATE, sig.getName(),
+						sig.getReturnType() == Void.TYPE ? "<Void>" : formatInfoParameter(returnValue)));
+			}
+		} catch (RuntimeException e) {
+			LOG.error("Error on generating log for returnValue.", e);
+		}
+	}
+
+	private static Logger getLogger(final JoinPoint joinPoint) {
+		return LoggerFactory.getLogger(joinPoint.getSignature().getDeclaringType());
+	}
+
+	private static String formatInfoParameters(final JoinPoint joinPoint) {
+		String[] paramNames = getSignature(joinPoint).getParameterNames();
+		Object[] paramValues = joinPoint.getArgs();
+
+		var stringJoiner = new StringJoiner(", ");
+
+		for (int n = 0; n < paramValues.length; n++) {
+			if (paramNames != null) {
+				stringJoiner.add(String.format(LOGGING_TEMPLATE, paramNames[n], formatInfoParameter(paramValues[n])));
+			} else {
+				stringJoiner.add(formatInfoParameter(paramValues[n]));
+			}
+		}
+
+		return stringJoiner.toString();
+	}
+
+	private static String formatInfoParameter(Object value) {
+		if (value != null && printValueOnInfoLevel(value.getClass())) {
+			return formatParameter(value);
+		} else if (value != null) {
+			var sb = new StringBuilder();
+			sb.append("<").append(value.getClass().getSimpleName());
+			if (value.getClass().isArray()) {
+				sb.deleteCharAt(sb.length() - 1);
+				try {
+					sb.append(ArrayUtils.getLength(value)).append("]");
+				} catch (ClassCastException e) {
+					e.printStackTrace();
+					System.out.println(value.getClass().getSimpleName());
+				}
+			}
+			sb.append(">");
+			return sb.toString();
+		} else {
+			return "-null-";
+		}
+	}
+
+	private static boolean printValueOnInfoLevel(Class<?> paramClass) {
+		return paramClass.isPrimitive() || //
+				StringBasedValue.class.isAssignableFrom(paramClass) || //
+				String.class.isAssignableFrom(paramClass) || //
+				Number.class.isAssignableFrom(paramClass);
+	}
+
+	private static String formatDebuggingParameter(final JoinPoint joinPoint) {
+		String[] paramNames = getSignature(joinPoint).getParameterNames();
+		Object[] paramValues = joinPoint.getArgs();
+
+		var sb = new StringBuilder();
+		for (int n = 0; n < paramValues.length; n++) {
+			if (n > 0) {
+				sb.append(", ");
+			}
+			if (paramNames != null) {
+				sb.append(paramNames[n]).append(": ");
+			}
+			sb.append(formatParameter(paramValues[n]));
+		}
+		return sb.toString();
+	}
+
+	private static String formatParameter(final Object param) {
+		if (param == null) {
+			return "NULL";
+		}
+		if (Collection.class.isAssignableFrom(param.getClass())) {
+			return "Collection with size " + ((Collection<?>) param).size();
+		} else {
+			return param.toString();
+		}
+	}
+
+	private static MethodSignature getSignature(final JoinPoint joinPoint) {
+		return (MethodSignature) joinPoint.getSignature();
+	}
+}
\ No newline at end of file

pluto-server/src/main/java/de/itvsh/ozg/pluto/common/logging/AspectPointcuts.java

+package de.itvsh.ozg.pluto.common.logging;
+
+import org.aspectj.lang.annotation.Pointcut;
+
+public class AspectPointcuts {
+
+	@Pointcut("execution(public * *(..))")
+	void anyPublicMethods() {
+		// aspect pointcut - no implementation needed
+	}
+
+	@Pointcut("within(de.itvsh.ozg..*)")
+	void anythingInBMS() {
+		// aspect pointcut - no implementation needed
+	}
+
+	@Pointcut("anyPublicMethods() && anythingInBMS()")
+	void anyPublicMethodInBMS() {
+		// aspect pointcut - no implementation needed
+	}
+
+	@Pointcut("anyPublicMethodInBMS() && @target(org.springframework.stereotype.Service)")
+	void anyPublicServiceMethod() {
+		// aspect pointcut - no implementation needed
+	}
+
+	@Pointcut("execution(public * org.springframework.data.repository.Repository+.*(..))")
+	void anyPublicRepositoryMethod() {
+		// aspect pointcut - no implementation needed
+	}
+}

pluto-server/src/main/java/de/itvsh/ozg/pluto/common/logging/KopLoggingAspect.java

+package de.itvsh.ozg.pluto.common.logging;
+
+import org.aspectj.lang.JoinPoint;
+import org.aspectj.lang.annotation.AfterReturning;
+import org.aspectj.lang.annotation.AfterThrowing;
+import org.aspectj.lang.annotation.Aspect;
+import org.aspectj.lang.annotation.Before;
+import org.springframework.stereotype.Component;
+
+@Aspect
+@Component
+public class KopLoggingAspect extends AspectPointcuts {
+
+	@Before("anyPublicServiceMethod()")
+	public void onServiceMethod(JoinPoint joinPoint) {
+		AspectLoggingUtils.log(joinPoint);
+	}
+
+	@Before("anyPublicRepositoryMethod()")
+	public void onRepositoryMethod(JoinPoint joinPoint) {
+		AspectLoggingUtils.log(joinPoint);
+	}
+
+	@AfterThrowing(pointcut = "anyPublicServiceMethod()", throwing = "ex")
+	public void afterExceptionInServiceMethod(JoinPoint joinPoint, Exception ex) {
+		AspectLoggingUtils.logException(joinPoint, ex);
+	}
+
+	@AfterReturning(pointcut = "anyPublicServiceMethod()", returning = "returnValue")
+	public void afterServiceMethod(JoinPoint joinPoint, Object returnValue) {
+		AspectLoggingUtils.logReturnValue(joinPoint, returnValue);
+	}
+}

pluto-server/src/main/java/de/itvsh/ozg/pluto/vorgang/Eingang.java

@@ -8,13 +8,15 @@ import lombok.Getter;
 import lombok.Singular;
 import lombok.ToString;
 
-@ToString(exclude = { "formData" })
+@ToString(onlyExplicitlyIncluded = true)
 @Getter
 @Builder
 public class Eingang {
 
+	@ToString.Include
 	private String id;
 
+	@ToString.Include
 	private EingangHeader header;
 	private Antragsteller antragsteller;
 

pluto-server/src/main/java/de/itvsh/ozg/pluto/vorgang/EingangHeader.java

@@ -15,6 +15,7 @@ public class EingangHeader {
 	private ZonedDateTime createdAt;
 	private String formId;
 	private String formName;
+
 	private String sender;
 	private String customer;
 	private String customerId;

pluto-server/src/main/java/de/itvsh/ozg/pluto/vorgang/GrpcVorgangService.java

@@ -28,7 +28,6 @@ class GrpcVorgangService extends VorgangServiceGrpc.VorgangServiceImplBase {
 	@Override
 	public void createVorgang(GrpcCreateVorgangRequest request, StreamObserver<GrpcCreateVorgangResponse> responseObserver) {
 		Eingang eingang = eingangMapper.fromGrpc(request.getEingang());
-		LOG.info(eingang);
 
 		vorgangService.createVorgang(eingang);
 

pluto-server/src/main/resources/application.yml

@@ -26,11 +26,12 @@ pluto:
 management:
   server:
     port: 8081
-  endpoint:
   health:
-      probes.enabled: true
     livenessState:
       enabled: true
     readinessState:
       enabled: true
+  endpoint:
+    health:
+      probes.enabled: true
 

pluto-server/src/test/java/de/itvsh/ozg/pluto/vorgang/GrpcVorgangServiceITCase.java → pluto-server/src/test/java/de/itvsh/ozg/pluto/vorgang/VorgangITCase.java

@@ -14,7 +14,7 @@ import de.itvsh.ozg.pluto.common.grpc.StreamRecorder;
 import de.itvsh.ozg.pluto.common.test.DataITCase;
 
 @DataITCase
-class GrpcVorgangServiceITCase {
+class VorgangITCase {
 
 	@Autowired
 	private GrpcVorgangService service;

pluto-server/src/test/resources/application-itcase.yml

 logging:
   level:
-    ROOT: ERROR
+    ROOT: ERROR,
+    '[de.itvsh]': WARN
 
 grpc:
   server: