Uploaded image for project: 'SLF4J'
  1. SLF4J
  2. SLF4J-167

Initialization (getILoggerFactory) is not thread safe

    Details

    • Type: Bug
    • Status: Resolved
    • Resolution: Fixed
    • Affects Version/s: 1.5.x
    • Fix Version/s: 1.7.14
    • Component/s: Core API
    • Labels:
      None
    • Environment:

      Operating System: All
      Platform: All

      Description

      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)

        Unknown macro: { 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)

        Unknown macro: { 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");
        }

        Attachments

          Issue Links

            Activity

              People

              • Assignee:
                ceki Ceki Gülcü
                Reporter:
                rcogswell Ryan Cogswell
              • Votes:
                2 Vote for this issue
                Watchers:
                17 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: