Recently, the project has entered the joint commissioning stage. The interface of the service layer needs to interact with the protocol layer. The protocol layer needs to assemble the input parameter [json string] into the json string required by the service layer. It is easy to make mistakes in the assembly process. The interface debugging failure caused by the input parameter error occurs many times in the joint debugging. Therefore, I want to write a request log section and print the input parameter information. At the same time, the protocol layer calls the service layer interface name several times. Through the request log section, we can know whether the upper layer has initiated the call, so as to facilitate the front and rear ends to throw the pot and show evidence

Write in front

This article is practical. It will not explain the principle of the section, but simply introduce the knowledge points of the section

Section introduction

Aspect oriented programming is a programming paradigm. As a supplement to OOP, it is used to deal with the crosscutting concerns distributed in various modules in the system, such as transaction management, permission control, cache control, log printing, etc. AOP divides the functional modules of software into two parts: core concerns and crosscutting concerns. The main function of business processing is the core concern, rather than the cross cutting concern, which is not the core and needs to be expanded. The function of AOP is to separate various concerns in the system and separate the core concerns and crosscutting concerns. The use of facets has the following advantages:

• Focus on one concern / crosscutting logic
• You can easily add / remove concerns
• It is less intrusive and enhances code readability and maintainability. Therefore, when you want to print the request log, it is easy to think of aspects and invade the control layer code 0

Use of sections [based on annotation]

• @Aspect = > declare this class as an annotation class

Tangent notes:

• @Pointcut = > define a tangent point to simplify the code

Notice notes:

• @Before = > execute code before pointcut
• @After = > execute code after pointcut
• @After returning = > execute the code after the content returned by the pointcut, which can encapsulate the return value of the pointcut
• @Afterthrowing = > execute after exception thrown by pointcut
• @Around = > surround, execute code before and after the pointcut

Write a request log section

• Use @ Pointcut to define the tangent point

@Pointcut("execution(* your_package.controller..*(..))")
public void requestServer() {
}

@Pointcut defines a cut-off point. Because it is a request log cut, the cut-off point defines the methods under all classes under the Controller package. After defining the pointcut, you can directly use the requestServer method name in the notification annotation

• Use @ Before to execute Before the tangent point

@Before("requestServer()")
  public void doBefore(JoinPoint joinPoint) {
      ServletRequestAttributes attributes = (ServletRequestAttributes) 
  RequestContextHolder.getRequestAttributes();
      HttpServletRequest request = attributes.getRequest();
  
      LOGGER.info("===============================Start========================");
      LOGGER.info("IP                 : {}", request.getRemoteAddr());
      LOGGER.info("URL                : {}", request.getRequestURL().toString());
      LOGGER.info("HTTP Method        : {}", request.getMethod());
      LOGGER.info("Class Method       : {}.{}", joinPoint.getSignature().getDeclaringTypeName(), joinPoint.getSignature().getName());
  }

Before entering the Controller method, print out the caller's IP, request URL, HTTP request type and called method name

• Use @ Around to print input parameters entering the control layer

  @Around("requestServer()")
  public Object doAround(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
      long start = System.currentTimeMillis();
      Object result = proceedingJoinPoint.proceed();
      LOGGER.info("Request Params       : {}", getRequestParams(proceedingJoinPoint));
      LOGGER.info("Result               : {}", result);
      LOGGER.info("Time Cost            : {} ms", System.currentTimeMillis() - start);
  
      return result;
  }

The input parameters, results and time-consuming are printed

• getRquestParams method

    private Map<String, Object> getRequestParams(ProceedingJoinPoint proceedingJoinPoint) {
         Map<String, Object> requestParams = new HashMap<>();
    
          //Parameter name
         String[] paramNames = ((MethodSignature)proceedingJoinPoint.getSignature()).getParameterNames();
         //Parameter value
         Object[] paramValues = proceedingJoinPoint.getArgs();
    
         for (int i = 0; i < paramNames.length; i++) {
             Object value = paramValues[i];
    
             //If it is a file object
             if (value instanceof MultipartFile) {
                 MultipartFile file = (MultipartFile) value;
                 value = file.getOriginalFilename();  //Get file name
             }
    
             requestParams.put(paramNames[i], value);
         }
    
         return requestParams;
     }

