1. 程式人生 > >slf4j繫結log4j2日誌系統的過程(原始碼分析)

slf4j繫結log4j2日誌系統的過程(原始碼分析)

一、環境及介紹

slf4j和log4j2的介紹在文章http://blog.csdn.net/honghailiang888/article/details/52681777進行過介紹,原始碼分析版本log4j-api-2.2.jar、log4j-core-2.2.jar、log4j-slf4j-impl-2.2.jar、slf4j-api-1.7.21.jar

二、從使用入手

/**
 * @author HHL
 * 
 * @date 2016年9月27日
 * 
 *       日誌工具類類,採用slf4j方式
 */
public class LogUtil {
	// test日誌
	public static Logger testLog = LoggerFactory.getLogger("test_logger");
	
	public static boolean isPrintStackTrace = true;
	
	// 記錄test錯誤日誌資訊
	public static void testLogError(String errorMessage, Exception ex) {
		if (testLog != null) {
			testLog.error(errorMessage);
		}

		if (isPrintStackTrace && ex != null && testLog != null) {
			testLog.error(ex.getMessage(), ex);
		}
	}

	public static void printInfoLog(Class<?> cla, String message) {
		LoggerFactory.getLogger(cla).info(message);
	}
}

配置檔案內容log4j2.xml

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN">
  <Appenders>
    <Console name="Console" target="SYSTEM_OUT">
      <PatternLayout pattern="%d{YYYY-MM-dd HH:mm:ss.SSS} [%t] %-5level %l %msg%n"/>
    </Console>
    
    <RollingFile name="test_logger" filename="${sys:catalina.home}/logs/test_logger.log"
      filepattern="${sys:catalina.home}/logs/test_logger.%d{yyyy-MM-dd-HH}.log">
  	<PatternLayout pattern="%d{YYYY-MM-dd HH:mm:ss.SSS} %5p [%t] %c(%F:%L) - %msg%n" />
      <Policies>
      	<!-- 檔案大小配置 -->
        <SizeBasedTriggeringPolicy size="100 KB"/>
      </Policies>	
       <!-- 共存log檔案數量 -->
       <DefaultRolloverStrategy max="20"/>
    </RollingFile>
    
  </Appenders>
  
  <Loggers>
    <Root level="info">
      <AppenderRef ref="Console"/>
    </Root>
    <!-- springMVC log配置 -->
    <Logger name="org.springframework.web" level="info" additivity="false">
      <AppenderRef ref="Console"/>
    </Logger>
    <!-- mybatis log配置 -->
    <Logger name="com.mango.mapper" level="trace" additivity="false">
      <AppenderRef ref="Console"/>
    </Logger>
    <!-- log檔案配置 -->
    <Logger name="test_logger" level="info" additivity="true">
      <AppenderRef ref="test_logger"/>
    </Logger>
  </Loggers>
</Configuration>

三、原始碼分析

1.從第一句入手

public static Logger testLog = LoggerFactory.getLogger("test_logger");
 /**
     * Return a logger named according to the name parameter using the
     * statically bound {@link ILoggerFactory} instance.
     * 
     * @param name
     *            The name of the logger.
     * @return logger
     */
    public static Logger getLogger(String name) {
        ILoggerFactory iLoggerFactory = getILoggerFactory();
        return iLoggerFactory.getLogger(name);
    }
