In development projects, we often need to print logs, so that developers can understand the interface invocation and locate errors. In many cases, we need to print logs for the entry and exit of Controller or Service, but we do not want to use logger printing in each method repeatedly. At this time, we hope to have a unified manager to print. Sprin G AOP comes in handy. With the idea of facets, we cut it in and out of Controller or Service to achieve uniform log printing.

Spring AOP can not only print logs without generating new classes, but also manage transactions, caches, etc. Specifically, you can learn about official documents. https://docs.spring.io/spring/docs/current/spring-framework-reference/core.html#aop-api

Basic concepts

In the use of Spring AOP, here is a brief explanation of some basic knowledge, if not correct in time, here is mainly based on official documents to summarize. The content of this chapter mainly involves knowledge points.

Pointcut: A point of entry, where rules are defined and methods are cut in (image metaphor is a knife).

JoinPoint: JoinPoint, used to connect defined facets.

Before: Before, before the pointcut method is executed.

AfterReturning: Executes when the pointcut method ends and returns.

In addition to Spring AOP-related knowledge, threads-related knowledge points are also involved here, because we need to consider that each of them needs to save its own variables in multi-threads, so we use ThreadLocal.

Dependency introduction

Here we mainly use aop and mongodb, add the following dependencies in the pom.xml file:

<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-aop</artifactId>
</dependency>
<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-data-mongodb</artifactId>
</dependency>

Relevant Entity Classes

/**
 * Request log entity for saving request log
 */
@Document
class WebLog {
    var id: String = ""
    var request: String? = null
    var response: String? = null
    var time: Long? = null
    var requestUrl: String? = null
    var requestIp: String? = null
    var startTime: Long? = null
    var endTime: Long? = null
    var method: String? = null

    override fun toString(): String {
        return ObjectMapper().writeValueAsString(this)
    }
}

/**
 * Business objects, as defined in JPA in the previous chapter
 */
@Document
class Student {
    @Id
    var id :String? = null
    var name :String? = null
    var age :Int? = 0
    var gender :String? = null
    var sclass :String ?= null

    override fun toString(): String {
        return ObjectMapper().writeValueAsString(this)
    }
}

Defining sections

Defining entry points

/**
 * Define a cut-in, as long as it's for io.intodream..web public modification methods need to cut-in
 */
@Pointcut(value = "execution(public * io.intodream..web.*.*(..))")
fun webLog() {}

Expressions that define pointcuts can also use within, such as:

/**
 * The methods represented under the io.intodream.web package will be cut into
 */
@Pointcut(value = "within(io.intodream.web..*")

Define a join point

/**
 * Connection Points of Aspects, and declare what needs to be done before the Connection Point enters
 */
@Before(value = "webLog()")
@Throws(Throwable::class)
fun doBefore(joinPoint: JoinPoint) {
    val webLog = WebLog()
    webLog.startTime = System.currentTimeMillis()
    val attributes = RequestContextHolder.getRequestAttributes() as ServletRequestAttributes?
    val request = attributes!!.request
    val args = joinPoint.args
    val paramNames = (joinPoint.signature as CodeSignature).parameterNames
    val params = HashMap<String, Any>(args.size)
    for (i in args.indices) {
        if (args[i] !is BindingResult) {
            params[paramNames[i]] = args[i]
        }
    }
    webLog.id = UUID.randomUUID().toString()
    webLog.request = params.toString()
    webLog.requestUrl = request.requestURI.toString()
    webLog.requestIp = request.remoteAddr
    webLog.method = request.method
    webRequestLog.set(webLog)
    logger.info("REQUEST={} {}; SOURCE IP={}; ARGS={}", request.method,
            request.requestURL.toString(), request.remoteAddr, params)
}

Execution after method completion

@AfterReturning(returning = "ret", pointcut = "webLog()")
@Throws(Throwable::class)
fun doAfterReturning(ret: Any) {
    val webLog = webRequestLog.get()
    webLog.response = ret.toString()
    webLog.endTime = System.currentTimeMillis()
    webLog.time = webLog.endTime!! - webLog.startTime!!
    logger.info("RESPONSE={}; SPEND TIME={}MS", ObjectMapper().writeValueAsString(ret), webLog.time)
    logger.info("webLog:{}", webLog)
    webLogRepository.save(webLog)
    webRequestLog.remove()
}

