[LOG4J2-763] Async loggers convert message parameters toString at log record writing not at log statement execution

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 2.0
• Fix Version/s: 2.0.2
• Assignee: Remko Popma
• Reporter: Stephen Connolly
• Created: 03/Aug/14 23:18
• Updated: 20/Nov/16 13:04
• Resolved: 11/Aug/14 14:17

Description

http://javaadventure.blogspot.com/2014/07/log4j-20-async-loggers-and-immutability.html

When using parameterized messages, the toString() method of the log messages is not called when the log message is enqueued, rather after the log message has been dequeued for writing. If any of the message parameters are mutable, they can thus have changed state before the log message is written, thus resulting in the logged message content being incorrect.

From the blog post, code that demonstrates the problem:

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import java.util.concurrent.atomic.AtomicLong;

public class App {
    private static final AtomicLong value = new AtomicLong();
    public String toString() {
        return Long.toString(value.get());
    }
    public long next() {
        return value.incrementAndGet();
    }

    public static void main(String[] args) {
        for (int i = 0; i < 32; i++) {
            new Thread() {
                final Logger logger = LogManager.getLogger(App.class);
                 final App instance = new App();
                @Override
                 public void run() {
                     for (int i = 0; i < 100000; i++) {
                         logger.warn("{} == {}", instance.next(), instance);
                     }
                 }
            }.start();
        }
    }
}

Here is the first few lines of logging output

2014-07-28 15:59:45,729 WARN t.App [Thread-13] 13 == 13 
2014-07-28 15:59:45,730 WARN t.App [Thread-29] 29 == 29 
2014-07-28 15:59:45,729 WARN t.App [Thread-15] 15 == 15 
2014-07-28 15:59:45,729 WARN t.App [Thread-6] 6 == 6 
2014-07-28 15:59:45,730 WARN t.App [Thread-30] 30 == 30 
2014-07-28 15:59:45,729 WARN t.App [Thread-20] 20 == 20 
2014-07-28 15:59:45,729 WARN t.App [Thread-8] 8 == 8 
2014-07-28 15:59:45,730 WARN t.App [Thread-28] 28 == 28 
2014-07-28 15:59:45,729 WARN t.App [Thread-19] 19 == 19 
2014-07-28 15:59:45,729 WARN t.App [Thread-18] 18 == 18 
2014-07-28 15:59:45,729 WARN t.App [Thread-5] 5 == 6 
2014-07-28 15:59:45,731 WARN t.App [Thread-13] 33 == 37 
2014-07-28 15:59:45,731 WARN t.App [Thread-8] 39 == 39 
2014-07-28 15:59:45,731 WARN t.App [Thread-28] 40 == 41 
2014-07-28 15:59:45,731 WARN t.App [Thread-18] 42 == 43 
2014-07-28 15:59:45,731 WARN t.App [Thread-5] 43 == 43

To make my previous code work with Asynchronous loggers (other than by fixing the mutable state) I would need to log like this:

if (logger.isWarnEnabled()) {
    logger.warn("{} == {}", instance.next(), instance.toString());
}

Issue Links

• is related to: LOG4J2-898 Format messages asynchronously
• is related to: LOG4J2-772 Performance enhancement: ParameterizedMessage should not take String snapshots of its parameters in constructor
• relates to: LOG4J2-1718 Introduce marker interface AsynchronouslyFormattable