preface

Java has many logging frameworks to choose from. If multiple logging frameworks exist in the same project, it is easy to encounter log framework conflicts, resulting in log printing failure. This article takes a typical log conflict troubleshooting problem as an example, provides troubleshooting steps and ideas, and finally analyzes the causes of log framework conflicts.

When we encounter a problem, we do not know the root cause of the problem. If we already know the cause of the problem, the problem will be solved easily. Therefore, I hope to reproduce my thoughts and steps of troubleshooting problems when I did not know much about the log framework at that time. How to find solutions to unknown problems is a very important skill.

A typical log conflict check

The problem background

In project A, Log4j2 is used for the log framework configuration. The log can be printed normally on the master branch, but the log cannot be printed after the code is added to the development branch. Project dependencies include Log4j2, Logback, and other logging frameworks.

Process and process of troubleshooting

When troubleshooting problems, we must first have a clear idea, that is, bold assumptions, careful verification, not like a headless fly disorderly try. From the appearance of the problem, several intuitive assumptions can be made:

  1. The server environment is faulty
  2. There is a problem with the Log4j2 configuration of the development branch

The next step is to verify the hypothesis. First, apply for several more machines to deploy the project branch and find that the problem still exists, so the first hypothesis can be ruled out. Secondly, the Log4j2 configuration of another project B was compared with that of project A, and no detailed differences were found, which can rule out the second hypothesis.

In the case that all the existing hypotheses have failed, more information needs to be collected to make a judgment. The next step is to collect information with controlled experiments. So I broke two projects, A and B, respectively, to observe whether their log entity types are consistent. It is found that the log entity types of the two are different. The log implementation of A is Logback, and the log implementation of B is Log4j2. Obviously, A cannot print the log because the log entity is wrong, but both use the same LoggerFactory to create Logger. From the results of the controlled experiment, one hypothesis can be made that the dependency conflict causes the A runtime to use the logging entity instead of Log4j2.

Now that we have the general direction of the problem, the next step is to arrange packets. There are two ways to discharge packets:

  1. Brute force solution: Remove all possible conflicting log packets and try them one by one.
  2. Precision blasting: Use class loading information to determine which JAR is loaded at runtime

The brute force solution takes too long, so I’ll do it the second way.

You can obtain log entities as follows:

    private static final Logger LOGGER = LoggerFactory
            .getLogger(xxx.class);
Copy the code

The LoggerFactory code looks like this:

public abstract class LoggerFactory extends LogFactory {

    public static Logger getLogger(Class clazz) {
        ClassLoader oldTccl = Thread.currentThread().getContextClassLoader();

        try {
            Thread.currentThread().setContextClassLoader(LoggerFactory.class.getClassLoader());
            returngetLogger(getLog(clazz)); } finally { Thread.currentThread().setContextClassLoader(oldTccl); }}}Copy the code

It can be seen from the code that the getLog method comes from the parent class LogFactory. When I tried to obtain the implementation of LogFactory, I found that there are three JARS with the same package name LogFactory implementation. So I broke the code of project A and project B and used the running code function of IDEA to execute the following command to obtain the loading information of LogFactory.

Project B uses Spring-JCL, project A uses JCL-over-SLf4J, and then excludes JCL-over-SLf4J in project A.

In the above screening process, there are two key points:

  1. Locate the root cause of the problem as a class loading conflict and determine the troubleshooting direction.
  2. The breakpoint is used to obtain the loading information of the conflicting classes and quickly locate the conflicting JAR.

Why do logging frameworks conflict

That’s the end of the problem, but there’s still a deeper question: why should there be conflicts when there are multiple logging frameworks? After solving the problem, I delved into the history and design of the logging framework and found that it had something to do with the implementation mechanism of the logging framework.

The history of the logging framework

Let’s start with the history of logging frameworks.

  • The first entry isJava Util Log, JUL for short, is the built-in log function in the JDK. Although official, JUL is not widely used, mainly because its features are relatively simple and difficult to use.
  • thenLog4j 1.xHere it is: it is a very well-designed logging framework implemented by Gulcu, and is a very widely used framework.
  • Commons Logging: JCL for short, an Apache project. JCL is a Log Facade that provides only the Log API, not the Implementation, using Adapter to use Log4j or JUL as Log Implementation. The purpose is to unify the logging interface specification and adapt to multiple logging implementations.
  • SLF4J/LogbackSLF4J(The Simple Logging Facade for Java) and Logback are also projects created by Gulcu to provide higher performance implementations. Where SLF4j is a Log Facade similar to JCL and Logback is a Log Implementation similar to Log4j. I think the JCL interface design is not good, so I redesigned it.
  • Log4j2The Log4j maintainers have come up with a new logging framework to protect Log4j users from SLF4J/Logback. Log4j2 is not compatible with log4j1.x, and the design largely mimics SLF4J/Logback, with significant performance improvements. Log4j2 also has a Facade/Implementation separation between log4J-API and log4J-core.

So far we have three Log interfaces and four Log implementations, and sure enough programmers love to build wheels. With so many frameworks in place, someone started bridging them, one for all, one for all, as shown below.

Because many jars use different logging frameworks, it is common to introduce jar packages that cause logging class conflicts. The problem we checked was the introduction of jCL-over-SLf4J bridge packages.

