logging-log4j-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Remko Popma (JIRA)" <j...@apache.org>
Subject [jira] [Updated] (LOG4J2-763) Async loggers convert message parameters toString at log record writing not at log statement execution
Date Wed, 06 Aug 2014 16:31:15 GMT

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

Remko Popma updated LOG4J2-763:
-------------------------------

    Attachment: LOG4J2-763.patch

I've taken the simple approach of calling {{getFormattedMessage}} in the constructor to cache
the formatted message string. For most message implementation classes this is sufficient.

For ObjectMessage I added a String field to capture the value of {{obj.toString()}} at message
construction time.

MapMessage and StructuredDataMessage are mutable by design. The simplest thing to do here
is to document that they should not be modified after they have been logged.

Please see attached patch.
If there are no objections to this approach I will commit this (still need to do unit tests
and site changes to mention users should take care with MapMessage and StructuredDataMessage
with async logging.)

> Async loggers convert message parameters toString at log record writing not at log statement
execution
> ------------------------------------------------------------------------------------------------------
>
>                 Key: LOG4J2-763
>                 URL: https://issues.apache.org/jira/browse/LOG4J2-763
>             Project: Log4j 2
>          Issue Type: Bug
>    Affects Versions: 2.0
>            Reporter: Stephen Connolly
>            Assignee: Remko Popma
>         Attachments: LOG4J2-763.patch
>
>
> 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}



--
This message was sent by Atlassian JIRA
(v6.2#6252)

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


Mime
View raw message