God, how many holes have I stepped on in a simple unified log format

In recent days, we have received a requirement that the configuration file of log4j should be packaged into a jar file. At the same time, the jar relies on skywalking related packages. On a large level, in order to unify the log output format of the whole company, it is convenient to access skywalking and elk.

How do I think about it

  1. The global format is unified, that is to say, the file location of log4j2.xml needs to be constrained

Because the location of our existing log file is written in log4j2.xml, now we do not want to adjust the content of the file, but the log of each application should be in a separate folder, so we need to configure a variable in the XML configuration file to set the application name.

  1. Different environments have different output levels for logs in the code

For example, in the development environment, we need to output sql logs, but in the production environment, due to performance and log volume problems, we will not output sql log information.

  1. Simple configuration

Configuration needs learning cost. It's better to complete log unification without separate configuration

  1. compatible

The way to read configuration files should be compatible. For example, there may be configuration files of yml and properties in the project, and the naming method may be strange. You should make maximum compatibility for each application

  1. File

Provide a certain degree of documentation and guide to be able to personalize some content

Research related technologies

  • log4j2
  • SpringBoot Logging
  • SpringBoot life cycle

Main practices of the whole development

How to read configuration file content

Friends who are familiar with Spring should know that Spring will load the configuration file into the implementation class of Environment (which implementation class depends on the Environment, StandardServletEnvironment, StandardReactiveWebEnvironment, StandardEnvironment). Therefore, if you want to read the value in the configuration file, you must read it after the Environment is loaded

Spring boot time to load Environment

During the loading process of SpringBoot, the loading process of Environment is still relatively early. From the source code, it can be seen that sprint boot is to load Environment at the beginning

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);
      
      // Preparing the Environment 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;
	}
  • As you can see from the 13 lines of code, after initializing the ApplicationArguments parameter, SpringBoot will take the preparation Environment environment (for more in-depth code, please refer to it).

hold Environment object

How to hold an Environment object

After reading the log4j extension config project, you can see that a very common practice is to use the spring environmentholder object to hold the 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;
    }
}

It's not too late to set the Environment to spring Environment holder

We won't discuss this topic first, because there are many places involved here that can get this object, such as EnvironmentAware, ApplicationContextAware, etc., but the point is when it's not too late. To understand this process, we need to know when spring boot has sold log4j2

How to set dynamic variables in Log4j configuration file

Here we need to use the Log4j plug-in mechanism. You can use MDC or System.Properties. To look more advanced, I use the plug-in mechanism to implement

@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";
    }
}

configuration file

<?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>

  <!--Define all first appender-->

  <Appenders>

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

    <!-- Each time the size exceeds size,Then this size Size logs are automatically saved by year-The folder created in the month is compressed as an archive-->
    <RollingFile name="appender_info" fileName="${localhost_path}/info.log"
      filePattern="${localhost_path}/$${date:yyyy-MM}/info-%d{yyyy-MM-dd}-%i.log">
      <!--Console output only level And above( onMatch),Other direct rejection( onMismatch)-->
      <ThresholdFilter level="info" onMatch="ACCEPT" onMismatch="DENY"/>
      <PatternLayout pattern="${COMMON_LOG_PATTERN}"/>
      <Policies>
        <TimeBasedTriggeringPolicy/>
        <SizeBasedTriggeringPolicy size="100MB"/>
      </Policies>
    </RollingFile>

    <!-- Each time the size exceeds size,Then this size Size logs are automatically saved by year-The folder created in the month is compressed as an archive-->
    <RollingFile name="appender_warn" fileName="${localhost_path}/warn.log"
      filePattern="${localhost_path}/$${date:yyyy-MM}/warn-%d{yyyy-MM-dd}-%i.log">
      <!--Console output only level And above( onMatch),Other direct rejection( onMismatch)-->
      <ThresholdFilter level="warn" onMatch="ACCEPT" onMismatch="DENY"/>
      <PatternLayout pattern="${COMMON_LOG_PATTERN}"/>
      <Policies>
        <TimeBasedTriggeringPolicy/>
        <SizeBasedTriggeringPolicy size="100MB"/>
      </Policies>
    </RollingFile>


    <!-- Each time the size exceeds size,Then this size Size logs are automatically saved by year-The folder created in the month is compressed as an archive-->
    <RollingFile name="appender_error" fileName="${localhost_path}/error.log"
      filePattern="${localhost_path}/$${date:yyyy-MM}/error-%d{yyyy-MM-dd}-%i.log">
      <!--Console output only level And above( onMatch),Other direct rejection( onMismatch)-->
      <ThresholdFilter level="error" onMatch="ACCEPT" onMismatch="DENY"/>
      <PatternLayout pattern="${COMMON_LOG_PATTERN}"/>
      <Policies>
        <TimeBasedTriggeringPolicy/>
        <SizeBasedTriggeringPolicy size="100MB"/>
      </Policies>
    </RollingFile>

  </Appenders>


  <Loggers>
    <!--Filter out spring and mybatis Some useless DEBUG information-->
    <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} is the value we need to set dynamically

