天呐，一个简单的统一日志格式我踩了多少坑

默克微学
1,833 阅读8分钟

天呐，一个简单的统一日志格式我踩了多少坑

这几天接到一个需求，是要求将log4j的配置文件统一封装到jar文件,同时这个jar依赖skywalking的相关包,从大的层面上来说，为了统一整个公司的日志输出格式，便利的接入skywalking和elk做准备。

我是怎么考虑的

  1. 全局格式统一，也就是说需要约束好 log4j2.xml 的文件位置

由于我们现有的日志文件位置是写死在 log4j2.xml的 ，现在并不想调整该文件的内容，但是每个应用的日志应该在单独的文件夹下，所以需要在xml配置文件中配置一个变量用来设置应用名称。

  1. 不同的环境对代码中日志的输出级别不同

例如在开发环境中，我们需要对 sql 日志进行输出，但是在生产环境中，由于性能和日志量的问题，并不会输出 sql 的日志信息。

  1. 配置要简单

配置是需要有学习成本的，最好能够不需要单独的配置就能够完成日志的统一

  1. 兼容

读取配置文件的方式要兼容，例如项目中可能存在配置文件为 yml 、 properties ,而且命名方式可能千奇百怪，应该对各个应用做最大程度上的兼容

  1. 文档

提供一定程度的文档，指导能够个性化配置一些内容

研究相关技术

  • log4j2
  • SpringBoot Logging
  • SpringBoot 生命周期

整个开发的主要做法

如何读取配置文件内容

熟悉 Spring的朋友应该知道，Spring 会将配置文件加载到Environment的实现类中(具体哪个实现类由环境而定，StandardServletEnvironment、StandardReactiveWebEnvironment、StandardEnvironment),所以想要读取配置文件中的值，必然需要在Environment加载之后去读取

SpringBoot 加载Environment的时机

在SpringBoot的加载过程中，Environment的加载过程还是比较早的,通过源码可以了解到,SprinBoot在最开始的时候就是去加载Environment

public ConfigurableApplicationContext run(String... args) {
		StopWatch stopWatch = new StopWatch();
		stopWatch.start();
		ConfigurableApplicationContext context = null;
		Collection<SpringBootExceptionReporter> exceptionReporters = new ArrayList<>();
		configureHeadlessProperty();
		SpringApplicationRunListeners listeners = getRunListeners(args);
		listeners.starting();
		try {
			ApplicationArguments applicationArguments = new DefaultApplicationArguments(args);
      
      // 准备 Environment环境
			ConfigurableEnvironment environment = prepareEnvironment(listeners, applicationArguments);
			configureIgnoreBeanInfo(environment);
			Banner printedBanner = printBanner(environment);
			context = createApplicationContext();
			exceptionReporters = getSpringFactoriesInstances(SpringBootExceptionReporter.class,
					new Class[] { ConfigurableApplicationContext.class }, context);
			prepareContext(context, environment, listeners, applicationArguments, printedBanner);
			refreshContext(context);
			afterRefresh(context, applicationArguments);
			stopWatch.stop();
			if (this.logStartupInfo) {
				new StartupInfoLogger(this.mainApplicationClass).logStarted(getApplicationLog(), stopWatch);
			}
			listeners.started(context);
			callRunners(context, applicationArguments);
		}
		catch (Throwable ex) {
			handleRunFailure(context, ex, exceptionReporters, listeners);
			throw new IllegalStateException(ex);
		}

		try {
			listeners.running(context);
		}
		catch (Throwable ex) {
			handleRunFailure(context, ex, exceptionReporters, null);
			throw new IllegalStateException(ex);
		}
		return context;
	}
  • 从13行代码就可以看到，SpringBoot在初始化完ApplicationArguments 参数之后就会取准备Environment环境（更深入的代码，请自己查阅） 。

hold住 Environment对象

如何持有Environment对象

阅读过log4j-extension-config工程的同学，可以看到，这里使用可一个十分常规的做法，SpringEnvironmentHolder对象持有Environment

public class SpringEnvironmentHolder {

    public static Environment environment = null;
    public static ApplicationContext applicationContext = null;

    public void setEnvironment(Environment environment) {
        SpringEnvironmentHolder.environment = environment;
    }

    public void setApplicationContext(ApplicationContext applicationContext) {
        SpringEnvironmentHolder.applicationContext = applicationContext;
    }


    public static Environment getEnvironment() {
        return environment;
    }

    public static ApplicationContext getApplicationContext() {
        return applicationContext;
    }
}

什么时候将Environment 设置到SpringEnvironmentHolder 时机才不算晚

这个话题我们先不去讨论，因为这里牵扯到很多地方都可以获取这个对象，例如EnvironmentAware、ApplicationContextAware、等等，但是重点在于什么时候不算晚，想要了解这个过程，我们需要了解SpringBoot在什么时候对log4j2出手了

如何在Log4j的配置文件里面设置动态变量

