[slf4j-dev] [Bug 176] New: Initialization (getILoggerFactory) is not thread safe

[bugzilla-daemon at pixie.qos.ch]

http://bugzilla.slf4j.org/show_bug.cgi?id=176

           Summary: Initialization (getILoggerFactory) is not thread safe
           Product: SLF4J
           Version: 1.5.x
          Platform: All
        OS/Version: All
            Status: NEW
          Severity: major
          Priority: P2
         Component: Core API
        AssignedTo: slf4j-dev at qos.ch
        ReportedBy: rcogswell at datasltn.com


If a getLogger call occurs during initialization from a thread other than the
one that triggered the initialization, it is treated the same as if it were a
re-entrant call from the initialization thread (i.e. getILoggerFactory returns
the TEMP_FACTORY).

Scenario:
1. An SLF4J LogFactory.getLogger statement is at the beginning of a worker
thread class's run method.
2. Two or more worker threads are started at the same time during server
startup.
3. Since the getLogger statements from the workers are executed nearly
simultaneously, the first one triggers the SLF4J initialization and subsequent
workers receive NOPLogger instances from the TEMP_FACTORY since
LoggerFactory.INITIALIZATION_STATE == ONGOING_INITILIZATION.
4. Logging then works successfully for the worker that triggered the
initialization, but the logging for all other workers is suppressed.

The only reason I've indicated the severity as "major" instead of "critical" is
that I happen to have my own wrapper class around SLF4J, so it was easy for me
to independently track whether or not SLF4J has been called and introduce
appropriate synchronization around the first call.  For those using SLF4J
directly (as recommended), there would not likely be any straightforward
workaround.

Below I've included a new implementation for LoggerFactory.getILoggerFactory to
address this.  The key aspects of this new implementation are as follows:
1. Checks first for successful initialization since this is the case for which
performance matters most.
2. Synchronizes around determining whether or not the current thread should
perform initialization, but does not synchronize around the initialization
itself.
3. Retains the previous behavior for re-entrant calls from the thread
performing the initialization.
4. Calls from other threads during initialization will wait up to 10 seconds
for the initialization to finish.

The main downsides of the implementation below (aside from not yet being
tested):
1. If a logging implementation uses multiple threads to perform its
initialization and one of those threads does a getLogger call, then this change
would have undesirable effects, but I would be very surprised if any SLF4J
implementations have multi-threaded initialization.
2. 10 seconds was a fairly arbitrary choice.  It might be worthwhile to allow
this to be controlled by a system property with a default of 10 seconds.
3. Considerably more complicated than the current implementation.

  private static Thread INITIALIZATION_THREAD = null;
  private static Object INITIALIZATION_SYNCH = new Object();
  /**
   * Return the {@link ILoggerFactory} instance in use.
   *
   * <p>
   * ILoggerFactory instance is bound with this class at compile time.
   *
   * @return the ILoggerFactory instance in use
   */
  public static ILoggerFactory getILoggerFactory() {
    if (INITIALIZATION_STATE == SUCCESSFUL_INITILIZATION) {
      return getSingleton().getLoggerFactory();
    }
    if (INITIALIZATION_STATE == FAILED_INITILIZATION) {
      throw new IllegalStateException(UNSUCCESSFUL_INIT_MSG);
    }
    boolean shouldPerformInitialization = false;
    synchronized (INITIALIZATION_SYNCH) {
      if (INITIALIZATION_STATE == UNINITIALIZED) {
        INITIALIZATION_STATE = ONGOING_INITILIZATION;
        INITIALIZATION_THREAD = Thread.currentThread();
        shouldPerformInitialization = true;
      } else if (INITIALIZATION_STATE == ONGOING_INITILIZATION) {
        if (Thread.currentThread() == INITIALIZATION_THREAD) {
          // support re-entrant behavior.
          // See also http://bugzilla.slf4j.org/show_bug.cgi?id=106
          return TEMP_FACTORY;
        }
        try {
          INITIALIZATION_SYNCH.wait(10000);
        } catch (InterruptedException e) {
          Util.reportFailure("Initialization failed to complete within 10
seconds.");
          return TEMP_FACTORY;
        }
      }
    }
    if (shouldPerformInitialization) {
      performInitialization();
      synchronized (INITIALIZATION_SYNCH) {
        INITIALIZATION_THREAD = null;
        INITIALIZATION_SYNCH.notifyAll();
      }
    }
    switch (INITIALIZATION_STATE) {
    case SUCCESSFUL_INITILIZATION:
      return getSingleton().getLoggerFactory();
    case FAILED_INITILIZATION:
      throw new IllegalStateException(UNSUCCESSFUL_INIT_MSG);
    }
    throw new IllegalStateException("Unreachable code");
  }


-- 
Configure bugmail: http://bugzilla.slf4j.org/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.