/**
     * Return the {@link ILoggerFactory} instance in use.
     * <p/>
     * <p/>
     * ILoggerFactory instance is bound with this class at compile time.
     * 
     * @return the ILoggerFactory instance in use
     */
    public static ILoggerFactory getILoggerFactory() {
        if (INITIALIZATION_STATE == UNINITIALIZED) {
            synchronized (LoggerFactory.class) {
                if (INITIALIZATION_STATE == UNINITIALIZED) {
                    INITIALIZATION_STATE = ONGOING_INITIALIZATION;
                    performInitialization();
                }
            }
        }
        switch (INITIALIZATION_STATE) {
        case SUCCESSFUL_INITIALIZATION:
            return 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");
    }


其中初次bind的日誌系統就在上述performInitialization()中

private final static void performInitialization() {
        bind();
        if (INITIALIZATION_STATE == SUCCESSFUL_INITIALIZATION) {
            versionSanityCheck();
        }
    }


直接看bind()函式:

private final static void bind() {
        try {
            Set<URL> staticLoggerBinderPathSet = null;
            // skip check under android, see also
            // http://jira.qos.ch/browse/SLF4J-328
            if (!isAndroid()) {
                staticLoggerBinderPathSet = findPossibleStaticLoggerBinderPathSet();
                reportMultipleBindingAmbiguity(staticLoggerBinderPathSet);
            }
            // the next line does the binding
            StaticLoggerBinder.getSingleton();
            INITIALIZATION_STATE = SUCCESSFUL_INITIALIZATION;
            reportActualBinding(staticLoggerBinderPathSet);
            fixSubstituteLoggers();
            replayEvents();
            // release all resources in SUBST_FACTORY
            SUBST_FACTORY.clear();
        } catch (NoClassDefFoundError ncde) {
            String msg = ncde.getMessage();
            if (messageContainsOrgSlf4jImplStaticLoggerBinder(msg)) {
                INITIALIZATION_STATE = NOP_FALLBACK_INITIALIZATION;
                Util.report("Failed to load class \"org.slf4j.impl.StaticLoggerBinder\".");
                Util.report("Defaulting to no-operation (NOP) logger implementation");
                Util.report("See " + NO_STATICLOGGERBINDER_URL + " for further details.");
            } else {
                failedBinding(ncde);
                throw ncde;
            }
        } catch (java.lang.NoSuchMethodError nsme) {
            String msg = nsme.getMessage();
            if (msg != null && msg.contains("org.slf4j.impl.StaticLoggerBinder.getSingleton()")) {
                INITIALIZATION_STATE = FAILED_INITIALIZATION;
                Util.report("slf4j-api 1.6.x (or later) is incompatible with this binding.");
                Util.report("Your binding is version 1.5.5 or earlier.");
                Util.report("Upgrade your binding to version 1.6.x.");
            }
            throw nsme;
        } catch (Exception e) {
            failedBinding(e);
            throw new IllegalStateException("Unexpected initialization failure", e);
        }
    }


findPossibleStaticLoggerBinderPathSet()發現可能的binder路徑,從類路徑中尋找org/slf4j/impl/StaticLoggerBinder.class類:LoggerFactory.java

// We need to use the name of the StaticLoggerBinder class, but we can't
    // reference
    // the class itself.
    private static String STATIC_LOGGER_BINDER_PATH = "org/slf4j/impl/StaticLoggerBinder.class";

    static Set<URL> findPossibleStaticLoggerBinderPathSet() {
        // use Set instead of list in order to deal with bug #138
        // LinkedHashSet appropriate here because it preserves insertion order
        // during iteration
        Set<URL> staticLoggerBinderPathSet = new LinkedHashSet<URL>();
        try {
            ClassLoader loggerFactoryClassLoader = LoggerFactory.class.getClassLoader();
            Enumeration<URL> paths;
            if (loggerFactoryClassLoader == null) {
                paths = ClassLoader.getSystemResources(STATIC_LOGGER_BINDER_PATH);
            } else {
                paths = loggerFactoryClassLoader.getResources(STATIC_LOGGER_BINDER_PATH);
            }
            while (paths.hasMoreElements()) {
                URL path = paths.nextElement();
                staticLoggerBinderPathSet.add(path);
            }
        } catch (IOException ioe) {
            Util.report("Error getting resources from path", ioe);
        }
        return staticLoggerBinderPathSet;
    }


其中獲取到的path為jar:file:/D:/software/Server/Tomcat/apache-tomcat-7.0.30/webapps/ETeam/WEB-INF/lib/log4j-slf4j-impl-2.2.jar!/org/slf4j/impl/StaticLoggerBinder.class,如果為多個(會記錄會發出警告 reportMultipleBindingAmbiguity(staticLoggerBinderPathSet);),則會隨機(

SLF4J 會在編譯時會繫結import org.slf4j.impl.StaticLoggerBinder; 該類裡面實現對具體日誌方案的繫結接入。任何一種基於slf4j 的實現都要有一個這個類。如:

org.slf4j.slf4j-log4j12-1.5.6: 提供對 log4j 的一種適配實現。

Org.slf4j.slf4j-simple-1.5.6: 是一種 simple 實現,會將 log 直接打到控制檯。

……

那麼這個地方就要注意了:如果有任意兩個實現slf4j 的包同時出現,那就有可能釀就悲劇,你可能會發現日誌不見了、或都打到控制檯了。原因是這兩個jar 包裡都有各自的org.slf4j.impl.StaticLoggerBinder ,編譯時候繫結的是哪個是不確定的(根據類載入原理,一般只會載入一個,且是順序載入,因此執行的時候只會選擇一個)。這個地方要特別注意!!出現過幾次因為這個導致日誌錯亂的問題。

)選取一個bind(多個時會記錄選擇的哪個reportActualBinding(staticLoggerBinderPathSet);),但這裡只有一個,因此只會選擇一個。

總結,其實這裡獲取StaticLoggerBinder類的路徑只是用來記錄用,使用哪一個在編譯時期就已經決定了(log4j-slf4j-impl-2.2.jar包起了橋接的作用)。這個時候就和log4j2關聯上了。獲得的loggerFactory就是

/**
     * Private constructor to prevent instantiation
     */
    private StaticLoggerBinder() {
        loggerFactory = new Log4jLoggerFactory();
    }

2、看Log4jLoggerFactory.java中的getLogger是繼承的AbstractLoggerAdapter類中的

@Override
    public L getLogger(final String name) {
        final LoggerContext context = getContext();   //獲取logger環境
        final ConcurrentMap<String, L> loggers = getLoggersInContext(context);
        if (loggers.containsKey(name)) {
            return loggers.get(name);
        }
        loggers.putIfAbsent(name, newLogger(name, context));
        return loggers.get(name);  根據名字獲取logger
    }

看getContext()幹了什麼

@Override
    protected LoggerContext getContext() {
        final Class<?> anchor = ReflectionUtil.getCallerClass(FQCN, PACKAGE); 獲取呼叫類
        return anchor == null ? LogManager.getContext() : getContext(ReflectionUtil.getCallerClass(anchor));
    }

最終呼叫到了LogManager.java中,徹底進入log4j2

/**
     * Gets the {@link LoggerContext} associated with the given caller class.
     *
     * @param callerClass the caller class
     * @return the LoggerContext for the calling class
     */
    protected LoggerContext getContext(final Class<?> callerClass) {
        ClassLoader cl = null;
        if (callerClass != null) {
            cl = callerClass.getClassLoader();
        }
        if (cl == null) {
            cl = LoaderUtil.getThreadContextClassLoader();
        }
        return LogManager.getContext(cl, false);
    }
public static LoggerContext getContext(final ClassLoader loader, final boolean currentContext) {
        return factory.getContext(FQCN, loader, null, currentContext);
    }

Log4jContextFactory.java

/**
     * Loads the LoggerContext using the ContextSelector.
     * @param fqcn The fully qualified class name of the caller.
     * @param loader The ClassLoader to use or null.
     * @param currentContext If true returns the current Context, if false returns the Context appropriate
     * for the caller if a more appropriate Context can be determined.
     * @param externalContext An external context (such as a ServletContext) to be associated with the LoggerContext.
     * @return The LoggerContext.
     */
    @Override
    public LoggerContext getContext(final String fqcn, final ClassLoader loader, final Object externalContext,
                                    final boolean currentContext) {
        final LoggerContext ctx = selector.getContext(fqcn, loader, currentContext);
        if (externalContext != null && ctx.getExternalContext() == null) {
            ctx.setExternalContext(externalContext);
        }
        if (ctx.getState() == LifeCycle.State.INITIALIZED) {
            ctx.start();           //初始獲取,會解析配置檔案log4j2.xml
        }
        return ctx;
    }

LoggerContext.java

@Override
    public void start() {
        LOGGER.debug("Starting LoggerContext[name={}, {}]...", getName(), this);
        if (configLock.tryLock()) {
            try {
                if (this.isInitialized() || this.isStopped()) {
                    this.setStarting();
                    reconfigure();       //解析配置檔案
                    if (this.config.isShutdownHookEnabled()) {
                        setUpShutdownHook();
                    }
                    this.setStarted();
                }
            } finally {
                configLock.unlock();
            }
        }
        LOGGER.debug("LoggerContext[name={}, {}] started OK.", getName(), this);
    }
/**
     * Reconfigure the context.
     */
    public synchronized void reconfigure() {
        final ClassLoader cl = ClassLoader.class.isInstance(externalContext) ? (ClassLoader) externalContext : null;
        LOGGER.debug("Reconfiguration started for context[name={}] at {} ({}) with optional ClassLoader: {}", name,
            configLocation, this, cl);
        final Configuration instance = ConfigurationFactory.getInstance().getConfiguration(name, configLocation, cl);
        setConfiguration(instance);
        /*
         * instance.start(); Configuration old = setConfiguration(instance);
         * updateLoggers(); if (old != null) { old.stop(); }
         */

        LOGGER.debug("Reconfiguration complete for context[name={}] at {} ({}) with optional ClassLoader: {}", name,
            configLocation, this, cl);
    }

直接看最終的

private Configuration getConfiguration(final boolean isTest, final String name) {
            final boolean named = name != null && name.length() > 0;
            final ClassLoader loader = LoaderUtil.getThreadContextClassLoader();
            for (final ConfigurationFactory factory : factories) {
                String configName;
                final String prefix = isTest ? TEST_PREFIX : DEFAULT_PREFIX;
                final String [] types = factory.getSupportedTypes();
                if (types == null) {
                    continue;
                }

                for (final String suffix : types) {
                    if (suffix.equals("*")) {
                        continue;
                    }
                    configName = named ? prefix + name + suffix : prefix + suffix;

                    final ConfigurationSource source = getInputFromResource(configName, loader);
                    if (source != null) {
                        return factory.getConfiguration(source);
                    }
                }
            }
            return null;
        }
</pre><pre class="java" name="code" code_snippet_id="1933544" snippet_file_name="blog_20161017_19_6401194">/**
     * File name prefix for test configurations.
     */
    protected static final String TEST_PREFIX = "log4j2-test";
    /**
     * File name prefix for standard configurations.
     */
    protected static final String DEFAULT_PREFIX = "log4j2";


slf4j和log4j2的結合就此出現,log輸出也是用的log4j2的。

四、沒有配置的情況下,預設的配置為

/**
 * The default configuration writes all output to the Console using the default logging level. You configure default
 * logging level by setting the system property "org.apache.logging.log4j.level" to a level name. If you do not
 * specify the property, Log4j uses the ERROR Level. Log Events will be printed using the basic formatting provided
 * by each Message.
 */
public class DefaultConfiguration extends AbstractConfiguration {

    private static final long serialVersionUID = 1L;

    /**
     * The name of the default configuration.
     */
    public static final String DEFAULT_NAME = "Default";
    /**
     * The System Property used to specify the logging level.
     */
    public static final String DEFAULT_LEVEL = "org.apache.logging.log4j.level";
    /**
     * The default Pattern used for the default Layout.
     */
    public static final String DEFAULT_PATTERN = "%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n";

    /**
     * Constructor to create the default configuration.
     */
    public DefaultConfiguration() {
        super(ConfigurationSource.NULL_SOURCE);
        
        setName(DEFAULT_NAME);
        final Layout<? extends Serializable> layout = PatternLayout.newBuilder()
            .withPattern(DEFAULT_PATTERN)
            .withConfiguration(this)
            .build();
        final Appender appender = ConsoleAppender.createDefaultAppenderForLayout(layout);
        appender.start();
        addAppender(appender);
        final LoggerConfig root = getRootLogger();
        root.addAppender(appender, null, null);

        final String levelName = PropertiesUtil.getProperties().getStringProperty(DEFAULT_LEVEL);
        final Level level = levelName != null && Level.valueOf(levelName) != null ?
            Level.valueOf(levelName) : Level.ERROR;
        root.setLevel(level);
    }

    @Override
    protected void doConfigure() {
    }
}

輸出到console中,預設級別為error級別,也可以通過system property "org.apache.logging.log4j.level"配置級別