Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Critical Critical
    • Resolution: Fixed
    • Affects Version/s: 2.0-beta4
    • Fix Version/s: 2.0-beta5
    • Component/s: Core
    • Labels:

      Description

      We randomly get the following:

      java.util.ConcurrentModificationException
      at org.apache.logging.log4j.core.config.ConfigurationFactory$Factory.getConfiguration(ConfigurationFactory.java:377)
      at org.apache.logging.log4j.core.config.ConfigurationFactory$Factory.getConfiguration(ConfigurationFactory.java:361)
      at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:266)
      at org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:134)
      at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:75)
      at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:30)
      at org.apache.logging.log4j.LogManager.getLogger(LogManager.java:165)
      at org.apache.logging.log4j.LogManager.getLogger(LogManager.java:174)
      at …

      factories is defined as:

      private static List<ConfigurationFactory> factories = new ArrayList<ConfigurationFactory>();

      The simple fix is to use a java.util.concurrent.CopyOnWriteArrayList:

      private static final List<ConfigurationFactory> factories = new CopyOnWriteArrayList<ConfigurationFactory>();

      https://svn.apache.org/repos/asf/logging/log4j/log4j2/trunk/core/src/main/java/org/apache/logging/log4j/core/config/ConfigurationFactory.java

        Activity

        Hide
        Jed Wesley-Smith added a comment -

        Anything in particular holding up a beta5 release?

        It has been a few months since the last one and this particular problem is seriously slowing our test runs as they must be executed sequentially to avoid tripping this up.

        Show
        Jed Wesley-Smith added a comment - Anything in particular holding up a beta5 release? It has been a few months since the last one and this particular problem is seriously slowing our test runs as they must be executed sequentially to avoid tripping this up.
        Hide
        Remko Popma added a comment -

        Maven build seems broken: org.apache.logging.log4j.LogManager now has an (unused)
        import com.sun.xml.internal.xsom.impl.UnionSimpleTypeImpl; that stops the build.
        Removing the import fixes the problem.

        Show
        Remko Popma added a comment - Maven build seems broken: org.apache.logging.log4j.LogManager now has an (unused) import com.sun.xml.internal.xsom.impl.UnionSimpleTypeImpl; that stops the build. Removing the import fixes the problem.
        Hide
        Ralph Goers added a comment -

        Fixed in revision 1452151. Please verify and close.

        Show
        Ralph Goers added a comment - Fixed in revision 1452151. Please verify and close.
        Hide
        Ralph Goers added a comment -

        Making the change as you propose has the side effect of causing the initialization to occur when the ConfigurationFactory class is first referenced instead of when an instance of the ConfigurationFactory is required. Doing that would cause the createFactories method to try to create instances of the ConfigurationFactory class while that class hasn't finished initializing, which I don't think is a good idea.

        Show
        Ralph Goers added a comment - Making the change as you propose has the side effect of causing the initialization to occur when the ConfigurationFactory class is first referenced instead of when an instance of the ConfigurationFactory is required. Doing that would cause the createFactories method to try to create instances of the ConfigurationFactory class while that class hasn't finished initializing, which I don't think is a good idea.
        Hide
        Remko Popma added a comment - - edited

        You are right, I missed the "volatile" declaration.

        Still, the "static singleton" solution proposed in both the articles (in yours it's under "Making it work for static singletons") looks a lot simpler:
        (and it will be faster because it doesn't even have the volatile memory barrier).

        private static List<ConfigurationFactory> factories = createFactories(); // no need to make this volatile

        public static List<ConfigurationFactory> getInstance()

        { return factories; }

        private static List<ConfigurationFactory> createFactories()

        { // no need for null checking or synchronization here List<ConfigurationFactory> list = new ArrayList<ConfigurationFactory>(); .... return Collections.unmodifiableList(list); }
        Show
        Remko Popma added a comment - - edited You are right, I missed the "volatile" declaration. Still, the "static singleton" solution proposed in both the articles (in yours it's under "Making it work for static singletons") looks a lot simpler: (and it will be faster because it doesn't even have the volatile memory barrier). private static List<ConfigurationFactory> factories = createFactories(); // no need to make this volatile public static List<ConfigurationFactory> getInstance() { return factories; } private static List<ConfigurationFactory> createFactories() { // no need for null checking or synchronization here List<ConfigurationFactory> list = new ArrayList<ConfigurationFactory>(); .... return Collections.unmodifiableList(list); }
        Hide
        Ralph Goers added a comment -

        The article you reference is very old. Take a look at http://www.cs.umd.edu/~pugh/java/memoryModel/DoubleCheckedLocking.html and then search for "volatile" (this is just the first article Google gave me when I searched - there are others). You will notice that in the code fragment I posted above the factories variable is declared volatile. Noel left it out in his example because he was simply fixing the mistake I made of not checking the variable again.

        The semantics of volatile changed in Java 5 such that it provides some of the same guarantees you get with synchronizing access to a variable. Log4j2 takes advantage of this during reconfiguration to avoid having to synchronize access to the configuration. See http://www.javamex.com/tutorials/synchronization_volatile_java_5.shtml for a reasonable, if simple, explanation. There are some other things that can happen with non-volatile variables or even volatile variables prior to java 5 that won't any more due to the memory guarantees.

        In any case, DCL does work if the variable being checked is declared volatile or is an element of a ConcurrentHashMap, or the like, which provide similar guarantees.

        Show
        Ralph Goers added a comment - The article you reference is very old. Take a look at http://www.cs.umd.edu/~pugh/java/memoryModel/DoubleCheckedLocking.html and then search for "volatile" (this is just the first article Google gave me when I searched - there are others). You will notice that in the code fragment I posted above the factories variable is declared volatile. Noel left it out in his example because he was simply fixing the mistake I made of not checking the variable again. The semantics of volatile changed in Java 5 such that it provides some of the same guarantees you get with synchronizing access to a variable. Log4j2 takes advantage of this during reconfiguration to avoid having to synchronize access to the configuration. See http://www.javamex.com/tutorials/synchronization_volatile_java_5.shtml for a reasonable, if simple, explanation. There are some other things that can happen with non-volatile variables or even volatile variables prior to java 5 that won't any more due to the memory guarantees. In any case, DCL does work if the variable being checked is declared volatile or is an element of a ConcurrentHashMap, or the like, which provide similar guarantees.
        Hide
        Remko Popma added a comment -

        Double-checked locking is broken because the JIT will optimize and out-of-order writes can happen.

        Here is the analysis plus a solution:
        http://www.ibm.com/developerworks/java/library/j-dcl/index.html

        Show
        Remko Popma added a comment - Double-checked locking is broken because the JIT will optimize and out-of-order writes can happen. Here is the analysis plus a solution: http://www.ibm.com/developerworks/java/library/j-dcl/index.html
        Hide
        Noel Grandin added a comment -

        The thread-safe DCL looks like:

        public static ConfigurationFactory getInstance() {
        if (factories == null) {
        synchronized (TEST_PREFIX) {
        if (factories == null)

        { List<ConfigurationFactory> list = new ArrayList<ConfigurationFactory>(); .... factories = Collections.unmodifiableList(list); }

        }
        }
        return configFactory;
        }

        Otherwise, later on, someone adds something that shouldn't be executed more than once inside the inner block, and bad stuff happens

        Show
        Noel Grandin added a comment - The thread-safe DCL looks like: public static ConfigurationFactory getInstance() { if (factories == null) { synchronized (TEST_PREFIX) { if (factories == null) { List<ConfigurationFactory> list = new ArrayList<ConfigurationFactory>(); .... factories = Collections.unmodifiableList(list); } } } return configFactory; } Otherwise, later on, someone adds something that shouldn't be executed more than once inside the inner block, and bad stuff happens
        Hide
        Ralph Goers added a comment -

        I am thinking more like using thread safe double checked locking:

        private static volatile List<ConfigurationFactory> factories = null;

        public static ConfigurationFactory getInstance() {

        if (factories == null) {
        synchronized (TEST_PREFIX)

        { List<ConfigurationFactory> list = new ArrayList<ConfigurationFactory>(); .... factories = Collections.unmodifiableList(list); }

        }
        return configFactory;

        }

        Show
        Ralph Goers added a comment - I am thinking more like using thread safe double checked locking: private static volatile List<ConfigurationFactory> factories = null; public static ConfigurationFactory getInstance() { if (factories == null) { synchronized (TEST_PREFIX) { List<ConfigurationFactory> list = new ArrayList<ConfigurationFactory>(); .... factories = Collections.unmodifiableList(list); } } return configFactory; }
        Hide
        Gary Gregory added a comment -

        Ralph: So... CopyOnWriteArrayList or something else?

        Show
        Gary Gregory added a comment - Ralph: So... CopyOnWriteArrayList or something else?
        Hide
        Jed Wesley-Smith added a comment -

        > What is bizarre?

        Creating a new Configuration each time getInstance is called. I hadn't noticed that, I was only looking at the direct usages of the list.

        Show
        Jed Wesley-Smith added a comment - > What is bizarre? Creating a new Configuration each time getInstance is called. I hadn't noticed that, I was only looking at the direct usages of the list.
        Hide
        Ralph Goers added a comment -

        What is bizarre?

        Show
        Ralph Goers added a comment - What is bizarre?
        Hide
        Jed Wesley-Smith added a comment -

        > I looked at this code last night and it struck me that I don't think getInstance should be adding factory Class instances to the list every time it is called. There are a couple of choices in fixing that which would also solve the ConcurrentModificationException.

        That is truly bizarre.

        Show
        Jed Wesley-Smith added a comment - > I looked at this code last night and it struck me that I don't think getInstance should be adding factory Class instances to the list every time it is called. There are a couple of choices in fixing that which would also solve the ConcurrentModificationException. That is truly bizarre.
        Hide
        Jed Wesley-Smith added a comment -

        > Using a CopyOnWriteArrayList seems like a brute force solution would generate a lot of garbage when many loggers are added. My server at work uses 100's of loggers.

        100s is not very many at all. Also, we are talking about ConfigurationFactory objects, not Loggers. This technique (copy-on-write) is tried and true for this kind of read-mostly configuration data.

        > The alternative would be to synchronize in just the right places, which is harder to get right.

        Well no, it is easy actually, but you don't want to. Syncchronizing or locking means you must synchronize readers as well as writers – which is an unnecessary performance hit. CopyOnWriteArrayList does the right thing for you. It is extremely simple to implement.

        Show
        Jed Wesley-Smith added a comment - > Using a CopyOnWriteArrayList seems like a brute force solution would generate a lot of garbage when many loggers are added. My server at work uses 100's of loggers. 100s is not very many at all. Also, we are talking about ConfigurationFactory objects, not Loggers. This technique (copy-on-write) is tried and true for this kind of read-mostly configuration data. > The alternative would be to synchronize in just the right places, which is harder to get right. Well no, it is easy actually, but you don't want to. Syncchronizing or locking means you must synchronize readers as well as writers – which is an unnecessary performance hit. CopyOnWriteArrayList does the right thing for you. It is extremely simple to implement.
        Hide
        Gary Gregory added a comment -

        Are duplicate factories allowed? If not, the type of the static variable should be a Set, not a List.

        Show
        Gary Gregory added a comment - Are duplicate factories allowed? If not, the type of the static variable should be a Set, not a List.
        Hide
        Ralph Goers added a comment -

        I looked at this code last night and it struck me that I don't think getInstance should be adding factory Class instances to the list every time it is called. There are a couple of choices in fixing that which would also solve the ConcurrentModificationException.

        Show
        Ralph Goers added a comment - I looked at this code last night and it struck me that I don't think getInstance should be adding factory Class instances to the list every time it is called. There are a couple of choices in fixing that which would also solve the ConcurrentModificationException.
        Hide
        Gary Gregory added a comment -

        Using a CopyOnWriteArrayList seems like a brute force solution would generate a lot of garbage when many loggers are added. My server at work uses 100's of loggers.

        The alternative would be to synchronize in just the right places, which is harder to get right.

        Ralph, any thoughts?

        Show
        Gary Gregory added a comment - Using a CopyOnWriteArrayList seems like a brute force solution would generate a lot of garbage when many loggers are added. My server at work uses 100's of loggers. The alternative would be to synchronize in just the right places, which is harder to get right. Ralph, any thoughts?

          People

          • Assignee:
            Ralph Goers
            Reporter:
            Jed Wesley-Smith
          • Votes:
            2 Vote for this issue
            Watchers:
            5 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development