支持SpEL表达式的自定义日志注解@SysLog介绍
目录
- 序言
- 预期
- 思路
- 过程
- 结果
序言
之前封装过一个日志注解,打印方法执行信息,功能较为单一不够灵活,近来兴趣来了,想重构下,使其支持表达式语法,以应对灵活的日志打印需求。
该注解是方法层面的日志打印,如需更细的粒度,还请手撸log.xxx()。
预期
通过自定义注解,灵活的语法表达式,拦截自定义注解下的方法并打印日志
日志要支持以下内容:
- 方法执行时间
- 利用已知信息(入参、配置、方法),书写灵活的日志SpEL表达式
- 打印方法返回结果
- 按照指定日志类型打印日志
思路
定义自定义注解
拦截自定义注解方法完成以下动作
- a. 计算方法执行时间
- b. 解析特定类型的表达式(这里不仅限于SpEL表达式)
- c. 获取返回结果
- d. 按照日志类型进行打印
特定类型表达式方案
- a. 属性解析表达式(如:mybatis对属性的解析,xxx${yyy.aaa}zzz或xxx#{yyy.bbb}zzz书写方式 )
- b. SpEL表达式(如:${xxx}、#{‘xxx’+#yyy.ppp+aaa.mmm()})
问题:选属性解析表达式、还是SpEL表达式
属性解析表达式:
- a. 优点:直观、配置简单
- b. 缺点:需要自行处理属性为待解析对象(容易翻车)
SpEL表达式:
- a. 优点:解析强大,性能优良
- b. 缺点:配置复杂不直观
过程
定义自定义注解@SysLog
@Target(ElementType.METHOD) @Retention(RetentionPolicy.RUNTIME) @Documented public @interface SysLog { /** * 日志描述 * * @return 返回日志描述信息 */ String value(); /** * 日志等级(info、debug、trace、warn、error) * * @return 返回日志等级 */ String level() default "info"; /** * 打印方法返回结果 * * @return 返回打印方法返回结果 */ boolean printResult() default false; }
该类包含以下信息:
- 日志信息(支持动态表达式)
- 日志级别(info、debug、trace、warn、error)
- 是否打印方法返回的结果
走过的弯路1(PropertyParser)
采用MyBatis对XML解析的方式进行解析,需要把拦截到的入参Bean内的属性转换为Properties的方式进行parse,遇到复杂对象就容易出错,属性无法进行动态解析,具体就不详细描述了,感兴趣的可以看下这个类org.apache.ibatis.parsing.PropertyParser
走过的弯路2(ParserContext)
比使用MyBatis更加友好一丢丢,使用Spring自带的ParserContext设定解析规则,结合解析类ExpressionParser进行解析,也没有解决上面遇到的问题,不用引用其它jar包或手撸解析规则,具体就不详细描述了,感兴趣的可以看下这个类
org.springframework.expression.ParserContext
最后的定型方案:
切面拦截方法前后的入参、出参、异常,
SpEL表达式解析,根据表达式去动态解析,语法比预想中强大;
为了确认性能损耗,最后还做了个性能压测
自定义注解切面类SysLogAspect(最终选型SpEL表达式方式)
/** * SysLog方法拦截打印日志类 * * @author lipengfei * @version 1.0 * @since 2019/3/29 10:49 AM */ @Aspect public class SysLogAspect { private static final Logger log = LoggerFactory.getLogger(SysLogAspect.class); private static final DefaultParameterNameDiscoverer DEFAULT_PARAMETER_NAME_DISCOVERER = new DefaultParameterNameDiscoverer(); private static final ExpressionParser EXPRESSION_PARSER = new SpelExpressionParser(); private static final TemplateParserContext TEMPLATE_PARSER_CONTEXT = new TemplateParserContext(); private static final ThreadLocal<StandardEvaluationContext> StandardEvaluationContextThreadLocal = new ThreadLocal<>(); /** * 开始时间 */ private static final ThreadLocal<Long> START_TIME = new ThreadLocal<>(); @Pointcut("@annotation(net.zongfei.core.log.SysLog)") public void sysLogPointCut() { } /** * 处理完请求后执行 * * @param joinPoint 切点 */ @SuppressWarnings("unused") @Before("sysLogPointCut()") public void doBeforeReturning(JoinPoint joinPoint) { // 设置请求开始时间 START_TIME.set(System.currentTimeMillis()); } /** * 处理完请求后执行 * * @param joinPoint 切点 */ @AfterReturning( pointcut = "sysLogPointCut()", returning = "result" ) public void doAfterReturning(JoinPoint joinPoint, Object result) { printLog(joinPoint, result, null); } /** * 拦截异常操作 * * @param joinPoint 切点 * @param e 异常 */ @AfterThrowing( pointcut = "sysLogPointCut()", throwing = "e" ) public void doAfterThrowing(JoinPoint joinPoint, Exception e) { printLog(joinPoint, null, e); } /** * 打印日志 * * @param point 切点 * @param result 返回结果 * @param e 异常 */ protected void printLog(JoinPoint point, Object result, Exception e) { MethodSignature signature = (MethodSignature) point.getSignature(); String className = ClassUtils.getUserClass(point.getTarget()).getName(); String methodName = point.getSignature().getName(); Class<?>[] parameterTypes = signature.getMethod().getParameterTypes(); Method method; try { method = point.getTarget().getClass().getMethod(methodName, parameterTypes); } catch (NoSuchMethodException ex) { ex.printStackTrace(); return; } // 获取注解相关信息 SysLog sysLog = method.getAnnotation(SysLog.class); String logExpression = sysLog.value(); String logLevel = sysLog.level(); boolean printResult = sysLog.printResult(); // 解析日志中的表达式 Object[] args = point.getArgs(); String[] parameterNames = DEFAULT_PARAMETER_NAME_DISCOVERER.getParameterNames(method); Map<String, Object> params = new HashMap<>(); if (parameterNames != null) { for (int i = 0; i < parameterNames.length; i++) { params.put(parameterNames[i], args[i]); } } // 解析表达式 String logInfo = parseExpression(logExpression, params); Long costTime = null; // 请求开始时间 Long startTime = START_TIME.get(); if (startTime != null) { // 请求耗时 costTime = System.currentTimeMillis() - startTime; // 清空开始时间 START_TIME.remove(); } // 如果发生异常,强制打印错误级别日志 if(e != null) { log.error("{}#{}(): {}, exception: {}, costTime: {}ms", className, methodName, logInfo, e.getMessage(), costTime); return; } // 以下为打印对应级别的日志 if("info".equalsIgnoreCase(logLevel)){ if (printResult) { log.info("{}#{}(): {}, result: {}, costTime: {}ms", className, methodName, logInfo, result, costTime); } else { log.info("{}#{}(): {}, costTime: {}ms", className, methodName, logInfo, costTime); } } else if("debug".equalsIgnoreCase(logLevel)){ if (printResult) { log.debug("{}#{}(): {}, result: {}, costTime: {}ms", className, methodName, logInfo, result, costTime); } else { log.debug("{}#{}(): {}, costTime: {}ms", className, methodName, logInfo, costTime); } } else if("trace".equalsIgnoreCase(logLevel)){ if (printResult) { log.trace("{}#{}(): {}, result: {}, costTime: {}ms", className, methodName, logInfo, result, costTime); } else { log.trace("{}#{}(): {}, costTime: {}ms", className, methodName, logInfo, costTime); } } else if("warn".equalsIgnoreCase(logLevel)){ if (printResult) { log.warn("{}#{}(): {}, result: {}, costTime: {}ms", className, methodName, logInfo, result, costTime); } else { log.warn("{}#{}(): {}, costTime: {}ms", className, methodName, logInfo, costTime); } } else if("error".equalsIgnoreCase(logLevel)){ if (printResult) { log.error("{}#{}(): {}, result: {}, costTime: {}ms", className, methodName, logInfo, result, costTime); } else { log.error("{}#{}(): {}, costTime: {}ms", className, methodName, logInfo, costTime); } } } private String parseExpression(String template, Map<String, Object> params) { // 将ioc容器设置到上下文中 ApplicationContext applicationContext = SpringContextUtil.getContext(); // 线程初始化StandardEvaluationContext StandardEvaluationContext standardEvaluationContext = StandardEvaluationContextThreadLocal.get(); if(standardEvaluationContext == null){ standardEvaluationContext = new StandardEvaluationContext(applicationContext); standardEvaluationContext.addPropertyAccessor(new BeanFactoryAccessor()); StandardEvaluationContextThreadLocal.set(standardEvaluationContext); } // 将自定义参数添加到上下文 standardEvaluationContext.setVariables(params); // 解析表达式 Expression expression = EXPRESSION_PARSER.parseExpression(template, TEMPLATE_PARSER_CONTEXT); return expression.getValue(standardEvaluationContext, String.class); } }
该类按照上面思路中的逻辑进行开发,没有特别复杂的逻辑
为了提高性能和线程安全,对一些类加了static和ThreadLocal
结果
使用方式:
@SysLog(value = “#{‘用户登录'}”) @SysLog(value = “#{'用户登录: method: ' + #loginRequest.username}”, printResult = true) @SysLog(value = “#{'用户登录: method: ' + #loginRequest.username + authBizService.test()}”, printResult = true) …
更多书写方式参考SpEL表达式即可
/** * 用户登录接口 * * @param loginRequest 用户登录输入参数类 * @return 返回用户登录结果输出类 */ @ApiOperation("用户登录接口") @PostMapping(value = "/login") @SysLog(value = "#{'用户登录: username: ' + #loginRequest.username + authBizService.test()}", level = "debug", printResult = true) @Access(type = AccessType.LOGIN, description = "用户登录") public LoginResponse login( @ApiParam(value = "用户登录参数") @RequestBody @Valid LoginRequest loginRequest ) { // 业务代码 }
结果打印:
2021-09-01 22:04:05.713 ERROR 98511 CRM [2cab21fdd2469b2e--2cab21fdd2469b2e] [nio-8000-exec-2] n.z.m.a.SysLogAspect : net.zongfei.crm.api.AuthController#login(): 用户登录: username: lipengfei90@live.cn method: this is test method(), exception: [用户模块] - 用户名或密码错误, costTime: 261ms
压测下来性能损耗较低(可忽略不计)
以上为个人经验,希望能给大家一个参考,也希望大家多多支持我们。