God, what a mess I’ve made with a simple unified log format

Recently, we received a request to package the log4j configuration file into a JAR file that relies on the SkyWalking package. On a larger level, in order to unify the log output format of the entire company, it is convenient to access SkyWalking and ELK.

What was I thinking

  1. The global format is uniform, that is, the constraint needs to be goodlog4j2.xmlFile location of

Since our existing log file location is written to log4j2.xml, we do not want to adjust the contents of the file at this time, but each application log 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 levels of output to logs in your code

For example, in the development environment, SQL logs need to be output, but in the production environment, SQL logs are not output due to performance and log volume problems.

  1. Keep the configuration simple

There is a learning cost to configuration and it is best to unify logs without a separate configuration

  1. Compatible with

The way to read configuration files should be compatible. For example, there may be configuration files named yML and Properties in the project, and the naming method may be strange. It should be compatible to the maximum extent for each application

  1. The document

Provide some level of documentation to help you personalize some of your content

Research related technology

  • log4j2
  • SpringBoot Logging
  • SpringBoot life cycle

The main approach of the whole development

How do I read the contents of the configuration file

Those familiar with Spring should know that Spring loads configuration files into the Environment’s implementation class (which implementation class depends on the Environment, StandardServletEnvironment StandardReactiveWebEnvironment StandardEnvironment), so want to read the values in the configuration file, will need to read after the Environment loading

SpringBootloadingEnvironmentThe timing of the

In the SpringBoot loading process, the Environment loading process is relatively early, through the source code can be understood,SprinBoot is to load the Environment at the very 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);

      

      // Prepare the 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;

	}

Copy the code
  • from13A line of code shows that SpringBoot is done initializingApplicationArgumentsThe parameter is then taken to prepare the Environment Environment (for more in-depth code, please see for yourself).

holdliveEnvironmentobject

How to holdEnvironmentobject

For those of you who have read the Log4J-extension-Config project, you can see that SpringEnvironmentHolder holds the Environment as a very common practice

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(a) {

        return environment;

    }



    public static ApplicationContext getApplicationContext(a) {

        return applicationContext;

    }

}



Copy the code

When willEnvironmentSet it toSpringEnvironmentHolderIt’s not too late

We won’t go into this topic because there are so many places to get this object, such as EnvironmentAware, ApplicationContextAware, etc., but it is important to know when it is not too late to understand the process, We need to know when does SpringBoot attack log4j2

How to inLog4jSet dynamic variables in the configuration file

This is where the Log4j plugin mechanism is needed, either using MDC or system.properties. For a more advanced look, I used the plugin mechanism to implement it.

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

    }

}



Copy the code

The configuration file


      

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



  <Appenders>



    <Console name="appender_console" target="SYSTEM_OUT">

      <PatternLayout pattern="${COMMON_LOG_PATTERN}"/>

    </Console>



    <! -- Every time the size of the log exceeds the size, the size of the log will be automatically saved in the folder created by year and month and 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 only outputs messages of level and above (onMatch).

      <ThresholdFilter level="info" onMatch="ACCEPT" onMismatch="DENY"/>

      <PatternLayout pattern="${COMMON_LOG_PATTERN}"/>

      <Policies>

        <TimeBasedTriggeringPolicy/>

        <SizeBasedTriggeringPolicy size="100MB"/>

      </Policies>

    </RollingFile>



    <! -- Every time the size of the log exceeds the size, the size of the log will be automatically saved in the folder created by year and month and 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 only outputs messages of level and above (onMatch).

      <ThresholdFilter level="warn" onMatch="ACCEPT" onMismatch="DENY"/>

      <PatternLayout pattern="${COMMON_LOG_PATTERN}"/>

      <Policies>

        <TimeBasedTriggeringPolicy/>

        <SizeBasedTriggeringPolicy size="100MB"/>

      </Policies>

    </RollingFile>





    <! -- Every time the size of the log exceeds the size, the size of the log will be automatically saved in the folder created by year and month and 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 only outputs messages of level and above (onMatch).

      <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 DEBUG messages -->

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