The parameters passed through the @ PathVariable and @ RequestParam annotations cannot print the parameter name, so you need to splice the parameter name manually. At the same time, special processing is carried out on the file object, just get the file name

• @Execute After method call

  @After("requestServer()")
  public void doAfter(JoinPoint joinPoint) {
      LOGGER.info("===============================End========================");
  }

There is no business logic, but the End is printed

• Complete section code

  @Component
  @Aspect
  public class RequestLogAspect {
      private final static Logger LOGGER = LoggerFactory.getLogger(RequestLogAspect.class);
  
      @Pointcut("execution(* your_package.controller..*(..))")
      public void requestServer() {
      }
  
      @Before("requestServer()")
      public void doBefore(JoinPoint joinPoint) {
          ServletRequestAttributes attributes = (ServletRequestAttributes) 
  RequestContextHolder.getRequestAttributes();
          HttpServletRequest request = attributes.getRequest();
  
          LOGGER.info("===============================Start========================");
          LOGGER.info("IP                 : {}", request.getRemoteAddr());
          LOGGER.info("URL                : {}", request.getRequestURL().toString());
          LOGGER.info("HTTP Method        : {}", request.getMethod());
          LOGGER.info("Class Method       : {}.{}", joinPoint.getSignature().getDeclaringTypeName(), 
   joinPoint.getSignature().getName());
      }
  
  
      @Around("requestServer()")
      public Object doAround(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
          long start = System.currentTimeMillis();
          Object result = proceedingJoinPoint.proceed();
          LOGGER.info("Request Params     : {}", getRequestParams(proceedingJoinPoint));
          LOGGER.info("Result               : {}", result);
          LOGGER.info("Time Cost            : {} ms", System.currentTimeMillis() - start);
  
          return result;
      }
  
      @After("requestServer()")
      public void doAfter(JoinPoint joinPoint) {
          LOGGER.info("===============================End========================");
      }
  
      /**
       * Get input parameters
       * @param proceedingJoinPoint
       *
       * @return
       * */
      private Map<String, Object> getRequestParams(ProceedingJoinPoint proceedingJoinPoint) {
          Map<String, Object> requestParams = new HashMap<>();
  
          //Parameter name
          String[] paramNames = 
  ((MethodSignature)proceedingJoinPoint.getSignature()).getParameterNames();
          //Parameter value
          Object[] paramValues = proceedingJoinPoint.getArgs();
  
          for (int i = 0; i < paramNames.length; i++) {
              Object value = paramValues[i];
  
              //If it is a file object
              if (value instanceof MultipartFile) {
                  MultipartFile file = (MultipartFile) value;
                  value = file.getOriginalFilename();  //Get file name
              }
  
              requestParams.put(paramNames[i], value);
          }
  
          return requestParams;
      }
  }

High and send request log section

After writing, I was very satisfied with my code, but I thought there might be something perfect, so I communicated with my friends. emmmm

Sure enough, there are still places to continue to optimize. Each line of information is printed. Under high concurrent requests, the problem of printing log serialization between requests does occur, because the number of requests in the test stage is small and there is no serialization. Sure enough, the production environment is the first development force and can encounter more bug s, Write more robust code to solve the problem of log serialization. Just merge multiple lines of print information into one line, so construct an object

• RequestInfo.java

  @Data
  public class RequestInfo {
      private String ip;
      private String url;
      private String httpMethod;
      private String classMethod;
      private Object requestParams;
      private Object result;
      private Long timeCost;
  }
  

