支持SpEL表達式的自定義日志註解@SysLog介紹

Posted on by

序言

之前封裝過一個日志註解，打印方法執行信息，功能較為單一不夠靈活，近來興趣來瞭，想重構下，使其支持表達式語法，以應對靈活的日志打印需求。

該註解是方法層面的日志打印，如需更細的粒度，還請手擼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: [email protected] method: this is test method(), exception: [用戶模塊] – 用戶名或密碼錯誤, costTime: 261ms

壓測下來性能損耗較低（可忽略不計）

以上為個人經驗，希望能給大傢一個參考，也希望大傢多多支持WalkonNet。

推薦閱讀：