Copy the code
  • ${PPL :ppx.name} is the value we need to set dynamically

Other configurations:

ytjMJO

SpringBootloadinglog4jThe normal process

SpringBootloadingLogEntrance position of

Can see org. Springframework. Boot. Context. Logging under this package, there are two classes, ClasspathLoggingApplicationListener and LoggingApplicationListener, of which main part is LoggingApplicationListener this class will go to fire again Initialization tasks for the Log4j context. The reason the word again is mentioned here is because of the mechanism of log4j and SLf4J, Private static final Log Logger = LogFactory.getLog(springApplication.class); This is SpringBoot encapsulates slfj4 and log4j, the definition of the underlying will eventually go to load a log4j context, and LoggingApplicationListener again, the function of this class is loaded a log4j context, According to the SpringBoot logging configuration, such as logging.config and so on.

SpringBootloadingApplicationListenerThe timing of the

Through the analysis of the start-up process of SpringBoot in org. Springframework. Boot. SpringApplication# ApplicationStartingEvent prepareEnvironment before they start this process Events, in dealing with prepareEnvironment SpringBoot began ApplicationListener ApplicationEnvironmentPreparedEvent processing. So in the event of an ApplicationEnvironmentPreparedEvent has been able to get to the configuration information of the Environment.

log4j-extension-configTo obtainEnvironmentThe timing of the

log4j-extension-configThis project acquiresEnvironmentThe timing is thatEnvironmentPostProcessorThe event isConfigFileApplicationListenerExecution completed than triggered after execution.As can be seen from the picture above,ConfigFileApplicationListenerIs better than log processingLoggingApplicationListenerEarly implementation, so avoid inLoggingApplicationListenerNot available at execution timeEnviornmentIn the case

Pit, log4j2.xml actually loads directly

This is where I spend a lot of time and it’s the key thing that drives me to get familiar with the process.

The original idea was that since the log4j2.xml file would be loaded by default in the log file defined by SpringBoot, to save some configuration (logging.config), I set the default configuration file to log4j2.xml, causing the project name to fail to be read the first time the log4j2 context is loaded.

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

    }

}

Copy the code

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

This is because Log4j2 starts loading the default configuration file before the SpringBoot life cycle starts. I think there is a SpringBoot design problem here, and people who are not aware of Log4j will think that this configuration file is initialized when SpringBoot starts the configuration logging process, which it is not.

The LoggerContext file starts with a list of configuration files (including log4j2.xml). If the LoggerContext file starts with a list of configuration files (including log4j2.xml), the LoggerContext file starts with a list of configuration files (including log4j2.xml). If the LoggerContext file starts with a list of configuration files (including log4j2.xml). Therefore, the log4j.xml file is configured before the logContext created by the SpringBoot context. As a result, the dynamic properties read from the Spring Environment will not be set in log4j2.xml. Because the process here is too long, I will simply list the general process. 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.LoggerC ontext, boolean, Java. Lang. String) > > > > > loaded log4j2. XML > > > > > org. Apache. Logging. Log4j. Core. LoggerContext# setConfiguration > > > > > > Org. Apache. Logging. Log4j. Core. Config. AbstractConfiguration# createPluginObject gap created XML configuration > > > > > > Org. Apache. Logging. Log4j. Core. Appender. RollingFileAppender. Builder# build file created

Where the core: org. Apache. Logging. Log4j. Core. LoggerContext# reconfigure (java.net.URI)

SpringBoot also triggers this process, but SpringBoot does a configuration extension.

conclusion

In the process of developing this simple unified log format, encountered many problems, originally thought to be a very simple process, in fact, in the later view, need to design knowledge is still very much. It contains the most complex log4j loading process, SpringBoot log4j configuration process, SpringBoot boot life cycle of a process, after the end, I spent a total of two or three days to study this process. The results were satisfactory, although there were compromises in the process of not changing the log file name to the application name (the first version abandoned the SpringBoot process completely and implemented a manual yML reading function). Fortunately, he finally persevered.

The last

Follow me for PDF download