这里就需要用到 Log4j 插件机制，可以使用MDC或者 System.Properties ，为了看起来更加高级，我使用了插件机制去实现.

@Plugin(name = "ppl", category = StrLookup.CATEGORY)
public class SpringEnvironmentLookup extends AbstractLookup {

    @Override
    public String lookup(LogEvent event, String key) {
        if (SpringEnvironmentHolder.getEnvironment() != null) {
            return SpringEnvironmentHolder.getEnvironment().getProperty(key);
        }
        return "default";
    }
}

配置文件

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="INFO" monitorInterval="60">

  <Properties>
    <property name="APP_NAME" value="${ppl:ppx.name}"/>
    <property name="localhost_path">/date/project/${APP_NAME}/logs</property>
  </Properties>

  <!--先定义所有的appender-->

  <Appenders>

    <Console name="appender_console" target="SYSTEM_OUT">
      <PatternLayout pattern="${COMMON_LOG_PATTERN}"/>
    </Console>

    <!-- 每次大小超过size，则这size大小的日志会自动存入按年份-月份建立的文件夹下面并进行压缩，作为存档-->
    <RollingFile name="appender_info" fileName="${localhost_path}/info.log"
      filePattern="${localhost_path}/?{date:yyyy-MM}/info-%d{yyyy-MM-dd}-%i.log">
      <!--控制台只输出level及以上级别的信息（onMatch），其他的直接拒绝（onMismatch）-->
      <ThresholdFilter level="info" onMatch="ACCEPT" onMismatch="DENY"/>
      <PatternLayout pattern="${COMMON_LOG_PATTERN}"/>
      <Policies>
        <TimeBasedTriggeringPolicy/>
        <SizeBasedTriggeringPolicy size="100MB"/>
      </Policies>
    </RollingFile>

    <!-- 每次大小超过size，则这size大小的日志会自动存入按年份-月份建立的文件夹下面并进行压缩，作为存档-->
    <RollingFile name="appender_warn" fileName="${localhost_path}/warn.log"
      filePattern="${localhost_path}/?{date:yyyy-MM}/warn-%d{yyyy-MM-dd}-%i.log">
      <!--控制台只输出level及以上级别的信息（onMatch），其他的直接拒绝（onMismatch）-->
      <ThresholdFilter level="warn" onMatch="ACCEPT" onMismatch="DENY"/>
      <PatternLayout pattern="${COMMON_LOG_PATTERN}"/>
      <Policies>
        <TimeBasedTriggeringPolicy/>
        <SizeBasedTriggeringPolicy size="100MB"/>
      </Policies>
    </RollingFile>


    <!-- 每次大小超过size，则这size大小的日志会自动存入按年份-月份建立的文件夹下面并进行压缩，作为存档-->
    <RollingFile name="appender_error" fileName="${localhost_path}/error.log"
      filePattern="${localhost_path}/?{date:yyyy-MM}/error-%d{yyyy-MM-dd}-%i.log">
      <!--控制台只输出level及以上级别的信息（onMatch），其他的直接拒绝（onMismatch）-->
      <ThresholdFilter level="error" onMatch="ACCEPT" onMismatch="DENY"/>
      <PatternLayout pattern="${COMMON_LOG_PATTERN}"/>
      <Policies>
        <TimeBasedTriggeringPolicy/>
        <SizeBasedTriggeringPolicy size="100MB"/>
      </Policies>
    </RollingFile>

  </Appenders>


  <Loggers>
    <!--过滤掉spring和mybatis的一些无用的DEBUG信息-->
    <Logger name="RocketmqClient" level="WARN"/>
    <Root level="INFO">
      <AppenderRef ref="appender_console"/>
      <AppenderRef ref="appender_info"/>
      <AppenderRef ref="appender_warn"/>
      <AppenderRef ref="appender_error"/>
    </Root>


  </Loggers>
</Configuration>
  • ${ppl:ppx.name} 就是我们需要动态设置的值

其他方式配置值：

ytjMJO
ytjMJO

SpringBoot加载 log4j 正常流程

SpringBoot加载Log的入口位置

可以看到org.springframework.boot.context.logging 在这个包下有两个类，分别是ClasspathLoggingApplicationListener和LoggingApplicationListener ,其中主要部分是 LoggingApplicationListener 这个类会去再次触发 Log4j上下文的初始化任务。 这里谈到了再次这个词，原因是因为log4j和slf4j的机制，由于在SpringApplicaiton 的类中定了一个静态属性,private static final Log logger = LogFactory.getLog(SpringApplication.class); 这个是SpringBoot封装了slfj4和log4j的定义方式，最终底层会去加载一次Log4j的上下文，而LoggingApplicationListener 这个类的功能是再次加载一个log4j的上下文，根据SpringBoot的logging配置，比如说：logging.config等等。

SpringBoot加载ApplicationListener的时机

