在Springboot中更好的打印日志
说明
我的系统缺乏一些日志打印,但我并不想显式的在我的业务代码中使用@Slf4j注解,因为这会造成我无法关注我的业务代码逻辑,因为通常来说,10行业务代码 你可以就需要3-4行log.info来打印日志
是的,这样代码很难看,所以我使用了Aop 拦截器 面向对象 threadLoacl等技术来设计我的程序日志打印
具体实现
在开始具体展示代码之前,我觉得有必要大概说一下实现的步骤
1.使用interceptor拦截器来拦截我的所有http请求,并初始化一个context上下文对象(基于threadLocal实现)
2.设计1个Aop,第一个Aop拦截所有的controller方法和serverImpl方法,然后将这些方法的入参和出参信息,来写入到context对象中
3.设计1个sql拦截器,来拦截所有执行的sql,然后将sql写入到context对象中
4.设计另1个aop,来打印所有收集到的context内容(在http请求将要结束之前(还未结束))
好的 你现在已经看到了大概的设计步骤 也许你有点不太懂 没有关系 我画了一张图来描述整个context的创建 到收集 到消费(打印日志)的全部过程 如下:
下面我将逐步展示实现的代码 并解释我为什么这样做, 因为说实在的 在设计这个微小框架的时候我遇到了一些问题
这些问题大概是这样的:
1.如果拦截所有controller方法 那么如果出现controller方法调用controller方法呢? 那么此时aop逻辑会执行2次(是的,我的系统是一个单体架构,我通常会这样写代码controller调用controller,但是本文章暂时不探讨此情况是否合适,只是说我遇到了此情况)
2.当同一个方法被多个aop代理时,@Order注解却失效了,aop代理们不能以预期的顺序执行,我被迫使用了@Priority作为代替
一个可爱的分割线--------------------------------------------------------------------------
好了 先不说什么问题了,别忘记正事, 首先我要给你看的是context对象的设计 这很重要 我必须先贴出来 (但是很大概率,你可能会觉得这什么GouShi?,好吧,我承认这很悲催,但你必须硬着头皮记好这个对象,它很重要,它很重要,它很重要*n)
//http请求上下文
@Data
public class ContextHttp {
private String eventId; //事件id 记录当前事件id,一个http调用代表1次事件,在此事件内发生的所有controller方法执行,service方法执行,sql执行都属于此次事件
private MyDate startTime; //开始时间 记录当前http请求进入的时间
private String ip; //请求者的ip 记录http请求发起者的ip
private String path; //访问路径 记录http请求访问路径
private ArrayDeque<ContextFunction> functionInvokeStock;//方法调用链.调用栈信息
private MyStep functionInvokeStep; //方法调用链.步进步出值
}看到这个context对象了吗,其实上面4个字段 你根本无需关注
它们只是大多数ContextHttp对象都有的值,我认为你应该关注这俩字段
private ArrayDeque<ContextFunction> functionInvokeStock; //方法调用链.调用栈信息
private MyStep functionInvokeStep; //方法调用链.步进步出值是的 我使用了面向对象设计 MyDate和MyStep就是 他们封装了一些底层数据 用于更好的支持当前的业务需要 MyDate不必多说 它封装了一个LocalDateTime对象
//面向对象:date
@Data
public class MyDate {
private LocalDateTime localDateTime;
此处省略.............
}但是MyStep请你务必好好关注
在介绍MyStep之前 你需要弄明白2个关键字 步入 和 步出
老实说 坦白说 说实话 说人话 : 步入就是方法入参的时候 步出就是方法出参的时候
以下这个图代表了方法的多次步入和步出 以及嵌套步入和步出
好了 下面是MyStep的具体实现 他的实现基本基于上图
想说的话 都写在注释里面了
//步入步出对象
@Data
public class MyStep {
//步入和步出的栈(栈:先进后出,用原生Stock也可以,只是使用ArrayDeque性能可能好点)
private ArrayDeque<Integer> stepStock;
//当前步入值
private AtomicInteger currentStepValue;
/*
* 创建一个步入步出器
* 当我们创建一个MyStep时
* 它的步入值为0 代表没有任何的步入
* 它的步入步出栈也是空的(0元素) 代表没有任何步入步出的栈帧进入
*/
public static MyStep of() {
MyStep myStep = new MyStep();
myStep.setStepStock(new ArrayDeque<>(initialStepSize()));
myStep.setCurrentStepValue(new AtomicInteger(0));
return myStep;
}
/*
* 步入步出器是初始化的吗?
* 当步入步出栈元素是空的 代表是初始化的
* 步入步出栈元素是空的 有2种情况 1是刚创建完毕 2是刚使用完毕
*/
public boolean isInitial() {
return this.stepStock.size() == initialStepSize();
}
//返回步入步出栈初始化的大小
private static int initialStepSize() {
return ConstantNumber.N_0_002; // 0
}
/*
* 步入
* 当调用步入时 则对当前步入值进行增量1
* 并且将增量1的结果写入到栈内
* (push是把元素写入到最顶端,栈嘛,就是这样,有首歌怎么唱来着,come on 逆战逆战 来也 啊呸呸呸 跑题了啊喂)
*/
public Integer intoAndGet() {
int i = currentStepValue.incrementAndGet();
this.stepStock.push(i);
return i;
}
/*
* 步出
* 当调用步出时 则在栈内弹出最顶端的元素 并返回
*/
public Integer outOfAndGet() {
return this.stepStock.pop();
}
}好了 在你搞懂MyStep的设计之后 恭喜你 送你3个表情包
现在再来看看ContextFunction对象吧 别担心 它很简单 是的 它只是一个正常的记录对象而已 并不是面向对象设计
ContextFunction
//方法调用链.调用帧
@Data
public class ContextFunction {
private String name; //方法名称
private Integer invokeValue; //步入值或步出值
private String invokeType; //步入还是步出? 1步入 2步出 3sql
private String invokeResource;//步入或步出或sql的资源(方法出参或入参或sql)
}
现在你已经认识了contextHttp对象的所有信息了 再来看看维护context的threadLocal吧
是的 它很简单 只是对ThreadLocal做一层全局的封装(这里全局指的是同一个线程下 所有人都可以通过ContextThreadLocal.get()) 来获取contextHttp对象
//Context ThreadLocal
public class ContextThreadLocal {
private ContextThreadLocal() {
}
private static final ThreadLocal<ContextHttp> tl = new ThreadLocal<>();
public static void set(ContextHttp contextHttp) {
tl.set(contextHttp);
}
public static ContextHttp get() {
return tl.get();
}
public static void remove() {
tl.remove();
}
}那么现在就是 使用context对象的时候了 嘿 还记得吗 我们要在interceptor拦截器中去出初始化它
如下:
//http请求拦截器
@Component
@Slf4j
public class InterceptorControllerFunction implements HandlerInterceptor {
//拦截http请求
@Override
public boolean preHandle(@NotNull HttpServletRequest request, @NotNull HttpServletResponse response, @NotNull Object handler) {
/*
* 在SpringBoot中，所有标注了 @RestController 或 @RequestMapping 注解的方法，都会被封装为 HandlerMethod 类型。
* 所以 如果请求处理器不是控制器方法（即非 @RestController 或 @RequestMapping 等注解的方法），则不进行处理。
*/
if (!(handler instanceof HandlerMethod)) {
return true;
}
try {
//组装context对象的上下文参数
ContextHttp contextHttp = new ContextHttp();
contextHttp.setEventId(RoleId.idUUIDTrim());
contextHttp.setStartTime( new MyDate() );
contextHttp.setPath(request.getRequestURI());
contextHttp.setIp(request.getRemoteAddr());
contextHttp.setFunctionInvokeStep(MyStep.of());
contextHttp.setFunctionInvokeStock(new ArrayDeque<>());
//初始化context对象的上下文参数
ContextThreadLocal.set(contextHttp);
//放行方法
return true;
} catch (Exception e) {
e.printStackTrace();
return false;
}
}
//在请求完成之后
@Override
public void afterCompletion(@NotNull HttpServletRequest request, @NotNull HttpServletResponse response, @NotNull Object handler, Exception ex) throws Exception {
ContextThreadLocal.remove();//移除当前线程的threadLocal的上下文数据
HandlerInterceptor.super.afterCompletion(request, response, handler, ex);//如果当前拦截器有父类 那么需要调用一下下面这行方法 否则不需要
}
}你可能 有一些疑问 为什么要在拦截器中初始化context对象 而不是在aop阶段?
是的 这就是我想说的第一个事情 : 我认为interceptor和aop有必要针对于context的访问和写入权限来做一些规范
我目前遵循的规范是 interceptor来初始化context对象 aop们来访问和填充或修改context对象
举一个栗子 aop们可以对context对象的functionInvokeStep字段来写入值 但是aop们不能去set整个functionInvokeStep 好吧 也许你听不明白 那么看一下代码吧
如果你还是看不懂 没关系 我还可以画一张图
是的 如图所示 我这么做完全是为了 能够统一的管理context的初始化值 防止在系统的各个地方都去set 造成混乱
OK 现在恭喜你 已经看了三分之一了
interceptor的逻辑已经看完了 它的作用就是初始化context 再来看看Aop们吧
切入点声明 , 我抽取了一个interface用于声明切入点 此interface并不具有任何的业务逻辑 你可以把它当做一个常量类来看待
其中controllerMethods是指向系统内所有controller方法的切入点
其中serviceImpMethods是指向系统内所有serverImpl方法的切入点
//用于声明Aop切入点
public interface AopZPointcut {
/*
* 在Java中，方法是由以下几个部分组成的：
* 1返回类型
* 2包名、类名
* 3方法名
* 4参数列表
* 例如，一个完整的方法声明是这样的:
* public int com.example.MyClass.myMethod(java.lang.String arg1, int arg2)
* 所以这解释了为什么aop的切入点表达式的第一个*代表方法的返回值,因为它要尽可能和java方法一样,降低人们对切入点表达式的学习成本
* AOP切入点表达式: @Pointcut("execution(* cn.xiaokeer.a_controller.*.*(..))")
*
*/
/*
* 定义切入点，拦截所有Controller类的所有方法
* 第一个*代表方法任意返回值
* cn.xiaokeer.a_controller代表controller包的路径
* 第二个*代表任意的controller包下的类
* 第三个*代表类内的任意方法
* (..)代表方法的任意入参
*/
@Pointcut("execution(* cn.xiaokeer.biz_controller.*.*(..))")
static void controllerMethods() {}
@Pointcut("execution(* cn.xiaokeer.biz_service_impl.*.*(..)))")
static void serviceImplMethods(){}
@Pointcut("@annotation(cn.xiaokeer.config_annotation.EnumAopTortoiseApi)")
static void enumAopTortoiseApi() { }
}AopAssembleStock
这个aop的逻辑非常简单 首先它拦截所有controller和serverImpl方法 在这些方法执行之前 对context内的方法调用栈写入栈帧 , 以及在这些方法执行成功之后 再次对context内的方法调用栈写入栈帧
但我依然需要告诉你一些事情
1.请你不要关注RoleAop这个类的逻辑 它只是一个工具类 用于操作JoinPoint对象
2.请你关注一下@Before中的 contextHttp.getFunctionInvokeStep().intoAndGet() 这行代码 因为这是最主要的逻辑 , 是的它在操作我们之前说的MyStep对象 它执行了一次步入 ,此次步入将得到1(如果是第一次aop拦截的时候,如果是第二次aop拦截,那么写入的步入值就是2)
3.请你关注一下@AfterReturning中的 contextHttp.getFunctionInvokeStep().outOfAndGet()这行代码 , 是的,它也在操作我们之前所说的MyStep对象, 它执行了一次步出,此次步出将得到上一次最新的步入值
4.如果你看不懂我在说什么 那我只好画一个图了 谁叫我这么宠你呢
//拦截controller和serverImpl的方法 并在contextHttp中写入方法调用帧
@Priority(AopZPriority.ORDER + AopZPriority.INCREMENT * ConstantNumber.N_3_003)
@Aspect
@Slf4j
@Component
public class AopAssembleStock {
//在方法执行之前 执行
@Before("cn.xiaokeer.support_aop.AopZPointcut.controllerMethods() " +
"|| cn.xiaokeer.support_aop.AopZPointcut.serviceImplMethods()")
public void beforeControllerMethod(JoinPoint joinPoint) {
ContextHttp contextHttp = ContextThreadLocal.get();
//组装方法上下文信息(调用帧)
ContextFunction f = new ContextFunction();
f.setInvokeResource(RoleAop.getArgsStr(joinPoint));//设置方法入参
f.setName(RoleAop.getMethodName(joinPoint));//设置方法名称
f.setInvokeValue(contextHttp.getFunctionInvokeStep().intoAndGet()); //设置方法调用步入值
f.setInvokeType("1"); //设置本次的调用帧类型是步入
//在方法调用链末尾插入本次的调用帧
contextHttp.getFunctionInvokeStock().addLast(f);
}
//在方法执行成功之后 执行
@AfterReturning(pointcut = "cn.xiaokeer.support_aop.AopZPointcut.controllerMethods() " +
"|| cn.xiaokeer.support_aop.AopZPointcut.serviceImplMethods()",
returning = "result")
public void afterReturning(JoinPoint joinPoint, Object result) {
ContextHttp contextHttp = ContextThreadLocal.get();
//组装方法上下文信息(调用帧)
ContextFunction f = new ContextFunction();
f.setInvokeResource(RoleJson.to(result));
f.setName(RoleAop.getMethodName(joinPoint));
f.setInvokeValue(contextHttp.getFunctionInvokeStep().outOfAndGet());
f.setInvokeType("2"); //设置本次的调用帧类型是步出
//在方法调用链末尾插入本次的调用帧
contextHttp.getFunctionInvokeStock().addLast(f);
}
}好了 现在你已经知道了方法调用们是如何被收集信息了的 那么再来看看我们要如何打印这些context为日志吧
AopPrintControllerLog
是的了 这就是我在文章开头提到的第另个Aop 它是真正打印所有方法调用日志的aop
包括controller入参日志 controller出参日志 以及最主要的 方法调用链日志
注意观察代码
我们先来看看@Befor的逻辑 , 你会发现在打印日志之前 会先执行一下
contextHttp.getFunctionInvokeStep().isInitial()
这是在向context上下文询问: 方法调用栈是初始化的吗? 我来告诉你为什么要这么做 以及不这样做的后果
因为如果刚进入aop代理逻辑 那么此条件一定满足 那么就打印controller入参信息 这没什么问题
但如果controller调用controller呢? 是的 此aop逻辑会再次进入,如果你不加这个条件 它就会再次打印一遍controller入参日志 但如果你加了 那么就算第二次进入此aop逻辑 此条件也不再满足 因为调用栈已经被写入了一次栈帧了(对 就是刚刚的AopAssembleStock的aop写入的)
好了@Before的逻辑 你已经看懂了 那么@AfterReturning也一样 同样会询问一下 方法调用栈是初始化的吗? 然后才进行controller的结束日志打印 以及打印全部的方法调用栈信息 这里是使用的pop一个个弹出stock的信息 你也可以换成for循环
@Priority(AopZPriority.ORDER + AopZPriority.INCREMENT * ConstantNumber.N_2_002)
@Aspect
@Slf4j
@Component
public class AopPrintControllerLog {
//在方法执行之前 执行
@Before("cn.xiaokeer.support_aop.AopZPointcut.controllerMethods()")
public void beforeControllerMethod(JoinPoint joinPoint) {
ContextHttp contextHttp = ContextThreadLocal.get();
//如果当前刚开始步进 则打印方法入参信息
if (contextHttp.getFunctionInvokeStep().isInitial()) {
String path = contextHttp.getPath();
String ip = contextHttp.getIp();
String args = RoleAop.getArgsStr(joinPoint);
String eventId = contextHttp.getEventId();
log.info("EventId:[{}],RequestMapping:[{}], RequestParams:[{}],ip:[{}]",eventId,path, args, ip);
}
}
//在方法执行成功之后 执行
@AfterReturning(returning = "response",
pointcut = "cn.xiaokeer.support_aop.AopZPointcut.controllerMethods()")
public void doAfterRunning(Object response) {
ContextHttp contextHttp = ContextThreadLocal.get();
//如果是步出完毕 则打印方法出参日志
if (contextHttp.getFunctionInvokeStep().isInitial()) {
//打印方法调用栈
ArrayDeque<ContextFunction> stock = contextHttp.getFunctionInvokeStock();
ContextFunction f;
while ((f = stock.pollFirst()) != null) {
log.info("EventId:[{}],name:[{}],invokeValue:[{}],invokeType:[{}],invokeResource:[{}]",
contextHttp.getEventId(), f.getName(), f.getInvokeValue(), f.getInvokeType(), f.getInvokeResource());
}
//打印 路径 响应 执行耗时
String path = contextHttp.getPath();
long time = System.currentTimeMillis() - contextHttp.getStartTime().unixTimestamp();
log.info("EventId:[{}],RequestMapping:[{}], Response:[{}], spend times: [{}ms]",contextHttp.getEventId(), path, response, time);
}
}
}最后的sql的拦截
sql拦截你可以参考此文章 https://blog.csdn.net/weixin_55768452/article/details/139717597
此文章已经说的很清楚了 拿来改一改就行 (把print输出的日志 给放到context中的方法调用链中)
至此 你可以看完了所有的代码实现了 我已经迫不及待要向你展示一下最终的效果了
我们来刷新一下前端的页面 发起几个调用
然后观察一下springBoot的日志
END