[ 
https://issues.apache.org/jira/browse/LOG4J2-1583?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
 ]

Remko Popma updated LOG4J2-1583:
--------------------------------
    Comment: was deleted

(was: NOTES TO SELF. PLEASE IGNORE. WILL DELETE SOON.

{code}
Index: 
log4j-core/src/main/java/org/apache/logging/log4j/core/config/LoggerConfig.java
IDEA additional info:
Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP
<+>UTF-8
===================================================================
--- 
log4j-core/src/main/java/org/apache/logging/log4j/core/config/LoggerConfig.java 
    (revision )
+++ 
log4j-core/src/main/java/org/apache/logging/log4j/core/config/LoggerConfig.java 
    (revision )
@@ -396,7 +396,12 @@
                 }
             }
         }
-        log(logEventFactory.createEvent(loggerName, marker, fqcn, level, data, 
props, t));
+        final LogEvent logEvent = logEventFactory.createEvent(loggerName, 
marker, fqcn, level, data, props, t);
+        try {
+            log(logEvent);
+        } finally {
+            ReusableLogEventFactory.release(logEvent);
+        }
     }
 
     /**

Index: 
log4j-core/src/main/java/org/apache/logging/log4j/core/impl/ReusableLogEventFactory.java
IDEA additional info:
Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP
<+>UTF-8
===================================================================
--- 
log4j-core/src/main/java/org/apache/logging/log4j/core/impl/ReusableLogEventFactory.java
    (revision )
+++ 
log4j-core/src/main/java/org/apache/logging/log4j/core/impl/ReusableLogEventFactory.java
    (revision )
@@ -58,15 +58,19 @@
                                 final String fqcn, final Level level, final 
Message message,
                                 final List<Property> properties, final 
Throwable t) {
         MutableLogEvent result = mutableLogEventThreadLocal.get();
-        if (result == null) {
+        if (result == null || result.reserved) {
+            final boolean initThreadLocal = result == null;
             result = new MutableLogEvent();
 
             // usually no need to re-initialize thread-specific fields since 
the event is stored in a ThreadLocal
             result.setThreadId(Thread.currentThread().getId());
             result.setThreadName(Thread.currentThread().getName()); // 
Thread.getName() allocates Objects on each call
             result.setThreadPriority(Thread.currentThread().getPriority());
+            if (initThreadLocal) {
-            mutableLogEventThreadLocal.set(result);
-        }
+                mutableLogEventThreadLocal.set(result);
+            }
+        }
+        result.reserved = true;
         result.clear(); // ensure any previously cached values (thrownProxy, 
source, etc.) are cleared
 
         result.setLoggerName(loggerName);
@@ -87,5 +91,11 @@
             result.setThreadPriority(Thread.currentThread().getPriority());
         }
         return result;
+    }
+
+    public static void release(final LogEvent logEvent) {
+        if (logEvent instanceof MutableLogEvent) {
+            ((MutableLogEvent) logEvent).reserved = false;
+        }
     }
 }

Index: log4j-api/src/main/java/org/apache/logging/log4j/spi/AbstractLogger.java
IDEA additional info:
Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP
<+>UTF-8
===================================================================
--- log4j-api/src/main/java/org/apache/logging/log4j/spi/AbstractLogger.java    
(revision )
+++ log4j-api/src/main/java/org/apache/logging/log4j/spi/AbstractLogger.java    
(revision )
@@ -169,14 +169,14 @@
      */
     protected void catching(final String fqcn, final Level level, final 
Throwable t) {
         if (isEnabled(level, CATCHING_MARKER, (Object) null, null)) {
-            logMessage(fqcn, level, CATCHING_MARKER, catchingMsg(t), t);
+            logMessageSafely(fqcn, level, CATCHING_MARKER, catchingMsg(t), t);
         }
     }
 
     @Override
     public void catching(final Throwable t) {
         if (isEnabled(Level.ERROR, CATCHING_MARKER, (Object) null, null)) {
-            logMessage(FQCN, Level.ERROR, CATCHING_MARKER, catchingMsg(t), t);
+            logMessageSafely(FQCN, Level.ERROR, CATCHING_MARKER, 
catchingMsg(t), t);
         }
     }
 
@@ -501,7 +501,7 @@
     protected EntryMessage enter(final String fqcn, final String format, final 
Supplier<?>... paramSuppliers) {
         EntryMessage entryMsg = null;
         if (isEnabled(Level.TRACE, ENTRY_MARKER, (Object) null, null)) {
-            logMessage(fqcn, Level.TRACE, ENTRY_MARKER, entryMsg = 
entryMsg(format, paramSuppliers), null);
+            logMessageSafely(fqcn, Level.TRACE, ENTRY_MARKER, entryMsg = 
entryMsg(format, paramSuppliers), null);
         }
         return entryMsg;
     }
