在线debug日志

写在开篇

最近工作中涉及实时算法工程框架相关的开发，由于发现实时预测的结果和线下预测结果有偏差，需要向业务提供接口调用过程中的debug日志，供其分析排查问题。

但在茫茫的日志海洋中搂取日志对于业务来说压力比较大，因此我们提出通过对目前预测接口进行包装，提供测试能力，在接口出参返回整个接口调用过程中的debug日志的方案。

这个过程中将利用我们上一篇博客中介绍的log4j2的插件，实现了这个有趣的小功能。如果大家对于log4j2插件功能还不熟悉，可以先阅读我的上一篇文章。

整体思路

首先，我们梳理一下思路，这个功能需要处理predict()业务接口输出日志的位置，所以我们可以通过实现appender插件获取到业务日志，再将每次调用的日志收集保存下来，而对于这个场景，大家会不约而同的想到ThreadLocal，整体的流程如下图所示。

我们再回顾一下这个过程，对于简单的同步业务场景，应该是没有什么问题了，但如果业务接口中存在异步逻辑，该怎么处理呢？

结合上面这张图，我给大家介绍一下我的思路。
1、生成一个uuid作为一次接口调用tracekey，且存入MDC中。
2、每次追加日志时，会先获取MDC中的uuid，将日志放入其对应本地缓存中
3、在业务接口调用结束的时候，根据MDC中的uuid，获取本地缓存中的日志
4、清除MDC中的uuid

需要注意的是，上述处理流程只能处理异步后在方法调用结束之前会阻塞获取异步调用结果的场景，对于异步处理的流程，个人觉得是没有返回debug日志的必要。

需要注意的点

对于测试接口的请求，才需要返回debug日志，否则会影响接口正常调用的性能

需要对接口来源进行打标，而且考虑到子线程的使用，需要通过TransmittableThreadLocal来传递标记，而且对于使用的线程池，需要使用TtlExecutors对线程池包装一下
log4j2的MDC或ThreadContext子线程中取不到父线程的标记，需要在配置文件中加上
1
isThreadContextMapInheritable=true

具体代码实现

Appender

@Log4j2
@Plugin(name = "LogAppender", category = "Core", elementType = "appender", printObject = true)
public class LogAppender extends AbstractAppender {

    /**
     * debug日志bean
     */
    private static final String DEBUG_LOG_SERVICE = "debugLogService";

    public LogAppender(String name, Filter filter, Layout<? extends Serializable> layout, boolean ignoreExceptions) {
        super(name, filter, layout, ignoreExceptions);
    }

    @Override
    public void append(LogEvent logEvent) {
        if (Boolean.FALSE.equals(ThreadLocalLogUtil.getIsLog())) {
            // 不需要记录调用日志
            return;
        }
        if (logEvent == null) {
            return;
        }
        String traceKey = ThreadContext.get(OsConstant.THEAD_CONTEXT_TRACE_KEY);
        if (StringUtils.isBlank(traceKey)) {
            return;
        }
        final byte[] bytes = getLayout().toByteArray(logEvent);
        String log = new String(bytes);
        Object serviceObj = SpringBeanUtils.getBean(DEBUG_LOG_SERVICE);
        if (serviceObj instanceof DebugLogService) {
            DebugLogService debugLogService = (DebugLogService) serviceObj;
            debugLogService.appendDebugLog(traceKey, log);
        }
    }

    // 下面这个方法可以接收配置文件中的参数信息
    @PluginFactory
    public static LogAppender createAppender(
            @PluginAttribute("name") String name,
            @PluginElement("Filter") final Filter filter,
            @PluginElement("Layout") Layout<? extends Serializable> layout,
            @PluginAttribute("ignoreExceptions") boolean ignoreExceptions) {
        if (StringUtils.isBlank(name)) {
            log.error("No name provided for LogAppenderImpl");
            return null;
        }
        if (layout == null) {
            layout = PatternLayout.createDefaultLayout();
        }
        return new LogAppender(name, filter, layout, ignoreExceptions);
    }
}

