[
https://issues.apache.org/jira/browse/LOG4J2-763?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14093546#comment-14093546
]
Remko Popma edited comment on LOG4J2-763 at 8/12/14 1:06 PM:
-------------------------------------------------------------
Added below serialization JUnit tests in revision 1617465.
{code}
// add to ObjectMessageTest
@Test
public void testSerializeWithSerializableParam() {
BigDecimal big = BigDecimal.valueOf(123.456);
ObjectMessage msg = new ObjectMessage(big);
ObjectMessage other = SerialUtil.deserialize(SerialUtil.serialize(msg));
assertEquals(msg, other);
}
@Test
public void testDeserializeNonSerializableParamNotEqualIfToStringDiffers() {
ObjectMessageTest nonSerializable = new ObjectMessageTest();
assertFalse(nonSerializable instanceof Serializable);
ObjectMessage msg = new ObjectMessage(nonSerializable);
ObjectMessage other = SerialUtil.deserialize(SerialUtil.serialize(msg));
assertNotEquals("Expected different: toString is different", msg,
other);
}
@Test
public void testDeserializeNonSerializableParamEqualIfToStringSame() {
class NonSerializable {
public boolean equals(Object other) {
return other instanceof NonSerializable; // a very lenient
equals()
}
}
NonSerializable nonSerializable = new NonSerializable();
assertFalse(nonSerializable instanceof Serializable);
ObjectMessage msg = new ObjectMessage(nonSerializable);
ObjectMessage other = SerialUtil.deserialize(SerialUtil.serialize(msg));
// TODO this fails: msg.obj.equals(other.obj) is false...
// TODO our equals() implementation does not match the serialization mechanism
assertEquals(msg, other);
}
// new helper class (src/test/java/org.apache.log4j.util?)
public class SerialUtil {
public static byte[] serialize(Serializable obj) {
try {
ByteArrayOutputStream bas = new ByteArrayOutputStream(8192);
ObjectOutputStream oos = new ObjectOutputStream(bas);
oos.writeObject(obj);
oos.flush();
return bas.toByteArray();
} catch (Exception ex) {
throw new IllegalStateException("Could not serialize", ex);
}
}
@SuppressWarnings("unchecked")
public static <T> T deserialize(byte[] data) {
try {
ByteArrayInputStream bas = new ByteArrayInputStream(data);
ObjectInputStream ois = new ObjectInputStream(bas);
return (T) ois.readObject();
} catch (Exception ex) {
throw new IllegalStateException("Could not deserialize", ex);
}
}
}
{code}
was (Author: [email protected]):
TODO: add serialization JUnit tests.
{code}
// add to ObjectMessageTest
@Test
public void testSerializeWithSerializableParam() {
BigDecimal big = BigDecimal.valueOf(123.456);
ObjectMessage msg = new ObjectMessage(big);
ObjectMessage other = SerialUtil.deserialize(SerialUtil.serialize(msg));
assertEquals(msg, other);
}
@Test
public void testDeserializeNonSerializableParamNotEqualIfToStringDiffers() {
ObjectMessageTest nonSerializable = new ObjectMessageTest();
assertFalse(nonSerializable instanceof Serializable);
ObjectMessage msg = new ObjectMessage(nonSerializable);
ObjectMessage other = SerialUtil.deserialize(SerialUtil.serialize(msg));
assertNotEquals("Expected different: toString is different", msg,
other);
}
@Test
public void testDeserializeNonSerializableParamEqualIfToStringSame() {
class NonSerializable {
public boolean equals(Object other) {
return other instanceof NonSerializable; // a very lenient
equals()
}
}
NonSerializable nonSerializable = new NonSerializable();
assertFalse(nonSerializable instanceof Serializable);
ObjectMessage msg = new ObjectMessage(nonSerializable);
ObjectMessage other = SerialUtil.deserialize(SerialUtil.serialize(msg));
// TODO this fails: msg.obj.equals(other.obj) is false...
// TODO our equals() implementation does not match the serialization mechanism
assertEquals(msg, other);
}
// new helper class (src/test/java/org.apache.log4j.util?)
public class SerialUtil {
public static byte[] serialize(Serializable obj) {
try {
ByteArrayOutputStream bas = new ByteArrayOutputStream(8192);
ObjectOutputStream oos = new ObjectOutputStream(bas);
oos.writeObject(obj);
oos.flush();
return bas.toByteArray();
} catch (Exception ex) {
throw new IllegalStateException("Could not serialize", ex);
}
}
@SuppressWarnings("unchecked")
public static <T> T deserialize(byte[] data) {
try {
ByteArrayInputStream bas = new ByteArrayInputStream(data);
ObjectInputStream ois = new ObjectInputStream(bas);
return (T) ois.readObject();
} catch (Exception ex) {
throw new IllegalStateException("Could not deserialize", ex);
}
}
}
{code}
> 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]