@@ -517,7 +517,7 @@
     protected EntryMessage enter(final String fqcn, final String format, final 
MessageSupplier... paramSuppliers) {
         EntryMessage entryMsg = null;
         if (isEnabled(Level.TRACE, ENTRY_MARKER, (Object) null, null)) {
-            logMessage(fqcn, Level.TRACE, ENTRY_MARKER, entryMsg = 
entryMsg(format, paramSuppliers), null);
+            logMessageSafely(fqcn, Level.TRACE, ENTRY_MARKER, entryMsg = 
entryMsg(format, paramSuppliers), null);
         }
         return entryMsg;
     }
@@ -532,7 +532,7 @@
     protected EntryMessage enter(final String fqcn, final String format, final 
Object... params) {
         EntryMessage entryMsg = null;
         if (isEnabled(Level.TRACE, ENTRY_MARKER, (Object) null, null)) {
-            logMessage(fqcn, Level.TRACE, ENTRY_MARKER, entryMsg = 
entryMsg(format, params), null);
+            logMessageSafely(fqcn, Level.TRACE, ENTRY_MARKER, entryMsg = 
entryMsg(format, params), null);
         }
         return entryMsg;
     }
@@ -547,7 +547,7 @@
     protected EntryMessage enter(final String fqcn, final MessageSupplier 
msgSupplier) {
         EntryMessage message = null;
         if (isEnabled(Level.TRACE, ENTRY_MARKER, (Object) null, null)) {
-            logMessage(fqcn, Level.TRACE, ENTRY_MARKER, message = 
flowMessageFactory.newEntryMessage(
+            logMessageSafely(fqcn, Level.TRACE, ENTRY_MARKER, message = 
flowMessageFactory.newEntryMessage(
                     msgSupplier.get()), null);
         }
         return message;
@@ -565,7 +565,7 @@
     protected EntryMessage enter(final String fqcn, final Message message) {
         EntryMessage flowMessage = null;
         if (isEnabled(Level.TRACE, ENTRY_MARKER, (Object) null, null)) {
-            logMessage(fqcn, Level.TRACE, ENTRY_MARKER, flowMessage = 
flowMessageFactory.newEntryMessage(message),
+            logMessageSafely(fqcn, Level.TRACE, ENTRY_MARKER, flowMessage = 
flowMessageFactory.newEntryMessage(message),
                     null);
         }
         return flowMessage;
@@ -590,9 +590,9 @@
     protected void entry(final String fqcn, final Object... params) {
         if (isEnabled(Level.TRACE, ENTRY_MARKER, (Object) null, null)) {
             if (params == null) {
-                logMessage(fqcn, Level.TRACE, ENTRY_MARKER, entryMsg(null, 
(Supplier<?>[]) null), null);
+                logMessageSafely(fqcn, Level.TRACE, ENTRY_MARKER, 
entryMsg(null, (Supplier<?>[]) null), null);
             } else {
-                logMessage(fqcn, Level.TRACE, ENTRY_MARKER, entryMsg(null, 
params), null);
+                logMessageSafely(fqcn, Level.TRACE, ENTRY_MARKER, 
entryMsg(null, params), null);
             }
         }
     }
@@ -1810,7 +1810,7 @@
     public void logIfEnabled(final String fqcn, final Level level, final 
Marker marker, final Message msg,
             final Throwable t) {
         if (isEnabled(level, marker, msg, t)) {
-            logMessage(fqcn, level, marker, msg, t);
+            logMessageSafely(fqcn, level, marker, msg, t);
         }
     }
 
@@ -1963,117 +1963,117 @@
 
     protected void logMessage(final String fqcn, final Level level, final 
Marker marker, final CharSequence message,
             final Throwable t) {
-        logMessage(fqcn, level, marker, messageFactory.newMessage(message), t);
+        logMessageSafely(fqcn, level, marker, 
messageFactory.newMessage(message), t);
     }
 
     protected void logMessage(final String fqcn, final Level level, final 
Marker marker, final Object message,
             final Throwable t) {
-        logMessage(fqcn, level, marker, messageFactory.newMessage(message), t);
+        logMessageSafely(fqcn, level, marker, 
messageFactory.newMessage(message), t);
     }
 
     protected void logMessage(final String fqcn, final Level level, final 
Marker marker,
             final MessageSupplier msgSupplier, final Throwable t) {
         final Message message = LambdaUtil.get(msgSupplier);
-        logMessage(fqcn, level, marker, message, t);
+        logMessageSafely(fqcn, level, marker, message, t);
     }
 
     protected void logMessage(final String fqcn, final Level level, final 
Marker marker, final Supplier<?> msgSupplier,
             final Throwable t) {
         final Message message = LambdaUtil.getMessage(msgSupplier, 
messageFactory);
-        logMessage(fqcn, level, marker, message, t);
+        logMessageSafely(fqcn, level, marker, message, t);
     }
 
     protected void logMessage(final String fqcn, final Level level, final 
Marker marker, final String message,
             final Throwable t) {
-        logMessage(fqcn, level, marker, messageFactory.newMessage(message), t);
+        logMessageSafely(fqcn, level, marker, 
messageFactory.newMessage(message), t);
     }
 
     protected void logMessage(final String fqcn, final Level level, final 
Marker marker, final String message) {
         final Message msg = messageFactory.newMessage(message);
-        logMessage(fqcn, level, marker, msg, msg.getThrowable());
+        logMessageSafely(fqcn, level, marker, msg, msg.getThrowable());
     }
 
     protected void logMessage(final String fqcn, final Level level, final 
Marker marker, final String message,
             final Object... params) {
         final Message msg = messageFactory.newMessage(message, params);
-        logMessage(fqcn, level, marker, msg, msg.getThrowable());
+        logMessageSafely(fqcn, level, marker, msg, msg.getThrowable());
     }
 
     protected void logMessage(final String fqcn, final Level level, final 
Marker marker, final String message,
             final Object p0) {
         final Message msg = messageFactory.newMessage(message, p0);
-        logMessage(fqcn, level, marker, msg, msg.getThrowable());
+        logMessageSafely(fqcn, level, marker, msg, msg.getThrowable());
     }
 
     protected void logMessage(final String fqcn, final Level level, final 
Marker marker, final String message,
             final Object p0, final Object p1) {
         final Message msg = messageFactory.newMessage(message, p0, p1);
-        logMessage(fqcn, level, marker, msg, msg.getThrowable());
+        logMessageSafely(fqcn, level, marker, msg, msg.getThrowable());
     }
 
     protected void logMessage(final String fqcn, final Level level, final 
Marker marker, final String message,
             final Object p0, final Object p1, final Object p2) {
         final Message msg = messageFactory.newMessage(message, p0, p1, p2);
-        logMessage(fqcn, level, marker, msg, msg.getThrowable());
+        logMessageSafely(fqcn, level, marker, msg, msg.getThrowable());
     }
 
     protected void logMessage(final String fqcn, final Level level, final 
Marker marker, final String message,
             final Object p0, final Object p1, final Object p2, final Object 
p3) {
         final Message msg = messageFactory.newMessage(message, p0, p1, p2, p3);
-        logMessage(fqcn, level, marker, msg, msg.getThrowable());
+        logMessageSafely(fqcn, level, marker, msg, msg.getThrowable());
     }
 
     protected void logMessage(final String fqcn, final Level level, final 
Marker marker, final String message,
             final Object p0, final Object p1, final Object p2, final Object 
p3, final Object p4) {
         final Message msg = messageFactory.newMessage(message, p0, p1, p2, p3, 
p4);
-        logMessage(fqcn, level, marker, msg, msg.getThrowable());
+        logMessageSafely(fqcn, level, marker, msg, msg.getThrowable());
     }
 
     protected void logMessage(final String fqcn, final Level level, final 
Marker marker, final String message,
             final Object p0, final Object p1, final Object p2, final Object 
p3, final Object p4, final Object p5) {
         final Message msg = messageFactory.newMessage(message, p0, p1, p2, p3, 
p4, p5);
-        logMessage(fqcn, level, marker, msg, msg.getThrowable());
+        logMessageSafely(fqcn, level, marker, msg, msg.getThrowable());
     }
 
     protected void logMessage(final String fqcn, final Level level, final 
Marker marker, final String message,
             final Object p0, final Object p1, final Object p2, final Object 
p3, final Object p4, final Object p5,
             final Object p6) {
         final Message msg = messageFactory.newMessage(message, p0, p1, p2, p3, 
p4, p5, p6);
-        logMessage(fqcn, level, marker, msg, msg.getThrowable());
+        logMessageSafely(fqcn, level, marker, msg, msg.getThrowable());
     }
 
     protected void logMessage(final String fqcn, final Level level, final 
Marker marker, final String message,
             final Object p0, final Object p1, final Object p2, final Object 
p3, final Object p4, final Object p5,
             final Object p6, final Object p7) {
         final Message msg = messageFactory.newMessage(message, p0, p1, p2, p3, 
p4, p5, p6, p7);
-        logMessage(fqcn, level, marker, msg, msg.getThrowable());
+        logMessageSafely(fqcn, level, marker, msg, msg.getThrowable());
     }
 
     protected void logMessage(final String fqcn, final Level level, final 
Marker marker, final String message,
             final Object p0, final Object p1, final Object p2, final Object 
p3, final Object p4, final Object p5,
             final Object p6, final Object p7, final Object p8) {
         final Message msg = messageFactory.newMessage(message, p0, p1, p2, p3, 
p4, p5, p6, p7, p8);
-        logMessage(fqcn, level, marker, msg, msg.getThrowable());
+        logMessageSafely(fqcn, level, marker, msg, msg.getThrowable());
     }
 
     protected void logMessage(final String fqcn, final Level level, final 
Marker marker, final String message,
             final Object p0, final Object p1, final Object p2, final Object 
p3, final Object p4, final Object p5,
             final Object p6, final Object p7, final Object p8, final Object 
p9) {
         final Message msg = messageFactory.newMessage(message, p0, p1, p2, p3, 
p4, p5, p6, p7, p8, p9);
-        logMessage(fqcn, level, marker, msg, msg.getThrowable());
+        logMessageSafely(fqcn, level, marker, msg, msg.getThrowable());
     }
 
     protected void logMessage(final String fqcn, final Level level, final 
Marker marker, final String message,
             final Supplier<?>... paramSuppliers) {
         final Message msg = messageFactory.newMessage(message, 
LambdaUtil.getAll(paramSuppliers));
-        logMessage(fqcn, level, marker, msg, msg.getThrowable());
+        logMessageSafely(fqcn, level, marker, msg, msg.getThrowable());
     }
 
     @Override
     public void printf(final Level level, final Marker marker, final String 
format, final Object... params) {
         if (isEnabled(level, marker, format, params)) {
             final Message msg = new StringFormattedMessage(format, params);
-            logMessage(FQCN, level, marker, msg, msg.getThrowable());
+            logMessageSafely(FQCN, level, marker, msg, msg.getThrowable());
         }
     }
 
@@ -2081,10 +2081,20 @@
     public void printf(final Level level, final String format, final Object... 
params) {
         if (isEnabled(level, null, format, params)) {
             final Message msg = new StringFormattedMessage(format, params);
-            logMessage(FQCN, level, null, msg, msg.getThrowable());
+            logMessageSafely(FQCN, level, null, msg, msg.getThrowable());
         }
     }
 
+    private void logMessageSafely(String fqcn, Level level, Marker marker, 
Message msg, Throwable throwable) {
+        try {
+            logMessage(fqcn, level, marker, msg, throwable);
+        } finally {
+            if (messageFactory instanceof ReusableMessageFactory) {
+                ((ReusableMessageFactory) messageFactory).release(msg);
+            }
+        }
+    }
+
     @Override
     public <T extends Throwable> T throwing(final T t) {
         return throwing(FQCN, Level.ERROR, t);
@@ -2106,7 +2116,7 @@
      */
     protected <T extends Throwable> T throwing(final String fqcn, final Level 
level, final T t) {
         if (isEnabled(level, THROWING_MARKER, (Object) null, null)) {
-            logMessage(fqcn, level, THROWING_MARKER, throwingMsg(t), t);
+            logMessageSafely(fqcn, level, THROWING_MARKER, throwingMsg(t), t);
         }
         return t;
     }
@@ -2414,7 +2424,7 @@
     public void traceExit(final EntryMessage message) {
         // If the message is null, traceEnter returned null because flow 
logging was disabled, we can optimize out calling isEnabled().
         if (message != null && isEnabled(Level.TRACE, EXIT_MARKER, message, 
null)) {
-            logMessage(FQCN, Level.TRACE, EXIT_MARKER, 
flowMessageFactory.newExitMessage(message), null);
+            logMessageSafely(FQCN, Level.TRACE, EXIT_MARKER, 
flowMessageFactory.newExitMessage(message), null);
         }
     }
 
@@ -2422,7 +2432,7 @@
     public <R> R traceExit(final EntryMessage message, final R result) {
         // If the message is null, traceEnter returned null because flow 
logging was disabled, we can optimize out calling isEnabled().
         if (message != null && isEnabled(Level.TRACE, EXIT_MARKER, message, 
null)) {
-            logMessage(FQCN, Level.TRACE, EXIT_MARKER, 
flowMessageFactory.newExitMessage(result, message), null);
+            logMessageSafely(FQCN, Level.TRACE, EXIT_MARKER, 
flowMessageFactory.newExitMessage(result, message), null);
         }
         return result;
     }
@@ -2431,7 +2441,7 @@
     public <R> R traceExit(final Message message, final R result) {
         // If the message is null, traceEnter returned null because flow 
logging was disabled, we can optimize out calling isEnabled().
         if (message != null && isEnabled(Level.TRACE, EXIT_MARKER, message, 
null)) {
-            logMessage(FQCN, Level.TRACE, EXIT_MARKER, 
flowMessageFactory.newExitMessage(result, message), null);
+            logMessageSafely(FQCN, Level.TRACE, EXIT_MARKER, 
flowMessageFactory.newExitMessage(result, message), null);
         }
         return result;
     }

Index: 
log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableMessageFactory.java
IDEA additional info:
Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP
<+>UTF-8
===================================================================
--- 
log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableMessageFactory.java
        (revision )
+++ 
log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableMessageFactory.java
        (revision )
@@ -55,7 +55,7 @@
             result = new ReusableParameterizedMessage();
             threadLocalParameterized.set(result);
         }
-        return result;
+        return result.reserved ? new ReusableParameterizedMessage().reserve() 
: result.reserve();
     }
 
     private static ReusableSimpleMessage getSimple() {
@@ -74,6 +74,13 @@
             threadLocalObjectMessage.set(result);
         }
         return result;
+    }
+
+    public void release(Message message) {
+        if (message instanceof ReusableParameterizedMessage) {
+            System.out.println("Releasing " + message.hashCode());
+            ((ReusableParameterizedMessage) message).reserved = false;
+        }
     }
 
     @Override

Index: 
log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableParameterizedMessage.java
IDEA additional info:
Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP
<+>UTF-8
===================================================================
--- 
log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableParameterizedMessage.java
  (revision )
+++ 
log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableParameterizedMessage.java
  (revision )
@@ -33,7 +33,7 @@
     private static final int MIN_BUILDER_SIZE = 512;
     private static final int MAX_PARMS = 10;
     private static final long serialVersionUID = 7800075879295123856L;
-    private static ThreadLocal<StringBuilder> buffer = new ThreadLocal<>();
+    private ThreadLocal<StringBuilder> buffer = new ThreadLocal<>(); // 
non-static: LOG4J2-1583
 
     private String messagePattern;
     private int argCount;
@@ -42,6 +42,7 @@
     private transient Object[] varargs;
     private transient Object[] params = new Object[MAX_PARMS];
     private transient Throwable throwable;
+    transient boolean reserved = false; // LOG4J2-1583
 
     /**
      * Creates a reusable message.
@@ -308,6 +309,11 @@
         }
     }
 
+    ReusableParameterizedMessage reserve() {
+        System.out.println("Reserving " + hashCode());
+        reserved = true;
+        return this;
+    }
 
     @Override
     public String toString() {

{code}
)

> Nested logging call disrupts output of outer logging call
> ---------------------------------------------------------
>
>                 Key: LOG4J2-1583
>                 URL: https://issues.apache.org/jira/browse/LOG4J2-1583
>             Project: Log4j 2
>          Issue Type: Bug
>          Components: Core
>    Affects Versions: 2.6, 2.6.1, 2.6.2
>         Environment: JVM 1.8.0_102, MacOS 10.11.6
>            Reporter: Larry West
>            Assignee: Remko Popma
>             Fix For: 2.7
>
>         Attachments: LOG4J-1583.tbz2, Log4j2ProblemDemo.java, log4j2.xml, 
> pom.xml
>
>
> If a call to logger.info() invokes the toString() method on one of its 
> parameters, and that toString() method invokes another method which has 
> another, nested logging call, then the output of the outer call is mangled.
> This can be quite confusing as the nested logging may be conditional, or at 
> DEBUG level, etc.
> Problem _appears_ to be related to ReusableParameterizedMessage.swapMessage() 
> and the values in indices[].  (It looks inherently non-reentrant.)



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscr...@logging.apache.org
For additional commands, e-mail: log4j-dev-h...@logging.apache.org

Reply via email to