• Surround notification method body

  @Around("requestServer()")
  public Object doAround(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
      long start = System.currentTimeMillis();
      ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
      HttpServletRequest request = attributes.getRequest();
      Object result = proceedingJoinPoint.proceed();
      RequestInfo requestInfo = new RequestInfo();
              requestInfo.setIp(request.getRemoteAddr());
      requestInfo.setUrl(request.getRequestURL().toString());
      requestInfo.setHttpMethod(request.getMethod());
      requestInfo.setClassMethod(String.format("%s.%s", proceedingJoinPoint.getSignature().getDeclaringTypeName(),
              proceedingJoinPoint.getSignature().getName()));
      requestInfo.setRequestParams(getRequestParamsByProceedingJoinPoint(proceedingJoinPoint));
      requestInfo.setResult(result);
      requestInfo.setTimeCost(System.currentTimeMillis() - start);
      LOGGER.info("Request Info      : {}", JSON.toJSONString(requestInfo));
  
      return result;
  }

Assemble the information such as url and http request into RequestInfo objects, and then serialize the print objects to print the serialized object results instead of directly printing the objects, because serialization is more intuitive and clearer, and the results can be parsed with the help of online parsing tools

Isn't it good?

While solving the serial problem of high parallel request, the printing of exception request information is added, and the method of throwing exception is handled by using @ AfterThrowing annotation

• RequestErrorInfo.java

  @Data
  public class RequestErrorInfo {
      private String ip;
      private String url;
      private String httpMethod;
      private String classMethod;
      private Object requestParams;
      private RuntimeException exception;
  }

• Exception notification surround

  @AfterThrowing(pointcut = "requestServer()", throwing = "e")
  public void doAfterThrow(JoinPoint joinPoint, RuntimeException e) {
      ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
      HttpServletRequest request = attributes.getRequest();
      RequestErrorInfo requestErrorInfo = new RequestErrorInfo();
      requestErrorInfo.setIp(request.getRemoteAddr());
      requestErrorInfo.setUrl(request.getRequestURL().toString());
      requestErrorInfo.setHttpMethod(request.getMethod());
      requestErrorInfo.setClassMethod(String.format("%s.%s", joinPoint.getSignature().getDeclaringTypeName(),
              joinPoint.getSignature().getName()));
      requestErrorInfo.setRequestParams(getRequestParamsByJoinPoint(joinPoint));
      requestErrorInfo.setException(e);
      LOGGER.info("Error Request Info      : {}", JSON.toJSONString(requestErrorInfo));
  }

For exceptions, the time consumption is meaningless, so the time consumption is not counted, but the printing of exceptions is added

Finally, put the complete log request section code:

@Component
@Aspect
public class RequestLogAspect {
    private final static Logger LOGGER = LoggerFactory.getLogger(RequestLogAspect.class);

    @Pointcut("execution(* your_package.controller..*(..))")
    public void requestServer() {
    }

    @Around("requestServer()")
    public Object doAround(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
        long start = System.currentTimeMillis();
        ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
        HttpServletRequest request = attributes.getRequest();
        Object result = proceedingJoinPoint.proceed();
        RequestInfo requestInfo = new RequestInfo();
                requestInfo.setIp(request.getRemoteAddr());
        requestInfo.setUrl(request.getRequestURL().toString());
        requestInfo.setHttpMethod(request.getMethod());
        requestInfo.setClassMethod(String.format("%s.%s", proceedingJoinPoint.getSignature().getDeclaringTypeName(),
                proceedingJoinPoint.getSignature().getName()));
        requestInfo.setRequestParams(getRequestParamsByProceedingJoinPoint(proceedingJoinPoint));
        requestInfo.setResult(result);
        requestInfo.setTimeCost(System.currentTimeMillis() - start);
        LOGGER.info("Request Info      : {}", JSON.toJSONString(requestInfo));

        return result;
    }


