2018. július 5., csütörtök

Setting up MDC context with AOP in Spring Boot application


In order to be able to analyse logs of complex processes for your application, it is useful to use Mapped Diagnostic Context (MDC) and put some process specific information into it. Currently I am implementing a Spring Boot application, with several services, and lots of calls between them. As there is a huge number of users parallel, when it comes to analyse a production log, it is not easy to find the subsequent process calls, belonging to a REST call in the log file.

In order to make my life easier, there is still a unique session id in the log, using MDC, to find all the calls belonging to a specific user and call. But to make the analysis easier, I decided to add function specific information to the logs. So, if a REST method gets called, it can set the logical function name in the MDC. Therefore all later call to helper or DAO classes can be logged with the same function name, and can be found so easily.

Obviously, setting the MDC value could be done at the beginning of in every REST method as well, like this:


1
2
3
4
5
6
@RequestMapping(value = "/logic/delete", method = { RequestMethod.POST })
public ResponseEntity<String> delete(HttpServletRequest httpServletRequest, @Valid @RequestBody DeleteLogicRequest request) {
    MDC.put(BACKEND_FUNCTION_NAME, "[" + functionName + "]");
  
    // do the subsequent service calls...

Fortunately using Sping AOP possibilities, it is easy to implement this cross cutting functionality in a more sophisticated way.

First, I defined an annotation, to mark services, where function information needs to be set into the MDC context, before calling any of its public methods.



 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
import java.lang.annotation.ElementType;
import java.lang.annotation.Retention;
import java.lang.annotation.RetentionPolicy;
import java.lang.annotation.Target;

/**
 * Used to mark classes in which before all method call the function information should be set into the MDC context. All logs of subsequent method
 * calls on any bean will contain the MDC information.
 */
@Target({ ElementType.TYPE })
@Retention(RetentionPolicy.RUNTIME)
public @interface ClassWithMdcContext {
 String functionName() default "";
}


I also defined another annotation, to make it possible to mark single methods. The function name information will be set by the Spring framework into MDC before calling the marked methods.


 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
import java.lang.annotation.ElementType;
import java.lang.annotation.Retention;
import java.lang.annotation.RetentionPolicy;
import java.lang.annotation.Target;

/**
 * Used to mark methods in which before calling it, the function information should be set into the MDC context. All logs of subsequent method calls
 * on any bean will contain the MDC information.
 */
@Target({ ElementType.METHOD })
@Retention(RetentionPolicy.RUNTIME)
public @interface MethodWithMdcContext {
 String functionName() default "";
}


The AOP magic happens in the following class.


 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
import java.lang.reflect.Method;

import org.apache.commons.lang3.StringUtils;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Pointcut;
import org.aspectj.lang.reflect.MethodSignature;
import org.slf4j.MDC;
import org.springframework.core.annotation.Order;
import org.springframework.stereotype.Service;

// Marks the AOP functionality as the first one. Needed while logging happens also with AOP, and you make sure, that MDC information is set before any
// other AOP activities.
@Order(1)
@Service
@Aspect
public class MdcContextInitialiser {
 private static final String BACKEND_FUNCTION_NAME = "backendFunctionName";

 @Around("methodsAnnoatatedWithMethodWithMdcContext()")
 public Object aroundAnnotatedMethods(ProceedingJoinPoint joinPoint) throws Throwable {
  setMdcContextForMethod(joinPoint);
  return joinPoint.proceed();
 }

 @Around("classesAnnotatedWithClassWithMdcContext()")
 public Object aroundAnnotatedClass(ProceedingJoinPoint joinPoint) throws Throwable {
  setMdcContextForClass(joinPoint);
  return joinPoint.proceed();
 }

 @Pointcut(value = "@annotation(MethodWithMdcContext)")
 public void methodsAnnoatatedWithMethodWithMdcContext() {
  // defines pointcut for methods annotated with MethodWithMdcContext
 }

 @Pointcut("@within(ClassWithMdcContext)") // this should work for the annotation service pointcut
 private void classesAnnotatedWithClassWithMdcContext() {
  // defines pointcut for classes annotated with ClassWithMdcContext
 }

 private void setMdcContextForMethod(ProceedingJoinPoint joinPoint) {
  MethodSignature signature = (MethodSignature) joinPoint.getSignature();
  Method method = signature.getMethod();
  MethodWithMdcContext annotation = method.getAnnotation(MethodWithMdcContext.class);

  String functionName = annotation.functionName();

  if (StringUtils.isBlank(functionName)) {
   functionName = getClassName(signature.getDeclaringTypeName()) + "_" + method.getName();
  }

  MDC.put(BACKEND_FUNCTION_NAME, "[" + functionName + "]");
 }

 @SuppressWarnings({ "unchecked", "rawtypes" })
 private void setMdcContextForClass(ProceedingJoinPoint joinPoint) {
  MethodSignature signature = (MethodSignature) joinPoint.getSignature();
  Class clazz = signature.getDeclaringType();
  ClassWithMdcContext annotation = (ClassWithMdcContext) clazz.getAnnotation(ClassWithMdcContext.class);

  String functionName = annotation.functionName();

  if (StringUtils.isBlank(functionName)) {
   functionName = getClassName(signature.getDeclaringTypeName()) + "_" + signature.getMethod().getName();
  }

  MDC.put(BACKEND_FUNCTION_NAME, "[" + functionName + "]");
 }

 private String getClassName(String classFullName) {
  int startIndexOfClassName = StringUtils.lastIndexOf(classFullName, ".") + 1;
  return StringUtils.substring(classFullName, startIndexOfClassName);
 }

}


The MdcContextInitialiser class initializes the MDC context, corresponding to the annotations above. I defined a pointcut for both of the annotations, and an around method, in order to call the MDC initialization before calling the actual method.

The functionName property in both annotations allows to define any logical function name for the log, like "StartupCall", "AddToCart" or "Purchase". In case of it is not defined, a combination of the class and method name will be used.

In order to get the MDC data printed in the log, you need to add the key "backendFunctionName" to the log pattern in the logback.xml.


 1
 2
 3
 4
 5
 6
 7
 8
 9
10
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
 <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
  <level>INFO</level>
 </filter>
 <encoder>
  <Pattern>%d %-5level %X{genericID} %X{backendFunctionName} %C{0} %L : %msg%n</Pattern>
 </encoder>
</appender>


After marking some classes or methods with the corresponding annotation, your log will contain the function name. Say calling the LogicRestService.getAll() method, the log looks like this:



 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
     [exec] 2018-07-05 16:00:42,704 INFO  [LogicRestService_getAll] AuthenticationFilter 56 : Processing URL: https://localhost/rest/logic/all
     [exec] 2018-07-05 16:00:42,706 INFO  [LogicRestService_getAll] AuthenticationFilter 183 : URL needs to be processed: https://localhost/rest/logic/all for type crbheader
     [exec] 2018-07-05 16:00:42,706 INFO  [LogicRestService_getAll] AuthenticationFilter 183 : URL needs to be processed: https://localhost/rest/logic/all for type ManualLogin
     [exec] 2018-07-05 16:00:42,706 INFO  [LogicRestService_getAll] AuthenticationFilter 118 : URL https://localhost/rest/logic/all requires manual login: true
     [exec] 2018-07-05 16:00:42,706 INFO  [LogicRestService_getAll] AuthenticationFilter 125 : User logged in with manual login: true
     [exec] 2018-07-05 16:00:42,707 INFO  [LogicRestService_getAll] ExecutionTimeMonitor 119 : Entering GatewayDao.findGatewayIdBySubscriberId(String) parameters: [51125096]
     [exec] 2018-07-05 16:00:42,710 INFO  [LogicRestService_getAll] ExecutionTimeMonitor 124 : Exiting GatewayDao.findGatewayIdBySubscriberId(String) : 3 ms result : Optional.empty
     [exec] 2018-07-05 16:00:42,714 INFO  [LogicRestService_getAll] ExecutionTimeMonitor 119 : Entering LogicRestService.getAll(HttpServletRequest) parameters: [org.springframework.web.util.ContentCachingRequestWrapper@72689384]
     [exec] 2018-07-05 16:00:42,716 INFO  [LogicRestService_getAll] ExecutionTimeMonitor 119 : Entering LogicDao.findByGatewaySubscriberIdAndWorkingState(String) parameters: [53474139]
     [exec] 2018-07-05 16:00:42,718 INFO  [LogicRestService_getAll] ExecutionTimeMonitor 124 : Exiting LogicDao.findByGatewaySubscriberIdAndWorkingState(String) : 2 ms result : []
     [exec] 2018-07-05 16:00:42,718 INFO  [LogicRestService_getAll] ExecutionTimeMonitor 124 : Exiting LogicRestService.getAll(HttpServletRequest) : 4 ms result : <200 OK,[],{}>

As you can see, all further log entry contains the function information. In this way it ts quite easy to identify all the logs belonging to a given REST service, even if they are separated by entries from other processes or sessions.
Bejegyezte: dátum:

Nincsenek megjegyzések:

Megjegyzés küldése

Feliratkozás: Megjegyzések küldése (Atom)