Log4j 2
  1. Log4j 2
  2. LOG4J2-763

Async loggers convert message parameters toString at log record writing not at log statement execution

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 2.0
    • Fix Version/s: 2.0.2
    • Component/s: None
    • Labels:
      None

      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

          Activity

          Remko Popma made changes -
          Status Reopened [ 4 ] Resolved [ 5 ]
          Resolution Fixed [ 1 ]
          Remko Popma made changes -
          Link This issue is related to LOG4J2-772 [ LOG4J2-772 ]
          Remko Popma made changes -
          Resolution Fixed [ 1 ]
          Status Resolved [ 5 ] Reopened [ 4 ]
          Remko Popma made changes -
          Status In Progress [ 3 ] Resolved [ 5 ]
          Resolution Fixed [ 1 ]
          Remko Popma made changes -
          Fix Version/s 2.0.2 [ 12327553 ]
          Remko Popma made changes -
          Attachment LOG4J2-763.patch [ 12660169 ]
          Remko Popma made changes -
          Status Open [ 1 ] In Progress [ 3 ]
          Remko Popma made changes -
          Assignee Remko Popma [ remkop@yahoo.com ]
          Remko Popma made changes -
          Field Original Value New Value
          Description http://javaadventure.blogspot.com/2014/07/log4j-20-async-loggers-and-immutability.html

          TL;DR 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.
          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:
          {code}
          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();
                  }
              }
          }
          {code}

          Here is the first few lines of logging output
          {code}
          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
          {code}

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

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

          Stephen Connolly created issue -

            People

            • Assignee:
              Remko Popma
              Reporter:
              Stephen Connolly
            • Votes:
              0 Vote for this issue
              Watchers:
              5 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development