Uploaded image for project: 'Log4j 2'
  1. Log4j 2
  2. LOG4J2-1990

ConcurrentModificationException logging a parameter of type Map

    Details

    • Type: Bug
    • Status: Reopened
    • Priority: Major
    • Resolution: Unresolved
    • Affects Version/s: 2.8.2
    • Fix Version/s: 2.10.0
    • Component/s: Core
    • Labels:
      None
    • Flags:
      Important

      Description

      Hello,
      Working with current JMeter trunk and:

      • attached test plan
      • org.apache.jmeter.protocol.http.control.CacheManager level set to debug in log4j2.xml in bin folder

      I get:

      java.util.concurrent.ExecutionException: java.util.ConcurrentModificationException
      	at java.util.concurrent.FutureTask.report(FutureTask.java:122) ~[?:1.8.0_121]
      	at java.util.concurrent.FutureTask.get(FutureTask.java:192) ~[?:1.8.0_121]
      	at org.apache.jmeter.protocol.http.sampler.HTTPSamplerBase.downloadPageResources(HTTPSamplerBase.java:1349) [ApacheJMeter_http.jar:3.3-SNAPSHOT.20170724]
      	at org.apache.jmeter.protocol.http.sampler.HTTPSamplerBase.resultProcessing(HTTPSamplerBase.java:1657) [ApacheJMeter_http.jar:3.3-SNAPSHOT.20170724]
      	at org.apache.jmeter.protocol.http.sampler.HTTPAbstractImpl.resultProcessing(HTTPAbstractImpl.java:519) [ApacheJMeter_http.jar:3.3-SNAPSHOT.20170724]
      	at org.apache.jmeter.protocol.http.sampler.HTTPHC4Impl.sample(HTTPHC4Impl.java:534) [ApacheJMeter_http.jar:3.3-SNAPSHOT.20170724]
      	at org.apache.jmeter.protocol.http.sampler.HTTPSamplerProxy.sample(HTTPSamplerProxy.java:74) [ApacheJMeter_http.jar:3.3-SNAPSHOT.20170724]
      	at org.apache.jmeter.protocol.http.sampler.HTTPSamplerBase.sample(HTTPSamplerBase.java:1189) [ApacheJMeter_http.jar:3.3-SNAPSHOT.20170724]
      	at org.apache.jmeter.protocol.http.sampler.HTTPSamplerBase.sample(HTTPSamplerBase.java:1178) [ApacheJMeter_http.jar:3.3-SNAPSHOT.20170724]
      	at org.apache.jmeter.threads.JMeterThread.executeSamplePackage(JMeterThread.java:500) [ApacheJMeter_core.jar:3.3-SNAPSHOT.20170724]
      	at org.apache.jmeter.threads.JMeterThread.processSampler(JMeterThread.java:425) [ApacheJMeter_core.jar:3.3-SNAPSHOT.20170724]
      	at org.apache.jmeter.threads.JMeterThread.run(JMeterThread.java:254) [ApacheJMeter_core.jar:3.3-SNAPSHOT.20170724]
      	at java.lang.Thread.run(Thread.java:745) [?:1.8.0_121]
      Caused by: java.util.ConcurrentModificationException
      	at org.apache.commons.collections.map.AbstractLinkedMap$LinkIterator.nextEntry(AbstractLinkedMap.java:560) ~[commons-collections-3.2.2.jar:3.2.2]
      	at org.apache.commons.collections.map.AbstractLinkedMap$EntrySetIterator.next(AbstractLinkedMap.java:428) ~[commons-collections-3.2.2.jar:3.2.2]
      	at org.apache.logging.log4j.message.ParameterFormatter.appendMap(ParameterFormatter.java:569) ~[log4j-api-2.8.2.jar:2.8.2]
      	at org.apache.logging.log4j.message.ParameterFormatter.appendPotentiallyRecursiveValue(ParameterFormatter.java:505) ~[log4j-api-2.8.2.jar:2.8.2]
      	at org.apache.logging.log4j.message.ParameterFormatter.recursiveDeepToString(ParameterFormatter.java:432) ~[log4j-api-2.8.2.jar:2.8.2]
      	at org.apache.logging.log4j.message.ParameterFormatter.formatMessage2(ParameterFormatter.java:189) ~[log4j-api-2.8.2.jar:2.8.2]
      	at org.apache.logging.log4j.message.ReusableParameterizedMessage.formatTo(ReusableParameterizedMessage.java:313) ~[log4j-api-2.8.2.jar:2.8.2]
      	at org.apache.logging.log4j.core.impl.MutableLogEvent.setMessage(MutableLogEvent.java:214) ~[log4j-core-2.8.2.jar:2.8.2]
      	at org.apache.logging.log4j.core.impl.ReusableLogEventFactory.createEvent(ReusableLogEventFactory.java:81) ~[log4j-core-2.8.2.jar:2.8.2]
      	at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:401) [log4j-core-2.8.2.jar:2.8.2]
      	at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:63) [log4j-core-2.8.2.jar:2.8.2]
      	at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:146) [log4j-core-2.8.2.jar:2.8.2]
      	at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2091) [log4j-api-2.8.2.jar:2.8.2]
      	at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2005) [log4j-api-2.8.2.jar:2.8.2]
      	at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1876) [log4j-api-2.8.2.jar:2.8.2]
      	at org.apache.logging.slf4j.Log4jLogger.debug(Log4jLogger.java:124) [log4j-slf4j-impl-2.8.2.jar:2.8.2]
      	at org.apache.jmeter.protocol.http.control.CacheManager.getEntry(CacheManager.java:501) ~[ApacheJMeter_http.jar:3.3-SNAPSHOT.20170724]
      	at org.apache.jmeter.protocol.http.control.CacheManager.inCache(CacheManager.java:431) ~[ApacheJMeter_http.jar:3.3-SNAPSHOT.20170724]
      	at org.apache.jmeter.protocol.http.sampler.HTTPHC4Impl.sample(HTTPHC4Impl.java:443) ~[ApacheJMeter_http.jar:3.3-SNAPSHOT.20170724]
      	at org.apache.jmeter.protocol.http.sampler.HTTPSamplerProxy.sample(HTTPSamplerProxy.java:74) ~[ApacheJMeter_http.jar:3.3-SNAPSHOT.20170724]
      	at org.apache.jmeter.protocol.http.sampler.HTTPSamplerBase$ASyncSample.call(HTTPSamplerBase.java:2031) ~[ApacheJMeter_http.jar:3.3-SNAPSHOT.20170724]
      	at org.apache.jmeter.protocol.http.sampler.HTTPSamplerBase$ASyncSample.call(HTTPSamplerBase.java:1) ~[ApacheJMeter_http.jar:3.3-SNAPSHOT.20170724]
      	at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:1.8.0_121]
      	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:1.8.0_121]
      	at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:1.8.0_121]
      	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) ~[?:1.8.0_121]
      	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) ~[?:1.8.0_121]
      	... 1 more
      

        Issue Links

          Activity

          Hide
          garydgregory Gary Gregory added a comment -

          Either JMeter needs to use an implementation of ConcurrentMap or we need to lock the map before we iterate on it (and if it is not a ConcurrentMap, which might be a slight optimization.)

          Gary

          Show
          garydgregory Gary Gregory added a comment - Either JMeter needs to use an implementation of ConcurrentMap or we need to lock the map before we iterate on it (and if it is not a ConcurrentMap , which might be a slight optimization.) Gary
          Hide
          garydgregory Gary Gregory added a comment -

          Also, instead of checking for Collection for deep recursion, should we check for Iterable and Enumeration instead?

          Show
          garydgregory Gary Gregory added a comment - Also, instead of checking for Collection for deep recursion, should we check for Iterable and Enumeration instead?
          Hide
          garydgregory Gary Gregory added a comment -

          Did you just close the issue? If so, please explain. Also, you can try the attached patch on top of git master if you want to build a local SNAPSHOT.

          Show
          garydgregory Gary Gregory added a comment - Did you just close the issue? If so, please explain. Also, you can try the attached patch on top of git master if you want to build a local SNAPSHOT.
          Hide
          remkop@yahoo.com Remko Popma added a comment -

          Gary, to answer your question, I would prefer to check for Map and Collection instead of Iterable or Enumeration, because custom user objects may implement Iterable etc but possibly have a different threading model where Log4j2 synchronizing on these objects could cause problems like deadlock.

          However, the risk that synchronizing causes other problems also exists with Map and Collection.

          I'm still not 100% sure it's a good idea for Log4j2 to synchronize on these parameter objects. During synchronous logging the application should not be modifying the object in another thread, and with asynchronous logging Log4j2 takes a snapshot of the parameters in the application thread, so we should never see a ConcurrentModificationException unless there's a bug somewhere.

          Show
          remkop@yahoo.com Remko Popma added a comment - Gary, to answer your question, I would prefer to check for Map and Collection instead of Iterable or Enumeration , because custom user objects may implement Iterable etc but possibly have a different threading model where Log4j2 synchronizing on these objects could cause problems like deadlock. However, the risk that synchronizing causes other problems also exists with Map and Collection . I'm still not 100% sure it's a good idea for Log4j2 to synchronize on these parameter objects. During synchronous logging the application should not be modifying the object in another thread, and with asynchronous logging Log4j2 takes a snapshot of the parameters in the application thread, so we should never see a ConcurrentModificationException unless there's a bug somewhere.
          Hide
          garydgregory Gary Gregory added a comment -

          OK, let's leave Map and Collection checking as is for now.

          WRT synchronizing on Maps and Collections, we might not have a choice WRT useability: If I (a method) am given a Map or Collections and I want to log it, what should I do? Wrap it in my own shallow copy of that Map or Collections and then pass it to a logger method to avoid a concurrency exception? That seems like tough sell I may have zero control over what is happening to that collection outside of my method or even my thread... I do not see that we have a choice but to synchronize...

          Thoughts?

          Show
          garydgregory Gary Gregory added a comment - OK, let's leave Map and Collection checking as is for now. WRT synchronizing on Maps and Collections, we might not have a choice WRT useability: If I (a method) am given a Map or Collections and I want to log it, what should I do? Wrap it in my own shallow copy of that Map or Collections and then pass it to a logger method to avoid a concurrency exception? That seems like tough sell I may have zero control over what is happening to that collection outside of my method or even my thread... I do not see that we have a choice but to synchronize... Thoughts?
          Hide
          remkop@yahoo.com Remko Popma added a comment -

          Users should not need to do anything special. They should be able to log Maps and Collections without seeing a ConcurrentModificationException.

          However, if an application has a bug, and one application thread is modifying the map while a different thread is iterating over it, then you will see this exception. You may see it while logging, or elsewhere when iterating over it. (Wrapping it will not help. Even synchronizing on it will not help if the other thread doesn't also synchronize on it before modifying the map.)

          TLDR: Log4j2 cannot defend your application against concurrency bugs.

          LOG4J2-1988 (while appearing similar because of the exception) is a different issue where asynchronous logging somehow failed to take a snapshot of the map before handing it off to the background thread. That one smells like a Log4j2 bug to me.

          This ticket seems to point to a concurrency bug in the application, not in Log4j2.

          Show
          remkop@yahoo.com Remko Popma added a comment - Users should not need to do anything special. They should be able to log Maps and Collections without seeing a ConcurrentModificationException. However, if an application has a bug, and one application thread is modifying the map while a different thread is iterating over it, then you will see this exception. You may see it while logging, or elsewhere when iterating over it. (Wrapping it will not help. Even synchronizing on it will not help if the other thread doesn't also synchronize on it before modifying the map.) TLDR: Log4j2 cannot defend your application against concurrency bugs. LOG4J2-1988 (while appearing similar because of the exception) is a different issue where asynchronous logging somehow failed to take a snapshot of the map before handing it off to the background thread. That one smells like a Log4j2 bug to me. This ticket seems to point to a concurrency bug in the application, not in Log4j2.
          Hide
          ralph.goers@dslextreme.com Ralph Goers added a comment -
          Show
          ralph.goers@dslextreme.com Ralph Goers added a comment - https://logging.apache.org/log4j/2.x/manual/async.html already documents all of this.
          Hide
          garydgregory Gary Gregory added a comment - - edited

          You're right, synchronizing will not help.

          Why won't wrapping help? m = new HashMap(); m.addAll(...) I guess that you could get a CME during the copying which needs to iterate...

          Maybe we need to catch CME and just log that we cannot get the next element:

          diff --git a/log4j-api/src/main/java/org/apache/logging/log4j/message/ParameterFormatter.java b/log4j-api/src/main/java/org/apache/logging/log4j/message/ParameterFormatter.java
          index 79c447a..4aa8c62 100644
          --- a/log4j-api/src/main/java/org/apache/logging/log4j/message/ParameterFormatter.java
          +++ b/log4j-api/src/main/java/org/apache/logging/log4j/message/ParameterFormatter.java
          @@ -19,11 +19,13 @@
           import java.text.SimpleDateFormat;
           import java.util.Arrays;
           import java.util.Collection;
          +import java.util.ConcurrentModificationException;
           import java.util.Date;
           import java.util.HashSet;
           import java.util.Map;
           import java.util.Set;
           
          +import org.apache.logging.log4j.status.StatusLogger;
           import org.apache.logging.log4j.util.StringBuilderFormattable;
           
           /**
          @@ -566,18 +568,22 @@
                       final Map<?, ?> oMap = (Map<?, ?>) o;
                       str.append('{');
                       boolean isFirst = true;
          -            for (final Object o1 : oMap.entrySet()) {
          -                final Map.Entry<?, ?> current = (Map.Entry<?, ?>) o1;
          -                if (isFirst) {
          -                    isFirst = false;
          -                } else {
          -                    str.append(", ");
          +            try {
          +                for (final Object o1 : oMap.entrySet()) {
          +                    final Map.Entry<?, ?> current = (Map.Entry<?, ?>) o1;
          +                    if (isFirst) {
          +                        isFirst = false;
          +                    } else {
          +                        str.append(", ");
          +                    }
          +                    final Object key = current.getKey();
          +                    final Object value = current.getValue();
          +                    recursiveDeepToString(key, str, new HashSet<>(dejaVu));
          +                    str.append('=');
          +                    recursiveDeepToString(value, str, new HashSet<>(dejaVu));
                           }
          -                final Object key = current.getKey();
          -                final Object value = current.getValue();
          -                recursiveDeepToString(key, str, new HashSet<>(dejaVu));
          -                str.append('=');
          -                recursiveDeepToString(value, str, new HashSet<>(dejaVu));
          +            } catch (ConcurrentModificationException e) {
          +                StatusLogger.getLogger().warn("ConcurrentModificationException logging a Map", e);
                       }
                       str.append('}');
                   }
          @@ -596,13 +602,17 @@
                       final Collection<?> oCol = (Collection<?>) o;
                       str.append('[');
                       boolean isFirst = true;
          -            for (final Object anOCol : oCol) {
          -                if (isFirst) {
          -                    isFirst = false;
          -                } else {
          -                    str.append(", ");
          +            try {
          +                for (final Object anOCol : oCol) {
          +                    if (isFirst) {
          +                        isFirst = false;
          +                    } else {
          +                        str.append(", ");
          +                    }
          +                    recursiveDeepToString(anOCol, str, new HashSet<>(dejaVu));
                           }
          -                recursiveDeepToString(anOCol, str, new HashSet<>(dejaVu));
          +            } catch (ConcurrentModificationException e) {
          +                StatusLogger.getLogger().warn("ConcurrentModificationException logging  a Collection", e);
                       }
                       str.append(']');
                   }
          

          and maybe even put something in the string we're building...
          ?

          Show
          garydgregory Gary Gregory added a comment - - edited You're right, synchronizing will not help. Why won't wrapping help? m = new HashMap(); m.addAll(...) I guess that you could get a CME during the copying which needs to iterate... Maybe we need to catch CME and just log that we cannot get the next element: diff --git a/log4j-api/src/main/java/org/apache/logging/log4j/message/ParameterFormatter.java b/log4j-api/src/main/java/org/apache/logging/log4j/message/ParameterFormatter.java index 79c447a..4aa8c62 100644 --- a/log4j-api/src/main/java/org/apache/logging/log4j/message/ParameterFormatter.java +++ b/log4j-api/src/main/java/org/apache/logging/log4j/message/ParameterFormatter.java @@ -19,11 +19,13 @@ import java.text.SimpleDateFormat; import java.util.Arrays; import java.util.Collection; +import java.util.ConcurrentModificationException; import java.util.Date; import java.util.HashSet; import java.util.Map; import java.util.Set; +import org.apache.logging.log4j.status.StatusLogger; import org.apache.logging.log4j.util.StringBuilderFormattable; /** @@ -566,18 +568,22 @@ final Map<?, ?> oMap = (Map<?, ?>) o; str.append('{'); boolean isFirst = true; - for (final Object o1 : oMap.entrySet()) { - final Map.Entry<?, ?> current = (Map.Entry<?, ?>) o1; - if (isFirst) { - isFirst = false; - } else { - str.append(", "); + try { + for (final Object o1 : oMap.entrySet()) { + final Map.Entry<?, ?> current = (Map.Entry<?, ?>) o1; + if (isFirst) { + isFirst = false; + } else { + str.append(", "); + } + final Object key = current.getKey(); + final Object value = current.getValue(); + recursiveDeepToString(key, str, new HashSet<>(dejaVu)); + str.append('='); + recursiveDeepToString(value, str, new HashSet<>(dejaVu)); } - final Object key = current.getKey(); - final Object value = current.getValue(); - recursiveDeepToString(key, str, new HashSet<>(dejaVu)); - str.append('='); - recursiveDeepToString(value, str, new HashSet<>(dejaVu)); + } catch (ConcurrentModificationException e) { + StatusLogger.getLogger().warn("ConcurrentModificationException logging a Map", e); } str.append('}'); } @@ -596,13 +602,17 @@ final Collection<?> oCol = (Collection<?>) o; str.append('['); boolean isFirst = true; - for (final Object anOCol : oCol) { - if (isFirst) { - isFirst = false; - } else { - str.append(", "); + try { + for (final Object anOCol : oCol) { + if (isFirst) { + isFirst = false; + } else { + str.append(", "); + } + recursiveDeepToString(anOCol, str, new HashSet<>(dejaVu)); } - recursiveDeepToString(anOCol, str, new HashSet<>(dejaVu)); + } catch (ConcurrentModificationException e) { + StatusLogger.getLogger().warn("ConcurrentModificationException logging a Collection", e); } str.append(']'); } and maybe even put something in the string we're building... ?
          Hide
          ralph.goers@dslextreme.com Ralph Goers added a comment -

          The bottom line is that when this happens it is user error. We have documented what we expect. The string that is in the process of being built is going to contain garbage, so returning from this successfully doesn't seem right. In this case I would put the try/catch in MutableLogEvent and print something like the Message simple name and message format string when an exception occurs along with writing a StatusLogger warning.

          Show
          ralph.goers@dslextreme.com Ralph Goers added a comment - The bottom line is that when this happens it is user error. We have documented what we expect. The string that is in the process of being built is going to contain garbage, so returning from this successfully doesn't seem right. In this case I would put the try/catch in MutableLogEvent and print something like the Message simple name and message format string when an exception occurs along with writing a StatusLogger warning.
          Hide
          garydgregory Gary Gregory added a comment -

          Like so:

          diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/impl/MutableLogEvent.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/impl/MutableLogEvent.java
          index 56867b4..9f8a8b8 100644
          --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/impl/MutableLogEvent.java
          +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/impl/MutableLogEvent.java
          @@ -19,6 +19,7 @@
           import java.io.InvalidObjectException;
           import java.io.ObjectInputStream;
           import java.util.Arrays;
          +import java.util.ConcurrentModificationException;
           import java.util.Map;
           
           import org.apache.logging.log4j.Level;
          @@ -32,6 +33,7 @@
           import org.apache.logging.log4j.message.ParameterizedMessage;
           import org.apache.logging.log4j.message.ReusableMessage;
           import org.apache.logging.log4j.message.SimpleMessage;
          +import org.apache.logging.log4j.status.StatusLogger;
           import org.apache.logging.log4j.util.StackLocatorUtil;
           import org.apache.logging.log4j.util.StringBuilders;
           import org.apache.logging.log4j.util.StringMap;
          @@ -207,11 +209,23 @@
           
               public void setMessage(final Message msg) {
                   if (msg instanceof ReusableMessage) {
          -            final ReusableMessage reusable = (ReusableMessage) msg;
          -            reusable.formatTo(getMessageTextForWriting());
          -            if (parameters != null) {
          -                parameters = reusable.swapParameters(parameters);
          -                parameterCount = reusable.getParameterCount();
          +            try {
          +                final ReusableMessage reusable = (ReusableMessage) msg;
          +                reusable.formatTo(getMessageTextForWriting());
          +                if (parameters != null) {
          +                    parameters = reusable.swapParameters(parameters);
          +                    parameterCount = reusable.getParameterCount();
          +                }
          +            } catch (ConcurrentModificationException e) {
          +                StringBuilder sb = getMessageTextForWriting();
          +                sb.append(getClass().getSimpleName());
          +                sb.append(": ");
          +                sb.append(e.getClass().getName());
          +                sb.append(" in setting a ");
          +                sb.append(msg.getClass().getSimpleName());
          +                sb.append("; format: ");
          +                sb.append(msg.getFormat());
          +                StatusLogger.getLogger().warn(sb.toString(), e);
                       }
                   } else {
                       // if the Message instance is reused, there is no point in freezing its message here
          

          ?

          Show
          garydgregory Gary Gregory added a comment - Like so: diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/impl/MutableLogEvent.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/impl/MutableLogEvent.java index 56867b4..9f8a8b8 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/impl/MutableLogEvent.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/impl/MutableLogEvent.java @@ -19,6 +19,7 @@ import java.io.InvalidObjectException; import java.io.ObjectInputStream; import java.util.Arrays; +import java.util.ConcurrentModificationException; import java.util.Map; import org.apache.logging.log4j.Level; @@ -32,6 +33,7 @@ import org.apache.logging.log4j.message.ParameterizedMessage; import org.apache.logging.log4j.message.ReusableMessage; import org.apache.logging.log4j.message.SimpleMessage; +import org.apache.logging.log4j.status.StatusLogger; import org.apache.logging.log4j.util.StackLocatorUtil; import org.apache.logging.log4j.util.StringBuilders; import org.apache.logging.log4j.util.StringMap; @@ -207,11 +209,23 @@ public void setMessage(final Message msg) { if (msg instanceof ReusableMessage) { - final ReusableMessage reusable = (ReusableMessage) msg; - reusable.formatTo(getMessageTextForWriting()); - if (parameters != null) { - parameters = reusable.swapParameters(parameters); - parameterCount = reusable.getParameterCount(); + try { + final ReusableMessage reusable = (ReusableMessage) msg; + reusable.formatTo(getMessageTextForWriting()); + if (parameters != null) { + parameters = reusable.swapParameters(parameters); + parameterCount = reusable.getParameterCount(); + } + } catch (ConcurrentModificationException e) { + StringBuilder sb = getMessageTextForWriting(); + sb.append(getClass().getSimpleName()); + sb.append(": "); + sb.append(e.getClass().getName()); + sb.append(" in setting a "); + sb.append(msg.getClass().getSimpleName()); + sb.append("; format: "); + sb.append(msg.getFormat()); + StatusLogger.getLogger().warn(sb.toString(), e); } } else { // if the Message instance is reused, there is no point in freezing its message here ?
          Hide
          ralph.goers@dslextreme.com Ralph Goers added a comment -

          yeah, that looks ok.

          Show
          ralph.goers@dslextreme.com Ralph Goers added a comment - yeah, that looks ok.
          Hide
          jira-bot ASF subversion and git services added a comment -

          Commit 6f6d95d3fcf2e17e66eb7763b6122adbe018f8be in logging-log4j2's branch refs/heads/master from Gary Gregory
          [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=6f6d95d ]

          LOG4J2-1990 ConcurrentModificationException logging a parameter of
          type Map.

          Show
          jira-bot ASF subversion and git services added a comment - Commit 6f6d95d3fcf2e17e66eb7763b6122adbe018f8be in logging-log4j2's branch refs/heads/master from Gary Gregory [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=6f6d95d ] LOG4J2-1990 ConcurrentModificationException logging a parameter of type Map.
          Hide
          garydgregory Gary Gregory added a comment -

          In git master, please verify and close. See https://repository.apache.org/content/repositories/snapshots/

          Show
          garydgregory Gary Gregory added a comment - In git master, please verify and close. See https://repository.apache.org/content/repositories/snapshots/
          Hide
          remkop@yahoo.com Remko Popma added a comment -

          Sorry I'm late with this feedback, but why is catching the ConcurrentModificationException a good idea?

          Before this change, if an application had a concurrency bug they would find out by this exception occurring in their application. Now Log4j2 hides the problem. If status logging is disabled it is hidden completely, if it is enabled users will only be able to find out if they monitor the console.

          We agreed that this problem was caused by a bug in the application. Log4j2 should not try to hide such bugs just because they happen to manifest while Log4j2 is doing work.

          Show
          remkop@yahoo.com Remko Popma added a comment - Sorry I'm late with this feedback, but why is catching the ConcurrentModificationException a good idea? Before this change, if an application had a concurrency bug they would find out by this exception occurring in their application. Now Log4j2 hides the problem. If status logging is disabled it is hidden completely, if it is enabled users will only be able to find out if they monitor the console. We agreed that this problem was caused by a bug in the application. Log4j2 should not try to hide such bugs just because they happen to manifest while Log4j2 is doing work.
          Hide
          garydgregory Gary Gregory added a comment -

          Here is a real life scenario I ran into two week ago that parallels this issue: I have an app that plugins into a larger framework. One of part of the app in invoked from main and the command line so it is "my" app but I still have to plugin a whole bunch of complex code into this framework. Another part of the app is run from the framework's command line with some other plugins I provide through a configuration file. In my app guts, at some point, I must traverse the Properties from java.util.System.getProperties(). Sometimes I get a {{ConcurrentModificationException}, sometimes not. Why? Because somewhere, someone (not my app) is fiddling with system properties, adding and/or removing entries, don't know, don't care. I can't do anything about it but I do not want to blow up so I have to do something.

          The general problem is that some code in a library or in an app is given a Map that it did not create and does not manage. Who owns the bug of not making this a ConcurrentMap? Doesn't matter. The point is that we need to not blow up randomly IMO.

          Show
          garydgregory Gary Gregory added a comment - Here is a real life scenario I ran into two week ago that parallels this issue: I have an app that plugins into a larger framework. One of part of the app in invoked from main and the command line so it is "my" app but I still have to plugin a whole bunch of complex code into this framework. Another part of the app is run from the framework's command line with some other plugins I provide through a configuration file. In my app guts, at some point, I must traverse the Properties from java.util.System.getProperties() . Sometimes I get a {{ConcurrentModificationException}, sometimes not. Why? Because somewhere, someone (not my app) is fiddling with system properties, adding and/or removing entries, don't know, don't care. I can't do anything about it but I do not want to blow up so I have to do something . The general problem is that some code in a library or in an app is given a Map that it did not create and does not manage. Who owns the bug of not making this a ConcurrentMap ? Doesn't matter. The point is that we need to not blow up randomly IMO.
          Hide
          garydgregory Gary Gregory added a comment -

          Oh, yes, and I agree if you think this ugly

          Show
          garydgregory Gary Gregory added a comment - Oh, yes, and I agree if you think this ugly
          Hide
          ralph.goers@dslextreme.com Ralph Goers added a comment -

          In my opinion Log4J should never be the cause of an application failure. We use the AppenderControl to catch exceptions from appenders and hide them from the application unless configured not to do that. In this case the exception can happen much earlier in the event processing. And we don't have a way to provide the user with a choice on whether they want to see it or not.

          Show
          ralph.goers@dslextreme.com Ralph Goers added a comment - In my opinion Log4J should never be the cause of an application failure. We use the AppenderControl to catch exceptions from appenders and hide them from the application unless configured not to do that. In this case the exception can happen much earlier in the event processing. And we don't have a way to provide the user with a choice on whether they want to see it or not.
          Hide
          garydgregory Gary Gregory added a comment -

          Do we want an "ignoreExceptions" option at the <Configuration> level?

          Show
          garydgregory Gary Gregory added a comment - Do we want an "ignoreExceptions" option at the <Configuration> level?
          Hide
          remkop@yahoo.com Remko Popma added a comment - - edited

          Gary, you say you don't care, but you have no choice if you don't want to get hit with a ConcurrentModificationException. If you know that your application has this issue, you can only avoid this issue by iterating over the system properties in a try-catch loop.

          My argument is that working around application bugs is the responsibility of the application. If the application wants to log a map that may be modified elsewhere they should copy it in a try-catch block and log the copy. I agree if you think this is inconvenient. However, the bug means the map is suspect and one can't just pass it on to external libraries and hope for the best.

          Ralph, I don't think this classifies as Log4j2 causing application failure. The bug could manifest anywhere, it just happened to show up while Log4j2 was iterating over the map instead of application code doing the iterating. Would we be doing our users a service by hiding this bug?

          Show
          remkop@yahoo.com Remko Popma added a comment - - edited Gary, you say you don't care, but you have no choice if you don't want to get hit with a ConcurrentModificationException . If you know that your application has this issue, you can only avoid this issue by iterating over the system properties in a try-catch loop. My argument is that working around application bugs is the responsibility of the application. If the application wants to log a map that may be modified elsewhere they should copy it in a try-catch block and log the copy. I agree if you think this is inconvenient. However, the bug means the map is suspect and one can't just pass it on to external libraries and hope for the best. Ralph, I don't think this classifies as Log4j2 causing application failure. The bug could manifest anywhere, it just happened to show up while Log4j2 was iterating over the map instead of application code doing the iterating. Would we be doing our users a service by hiding this bug?
          Hide
          remkop@yahoo.com Remko Popma added a comment -

          I believe this is different from the "normal" error handling we do in AppenderControl. There we handle (and propagate when requested) exceptions that were caused by the logging itself, like disk full, socket disconnected, etc.

          This to me is more similar to trying to log an object that throws a NullPointerException in its toString method.

          Show
          remkop@yahoo.com Remko Popma added a comment - I believe this is different from the "normal" error handling we do in AppenderControl . There we handle (and propagate when requested) exceptions that were caused by the logging itself, like disk full, socket disconnected, etc. This to me is more similar to trying to log an object that throws a NullPointerException in its toString method.
          Hide
          jvz Matt Sicker added a comment -

          System properties are stored in a Properties instance which is a Hashtable which synchronizes on this. Thus, just synchronize on it to iterate. No other thread can modify it then, naturally.

          Show
          jvz Matt Sicker added a comment - System properties are stored in a Properties instance which is a Hashtable which synchronizes on this . Thus, just synchronize on it to iterate. No other thread can modify it then, naturally.
          Hide
          garydgregory Gary Gregory added a comment -

          That's what I did in my app but that will not work generically on all Map
          and Collection instances for us in Log4j.

          Show
          garydgregory Gary Gregory added a comment - That's what I did in my app but that will not work generically on all Map and Collection instances for us in Log4j.
          Hide
          jvz Matt Sicker added a comment -

          Similar to your idea of checking for ConcurrentMap and not needing synchronisation, you could check for instances of Hashtable and know it's fully synchronised already. Outside of that, it's hard to say. I'm a big fan of using immutable data structures everywhere possible due to bugs like this.

          Show
          jvz Matt Sicker added a comment - Similar to your idea of checking for ConcurrentMap and not needing synchronisation, you could check for instances of Hashtable and know it's fully synchronised already. Outside of that, it's hard to say. I'm a big fan of using immutable data structures everywhere possible due to bugs like this.
          Hide
          garydgregory Gary Gregory added a comment -

          What would that look like as a patch? Right we just catch CME.

          Show
          garydgregory Gary Gregory added a comment - What would that look like as a patch? Right we just catch CME.
          Hide
          jvz Matt Sicker added a comment -

          In ParameterFormatter: https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;a=blob;f=log4j-api/src/main/java/org/apache/logging/log4j/message/ParameterFormatter.java;h=79c447a89f34885f21de36581672dd0d9ced9381;hb=HEAD#l569

          appendMap and appendCollection can be enhanced for synchronisation when supportable (e.g., instanceof Hashtable, Vector, etc.)

          Show
          jvz Matt Sicker added a comment - In ParameterFormatter: https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;a=blob;f=log4j-api/src/main/java/org/apache/logging/log4j/message/ParameterFormatter.java;h=79c447a89f34885f21de36581672dd0d9ced9381;hb=HEAD#l569 appendMap and appendCollection can be enhanced for synchronisation when supportable (e.g., instanceof Hashtable, Vector, etc.)
          Hide
          garydgregory Gary Gregory added a comment -

          You mean like "if map is Hashtable then sync(map)"? Why not always sync on the map no matter what kind it is? Possible deadlocks?

          Show
          garydgregory Gary Gregory added a comment - You mean like "if map is Hashtable then sync(map)"? Why not always sync on the map no matter what kind it is? Possible deadlocks?
          Hide
          jvz Matt Sicker added a comment -

          Unless the class adds synchronized (or synchronized(this)) to its mutation methods, synchronising on the instance won't prevent anything. Then there's the java.util.concurrent classes which tend to use internal locks or other tricks (see LinkedTransferQueue for example) to avoid coarse locking like that which means locking on the instance, again, is pointless.

          Show
          jvz Matt Sicker added a comment - Unless the class adds synchronized (or synchronized(this) ) to its mutation methods, synchronising on the instance won't prevent anything. Then there's the java.util.concurrent classes which tend to use internal locks or other tricks (see LinkedTransferQueue for example) to avoid coarse locking like that which means locking on the instance, again, is pointless.
          Hide
          remkop@yahoo.com Remko Popma added a comment -

          Guys, what we're talking about is like trying to protect against applications logging objects that deliberately throw a RuntimeException when their toString method is called. We should not do it.

          We should undo the try-catch(ConcurrentModificationException) in MutableLogEvent.

          Show
          remkop@yahoo.com Remko Popma added a comment - Guys, what we're talking about is like trying to protect against applications logging objects that deliberately throw a RuntimeException when their toString method is called. We should not do it. We should undo the try-catch(ConcurrentModificationException) in MutableLogEvent.
          Hide
          jvz Matt Sicker added a comment -

          That's a good point. Perhaps catch, log some sort of warning, and rethrow? Could help in debugging.

          Show
          jvz Matt Sicker added a comment - That's a good point. Perhaps catch, log some sort of warning, and rethrow? Could help in debugging.
          Hide
          ralph.goers@dslextreme.com Ralph Goers added a comment - - edited

          Remko, my position is that if an application callers a logger method it should never get an exception from inside that method. Performing logging is not something that should ever cause an application to fail. So even though the application passed us something bad we shouldn't throw up because of it. We need to do something that makes the application aware there is a problem and then swallow the exception - unless we add a switch that says the exception should be propagated to the caller.

          In reality what we should be doing instead of modifying MutableLogEvent is modify the logMessageSafely method in AbstractLogger. It already has a try block. We simply should be catching exception and logging the exception to the StatusLogger when it happens. We could easily add an option to the Configuration element as Gary suggested that would allow the exception to be propagated if it is set.

          Show
          ralph.goers@dslextreme.com Ralph Goers added a comment - - edited Remko, my position is that if an application callers a logger method it should never get an exception from inside that method. Performing logging is not something that should ever cause an application to fail. So even though the application passed us something bad we shouldn't throw up because of it. We need to do something that makes the application aware there is a problem and then swallow the exception - unless we add a switch that says the exception should be propagated to the caller. In reality what we should be doing instead of modifying MutableLogEvent is modify the logMessageSafely method in AbstractLogger. It already has a try block. We simply should be catching exception and logging the exception to the StatusLogger when it happens. We could easily add an option to the Configuration element as Gary suggested that would allow the exception to be propagated if it is set.
          Hide
          garydgregory Gary Gregory added a comment -

          I'm with Ralph on this one.

          Show
          garydgregory Gary Gregory added a comment - I'm with Ralph on this one.
          Hide
          remkop@yahoo.com Remko Popma added a comment -

          If we do this we should do it for all runtime exceptions that may be thrown from toString, not just ConcurrentModificationException.

          Show
          remkop@yahoo.com Remko Popma added a comment - If we do this we should do it for all runtime exceptions that may be thrown from toString, not just ConcurrentModificationException.
          Hide
          ralph.goers@dslextreme.com Ralph Goers added a comment -

          Yes, it should catch Exception.

          Show
          ralph.goers@dslextreme.com Ralph Goers added a comment - Yes, it should catch Exception.
          Hide
          jvz Matt Sicker added a comment -

          All sounds good to me.

          Show
          jvz Matt Sicker added a comment - All sounds good to me.
          Hide
          jira-bot ASF subversion and git services added a comment -

          Commit e07cc14b10315088c47fbfd9a6049cf9861d9c27 in logging-log4j2's branch refs/heads/master from Gary Gregory
          [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=e07cc14 ]

          LOG4J2-1990 ConcurrentModificationException logging a parameter of
          type Map. Catch Exception instead of ConcurrentModificationException as
          suggested by Ralph.

          Show
          jira-bot ASF subversion and git services added a comment - Commit e07cc14b10315088c47fbfd9a6049cf9861d9c27 in logging-log4j2's branch refs/heads/master from Gary Gregory [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=e07cc14 ] LOG4J2-1990 ConcurrentModificationException logging a parameter of type Map. Catch Exception instead of ConcurrentModificationException as suggested by Ralph.
          Hide
          remkop@yahoo.com Remko Popma added a comment -

          Reopening for moving the error handling to a different place:

          what we should be doing instead of modifying MutableLogEvent is modify the logMessageSafely method in AbstractLogger.

          Show
          remkop@yahoo.com Remko Popma added a comment - Reopening for moving the error handling to a different place: what we should be doing instead of modifying MutableLogEvent is modify the logMessageSafely method in AbstractLogger.
          Hide
          jira-bot ASF subversion and git services added a comment -

          Commit 3c3a9e4a1d8d53a4fd2dfa302633380eaa08c6da in logging-log4j2's branch refs/heads/master from Gary Gregory
          [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=3c3a9e4 ]

          LOG4J2-1990 ConcurrentModificationException logging a parameter of
          type Map. Another go at it based on Ralph's suggestion.

          Show
          jira-bot ASF subversion and git services added a comment - Commit 3c3a9e4a1d8d53a4fd2dfa302633380eaa08c6da in logging-log4j2's branch refs/heads/master from Gary Gregory [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=3c3a9e4 ] LOG4J2-1990 ConcurrentModificationException logging a parameter of type Map. Another go at it based on Ralph's suggestion.
          Hide
          garydgregory Gary Gregory added a comment -

          Done in git master.

          Show
          garydgregory Gary Gregory added a comment - Done in git master.
          Hide
          jira-bot ASF subversion and git services added a comment -

          Commit 68de0ff88936cc2e8f77b3a67e6c495c390ea7be in logging-log4j2's branch refs/heads/master from Gary Gregory
          [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=68de0ff ]

          LOG4J2-1990 ConcurrentModificationException logging a parameter of
          type Map. Another go at it based on Ralph's suggestion.

          Show
          jira-bot ASF subversion and git services added a comment - Commit 68de0ff88936cc2e8f77b3a67e6c495c390ea7be in logging-log4j2's branch refs/heads/master from Gary Gregory [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=68de0ff ] LOG4J2-1990 ConcurrentModificationException logging a parameter of type Map. Another go at it based on Ralph's suggestion.
          Hide
          remkop@yahoo.com Remko Popma added a comment -

          Thanks for the quick work, Gary! You're on a roll!

          Show
          remkop@yahoo.com Remko Popma added a comment - Thanks for the quick work, Gary! You're on a roll!
          Hide
          jira-bot ASF subversion and git services added a comment -

          Commit 218117a910995918b75ba718076e4b08862245a9 in logging-log4j2's branch refs/heads/master from rpopma
          [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=218117a ]

          LOG4J2-1990 refactor #logMessageSafely method to stay within 35 byte MaxInlineSize threshold; add TODO for Configuration setting to propagate exceptions back to caller

          Show
          jira-bot ASF subversion and git services added a comment - Commit 218117a910995918b75ba718076e4b08862245a9 in logging-log4j2's branch refs/heads/master from rpopma [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=218117a ] LOG4J2-1990 refactor #logMessageSafely method to stay within 35 byte MaxInlineSize threshold; add TODO for Configuration setting to propagate exceptions back to caller
          Hide
          jira-bot ASF subversion and git services added a comment -

          Commit 8da3df59a5fd4cfb204ee975a93113614b1758eb in logging-log4j2's branch refs/heads/master from Gary Gregory
          [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=8da3df5 ]

          LOG4J2-1990 ConcurrentModificationException logging a parameter of
          type Map. Clearer error message.

          Show
          jira-bot ASF subversion and git services added a comment - Commit 8da3df59a5fd4cfb204ee975a93113614b1758eb in logging-log4j2's branch refs/heads/master from Gary Gregory [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=8da3df5 ] LOG4J2-1990 ConcurrentModificationException logging a parameter of type Map. Clearer error message.
          Hide
          jira-bot ASF subversion and git services added a comment -

          Commit 005139d6a2a5d6a75a6dde557a7d7693414114db in logging-log4j2's branch refs/heads/master from Gary Gregory
          [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=005139d ]

          LOG4J2-1990 ConcurrentModificationException logging a parameter of
          type Map. Clearer error message. Update to allow
          AppenderLoggingException to percolate to the caller when requested with
          the ignoreExceptions="false" setting.

          Show
          jira-bot ASF subversion and git services added a comment - Commit 005139d6a2a5d6a75a6dde557a7d7693414114db in logging-log4j2's branch refs/heads/master from Gary Gregory [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=005139d ] LOG4J2-1990 ConcurrentModificationException logging a parameter of type Map. Clearer error message. Update to allow AppenderLoggingException to percolate to the caller when requested with the ignoreExceptions="false" setting.
          Hide
          jira-bot ASF subversion and git services added a comment -

          Commit bfdb2f533ca569606dd8d62fdd15b0f706404ac6 in logging-log4j2's branch refs/heads/master from Gary Gregory
          [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=bfdb2f5 ]

          Revert "LOG4J2-1990 ConcurrentModificationException logging a parameter of type Map. Another go at it based on Ralph's suggestion."

          This reverts commit 68de0ff88936cc2e8f77b3a67e6c495c390ea7be.

          Show
          jira-bot ASF subversion and git services added a comment - Commit bfdb2f533ca569606dd8d62fdd15b0f706404ac6 in logging-log4j2's branch refs/heads/master from Gary Gregory [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=bfdb2f5 ] Revert " LOG4J2-1990 ConcurrentModificationException logging a parameter of type Map. Another go at it based on Ralph's suggestion." This reverts commit 68de0ff88936cc2e8f77b3a67e6c495c390ea7be.
          Hide
          jira-bot ASF subversion and git services added a comment -

          Commit 7aa2a223d175d055d31e4e4c4cce3c6519b42d70 in logging-log4j2's branch refs/heads/master from rpopma
          [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=7aa2a22 ]

          LOG4J2-1990 move exception handling out of hot code path

          Show
          jira-bot ASF subversion and git services added a comment - Commit 7aa2a223d175d055d31e4e4c4cce3c6519b42d70 in logging-log4j2's branch refs/heads/master from rpopma [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=7aa2a22 ] LOG4J2-1990 move exception handling out of hot code path
          Hide
          remkop@yahoo.com Remko Popma added a comment -

          The remaining problem is "where does the configuration to control this behavior live?"

          I am still very hesitant about hiding bugs in the application (exceptions being thrown from the toString method - always a bug). So even if we decide to make this the default (should we, really?) there needs to be a way to turn this off.

          But where? All this (Message formatting and calling toString on parameter objects) lives in the log4j-api module, so there is no Configuration object...

          Show
          remkop@yahoo.com Remko Popma added a comment - The remaining problem is "where does the configuration to control this behavior live?" I am still very hesitant about hiding bugs in the application (exceptions being thrown from the toString method - always a bug). So even if we decide to make this the default (should we, really?) there needs to be a way to turn this off. But where? All this (Message formatting and calling toString on parameter objects) lives in the log4j-api module, so there is no Configuration object...
          Hide
          jvz Matt Sicker added a comment -

          The only configuration available (even with my unmerged enhancements) in log4j-api is via properties be them system or a component properties file. In that regard, make a property like log4j2.ignoreExceptionsInToString or something like that.

          Show
          jvz Matt Sicker added a comment - The only configuration available (even with my unmerged enhancements) in log4j-api is via properties be them system or a component properties file. In that regard, make a property like log4j2.ignoreExceptionsInToString or something like that.
          Hide
          garydgregory Gary Gregory added a comment -

          I think log4j2.ignoreExceptions might be more consistent since we have settings like that already.

          Show
          garydgregory Gary Gregory added a comment - I think log4j2.ignoreExceptions might be more consistent since we have settings like that already.
          Hide
          jvz Matt Sicker added a comment -

          That just seems like too vague of a setting, though if it's supposed to be a global sort of ignore exceptions, then it would make sense.

          Show
          jvz Matt Sicker added a comment - That just seems like too vague of a setting, though if it's supposed to be a global sort of ignore exceptions, then it would make sense.
          Hide
          ralph.goers@dslextreme.com Ralph Goers added a comment - - edited

          I have a use case with Audit logging where I only want a specific logger to percolate exceptions, so using a system property isn't desirable. It would need to be a method on the Logger. I am glad that Gary thought of throwing a specific Exception in the AppenderControl as that would have been a big problem.

          I would be ok if in core you could configure a setting on a logger or globally to percolate exceptions and that caused the method on the loggers to be called when they are created.

          Show
          ralph.goers@dslextreme.com Ralph Goers added a comment - - edited I have a use case with Audit logging where I only want a specific logger to percolate exceptions, so using a system property isn't desirable. It would need to be a method on the Logger. I am glad that Gary thought of throwing a specific Exception in the AppenderControl as that would have been a big problem. I would be ok if in core you could configure a setting on a logger or globally to percolate exceptions and that caused the method on the loggers to be called when they are created.

            People

            • Assignee:
              Unassigned
              Reporter:
              pmouawad Philippe Mouawad
            • Votes:
              0 Vote for this issue
              Watchers:
              6 Start watching this issue

              Dates

              • Created:
                Updated:

                Development