乐趣区

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

jiezi

在开发项目中，我们经常会需要打印日志，这样方便开发人员了解接口调用情况及定位错误问题，很多时候对于 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 进行安全操作。

退出移动版