I. Spring AOP

AOP has the following concepts:

• Aspect: Declarations are similar to class declarations in Java, which contain some Pointcut s and corresponding Advice s.
• Joint point: A point that is clearly defined in a program. Including method calls, access to class members, etc.
• Pointcut: Represents a group of Joint point s, such as method name, parameter type, return type, and so on.
• Advice: Advice defines the specific operations to be performed by the program points defined in the Pointcut. It distinguishes the code to be invoked before, around, after(return, throw) and finally before, after or after each Joint point.
• Before: Call Advice before executing a method, such as login validation before requesting an interface.
• Around: Calling Advice before and after executing a method is the most common method.
• After: Call Advice after executing the method. After and return are called after the method returns normally. After throw is called after the method throws an exception.
• Finally: Advice is executed after a method call, whether an exception is thrown or returned normally.
• AOP proxy: AOP proxy is also a Java object, which is created by the AOP framework to accomplish the above actions. AOP objects can usually be accomplished by JDK dynamic proxy or CGLIb.
• Weaving: Code weaving that implements the aforementioned aspect programming can generate proxies at compile time or run time, Spring and most other Java frameworks are at run time.

Item examples

Of course, before using this case, if you need to know about log configuration, you can refer to it. SpringBoot asynchronously outputs Logback logs This article is no longer an overview.

2.1 Introducing Dependency in pom

<dependencies>
    <dependency>
        <groupId>org.springframework.boot</groupId>
        <artifactId>spring-boot-starter-web</artifactId>
    </dependency>

    <dependency>
        <groupId>org.springframework.boot</groupId>
        <artifactId>spring-boot-starter-aop</artifactId>
    </dependency>
    <!-- Tool Class for Analyzing Client Information-->
    <dependency>
        <groupId>eu.bitwalker</groupId>
        <artifactId>UserAgentUtils</artifactId>
        <version>1.20</version>
    </dependency>
    <!-- lombok -->
    <dependency>
        <groupId>org.projectlombok</groupId>
        <artifactId>lombok</artifactId>
        <scope>1.8.4</scope>
    </dependency>
</dependencies>

2.2 Controller Aspect: WebLogAspect

@Aspect
@Component
@Slf4j
public class WebLogAspect {

    /**
     * Entry method timestamp
     */
    private Long startTime;
    /**
     * Method End Time Stamp (Timing)
     */
    private Long endTime;

    public WebLogAspect() {
    }


    /**
     * Define the request log pointcut, whose pointcut expression can be matched in a variety of ways, here is the specified path
     */
    @Pointcut("execution(public * cn.van.log.aop.controller.*.*(..))")
    public void webLogPointcut() {
    }

    /**
     * Pre-notification:
     * 1. Execute before executing the target method, such as login validation before requesting the interface;
     * 2. Setting the request log information in the pre-notification, such as start time, request parameters, annotation content, etc.
     *
     * @param joinPoint
     * @throws Throwable
     */
    @Before("webLogPointcut()")
    public void doBefore(JoinPoint joinPoint) {

        // Receive the request and record the content of the request
        ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
        HttpServletRequest request = attributes.getRequest();
        //Get User-Agent in the request header
        UserAgent userAgent = UserAgent.parseUserAgentString(request.getHeader("User-Agent"));
        //Print the content of the request
        startTime = System.currentTimeMillis();
        log.info("Request start time:{}" + LocalDateTime.now());
        log.info("request Url : {}" + request.getRequestURL().toString());
        log.info("Request mode : {}" + request.getMethod());
        log.info("request ip : {}" + request.getRemoteAddr());
        log.info("Request method : " + joinPoint.getSignature().getDeclaringTypeName() + "." + joinPoint.getSignature().getName());
        log.info("Request parameters : {}" + Arrays.toString(joinPoint.getArgs()));
        // system information
        log.info("Browser:{}", userAgent.getBrowser().toString());
        log.info("Browser Version:{}", userAgent.getBrowserVersion());
        log.info("operating system: {}", userAgent.getOperatingSystem().toString());
    }

    /**
     * Return notification:
     * 1. Execute after the normal end of the target method
     * 1. Supplement request log information in return notification, such as return time, method time-consuming, return value, and save log information
     *
     * @param ret
     * @throws Throwable
     */
    @AfterReturning(returning = "ret", pointcut = "webLogPointcut()")
    public void doAfterReturning(Object ret) throws Throwable {
        endTime = System.currentTimeMillis();
        log.info("At the end of the request:{}" + LocalDateTime.now());
        log.info("Request time-consuming:{}" + (endTime - startTime));
        // Processing the request and returning the content
        log.info("Request return : {}" + ret);
    }

    /**
     * Exception notification:
     * 1. Execute when the target method ends abnormally, an exception occurs or an exception is thrown
     * 1. Set exception information in exception notification and save it
     *
     * @param throwable
     */
    @AfterThrowing(value = "webLogPointcut()", throwing = "throwable")
    public void doAfterThrowing(Throwable throwable) {
        // Save exceptional log records
        log.error("Abnormal time:{}" + LocalDateTime.now());
        log.error("Throw an exception:{}" + throwable.getMessage());
    }
}

2.3 Writing Tests

@RestController
@RequestMapping("/log")
public class LogbackController {

    /**
     * Test normal requests
     * @param msg
     * @return
     */
    @GetMapping("/{msg}")
    public String getMsg(@PathVariable String msg) {
        return "request msg : " + msg;
    }