Other configuration values:

Spring boot load log4j normal process

The entry location for spring boot to load Log

You can see that org.springframework.boot.context.logging has two classes under this package, ClasspathLoggingApplicationListener and LoggingApplicationListener. The main part is LoggingApplicationListener, which will trigger the initialization task of Log4j context again. Here we talk about the word again because of the mechanism of log4j and slf4j. Because a static attribute is defined in the spring applicaton class, private static final log logger = logfactory.getlog (spring application. Class); This is how spring boot encapsulates the definition of slfj4 and log4j. Finally, the bottom layer will load the context of log4j once. The function of LoggingApplicationListener class is to load the context of log4j again. According to the logging configuration of spring boot, for example, logging.config and so on.

Spring boot time to load ApplicationListener

By analyzing the startup process of SpringBoot, the application startingevent event is issued before the org.springframework.boot.springapplication ා prepareEnvironment process. In the process of processing prepareEnvironment, SpringBoot starts the application environmentpreparedevent process of ApplicationListener. Therefore, the configuration information of Environment can be obtained in the application Environment preparedevent event

Log4j extension config time to get Environment

Log4j extension config: the time to get Environment is that the event Environment postprocessor is triggered after the completion ratio of ConfigFileApplicationListener As can be seen from the above figure, ConfigFileApplicationListener is executed earlier than LoggingApplicationListener in log processing, so it avoids the situation that the Enviornment cannot be obtained when LoggingApplicationListener is executed

Pit, log4j2.xml even loaded directly

This is the key point that I spend a lot of time and push me to get familiar with the whole process.

The original idea was that since the log4j2.xml file would be loaded by default in the log file defined by SpringBoot, in order to save a part of configuration (logging.config), I set the default configuration file as log4j2.xml, which resulted in that the project name could not be read when the log4j2 context was loaded for the first time.

@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";
    }
}

The output file format is / date/project/default/logs/info.log. But in fact, the value of default should be the application name I set. Default is just a scheme I wrote.

The reason is that Log4j2 starts to load the default configuration file before the spring boot life cycle starts. I think it's a spring boot design problem. People who don't know log4j will mistakenly think that this configuration file is initialized when spring boot starts the configuration log process, but it's not.

Next, we will briefly analyze the initialization process of log4j2's own province: LoggerContext file will first traverse the configuration files of some columns (including log4j2.xml) during startup. If it is traversed, it will read and start to set and create according to the contents of the configuration file. Therefore, after the log4j.xml file is configured here, it is actually earlier than the logContext created by the spring boot context. As a result, the dynamic properties read from the Spring Environment configured in log4j2.xml will not be set. Because the process here is too long, I will simply list the general process here 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() [core] > > > Org. Apache. Logging. Log4j. Core. Config. Configurationfactory. Factory? Getconfiguration (org. Apache. Logging. Log4j. Core. Loggercontext, Boolean, Java. Lang. string) > > > loaded log4j2. XML > > > org.apache.logging.log4j.core.LoggerContext#setConfiguration >>>>>> Org. Apache. Logging. Log4j. Core. Config. Abstractconfiguration? Createpluginobject creates the gap of xml configuration Org. Apache. Logging. Log4j. Core. Appender. Rollingfileappender. Builder - create file

Core: org.apache.logging.log4j.core.LoggerContext#reconfigure(java.net.URI)

In fact, SpringBoot also triggers this process, but it does some configuration extension.

summary

In the process of developing this simple unified log format, there are many problems. Originally, it was thought to be a very simple process, but in fact, there are still many knowledge points to be designed. It includes the most complex Log4j loading process, the process of configuring Log4j by SpringBoot, and the process of starting the life cycle by SpringBoot. At the end of the process, I spent two or three days studying this process. The result is quite satisfactory. Of course, there was a compromise in the process that the log file name could not be changed into an application name (the first version completely abandoned the spring boot process and manually implemented a function of reading yml). Fortunately, I finally insisted.

Last

Follow me and download in PDF format

Tags: Programming log4j Spring Apache xml

Posted on Sun, 29 Mar 2020 01:54:24 -0700 by Amy1980