SpringBoot prints global logs through AOP

Posted by allinurl on Thu, 09 Dec 2021 06:49:56 +0100

Common notes

1,@Before

When you decorate a method, it is treated as a Before enhancement
When you use the @ Before modifier, you need to specify a value attribute value, which specifies a pointcut expression (either an existing pointcut or a pointcut expression can be defined directly) to specify which pointcuts the enhancement processing will be woven into
Indicates the operation to be performed or the method to be performed before the pointcut is executed

2,@After

Same as Before
Indicates what to do after the pointcut is executed
Usually used for resource release

3, @Around

Around enhancement processing is a powerful enhancement processing;
Approximately equal to the sum of Before enhancement and after returning enhancement
The enhancement action can be woven either before the execution of the target method or after the execution of the target method
The Around enhancement processing can change the parameter value of the execution target method or the return value after the execution of the target method
Although around enhanced processing is powerful, it usually needs to be used in a thread safe environment. Therefore, Before and after returning enhanced processing are generally used to solve problems that can be solved. Around is not recommended
If you need to share some state data before and after the execution of the target method, you should consider using Around enhanced processing; Especially when you need to change the return value of the target method, you can only use Around enhancement
@For Around enhanced processing, you need to specify a value attribute, which specifies the entry point to which the enhanced processing is implanted
When defining an Around enhanced processing method, the first formal parameter of the method must be of type ProceedingJoinPoint (containing at least one formal parameter). In the enhanced processing method body, the target method will be executed only by calling the processed() method of the ProceedingJoinPoint parameter - this is the key that Around enhanced processing can fully control the execution time and how of the target method; If the program does not call the processed () method of the ProceedingJoinPoint parameter, the target method will not be executed.
When calling the processed () method of the ProceedingJoinPoint parameter, you can also pass in an Object [] Object as the parameter, and the value in the array will be passed into the target method as the actual parameter of the execution method

code implementation

maven dependency

   //The lombok also contains the entity annotation data
    <dependency>
            <groupId>org.projectlombok</groupId>
            <artifactId>lombok</artifactId>
            <scope>test</scope>
        </dependency>
        //aop dependency
        <dependency>
            <groupId>org.aspectj</groupId>
            <artifactId>aspectjweaver</artifactId>
            <version>1.9.6</version>
        </dependency>
        //Introduce log dependency of lombok
        <dependency>
            <groupId>org.projectlombok</groupId>
            <artifactId>lombok</artifactId>
            <version>1.18.12</version>
        </dependency>
        <dependency>
            <groupId>com.google.code.gson</groupId>
            <artifactId>gson</artifactId>
            <version>2.8.6</version>
        </dependency>

aop
Everyone who has studied springboot knows that springboot is configured with AOP by default. This is also the advantage of springboot. Many default configurations have been simplified for us.

 package com.example.springbootorderrabbitmqproducer.AOP;



import com.google.gson.Gson;
import lombok.extern.slf4j.Slf4j;
import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.*;
import org.springframework.stereotype.Component;
import org.springframework.web.context.request.RequestContextHolder;
import org.springframework.web.context.request.ServletRequestAttributes;

import javax.servlet.http.HttpServletRequest;

/**
 * @author Kang World Bank
 * @Title:
 * @Package com.example.springbootorderrabbitmqproducer.AOP
 * @Description: Global print log
 * @date 2021-12-09 8:05
 */
@Aspect
@Component
@Slf4j
public class Logs {
    /** Take all the requests defined under the controller package as the entry point */
    @Pointcut("execution(public * com.example.springbootorderrabbitmqproducer.controller..*.*(..))")
    public void webLog() {}
    /**
     * Weave before the tangent point
     * @param joinPoint
     * @throws Throwable
     */
    @Before("webLog()")
    public void doBefore(JoinPoint joinPoint) {
        try{
            // Start printing request log
            ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
            HttpServletRequest request = attributes.getRequest();
            // Print request related parameters
            log.info("========================================== Start ==========================================");
            // Print request url
            log.info("URL      : {}", request.getRequestURL().toString());
            // Print Http method
            log.info("HTTP Method  : {}", request.getMethod());
            // Print the full path and execution method of calling controller
            log.info("Class Method  : {}.{}", joinPoint.getSignature().getDeclaringTypeName(), joinPoint.getSignature().getName());
            // Print requested IP
            log.info("IP       : {}", request.getRemoteAddr());
            // Print request input parameter
            String args = new Gson().toJson(joinPoint.getArgs());
            log.info("Request Args  : {}", args);
        } catch (Exception e) {
            log.error("Log printing failed");
        }
    }
    /**
     * Weave after tangent point
     * @throws Throwable
     */
    @After("webLog()")
    public void doAfter() throws Throwable {
        log.info("=========================================== End ===========================================");
        // There is one blank line between each request
        log.info("");
    }
    /**
     * surround
     * @param proceedingJoinPoint
     * @return
     * @throws Throwable
     */
    @Around("webLog()")
    public Object doAround(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
        long startTime = System.currentTimeMillis();
        Object result = proceedingJoinPoint.proceed();
        // Print out parameters
         log.info("Response Args : {}", new Gson().toJson(result));
        // Execution time
        log.info("Time-Consuming : {} ms", System.currentTimeMillis() - startTime);
        return result;
    }


}

