[
https://issues.apache.org/jira/browse/LOG4J2-763?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14092349#comment-14092349
]
Remko Popma edited comment on LOG4J2-763 at 8/11/14 1:56 PM:
-------------------------------------------------------------
Re-opening: the current implementation solves the problem but may have some
performance impact. It is better to avoid creating the formatted string in the
constructor because messages may be filtered out (e.g. because their log level
is too low) and this formatted message string may end up not being used.
A better solution is to revert to lazy initialization and have async components
call the {{Message.getFormattedMessage()}} method before passing the log event
to another thread.
In addition to reverting,
* ObjectMessage should cache its formatted message string and initialize this
cached string in {{getFormattedMessage}}.
* ParameterizedMessage should not take string snapshots in its constructor but
should delay that work until the {{getFormattedMessage}} method is called. - I
created LOG4J2-772 for this as I may not have time for this refactoring at the
moment and it is not as urgent.
was (Author: [email protected]):
Re-opening: the current implementation solves the problem but may have some
performance impact. It is better to avoid creating the formatted string in the
constructor because messages may be filtered out (e.g. because their log level
is too low) and this formatted message string may end up not being used.
A better solution is to revert to lazy initialization and have async components
call the {{Message.getFormattedMessage()}} method before passing the log event
to another thread.
In addition to reverting,
* ObjectMessage should cache its formatted message string and initialize this
cached string in {{getFormattedMessage}}.
* ParameterizedMessage should not take string snapshots in its constructor but
should delay that work until the {{getFormattedMessage}} method is called.
> 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
> Fix For: 2.0.2
>
> 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: [email protected]
For additional commands, e-mail: [email protected]