这里需要注意一个上下文的问题，log4j2在dao层、service层初始化结束之前就已经初始化了，如果采用@Resource这种依赖注入的方式构建bean是行不通的，获取到的只能是null，但是ApplicationContext已经加载，可以通过ApplicationContext手动获取bean。

Aspect

为了降低对业务代码的侵入、以及兼顾代码的可拓展性，对接口调用的打标，接口返回debugLog等过程就通过切面实现了。

@Aspect
@Component
@Log4j2
public class LogAspect {

    @Resource
    private DebugLogService debugLogService;

    @Around("execution(* com.kyrie.predict.service.AService.predict(..))")
    public Object doAround(ProceedingJoinPoint pjp) throws Throwable {
        setIsLogFlag(pjp);

        Object result = null;
        try {
            result = pjp.proceed();
        } catch (Exception e) {
            log.error("LogAspect-doAround-e:", e);
            throw e;
        } finally {
            addDebugLog(result);
        }
        return result;
    }

    /**
     * ThreadLocal设置是否返回debug日志标签
     * @param pjp
     */
    private void setIsLogFlag(ProceedingJoinPoint pjp) {
        Boolean isLogFlag = Boolean.FALSE;

        Object[] args = pjp.getArgs();
        if (args != null && args.length > 0) {
            Object arg = args[0];
            if (arg instanceof OsInputData) {
                OsInputData osInputData = (OsInputData) arg;
                String source = osInputData.getSource();
                if (StringUtils.isNotBlank(source) && OsConstant.SOURCE_SJ_DEBUG.equals(source)) {
                    isLogFlag = Boolean.TRUE;
                }
            }
        }
        log.info("打印debug日志：{}", isLogFlag);
        ThreadLocalLogUtil.setIsLog(isLogFlag);
    }

    /**
     * 返回结果设置debugLog
     * @param result
     */
    private void addDebugLog(Object result) {
        if (!ThreadLocalLogUtil.getIsLog()) {
            return;
        }
        String traceKey = ThreadContext.get(OsConstant.THEAD_CONTEXT_TRACE_KEY);
        if (StringUtils.isNotBlank(traceKey)) {
            if (result == null) {
                result = new OsOutputData();
            }
            if (result instanceof OsOutputData) {
                OsOutputData osOutputData = (OsOutputData) result;
                List<String> debugLog = debugLogService.getDebugLog(traceKey);
                osOutputData.setDebugLogs(debugLog);
            }
            debugLogService.removeDebugLog(traceKey);
        }
        ThreadLocalLogUtil.remove();
    }
}

这里有个地方可能会遗漏，对于这个接口的产生的异常，我们也是需要进行捕获，同时追加到返回debug日志中的。

log4j2.xml

<?xml version="1.0" encoding="UTF-8"?>

<Configuration status="WARN" monitorInterval="3600">
    <Appenders>
		<!-- ... -->
        
        <LogAppender name="logAppender">
            <ThresholdFilter level="info" onMatch="ACCEPT" onMismatch="DENY"/>
            <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS}[%-5level]%m[%C.%M:%L][%X{traceKey}]- %n" />
        </LogAppender>

    </Appenders>

    <Loggers>
        <!-- ... -->

        <!-- 需要返回debug日志 -->
        <logger name="com.kyrie.predict" level="debug" additivity="true">
            <appender-ref ref="logAppender" />
        </logger>

        <!-- 配置日志的根节点 -->
        <root level="info">
            <appender-ref ref="console"/>
            <appender-ref ref="file" />
            <appender-ref ref="error" />
        </root>
    </Loggers>

</Configuration>

这里还有个需要注意的地方是debug日志的logger需要将additivity置为true，不影响根日志的正常输出，关于配置的属性详情，可以参考我的上一篇文章。