controller

 package com.example.springbootorderrabbitmqproducer.controller;

import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.PathVariable;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RestController;

/**
 * @author Kang World Bank
 * @Title:
 * @Package com.example.springbootorderrabbitmqproducer.controller
 * @Description: Test log controller
 * @date 2021-12-09 8:27
 */
@RestController
@RequestMapping("/test")
public class testController {
    @GetMapping("/info/{mesg}")
    public String testLoginfo(@PathVariable("mesg") String mesg){
       return mesg;
    }
}

Realization effect

Before method execution

 : ========================================== Start ==========================================
2021-12-09 08:39:34.556  INFO 32148 --- [nio-8080-exec-1] c.e.s.AOP.Logs                           : URL      : http://localhost:8080/test/info/ksh
2021-12-09 08:39:34.556  INFO 32148 --- [nio-8080-exec-1] c.e.s.AOP.Logs                           : HTTP Method  : GET
2021-12-09 08:39:34.557  INFO 32148 --- [nio-8080-exec-1] c.e.s.AOP.Logs                           : Class Method  : com.example.springbootorderrabbitmqproducer.controller.testController.testLoginfo
2021-12-09 08:39:34.558  INFO 32148 --- [nio-8080-exec-1] c.e.s.AOP.Logs                           : IP       : 0:0:0:0:0:0:0:1
2021-12-09 08:39:34.560  INFO 32148 --- [nio-8080-exec-1] c.e.s.AOP.Logs                           : Request Args  : ["ksh"]

After method execution

 2021-12-09 08:39:34.564  INFO 32148 --- [nio-8080-exec-1] c.e.s.AOP.Logs                           : =========================================== End ===========================================
2021-12-09 08:39:34.564  INFO 32148 --- [nio-8080-exec-1] c.e.s.AOP.Logs                           : 

Before and after method execution

 2021-12-09 08:39:34.564  INFO 32148 --- [nio-8080-exec-1] c.e.s.AOP.Logs                           : Response Args : "ksh"
2021-12-09 08:39:34.564  INFO 32148 --- [nio-8080-exec-1] c.e.s.AOP.Logs                           : Time-Consuming : 9 ms

reflection

The following code

Think about it,

Object result = proceedingJoinPoint.proceed(); Does the location of the method affect the execution of Around?

Think two,

Object result = proceedingJoinPoint.proceed(); Method appears in
long startTime = System.currentTimeMillis();
log.info("enter the specified path" + proceedingJoinPoint.getTarget() + "controller"); Under these two lines of code, what will be output before the method is executed? Do you want to execute Befour or Around first?

  /**
     * surround
     * @param proceedingJoinPoint
     * @return
     * @throws Throwable
     */
    @Around("webLog()")
    public Object doAround(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
        long startTime = System.currentTimeMillis();
        log.info("Enter the specified path"+proceedingJoinPoint.getTarget()+"controller");
        Object result = proceedingJoinPoint.proceed();
        // Print out parameters
         log.info("Response Args : {}", new Gson().toJson(result));
        // Execution time
        log.info("Time-Consuming : {} ms", System.currentTimeMillis() - startTime);
        log.info("Method execution completed");
        return result;
    }

Reveal the answer

Think about it,
It will affect the execution of the Around method. If object result = proceedingjoinpoint. Processed() appears in the first line, the log Before entering the method will not be printed. (it means that the Around method will not print the log Before entering the method and will not affect the Before method)
reason:
The method of processingjoinpoint. Processed(), processed() is to continue to execute the target method, which is the method cut in by the pointcut. This method can be used to control the running time of the cut method.

Think two,
Contrary to the above around code, the full path to the controller will be printed Before entering the method. From the results, the priority of around is higher than that of Before (specific to be studied)
Output results:

Welcome to triple click, support Xiaobian!!!

Topics: Java Spring Boot