通过分析SpringBoot的启动过程,在org.springframework.boot.SpringApplication#prepareEnvironment这个过程之前就开始发出ApplicationStartingEvent 事件,在处理prepareEnvironment 中，SpringBoot就开始了ApplicationListener的 ApplicationEnvironmentPreparedEvent处理。 所以在ApplicationEnvironmentPreparedEvent事件中已经能够获取到 Environment的配置信息了.

log4j-extension-config 获取Environment的时机

log4j-extension-config 这个项目获取Environment 的时机在于EnvironmentPostProcessor 这个事件是 ConfigFileApplicationListener 执行完成比之后触发执行的. nBEp8k 从上图中可以看出，ConfigFileApplicationListener 是比日志处理LoggingApplicationListener 早执行的，所以避免了在LoggingApplicationListener执行时，还获取不到Enviornment的情况

坑，log4j2.xml 竟然直接加载

这个是我花费了大量的时间同时也是推动我去熟悉一整个流程的关键点。

最早的时候想法是，既然在SpringBoot定义的的日志文件中会去默认加载log4j2.xml的文件，为了省一部配置(logging.config)，我设置默认的配置文件为log4j2.xml,导致了第一次log4j2 上下文加载的时候读取项目名称的时候读取不到。

@Plugin(name = "ppl", category = StrLookup.CATEGORY)
public class SpringEnvironmentLookup extends AbstractLookup {

    @Override
    public String lookup(LogEvent event, String key) {
        if (SpringEnvironmentHolder.getEnvironment() != null) {
            return SpringEnvironmentHolder.getEnvironment().getProperty(key);
        }
        return "default";
    }
}

输出的文件格式为/date/project/default/logs/info.log. 但是其实 default 这个值应该是我设置的应用名称，default 只是我写的一个兜底的方案。

原因在于Log4j2在SpringBoot生命周期启动之前就开始加载了这个默认的配置文件，所以导致的。这里我觉得是SpringBoot设计上的问题，不清楚log4j的人会误认为这个配置文件是在SpringBoot启动配置日志流程的时候初始化的，其实并不是。

下面我们会简单分析一下log4j2 自己本省的初始化流程: LoggerContext 文件在启动过程中会先去遍历一些列的配置文件（包含了log4j2.xml),如果遍历到，则会进行读取并且开始根据配置文件里面的内容进行设置、创建。所以这里的配置了log4j.xml 文件之后，其实已经比SpringBoot上下文创建的logContext上下文早了，所以导致了，在log4j2.xml中配置了从Spring Environment中读取的动态属性不会被设置值。由于这里的流程篇幅太长，我这边简单的罗列一下大概的流程. SpringApplicaiton org.springframework.boot.SpringApplication#logger >>>>> org.apache.commons.logging.LogFactory#getLog(java.lang.Class<?>) >>>>> org.apache.commons.logging.LogAdapter#createLog >>>>> org.apache.commons.logging.LogAdapter.Log4jAdapter#createLog >>>>> org.apache.commons.logging.LogAdapter.Log4jLog#Log4jLog >>>>> org.apache.logging.log4j.LogManager#getContext(java.lang.ClassLoader, boolean) >>>>> org.apache.logging.log4j.LogManager#factory#static >>>>> org.apache.logging.log4j.core.impl.Log4jContextFactory#getContext(java.lang.String, java.lang.ClassLoader, java.lang.Object, boolean) >>>> org.apache.logging.log4j.core.LoggerContext#start() >>>>> org.apache.logging.log4j.core.LoggerContext#reconfigure()【核心】 >>>>> org.apache.logging.log4j.core.config.ConfigurationFactory.Factory#getConfiguration(org.apache.logging.log4j.core.LoggerContext, boolean, java.lang.String) >>>>> 加载了 log4j2.xml >>>>> org.apache.logging.log4j.core.LoggerContext#setConfiguration >>>>>> org.apache.logging.log4j.core.config.AbstractConfiguration#createPluginObject 创建了xml 配置的差距 >>>>>> org.apache.logging.log4j.core.appender.RollingFileAppender.Builder#build 创建文件

核心的地方: org.apache.logging.log4j.core.LoggerContext#reconfigure(java.net.URI)

其实 SpringBoot 也是触发了这过程，只不过SpringBoot 做了一下配置化的扩展。

总结

在开发这个简单的统一日志格式过程中，碰到了许多问题，原本以为是一个非常简单的过程，其实在后面看来，需要设计到的知识点还是十分的多。其中包含了最复杂的一个log4j加载流程，SpringBoot 配置 Log4j的流程 ，SpringBoot 启动的生命周期的一个流程，终结下来，自己一共花了2，3天的时机研究了这个过程。结果还是比较满意的，当然其中对 日志文件名称不能变成应用名称这个过程也做过妥协(第一个版本完全抛弃了SpringBoot的流程，手动实现了一个读取yml的功能). 所幸，自己最后坚持了下来。

最后

关注我，提供PDF格式下载 扫码_搜索联合传播样式-标准色版

avatar
文章
阅读
粉丝