转转中间件日志单独打印的实践

一、背景

转转架构部目前有RPC、MQ、监控、分布式任务调度平台等数十个中间件，每个中间件都会通过SLF4J日志门面来打印一些日志，以便排查问题。这种方式存在以下几个问题：

• 中间件日志与业务日志混合在一起，干扰业务排查问题，有的业务甚至直接把中间件日志给屏蔽掉了；
• 业务日志会通过Flume收集到Hadoop集群，这样中间件日志也会随同被收集上去，但没有实际的业务价值，徒增存储成本。

基于此，我们需要把中间件的一些不太重要的日志（如状态、心跳、MQ生产&消费等）单独打印，仅供架构组员排查问题使用，既不干扰业务，又不占用大数据空间。

二、解决方案

主要思路如下：

1. 框架在LoggerContext中添加单独日志相关的配置，封装在架构组公共日志组件zzarch-log-commonjar包里；
2. 框架对外暴露获取日志对象logger的接口；
3. 中间件通过该接口获取日志对象logger，并按之前的用法打印日志。

2.1 在LoggerContext中添加单独日志相关的配置

类似于log4j2.xml的方式，我们也可以通过显式编码的方式进行日志配置（详见：Programmatic Configuration^[1]）。核心类ArchLogConfigure的代码如下（已简化）：

public class ArchLogConfigure {
    private static final String SERVICE_NAME = ApplicationUtil.getApplicationName(); // 当前服务名称，如:zzproduct

    public static final String FILE_NAME_FORMAT = "/opt/log/arch/%s/arch.log";// 形如：/opt/log/arch/zzproduct/info.log
    public static final String FILE_PATTERN_FORMAT = "/opt/log/arch/%s/arch.log.%%d{yyyy-MM-dd-HH}";// 形如：/opt/log/arch/zzproduct/arch.log.2020-12-20
    public static final String LOG_PATTERN = "%d{HH:mm:ss.SSS} %X{TRACE_ID}-%X{SPAN_ID}-%X{SAMPLED} %t %p %C{1.}:%L - %m%n";
    public static final String ARCH_APPENDER_NAME = "ARCH_APPENDER";
    public static final String ARCH_LOGGER_NAME = "LOGGER4ARCH";
    private static volatile boolean inited = false;

    /**
     * 初始化
     */
    public static void init() {
        if (inited) { // DCL检查
            return;
        }
        synchronized (ArchLogConfigure.class) {
            if (inited) {
                return;
            }

            init0();
        }
    }

    private static void init0() {
        try {
            final LoggerContext loggerContext = (LoggerContext) LogManager.getContext(false);
            final Configuration configuration = loggerContext.getConfiguration();

            // 1.创建arch appender
            Appender archAppender = initRollingRandomAccessFileAppender(loggerContext);
            AppenderRef archAppenderRef = AppenderRef.createAppenderRef(ARCH_APPENDER_NAME, null, null);

            // 2.创建logger
            AppenderRef[] refs = new AppenderRef[] { archAppenderRef };
            LoggerConfig loggerConfig = AsyncLoggerConfig.createLogger("false", "INFO", ARCH_LOGGER_NAME, "true", refs,
                    null, configuration, null);
            loggerConfig.addAppender(archAppender, null, null);

            // 3.添加logger并更新
            configuration.addLogger(ARCH_LOGGER_NAME, loggerConfig);
            loggerContext.updateLoggers();

            inited = true;
        } catch (Exception e) {
            e.printStackTrace();
        }
    }