The main idea here is to record the detailed request parameters, request method, request ip, request mode and entry time before the method is executed, and then put the object into ThreadLocal. After the method is finished, the corresponding return object is fetched and the request time is calculated. Then the request log is saved in mongodb.

Completed code

package io.intodream.kotlin07.aspect

import com.fasterxml.jackson.databind.ObjectMapper
import io.intodream.kotlin07.dao.WebLogRepository
import io.intodream.kotlin07.entity.WebLog
import org.aspectj.lang.JoinPoint
import org.aspectj.lang.annotation.AfterReturning
import org.aspectj.lang.annotation.Aspect
import org.aspectj.lang.annotation.Before
import org.aspectj.lang.annotation.Pointcut
import org.aspectj.lang.reflect.CodeSignature
import org.slf4j.Logger
import org.slf4j.LoggerFactory
import org.springframework.beans.factory.annotation.Autowired
import org.springframework.core.annotation.Order
import org.springframework.stereotype.Component
import org.springframework.validation.BindingResult
import org.springframework.web.context.request.RequestContextHolder
import org.springframework.web.context.request.ServletRequestAttributes
import java.util.*

/**
 * {Description}
 *
 * @author yangxianxi@gogpay.cn
 * @date 2019/4/10 19:06
 *
 */
@Aspect
@Order(5)
@Component
class WebLogAspect {

    private val logger:Logger = LoggerFactory.getLogger(WebLogAspect::class.java)

    private val webRequestLog: ThreadLocal<WebLog> = ThreadLocal()

    @Autowired lateinit var webLogRepository: WebLogRepository

    /**
     * Define a cut-in, as long as it is for io.intodream..web public modification methods have to cut-in
     */
    @Pointcut(value = "execution(public * io.intodream..web.*.*(..))")
    fun webLog() {}

    /**
     * Connection Points of Aspects, and declare what needs to be done before the Connection Point enters
     */
    @Before(value = "webLog()")
    @Throws(Throwable::class)
    fun doBefore(joinPoint: JoinPoint) {
        val webLog = WebLog()
        webLog.startTime = System.currentTimeMillis()
        val attributes = RequestContextHolder.getRequestAttributes() as ServletRequestAttributes?
        val request = attributes!!.request
        val args = joinPoint.args
        val paramNames = (joinPoint.signature as CodeSignature).parameterNames
        val params = HashMap<String, Any>(args.size)
        for (i in args.indices) {
            if (args[i] !is BindingResult) {
                params[paramNames[i]] = args[i]
            }
        }
        webLog.id = UUID.randomUUID().toString()
        webLog.request = params.toString()
        webLog.requestUrl = request.requestURI.toString()
        webLog.requestIp = request.remoteAddr
        webLog.method = request.method
        webRequestLog.set(webLog)
        logger.info("REQUEST={} {}; SOURCE IP={}; ARGS={}", request.method,
                request.requestURL.toString(), request.remoteAddr, params)
    }

    @AfterReturning(returning = "ret", pointcut = "webLog()")
    @Throws(Throwable::class)
    fun doAfterReturning(ret: Any) {
        val webLog = webRequestLog.get()
        webLog.response = ret.toString()
        webLog.endTime = System.currentTimeMillis()
        webLog.time = webLog.endTime!! - webLog.startTime!!
        logger.info("RESPONSE={}; SPEND TIME={}MS", ObjectMapper().writeValueAsString(ret), webLog.time)
        logger.info("webLog:{}", webLog)
        webLogRepository.save(webLog)
        webRequestLog.remove()
    }
}

Here we define the aspect of the Web layer, and I can also define a aspect for the Service layer, but we can lower the level slightly for the entry and return logs of the Service layer. Here we change debug, which is implemented as follows:

package io.intodream.kotlin07.aspect

