Source code and asynchronous log of slf4j and log4j

Keywords: log4j Apache xml github

In our projects, we usually use slf4j to log in this way:
org.slf4j.Logger logger = org.slf4j.LoggerFactory.getLogger(Test.class);
Start with this log Logger creation to see the source code:
org.slf4j.LoggerFactory.getLogger(String name){
    ILoggerFactory iLoggerFactory = getILoggerFactory(); //1 places
    return iLoggerFactory.getLogger(name);
}
perhaps
public static Logger getLogger(Class<?> clazz) {
    Logger logger = getLogger(clazz.getName()); //2 places
    if (DETECT_LOGGER_NAME_MISMATCH) {
        Class<?> autoComputedCallingClass = Util.getCallingClass();
        if (autoComputedCallingClass != null && nonMatchingClasses(clazz, autoComputedCallingClass)) {
            Util.report(String.format("Detected logger name mismatch. Given name: \"%s\"; computed name: \"%s\".", logger.getName(),
                            autoComputedCallingClass.getName()));
            Util.report("See " + LOGGER_NAME_MISMATCH_URL + " for an explanation");
        }
    }
    return logger;
}
The getLogger(String name) method is also called in two places.
Look back at the getILoggerFactory() method at 1 and call the getLogget method, knowing that the Logger object is created using the factory pattern.
public static ILoggerFactory getILoggerFactory() {
    if (INITIALIZATION_STATE == UNINITIALIZED) {
        synchronized (LoggerFactory.class) {
            if (INITIALIZATION_STATE == UNINITIALIZED) { //3 places
                INITIALIZATION_STATE = ONGOING_INITIALIZATION;
                performInitialization();
            }
        }
    }
    switch (INITIALIZATION_STATE) {
    case SUCCESSFUL_INITIALIZATION: //4 places
        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");
}
In three places, if the state is not initialized, the initialization is carried out first. After successful initialization, the StaticLoggerBinder object is obtained by using the singleton mode in four places, and the factory object of Logger is obtained.
The following source code, StaticLoggerBinder, constructs the new factory object Log4jLoggerFactory
private StaticLoggerBinder() {
    loggerFactory = new Log4jLoggerFactory();
    try {
        @SuppressWarnings("unused")
        Level level = Level.TRACE;
    } catch (NoSuchFieldError nsfe) {
        Util.report("This version of SLF4J requires log4j version 1.2.12 or later. See also http://www.slf4j.org/codes.html#log4j_version");
    }
}
So knowing that the ILoggerFactory object taken at "1" in the source code above is an example of org.slf4j.impl.Log4jLoggerFactory, then look at Log4jLoggerFactory.getLogger(String name)
public class Log4jLoggerFactory implements ILoggerFactory {
    // key: name (String), value: a Log4jLoggerAdapter;
    ConcurrentMap<String, Logger> loggerMap;

    public Log4jLoggerFactory() {
        loggerMap = new ConcurrentHashMap<String, Logger>();
    }

    public Logger getLogger(String name) {
        Logger slf4jLogger = loggerMap.get(name);
        if (slf4jLogger != null) {
            return slf4jLogger;
        } else {
            org.apache.log4j.Logger log4jLogger;
            if (name.equalsIgnoreCase(Logger.ROOT_LOGGER_NAME)) //ROOT_LOGGER_NAME = "ROOT"
                log4jLogger = LogManager.getRootLogger();
            else
                log4jLogger = LogManager.getLogger(name); //5 places

            Logger newInstance = new Log4jLoggerAdapter(log4jLogger); //51 places
            Logger oldInstance = loggerMap.putIfAbsent(name, newInstance);
            return oldInstance == null ? newInstance : oldInstance;
        }
    }
}
Map loggerMap of Log4jLogger Facotry stores the key-value mapping relationship of org.slf4j.Logger.
"Five places" for source code, where LogManager first get s Logger log4jLogger objects to log4j
public class LogManager {
  /**
   * @deprecated This variable is for internal use only. It will
   * become package protected in future versions.
   * */
  static public final String DEFAULT_CONFIGURATION_FILE = "log4j.properties";
 
  static final String DEFAULT_XML_CONFIGURATION_FILE = "log4j.xml";  
   
  /**
   * @deprecated This variable is for internal use only. It will
   * become private in future versions.
   * */
  static final public String DEFAULT_CONFIGURATION_KEY="log4j.configuration";

  /**
   * @deprecated This variable is for internal use only. It will
   * become private in future versions.
   * */
  static final public String CONFIGURATOR_CLASS_KEY="log4j.configuratorClass";

  /**
  * @deprecated This variable is for internal use only. It will
  * become private in future versions.
  */
  public static final String DEFAULT_INIT_OVERRIDE_KEY = "log4j.defaultInitOverride";

  static private RepositorySelector repositorySelector;

  static {
    // By default we use a DefaultRepositorySelector which always returns 'h'.
    Hierarchy h = new Hierarchy(new RootLogger((Level) Level.DEBUG)); //61 places
    repositorySelector = new DefaultRepositorySelector(h); //6 places

    /** Search for the properties file log4j.properties in the CLASSPATH.  */
    String override = OptionConverter.getSystemProperty(DEFAULT_INIT_OVERRIDE_KEY, null);

    // if there is no default init override, then get the resource
    // specified by the user or the default config file.
    if(override == null || "false".equalsIgnoreCase(override)) {

      //Use - Dlog4j.configuration=log4j.properties to specify the log4j configuration file
      String configurationOptionStr = OptionConverter.getSystemProperty(DEFAULT_CONFIGURATION_KEY, null);

      String configuratorClassName = OptionConverter.getSystemProperty(CONFIGURATOR_CLASS_KEY, null);

      URL url = null;

      // if the user has not specified the log4j.configuration
      // property, we search first for the file "log4j.xml" and then
      // "log4j.properties"
      if(configurationOptionStr == null) {
        //If no log4j configuration file is specified, load log4j.xml first    
        url = Loader.getResource(DEFAULT_XML_CONFIGURATION_FILE);
        if(url == null) {
          //Without log4j.xml, the log4j.properties are loaded
          url = Loader.getResource(DEFAULT_CONFIGURATION_FILE);
        }
      } else {
        try {
          url = new URL(configurationOptionStr);
        } catch (MalformedURLException ex) {
          // so, resource is not a URL:
          // attempt to get the resource from the class path
          url = Loader.getResource(configurationOptionStr);
        }    
      }
      
      // If we have a non-null url, then delegate the rest of the
      // configuration to the OptionConverter.selectAndConfigure
      // method.
      if(url != null) {
        LogLog.debug("Using URL ["+url+"] for automatic log4j configuration.");
        try {
            //Configure log4j logs
            OptionConverter.selectAndConfigure(url, configuratorClassName, LogManager.getLoggerRepository()); //62 places
        } catch (NoClassDefFoundError e) {
            LogLog.warn("Error during default initialization", e);
        }
      } else {
        LogLog.debug("Could not find resource: ["+configurationOptionStr+"].");
      }
    } else {
        LogLog.debug("Default initialization of overridden by " +
            DEFAULT_INIT_OVERRIDE_KEY + "property.");
    }  
  }
 
  static public LoggerRepository getLoggerRepository() {
    if (repositorySelector == null) { //7 places
        repositorySelector = new DefaultRepositorySelector(new NOPLoggerRepository());
        guard = null;
        Exception ex = new IllegalStateException("Class invariant violation");
        String msg = "log4j called after unloading, see http://logging.apache.org/log4j/1.2/faq.html#unload.";
        if (isLikelySafeScenario(ex)) {
            LogLog.debug(msg, ex);
        } else {
            LogLog.error(msg, ex);
        }
    }
    return repositorySelector.getLoggerRepository(); //8 places
  }

  public static Logger getLogger(final String name) {
     // Delegate the actual manufacturing of the logger to the logger repository.
    return getLoggerRepository().getLogger(name);
  }
}
In LogManager, first look at - Dlog4j.configuration=log4j.properties to specify the log4j configuration file. If no log4j configuration file is specified, first load log4j.xml, and then load log4j.properties without log4j.xml.
Look at the getLogger method of LogManager, which actually calls getLoggerRepository(), gets the LoggerRepository object, and gets the Logger object by getLogger(name).
Let's first look at the getLoggerRepository() method
Repository Selector at 7 locations has a DefaultRepository Selector object at 6 locations when the LogManager class is loaded. The LoggerRepository-Hierarchy object is set and the DEBUG level of the log is set.
Look at 61 new Hierarchy objects:
public class Hierarchy implements LoggerRepository, RendererSupport, ThrowableRendererSupport {

  private LoggerFactory defaultFactory;
  private Vector listeners;

  Hashtable ht;
  Logger root;
  RendererMap rendererMap;

  int thresholdInt;
  Level threshold;

  boolean emittedNoAppenderWarning = false;
  boolean emittedNoResourceBundleWarning = false;

  private ThrowableRenderer throwableRenderer = null;

  public Hierarchy(Logger root) {
    ht = new Hashtable();
    listeners = new Vector(1);
    this.root = root; //log4j.Logger
    // Enable all level levels by default.
    setThreshold(Level.ALL);
    this.root.setHierarchy(this); //62 places
    rendererMap = new RendererMap();
    defaultFactory = new DefaultCategoryFactory();
  }
The set Hierarchy (Logger Repository repository) method at 62 is Category's method, while log4j.Logger inherits Category:
// Categories need to know what Hierarchy they are in
protected LoggerRepository repository;
final void setHierarchy(LoggerRepository repository) {
    this.repository = repository;
}
//So eight getLoggerRepository() get Hierarchy objects.
public class DefaultRepositorySelector implements RepositorySelector {

  final LoggerRepository repository;

  public DefaultRepositorySelector(LoggerRepository repository) {
    this.repository = repository;
  }
}
So getLoggerRepository().getLogger(name) calls Hierarchy's getLogger(String name) method. Look at the following nine
public class Hierarchy implements LoggerRepository, RendererSupport, ThrowableRendererSupport {
  private Vector listeners;

  Hashtable ht;
  Logger root;

  public Hierarchy(Logger root) {
    ht = new Hashtable();
    listeners = new Vector(1);
    this.root = root;
    // Enable all level levels by default.
    setThreshold(Level.ALL);
    this.root.setHierarchy(this);
    rendererMap = new RendererMap();
    defaultFactory = new DefaultCategoryFactory();
  }

  public Logger getLogger(String name) { //9 places
    return getLogger(name, defaultFactory);
  }

  public Logger getLogger(String name, LoggerFactory factory) {
    //System.out.println("getInstance("+name+") called.");
    CategoryKey key = new CategoryKey(name);
    // Synchronize to prevent write conflicts. Read conflicts (in
    // getChainedLevel method) are possible only if variable
    // assignments are non-atomic.
    Logger logger;

    synchronized(ht) {
      Object o = ht.get(key);
      if(o == null) {
    logger = factory.makeNewLoggerInstance(name); //10 places
    logger.setHierarchy(this);
    ht.put(key, logger);
    updateParents(logger); //11 places
    return logger;
      } else if(o instanceof Logger) {
    return (Logger) o;
      } else if (o instanceof ProvisionNode) {
    //System.out.println("("+name+") ht.get(this) returned ProvisionNode");
    logger = factory.makeNewLoggerInstance(name);
    logger.setHierarchy(this);
    ht.put(key, logger);
    updateChildren((ProvisionNode) o, logger);
    updateParents(logger);
    return logger;
      }
      else {
    // It should be impossible to arrive here
    return null;  // but let's keep the compiler happy.
      }
    }
  }
Create an org.apache.log4j.Logger object in 10 places and save it in Hashtable ht <name, org.apache.log4j.Logger>.
In 11 updateParents methods:
private void updateParents(Logger cat) {
    String name = cat.name;
    int length = name.length();
    boolean parentFound = false;

    //System.out.println("UpdateParents called for " + name);

    // if name = "w.x.y.z", loop thourgh "w.x.y", "w.x" and "w", but not "w.x.y.z"
    for(int i = name.lastIndexOf('.', length-1); i >= 0;
                                     i = name.lastIndexOf('.', i-1))  {
      String substr = name.substring(0, i);

      //System.out.println("Updating parent : " + substr);
      CategoryKey key = new CategoryKey(substr); // simple constructor
      Object o = ht.get(key);
      // Create a provision node for a future parent.
      if(o == null) {
    //System.out.println("No parent "+substr+" found. Creating ProvisionNode.");
    ProvisionNode pn = new ProvisionNode(cat);
    ht.put(key, pn);
      } else if(o instanceof Category) {
    parentFound = true;
    cat.parent = (Category) o;
    //System.out.println("Linking " + cat.name + " -> " + ((Category) o).name);
    break; // no need to update the ancestors of the closest ancestor
      } else if(o instanceof ProvisionNode) {
    ((ProvisionNode) o).addElement(cat);
      } else {
    Exception e = new IllegalStateException("unexpected object type " +
                    o.getClass() + " in ht.");
    e.printStackTrace();
      }
    }
    // If we could not find any existing parents, then link with root.
    if(!parentFound)
      cat.parent = root;
  }
Look at the source code here, such as Logger created for the w.x.y.z.Foo class, and then its parent w.x.y...
Everywhere, even if the log4j Logger object log4jLogger has been created.

Back to "51" of the source code, use log4jLogger to create an adapter => slf4j Logger object and save it in the Concurrent HashMap object loggerMap of org.slf4j.impl.Log4jLoggerFactory. Next time, use it directly instead of new.
public final class Log4jLoggerAdapter extends MarkerIgnoringBase implements LocationAwareLogger, Serializable {

    private static final long serialVersionUID = 6182834493563598289L;

    final transient org.apache.log4j.Logger logger;

    /**
     * Following the pattern discussed in pages 162 through 168 of "The complete
     * log4j manual".
     */
    final static String FQCN = Log4jLoggerAdapter.class.getName();

    // Does the log4j version in use recognize the TRACE level?
    // The trace level was introduced in log4j 1.2.12.
    final boolean traceCapable;

    // WARN: Log4jLoggerAdapter constructor should have only package access so
    // that
    // only Log4jLoggerFactory be able to create one.
    Log4jLoggerAdapter(org.apache.log4j.Logger logger) {
        this.logger = logger;
        this.name = logger.getName();
        traceCapable = isTraceCapable();
    }
    //Other omissions...
}
When the Log4jLoggerAdapter object newInstance is first published by new, it contains the relevant attributes of org.apache.log4j.Logger logger:
{
aai = null;
additve = true;
level = null;
parent = org.apache.log4j.spi.RootLogger;
repository = org.apache.log4j.Hierarchy;
resourceBundle = null;
}
Look at Category's call Appenders method:
public void callAppenders(LoggingEvent event) {
    int writes = 0;

    for(Category c = this; c != null; c=c.parent) {
      // Protected against simultaneous call to addAppender, removeAppender,...
      synchronized(c) {
    if(c.aai != null) { //11 places
      writes += c.aai.appendLoopOnAppenders(event);
    }
    if(!c.additive) {
      break;
    }
      }
    }

    if(writes == 0) {
      repository.emitNoAppenderWarning(this);
    }
 }
For 11 locations, the current aai of log4j.Logger is null, which loops back to its parent, RootLogger, while the Appender Attachable Impl aai of RootLogger is not empty.
[org.apache.log4j.ConsoleAppender, org.apache.log4j.DailyRollingFileAppender]

In fact, the focus is on how log4j is initialized. Here we look at the configuration file as log4j.properties.
For example, log4j.properties content:
log4j.rootLogger = info, stdout, D

log4j.appender.stdout = org.apache.log4j.ConsoleAppender
log4j.appender.stdout.layout = org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern = %d{MM-dd HH:mm:ss}:%p(%L) %c - %m%n

log4j.appender.D = org.apache.log4j.DailyRollingFileAppender
log4j.appender.D.File = logs/stdout.log
log4j.appender.D.DatePattern = '.'yyyy-MM-dd
log4j.appender.D.Append = true
log4j.appender.D.Encoding=UTF-8
log4j.appender.D.Threshold = INFO
log4j.appender.D.layout = org.apache.log4j.PatternLayout
log4j.appender.D.layout.ConversionPattern = %d{MM-dd HH:mm:ss}:%p(%L) %c - %m%n
The info of log4j.rootLogger represents the log level, while stdout and D indicate that the log needs to be exported to the corresponding Appender.

At the source code "62" of LogManager above, the OptionConverter.selectAndConfigure(...) method is called to configure log4j, and the PropertyConfigurator.doConfigure method is called here.
The doConfigure method configures the Appender of RootLogger:
void configureRootCategory(Properties props, LoggerRepository hierarchy) {
    String effectiveFrefix = ROOT_LOGGER_PREFIX;
    String value = OptionConverter.findAndSubst(ROOT_LOGGER_PREFIX, props);

    if(value == null) {
      value = OptionConverter.findAndSubst(ROOT_CATEGORY_PREFIX, props);
      effectiveFrefix = ROOT_CATEGORY_PREFIX;
    }

    if(value == null)
      LogLog.debug("Could not find root logger information. Is this OK?");
    else {
      Logger root = hierarchy.getRootLogger(); //12 places
      synchronized(root) {
        parseCategory(props, root, effectiveFrefix, INTERNAL_ROOT_NAME, value);
      }
    }
  }
Take RootLogger at 12 places and call the parseCategory method to add the configuration Appender class of log4j.properties to RootLogger. From the log4j.properties file above, you can see that two Appenders will be loaded.
Org. apache. log4j. Console Appender and org. apache. log4j. Daily Rolling File Appender.

So back to 11 of Category's call Appenders methods
if(c.aai != null) {
  writes += c.aai.appendLoopOnAppenders(event);
}
appendLoopOnAppenders Method:
public int appendLoopOnAppenders(LoggingEvent event) {
    int size = 0;
    Appender appender;

    if(appenderList != null) {
      size = appenderList.size();
      for(int i = 0; i < size; i++) {
        appender = (Appender) appenderList.elementAt(i);
        appender.doAppend(event); //13 places
      }
    }    
    return size;
}
When printing logs, Appenders are called iteratively, the two Appenders that call the log4j.properties configuration
Appender's doAppend method is called in 13 places. Appender Skeleton is the abstract class of Appender's implementation.
So the doAppend method of AppenderSkeleton is called first:
public abstract class AppenderSkeleton implements Appender, OptionHandler {
  public synchronized void doAppend(LoggingEvent event) {
    if(closed) {
      LogLog.error("Attempted to append to closed appender named ["+name+"].");
      return;
    }
    
    if(!isAsSevereAsThreshold(event.getLevel())) {
      return;
    }

    Filter f = this.headFilter;
    
    FILTER_LOOP:
    while(f != null) { //14 places
      switch(f.decide(event)) {
      case Filter.DENY: return;
      case Filter.ACCEPT: break FILTER_LOOP;
      case Filter.NEUTRAL: f = f.getNext();
      }
    }
    
    this.append(event); //15 places    
  }

  abstract protected void append(LoggingEvent event);
}
In AppenderSkeleton's doAppend method above, "14 places" look for the chain Filter (equivalent to the responsibility chain mode), according to the return status of the Filter:
1.Filter.DENY, no log printing, method end;
2.Filter.ACCEPT, can print logs, exit the cycle;
3.Filter.NEUTRAL, neutral state, left to the next Filter to decide.
Finally, Appender Skeleton's inheritance class implements the append method by calling the append abstract method at "15 places".

Print to console:
public class ConsoleAppender extends WriterAppender {}

Print to file (date scroll):
public class DailyRollingFileAppender extends FileAppender {}
public class FileAppender extends WriterAppender {}
public class WriterAppender extends AppenderSkeleton {}

If you use asynchronous logs, log4j configuration files need to use log4j.xml, and the Appender used for asynchronous logs is org.apache.log4j.AsyncAppender.
public class AsyncAppender extends AppenderSkeleton implements AppenderAttachable {}
It can be seen that the asynchronous log Appender also inherits Appender Skeleton.
Next I rewrote Appender for the asynchronous log myself:
https://github.com/jjavaboy/lam-nio/blob/master/lam-nio-core/src/main/java/lam/log/LamScheduleAsyncAppender.java
log4j.xml configuration file:
https://github.com/jjavaboy/lam-nio/blob/master/lam-schedule/src/main/resources/log4j.xml

Posted by Evanthes on Fri, 31 May 2019 15:44:01 -0700