    /**
     * 构建RollingRandomAccessFileAppender
     *
     * @return
     */
    private static Appender initRollingRandomAccessFileAppender(LoggerContext loggerContext) {
        TriggeringPolicy policy = TimeBasedTriggeringPolicy.createPolicy("1", null);
        PatternLayout layout = PatternLayout.newBuilder().withPattern(LOG_PATTERN).build();
        String fileName = String.format(FILE_NAME_FORMAT, SERVICE_NAME); // 如：/opt/log/arch/zzproduct/arch.log
        String fileNamePattern = String.format(FILE_PATTERN_FORMAT, SERVICE_NAME); // 如：/opt/log/arch/zzproduct/arch.log.2020-12-20

        // 1.构建appender
        RollingRandomAccessFileAppender res = RollingRandomAccessFileAppender.createAppender(fileName, fileNamePattern,
                null, ARCH_APPENDER_NAME, "true", null, policy, null, layout, null, null, null, null,
                loggerContext.getConfiguration());

        // 2.启动
        res.start();
        loggerContext.getConfiguration().addAppender(res);

        return res;
    }
}

该类的作用相当于在log4j2.xml中添加如下配置：

<RollingRandomAccessFile name="ARCH_APPENDER" fileName="/opt/log/arch/${SERVICE_NAME}/arch.log"
                         filePattern="/opt/log/arch/${SERVICE_NAME}/arch.log.%%d{yyyy-MM-dd-HH}">

    <PatternLayout pattern="%d{HH:mm:ss.SSS} %X{TRACE_ID}-%X{SPAN_ID}-%X{SAMPLED} %t %p %C{1.}:%L - %m%n" />

    <Policies>
        <TimeBasedTriggeringPolicy interval="1" modulate="true" />
    </Policies>
</RollingRandomAccessFile>

<AsyncLogger name="LOGGER4ARCH" level="INFO" includeLocation="true" additivity="false">
    <AppenderRef ref="ARCH_APPENDER" />
</AsyncLogger>

2.2 框架对外暴露获取日志对象logger的接口

这个就比较简单了，我们通过LoggerFactory获取LOGGER4ARCH对应的日志对象就可以了。核心类ArchLoggerFactory的代码如下：

public class ArchLoggerFactory {
    static {
        ArchLogConfigure.init();
    }

    public static Logger getArchLogger() {
        return LoggerFactory.getLogger("LOGGER4ARCH");
    }
}

经过以上两步，我们将其封装在架构组公共日志组件zzarch-log-commonjar包里，中间件就可以直接使用了。

三、如何使用

中间件只须通过ArchLoggerFactory.getArchLogger()获取logger对象，并按之前的方式使用即可。示例如下：

public class ArchLoggerFactoryTest {
    private final Logger archLogger = ArchLoggerFactory.getArchLogger();
    private final Logger logger = LoggerFactory.getLogger(this.getClass());

    @Test
    public void test() throws InterruptedException {
        for (int i = 0; i < 1000; i++) {
            archLogger.debug("name={}", "adu");
            archLogger.info("name={}", "adu");
            archLogger.warn("name={}", "adu");
            archLogger.error("name={}", "adu");

            logger.debug("name={}", "adu");
            logger.info("name={}", "adu");
            logger.warn("name={}", "adu");
            logger.error("name={}", "adu");

            Thread.sleep(1000);
        }
    }
}

四、总结

本文我们通过显式编码的方式在log4j2的LoggerContext中添加单独日志相关的配置，从而实现中间件日志单独打印的目的，而且对业务无感。主要思路如下：

1. 框架在LoggerContext中添加单独日志相关的配置，封装在架构组公共日志组件zzarch-log-commonjar包里；
2. 框架对外暴露获取日志对象logger的接口；
3. 中间件通过该接口获取日志对象logger，并按之前的用法打印日志。

解决方案比较简单，但收益巨大：

1. 避免干扰业务排查问题；
2. 减少大数据存储成本。

注：这里只针对中间件的一些不太重要的日志（如状态、心跳、MQ生产&消费等）单独打印，一些重要的日志建议还是跟业务日志打在一起，方便RD排查问题。

关于作者

杜云杰，架构师，转转架构部负责人，转转技术委员会成员。负责服务治理、MQ、云平台、APM、IM、分布式调用链追踪、监控系统、配置中心、分布式任务调度平台、分布式ID生成器、分布式锁等基础组件。微信号：waterystone，欢迎建设性交流。

道阻且长，拥抱变化；而困而知，且勉且行。

参考资料