You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-dev@logging.apache.org by "Remko Popma (JIRA)" <ji...@apache.org> on 2014/08/04 05:06:12 UTC
[jira] [Comment Edited] (LOG4J2-763) Async loggers convert message
parameters toString at log record writing not at log statement execution
[ https://issues.apache.org/jira/browse/LOG4J2-763?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14084247#comment-14084247 ]
Remko Popma edited comment on LOG4J2-763 at 8/4/14 3:05 AM:
------------------------------------------------------------
Strange: I thought ParameterizedMessage was okay because it already takes a snapshot of the parameters when the LogEvent is created, but looking again at Stephen's blog post, he is using... parameterized messages.
Looking at the resulting log output, I can't actually see what is wrong with it.
Stephen, what did you expect to see in the log output?
The suggested solution:
{code}
if (logger.isWarnEnabled()) {
logger.warn("{} == {}", instance.next(), instance.toString());
}
{code}
I don't think this will produce different results, does it? The only difference I can see is that the window of opportunity for another thread to increment the counter is narrower now than in the original code. But it will still not *guarantee* that you see the same number...
The problem is that the {{value}} field is static, so shared by all App instances. Giving each Thread its own App instance does not help since they all still share the same AtomicLong {{value}} field.
was (Author: remkop@yahoo.com):
Strange: I thought ParameterizedMessage was okay because it already takes a snapshot of the parameters when the LogEvent is created, but looking again at Stephen's blog post, he is using... parameterized messages.
Looking at the resulting log output, I can't actually see what is wrong with it.
Stephen, what did you expect to see in the log output?
The suggested solution:
{code}
if (logger.isWarnEnabled()) {
logger.warn("{} == {}", instance.next(), instance.toString());
}
{code}
I don't think this will produce different results, does it? The only difference I can see is that the window of opportunity for another thread to increment the counter is narrower in the code below. But it will still not *guarantee* that you see the same number...
The problem is that the {{value}} field is static, so shared by all App instances. Giving each Thread its own App instance does not help since they all still share the same AtomicLong {{value}} field.
> 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
>
> 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