SpringBoot 2.X Kotlin系列之AOP统一打印日志

在开发项目中，我们经常会需要打印日志，这样方便开发人员了解接口调用情况及定位错误问题，很多时候对于Controller或者是Service的 入参 和 出参 需要打印日志，但是我们又不想重复的在每个方法里去使用 logger 打印，这个时候希望有一个管理者统一来打印，这时Spring AOP就派上用场了，利用切面的思想，我们在进入、出入Controller或Service时给它 切一刀 实现统一日志打印。

SpringAOP不仅可以实现在不产生新类的情况下打印日志，还可以管理事务、缓存等。具体可以了解官方文档。 https://docs.spring.io/spring/docs/current/spring-framework-reference/core.html#aop-api

基础概念

在使用SpringAOP，这里还是先简单讲解一些基本的知识吧，如果说的不对请及时指正，这里主要是根据官方文档来总结的。本章内容主要涉及的知识点。

Pointcut: 切入点，这里用于定义规则，进行方法的切入（形象的比喻就是一把刀）。

JoinPoint: 连接点，用于连接定义的切面。

Before: 在之前，在切入点方法执行之前。

AfterReturning: 在切入点方法结束并返回时执行。

这里除了SpringAOP相关的知识，还涉及到了线程相关的知识点，因为我们需要考虑多线程中它们各自需要保存自己的变量，所以就用到了 ThreadLocal 。

依赖引入

这里主要是用到 aop 和 mongodb ，在 pom.xml 文件中加入以下依赖即可:

<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>

相关实体类

/**
 * 请求日志实体，用于保存请求日志
 */
@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)
    }
}

/**
 * 业务对象，上一章讲JPA中有定义
 */
@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)
    }
}

定义切面

定义切入点

/**
 * 定义一个切入，只要是为io.intodream..web下public修饰的方法都要切入
 */
@Pointcut(value = "execution(public * io.intodream..web.*.*(..))")
fun webLog() {}

定义切入点的表达式还可以使用 within 、如:

/**
 * 表示在io.intodream.web包下的方法都会被切入
 */
@Pointcut(value = "within(io.intodream.web..*")

定义一个连接点

/**
 * 切面的连接点，并声明在该连接点进入之前需要做的一些事情
 */
@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()
}

这里的主要思路是，在方法执行前，先记录详情的请求参数，请求方法，请求ip， 请求方式及进入时间，然后将对象放入到 ThreadLocal 中，在方法结束后并取到对应的返回对象且计算出请求耗时，然后将请求日志保存到 mongodb 中。

完成的代码

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.*

/**
 * {描述}
 *
 * @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

    /**
     * 定义一个切入，只要是为io.intodream..web下public修饰的方法都要切入
     */
    @Pointcut(value = "execution(public * io.intodream..web.*.*(..))")
    fun webLog() {}

    /**
     * 切面的连接点，并声明在该连接点进入之前需要做的一些事情
     */
    @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()
    }
}

这里定义的是Web层的切面，对于Service层我也可以定义一个切面，但是对于Service层的进入和返回的日志我们可以把级别稍等调低一点，这里改 debug ,具体实现如下：

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层所有public修饰的方法调用返回日志
 *
 * @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))
    }
}

接口测试

这里就不在贴出Service层和web的代码实现了，因为我是拷贝之前将JPA那一章的代码，唯一不同的就是加入了切面，切面的加入并不影响原来的业务流程。

执行如下请求:

我们会在控制台看到如下日志

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"}

查看数据库会看到我们的请求日志已经写入了:

这里有一个地方需要注意，在Service层的实现，具体如下:

return studentRepository.findById(id).get()

这里的 findById 会返回一个 Optional<T> 对象，如果没有查到数据，我们使用 get 获取数据会出现异常 java.util.NoSuchElementException: No value present ，可以改为返回对象可以为空只要在返回类型后面加一个 ? 即可，同时调用 Optional 的 ifPresent 进行安全操作。