import com.fasterxml.jackson.databind.ObjectMapper
import org.aspectj.lang.JoinPoint
import org.aspectj.lang.annotation.AfterReturning
import org.aspectj.lang.annotation.Aspect
import org.aspectj.lang.annotation.Before
import org.aspectj.lang.annotation.Pointcut
import org.aspectj.lang.reflect.CodeSignature
import org.slf4j.Logger
import org.slf4j.LoggerFactory
import org.springframework.core.annotation.Order
import org.springframework.stereotype.Component
import org.springframework.validation.BindingResult

/**
 * service Layer All public Decorated Method Calls Return Logs
 *
 * @author yangxianxi@gogpay.cn
 * @date 2019/4/10 17:33
 *
 */
@Aspect
@Order(2)
@Component
class ServiceLogAspect {

    private val logger: Logger = LoggerFactory.getLogger(ServiceLogAspect::class.java)

    /**
     *
     */
    @Pointcut(value = "execution(public * io.intodream..service.*.*(..))")
    private fun serviceLog(){}

    @Before(value = "serviceLog()")
    fun deBefore(joinPoint: JoinPoint) {
        val args = joinPoint.args
        val codeSignature = joinPoint.signature as CodeSignature
        val paramNames = codeSignature.parameterNames
        val params = HashMap<String, Any>(args.size).toMutableMap()
        for (i in args.indices) {
            if (args[i] !is BindingResult) {
                params[paramNames[i]] = args[i]
            }
        }
        logger.debug("CALL={}; ARGS={}", joinPoint.signature.name, params)
    }

    @AfterReturning(returning = "ret", pointcut = "serviceLog()")
    @Throws(Throwable::class)
    fun doAfterReturning(ret: Any) {
        logger.debug("RESPONSE={}", ObjectMapper().writeValueAsString(ret))
    }
}

Interface test

There is no need to post the Service layer and web code to achieve, because I copy the JPA chapter before the code, the only difference is to add the aspect, the addition of the aspect does not affect the original business process.

Perform the following requests:

We will see the following logs in the console

2019-04-14 19:32:27.208  INFO 4914 --- [nio-9000-exec-1] i.i.kotlin07.aspect.WebLogAspect         : REQUEST=POST http://localhost:9000/api/student/; SOURCE IP=0:0:0:0:0:0:0:1; ARGS={student={"id":"5","name":"Rose","age":17,"gender":"Girl","sclass":"Second class"}}
2019-04-14 19:32:27.415  INFO 4914 --- [nio-9000-exec-1] org.mongodb.driver.connection            : Opened connection [connectionId{localValue:2, serverValue:4}] to localhost:27017
2019-04-14 19:32:27.431  INFO 4914 --- [nio-9000-exec-1] i.i.kotlin07.aspect.WebLogAspect         : RESPONSE={"id":"5","name":"Rose","age":17,"gender":"Girl","sclass":"Second class"}; SPEND TIME=239MS
2019-04-14 19:32:27.431  INFO 4914 --- [nio-9000-exec-1] i.i.kotlin07.aspect.WebLogAspect         : webLog:{"id":"e7b0ca1b-0a71-4fa0-9f5f-95a29d4d54a1","request":"{student={\"id\":\"5\",\"name\":\"Rose\",\"age\":17,\"gender\":\"Girl\",\"sclass\":\"Second class\"}}","response":"{\"id\":\"5\",\"name\":\"Rose\",\"age\":17,\"gender\":\"Girl\",\"sclass\":\"Second class\"}","time":239,"requestUrl":"/api/student/","requestIp":"0:0:0:0:0:0:0:1","startTime":1555241547191,"endTime":1555241547430,"method":"POST"}

Looking at the database, you can see that our request log has been written:

Here's one thing to note about the implementation of Service Layer, which is as follows:

return studentRepository.findById(id).get()

findById here returns an Optional < T> object. If we do not find the data, the exception java.util.NoSuchElementException: No value present will appear when we use get to get the data. We can change the return object to null as long as we add a? After the return type. At the same time, we call Optional's ifentPresentation for security operations.