Dynamic load log implementation

As mentioned earlier, the logging framework is divided into logging interface and logging implementation. As long as we use logging interface (JCL, SLF4J) in our code, we can replace the logging implementation at any time.

SLF4J loads logging implementations

SLF4J load logging implementation is divided into two steps:

  1. Gets the ILoggerFactory log factory
  2. Get the Logger according to ILoggerFactory

SLF4J requires that all logging implementation JARS implement the class StaticLoggerBinder and be placed in the specified directory: Org/slf4j/impl/StaticLoggerBinder. Class, slf4j LoggerFactory to scan all the jars in this address, refer to the following code.

private static String STATIC_LOGGER_BINDER_PATH = "org/slf4j/impl/StaticLoggerBinder.class";

static Set<URL> findPossibleStaticLoggerBinderPathSet() { LinkedHashSet staticLoggerBinderPathSet = new LinkedHashSet(); / / load all possible log factory class try {this ioe = LoggerFactory. Class. GetClassLoader (); Enumeration paths;if(ioe == null) {
                paths = ClassLoader.getSystemResources(STATIC_LOGGER_BINDER_PATH);
            } else {
                paths = ioe.getResources(STATIC_LOGGER_BINDER_PATH);
            }

            while(paths.hasMoreElements()) {
                URL path = (URL)paths.nextElement();
                staticLoggerBinderPathSet.add(path);
            }
        } catch (IOException var4) {
            Util.report("Error getting resources from path", var4);
        }

        return staticLoggerBinderPathSet;
    }
Copy the code

Although it scans multiple logging implementations, only one JVM of the same name can exist, and the purpose of the scan is to print a log telling the user how many logging implementations are in the dependency package. The following code returns the final logging implementation used.

public static ILoggerFactory getILoggerFactory() {
        if (INITIALIZATION_STATE == UNINITIALIZED) {
            synchronized (LoggerFactory.class) {
                if (INITIALIZATION_STATE == UNINITIALIZED) {
                    INITIALIZATION_STATE = ONGOING_INITIALIZATION;
                    performInitialization();
                }
            }
        }
        switch (INITIALIZATION_STATE) {
        caseSUCCESSFUL_INITIALIZATION: // The actual logging engineering class is returned using static methodsreturn StaticLoggerBinder.getSingleton().getLoggerFactory();
        case NOP_FALLBACK_INITIALIZATION:
            return NOP_FALLBACK_FACTORY;
        case FAILED_INITIALIZATION:
            throw new IllegalStateException(UNSUCCESSFUL_INIT_MSG);
        case ONGOING_INITIALIZATION:
            // support re-entrant behavior.
            // See also http://jira.qos.ch/browse/SLF4J-97
            return SUBST_FACTORY;
        }
        throw new IllegalStateException("Unreachable code");
    }
Copy the code

You may ask, which logging implementation class is used when there are multiple logging implementations? The answer is simple, because SLF4J uses static classes to load logging projects, essentially letting the JVM decide which classes to use: whichever is loaded into the JVM first. To find out, I specifically looked at the implementation of the URLClassPath load class, which scans the jar in the order it was added to URLClassPath and returns the first one that matches the criteria.

How JCL loads logging implementations

Compared to SLF4J’s more capricious loading approach, which depends on the order in which classes are loaded by the JVM, JCL provides more configuration capability to specify which logging engineering classes to use.

Similarly, JCL has a two-step log loading implementation:

  1. Gets the LogFactory LogFactory class
  2. Get the Logger from LogFactory

The first is to get the LogFactory:

  1. System properties are first read from system propertiesSystem.getProperty("org.apache.commons.logging.LogFactory")
  2. Use Java’s SPI mechanism to search for the corresponding implementation:META-INF/services/org.apache.commons.logging.LogFactoryI won’t talk too much about SPI here, but it’s simply a matter of finding which JAR packages contain the above file, which refers to the corresponding LogFactory implementation
  3. Look for commons-logging.properties in the commons-logging configuration fileorg.apache.commons.logging.LogFactoryThe value of the
  4. If you haven’t found it yet, use the defaultorg.apache.commons.logging.impl.LogFactoryImpl

Once you find the LogFactory, you get the Logger based on the LogFactory, which is implemented in different ways. The problem I encountered earlier was using SLJ4J’s LogFactory and loading the wrong Logger due to a class conflict.

conclusion

There will always be strange and strange problems in the development process. When there is a feeling that there is no place to start, first stabilize your mind and conduct investigation in accordance with bold assumptions and careful verification. It is often because the foundation is not solid. If you understand the loading implementation of the logging framework, you can easily locate the problem like this one. I don’t know the implementation of the logging framework, but I can solve the problem based on my previous knowledge of the class loading mechanism; If you don’t understand the class loading mechanism, there is basically no solution. Therefore, to treat problems as learning opportunities, not only to solve the problem, but also to dig into the principles behind it, do a good summary, so as to lay a solid foundation for solving more problems.

The resources

  • Java Logging Framework Parsing (Part 1) – Historical Evolution
  • JCL and JUL, log4J1, log4j2, logback integration principle
  • Slf4j and JUL, log4j1, log4j2, logback integration principle