日常开发日志打印需要注意哪些地方
- 不能面向debug编程,过于依赖debug,应该多依赖日志输出;
- 代码开发测试完成之后不要急着提交,先跑一遍看看日志是否看得懂;
- 日志必须包含哪些信息:
– 每次请求的唯一id(便于从海量的日志里区分某次请求);
– 每次请求的用户信息(从海量日志里快速找到该用户做了什么); - 某些地方必须打印日志:
- 分支语句的变量必须打印日志,重要参数必须打印(比如订单code等);
- 修改(包括新增)操作必须打印日志(出问题,做到有证可查);
- 数据量大的时候需要打印数据量,及耗时(用于分析性能。比如查询一个列表,要打印结果列表大小);
使用日志插件优雅解决以上问题
日志插件项目
点我 点我 我是日志插件项目 ,欢迎star
日志插件安装
下载源码,然后mvn install
到自己的maven仓库,最后在项目中添加如下依赖:
com.enhance
log-plugin
1.0-SNAPSHOT
项目添加日志配置文件,日志配置文件在日志插件里有案例,详情可参考日志插件的logback.xml文件,主要对日志输出格式做如下配置:
%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread %X{X-B3-TraceId}] %-5level[%X{user} %X{logjson} %X{code}]%logger{50} - %msg%n
UTF-8
- %X{X-B3-TraceId} :一次请求的唯一traceID
- %X{user} : 一次请求的用户信息,通过实现接口LogService获取用户信息,然后存入MDC
- %X{logjson} : 存放action、itemType和itemIds值
- %X{code}: 方法内一些想存放入MDC的值
日志平台(ELK)安装
下载源码去到nodes-stand-alone目录执行init.sh
脚本即可。这里搭建的ELK是在单台服务器上,不适合生产环境使用。
日志插件功能介绍
打印方法入参出参
方法添加注解code>@Log,所有入参、出参都打印
过滤掉不需要打印的入参
- 方法添加
@Log(excludeInParam = {"arg1"})
:排除第二个参数不打印 @Log(excludeInParam = {"arg0", "arg1"})
:多个参数时,忽略掉多个参数不打印@Log(excludeInParam = {"arg2.password"})
:忽略第二个参数的password属性不打印
指定打印某些参数或属性
@Log(includeInParam = {"arg2.name"})
:其他参数正常打印,第三个参数只打印user的name属性@Log(excludeInParam = {"arg2.password"},includeInParam = {"arg2.password"})
:当excludeInParam排除参数的某个属性和includeInParam冲突时,includeInParam生效@Log(excludeInParam = {"arg2"} , includeInParam = {"arg2.password"})
:当excludeInParam排除参数和includeInParam冲突时,excludeInParam生效
日志包含用户信息
实现LogService接口,然后在方法上添加@Log注解即可让日志信息包含用户信息
日志信息包含唯一的key
@LogProfiler(itemIds = "order.orderCode")
:比如订单修改,希望每条日志都包含订单编号@Log(itemIds = {"order.user.userCode","order.orderCode"})
:比如订单修改,希望每条日志都包含订单编号和订单所属用户@Log(itemIds = {"orderEntryDetails[0].orderId"})
: 比如订单修改时,订单行处理时,希望每条日志信息包含订单id
日志信息包含被操作表信息及操作类型
@Log(itemIds = {"orderDetailDTO.orderCode"},itemType = "order表",action = Action.U)
:当有海量日志时,可根据一条日志信息就能知道,具体用户对表的某条记录进行的具体的操作,及具体的操作内容。
日志工具
printCode(String describe, String separator, String... values)
:后续日志信息打印自定义描述和多个code值printCode(String describe, String value)
:后续日志打印自定义描述和code值printCodeByTemplate(String template, Object... values)
:后续日志打印自定义模板日志
日志插件使用
打印方法的入参和出参
经常出现正式环境出问题了,然后发现没有打印方法的入参和出参,然后重新发版就为了添加一条日志,虽然这种做法很low,但是是可能发生的。只需要添加一个@Log注解就能轻松解决。
打印方法入参出参
添加注解@Log,@Log默认是debug级别才会打印入参和出参的,可通过printInfoLog来控制是否打印
- printInfoLog为true,默认会打印INFO级别日志,但是会导致日志里增加
- printInfoLog默认值为false,可通过动态修改某个类的日志级别为DEBUG,达到打印方法入参和出参的目的
过滤掉不需要打印的入参
当一个入参很大,某些数据打印出来没意义,或者属于敏感信息不能打印,可以通过excludeInParam过滤掉不打印。
- 多个参数时,忽略掉某个参数不打印
-
多个参数时,忽略掉多个参数不打印
-
忽略某个参数的某些属性不打印
-
参数时集合类型,忽略掉不打印
指定打印某些参数或属性
当一个方法有多个入参,可以通过includeInParam或param指定打印某些参数,或某些参数的指定属性,从而只打印自己关心部分的日志,减少日志量。
- 打印某个参数的指定属性,其它参数正常打印
-
当excludeInParam排除参数的某个属性和includeInParam冲突时,includeInParam生效
-
当excludeInParam排除参数和includeInParam冲突时,excludeInParam生效
-
当配置了param,就只会打印param配置的参数,此时excludeInParam和includeInParam不会生效
出参只打印数组大小
当方法的出参是一个集合时,可通过printOutParamSize控制是打印集合详情,还是只打印集合大小;在controller层,往往出参是包了一层,真正的数据只是出参对象的一个属性值,此时可通过继承FilterResultService类,实现shouldFilter方法和filter方法,对结果进行处理,已达到只打印集合大小和真正的数据详情。
public abstract class FilterResultService {
public abstract boolean shouldFilter(U u);
public Optional filterResult(U u) {
if (shouldFilter(u)) {
log.info("Start dealing with the results");
return Optional.ofNullable(filter(u));
}
return null;
}
public abstract T filter(U u);
}
默认了一个DefaultFilterResultServiceImpl对结果进行处理:
@Component
public class DefaultFilterResultServiceImpl extends FilterResultService {
@Override
public boolean shouldFilter(Object o) {
return false;
}
@Override
public Object filter(Object o) {
return o;
}
}
日志尽可能多的包含有用信息
在尽可能包含更多有效信息的同时,不能增加太多的额外工作;
日志包含用户信息
实现LogService接口,然后再方法上添加@Log注解即可
@Component
public class UserInfoService implements LogService {
/**
* 获取用户信息,用于放入日志框架的MDC里
*
* @return java.lang.String
* @author gongliangjun 2019-12-19 3:33 PM
*/
@Override
public String getUserInfo() {
// 这里为了测试,模拟从请求中获取用户信息,可根据自己实际情况修改
return "admin001";
}
在查询订单列表上添加@Log注解
日志信息包含唯一的key
- 比如订单修改,希望每条日志都包含订单编号
-
比如订单修改,希望每条日志都包含订单编号和订单所属用户
这里的用户在请求pojo的orderDetailDTO.user.userCode里,所以注解是
@Log(itemIds = {"orderDetailDTO.user.userCode"})
-
比如订单修改时,订单行处理时,希望每条日志信息包含订单id
处理订单行方法入参是一个集合,所以注解是
@Log(itemIds = {"orderEntryDetails[0].orderId"})
日志信息包含被操作表信息及操作类型
比如在修改或者删除时,希望日志信息包含被操作的表和具体操作类型,以备出现问题时有证可查,这里需要用@Log的itemType和action,itemType表示表类型,action表示操作类型,操作有6种:
- A 新增操作
- D 删除操作
- U 更新操作
- Q 查询操作
- LQ 查询列表操作
- NULL 其他操作
添加注解@Log(itemIds = {"orderDetailDTO.orderCode"},itemType = "order表",action = Action.U)
,效果如下:
当有海量日志时,我们根据上图一条日志信息就能知道,用户admin001对order表orderCode为MO001的订单进行了更新操作,已经具体的更新内容。
多个方法使用@Log注解
这里我以一个尽可能真实的案例来举例。一个订单详情查询接口,其中包含订单头详情、订单行详情、产品详情和用户详情4个方法,大概调用情况如下:
queryOrderDetail
、conversionOrder
、 conversionOrderEntry
、 conversionSku
和 code>conversionUser几个方法都加@Log注解,@Log主要是基于MDC实现的,所以在queryOrderDetail
方法调用方法conversionOrder
,进入conversionOrder
方法时,MDC里存入的就是conversionOrder
方法相关的值,再回到前方法queryOrderDetail
时,MDC中应该切换为方法queryOrderDetail
的值。所以这里存在一个方法调用栈,也需要一个上下文来存储方法相关的MDC值。所以这里我使用了一个LogThreadContext
上下文来存储方法相关的MDC值,和管理方法调用关系的一个stack,然后把LogThreadContext放入到InheritableThreadLocal
中。
具体调用时,日志打印效果如下:
以上每条日志信息都包含一个唯一的tranceID,配合日志框架,比如ELK(项目也有基于docker 快速搭建ELK日志平台的脚本),便可以从海量日志里快速筛选出一次请求的所有日志;也包含了此次请求的用户(实现接口LogService获取用户信息);也包含了每个方法特定的key,方便程序员追溯问题。
日志工具使用
通过LogUtil提供的一下方法,可以在项目开发中使打印的日志信息更有意义,简便了日志打印,从而提高工作效率。LogUtil中简便打印日志的方法,主要使用场景还是在实际项目中,当遇到循环处理逻辑时,循环体逻辑复杂,这时候需要循环体里的日志每条都包含具体处理记录的信息。LogUtil主要提供了如下几个方法:
- printCode(String describe, String separator, String… values)
打印自定义描述和多个code值 需要配合@log或@LogProfiler注解一起使用,MDC才能清空 一般在循环内使用,循环结
束要调用clearMDC()
# 例子: for (OrderEntry orderEntry : orderEntries) { LogUtil.printCode("orderEntry skuid和数量", "-", orderEntry.getSkuId().toString(),orderEntry.getQuantity().toString()); log.info("开始处理..."); log.info("处理中"); log.info("处理结束"); LogUtil.clearMDC(); } 结果: INFO [(orderEntry skuid和数量:1-21)]c.enhance.logplugin.demo.service.OrderServiceImpl - 开始处理... INFO [(orderEntry skuid和数量:1-21)]c.enhance.logplugin.demo.service.OrderServiceImpl - 处理中 INFO [(orderEntry skuid和数量:1-21)]c.enhance.logplugin.demo.service.OrderServiceImpl - 处理结束
- printCode(String describe, String value)
打印自定义描述和code值 需要配合@log或@LogProfiler注解一起使用,MDC才能清空 一般在循环内使用,循环结束要调用clearMDC()
# 例子:orderEntries 有两条数据 for (OrderEntry orderEntry : orderEntries) { LogUtil.printCode("处理的skuid", orderEntry.getSkuId().toString()); log.info("开始处理..."); log.info("处理中"); log.info("处理结束"); LogUtil.clearMDC(); } 结果: INFO [(处理的skuid:1)]c.enhance.logplugin.demo.service.OrderServiceImpl - 开始处理... INFO [(处理的skuid:1)]c.enhance.logplugin.demo.service.OrderServiceImpl - 处理中 INFO [(处理的skuid:1)]c.enhance.logplugin.demo.service.OrderServiceImpl - 处理结束 INFO [(处理的skuid:2)]c.enhance.logplugin.demo.service.OrderServiceImpl - 开始处理... INFO [(处理的skuid:2)]c.enhance.logplugin.demo.service.OrderServiceImpl - 处理中 INFO [(处理的skuid:2)]c.enhance.logplugin.demo.service.OrderServiceImpl - 处理结束
- printCode(String value)
打印特定code值 需要配合@log注解一起使用,MDC才能清空 一般在循环内使用,循环结束要调用clearMDC()
例子:orderEntries 有两条数据 for (OrderEntry orderEntry : orderEntries) { LogUtil.printCode(orderEntry.getSkuId().toString()); log.info("开始处理..."); log.info("处理中"); log.info("处理结束"); LogUtil.clearMDC(); } 结果: INFO [1]c.enhance.logplugin.demo.service.OrderServiceImpl - 开始处理... INFO [1]c.enhance.logplugin.demo.service.OrderServiceImpl - 处理中 INFO [1]c.enhance.logplugin.demo.service.OrderServiceImpl - 处理结束 INFO [2]c.enhance.logplugin.demo.service.OrderServiceImpl - 开始处理... INFO [2]c.enhance.logplugin.demo.service.OrderServiceImpl - 处理中 INFO [2]c.enhance.logplugin.demo.service.OrderServiceImpl - 处理结束
- printCodeByTemplate(String template, Object… values)
自定义模板打印日志 需要配合@log注解一起使用,MDC才能清空 一般在循环内使用,循环结束要调用clearMDC()
# 例子:orderEntries 有两条数据 for (OrderEntry orderEntry : orderEntries) { LogUtil.printCodeByTemplate("skuId[{}] 数量[{}]",orderEntry.getSkuId(),orderEntry.getQuantity()); log.info("开始处理..."); log.info("处理中"); log.info("处理结束"); LogUtil.clearMDC(); } 结果: INFO [skuId:1 数量:21]c.enhance.logplugin.demo.service.OrderServiceImpl - 开始处理... INFO [skuId:1 数量:21]c.enhance.logplugin.demo.service.OrderServiceImpl - 处理中 INFO [skuId:1 数量:21]c.enhance.logplugin.demo.service.OrderServiceImpl - 处理结束 INFO [skuId:2 数量:11]c.enhance.logplugin.demo.service.OrderServiceImpl - 开始处理... INFO [skuId:2 数量:11]c.enhance.logplugin.demo.service.OrderServiceImpl - 处理中 INFO [skuId:2 数量:11]c.enhance.logplugin.demo.service.OrderServiceImpl - 处理结束
方法执行耗时统计
实际项目可能需要对一个方法执行耗时进行统计,以便找到效率比较低的方法,后续好做系统优化。通过日志插件的code>@EnableProfiler和code>@LogProfiler注解,可以轻松实现对一个方法执行时间进行统计。code>@EnableProfiler只对方法进行耗时统计,不具备打印日志功能;code>@LogProfiler具备日志打印和耗时统计功能,相当于@Log和@code>@EnableProfiler。
方法调用执行耗时统计
这里还是以订单详情查询作为例子,在每个需要统计的方法上添加code>@EnableProfiler或code>@LogProfiler注解
方法内代码块执行耗时统计
这里还是以订单详情查询接口举例,在queryOrderDetail方法内单独统计了查询一个订单所用时长,和模拟一段复杂逻辑执行所用时长。通过LogUtil的startProfiler(name)
方法对方法内的代码块执行耗时进行统计,然后在整个执行耗时统计里打印出来。
@LogProfiler(itemIds = "orderCode")
@Override
public OrderDetailDTO queryOrderDetail(String orderCode) {
log.info("开始处理订单数据");
SleepUtil.threadSleep(2);
Order order1 = new Order();
order1.setOrderCode(orderCode);
// 想统计查询一个订单所用时间
LogThreadContext ltc = LogUtil.startProfiler("findOne");
Optional orderOptional = orderMapper.findOne(Example.of(order1));
ltc.stopInstantProfiler();
//统计一段复杂逻辑耗时
LogUtil.startProfiler("复杂逻辑统计");
log.info("模拟这里需要处理一大段逻辑");
SleepUtil.threadSleep(4,10);
ltc.stopInstantProfiler();
......
......
log.info("订单数据处理完成");
return detailDTO;
}
日志插件核心类
- LogThreadContext日志上下文,存放了方法相关的日志信息
@XSlf4j public final class LogThreadContext { public final static ThreadLocal
LOG_THREAD_CONTEXT = new InheritableThreadLocal<>(); private final static String TRACEID = "X-B3-TraceId"; /** * 当前方法的日志上下文 */ private LogContext currentLogContext; //瞬间统计器 通过LogsUtil.startProfiler 产生的Profiler private Profiler instantProfiler; /** * 方法调用时日志上下文存放的一个栈 */ private Stack logContexts = new Stack<>(); /** * 方法调用时MDC相关信息存放的一个栈 */ private Stack - LogAop
@Aspect @Component @Order(1) //order最小最先执行 保证ProfilerAOP 后于LogAop执行 public class LogAOP implements ApplicationContextAware { /** * logger */ private static final Logger LOG = XLoggerFactory.getXLogger(LogAOP.class); private static final String LOG_JSON = "logjson"; private static final String USER = "user"; private static final String CODE = "code"; private static final String DOT_NOTATION = "."; @Autowired private List
filterResultServices; private LogService logService; @Pointcut("@annotation(com.enhance.annotations.Log) || @annotation(com.enhance.annotations.LogProfiler)") public void logPoint() { } @SneakyThrows @Around("logPoint()") public Object handlerLogMethod(ProceedingJoinPoint joinPoint) { // // 得到方法上的注解 // ------------------------------------------------------------------------------ MethodSignature signature = (MethodSignature) joinPoint.getSignature(); Method method = signature.getMethod(); LogProfiler logProfiler = method.getAnnotation(LogProfiler.class); Log logAnnotation = method.getAnnotation(Log.class); Object result = null; if (logAnnotation != null && null != logProfiler) { LOG.warn("@LogProfiler 和 @Log 不允许一起使用"); result = joinPoint.proceed(); } else { LogThreadContext ltc = LogThreadContext.getLogThreadContext(); try { try { initLogContext(method, ltc); this.handBeforeMethodLog(joinPoint, ltc); } catch (Exception e) { LOG.warn("handlerLogMethod before:{}", e); } result = joinPoint.proceed(); } finally { try { if (null != logProfiler) { ProfilerAOP.printProfiler(ltc); } this.handAfterMethodLog(joinPoint, ltc, result); this.handleMDCValue(); } catch (Exception e) { LOG.warn("handlerLogMethod finally:{}", e); } } } return result; } /** * 初始化日志上下文 * * @return void * @author gongliangjun 2020-06-04 2:30 PM */ private void initLogContext(Method method, LogThreadContext ltc) { LogContext logContext = new LogContext(); LogProfiler logProfiler = method.getAnnotation(LogProfiler.class); Log logAnnotation = method.getAnnotation(Log.class); if (logProfiler != null) { logContext.setEnableLog(true); logContext.setAction(logProfiler.action()); logContext.setEnableProfiler(true); logContext.setExcludeInParam(logProfiler.excludeInParam()); logContext.setIncludeValue(logProfiler.includeInParam()); logContext.setItemIds(logProfiler.itemIds()); logContext.setItemType(logProfiler.itemType()); logContext.setParam(logProfiler.param()); logContext.setPrintInfoLog(logProfiler.printInfoLog()); logContext.setPrintOutParamSize(logProfiler.printOutParamSize()); logContext.setProfilerName(logProfiler.profilerName()); } else if (logAnnotation != null) { logContext.setEnableLog(true); logContext.setAction(logAnnotation.action()); logContext.setExcludeInParam(logAnnotation.excludeInParam()); logContext.setIncludeValue(logAnnotation.includeInParam()); logContext.setItemIds(logAnnotation.itemIds()); logContext.setItemType(logAnnotation.itemType()); logContext.setParam(logAnnotation.param()); logContext.setPrintInfoLog(logAnnotation.printInfoLog()); logContext.setPrintOutParamSize(logAnnotation.printOutParamSize()); } ltc.putContext(logContext); ltc.setCurrentLogContext(logContext); } /** * 方法执行完成后 处理MDC里的值 * * @return void * @author gongliangjun 2020-06-04 2:25 PM */ private void handleMDCValue() { LogThreadContext ltc = LogThreadContext.getLogThreadContext(); try { //=============================================================================== // 先对自己的code出栈 并且清除MDC //=============================================================================== Map popCallStack = ltc.popCallStack(); clearMDC(popCallStack.keySet()); if (!ltc.isEmptyCallStack()) { Map currentMethodStack = ltc.peekCallStack(); //=============================================================================== // 把之前方法的数据存入MDC //=============================================================================== for (Entry entry : currentMethodStack.entrySet()) { String key = entry.getKey(); String value = entry.getValue(); MDC.put(key, value); } } else { // 因为Tomcat线程重用 clearMDC(new String[]{CODE, USER, LOG_JSON}); } } catch (Exception e) { LOG.warn("handleMDCValue error: {} ", e); } } /** * 打印调用方法后的日志 * * @return void * @author 龚梁钧 2019-06-28 13:15 */ private void handAfterMethodLog(ProceedingJoinPoint joinPoint, LogThreadContext ltc, Object result) { LogContext logContext = ltc.getCurrentLogContext(); // 是否需要打印日志 boolean printLog = logContext.printInfoLog(); // 如果是数组 是否打印出参大小,不打印对象值 boolean printOutParamSize = logContext.printOutParamSize(); MethodSignature signature = (MethodSignature) joinPoint.getSignature(); StringBuffer endString = new StringBuffer(); Object target = joinPoint.getTarget(); Logger logger = LoggerFactory.getLogger(target.getClass()); if (target instanceof Proxy) { endString.append(signature.getDeclaringTypeName()) .append(".") .append(signature.getName()); } endString.append(signature.getName()); endString.append(" end "); if (logger.isDebugEnabled() || printLog) { if (result instanceof Collection && printOutParamSize) { logger.info(endString.append(" output parameters size:{}").toString(), Collection.class.cast(result).size()); return; } String responseStr = null; try { if (CollectionUtils.isNotEmpty(filterResultServices)) { for (FilterResultService filterResultService : filterResultServices) { Optional filterResult = filterResultService.filterResult(result); // 返回null,说明不需要处理 返回Optional.empty(),说明处理了,处理结果为null if (filterResult != null) { LOG.debug("返回结果处理成功"); if (filterResult.isPresent()) { Object fr = filterResult.get(); if (fr instanceof Collection && printOutParamSize) { logger.info(endString.append(" output parameters size:{}").toString(), Collection.class.cast(fr).size()); return; } else { responseStr = JSON.toJSONString(filterResult); } break; } else { LOG.debug("处理结果为空"); } } } } } catch (Exception e) { LOG.warn("handAfterMethodLog error:{}", e); } if (StringUtils.isEmpty(responseStr)) { responseStr = result == null ? "void" : JSON.toJSONString(result); } endString.append("output parameters:").append(responseStr); if (printLog) { logger.info(endString.toString()); } else { logger.debug(endString.toString()); } } else { logger.info(endString.toString()); } } /** * 打印调用方法前的日志 * * @return org.slf4j.Logger * @author 龚梁钧 2019-06-28 13:13 */ private Logger handBeforeMethodLog(ProceedingJoinPoint joinPoint, LogThreadContext ltc) { LogContext logContext = ltc.getCurrentLogContext(); String[] params = logContext.param(); Object target = joinPoint.getTarget(); Class> targetClass = target.getClass(); // 是否需要打印日志 boolean printLog = logContext.printInfoLog(); MethodSignature signature = (MethodSignature) joinPoint.getSignature(); Logger logger = LoggerFactory.getLogger(targetClass); if (logger.isDebugEnabled() || printLog) { //=============================================================================== // 保存action、itemType、itemId到MDC //=============================================================================== saveLogInfo2MDC(joinPoint, ltc); StringBuilder mesInfo = new StringBuilder(); if (target instanceof Proxy) { mesInfo.append(signature.getDeclaringTypeName()) .append("."); } mesInfo.append(signature.getName()); String profilerName = new StringBuilder(targetClass.getSimpleName()).append("#") .append(mesInfo.toString()).toString(); //=============================================================================== // 方法调用耗时统计 //=============================================================================== if (Boolean.TRUE.equals(logContext.enableProfiler())) { ProfilerAOP.handleProfiler(logger, ltc, logContext, profilerName); } mesInfo.append(" start parameters:{}"); // // 如果params大于0,说明存在用户想打印的参数 // ------------------------------------------------------------------------------ if (params.length > 0) { SPELUtil spel = new SPELUtil(joinPoint); JSONObject json = new JSONObject(); for (String param : params) { // 其他参数,spel表达式 json.put(param, spel.cacl(param)); } if (printLog) { logger.info(mesInfo.toString(), json.toJSONString()); } else { logger.debug(mesInfo.toString(), json.toJSONString()); } } else { // 所在的类.方法 String methodStr = this.getMethodParam(joinPoint, logContext); // String methodStr = this.getMethodParam(joinPoint, excludeInParam); if (printLog) { logger.info(mesInfo.toString(), methodStr); } else { logger.debug(mesInfo.toString(), methodStr); } } } return logger; } private void saveLogInfo2MDC(ProceedingJoinPoint pjp, LogThreadContext ltc) { //=============================================================================== // 保存用户信息到MDC //=============================================================================== if (this.logService != null) { String userInfo = logService.getUserInfo(); if (StringUtils.isNotEmpty(userInfo)) { MDC.put(USER, userInfo); } } JSONObject json = this.getLogJson(pjp, ltc); if (!json.isEmpty()) { String jsonString = json.toJSONString(); MDC.put(LOG_JSON, jsonString); ltc.putCallStack(new HashMap(3) {{ put(LOG_JSON, jsonString); }}); } else { ltc.putCallStack(new HashMap(1)); } } /** * 获取注解Log的值,构造成json,供sf4j使用 * * @return com.alibaba.fastjson.JSONObject * @author 龚梁钧 2019-06-28 11:24 */ private JSONObject getLogJson(ProceedingJoinPoint pjp, LogThreadContext ltc) { LogContext logContext = ltc.getCurrentLogContext(); LogConst.Action action = logContext.action(); String itemType = logContext.itemType(); String[] itemIds = logContext.itemIds(); SPELUtil spel = new SPELUtil(pjp); JSONObject json = new JSONObject(); // 操作 if (!LogConst.Action.NULL.equals(action)) { json.put("A", action.toString()); } // 对象类型 if (StringUtils.isNotEmpty(itemType)) { json.put("T", itemType); } // 对象类型 if (itemIds.length > 0) { for (String itemId : itemIds) { if (itemId.contains(DOT_NOTATION)) { String substring = itemId.substring(itemId.indexOf(DOT_NOTATION) + 1); json.put(substring, spel.cacl(itemId)); } else { json.put(itemId, spel.cacl(itemId)); } } } return json; } private void clearMDC(String[] clears) { for (String clear : clears) { MDC.remove(clear); } } private void clearMDC(Set clears) { for (String clear : clears) { MDC.remove(clear); } } /** * 获取方法入参 * * @return java.lang.String * @author 龚梁钧 2019-06-28 13:35 */ private String getMethodParam(ProceedingJoinPoint point, LogContext logContext) { Object[] methodArgs = point.getArgs(); Parameter[] parameters = ((MethodSignature) point.getSignature()).getMethod().getParameters(); String requestStr; try { requestStr = logParam(parameters, methodArgs, logContext); } catch (Exception e) { LOG.warn("failed to get parameters: {}", e); requestStr = "failed to get parameters"; } return requestStr; } /** * 拼接入参 * * @param paramsArgsName * @param paramsArgsValue * @param logContext * @author gongliangjun 2020-06-05 3:16 PM * @return java.lang.String */ private String logParam(Parameter[] paramsArgsName, Object[] paramsArgsValue, LogContext logContext) { if (ArrayUtils.isEmpty(paramsArgsName) || ArrayUtils.isEmpty(paramsArgsValue)) { return ""; } String[] excludeInParam = logContext.getExcludeInParam(); String[] includeInParam = logContext.getIncludeInParam(); Map > excludeCollect = null; Map > includeCollect = null; if (ArrayUtils.isNotEmpty(includeInParam)) { includeCollect = Arrays.stream(includeInParam) .filter(a -> a.startsWith("arg") && a.contains(".")) .collect(Collectors.groupingBy(e -> { String substring = e.substring(0, 4); return substring; })); } if (ArrayUtils.isNotEmpty(excludeInParam)) { excludeCollect = Arrays.stream(excludeInParam) .filter(a -> a.startsWith("arg") && a.contains(".")) .collect(Collectors.groupingBy(e -> { String substring = e.substring(0, 4); return substring; })); } StringBuffer buffer = new StringBuffer(); Flag: for (int i = 0; i < paramsArgsValue.length; i++) { //参数名 String name = paramsArgsName[i].getName(); //参数值 Object value = paramsArgsValue[i]; // // 判断当前参数值是否属于excludeInParam,如果属于,则跳过不进行拼接 // ------------------------------------------------------------------------------ for (String exclude : excludeInParam) { if (name.equals(exclude)) { continue Flag; } Class> aClass = value.getClass(); if (exclude.equals(aClass.getSimpleName()) || exclude.equals(aClass.getName())) { continue Flag; } } buffer.append(name + "="); if (value instanceof String) { buffer.append(value + ","); } else { PropertyPreFilters filter = new PropertyPreFilters(); if (null != includeCollect) { List list = includeCollect.get(name); if (null != list) { for (String e : list) { filter.addFilter(e.substring(e.indexOf(".")+1)); } } } if (null != excludeCollect) { List list = excludeCollect.get(name); if (null != list) { for (String e : list) { filter.addFilter().addExcludes(e.substring(e.indexOf(".")+1)); } } } List filters = filter.getFilters(); if (null != filters && filters.size() > 0) { SimplePropertyPreFilter[] simplePropertyPreFilters = new SimplePropertyPreFilter[filters .size()]; for (int i1 = 0; i1 < filters.size(); i1++) { simplePropertyPreFilters[i1] = filters.get(i1); } buffer.append(JSON.toJSONString(value, simplePropertyPreFilters) + ","); }else { buffer.append(JSON.toJSONString(value) + ","); } } } return buffer.toString(); } @Override public void setApplicationContext(ApplicationContext applicationContext) { try { this.logService = applicationContext.getBean(LogService.class); } catch (BeansException e) { LOG.info("logService is null"); } } } - ProfilerAOP,方法执行耗时统计切面
@Aspect @Component @XSlf4j @Order(10) //order最小最先执行 保证ProfilerAOP 后于LogAop执行 public class ProfilerAOP { /** * 打印方法执行耗时统计 * * * @param ltc * @author gongliangjun 2020-06-04 2:28 PM * @return void */ static void printProfiler(LogThreadContext ltc) { Profiler parent = ltc.getFirstProfiler(); //=============================================================================== // 当第一个方法是 //=============================================================================== if (ltc.isFirstMethod() && null != parent) { TimeInstrument timeInstrument = parent.stop(); timeInstrument.print(); ProfilerRegistry profilerRegistry = ProfilerRegistry.getThreadContextInstance(); profilerRegistry.clear(); ltc.removeCurrentProfiler(); ltc.removeCurrentLogContext(); } else { ltc.removeCurrentProfiler(); try { ltc.changeCurrentLogContext(); } catch (Exception e) { log.warn("changeCurrentLogContext error:{}", e); } } } /** * 处理方法执行耗时统计 * * @param logger * @param ltc * @param logContext * @param profilerName * @author gongliangjun 2020-06-04 2:28 PM * @return void */ static void handleProfiler(Logger logger, LogThreadContext ltc, LogContext logContext, String profilerName) { // 在线程上下文的探查器注册表中注册此探查器 ProfilerRegistry profilerRegistry = ProfilerRegistry.getThreadContextInstance(); if (ltc.isFirstProfiler()) { Profiler parent = new Profiler(profilerName); ltc.put(profilerName, parent); parent.registerWith(profilerRegistry); parent.setLogger(logger); parent.start(profilerName); } else { String name = logContext.profilerName(); if (StringUtils.isNotBlank(name)) { profilerName = name; } Profiler parent = ltc.getPrevProfiler(); parent.setLogger(logger); Profiler childProfiler = parent.startNested(profilerName); // 获取注册的分析器 childProfiler.start(profilerName); //=============================================================================== // 将childProfiler放入log上下文中 //=============================================================================== ltc.putProfiler(childProfiler); } } @Pointcut("@annotation(com.enhance.annotations.EnableProfiler)") public void profilerPoint() { } @SneakyThrows @Around("profilerPoint()") public Object handlerProfilerMethod(ProceedingJoinPoint joinPoint) { MethodSignature signature = (MethodSignature) joinPoint.getSignature(); Method method = signature.getMethod(); LogProfiler logProfiler = method.getAnnotation(LogProfiler.class); if (logProfiler != null) { return joinPoint.proceed(); } else { Object target = joinPoint.getTarget(); Class> targetClass = target.getClass(); Logger logger = LoggerFactory.getLogger(targetClass); StringBuilder methodName = new StringBuilder(); if (target instanceof Proxy) { methodName.append(signature.getDeclaringTypeName()) .append("."); } methodName.append(signature.getName()); LogThreadContext ltc = LogThreadContext.getLogThreadContext(); initLogContext(method, ltc); LogContext logContext = ltc.getCurrentLogContext(); String profilerName = methodName.toString(); Object result = null; try { try { handleProfiler(logger, ltc, logContext, profilerName); } catch (Exception e) { log.warn("handlerProfilerMethod error:{}", e); } result = joinPoint.proceed(); } finally { printProfiler(ltc); } return result; } } private void initLogContext(Method method, LogThreadContext ltc) { EnableProfiler enableProfiler = method.getAnnotation(EnableProfiler.class); Log logAnnotation = method.getAnnotation(Log.class); LogContext logContext; if (logAnnotation != null) { //=============================================================================== // 说明该方法已经在LogThreadContext 的logContexts里存过值了,这里只需取出来setProfilerName、setEnableProfiler //=============================================================================== logContext = ltc.peekContext(); logContext.setEnableLog(true); } else { logContext = new LogContext(); ltc.putContext(logContext); } logContext.setEnableProfiler(true); String profilerName = enableProfiler.profilerName(); logContext.setProfilerName(profilerName); ltc.setCurrentLogContext(logContext); } }
- LogUtil工具类
@Slf4j public class LogUtil { private final static String CODE = "code"; private final static String OLD_CODE = "oldCode"; private final static String MSG_FORMAT = "(%s:%s)"; /** * 开始方法耗时统计,需要配合注解@Log使用 * * @return void * @author gongliangjun 2020-06-01 11:26 AM */ public static LogThreadContext startProfiler(String name) { LogThreadContext ltc = LogThreadContext.getLogThreadContext(); if (ltc.isEnableProfiler()) { LogContext logContext = ltc.getCurrentLogContext(); String profilerName = logContext.getProfilerName(); Profiler parent = ltc.get(profilerName); Profiler childProfiler = parent.startNested(name); // 获取注册的分析器 String names = new StringBuilder(profilerName).append("-->").append(name).toString(); childProfiler.start(names); ltc.setInstantProfiler(childProfiler); return ltc; } else { log.warn("method startProfiler(name) 需要配合注解@LogProfiler或者@EnableProfiler使用,并且开启enableProfiler"); } return ltc; } /** * 打印自定义描述和多个code值 需要配合@log或@LogProfiler注解一起使用,MDC才能清空 一般在循环内使用,循环结束要调用clearMDC() * * 例子: * for (OrderEntry orderEntry : orderEntries) { * LogUtil.printCode("orderEntry skuid和数量", "-", orderEntry.getSkuId().toString(),orderEntry.getQuantity().toString()); * log.info("开始处理..."); * log.info("处理中"); * log.info("处理结束"); * LogUtil.clearMDC(); * } * 结果: * INFO [(orderEntry skuid和数量:1-21)]c.enhance.logplugin.demo.service.OrderServiceImpl - 开始处理... * INFO [(orderEntry skuid和数量:1-21)]c.enhance.logplugin.demo.service.OrderServiceImpl - 处理中 * INFO [(orderEntry skuid和数量:1-21)]c.enhance.logplugin.demo.service.OrderServiceImpl - 处理结束 * * @return void * @author gongliangjun 2019-10-30 11:04 AM */ public static void printCode(String describe, String separator, String... values) { LogThreadContext ltc = LogThreadContext.getLogThreadContext(); if (ltc.isEnableLog()) { StringBuilder msg = new StringBuilder("("); if (StringUtils.isNotEmpty(describe)) { msg.append(describe).append(":"); } if (StringUtils.isEmpty(separator)) { separator = " "; } String msgs = Arrays.stream(values).collect(Collectors.joining(separator)); msg = msg.append(msgs).append(")"); Map
callStack = ltc.peekCallStack(); String codeValue = callStack.get(CODE); if (StringUtils.isNotBlank(codeValue)) { callStack.put(OLD_CODE, codeValue); } callStack.put(CODE,msg.toString()); MDC.put(CODE, msg.toString()); } else { log.warn("method printCode() 需要配合注解@Log或@LogProfiler使用"); } } /** * 打印自定义描述和code值 需要配合@log或@LogProfiler注解一起使用,MDC才能清空 一般在循环内使用,循环结束要调用clearMDC() * 例子:orderEntries 有两条数据 * for (OrderEntry orderEntry : orderEntries) { * LogUtil.printCode("处理的skuid", orderEntry.getSkuId().toString()); * log.info("开始处理..."); * log.info("处理中"); * log.info("处理结束"); * LogUtil.clearMDC(); * } * 结果: * INFO [(处理的skuid:1)]c.enhance.logplugin.demo.service.OrderServiceImpl - 开始处理... * INFO [(处理的skuid:1)]c.enhance.logplugin.demo.service.OrderServiceImpl - 处理中 * INFO [(处理的skuid:1)]c.enhance.logplugin.demo.service.OrderServiceImpl - 处理结束 * INFO [(处理的skuid:2)]c.enhance.logplugin.demo.service.OrderServiceImpl - 开始处理... * INFO [(处理的skuid:2)]c.enhance.logplugin.demo.service.OrderServiceImpl - 处理中 * INFO [(处理的skuid:2)]c.enhance.logplugin.demo.service.OrderServiceImpl - 处理结束 * @return void * @author gongliangjun 2019-10-30 11:03 AM */ public static void printCode(String describe, String value) { LogThreadContext ltc = LogThreadContext.getLogThreadContext(); if (ltc.isEnableLog()) { String format = String.format(MSG_FORMAT, describe, value); Map callStack = ltc.peekCallStack(); String codeValue = callStack.get(CODE); if (StringUtils.isNotBlank(codeValue)) { callStack.put(OLD_CODE, codeValue); } callStack.put(CODE,format); MDC.put(CODE, format); } else { log.warn("method printCode() 需要配合注解@Log或@LogProfiler使用"); } } /** * 打印特定code值 需要配合@log注解一起使用,MDC才能清空 一般在循环内使用,循环结束要调用clearMDC() * 例子:orderEntries 有两条数据 * for (OrderEntry orderEntry : orderEntries) { * LogUtil.printCode(orderEntry.getSkuId().toString()); * log.info("开始处理..."); * log.info("处理中"); * log.info("处理结束"); * LogUtil.clearMDC(); * } * 结果: * INFO [1]c.enhance.logplugin.demo.service.OrderServiceImpl - 开始处理... * INFO [1]c.enhance.logplugin.demo.service.OrderServiceImpl - 处理中 * INFO [1]c.enhance.logplugin.demo.service.OrderServiceImpl - 处理结束 * INFO [2]c.enhance.logplugin.demo.service.OrderServiceImpl - 开始处理... * INFO [2]c.enhance.logplugin.demo.service.OrderServiceImpl - 处理中 * INFO [2]c.enhance.logplugin.demo.service.OrderServiceImpl - 处理结束 * @return void * @author gongliangjun 2019-10-30 11:03 AM */ public static void printCode(String value) { LogThreadContext ltc = LogThreadContext.getLogThreadContext(); if (ltc.isEnableLog()) { Map callStack = ltc.peekCallStack(); String codeValue = callStack.get(CODE); if (StringUtils.isNotBlank(codeValue)) { callStack.put(OLD_CODE, codeValue); } callStack.put(CODE,value); MDC.put(CODE, value); } else { log.warn("method printCode() 需要配合注解@Log或@LogProfiler使用"); } } /** * 自定义模板打印日志 需要配合@log注解一起使用,MDC才能清空 一般在循环内使用,循环结束要调用clearMDC() * 例子:orderEntries 有两条数据 * for (OrderEntry orderEntry : orderEntries) { * LogUtil.printCodeByTemplate("skuId[{}] 数量[{}]",orderEntry.getSkuId(),orderEntry.getQuantity()); * log.info("开始处理..."); * log.info("处理中"); * log.info("处理结束"); * LogUtil.clearMDC(); * } * 结果: * INFO [skuId:1 数量:21]c.enhance.logplugin.demo.service.OrderServiceImpl - 开始处理... * INFO [skuId:1 数量:21]c.enhance.logplugin.demo.service.OrderServiceImpl - 处理中 * INFO [skuId:1 数量:21]c.enhance.logplugin.demo.service.OrderServiceImpl - 处理结束 * INFO [skuId:2 数量:11]c.enhance.logplugin.demo.service.OrderServiceImpl - 开始处理... * INFO [skuId:2 数量:11]c.enhance.logplugin.demo.service.OrderServiceImpl - 处理中 * INFO [skuId:2 数量:11]c.enhance.logplugin.demo.service.OrderServiceImpl - 处理结束 * * * @param template 和log使用方式一样,使用{}作为占位符 * @param values 需要替换占位符{}的值 * @return void * @author gongliangjun 2019-10-30 10:47 AM */ public static void printCodeByTemplate(String template, Object... values) { LogThreadContext ltc = LogThreadContext.getLogThreadContext(); if (ltc.isEnableLog()) { String msgFormat = template.replace("{}", "%s"); String format = String.format(msgFormat, values); Map callStack = ltc.peekCallStack(); String value = callStack.get(CODE); if (StringUtils.isNotBlank(value)) { callStack.put(OLD_CODE, value); } callStack.put(CODE,format); MDC.put(CODE, format); } else { log.warn("method printCode() 需要配合注解@Log或@LogProfiler使用"); } } public static void clearMDC() { LogThreadContext ltc = LogThreadContext.getLogThreadContext(); if (ltc.isEnableLog()) { Map callStack = ltc.peekCallStack(); String old = callStack.get(OLD_CODE); if (StringUtils.isNotBlank(old)) { MDC.put(CODE,old); callStack.put(CODE,old); callStack.remove(OLD_CODE); }else { MDC.remove(CODE); } }else { log.warn("method clearMDC() 需要配合注解@Log或@LogProfiler使用"); } } }