    /**
     * Test throw exception
     * @return
     */
    @GetMapping("/test")
    public String getException(){
        // Deliberately create an anomaly
        Integer.parseInt("abc123");
        return "success";
    }
}

2.4 @Before and @AfterReturning sections can also be replaced by the following code

    /**
     * Calling Advice before and after execution of a method is the most commonly used method, equivalent to what @Before and @AfterReturning do.
     * @param pjp
     * @return
     * @throws Throwable
     */
    @Around("webLogPointcut()")
    public Object doAround(ProceedingJoinPoint pjp) throws Throwable {
        // Receive the request and record the content of the request
        ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
        HttpServletRequest request = attributes.getRequest();
        //Get User-Agent in the request header
        UserAgent userAgent = UserAgent.parseUserAgentString(request.getHeader("User-Agent"));
        //Print the content of the request
        startTime = System.currentTimeMillis();
        log.info("request Url : {}" , request.getRequestURL().toString());
        log.info("Request mode : {}" , request.getMethod());
        log.info("request ip : {}" , request.getRemoteAddr());
        log.info("Request method : " , pjp.getSignature().getDeclaringTypeName() , "." , pjp.getSignature().getName());
        log.info("Request parameters : {}" , Arrays.toString(pjp.getArgs()));
    // system information
        log.info("Browser:{}", userAgent.getBrowser().toString());
        log.info("Browser Version:{}",userAgent.getBrowserVersion());
        log.info("operating system: {}", userAgent.getOperatingSystem().toString());
        // pjp.proceed(): When we have finished executing the tangent code, we have to continue processing the business-related code. The proceed() method continues to execute the business code, and its return value is the return value after the business process is completed.
        Object ret = pjp.proceed();
        log.info("At the end of the request:"+ LocalDateTime.now());
        log.info("Request time-consuming:{}" , (System.currentTimeMillis() - startTime));
        // Processing the request and returning the content
        log.info("Request return : " , ret);
        return ret;
    }

III. Testing

3.1 Request entry LogbackController.java

@RestController
@RequestMapping("/log")
public class LogbackController {

    /**
     * Test normal requests
     * @param msg
     * @return
     */
    @GetMapping("/normal/{msg}")
    public String getMsg(@PathVariable String msg) {
        return msg;
    }

    /**
     * Test throw exception
     * @return
     */
    @GetMapping("/exception/{msg}")
    public String getException(@PathVariable String msg){
        // Deliberately create an anomaly
        Integer.parseInt("abc123");
        return msg;
    }
}

3.2 Test normal requests

Open browser, access http://localhost:8082/log/normal/hello

The logs are printed as follows:

[2019-02-24 22:37:50.050] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-1] [65] [INFO ] Request start time: 2019-02-24T22:37:50.892
[2019-02-24 22:37:50.050] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-1] [66] [INFO ] request Url : http://localhost:8082/log/normal/hello
[2019-02-24 22:37:50.050] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-1] [67] [INFO ] Request mode : GET
[2019-02-24 22:37:50.050] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-1] [68] [INFO ] request ip : 0:0:0:0:0:0:0:1
[2019-02-24 22:37:50.050] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-1] [69] [INFO ] Request method : 
[2019-02-24 22:37:50.050] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-1] [70] [INFO ] Request parameters : [hello]
[2019-02-24 22:37:50.050] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-1] [72] [INFO ] Browser: CHROME
[2019-02-24 22:37:50.050] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-1] [73] [INFO ] Browser Version: 76.0.3809.100
[2019-02-24 22:37:50.050] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-1] [74] [INFO ] operating system: MAC_OS_X
[2019-02-24 22:37:50.050] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-1] [88] [INFO ] Request closure time: 2019-02-24T22:37:50.901
[2019-02-24 22:37:50.050] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-1] [89] [INFO ] Request time: 14
[2019-02-24 22:37:50.050] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-1] [91] [INFO ] Request return : hello

3.3 Testing anomalies

Visit: http://localhost:8082/log/exception/hello

[2019-02-24 22:39:57.057] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-9] [65] [INFO ] Request start time: 2019-02-24T22:39:57.728
[2019-02-24 22:39:57.057] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-9] [66] [INFO ] request Url : http://localhost:8082/log/exception/hello
[2019-02-24 22:39:57.057] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-9] [67] [INFO ] Request mode : GET
[2019-02-24 22:39:57.057] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-9] [68] [INFO ] request ip : 0:0:0:0:0:0:0:1
[2019-02-24 22:39:57.057] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-9] [69] [INFO ] Request method : 
[2019-02-24 22:39:57.057] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-9] [70] [INFO ] Request parameters : [hello]
[2019-02-24 22:39:57.057] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-9] [72] [INFO ] Browser: CHROME
[2019-02-24 22:39:57.057] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-9] [73] [INFO ] Browser Version: 76.0.3809.100
[2019-02-24 22:39:57.057] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-9] [74] [INFO ] operating system: MAC_OS_X
[2019-02-24 22:39:57.057] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-9] [104] [ERROR] Abnormal time: 2019-02-24T22:39:57.731
[2019-02-24 22:39:57.057] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-9] [105] [ERROR] Throw an exception: For input string: "abc123"
[2019-02-24 22:39:57.057] [org.apache.juli.logging.DirectJDKLog] [http-nio-8082-exec-9] [175] [ERROR] Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is java.lang.NumberFormatException: For input string: "abc123"] with root cause
java.lang.NumberFormatException: For input string: "abc123"

Source Code

4.1 Sample Code

1. Github sample code