    @AfterThrowing(pointcut = "requestServer()", throwing = "e")
    public void doAfterThrow(JoinPoint joinPoint, RuntimeException e) {
        ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
        HttpServletRequest request = attributes.getRequest();
        RequestErrorInfo requestErrorInfo = new RequestErrorInfo();
        requestErrorInfo.setIp(request.getRemoteAddr());
        requestErrorInfo.setUrl(request.getRequestURL().toString());
        requestErrorInfo.setHttpMethod(request.getMethod());
        requestErrorInfo.setClassMethod(String.format("%s.%s", joinPoint.getSignature().getDeclaringTypeName(),
                joinPoint.getSignature().getName()));
        requestErrorInfo.setRequestParams(getRequestParamsByJoinPoint(joinPoint));
        requestErrorInfo.setException(e);
        LOGGER.info("Error Request Info      : {}", JSON.toJSONString(requestErrorInfo));
    }

    /**
     * Get input parameters
     * @param proceedingJoinPoint
     *
     * @return
     * */
    private Map<String, Object> getRequestParamsByProceedingJoinPoint(ProceedingJoinPoint proceedingJoinPoint) {
        //Parameter name
        String[] paramNames = ((MethodSignature)proceedingJoinPoint.getSignature()).getParameterNames();
        //Parameter value
        Object[] paramValues = proceedingJoinPoint.getArgs();

        return buildRequestParam(paramNames, paramValues);
    }

    private Map<String, Object> getRequestParamsByJoinPoint(JoinPoint joinPoint) {
        //Parameter name
        String[] paramNames = ((MethodSignature)joinPoint.getSignature()).getParameterNames();
        //Parameter value
        Object[] paramValues = joinPoint.getArgs();

        return buildRequestParam(paramNames, paramValues);
    }

    private Map<String, Object> buildRequestParam(String[] paramNames, Object[] paramValues) {
        Map<String, Object> requestParams = new HashMap<>();
        for (int i = 0; i < paramNames.length; i++) {
            Object value = paramValues[i];

            //If it is a file object
            if (value instanceof MultipartFile) {
                MultipartFile file = (MultipartFile) value;
                value = file.getOriginalFilename();  //Get file name
            }

            requestParams.put(paramNames[i], value);
        }

        return requestParams;
    }

    @Data
    public class RequestInfo {
        private String ip;
        private String url;
        private String httpMethod;
        private String classMethod;
        private Object requestParams;
        private Object result;
        private Long timeCost;
    }

    @Data
    public class RequestErrorInfo {
        private String ip;
        private String url;
        private String httpMethod;
        private String classMethod;
        private Object requestParams;
        private RuntimeException exception;
    }
}

Quickly add [if not] to your application. If there is no log, it is always suspected that the upper level is wrong, but there is no evidence

For traceId tracking and positioning, you can track the whole call chain according to traceId. Take log4j2 as an example to introduce how to add traceId

• Add interceptor

  public class LogInterceptor implements HandlerInterceptor {
      private final static String TRACE_ID = "traceId";
  
      @Override
      public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
          String traceId = java.util.UUID.randomUUID().toString().replaceAll("-", "").toUpperCase();
          ThreadContext.put("traceId", traceId);
  
          return true;
      }
  
      @Override
      public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler, ModelAndView modelAndView)
              throws Exception {
      }
  
      @Override
      public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex)
              throws Exception {        
          ThreadContext. remove(TRACE_ID);
      }
  }

Add traceId through ThreadContext before calling, and remove it after calling

• Modify the log configuration file and add a placeholder for traceId in the original log format

<property name="pattern">[TRACEID:%X{traceId}] %d{HH:mm:ss.SSS} %-5level %class{-1}.%M()/%L - %msg%xEx%n</property>

• Execution effect

Log tracking is more convenient

DMC is configured to use logback and log4j in the same way as ThreadContext. ThreadContext Replace put with MDC Put, and modify the log configuration file at the same time.