You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@logging.apache.org by rp...@apache.org on 2014/08/11 16:16:22 UTC
svn commit: r1617291 - in /logging/log4j/log4j2/trunk:
log4j-api/src/main/java/org/apache/logging/log4j/message/
log4j-api/src/test/java/org/apache/logging/log4j/message/
log4j-core/src/main/java/org/apache/logging/log4j/core/appender/
log4j-core/src/m...
Author: rpopma
Date: Mon Aug 11 14:16:22 2014
New Revision: 1617291
URL: http://svn.apache.org/r1617291
Log:
LOG4J2-763: use different mechanism to solve this problem: instead of initializing the formatted message string in the message constructor, postpone this as long as possible until getFormattedMessage() is called. Async loggers and AsyncAppender now call message.getFormattedMessage() before passing the log event to the background thread. Added more tests.
Modified:
logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/FormattedMessage.java
logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/LocalizedMessage.java
logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/MessageFormatMessage.java
logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/ObjectMessage.java
logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/StringFormattedMessage.java
logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/FormattedMessageTest.java
logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/LocalizedMessageTest.java
logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/MessageFormatMessageTest.java
logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/ObjectMessageTest.java
logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/StringFormattedMessageTest.java
logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java
logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java
logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java
logging/log4j/log4j2/trunk/src/changes/changes.xml
Modified: logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/FormattedMessage.java
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/FormattedMessage.java?rev=1617291&r1=1617290&r2=1617291&view=diff
==============================================================================
--- logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/FormattedMessage.java (original)
+++ logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/FormattedMessage.java Mon Aug 11 14:16:22 2014
@@ -46,7 +46,6 @@ public class FormattedMessage implements
this.messagePattern = messagePattern;
this.argArray = arguments;
this.throwable = throwable;
- getFormattedMessage(); // LOG4J2-763 take snapshot of parameters at message construction time
}
public FormattedMessage(final String messagePattern, final Object[] arguments) {
Modified: logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/LocalizedMessage.java
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/LocalizedMessage.java?rev=1617291&r1=1617290&r2=1617291&view=diff
==============================================================================
--- logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/LocalizedMessage.java (original)
+++ logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/LocalizedMessage.java Mon Aug 11 14:16:22 2014
@@ -78,7 +78,6 @@ public class LocalizedMessage implements
this.baseName = baseName;
this.resourceBundle = null;
this.locale = locale;
- getFormattedMessage(); // LOG4J2-763 take snapshot of parameters at message construction time
}
public LocalizedMessage(final ResourceBundle bundle, final Locale locale, final String key,
@@ -89,7 +88,6 @@ public class LocalizedMessage implements
this.baseName = null;
this.resourceBundle = bundle;
this.locale = locale;
- getFormattedMessage(); // LOG4J2-763 take snapshot of parameters at message construction time
}
public LocalizedMessage(final Locale locale, final String key, final Object[] arguments) {
Modified: logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/MessageFormatMessage.java
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/MessageFormatMessage.java?rev=1617291&r1=1617290&r2=1617291&view=diff
==============================================================================
--- logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/MessageFormatMessage.java (original)
+++ logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/MessageFormatMessage.java Mon Aug 11 14:16:22 2014
@@ -49,7 +49,6 @@ public class MessageFormatMessage implem
if (arguments != null && arguments.length > 0 && arguments[arguments.length - 1] instanceof Throwable) {
this.throwable = (Throwable) arguments[arguments.length - 1];
}
- getFormattedMessage(); // LOG4J2-763 take snapshot of parameters at message construction time
}
/**
Modified: logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/ObjectMessage.java
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/ObjectMessage.java?rev=1617291&r1=1617290&r2=1617291&view=diff
==============================================================================
--- logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/ObjectMessage.java (original)
+++ logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/ObjectMessage.java Mon Aug 11 14:16:22 2014
@@ -29,7 +29,7 @@ public class ObjectMessage implements Me
private static final long serialVersionUID = -5903272448334166185L;
private transient Object obj;
- private final String objectString;
+ private transient String objectString;
/**
* Create the ObjectMessage.
@@ -40,9 +40,6 @@ public class ObjectMessage implements Me
obj = "null";
}
this.obj = obj;
-
- // LOG4J2-763: take snapshot of parameters at message construction time
- objectString = String.valueOf(obj);
}
/**
@@ -51,6 +48,10 @@ public class ObjectMessage implements Me
*/
@Override
public String getFormattedMessage() {
+ // LOG4J2-763: cache formatted string in case obj changes later
+ if (objectString == null) {
+ objectString = String.valueOf(obj);
+ }
return objectString;
}
@@ -60,7 +61,7 @@ public class ObjectMessage implements Me
*/
@Override
public String getFormat() {
- return objectString;
+ return getFormattedMessage();
}
/**
@@ -69,7 +70,7 @@ public class ObjectMessage implements Me
*/
@Override
public Object[] getParameters() {
- return new Object[]{obj};
+ return new Object[] { obj };
}
@Override
@@ -82,8 +83,7 @@ public class ObjectMessage implements Me
}
final ObjectMessage that = (ObjectMessage) o;
-
- return !(obj != null ? !obj.equals(that.obj) : that.obj != null);
+ return obj == null ? that.obj == null : obj.equals(that.obj);
}
@Override
@@ -93,7 +93,7 @@ public class ObjectMessage implements Me
@Override
public String toString() {
- return "ObjectMessage[obj=" + objectString + ']';
+ return "ObjectMessage[obj=" + getFormattedMessage() + ']';
}
private void writeObject(final ObjectOutputStream out) throws IOException {
@@ -101,7 +101,7 @@ public class ObjectMessage implements Me
if (obj instanceof Serializable) {
out.writeObject(obj);
} else {
- out.writeObject(obj.toString());
+ out.writeObject(String.valueOf(obj));
}
}
Modified: logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/StringFormattedMessage.java
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/StringFormattedMessage.java?rev=1617291&r1=1617290&r2=1617291&view=diff
==============================================================================
--- logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/StringFormattedMessage.java (original)
+++ logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/StringFormattedMessage.java Mon Aug 11 14:16:22 2014
@@ -48,7 +48,6 @@ public class StringFormattedMessage impl
if (arguments != null && arguments.length > 0 && arguments[arguments.length - 1] instanceof Throwable) {
this.throwable = (Throwable) arguments[arguments.length - 1];
}
- getFormattedMessage(); // LOG4J2-763 take snapshot of parameters at message construction time
}
/**
Modified: logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/FormattedMessageTest.java
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/FormattedMessageTest.java?rev=1617291&r1=1617290&r2=1617291&view=diff
==============================================================================
--- logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/FormattedMessageTest.java (original)
+++ logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/FormattedMessageTest.java Mon Aug 11 14:16:22 2014
@@ -85,14 +85,27 @@ public class FormattedMessageTest {
}
@Test
- public void testSafeWithMutableParams() { // LOG4J2-763
+ public void testUnsafeWithMutableParams() { // LOG4J2-763
final String testMsg = "Test message %s";
final Mutable param = new Mutable().set("abc");
- FormattedMessage msg = new FormattedMessage(testMsg, param);
+ final FormattedMessage msg = new FormattedMessage(testMsg, param);
// modify parameter before calling msg.getFormattedMessage
param.set("XYZ");
- String actual = msg.getFormattedMessage();
+ final String actual = msg.getFormattedMessage();
+ assertEquals("Expected most recent param value", "Test message XYZ", actual);
+ }
+
+ @Test
+ public void testSafeAfterGetFormattedMessageIsCalled() { // LOG4J2-763
+ final String testMsg = "Test message %s";
+ final Mutable param = new Mutable().set("abc");
+ final FormattedMessage msg = new FormattedMessage(testMsg, param);
+
+ // modify parameter after calling msg.getFormattedMessage
+ msg.getFormattedMessage(); // freeze the formatted message
+ param.set("XYZ");
+ final String actual = msg.getFormattedMessage();
assertEquals("Should use initial param value", "Test message abc", actual);
}
}
Modified: logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/LocalizedMessageTest.java
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/LocalizedMessageTest.java?rev=1617291&r1=1617290&r2=1617291&view=diff
==============================================================================
--- logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/LocalizedMessageTest.java (original)
+++ logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/LocalizedMessageTest.java Mon Aug 11 14:16:22 2014
@@ -65,15 +65,27 @@ public class LocalizedMessageTest {
}
@Test
- public void testSafeWithMutableParams() { // LOG4J2-763
+ public void testUnsafeWithMutableParams() { // LOG4J2-763
final String testMsg = "Test message %s";
final Mutable param = new Mutable().set("abc");
- LocalizedMessage msg = new LocalizedMessage(testMsg, param);
+ final LocalizedMessage msg = new LocalizedMessage(testMsg, param);
// modify parameter before calling msg.getFormattedMessage
param.set("XYZ");
- String actual = msg.getFormattedMessage();
- assertEquals("Should use initial param value", "Test message abc", actual);
+ final String actual = msg.getFormattedMessage();
+ assertEquals("Expected most recent param value", "Test message XYZ", actual);
}
+ @Test
+ public void testSafeAfterGetFormattedMessageIsCalled() { // LOG4J2-763
+ final String testMsg = "Test message %s";
+ final Mutable param = new Mutable().set("abc");
+ final LocalizedMessage msg = new LocalizedMessage(testMsg, param);
+
+ // modify parameter after calling msg.getFormattedMessage
+ msg.getFormattedMessage();
+ param.set("XYZ");
+ final String actual = msg.getFormattedMessage();
+ assertEquals("Should use initial param value", "Test message abc", actual);
+ }
}
Modified: logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/MessageFormatMessageTest.java
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/MessageFormatMessageTest.java?rev=1617291&r1=1617290&r2=1617291&view=diff
==============================================================================
--- logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/MessageFormatMessageTest.java (original)
+++ logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/MessageFormatMessageTest.java Mon Aug 11 14:16:22 2014
@@ -63,14 +63,27 @@ public class MessageFormatMessageTest {
}
@Test
- public void testSafeWithMutableParams() { // LOG4J2-763
+ public void testUnsafeWithMutableParams() { // LOG4J2-763
final String testMsg = "Test message {0}";
final Mutable param = new Mutable().set("abc");
- MessageFormatMessage msg = new MessageFormatMessage(testMsg, param);
+ final MessageFormatMessage msg = new MessageFormatMessage(testMsg, param);
// modify parameter before calling msg.getFormattedMessage
param.set("XYZ");
- String actual = msg.getFormattedMessage();
+ final String actual = msg.getFormattedMessage();
+ assertEquals("Expected most recent param value", "Test message XYZ", actual);
+ }
+
+ @Test
+ public void testSafeAfterGetFormattedMessageIsCalled() { // LOG4J2-763
+ final String testMsg = "Test message {0}";
+ final Mutable param = new Mutable().set("abc");
+ final MessageFormatMessage msg = new MessageFormatMessage(testMsg, param);
+
+ // modify parameter after calling msg.getFormattedMessage
+ msg.getFormattedMessage();
+ param.set("XYZ");
+ final String actual = msg.getFormattedMessage();
assertEquals("Should use initial param value", "Test message abc", actual);
}
}
Modified: logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/ObjectMessageTest.java
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/ObjectMessageTest.java?rev=1617291&r1=1617290&r2=1617291&view=diff
==============================================================================
--- logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/ObjectMessageTest.java (original)
+++ logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/ObjectMessageTest.java Mon Aug 11 14:16:22 2014
@@ -41,13 +41,25 @@ public class ObjectMessageTest {
}
@Test
- public void testSafeWithMutableParams() { // LOG4J2-763
+ public void testUnsafeWithMutableParams() { // LOG4J2-763
final Mutable param = new Mutable().set("abc");
- ObjectMessage msg = new ObjectMessage(param);
+ final ObjectMessage msg = new ObjectMessage(param);
// modify parameter before calling msg.getFormattedMessage
param.set("XYZ");
- String actual = msg.getFormattedMessage();
+ final String actual = msg.getFormattedMessage();
+ assertEquals("Expected most recent param value", "XYZ", actual);
+ }
+
+ @Test
+ public void testSafeAfterGetFormattedMessageIsCalled() { // LOG4J2-763
+ final Mutable param = new Mutable().set("abc");
+ final ObjectMessage msg = new ObjectMessage(param);
+
+ // modify parameter after calling msg.getFormattedMessage
+ msg.getFormattedMessage();
+ param.set("XYZ");
+ final String actual = msg.getFormattedMessage();
assertEquals("Should use initial param value", "abc", actual);
}
}
Modified: logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/StringFormattedMessageTest.java
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/StringFormattedMessageTest.java?rev=1617291&r1=1617290&r2=1617291&view=diff
==============================================================================
--- logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/StringFormattedMessageTest.java (original)
+++ logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/StringFormattedMessageTest.java Mon Aug 11 14:16:22 2014
@@ -62,14 +62,27 @@ public class StringFormattedMessageTest
}
@Test
- public void testSafeWithMutableParams() { // LOG4J2-763
+ public void testUnsafeWithMutableParams() { // LOG4J2-763
final String testMsg = "Test message %s";
final Mutable param = new Mutable().set("abc");
- StringFormattedMessage msg = new StringFormattedMessage(testMsg, param);
+ final StringFormattedMessage msg = new StringFormattedMessage(testMsg, param);
// modify parameter before calling msg.getFormattedMessage
param.set("XYZ");
- String actual = msg.getFormattedMessage();
+ final String actual = msg.getFormattedMessage();
+ assertEquals("Should use initial param value", "Test message XYZ", actual);
+ }
+
+ @Test
+ public void testSafeAfterGetFormattedMessageIsCalled() { // LOG4J2-763
+ final String testMsg = "Test message %s";
+ final Mutable param = new Mutable().set("abc");
+ final StringFormattedMessage msg = new StringFormattedMessage(testMsg, param);
+
+ // modify parameter after calling msg.getFormattedMessage
+ msg.getFormattedMessage();
+ param.set("XYZ");
+ final String actual = msg.getFormattedMessage();
assertEquals("Should use initial param value", "Test message abc", actual);
}
}
Modified: logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java?rev=1617291&r1=1617290&r2=1617291&view=diff
==============================================================================
--- logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java (original)
+++ logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java Mon Aug 11 14:16:22 2014
@@ -138,6 +138,7 @@ public final class AsyncAppender extends
}
logEvent = ((RingBufferLogEvent) logEvent).createMemento();
}
+ logEvent.getMessage().getFormattedMessage(); // LOG4J2-763: ask message to freeze parameters
final Log4jLogEvent coreEvent = (Log4jLogEvent) logEvent;
boolean appendSuccessful = false;
if (blocking) {
Modified: logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java?rev=1617291&r1=1617290&r2=1617291&view=diff
==============================================================================
--- logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java (original)
+++ logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java Mon Aug 11 14:16:22 2014
@@ -226,6 +226,7 @@ public class AsyncLogger extends Logger
@Override
public void logMessage(final String fqcn, final Level level, final Marker marker, final Message message, final Throwable thrown) {
+ // TODO refactor to reduce size to <= 35 bytecodes to allow JVM to inline it
Info info = threadlocalInfo.get();
if (info == null) {
info = new Info(new RingBufferLogEventTranslator(), Thread.currentThread().getName(), false);
@@ -245,6 +246,7 @@ public class AsyncLogger extends Logger
config.loggerConfig.log(getName(), fqcn, marker, level, message, thrown);
return;
}
+ message.getFormattedMessage(); // LOG4J2-763: ask message to freeze parameters
final boolean includeLocation = config.loggerConfig.isIncludeLocation();
info.translator.setValues(this, getName(), marker, fqcn, level, message, //
// don't construct ThrowableProxy until required
Modified: logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java?rev=1617291&r1=1617290&r2=1617291&view=diff
==============================================================================
--- logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java (original)
+++ logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java Mon Aug 11 14:16:22 2014
@@ -316,6 +316,7 @@ class AsyncLoggerConfigHelper {
* calling thread needs to process the event itself
*/
public boolean callAppendersFromAnotherThread(final LogEvent event) {
+ // TODO refactor to reduce size to <= 35 bytecodes to allow JVM to inline it
final Disruptor<Log4jEventWrapper> temp = disruptor;
if (temp == null) { // LOG4J2-639
LOGGER.fatal("Ignoring log event after log4j was shut down");
@@ -336,6 +337,8 @@ class AsyncLoggerConfigHelper {
if (event instanceof RingBufferLogEvent) {
logEvent = ((RingBufferLogEvent) event).createMemento();
}
+ logEvent.getMessage().getFormattedMessage(); // LOG4J2-763: ask message to freeze parameters
+
// Note: do NOT use the temp variable above!
// That could result in adding a log event to the disruptor after it was shut down,
// which could cause the publishEvent method to hang and never return.
Modified: logging/log4j/log4j2/trunk/src/changes/changes.xml
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/src/changes/changes.xml?rev=1617291&r1=1617290&r2=1617291&view=diff
==============================================================================
--- logging/log4j/log4j2/trunk/src/changes/changes.xml (original)
+++ logging/log4j/log4j2/trunk/src/changes/changes.xml Mon Aug 11 14:16:22 2014
@@ -29,8 +29,7 @@
Startup takes a long time if you have empty packages attribute.
</action>
<action issue="LOG4J2-763" dev="rpopma" type="fix" due-to="Stephen Connolly">
- Improved FormattedMessage, StringFormattedMessage, LocalizedMessage, MessageFormatMessage and
- ObjectMessage for asynchronous logging to ensure the formatted message does not change even if
+ Improved asynchronous loggers and appenders to ensure the formatted message does not change even if
parameters are modified by the application. (ParameterizedMessage was already safe.)
Improved documentation.
</action>
Re: svn commit: r1617291 - in /logging/log4j/log4j2/trunk: log4j-api/src/main/java/org/apache/logging/log4j/message/ log4j-api/src/test/java/org/apache/logging/log4j/message/ log4j-core/src/main/java/org/apache/logging/log4j/core/appender/ log4j-core/src/m...
Posted by Ralph Goers <rg...@apache.org>.
That sounds good to me.
Sent from my iPad
> On Aug 12, 2014, at 6:10 AM, Remko Popma <re...@gmail.com> wrote:
>
> Well, you were right there was something fishy with the deserialization.
> If the ObjectMessage parameter is not Serializable, it gets serialized as a string.
> Then, originalObjectMessage.equals(deserializedObjectMessage) returns false since ObjectMessage.equals does not take into account that the parameter may have been turned into a string.
>
> I've added a JUnit test to illustrate the problem (now @Ignored or it would break the build).
> I propose that we modify the equals method to also compare the string version of the objMessage parameter.
> Thoughts?
>
>
>> On Tue, Aug 12, 2014 at 8:33 AM, Remko Popma <re...@gmail.com> wrote:
>> I'll add a junit test, but this is what it was before I started touching that class (except for obj.toString() -> String.valueOf(obj)).
>>
>> Sent from my iPhone
>>
>> > On 2014/08/12, at 8:02, Ralph Goers <ra...@dslextreme.com> wrote:
>> >
>> > Serialization does:
>> >
>> > if (obj instanceof Serializable) {
>> > out.writeObject(obj);
>> > } else {
>> > out.writeObject(String.valueOf(obj));
>> > }
>> >
>> > Deserialization does:
>> >
>> > in.defaultReadObject();
>> > obj = in.readObject();
>> >
>> > So if obj is not Serializable a String will be written. Upon deserialization obj will be set to either the the deserialized version of the object or to the String. I guess this will work.
>> >
>> > Ralph
>> >
>> >
>> >> On Aug 11, 2014, at 2:46 PM, Remko Popma <re...@gmail.com> wrote:
>> >>
>> >> I didn't change the serialization behavior. I only changed
>> >> obj.toString()
>> >> to
>> >> String.valueOf(obj)
>> >>
>> >> The stringValue field wasn't there originally (I incorrectly added it as non-transient in my first attempt). It is now transient so serialized form should be the same as pre-change.
>> >>
>> >> The serialization behavior of ObjectMessage has always been to serialize as Object if possible (Serializable), otherwise as String. Deserialization will just read whatever was serialized. That may not be the same object field but is the best we can do.
>> >>
>> >> Or did I miss something? (away from PC)
>> >>
>> >> Sent from my iPhone
>> >>
>> >>> On 2014/08/12, at 2:38, Ralph Goers <ra...@dslextreme.com> wrote:
>> >>>
>> >>> I believe this breaks deserialization of ObjectMessage. It is being serialized as either the serialized form of the Object or as a String. Deserialization doesn't account for this.
>> >>>
>> >>> Ralph
>> >>>
>> >>>> On Aug 11, 2014, at 7:16 AM, rpopma@apache.org wrote:
>> >>>>
>> >>>> Author: rpopma
>> >>>> Date: Mon Aug 11 14:16:22 2014
>> >>>> New Revision: 1617291
>> >>>>
>> >>>> URL: http://svn.apache.org/r1617291
>> >>>> Log:
>> >>>> LOG4J2-763: use different mechanism to solve this problem: instead of initializing the formatted message string in the message constructor, postpone this as long as possible until getFormattedMessage() is called. Async loggers and AsyncAppender now call message.getFormattedMessage() before passing the log event to the background thread. Added more tests.
>> >>>>
>> >>>> Modified:
>> >>>> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/FormattedMessage.java
>> >>>> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/LocalizedMessage.java
>> >>>> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/MessageFormatMessage.java
>> >>>> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/ObjectMessage.java
>> >>>> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/StringFormattedMessage.java
>> >>>> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/FormattedMessageTest.java
>> >>>> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/LocalizedMessageTest.java
>> >>>> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/MessageFormatMessageTest.java
>> >>>> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/ObjectMessageTest.java
>> >>>> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/StringFormattedMessageTest.java
>> >>>> logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java
>> >>>> logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java
>> >>>> logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java
>> >>>> logging/log4j/log4j2/trunk/src/changes/changes.xml
>> >>>>
>> >>>> Modified: logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/FormattedMessage.java
>> >>>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/FormattedMessage.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>> >>>> ==============================================================================
>> >>>> --- logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/FormattedMessage.java (original)
>> >>>> +++ logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/FormattedMessage.java Mon Aug 11 14:16:22 2014
>> >>>> @@ -46,7 +46,6 @@ public class FormattedMessage implements
>> >>>> this.messagePattern = messagePattern;
>> >>>> this.argArray = arguments;
>> >>>> this.throwable = throwable;
>> >>>> - getFormattedMessage(); // LOG4J2-763 take snapshot of parameters at message construction time
>> >>>> }
>> >>>>
>> >>>> public FormattedMessage(final String messagePattern, final Object[] arguments) {
>> >>>>
>> >>>> Modified: logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/LocalizedMessage.java
>> >>>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/LocalizedMessage.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>> >>>> ==============================================================================
>> >>>> --- logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/LocalizedMessage.java (original)
>> >>>> +++ logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/LocalizedMessage.java Mon Aug 11 14:16:22 2014
>> >>>> @@ -78,7 +78,6 @@ public class LocalizedMessage implements
>> >>>> this.baseName = baseName;
>> >>>> this.resourceBundle = null;
>> >>>> this.locale = locale;
>> >>>> - getFormattedMessage(); // LOG4J2-763 take snapshot of parameters at message construction time
>> >>>> }
>> >>>>
>> >>>> public LocalizedMessage(final ResourceBundle bundle, final Locale locale, final String key,
>> >>>> @@ -89,7 +88,6 @@ public class LocalizedMessage implements
>> >>>> this.baseName = null;
>> >>>> this.resourceBundle = bundle;
>> >>>> this.locale = locale;
>> >>>> - getFormattedMessage(); // LOG4J2-763 take snapshot of parameters at message construction time
>> >>>> }
>> >>>>
>> >>>> public LocalizedMessage(final Locale locale, final String key, final Object[] arguments) {
>> >>>>
>> >>>> Modified: logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/MessageFormatMessage.java
>> >>>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/MessageFormatMessage.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>> >>>> ==============================================================================
>> >>>> --- logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/MessageFormatMessage.java (original)
>> >>>> +++ logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/MessageFormatMessage.java Mon Aug 11 14:16:22 2014
>> >>>> @@ -49,7 +49,6 @@ public class MessageFormatMessage implem
>> >>>> if (arguments != null && arguments.length > 0 && arguments[arguments.length - 1] instanceof Throwable) {
>> >>>> this.throwable = (Throwable) arguments[arguments.length - 1];
>> >>>> }
>> >>>> - getFormattedMessage(); // LOG4J2-763 take snapshot of parameters at message construction time
>> >>>> }
>> >>>>
>> >>>> /**
>> >>>>
>> >>>> Modified: logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/ObjectMessage.java
>> >>>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/ObjectMessage.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>> >>>> ==============================================================================
>> >>>> --- logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/ObjectMessage.java (original)
>> >>>> +++ logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/ObjectMessage.java Mon Aug 11 14:16:22 2014
>> >>>> @@ -29,7 +29,7 @@ public class ObjectMessage implements Me
>> >>>> private static final long serialVersionUID = -5903272448334166185L;
>> >>>>
>> >>>> private transient Object obj;
>> >>>> - private final String objectString;
>> >>>> + private transient String objectString;
>> >>>>
>> >>>> /**
>> >>>> * Create the ObjectMessage.
>> >>>> @@ -40,9 +40,6 @@ public class ObjectMessage implements Me
>> >>>> obj = "null";
>> >>>> }
>> >>>> this.obj = obj;
>> >>>> -
>> >>>> - // LOG4J2-763: take snapshot of parameters at message construction time
>> >>>> - objectString = String.valueOf(obj);
>> >>>> }
>> >>>>
>> >>>> /**
>> >>>> @@ -51,6 +48,10 @@ public class ObjectMessage implements Me
>> >>>> */
>> >>>> @Override
>> >>>> public String getFormattedMessage() {
>> >>>> + // LOG4J2-763: cache formatted string in case obj changes later
>> >>>> + if (objectString == null) {
>> >>>> + objectString = String.valueOf(obj);
>> >>>> + }
>> >>>> return objectString;
>> >>>> }
>> >>>>
>> >>>> @@ -60,7 +61,7 @@ public class ObjectMessage implements Me
>> >>>> */
>> >>>> @Override
>> >>>> public String getFormat() {
>> >>>> - return objectString;
>> >>>> + return getFormattedMessage();
>> >>>> }
>> >>>>
>> >>>> /**
>> >>>> @@ -69,7 +70,7 @@ public class ObjectMessage implements Me
>> >>>> */
>> >>>> @Override
>> >>>> public Object[] getParameters() {
>> >>>> - return new Object[]{obj};
>> >>>> + return new Object[] { obj };
>> >>>> }
>> >>>>
>> >>>> @Override
>> >>>> @@ -82,8 +83,7 @@ public class ObjectMessage implements Me
>> >>>> }
>> >>>>
>> >>>> final ObjectMessage that = (ObjectMessage) o;
>> >>>> -
>> >>>> - return !(obj != null ? !obj.equals(that.obj) : that.obj != null);
>> >>>> + return obj == null ? that.obj == null : obj.equals(that.obj);
>> >>>> }
>> >>>>
>> >>>> @Override
>> >>>> @@ -93,7 +93,7 @@ public class ObjectMessage implements Me
>> >>>>
>> >>>> @Override
>> >>>> public String toString() {
>> >>>> - return "ObjectMessage[obj=" + objectString + ']';
>> >>>> + return "ObjectMessage[obj=" + getFormattedMessage() + ']';
>> >>>> }
>> >>>>
>> >>>> private void writeObject(final ObjectOutputStream out) throws IOException {
>> >>>> @@ -101,7 +101,7 @@ public class ObjectMessage implements Me
>> >>>> if (obj instanceof Serializable) {
>> >>>> out.writeObject(obj);
>> >>>> } else {
>> >>>> - out.writeObject(obj.toString());
>> >>>> + out.writeObject(String.valueOf(obj));
>> >>>> }
>> >>>> }
>> >>>>
>> >>>>
>> >>>> Modified: logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/StringFormattedMessage.java
>> >>>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/StringFormattedMessage.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>> >>>> ==============================================================================
>> >>>> --- logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/StringFormattedMessage.java (original)
>> >>>> +++ logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/StringFormattedMessage.java Mon Aug 11 14:16:22 2014
>> >>>> @@ -48,7 +48,6 @@ public class StringFormattedMessage impl
>> >>>> if (arguments != null && arguments.length > 0 && arguments[arguments.length - 1] instanceof Throwable) {
>> >>>> this.throwable = (Throwable) arguments[arguments.length - 1];
>> >>>> }
>> >>>> - getFormattedMessage(); // LOG4J2-763 take snapshot of parameters at message construction time
>> >>>> }
>> >>>>
>> >>>> /**
>> >>>>
>> >>>> Modified: logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/FormattedMessageTest.java
>> >>>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/FormattedMessageTest.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>> >>>> ==============================================================================
>> >>>> --- logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/FormattedMessageTest.java (original)
>> >>>> +++ logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/FormattedMessageTest.java Mon Aug 11 14:16:22 2014
>> >>>> @@ -85,14 +85,27 @@ public class FormattedMessageTest {
>> >>>> }
>> >>>>
>> >>>> @Test
>> >>>> - public void testSafeWithMutableParams() { // LOG4J2-763
>> >>>> + public void testUnsafeWithMutableParams() { // LOG4J2-763
>> >>>> final String testMsg = "Test message %s";
>> >>>> final Mutable param = new Mutable().set("abc");
>> >>>> - FormattedMessage msg = new FormattedMessage(testMsg, param);
>> >>>> + final FormattedMessage msg = new FormattedMessage(testMsg, param);
>> >>>>
>> >>>> // modify parameter before calling msg.getFormattedMessage
>> >>>> param.set("XYZ");
>> >>>> - String actual = msg.getFormattedMessage();
>> >>>> + final String actual = msg.getFormattedMessage();
>> >>>> + assertEquals("Expected most recent param value", "Test message XYZ", actual);
>> >>>> + }
>> >>>> +
>> >>>> + @Test
>> >>>> + public void testSafeAfterGetFormattedMessageIsCalled() { // LOG4J2-763
>> >>>> + final String testMsg = "Test message %s";
>> >>>> + final Mutable param = new Mutable().set("abc");
>> >>>> + final FormattedMessage msg = new FormattedMessage(testMsg, param);
>> >>>> +
>> >>>> + // modify parameter after calling msg.getFormattedMessage
>> >>>> + msg.getFormattedMessage(); // freeze the formatted message
>> >>>> + param.set("XYZ");
>> >>>> + final String actual = msg.getFormattedMessage();
>> >>>> assertEquals("Should use initial param value", "Test message abc", actual);
>> >>>> }
>> >>>> }
>> >>>>
>> >>>> Modified: logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/LocalizedMessageTest.java
>> >>>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/LocalizedMessageTest.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>> >>>> ==============================================================================
>> >>>> --- logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/LocalizedMessageTest.java (original)
>> >>>> +++ logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/LocalizedMessageTest.java Mon Aug 11 14:16:22 2014
>> >>>> @@ -65,15 +65,27 @@ public class LocalizedMessageTest {
>> >>>> }
>> >>>>
>> >>>> @Test
>> >>>> - public void testSafeWithMutableParams() { // LOG4J2-763
>> >>>> + public void testUnsafeWithMutableParams() { // LOG4J2-763
>> >>>> final String testMsg = "Test message %s";
>> >>>> final Mutable param = new Mutable().set("abc");
>> >>>> - LocalizedMessage msg = new LocalizedMessage(testMsg, param);
>> >>>> + final LocalizedMessage msg = new LocalizedMessage(testMsg, param);
>> >>>>
>> >>>> // modify parameter before calling msg.getFormattedMessage
>> >>>> param.set("XYZ");
>> >>>> - String actual = msg.getFormattedMessage();
>> >>>> - assertEquals("Should use initial param value", "Test message abc", actual);
>> >>>> + final String actual = msg.getFormattedMessage();
>> >>>> + assertEquals("Expected most recent param value", "Test message XYZ", actual);
>> >>>> }
>> >>>>
>> >>>> + @Test
>> >>>> + public void testSafeAfterGetFormattedMessageIsCalled() { // LOG4J2-763
>> >>>> + final String testMsg = "Test message %s";
>> >>>> + final Mutable param = new Mutable().set("abc");
>> >>>> + final LocalizedMessage msg = new LocalizedMessage(testMsg, param);
>> >>>> +
>> >>>> + // modify parameter after calling msg.getFormattedMessage
>> >>>> + msg.getFormattedMessage();
>> >>>> + param.set("XYZ");
>> >>>> + final String actual = msg.getFormattedMessage();
>> >>>> + assertEquals("Should use initial param value", "Test message abc", actual);
>> >>>> + }
>> >>>> }
>> >>>>
>> >>>> Modified: logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/MessageFormatMessageTest.java
>> >>>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/MessageFormatMessageTest.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>> >>>> ==============================================================================
>> >>>> --- logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/MessageFormatMessageTest.java (original)
>> >>>> +++ logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/MessageFormatMessageTest.java Mon Aug 11 14:16:22 2014
>> >>>> @@ -63,14 +63,27 @@ public class MessageFormatMessageTest {
>> >>>> }
>> >>>>
>> >>>> @Test
>> >>>> - public void testSafeWithMutableParams() { // LOG4J2-763
>> >>>> + public void testUnsafeWithMutableParams() { // LOG4J2-763
>> >>>> final String testMsg = "Test message {0}";
>> >>>> final Mutable param = new Mutable().set("abc");
>> >>>> - MessageFormatMessage msg = new MessageFormatMessage(testMsg, param);
>> >>>> + final MessageFormatMessage msg = new MessageFormatMessage(testMsg, param);
>> >>>>
>> >>>> // modify parameter before calling msg.getFormattedMessage
>> >>>> param.set("XYZ");
>> >>>> - String actual = msg.getFormattedMessage();
>> >>>> + final String actual = msg.getFormattedMessage();
>> >>>> + assertEquals("Expected most recent param value", "Test message XYZ", actual);
>> >>>> + }
>> >>>> +
>> >>>> + @Test
>> >>>> + public void testSafeAfterGetFormattedMessageIsCalled() { // LOG4J2-763
>> >>>> + final String testMsg = "Test message {0}";
>> >>>> + final Mutable param = new Mutable().set("abc");
>> >>>> + final MessageFormatMessage msg = new MessageFormatMessage(testMsg, param);
>> >>>> +
>> >>>> + // modify parameter after calling msg.getFormattedMessage
>> >>>> + msg.getFormattedMessage();
>> >>>> + param.set("XYZ");
>> >>>> + final String actual = msg.getFormattedMessage();
>> >>>> assertEquals("Should use initial param value", "Test message abc", actual);
>> >>>> }
>> >>>> }
>> >>>>
>> >>>> Modified: logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/ObjectMessageTest.java
>> >>>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/ObjectMessageTest.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>> >>>> ==============================================================================
>> >>>> --- logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/ObjectMessageTest.java (original)
>> >>>> +++ logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/ObjectMessageTest.java Mon Aug 11 14:16:22 2014
>> >>>> @@ -41,13 +41,25 @@ public class ObjectMessageTest {
>> >>>> }
>> >>>>
>> >>>> @Test
>> >>>> - public void testSafeWithMutableParams() { // LOG4J2-763
>> >>>> + public void testUnsafeWithMutableParams() { // LOG4J2-763
>> >>>> final Mutable param = new Mutable().set("abc");
>> >>>> - ObjectMessage msg = new ObjectMessage(param);
>> >>>> + final ObjectMessage msg = new ObjectMessage(param);
>> >>>>
>> >>>> // modify parameter before calling msg.getFormattedMessage
>> >>>> param.set("XYZ");
>> >>>> - String actual = msg.getFormattedMessage();
>> >>>> + final String actual = msg.getFormattedMessage();
>> >>>> + assertEquals("Expected most recent param value", "XYZ", actual);
>> >>>> + }
>> >>>> +
>> >>>> + @Test
>> >>>> + public void testSafeAfterGetFormattedMessageIsCalled() { // LOG4J2-763
>> >>>> + final Mutable param = new Mutable().set("abc");
>> >>>> + final ObjectMessage msg = new ObjectMessage(param);
>> >>>> +
>> >>>> + // modify parameter after calling msg.getFormattedMessage
>> >>>> + msg.getFormattedMessage();
>> >>>> + param.set("XYZ");
>> >>>> + final String actual = msg.getFormattedMessage();
>> >>>> assertEquals("Should use initial param value", "abc", actual);
>> >>>> }
>> >>>> }
>> >>>>
>> >>>> Modified: logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/StringFormattedMessageTest.java
>> >>>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/StringFormattedMessageTest.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>> >>>> ==============================================================================
>> >>>> --- logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/StringFormattedMessageTest.java (original)
>> >>>> +++ logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/StringFormattedMessageTest.java Mon Aug 11 14:16:22 2014
>> >>>> @@ -62,14 +62,27 @@ public class StringFormattedMessageTest
>> >>>> }
>> >>>>
>> >>>> @Test
>> >>>> - public void testSafeWithMutableParams() { // LOG4J2-763
>> >>>> + public void testUnsafeWithMutableParams() { // LOG4J2-763
>> >>>> final String testMsg = "Test message %s";
>> >>>> final Mutable param = new Mutable().set("abc");
>> >>>> - StringFormattedMessage msg = new StringFormattedMessage(testMsg, param);
>> >>>> + final StringFormattedMessage msg = new StringFormattedMessage(testMsg, param);
>> >>>>
>> >>>> // modify parameter before calling msg.getFormattedMessage
>> >>>> param.set("XYZ");
>> >>>> - String actual = msg.getFormattedMessage();
>> >>>> + final String actual = msg.getFormattedMessage();
>> >>>> + assertEquals("Should use initial param value", "Test message XYZ", actual);
>> >>>> + }
>> >>>> +
>> >>>> + @Test
>> >>>> + public void testSafeAfterGetFormattedMessageIsCalled() { // LOG4J2-763
>> >>>> + final String testMsg = "Test message %s";
>> >>>> + final Mutable param = new Mutable().set("abc");
>> >>>> + final StringFormattedMessage msg = new StringFormattedMessage(testMsg, param);
>> >>>> +
>> >>>> + // modify parameter after calling msg.getFormattedMessage
>> >>>> + msg.getFormattedMessage();
>> >>>> + param.set("XYZ");
>> >>>> + final String actual = msg.getFormattedMessage();
>> >>>> assertEquals("Should use initial param value", "Test message abc", actual);
>> >>>> }
>> >>>> }
>> >>>>
>> >>>> Modified: logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java
>> >>>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>> >>>> ==============================================================================
>> >>>> --- logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java (original)
>> >>>> +++ logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java Mon Aug 11 14:16:22 2014
>> >>>> @@ -138,6 +138,7 @@ public final class AsyncAppender extends
>> >>>> }
>> >>>> logEvent = ((RingBufferLogEvent) logEvent).createMemento();
>> >>>> }
>> >>>> + logEvent.getMessage().getFormattedMessage(); // LOG4J2-763: ask message to freeze parameters
>> >>>> final Log4jLogEvent coreEvent = (Log4jLogEvent) logEvent;
>> >>>> boolean appendSuccessful = false;
>> >>>> if (blocking) {
>> >>>>
>> >>>> Modified: logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java
>> >>>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>> >>>> ==============================================================================
>> >>>> --- logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java (original)
>> >>>> +++ logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java Mon Aug 11 14:16:22 2014
>> >>>> @@ -226,6 +226,7 @@ public class AsyncLogger extends Logger
>> >>>>
>> >>>> @Override
>> >>>> public void logMessage(final String fqcn, final Level level, final Marker marker, final Message message, final Throwable thrown) {
>> >>>> + // TODO refactor to reduce size to <= 35 bytecodes to allow JVM to inline it
>> >>>> Info info = threadlocalInfo.get();
>> >>>> if (info == null) {
>> >>>> info = new Info(new RingBufferLogEventTranslator(), Thread.currentThread().getName(), false);
>> >>>> @@ -245,6 +246,7 @@ public class AsyncLogger extends Logger
>> >>>> config.loggerConfig.log(getName(), fqcn, marker, level, message, thrown);
>> >>>> return;
>> >>>> }
>> >>>> + message.getFormattedMessage(); // LOG4J2-763: ask message to freeze parameters
>> >>>> final boolean includeLocation = config.loggerConfig.isIncludeLocation();
>> >>>> info.translator.setValues(this, getName(), marker, fqcn, level, message, //
>> >>>> // don't construct ThrowableProxy until required
>> >>>>
>> >>>> Modified: logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java
>> >>>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>> >>>> ==============================================================================
>> >>>> --- logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java (original)
>> >>>> +++ logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java Mon Aug 11 14:16:22 2014
>> >>>> @@ -316,6 +316,7 @@ class AsyncLoggerConfigHelper {
>> >>>> * calling thread needs to process the event itself
>> >>>> */
>> >>>> public boolean callAppendersFromAnotherThread(final LogEvent event) {
>> >>>> + // TODO refactor to reduce size to <= 35 bytecodes to allow JVM to inline it
>> >>>> final Disruptor<Log4jEventWrapper> temp = disruptor;
>> >>>> if (temp == null) { // LOG4J2-639
>> >>>> LOGGER.fatal("Ignoring log event after log4j was shut down");
>> >>>> @@ -336,6 +337,8 @@ class AsyncLoggerConfigHelper {
>> >>>> if (event instanceof RingBufferLogEvent) {
>> >>>> logEvent = ((RingBufferLogEvent) event).createMemento();
>> >>>> }
>> >>>> + logEvent.getMessage().getFormattedMessage(); // LOG4J2-763: ask message to freeze parameters
>> >>>> +
>> >>>> // Note: do NOT use the temp variable above!
>> >>>> // That could result in adding a log event to the disruptor after it was shut down,
>> >>>> // which could cause the publishEvent method to hang and never return.
>> >>>>
>> >>>> Modified: logging/log4j/log4j2/trunk/src/changes/changes.xml
>> >>>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/src/changes/changes.xml?rev=1617291&r1=1617290&r2=1617291&view=diff
>> >>>> ==============================================================================
>> >>>> --- logging/log4j/log4j2/trunk/src/changes/changes.xml (original)
>> >>>> +++ logging/log4j/log4j2/trunk/src/changes/changes.xml Mon Aug 11 14:16:22 2014
>> >>>> @@ -29,8 +29,7 @@
>> >>>> Startup takes a long time if you have empty packages attribute.
>> >>>> </action>
>> >>>> <action issue="LOG4J2-763" dev="rpopma" type="fix" due-to="Stephen Connolly">
>> >>>> - Improved FormattedMessage, StringFormattedMessage, LocalizedMessage, MessageFormatMessage and
>> >>>> - ObjectMessage for asynchronous logging to ensure the formatted message does not change even if
>> >>>> + Improved asynchronous loggers and appenders to ensure the formatted message does not change even if
>> >>>> parameters are modified by the application. (ParameterizedMessage was already safe.)
>> >>>> Improved documentation.
>> >>>> </action>
>> >>>
>> >>>
>> >>> ---------------------------------------------------------------------
>> >>> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
>> >>> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>> >>
>> >> ---------------------------------------------------------------------
>> >> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
>> >> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>> >
>> >
>> > ---------------------------------------------------------------------
>> > To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
>> > For additional commands, e-mail: log4j-dev-help@logging.apache.org
>> >
>
Re: svn commit: r1617291 - in /logging/log4j/log4j2/trunk:
log4j-api/src/main/java/org/apache/logging/log4j/message/ log4j-api/src/test/java/org/apache/logging/log4j/message/
log4j-core/src/main/java/org/apache/logging/log4j/core/appender/ log4j-core/src/m...
Posted by Remko Popma <re...@gmail.com>.
Well, you were right there was something fishy with the deserialization.
If the ObjectMessage parameter is not Serializable, it gets serialized as a
string.
Then, originalObjectMessage.equals(deserializedObjectMessage) returns false
since ObjectMessage.equals does not take into account that the parameter
may have been turned into a string.
I've added a JUnit test to illustrate the problem (now @Ignored or it would
break the build).
I propose that we modify the equals method to also compare the string
version of the objMessage parameter.
Thoughts?
On Tue, Aug 12, 2014 at 8:33 AM, Remko Popma <re...@gmail.com> wrote:
> I'll add a junit test, but this is what it was before I started touching
> that class (except for obj.toString() -> String.valueOf(obj)).
>
> Sent from my iPhone
>
> > On 2014/08/12, at 8:02, Ralph Goers <ra...@dslextreme.com> wrote:
> >
> > Serialization does:
> >
> > if (obj instanceof Serializable) {
> > out.writeObject(obj);
> > } else {
> > out.writeObject(String.valueOf(obj));
> > }
> >
> > Deserialization does:
> >
> > in.defaultReadObject();
> > obj = in.readObject();
> >
> > So if obj is not Serializable a String will be written. Upon
> deserialization obj will be set to either the the deserialized version of
> the object or to the String. I guess this will work.
> >
> > Ralph
> >
> >
> >> On Aug 11, 2014, at 2:46 PM, Remko Popma <re...@gmail.com> wrote:
> >>
> >> I didn't change the serialization behavior. I only changed
> >> obj.toString()
> >> to
> >> String.valueOf(obj)
> >>
> >> The stringValue field wasn't there originally (I incorrectly added it
> as non-transient in my first attempt). It is now transient so serialized
> form should be the same as pre-change.
> >>
> >> The serialization behavior of ObjectMessage has always been to
> serialize as Object if possible (Serializable), otherwise as String.
> Deserialization will just read whatever was serialized. That may not be the
> same object field but is the best we can do.
> >>
> >> Or did I miss something? (away from PC)
> >>
> >> Sent from my iPhone
> >>
> >>> On 2014/08/12, at 2:38, Ralph Goers <ra...@dslextreme.com>
> wrote:
> >>>
> >>> I believe this breaks deserialization of ObjectMessage. It is being
> serialized as either the serialized form of the Object or as a String.
> Deserialization doesn't account for this.
> >>>
> >>> Ralph
> >>>
> >>>> On Aug 11, 2014, at 7:16 AM, rpopma@apache.org wrote:
> >>>>
> >>>> Author: rpopma
> >>>> Date: Mon Aug 11 14:16:22 2014
> >>>> New Revision: 1617291
> >>>>
> >>>> URL: http://svn.apache.org/r1617291
> >>>> Log:
> >>>> LOG4J2-763: use different mechanism to solve this problem: instead of
> initializing the formatted message string in the message constructor,
> postpone this as long as possible until getFormattedMessage() is called.
> Async loggers and AsyncAppender now call message.getFormattedMessage()
> before passing the log event to the background thread. Added more tests.
> >>>>
> >>>> Modified:
> >>>>
> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/FormattedMessage.java
> >>>>
> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/LocalizedMessage.java
> >>>>
> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/MessageFormatMessage.java
> >>>>
> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/ObjectMessage.java
> >>>>
> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/StringFormattedMessage.java
> >>>>
> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/FormattedMessageTest.java
> >>>>
> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/LocalizedMessageTest.java
> >>>>
> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/MessageFormatMessageTest.java
> >>>>
> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/ObjectMessageTest.java
> >>>>
> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/StringFormattedMessageTest.java
> >>>>
> logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java
> >>>>
> logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java
> >>>>
> logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java
> >>>> logging/log4j/log4j2/trunk/src/changes/changes.xml
> >>>>
> >>>> Modified:
> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/FormattedMessage.java
> >>>> URL:
> http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/FormattedMessage.java?rev=1617291&r1=1617290&r2=1617291&view=diff
> >>>>
> ==============================================================================
> >>>> ---
> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/FormattedMessage.java
> (original)
> >>>> +++
> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/FormattedMessage.java
> Mon Aug 11 14:16:22 2014
> >>>> @@ -46,7 +46,6 @@ public class FormattedMessage implements
> >>>> this.messagePattern = messagePattern;
> >>>> this.argArray = arguments;
> >>>> this.throwable = throwable;
> >>>> - getFormattedMessage(); // LOG4J2-763 take snapshot of
> parameters at message construction time
> >>>> }
> >>>>
> >>>> public FormattedMessage(final String messagePattern, final Object[]
> arguments) {
> >>>>
> >>>> Modified:
> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/LocalizedMessage.java
> >>>> URL:
> http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/LocalizedMessage.java?rev=1617291&r1=1617290&r2=1617291&view=diff
> >>>>
> ==============================================================================
> >>>> ---
> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/LocalizedMessage.java
> (original)
> >>>> +++
> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/LocalizedMessage.java
> Mon Aug 11 14:16:22 2014
> >>>> @@ -78,7 +78,6 @@ public class LocalizedMessage implements
> >>>> this.baseName = baseName;
> >>>> this.resourceBundle = null;
> >>>> this.locale = locale;
> >>>> - getFormattedMessage(); // LOG4J2-763 take snapshot of
> parameters at message construction time
> >>>> }
> >>>>
> >>>> public LocalizedMessage(final ResourceBundle bundle, final Locale
> locale, final String key,
> >>>> @@ -89,7 +88,6 @@ public class LocalizedMessage implements
> >>>> this.baseName = null;
> >>>> this.resourceBundle = bundle;
> >>>> this.locale = locale;
> >>>> - getFormattedMessage(); // LOG4J2-763 take snapshot of
> parameters at message construction time
> >>>> }
> >>>>
> >>>> public LocalizedMessage(final Locale locale, final String key, final
> Object[] arguments) {
> >>>>
> >>>> Modified:
> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/MessageFormatMessage.java
> >>>> URL:
> http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/MessageFormatMessage.java?rev=1617291&r1=1617290&r2=1617291&view=diff
> >>>>
> ==============================================================================
> >>>> ---
> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/MessageFormatMessage.java
> (original)
> >>>> +++
> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/MessageFormatMessage.java
> Mon Aug 11 14:16:22 2014
> >>>> @@ -49,7 +49,6 @@ public class MessageFormatMessage implem
> >>>> if (arguments != null && arguments.length > 0 &&
> arguments[arguments.length - 1] instanceof Throwable) {
> >>>> this.throwable = (Throwable) arguments[arguments.length - 1];
> >>>> }
> >>>> - getFormattedMessage(); // LOG4J2-763 take snapshot of
> parameters at message construction time
> >>>> }
> >>>>
> >>>> /**
> >>>>
> >>>> Modified:
> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/ObjectMessage.java
> >>>> URL:
> http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/ObjectMessage.java?rev=1617291&r1=1617290&r2=1617291&view=diff
> >>>>
> ==============================================================================
> >>>> ---
> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/ObjectMessage.java
> (original)
> >>>> +++
> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/ObjectMessage.java
> Mon Aug 11 14:16:22 2014
> >>>> @@ -29,7 +29,7 @@ public class ObjectMessage implements Me
> >>>> private static final long serialVersionUID = -5903272448334166185L;
> >>>>
> >>>> private transient Object obj;
> >>>> - private final String objectString;
> >>>> + private transient String objectString;
> >>>>
> >>>> /**
> >>>> * Create the ObjectMessage.
> >>>> @@ -40,9 +40,6 @@ public class ObjectMessage implements Me
> >>>> obj = "null";
> >>>> }
> >>>> this.obj = obj;
> >>>> -
> >>>> - // LOG4J2-763: take snapshot of parameters at message
> construction time
> >>>> - objectString = String.valueOf(obj);
> >>>> }
> >>>>
> >>>> /**
> >>>> @@ -51,6 +48,10 @@ public class ObjectMessage implements Me
> >>>> */
> >>>> @Override
> >>>> public String getFormattedMessage() {
> >>>> + // LOG4J2-763: cache formatted string in case obj changes
> later
> >>>> + if (objectString == null) {
> >>>> + objectString = String.valueOf(obj);
> >>>> + }
> >>>> return objectString;
> >>>> }
> >>>>
> >>>> @@ -60,7 +61,7 @@ public class ObjectMessage implements Me
> >>>> */
> >>>> @Override
> >>>> public String getFormat() {
> >>>> - return objectString;
> >>>> + return getFormattedMessage();
> >>>> }
> >>>>
> >>>> /**
> >>>> @@ -69,7 +70,7 @@ public class ObjectMessage implements Me
> >>>> */
> >>>> @Override
> >>>> public Object[] getParameters() {
> >>>> - return new Object[]{obj};
> >>>> + return new Object[] { obj };
> >>>> }
> >>>>
> >>>> @Override
> >>>> @@ -82,8 +83,7 @@ public class ObjectMessage implements Me
> >>>> }
> >>>>
> >>>> final ObjectMessage that = (ObjectMessage) o;
> >>>> -
> >>>> - return !(obj != null ? !obj.equals(that.obj) : that.obj !=
> null);
> >>>> + return obj == null ? that.obj == null : obj.equals(that.obj);
> >>>> }
> >>>>
> >>>> @Override
> >>>> @@ -93,7 +93,7 @@ public class ObjectMessage implements Me
> >>>>
> >>>> @Override
> >>>> public String toString() {
> >>>> - return "ObjectMessage[obj=" + objectString + ']';
> >>>> + return "ObjectMessage[obj=" + getFormattedMessage() + ']';
> >>>> }
> >>>>
> >>>> private void writeObject(final ObjectOutputStream out) throws
> IOException {
> >>>> @@ -101,7 +101,7 @@ public class ObjectMessage implements Me
> >>>> if (obj instanceof Serializable) {
> >>>> out.writeObject(obj);
> >>>> } else {
> >>>> - out.writeObject(obj.toString());
> >>>> + out.writeObject(String.valueOf(obj));
> >>>> }
> >>>> }
> >>>>
> >>>>
> >>>> Modified:
> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/StringFormattedMessage.java
> >>>> URL:
> http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/StringFormattedMessage.java?rev=1617291&r1=1617290&r2=1617291&view=diff
> >>>>
> ==============================================================================
> >>>> ---
> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/StringFormattedMessage.java
> (original)
> >>>> +++
> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/StringFormattedMessage.java
> Mon Aug 11 14:16:22 2014
> >>>> @@ -48,7 +48,6 @@ public class StringFormattedMessage impl
> >>>> if (arguments != null && arguments.length > 0 &&
> arguments[arguments.length - 1] instanceof Throwable) {
> >>>> this.throwable = (Throwable) arguments[arguments.length - 1];
> >>>> }
> >>>> - getFormattedMessage(); // LOG4J2-763 take snapshot of
> parameters at message construction time
> >>>> }
> >>>>
> >>>> /**
> >>>>
> >>>> Modified:
> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/FormattedMessageTest.java
> >>>> URL:
> http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/FormattedMessageTest.java?rev=1617291&r1=1617290&r2=1617291&view=diff
> >>>>
> ==============================================================================
> >>>> ---
> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/FormattedMessageTest.java
> (original)
> >>>> +++
> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/FormattedMessageTest.java
> Mon Aug 11 14:16:22 2014
> >>>> @@ -85,14 +85,27 @@ public class FormattedMessageTest {
> >>>> }
> >>>>
> >>>> @Test
> >>>> - public void testSafeWithMutableParams() { // LOG4J2-763
> >>>> + public void testUnsafeWithMutableParams() { // LOG4J2-763
> >>>> final String testMsg = "Test message %s";
> >>>> final Mutable param = new Mutable().set("abc");
> >>>> - FormattedMessage msg = new FormattedMessage(testMsg, param);
> >>>> + final FormattedMessage msg = new FormattedMessage(testMsg,
> param);
> >>>>
> >>>> // modify parameter before calling msg.getFormattedMessage
> >>>> param.set("XYZ");
> >>>> - String actual = msg.getFormattedMessage();
> >>>> + final String actual = msg.getFormattedMessage();
> >>>> + assertEquals("Expected most recent param value", "Test
> message XYZ", actual);
> >>>> + }
> >>>> +
> >>>> + @Test
> >>>> + public void testSafeAfterGetFormattedMessageIsCalled() { //
> LOG4J2-763
> >>>> + final String testMsg = "Test message %s";
> >>>> + final Mutable param = new Mutable().set("abc");
> >>>> + final FormattedMessage msg = new FormattedMessage(testMsg,
> param);
> >>>> +
> >>>> + // modify parameter after calling msg.getFormattedMessage
> >>>> + msg.getFormattedMessage(); // freeze the formatted message
> >>>> + param.set("XYZ");
> >>>> + final String actual = msg.getFormattedMessage();
> >>>> assertEquals("Should use initial param value", "Test message
> abc", actual);
> >>>> }
> >>>> }
> >>>>
> >>>> Modified:
> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/LocalizedMessageTest.java
> >>>> URL:
> http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/LocalizedMessageTest.java?rev=1617291&r1=1617290&r2=1617291&view=diff
> >>>>
> ==============================================================================
> >>>> ---
> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/LocalizedMessageTest.java
> (original)
> >>>> +++
> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/LocalizedMessageTest.java
> Mon Aug 11 14:16:22 2014
> >>>> @@ -65,15 +65,27 @@ public class LocalizedMessageTest {
> >>>> }
> >>>>
> >>>> @Test
> >>>> - public void testSafeWithMutableParams() { // LOG4J2-763
> >>>> + public void testUnsafeWithMutableParams() { // LOG4J2-763
> >>>> final String testMsg = "Test message %s";
> >>>> final Mutable param = new Mutable().set("abc");
> >>>> - LocalizedMessage msg = new LocalizedMessage(testMsg, param);
> >>>> + final LocalizedMessage msg = new LocalizedMessage(testMsg,
> param);
> >>>>
> >>>> // modify parameter before calling msg.getFormattedMessage
> >>>> param.set("XYZ");
> >>>> - String actual = msg.getFormattedMessage();
> >>>> - assertEquals("Should use initial param value", "Test message
> abc", actual);
> >>>> + final String actual = msg.getFormattedMessage();
> >>>> + assertEquals("Expected most recent param value", "Test
> message XYZ", actual);
> >>>> }
> >>>>
> >>>> + @Test
> >>>> + public void testSafeAfterGetFormattedMessageIsCalled() { //
> LOG4J2-763
> >>>> + final String testMsg = "Test message %s";
> >>>> + final Mutable param = new Mutable().set("abc");
> >>>> + final LocalizedMessage msg = new LocalizedMessage(testMsg,
> param);
> >>>> +
> >>>> + // modify parameter after calling msg.getFormattedMessage
> >>>> + msg.getFormattedMessage();
> >>>> + param.set("XYZ");
> >>>> + final String actual = msg.getFormattedMessage();
> >>>> + assertEquals("Should use initial param value", "Test message
> abc", actual);
> >>>> + }
> >>>> }
> >>>>
> >>>> Modified:
> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/MessageFormatMessageTest.java
> >>>> URL:
> http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/MessageFormatMessageTest.java?rev=1617291&r1=1617290&r2=1617291&view=diff
> >>>>
> ==============================================================================
> >>>> ---
> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/MessageFormatMessageTest.java
> (original)
> >>>> +++
> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/MessageFormatMessageTest.java
> Mon Aug 11 14:16:22 2014
> >>>> @@ -63,14 +63,27 @@ public class MessageFormatMessageTest {
> >>>> }
> >>>>
> >>>> @Test
> >>>> - public void testSafeWithMutableParams() { // LOG4J2-763
> >>>> + public void testUnsafeWithMutableParams() { // LOG4J2-763
> >>>> final String testMsg = "Test message {0}";
> >>>> final Mutable param = new Mutable().set("abc");
> >>>> - MessageFormatMessage msg = new MessageFormatMessage(testMsg,
> param);
> >>>> + final MessageFormatMessage msg = new
> MessageFormatMessage(testMsg, param);
> >>>>
> >>>> // modify parameter before calling msg.getFormattedMessage
> >>>> param.set("XYZ");
> >>>> - String actual = msg.getFormattedMessage();
> >>>> + final String actual = msg.getFormattedMessage();
> >>>> + assertEquals("Expected most recent param value", "Test
> message XYZ", actual);
> >>>> + }
> >>>> +
> >>>> + @Test
> >>>> + public void testSafeAfterGetFormattedMessageIsCalled() { //
> LOG4J2-763
> >>>> + final String testMsg = "Test message {0}";
> >>>> + final Mutable param = new Mutable().set("abc");
> >>>> + final MessageFormatMessage msg = new
> MessageFormatMessage(testMsg, param);
> >>>> +
> >>>> + // modify parameter after calling msg.getFormattedMessage
> >>>> + msg.getFormattedMessage();
> >>>> + param.set("XYZ");
> >>>> + final String actual = msg.getFormattedMessage();
> >>>> assertEquals("Should use initial param value", "Test message
> abc", actual);
> >>>> }
> >>>> }
> >>>>
> >>>> Modified:
> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/ObjectMessageTest.java
> >>>> URL:
> http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/ObjectMessageTest.java?rev=1617291&r1=1617290&r2=1617291&view=diff
> >>>>
> ==============================================================================
> >>>> ---
> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/ObjectMessageTest.java
> (original)
> >>>> +++
> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/ObjectMessageTest.java
> Mon Aug 11 14:16:22 2014
> >>>> @@ -41,13 +41,25 @@ public class ObjectMessageTest {
> >>>> }
> >>>>
> >>>> @Test
> >>>> - public void testSafeWithMutableParams() { // LOG4J2-763
> >>>> + public void testUnsafeWithMutableParams() { // LOG4J2-763
> >>>> final Mutable param = new Mutable().set("abc");
> >>>> - ObjectMessage msg = new ObjectMessage(param);
> >>>> + final ObjectMessage msg = new ObjectMessage(param);
> >>>>
> >>>> // modify parameter before calling msg.getFormattedMessage
> >>>> param.set("XYZ");
> >>>> - String actual = msg.getFormattedMessage();
> >>>> + final String actual = msg.getFormattedMessage();
> >>>> + assertEquals("Expected most recent param value", "XYZ",
> actual);
> >>>> + }
> >>>> +
> >>>> + @Test
> >>>> + public void testSafeAfterGetFormattedMessageIsCalled() { //
> LOG4J2-763
> >>>> + final Mutable param = new Mutable().set("abc");
> >>>> + final ObjectMessage msg = new ObjectMessage(param);
> >>>> +
> >>>> + // modify parameter after calling msg.getFormattedMessage
> >>>> + msg.getFormattedMessage();
> >>>> + param.set("XYZ");
> >>>> + final String actual = msg.getFormattedMessage();
> >>>> assertEquals("Should use initial param value", "abc", actual);
> >>>> }
> >>>> }
> >>>>
> >>>> Modified:
> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/StringFormattedMessageTest.java
> >>>> URL:
> http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/StringFormattedMessageTest.java?rev=1617291&r1=1617290&r2=1617291&view=diff
> >>>>
> ==============================================================================
> >>>> ---
> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/StringFormattedMessageTest.java
> (original)
> >>>> +++
> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/StringFormattedMessageTest.java
> Mon Aug 11 14:16:22 2014
> >>>> @@ -62,14 +62,27 @@ public class StringFormattedMessageTest
> >>>> }
> >>>>
> >>>> @Test
> >>>> - public void testSafeWithMutableParams() { // LOG4J2-763
> >>>> + public void testUnsafeWithMutableParams() { // LOG4J2-763
> >>>> final String testMsg = "Test message %s";
> >>>> final Mutable param = new Mutable().set("abc");
> >>>> - StringFormattedMessage msg = new
> StringFormattedMessage(testMsg, param);
> >>>> + final StringFormattedMessage msg = new
> StringFormattedMessage(testMsg, param);
> >>>>
> >>>> // modify parameter before calling msg.getFormattedMessage
> >>>> param.set("XYZ");
> >>>> - String actual = msg.getFormattedMessage();
> >>>> + final String actual = msg.getFormattedMessage();
> >>>> + assertEquals("Should use initial param value", "Test message
> XYZ", actual);
> >>>> + }
> >>>> +
> >>>> + @Test
> >>>> + public void testSafeAfterGetFormattedMessageIsCalled() { //
> LOG4J2-763
> >>>> + final String testMsg = "Test message %s";
> >>>> + final Mutable param = new Mutable().set("abc");
> >>>> + final StringFormattedMessage msg = new
> StringFormattedMessage(testMsg, param);
> >>>> +
> >>>> + // modify parameter after calling msg.getFormattedMessage
> >>>> + msg.getFormattedMessage();
> >>>> + param.set("XYZ");
> >>>> + final String actual = msg.getFormattedMessage();
> >>>> assertEquals("Should use initial param value", "Test message
> abc", actual);
> >>>> }
> >>>> }
> >>>>
> >>>> Modified:
> logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java
> >>>> URL:
> http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java?rev=1617291&r1=1617290&r2=1617291&view=diff
> >>>>
> ==============================================================================
> >>>> ---
> logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java
> (original)
> >>>> +++
> logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java
> Mon Aug 11 14:16:22 2014
> >>>> @@ -138,6 +138,7 @@ public final class AsyncAppender extends
> >>>> }
> >>>> logEvent = ((RingBufferLogEvent) logEvent).createMemento();
> >>>> }
> >>>> + logEvent.getMessage().getFormattedMessage(); // LOG4J2-763:
> ask message to freeze parameters
> >>>> final Log4jLogEvent coreEvent = (Log4jLogEvent) logEvent;
> >>>> boolean appendSuccessful = false;
> >>>> if (blocking) {
> >>>>
> >>>> Modified:
> logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java
> >>>> URL:
> http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java?rev=1617291&r1=1617290&r2=1617291&view=diff
> >>>>
> ==============================================================================
> >>>> ---
> logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java
> (original)
> >>>> +++
> logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java
> Mon Aug 11 14:16:22 2014
> >>>> @@ -226,6 +226,7 @@ public class AsyncLogger extends Logger
> >>>>
> >>>> @Override
> >>>> public void logMessage(final String fqcn, final Level level, final
> Marker marker, final Message message, final Throwable thrown) {
> >>>> + // TODO refactor to reduce size to <= 35 bytecodes to allow
> JVM to inline it
> >>>> Info info = threadlocalInfo.get();
> >>>> if (info == null) {
> >>>> info = new Info(new RingBufferLogEventTranslator(),
> Thread.currentThread().getName(), false);
> >>>> @@ -245,6 +246,7 @@ public class AsyncLogger extends Logger
> >>>> config.loggerConfig.log(getName(), fqcn, marker, level,
> message, thrown);
> >>>> return;
> >>>> }
> >>>> + message.getFormattedMessage(); // LOG4J2-763: ask message to
> freeze parameters
> >>>> final boolean includeLocation =
> config.loggerConfig.isIncludeLocation();
> >>>> info.translator.setValues(this, getName(), marker, fqcn, level,
> message, //
> >>>> // don't construct ThrowableProxy until required
> >>>>
> >>>> Modified:
> logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java
> >>>> URL:
> http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java?rev=1617291&r1=1617290&r2=1617291&view=diff
> >>>>
> ==============================================================================
> >>>> ---
> logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java
> (original)
> >>>> +++
> logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java
> Mon Aug 11 14:16:22 2014
> >>>> @@ -316,6 +316,7 @@ class AsyncLoggerConfigHelper {
> >>>> * calling thread needs to process the event itself
> >>>> */
> >>>> public boolean callAppendersFromAnotherThread(final LogEvent event) {
> >>>> + // TODO refactor to reduce size to <= 35 bytecodes to allow
> JVM to inline it
> >>>> final Disruptor<Log4jEventWrapper> temp = disruptor;
> >>>> if (temp == null) { // LOG4J2-639
> >>>> LOGGER.fatal("Ignoring log event after log4j was shut down");
> >>>> @@ -336,6 +337,8 @@ class AsyncLoggerConfigHelper {
> >>>> if (event instanceof RingBufferLogEvent) {
> >>>> logEvent = ((RingBufferLogEvent) event).createMemento();
> >>>> }
> >>>> + logEvent.getMessage().getFormattedMessage(); //
> LOG4J2-763: ask message to freeze parameters
> >>>> +
> >>>> // Note: do NOT use the temp variable above!
> >>>> // That could result in adding a log event to the disruptor
> after it was shut down,
> >>>> // which could cause the publishEvent method to hang and
> never return.
> >>>>
> >>>> Modified: logging/log4j/log4j2/trunk/src/changes/changes.xml
> >>>> URL:
> http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/src/changes/changes.xml?rev=1617291&r1=1617290&r2=1617291&view=diff
> >>>>
> ==============================================================================
> >>>> --- logging/log4j/log4j2/trunk/src/changes/changes.xml (original)
> >>>> +++ logging/log4j/log4j2/trunk/src/changes/changes.xml Mon Aug 11
> 14:16:22 2014
> >>>> @@ -29,8 +29,7 @@
> >>>> Startup takes a long time if you have empty packages attribute.
> >>>> </action>
> >>>> <action issue="LOG4J2-763" dev="rpopma" type="fix" due-to="Stephen
> Connolly">
> >>>> - Improved FormattedMessage, StringFormattedMessage,
> LocalizedMessage, MessageFormatMessage and
> >>>> - ObjectMessage for asynchronous logging to ensure the
> formatted message does not change even if
> >>>> + Improved asynchronous loggers and appenders to ensure the
> formatted message does not change even if
> >>>> parameters are modified by the application.
> (ParameterizedMessage was already safe.)
> >>>> Improved documentation.
> >>>> </action>
> >>>
> >>>
> >>> ---------------------------------------------------------------------
> >>> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
> >>> For additional commands, e-mail: log4j-dev-help@logging.apache.org
> >>
> >> ---------------------------------------------------------------------
> >> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
> >> For additional commands, e-mail: log4j-dev-help@logging.apache.org
> >
> >
> > ---------------------------------------------------------------------
> > To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
> > For additional commands, e-mail: log4j-dev-help@logging.apache.org
> >
>
Re: svn commit: r1617291 - in /logging/log4j/log4j2/trunk: log4j-api/src/main/java/org/apache/logging/log4j/message/ log4j-api/src/test/java/org/apache/logging/log4j/message/ log4j-core/src/main/java/org/apache/logging/log4j/core/appender/ log4j-core/src/m...
Posted by Remko Popma <re...@gmail.com>.
I'll add a junit test, but this is what it was before I started touching that class (except for obj.toString() -> String.valueOf(obj)).
Sent from my iPhone
> On 2014/08/12, at 8:02, Ralph Goers <ra...@dslextreme.com> wrote:
>
> Serialization does:
>
> if (obj instanceof Serializable) {
> out.writeObject(obj);
> } else {
> out.writeObject(String.valueOf(obj));
> }
>
> Deserialization does:
>
> in.defaultReadObject();
> obj = in.readObject();
>
> So if obj is not Serializable a String will be written. Upon deserialization obj will be set to either the the deserialized version of the object or to the String. I guess this will work.
>
> Ralph
>
>
>> On Aug 11, 2014, at 2:46 PM, Remko Popma <re...@gmail.com> wrote:
>>
>> I didn't change the serialization behavior. I only changed
>> obj.toString()
>> to
>> String.valueOf(obj)
>>
>> The stringValue field wasn't there originally (I incorrectly added it as non-transient in my first attempt). It is now transient so serialized form should be the same as pre-change.
>>
>> The serialization behavior of ObjectMessage has always been to serialize as Object if possible (Serializable), otherwise as String. Deserialization will just read whatever was serialized. That may not be the same object field but is the best we can do.
>>
>> Or did I miss something? (away from PC)
>>
>> Sent from my iPhone
>>
>>> On 2014/08/12, at 2:38, Ralph Goers <ra...@dslextreme.com> wrote:
>>>
>>> I believe this breaks deserialization of ObjectMessage. It is being serialized as either the serialized form of the Object or as a String. Deserialization doesn't account for this.
>>>
>>> Ralph
>>>
>>>> On Aug 11, 2014, at 7:16 AM, rpopma@apache.org wrote:
>>>>
>>>> Author: rpopma
>>>> Date: Mon Aug 11 14:16:22 2014
>>>> New Revision: 1617291
>>>>
>>>> URL: http://svn.apache.org/r1617291
>>>> Log:
>>>> LOG4J2-763: use different mechanism to solve this problem: instead of initializing the formatted message string in the message constructor, postpone this as long as possible until getFormattedMessage() is called. Async loggers and AsyncAppender now call message.getFormattedMessage() before passing the log event to the background thread. Added more tests.
>>>>
>>>> Modified:
>>>> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/FormattedMessage.java
>>>> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/LocalizedMessage.java
>>>> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/MessageFormatMessage.java
>>>> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/ObjectMessage.java
>>>> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/StringFormattedMessage.java
>>>> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/FormattedMessageTest.java
>>>> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/LocalizedMessageTest.java
>>>> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/MessageFormatMessageTest.java
>>>> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/ObjectMessageTest.java
>>>> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/StringFormattedMessageTest.java
>>>> logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java
>>>> logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java
>>>> logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java
>>>> logging/log4j/log4j2/trunk/src/changes/changes.xml
>>>>
>>>> Modified: logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/FormattedMessage.java
>>>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/FormattedMessage.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>>>> ==============================================================================
>>>> --- logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/FormattedMessage.java (original)
>>>> +++ logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/FormattedMessage.java Mon Aug 11 14:16:22 2014
>>>> @@ -46,7 +46,6 @@ public class FormattedMessage implements
>>>> this.messagePattern = messagePattern;
>>>> this.argArray = arguments;
>>>> this.throwable = throwable;
>>>> - getFormattedMessage(); // LOG4J2-763 take snapshot of parameters at message construction time
>>>> }
>>>>
>>>> public FormattedMessage(final String messagePattern, final Object[] arguments) {
>>>>
>>>> Modified: logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/LocalizedMessage.java
>>>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/LocalizedMessage.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>>>> ==============================================================================
>>>> --- logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/LocalizedMessage.java (original)
>>>> +++ logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/LocalizedMessage.java Mon Aug 11 14:16:22 2014
>>>> @@ -78,7 +78,6 @@ public class LocalizedMessage implements
>>>> this.baseName = baseName;
>>>> this.resourceBundle = null;
>>>> this.locale = locale;
>>>> - getFormattedMessage(); // LOG4J2-763 take snapshot of parameters at message construction time
>>>> }
>>>>
>>>> public LocalizedMessage(final ResourceBundle bundle, final Locale locale, final String key,
>>>> @@ -89,7 +88,6 @@ public class LocalizedMessage implements
>>>> this.baseName = null;
>>>> this.resourceBundle = bundle;
>>>> this.locale = locale;
>>>> - getFormattedMessage(); // LOG4J2-763 take snapshot of parameters at message construction time
>>>> }
>>>>
>>>> public LocalizedMessage(final Locale locale, final String key, final Object[] arguments) {
>>>>
>>>> Modified: logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/MessageFormatMessage.java
>>>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/MessageFormatMessage.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>>>> ==============================================================================
>>>> --- logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/MessageFormatMessage.java (original)
>>>> +++ logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/MessageFormatMessage.java Mon Aug 11 14:16:22 2014
>>>> @@ -49,7 +49,6 @@ public class MessageFormatMessage implem
>>>> if (arguments != null && arguments.length > 0 && arguments[arguments.length - 1] instanceof Throwable) {
>>>> this.throwable = (Throwable) arguments[arguments.length - 1];
>>>> }
>>>> - getFormattedMessage(); // LOG4J2-763 take snapshot of parameters at message construction time
>>>> }
>>>>
>>>> /**
>>>>
>>>> Modified: logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/ObjectMessage.java
>>>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/ObjectMessage.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>>>> ==============================================================================
>>>> --- logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/ObjectMessage.java (original)
>>>> +++ logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/ObjectMessage.java Mon Aug 11 14:16:22 2014
>>>> @@ -29,7 +29,7 @@ public class ObjectMessage implements Me
>>>> private static final long serialVersionUID = -5903272448334166185L;
>>>>
>>>> private transient Object obj;
>>>> - private final String objectString;
>>>> + private transient String objectString;
>>>>
>>>> /**
>>>> * Create the ObjectMessage.
>>>> @@ -40,9 +40,6 @@ public class ObjectMessage implements Me
>>>> obj = "null";
>>>> }
>>>> this.obj = obj;
>>>> -
>>>> - // LOG4J2-763: take snapshot of parameters at message construction time
>>>> - objectString = String.valueOf(obj);
>>>> }
>>>>
>>>> /**
>>>> @@ -51,6 +48,10 @@ public class ObjectMessage implements Me
>>>> */
>>>> @Override
>>>> public String getFormattedMessage() {
>>>> + // LOG4J2-763: cache formatted string in case obj changes later
>>>> + if (objectString == null) {
>>>> + objectString = String.valueOf(obj);
>>>> + }
>>>> return objectString;
>>>> }
>>>>
>>>> @@ -60,7 +61,7 @@ public class ObjectMessage implements Me
>>>> */
>>>> @Override
>>>> public String getFormat() {
>>>> - return objectString;
>>>> + return getFormattedMessage();
>>>> }
>>>>
>>>> /**
>>>> @@ -69,7 +70,7 @@ public class ObjectMessage implements Me
>>>> */
>>>> @Override
>>>> public Object[] getParameters() {
>>>> - return new Object[]{obj};
>>>> + return new Object[] { obj };
>>>> }
>>>>
>>>> @Override
>>>> @@ -82,8 +83,7 @@ public class ObjectMessage implements Me
>>>> }
>>>>
>>>> final ObjectMessage that = (ObjectMessage) o;
>>>> -
>>>> - return !(obj != null ? !obj.equals(that.obj) : that.obj != null);
>>>> + return obj == null ? that.obj == null : obj.equals(that.obj);
>>>> }
>>>>
>>>> @Override
>>>> @@ -93,7 +93,7 @@ public class ObjectMessage implements Me
>>>>
>>>> @Override
>>>> public String toString() {
>>>> - return "ObjectMessage[obj=" + objectString + ']';
>>>> + return "ObjectMessage[obj=" + getFormattedMessage() + ']';
>>>> }
>>>>
>>>> private void writeObject(final ObjectOutputStream out) throws IOException {
>>>> @@ -101,7 +101,7 @@ public class ObjectMessage implements Me
>>>> if (obj instanceof Serializable) {
>>>> out.writeObject(obj);
>>>> } else {
>>>> - out.writeObject(obj.toString());
>>>> + out.writeObject(String.valueOf(obj));
>>>> }
>>>> }
>>>>
>>>>
>>>> Modified: logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/StringFormattedMessage.java
>>>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/StringFormattedMessage.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>>>> ==============================================================================
>>>> --- logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/StringFormattedMessage.java (original)
>>>> +++ logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/StringFormattedMessage.java Mon Aug 11 14:16:22 2014
>>>> @@ -48,7 +48,6 @@ public class StringFormattedMessage impl
>>>> if (arguments != null && arguments.length > 0 && arguments[arguments.length - 1] instanceof Throwable) {
>>>> this.throwable = (Throwable) arguments[arguments.length - 1];
>>>> }
>>>> - getFormattedMessage(); // LOG4J2-763 take snapshot of parameters at message construction time
>>>> }
>>>>
>>>> /**
>>>>
>>>> Modified: logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/FormattedMessageTest.java
>>>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/FormattedMessageTest.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>>>> ==============================================================================
>>>> --- logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/FormattedMessageTest.java (original)
>>>> +++ logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/FormattedMessageTest.java Mon Aug 11 14:16:22 2014
>>>> @@ -85,14 +85,27 @@ public class FormattedMessageTest {
>>>> }
>>>>
>>>> @Test
>>>> - public void testSafeWithMutableParams() { // LOG4J2-763
>>>> + public void testUnsafeWithMutableParams() { // LOG4J2-763
>>>> final String testMsg = "Test message %s";
>>>> final Mutable param = new Mutable().set("abc");
>>>> - FormattedMessage msg = new FormattedMessage(testMsg, param);
>>>> + final FormattedMessage msg = new FormattedMessage(testMsg, param);
>>>>
>>>> // modify parameter before calling msg.getFormattedMessage
>>>> param.set("XYZ");
>>>> - String actual = msg.getFormattedMessage();
>>>> + final String actual = msg.getFormattedMessage();
>>>> + assertEquals("Expected most recent param value", "Test message XYZ", actual);
>>>> + }
>>>> +
>>>> + @Test
>>>> + public void testSafeAfterGetFormattedMessageIsCalled() { // LOG4J2-763
>>>> + final String testMsg = "Test message %s";
>>>> + final Mutable param = new Mutable().set("abc");
>>>> + final FormattedMessage msg = new FormattedMessage(testMsg, param);
>>>> +
>>>> + // modify parameter after calling msg.getFormattedMessage
>>>> + msg.getFormattedMessage(); // freeze the formatted message
>>>> + param.set("XYZ");
>>>> + final String actual = msg.getFormattedMessage();
>>>> assertEquals("Should use initial param value", "Test message abc", actual);
>>>> }
>>>> }
>>>>
>>>> Modified: logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/LocalizedMessageTest.java
>>>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/LocalizedMessageTest.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>>>> ==============================================================================
>>>> --- logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/LocalizedMessageTest.java (original)
>>>> +++ logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/LocalizedMessageTest.java Mon Aug 11 14:16:22 2014
>>>> @@ -65,15 +65,27 @@ public class LocalizedMessageTest {
>>>> }
>>>>
>>>> @Test
>>>> - public void testSafeWithMutableParams() { // LOG4J2-763
>>>> + public void testUnsafeWithMutableParams() { // LOG4J2-763
>>>> final String testMsg = "Test message %s";
>>>> final Mutable param = new Mutable().set("abc");
>>>> - LocalizedMessage msg = new LocalizedMessage(testMsg, param);
>>>> + final LocalizedMessage msg = new LocalizedMessage(testMsg, param);
>>>>
>>>> // modify parameter before calling msg.getFormattedMessage
>>>> param.set("XYZ");
>>>> - String actual = msg.getFormattedMessage();
>>>> - assertEquals("Should use initial param value", "Test message abc", actual);
>>>> + final String actual = msg.getFormattedMessage();
>>>> + assertEquals("Expected most recent param value", "Test message XYZ", actual);
>>>> }
>>>>
>>>> + @Test
>>>> + public void testSafeAfterGetFormattedMessageIsCalled() { // LOG4J2-763
>>>> + final String testMsg = "Test message %s";
>>>> + final Mutable param = new Mutable().set("abc");
>>>> + final LocalizedMessage msg = new LocalizedMessage(testMsg, param);
>>>> +
>>>> + // modify parameter after calling msg.getFormattedMessage
>>>> + msg.getFormattedMessage();
>>>> + param.set("XYZ");
>>>> + final String actual = msg.getFormattedMessage();
>>>> + assertEquals("Should use initial param value", "Test message abc", actual);
>>>> + }
>>>> }
>>>>
>>>> Modified: logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/MessageFormatMessageTest.java
>>>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/MessageFormatMessageTest.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>>>> ==============================================================================
>>>> --- logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/MessageFormatMessageTest.java (original)
>>>> +++ logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/MessageFormatMessageTest.java Mon Aug 11 14:16:22 2014
>>>> @@ -63,14 +63,27 @@ public class MessageFormatMessageTest {
>>>> }
>>>>
>>>> @Test
>>>> - public void testSafeWithMutableParams() { // LOG4J2-763
>>>> + public void testUnsafeWithMutableParams() { // LOG4J2-763
>>>> final String testMsg = "Test message {0}";
>>>> final Mutable param = new Mutable().set("abc");
>>>> - MessageFormatMessage msg = new MessageFormatMessage(testMsg, param);
>>>> + final MessageFormatMessage msg = new MessageFormatMessage(testMsg, param);
>>>>
>>>> // modify parameter before calling msg.getFormattedMessage
>>>> param.set("XYZ");
>>>> - String actual = msg.getFormattedMessage();
>>>> + final String actual = msg.getFormattedMessage();
>>>> + assertEquals("Expected most recent param value", "Test message XYZ", actual);
>>>> + }
>>>> +
>>>> + @Test
>>>> + public void testSafeAfterGetFormattedMessageIsCalled() { // LOG4J2-763
>>>> + final String testMsg = "Test message {0}";
>>>> + final Mutable param = new Mutable().set("abc");
>>>> + final MessageFormatMessage msg = new MessageFormatMessage(testMsg, param);
>>>> +
>>>> + // modify parameter after calling msg.getFormattedMessage
>>>> + msg.getFormattedMessage();
>>>> + param.set("XYZ");
>>>> + final String actual = msg.getFormattedMessage();
>>>> assertEquals("Should use initial param value", "Test message abc", actual);
>>>> }
>>>> }
>>>>
>>>> Modified: logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/ObjectMessageTest.java
>>>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/ObjectMessageTest.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>>>> ==============================================================================
>>>> --- logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/ObjectMessageTest.java (original)
>>>> +++ logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/ObjectMessageTest.java Mon Aug 11 14:16:22 2014
>>>> @@ -41,13 +41,25 @@ public class ObjectMessageTest {
>>>> }
>>>>
>>>> @Test
>>>> - public void testSafeWithMutableParams() { // LOG4J2-763
>>>> + public void testUnsafeWithMutableParams() { // LOG4J2-763
>>>> final Mutable param = new Mutable().set("abc");
>>>> - ObjectMessage msg = new ObjectMessage(param);
>>>> + final ObjectMessage msg = new ObjectMessage(param);
>>>>
>>>> // modify parameter before calling msg.getFormattedMessage
>>>> param.set("XYZ");
>>>> - String actual = msg.getFormattedMessage();
>>>> + final String actual = msg.getFormattedMessage();
>>>> + assertEquals("Expected most recent param value", "XYZ", actual);
>>>> + }
>>>> +
>>>> + @Test
>>>> + public void testSafeAfterGetFormattedMessageIsCalled() { // LOG4J2-763
>>>> + final Mutable param = new Mutable().set("abc");
>>>> + final ObjectMessage msg = new ObjectMessage(param);
>>>> +
>>>> + // modify parameter after calling msg.getFormattedMessage
>>>> + msg.getFormattedMessage();
>>>> + param.set("XYZ");
>>>> + final String actual = msg.getFormattedMessage();
>>>> assertEquals("Should use initial param value", "abc", actual);
>>>> }
>>>> }
>>>>
>>>> Modified: logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/StringFormattedMessageTest.java
>>>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/StringFormattedMessageTest.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>>>> ==============================================================================
>>>> --- logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/StringFormattedMessageTest.java (original)
>>>> +++ logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/StringFormattedMessageTest.java Mon Aug 11 14:16:22 2014
>>>> @@ -62,14 +62,27 @@ public class StringFormattedMessageTest
>>>> }
>>>>
>>>> @Test
>>>> - public void testSafeWithMutableParams() { // LOG4J2-763
>>>> + public void testUnsafeWithMutableParams() { // LOG4J2-763
>>>> final String testMsg = "Test message %s";
>>>> final Mutable param = new Mutable().set("abc");
>>>> - StringFormattedMessage msg = new StringFormattedMessage(testMsg, param);
>>>> + final StringFormattedMessage msg = new StringFormattedMessage(testMsg, param);
>>>>
>>>> // modify parameter before calling msg.getFormattedMessage
>>>> param.set("XYZ");
>>>> - String actual = msg.getFormattedMessage();
>>>> + final String actual = msg.getFormattedMessage();
>>>> + assertEquals("Should use initial param value", "Test message XYZ", actual);
>>>> + }
>>>> +
>>>> + @Test
>>>> + public void testSafeAfterGetFormattedMessageIsCalled() { // LOG4J2-763
>>>> + final String testMsg = "Test message %s";
>>>> + final Mutable param = new Mutable().set("abc");
>>>> + final StringFormattedMessage msg = new StringFormattedMessage(testMsg, param);
>>>> +
>>>> + // modify parameter after calling msg.getFormattedMessage
>>>> + msg.getFormattedMessage();
>>>> + param.set("XYZ");
>>>> + final String actual = msg.getFormattedMessage();
>>>> assertEquals("Should use initial param value", "Test message abc", actual);
>>>> }
>>>> }
>>>>
>>>> Modified: logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java
>>>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>>>> ==============================================================================
>>>> --- logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java (original)
>>>> +++ logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java Mon Aug 11 14:16:22 2014
>>>> @@ -138,6 +138,7 @@ public final class AsyncAppender extends
>>>> }
>>>> logEvent = ((RingBufferLogEvent) logEvent).createMemento();
>>>> }
>>>> + logEvent.getMessage().getFormattedMessage(); // LOG4J2-763: ask message to freeze parameters
>>>> final Log4jLogEvent coreEvent = (Log4jLogEvent) logEvent;
>>>> boolean appendSuccessful = false;
>>>> if (blocking) {
>>>>
>>>> Modified: logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java
>>>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>>>> ==============================================================================
>>>> --- logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java (original)
>>>> +++ logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java Mon Aug 11 14:16:22 2014
>>>> @@ -226,6 +226,7 @@ public class AsyncLogger extends Logger
>>>>
>>>> @Override
>>>> public void logMessage(final String fqcn, final Level level, final Marker marker, final Message message, final Throwable thrown) {
>>>> + // TODO refactor to reduce size to <= 35 bytecodes to allow JVM to inline it
>>>> Info info = threadlocalInfo.get();
>>>> if (info == null) {
>>>> info = new Info(new RingBufferLogEventTranslator(), Thread.currentThread().getName(), false);
>>>> @@ -245,6 +246,7 @@ public class AsyncLogger extends Logger
>>>> config.loggerConfig.log(getName(), fqcn, marker, level, message, thrown);
>>>> return;
>>>> }
>>>> + message.getFormattedMessage(); // LOG4J2-763: ask message to freeze parameters
>>>> final boolean includeLocation = config.loggerConfig.isIncludeLocation();
>>>> info.translator.setValues(this, getName(), marker, fqcn, level, message, //
>>>> // don't construct ThrowableProxy until required
>>>>
>>>> Modified: logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java
>>>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>>>> ==============================================================================
>>>> --- logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java (original)
>>>> +++ logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java Mon Aug 11 14:16:22 2014
>>>> @@ -316,6 +316,7 @@ class AsyncLoggerConfigHelper {
>>>> * calling thread needs to process the event itself
>>>> */
>>>> public boolean callAppendersFromAnotherThread(final LogEvent event) {
>>>> + // TODO refactor to reduce size to <= 35 bytecodes to allow JVM to inline it
>>>> final Disruptor<Log4jEventWrapper> temp = disruptor;
>>>> if (temp == null) { // LOG4J2-639
>>>> LOGGER.fatal("Ignoring log event after log4j was shut down");
>>>> @@ -336,6 +337,8 @@ class AsyncLoggerConfigHelper {
>>>> if (event instanceof RingBufferLogEvent) {
>>>> logEvent = ((RingBufferLogEvent) event).createMemento();
>>>> }
>>>> + logEvent.getMessage().getFormattedMessage(); // LOG4J2-763: ask message to freeze parameters
>>>> +
>>>> // Note: do NOT use the temp variable above!
>>>> // That could result in adding a log event to the disruptor after it was shut down,
>>>> // which could cause the publishEvent method to hang and never return.
>>>>
>>>> Modified: logging/log4j/log4j2/trunk/src/changes/changes.xml
>>>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/src/changes/changes.xml?rev=1617291&r1=1617290&r2=1617291&view=diff
>>>> ==============================================================================
>>>> --- logging/log4j/log4j2/trunk/src/changes/changes.xml (original)
>>>> +++ logging/log4j/log4j2/trunk/src/changes/changes.xml Mon Aug 11 14:16:22 2014
>>>> @@ -29,8 +29,7 @@
>>>> Startup takes a long time if you have empty packages attribute.
>>>> </action>
>>>> <action issue="LOG4J2-763" dev="rpopma" type="fix" due-to="Stephen Connolly">
>>>> - Improved FormattedMessage, StringFormattedMessage, LocalizedMessage, MessageFormatMessage and
>>>> - ObjectMessage for asynchronous logging to ensure the formatted message does not change even if
>>>> + Improved asynchronous loggers and appenders to ensure the formatted message does not change even if
>>>> parameters are modified by the application. (ParameterizedMessage was already safe.)
>>>> Improved documentation.
>>>> </action>
>>>
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
>>> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
>> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: svn commit: r1617291 - in /logging/log4j/log4j2/trunk: log4j-api/src/main/java/org/apache/logging/log4j/message/ log4j-api/src/test/java/org/apache/logging/log4j/message/ log4j-core/src/main/java/org/apache/logging/log4j/core/appender/ log4j-core/src/m...
Posted by Ralph Goers <ra...@dslextreme.com>.
Serialization does:
if (obj instanceof Serializable) {
out.writeObject(obj);
} else {
out.writeObject(String.valueOf(obj));
}
Deserialization does:
in.defaultReadObject();
obj = in.readObject();
So if obj is not Serializable a String will be written. Upon deserialization obj will be set to either the the deserialized version of the object or to the String. I guess this will work.
Ralph
On Aug 11, 2014, at 2:46 PM, Remko Popma <re...@gmail.com> wrote:
> I didn't change the serialization behavior. I only changed
> obj.toString()
> to
> String.valueOf(obj)
>
> The stringValue field wasn't there originally (I incorrectly added it as non-transient in my first attempt). It is now transient so serialized form should be the same as pre-change.
>
> The serialization behavior of ObjectMessage has always been to serialize as Object if possible (Serializable), otherwise as String. Deserialization will just read whatever was serialized. That may not be the same object field but is the best we can do.
>
> Or did I miss something? (away from PC)
>
> Sent from my iPhone
>
>> On 2014/08/12, at 2:38, Ralph Goers <ra...@dslextreme.com> wrote:
>>
>> I believe this breaks deserialization of ObjectMessage. It is being serialized as either the serialized form of the Object or as a String. Deserialization doesn't account for this.
>>
>> Ralph
>>
>>> On Aug 11, 2014, at 7:16 AM, rpopma@apache.org wrote:
>>>
>>> Author: rpopma
>>> Date: Mon Aug 11 14:16:22 2014
>>> New Revision: 1617291
>>>
>>> URL: http://svn.apache.org/r1617291
>>> Log:
>>> LOG4J2-763: use different mechanism to solve this problem: instead of initializing the formatted message string in the message constructor, postpone this as long as possible until getFormattedMessage() is called. Async loggers and AsyncAppender now call message.getFormattedMessage() before passing the log event to the background thread. Added more tests.
>>>
>>> Modified:
>>> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/FormattedMessage.java
>>> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/LocalizedMessage.java
>>> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/MessageFormatMessage.java
>>> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/ObjectMessage.java
>>> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/StringFormattedMessage.java
>>> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/FormattedMessageTest.java
>>> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/LocalizedMessageTest.java
>>> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/MessageFormatMessageTest.java
>>> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/ObjectMessageTest.java
>>> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/StringFormattedMessageTest.java
>>> logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java
>>> logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java
>>> logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java
>>> logging/log4j/log4j2/trunk/src/changes/changes.xml
>>>
>>> Modified: logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/FormattedMessage.java
>>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/FormattedMessage.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>>> ==============================================================================
>>> --- logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/FormattedMessage.java (original)
>>> +++ logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/FormattedMessage.java Mon Aug 11 14:16:22 2014
>>> @@ -46,7 +46,6 @@ public class FormattedMessage implements
>>> this.messagePattern = messagePattern;
>>> this.argArray = arguments;
>>> this.throwable = throwable;
>>> - getFormattedMessage(); // LOG4J2-763 take snapshot of parameters at message construction time
>>> }
>>>
>>> public FormattedMessage(final String messagePattern, final Object[] arguments) {
>>>
>>> Modified: logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/LocalizedMessage.java
>>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/LocalizedMessage.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>>> ==============================================================================
>>> --- logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/LocalizedMessage.java (original)
>>> +++ logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/LocalizedMessage.java Mon Aug 11 14:16:22 2014
>>> @@ -78,7 +78,6 @@ public class LocalizedMessage implements
>>> this.baseName = baseName;
>>> this.resourceBundle = null;
>>> this.locale = locale;
>>> - getFormattedMessage(); // LOG4J2-763 take snapshot of parameters at message construction time
>>> }
>>>
>>> public LocalizedMessage(final ResourceBundle bundle, final Locale locale, final String key,
>>> @@ -89,7 +88,6 @@ public class LocalizedMessage implements
>>> this.baseName = null;
>>> this.resourceBundle = bundle;
>>> this.locale = locale;
>>> - getFormattedMessage(); // LOG4J2-763 take snapshot of parameters at message construction time
>>> }
>>>
>>> public LocalizedMessage(final Locale locale, final String key, final Object[] arguments) {
>>>
>>> Modified: logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/MessageFormatMessage.java
>>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/MessageFormatMessage.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>>> ==============================================================================
>>> --- logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/MessageFormatMessage.java (original)
>>> +++ logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/MessageFormatMessage.java Mon Aug 11 14:16:22 2014
>>> @@ -49,7 +49,6 @@ public class MessageFormatMessage implem
>>> if (arguments != null && arguments.length > 0 && arguments[arguments.length - 1] instanceof Throwable) {
>>> this.throwable = (Throwable) arguments[arguments.length - 1];
>>> }
>>> - getFormattedMessage(); // LOG4J2-763 take snapshot of parameters at message construction time
>>> }
>>>
>>> /**
>>>
>>> Modified: logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/ObjectMessage.java
>>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/ObjectMessage.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>>> ==============================================================================
>>> --- logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/ObjectMessage.java (original)
>>> +++ logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/ObjectMessage.java Mon Aug 11 14:16:22 2014
>>> @@ -29,7 +29,7 @@ public class ObjectMessage implements Me
>>> private static final long serialVersionUID = -5903272448334166185L;
>>>
>>> private transient Object obj;
>>> - private final String objectString;
>>> + private transient String objectString;
>>>
>>> /**
>>> * Create the ObjectMessage.
>>> @@ -40,9 +40,6 @@ public class ObjectMessage implements Me
>>> obj = "null";
>>> }
>>> this.obj = obj;
>>> -
>>> - // LOG4J2-763: take snapshot of parameters at message construction time
>>> - objectString = String.valueOf(obj);
>>> }
>>>
>>> /**
>>> @@ -51,6 +48,10 @@ public class ObjectMessage implements Me
>>> */
>>> @Override
>>> public String getFormattedMessage() {
>>> + // LOG4J2-763: cache formatted string in case obj changes later
>>> + if (objectString == null) {
>>> + objectString = String.valueOf(obj);
>>> + }
>>> return objectString;
>>> }
>>>
>>> @@ -60,7 +61,7 @@ public class ObjectMessage implements Me
>>> */
>>> @Override
>>> public String getFormat() {
>>> - return objectString;
>>> + return getFormattedMessage();
>>> }
>>>
>>> /**
>>> @@ -69,7 +70,7 @@ public class ObjectMessage implements Me
>>> */
>>> @Override
>>> public Object[] getParameters() {
>>> - return new Object[]{obj};
>>> + return new Object[] { obj };
>>> }
>>>
>>> @Override
>>> @@ -82,8 +83,7 @@ public class ObjectMessage implements Me
>>> }
>>>
>>> final ObjectMessage that = (ObjectMessage) o;
>>> -
>>> - return !(obj != null ? !obj.equals(that.obj) : that.obj != null);
>>> + return obj == null ? that.obj == null : obj.equals(that.obj);
>>> }
>>>
>>> @Override
>>> @@ -93,7 +93,7 @@ public class ObjectMessage implements Me
>>>
>>> @Override
>>> public String toString() {
>>> - return "ObjectMessage[obj=" + objectString + ']';
>>> + return "ObjectMessage[obj=" + getFormattedMessage() + ']';
>>> }
>>>
>>> private void writeObject(final ObjectOutputStream out) throws IOException {
>>> @@ -101,7 +101,7 @@ public class ObjectMessage implements Me
>>> if (obj instanceof Serializable) {
>>> out.writeObject(obj);
>>> } else {
>>> - out.writeObject(obj.toString());
>>> + out.writeObject(String.valueOf(obj));
>>> }
>>> }
>>>
>>>
>>> Modified: logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/StringFormattedMessage.java
>>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/StringFormattedMessage.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>>> ==============================================================================
>>> --- logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/StringFormattedMessage.java (original)
>>> +++ logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/StringFormattedMessage.java Mon Aug 11 14:16:22 2014
>>> @@ -48,7 +48,6 @@ public class StringFormattedMessage impl
>>> if (arguments != null && arguments.length > 0 && arguments[arguments.length - 1] instanceof Throwable) {
>>> this.throwable = (Throwable) arguments[arguments.length - 1];
>>> }
>>> - getFormattedMessage(); // LOG4J2-763 take snapshot of parameters at message construction time
>>> }
>>>
>>> /**
>>>
>>> Modified: logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/FormattedMessageTest.java
>>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/FormattedMessageTest.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>>> ==============================================================================
>>> --- logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/FormattedMessageTest.java (original)
>>> +++ logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/FormattedMessageTest.java Mon Aug 11 14:16:22 2014
>>> @@ -85,14 +85,27 @@ public class FormattedMessageTest {
>>> }
>>>
>>> @Test
>>> - public void testSafeWithMutableParams() { // LOG4J2-763
>>> + public void testUnsafeWithMutableParams() { // LOG4J2-763
>>> final String testMsg = "Test message %s";
>>> final Mutable param = new Mutable().set("abc");
>>> - FormattedMessage msg = new FormattedMessage(testMsg, param);
>>> + final FormattedMessage msg = new FormattedMessage(testMsg, param);
>>>
>>> // modify parameter before calling msg.getFormattedMessage
>>> param.set("XYZ");
>>> - String actual = msg.getFormattedMessage();
>>> + final String actual = msg.getFormattedMessage();
>>> + assertEquals("Expected most recent param value", "Test message XYZ", actual);
>>> + }
>>> +
>>> + @Test
>>> + public void testSafeAfterGetFormattedMessageIsCalled() { // LOG4J2-763
>>> + final String testMsg = "Test message %s";
>>> + final Mutable param = new Mutable().set("abc");
>>> + final FormattedMessage msg = new FormattedMessage(testMsg, param);
>>> +
>>> + // modify parameter after calling msg.getFormattedMessage
>>> + msg.getFormattedMessage(); // freeze the formatted message
>>> + param.set("XYZ");
>>> + final String actual = msg.getFormattedMessage();
>>> assertEquals("Should use initial param value", "Test message abc", actual);
>>> }
>>> }
>>>
>>> Modified: logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/LocalizedMessageTest.java
>>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/LocalizedMessageTest.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>>> ==============================================================================
>>> --- logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/LocalizedMessageTest.java (original)
>>> +++ logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/LocalizedMessageTest.java Mon Aug 11 14:16:22 2014
>>> @@ -65,15 +65,27 @@ public class LocalizedMessageTest {
>>> }
>>>
>>> @Test
>>> - public void testSafeWithMutableParams() { // LOG4J2-763
>>> + public void testUnsafeWithMutableParams() { // LOG4J2-763
>>> final String testMsg = "Test message %s";
>>> final Mutable param = new Mutable().set("abc");
>>> - LocalizedMessage msg = new LocalizedMessage(testMsg, param);
>>> + final LocalizedMessage msg = new LocalizedMessage(testMsg, param);
>>>
>>> // modify parameter before calling msg.getFormattedMessage
>>> param.set("XYZ");
>>> - String actual = msg.getFormattedMessage();
>>> - assertEquals("Should use initial param value", "Test message abc", actual);
>>> + final String actual = msg.getFormattedMessage();
>>> + assertEquals("Expected most recent param value", "Test message XYZ", actual);
>>> }
>>>
>>> + @Test
>>> + public void testSafeAfterGetFormattedMessageIsCalled() { // LOG4J2-763
>>> + final String testMsg = "Test message %s";
>>> + final Mutable param = new Mutable().set("abc");
>>> + final LocalizedMessage msg = new LocalizedMessage(testMsg, param);
>>> +
>>> + // modify parameter after calling msg.getFormattedMessage
>>> + msg.getFormattedMessage();
>>> + param.set("XYZ");
>>> + final String actual = msg.getFormattedMessage();
>>> + assertEquals("Should use initial param value", "Test message abc", actual);
>>> + }
>>> }
>>>
>>> Modified: logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/MessageFormatMessageTest.java
>>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/MessageFormatMessageTest.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>>> ==============================================================================
>>> --- logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/MessageFormatMessageTest.java (original)
>>> +++ logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/MessageFormatMessageTest.java Mon Aug 11 14:16:22 2014
>>> @@ -63,14 +63,27 @@ public class MessageFormatMessageTest {
>>> }
>>>
>>> @Test
>>> - public void testSafeWithMutableParams() { // LOG4J2-763
>>> + public void testUnsafeWithMutableParams() { // LOG4J2-763
>>> final String testMsg = "Test message {0}";
>>> final Mutable param = new Mutable().set("abc");
>>> - MessageFormatMessage msg = new MessageFormatMessage(testMsg, param);
>>> + final MessageFormatMessage msg = new MessageFormatMessage(testMsg, param);
>>>
>>> // modify parameter before calling msg.getFormattedMessage
>>> param.set("XYZ");
>>> - String actual = msg.getFormattedMessage();
>>> + final String actual = msg.getFormattedMessage();
>>> + assertEquals("Expected most recent param value", "Test message XYZ", actual);
>>> + }
>>> +
>>> + @Test
>>> + public void testSafeAfterGetFormattedMessageIsCalled() { // LOG4J2-763
>>> + final String testMsg = "Test message {0}";
>>> + final Mutable param = new Mutable().set("abc");
>>> + final MessageFormatMessage msg = new MessageFormatMessage(testMsg, param);
>>> +
>>> + // modify parameter after calling msg.getFormattedMessage
>>> + msg.getFormattedMessage();
>>> + param.set("XYZ");
>>> + final String actual = msg.getFormattedMessage();
>>> assertEquals("Should use initial param value", "Test message abc", actual);
>>> }
>>> }
>>>
>>> Modified: logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/ObjectMessageTest.java
>>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/ObjectMessageTest.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>>> ==============================================================================
>>> --- logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/ObjectMessageTest.java (original)
>>> +++ logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/ObjectMessageTest.java Mon Aug 11 14:16:22 2014
>>> @@ -41,13 +41,25 @@ public class ObjectMessageTest {
>>> }
>>>
>>> @Test
>>> - public void testSafeWithMutableParams() { // LOG4J2-763
>>> + public void testUnsafeWithMutableParams() { // LOG4J2-763
>>> final Mutable param = new Mutable().set("abc");
>>> - ObjectMessage msg = new ObjectMessage(param);
>>> + final ObjectMessage msg = new ObjectMessage(param);
>>>
>>> // modify parameter before calling msg.getFormattedMessage
>>> param.set("XYZ");
>>> - String actual = msg.getFormattedMessage();
>>> + final String actual = msg.getFormattedMessage();
>>> + assertEquals("Expected most recent param value", "XYZ", actual);
>>> + }
>>> +
>>> + @Test
>>> + public void testSafeAfterGetFormattedMessageIsCalled() { // LOG4J2-763
>>> + final Mutable param = new Mutable().set("abc");
>>> + final ObjectMessage msg = new ObjectMessage(param);
>>> +
>>> + // modify parameter after calling msg.getFormattedMessage
>>> + msg.getFormattedMessage();
>>> + param.set("XYZ");
>>> + final String actual = msg.getFormattedMessage();
>>> assertEquals("Should use initial param value", "abc", actual);
>>> }
>>> }
>>>
>>> Modified: logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/StringFormattedMessageTest.java
>>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/StringFormattedMessageTest.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>>> ==============================================================================
>>> --- logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/StringFormattedMessageTest.java (original)
>>> +++ logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/StringFormattedMessageTest.java Mon Aug 11 14:16:22 2014
>>> @@ -62,14 +62,27 @@ public class StringFormattedMessageTest
>>> }
>>>
>>> @Test
>>> - public void testSafeWithMutableParams() { // LOG4J2-763
>>> + public void testUnsafeWithMutableParams() { // LOG4J2-763
>>> final String testMsg = "Test message %s";
>>> final Mutable param = new Mutable().set("abc");
>>> - StringFormattedMessage msg = new StringFormattedMessage(testMsg, param);
>>> + final StringFormattedMessage msg = new StringFormattedMessage(testMsg, param);
>>>
>>> // modify parameter before calling msg.getFormattedMessage
>>> param.set("XYZ");
>>> - String actual = msg.getFormattedMessage();
>>> + final String actual = msg.getFormattedMessage();
>>> + assertEquals("Should use initial param value", "Test message XYZ", actual);
>>> + }
>>> +
>>> + @Test
>>> + public void testSafeAfterGetFormattedMessageIsCalled() { // LOG4J2-763
>>> + final String testMsg = "Test message %s";
>>> + final Mutable param = new Mutable().set("abc");
>>> + final StringFormattedMessage msg = new StringFormattedMessage(testMsg, param);
>>> +
>>> + // modify parameter after calling msg.getFormattedMessage
>>> + msg.getFormattedMessage();
>>> + param.set("XYZ");
>>> + final String actual = msg.getFormattedMessage();
>>> assertEquals("Should use initial param value", "Test message abc", actual);
>>> }
>>> }
>>>
>>> Modified: logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java
>>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>>> ==============================================================================
>>> --- logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java (original)
>>> +++ logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java Mon Aug 11 14:16:22 2014
>>> @@ -138,6 +138,7 @@ public final class AsyncAppender extends
>>> }
>>> logEvent = ((RingBufferLogEvent) logEvent).createMemento();
>>> }
>>> + logEvent.getMessage().getFormattedMessage(); // LOG4J2-763: ask message to freeze parameters
>>> final Log4jLogEvent coreEvent = (Log4jLogEvent) logEvent;
>>> boolean appendSuccessful = false;
>>> if (blocking) {
>>>
>>> Modified: logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java
>>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>>> ==============================================================================
>>> --- logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java (original)
>>> +++ logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java Mon Aug 11 14:16:22 2014
>>> @@ -226,6 +226,7 @@ public class AsyncLogger extends Logger
>>>
>>> @Override
>>> public void logMessage(final String fqcn, final Level level, final Marker marker, final Message message, final Throwable thrown) {
>>> + // TODO refactor to reduce size to <= 35 bytecodes to allow JVM to inline it
>>> Info info = threadlocalInfo.get();
>>> if (info == null) {
>>> info = new Info(new RingBufferLogEventTranslator(), Thread.currentThread().getName(), false);
>>> @@ -245,6 +246,7 @@ public class AsyncLogger extends Logger
>>> config.loggerConfig.log(getName(), fqcn, marker, level, message, thrown);
>>> return;
>>> }
>>> + message.getFormattedMessage(); // LOG4J2-763: ask message to freeze parameters
>>> final boolean includeLocation = config.loggerConfig.isIncludeLocation();
>>> info.translator.setValues(this, getName(), marker, fqcn, level, message, //
>>> // don't construct ThrowableProxy until required
>>>
>>> Modified: logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java
>>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>>> ==============================================================================
>>> --- logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java (original)
>>> +++ logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java Mon Aug 11 14:16:22 2014
>>> @@ -316,6 +316,7 @@ class AsyncLoggerConfigHelper {
>>> * calling thread needs to process the event itself
>>> */
>>> public boolean callAppendersFromAnotherThread(final LogEvent event) {
>>> + // TODO refactor to reduce size to <= 35 bytecodes to allow JVM to inline it
>>> final Disruptor<Log4jEventWrapper> temp = disruptor;
>>> if (temp == null) { // LOG4J2-639
>>> LOGGER.fatal("Ignoring log event after log4j was shut down");
>>> @@ -336,6 +337,8 @@ class AsyncLoggerConfigHelper {
>>> if (event instanceof RingBufferLogEvent) {
>>> logEvent = ((RingBufferLogEvent) event).createMemento();
>>> }
>>> + logEvent.getMessage().getFormattedMessage(); // LOG4J2-763: ask message to freeze parameters
>>> +
>>> // Note: do NOT use the temp variable above!
>>> // That could result in adding a log event to the disruptor after it was shut down,
>>> // which could cause the publishEvent method to hang and never return.
>>>
>>> Modified: logging/log4j/log4j2/trunk/src/changes/changes.xml
>>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/src/changes/changes.xml?rev=1617291&r1=1617290&r2=1617291&view=diff
>>> ==============================================================================
>>> --- logging/log4j/log4j2/trunk/src/changes/changes.xml (original)
>>> +++ logging/log4j/log4j2/trunk/src/changes/changes.xml Mon Aug 11 14:16:22 2014
>>> @@ -29,8 +29,7 @@
>>> Startup takes a long time if you have empty packages attribute.
>>> </action>
>>> <action issue="LOG4J2-763" dev="rpopma" type="fix" due-to="Stephen Connolly">
>>> - Improved FormattedMessage, StringFormattedMessage, LocalizedMessage, MessageFormatMessage and
>>> - ObjectMessage for asynchronous logging to ensure the formatted message does not change even if
>>> + Improved asynchronous loggers and appenders to ensure the formatted message does not change even if
>>> parameters are modified by the application. (ParameterizedMessage was already safe.)
>>> Improved documentation.
>>> </action>
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
>> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: svn commit: r1617291 - in /logging/log4j/log4j2/trunk: log4j-api/src/main/java/org/apache/logging/log4j/message/ log4j-api/src/test/java/org/apache/logging/log4j/message/ log4j-core/src/main/java/org/apache/logging/log4j/core/appender/ log4j-core/src/m...
Posted by Remko Popma <re...@gmail.com>.
I didn't change the serialization behavior. I only changed
obj.toString()
to
String.valueOf(obj)
The stringValue field wasn't there originally (I incorrectly added it as non-transient in my first attempt). It is now transient so serialized form should be the same as pre-change.
The serialization behavior of ObjectMessage has always been to serialize as Object if possible (Serializable), otherwise as String. Deserialization will just read whatever was serialized. That may not be the same object field but is the best we can do.
Or did I miss something? (away from PC)
Sent from my iPhone
> On 2014/08/12, at 2:38, Ralph Goers <ra...@dslextreme.com> wrote:
>
> I believe this breaks deserialization of ObjectMessage. It is being serialized as either the serialized form of the Object or as a String. Deserialization doesn't account for this.
>
> Ralph
>
>> On Aug 11, 2014, at 7:16 AM, rpopma@apache.org wrote:
>>
>> Author: rpopma
>> Date: Mon Aug 11 14:16:22 2014
>> New Revision: 1617291
>>
>> URL: http://svn.apache.org/r1617291
>> Log:
>> LOG4J2-763: use different mechanism to solve this problem: instead of initializing the formatted message string in the message constructor, postpone this as long as possible until getFormattedMessage() is called. Async loggers and AsyncAppender now call message.getFormattedMessage() before passing the log event to the background thread. Added more tests.
>>
>> Modified:
>> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/FormattedMessage.java
>> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/LocalizedMessage.java
>> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/MessageFormatMessage.java
>> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/ObjectMessage.java
>> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/StringFormattedMessage.java
>> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/FormattedMessageTest.java
>> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/LocalizedMessageTest.java
>> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/MessageFormatMessageTest.java
>> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/ObjectMessageTest.java
>> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/StringFormattedMessageTest.java
>> logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java
>> logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java
>> logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java
>> logging/log4j/log4j2/trunk/src/changes/changes.xml
>>
>> Modified: logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/FormattedMessage.java
>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/FormattedMessage.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>> ==============================================================================
>> --- logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/FormattedMessage.java (original)
>> +++ logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/FormattedMessage.java Mon Aug 11 14:16:22 2014
>> @@ -46,7 +46,6 @@ public class FormattedMessage implements
>> this.messagePattern = messagePattern;
>> this.argArray = arguments;
>> this.throwable = throwable;
>> - getFormattedMessage(); // LOG4J2-763 take snapshot of parameters at message construction time
>> }
>>
>> public FormattedMessage(final String messagePattern, final Object[] arguments) {
>>
>> Modified: logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/LocalizedMessage.java
>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/LocalizedMessage.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>> ==============================================================================
>> --- logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/LocalizedMessage.java (original)
>> +++ logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/LocalizedMessage.java Mon Aug 11 14:16:22 2014
>> @@ -78,7 +78,6 @@ public class LocalizedMessage implements
>> this.baseName = baseName;
>> this.resourceBundle = null;
>> this.locale = locale;
>> - getFormattedMessage(); // LOG4J2-763 take snapshot of parameters at message construction time
>> }
>>
>> public LocalizedMessage(final ResourceBundle bundle, final Locale locale, final String key,
>> @@ -89,7 +88,6 @@ public class LocalizedMessage implements
>> this.baseName = null;
>> this.resourceBundle = bundle;
>> this.locale = locale;
>> - getFormattedMessage(); // LOG4J2-763 take snapshot of parameters at message construction time
>> }
>>
>> public LocalizedMessage(final Locale locale, final String key, final Object[] arguments) {
>>
>> Modified: logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/MessageFormatMessage.java
>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/MessageFormatMessage.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>> ==============================================================================
>> --- logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/MessageFormatMessage.java (original)
>> +++ logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/MessageFormatMessage.java Mon Aug 11 14:16:22 2014
>> @@ -49,7 +49,6 @@ public class MessageFormatMessage implem
>> if (arguments != null && arguments.length > 0 && arguments[arguments.length - 1] instanceof Throwable) {
>> this.throwable = (Throwable) arguments[arguments.length - 1];
>> }
>> - getFormattedMessage(); // LOG4J2-763 take snapshot of parameters at message construction time
>> }
>>
>> /**
>>
>> Modified: logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/ObjectMessage.java
>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/ObjectMessage.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>> ==============================================================================
>> --- logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/ObjectMessage.java (original)
>> +++ logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/ObjectMessage.java Mon Aug 11 14:16:22 2014
>> @@ -29,7 +29,7 @@ public class ObjectMessage implements Me
>> private static final long serialVersionUID = -5903272448334166185L;
>>
>> private transient Object obj;
>> - private final String objectString;
>> + private transient String objectString;
>>
>> /**
>> * Create the ObjectMessage.
>> @@ -40,9 +40,6 @@ public class ObjectMessage implements Me
>> obj = "null";
>> }
>> this.obj = obj;
>> -
>> - // LOG4J2-763: take snapshot of parameters at message construction time
>> - objectString = String.valueOf(obj);
>> }
>>
>> /**
>> @@ -51,6 +48,10 @@ public class ObjectMessage implements Me
>> */
>> @Override
>> public String getFormattedMessage() {
>> + // LOG4J2-763: cache formatted string in case obj changes later
>> + if (objectString == null) {
>> + objectString = String.valueOf(obj);
>> + }
>> return objectString;
>> }
>>
>> @@ -60,7 +61,7 @@ public class ObjectMessage implements Me
>> */
>> @Override
>> public String getFormat() {
>> - return objectString;
>> + return getFormattedMessage();
>> }
>>
>> /**
>> @@ -69,7 +70,7 @@ public class ObjectMessage implements Me
>> */
>> @Override
>> public Object[] getParameters() {
>> - return new Object[]{obj};
>> + return new Object[] { obj };
>> }
>>
>> @Override
>> @@ -82,8 +83,7 @@ public class ObjectMessage implements Me
>> }
>>
>> final ObjectMessage that = (ObjectMessage) o;
>> -
>> - return !(obj != null ? !obj.equals(that.obj) : that.obj != null);
>> + return obj == null ? that.obj == null : obj.equals(that.obj);
>> }
>>
>> @Override
>> @@ -93,7 +93,7 @@ public class ObjectMessage implements Me
>>
>> @Override
>> public String toString() {
>> - return "ObjectMessage[obj=" + objectString + ']';
>> + return "ObjectMessage[obj=" + getFormattedMessage() + ']';
>> }
>>
>> private void writeObject(final ObjectOutputStream out) throws IOException {
>> @@ -101,7 +101,7 @@ public class ObjectMessage implements Me
>> if (obj instanceof Serializable) {
>> out.writeObject(obj);
>> } else {
>> - out.writeObject(obj.toString());
>> + out.writeObject(String.valueOf(obj));
>> }
>> }
>>
>>
>> Modified: logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/StringFormattedMessage.java
>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/StringFormattedMessage.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>> ==============================================================================
>> --- logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/StringFormattedMessage.java (original)
>> +++ logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/StringFormattedMessage.java Mon Aug 11 14:16:22 2014
>> @@ -48,7 +48,6 @@ public class StringFormattedMessage impl
>> if (arguments != null && arguments.length > 0 && arguments[arguments.length - 1] instanceof Throwable) {
>> this.throwable = (Throwable) arguments[arguments.length - 1];
>> }
>> - getFormattedMessage(); // LOG4J2-763 take snapshot of parameters at message construction time
>> }
>>
>> /**
>>
>> Modified: logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/FormattedMessageTest.java
>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/FormattedMessageTest.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>> ==============================================================================
>> --- logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/FormattedMessageTest.java (original)
>> +++ logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/FormattedMessageTest.java Mon Aug 11 14:16:22 2014
>> @@ -85,14 +85,27 @@ public class FormattedMessageTest {
>> }
>>
>> @Test
>> - public void testSafeWithMutableParams() { // LOG4J2-763
>> + public void testUnsafeWithMutableParams() { // LOG4J2-763
>> final String testMsg = "Test message %s";
>> final Mutable param = new Mutable().set("abc");
>> - FormattedMessage msg = new FormattedMessage(testMsg, param);
>> + final FormattedMessage msg = new FormattedMessage(testMsg, param);
>>
>> // modify parameter before calling msg.getFormattedMessage
>> param.set("XYZ");
>> - String actual = msg.getFormattedMessage();
>> + final String actual = msg.getFormattedMessage();
>> + assertEquals("Expected most recent param value", "Test message XYZ", actual);
>> + }
>> +
>> + @Test
>> + public void testSafeAfterGetFormattedMessageIsCalled() { // LOG4J2-763
>> + final String testMsg = "Test message %s";
>> + final Mutable param = new Mutable().set("abc");
>> + final FormattedMessage msg = new FormattedMessage(testMsg, param);
>> +
>> + // modify parameter after calling msg.getFormattedMessage
>> + msg.getFormattedMessage(); // freeze the formatted message
>> + param.set("XYZ");
>> + final String actual = msg.getFormattedMessage();
>> assertEquals("Should use initial param value", "Test message abc", actual);
>> }
>> }
>>
>> Modified: logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/LocalizedMessageTest.java
>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/LocalizedMessageTest.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>> ==============================================================================
>> --- logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/LocalizedMessageTest.java (original)
>> +++ logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/LocalizedMessageTest.java Mon Aug 11 14:16:22 2014
>> @@ -65,15 +65,27 @@ public class LocalizedMessageTest {
>> }
>>
>> @Test
>> - public void testSafeWithMutableParams() { // LOG4J2-763
>> + public void testUnsafeWithMutableParams() { // LOG4J2-763
>> final String testMsg = "Test message %s";
>> final Mutable param = new Mutable().set("abc");
>> - LocalizedMessage msg = new LocalizedMessage(testMsg, param);
>> + final LocalizedMessage msg = new LocalizedMessage(testMsg, param);
>>
>> // modify parameter before calling msg.getFormattedMessage
>> param.set("XYZ");
>> - String actual = msg.getFormattedMessage();
>> - assertEquals("Should use initial param value", "Test message abc", actual);
>> + final String actual = msg.getFormattedMessage();
>> + assertEquals("Expected most recent param value", "Test message XYZ", actual);
>> }
>>
>> + @Test
>> + public void testSafeAfterGetFormattedMessageIsCalled() { // LOG4J2-763
>> + final String testMsg = "Test message %s";
>> + final Mutable param = new Mutable().set("abc");
>> + final LocalizedMessage msg = new LocalizedMessage(testMsg, param);
>> +
>> + // modify parameter after calling msg.getFormattedMessage
>> + msg.getFormattedMessage();
>> + param.set("XYZ");
>> + final String actual = msg.getFormattedMessage();
>> + assertEquals("Should use initial param value", "Test message abc", actual);
>> + }
>> }
>>
>> Modified: logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/MessageFormatMessageTest.java
>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/MessageFormatMessageTest.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>> ==============================================================================
>> --- logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/MessageFormatMessageTest.java (original)
>> +++ logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/MessageFormatMessageTest.java Mon Aug 11 14:16:22 2014
>> @@ -63,14 +63,27 @@ public class MessageFormatMessageTest {
>> }
>>
>> @Test
>> - public void testSafeWithMutableParams() { // LOG4J2-763
>> + public void testUnsafeWithMutableParams() { // LOG4J2-763
>> final String testMsg = "Test message {0}";
>> final Mutable param = new Mutable().set("abc");
>> - MessageFormatMessage msg = new MessageFormatMessage(testMsg, param);
>> + final MessageFormatMessage msg = new MessageFormatMessage(testMsg, param);
>>
>> // modify parameter before calling msg.getFormattedMessage
>> param.set("XYZ");
>> - String actual = msg.getFormattedMessage();
>> + final String actual = msg.getFormattedMessage();
>> + assertEquals("Expected most recent param value", "Test message XYZ", actual);
>> + }
>> +
>> + @Test
>> + public void testSafeAfterGetFormattedMessageIsCalled() { // LOG4J2-763
>> + final String testMsg = "Test message {0}";
>> + final Mutable param = new Mutable().set("abc");
>> + final MessageFormatMessage msg = new MessageFormatMessage(testMsg, param);
>> +
>> + // modify parameter after calling msg.getFormattedMessage
>> + msg.getFormattedMessage();
>> + param.set("XYZ");
>> + final String actual = msg.getFormattedMessage();
>> assertEquals("Should use initial param value", "Test message abc", actual);
>> }
>> }
>>
>> Modified: logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/ObjectMessageTest.java
>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/ObjectMessageTest.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>> ==============================================================================
>> --- logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/ObjectMessageTest.java (original)
>> +++ logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/ObjectMessageTest.java Mon Aug 11 14:16:22 2014
>> @@ -41,13 +41,25 @@ public class ObjectMessageTest {
>> }
>>
>> @Test
>> - public void testSafeWithMutableParams() { // LOG4J2-763
>> + public void testUnsafeWithMutableParams() { // LOG4J2-763
>> final Mutable param = new Mutable().set("abc");
>> - ObjectMessage msg = new ObjectMessage(param);
>> + final ObjectMessage msg = new ObjectMessage(param);
>>
>> // modify parameter before calling msg.getFormattedMessage
>> param.set("XYZ");
>> - String actual = msg.getFormattedMessage();
>> + final String actual = msg.getFormattedMessage();
>> + assertEquals("Expected most recent param value", "XYZ", actual);
>> + }
>> +
>> + @Test
>> + public void testSafeAfterGetFormattedMessageIsCalled() { // LOG4J2-763
>> + final Mutable param = new Mutable().set("abc");
>> + final ObjectMessage msg = new ObjectMessage(param);
>> +
>> + // modify parameter after calling msg.getFormattedMessage
>> + msg.getFormattedMessage();
>> + param.set("XYZ");
>> + final String actual = msg.getFormattedMessage();
>> assertEquals("Should use initial param value", "abc", actual);
>> }
>> }
>>
>> Modified: logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/StringFormattedMessageTest.java
>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/StringFormattedMessageTest.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>> ==============================================================================
>> --- logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/StringFormattedMessageTest.java (original)
>> +++ logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/StringFormattedMessageTest.java Mon Aug 11 14:16:22 2014
>> @@ -62,14 +62,27 @@ public class StringFormattedMessageTest
>> }
>>
>> @Test
>> - public void testSafeWithMutableParams() { // LOG4J2-763
>> + public void testUnsafeWithMutableParams() { // LOG4J2-763
>> final String testMsg = "Test message %s";
>> final Mutable param = new Mutable().set("abc");
>> - StringFormattedMessage msg = new StringFormattedMessage(testMsg, param);
>> + final StringFormattedMessage msg = new StringFormattedMessage(testMsg, param);
>>
>> // modify parameter before calling msg.getFormattedMessage
>> param.set("XYZ");
>> - String actual = msg.getFormattedMessage();
>> + final String actual = msg.getFormattedMessage();
>> + assertEquals("Should use initial param value", "Test message XYZ", actual);
>> + }
>> +
>> + @Test
>> + public void testSafeAfterGetFormattedMessageIsCalled() { // LOG4J2-763
>> + final String testMsg = "Test message %s";
>> + final Mutable param = new Mutable().set("abc");
>> + final StringFormattedMessage msg = new StringFormattedMessage(testMsg, param);
>> +
>> + // modify parameter after calling msg.getFormattedMessage
>> + msg.getFormattedMessage();
>> + param.set("XYZ");
>> + final String actual = msg.getFormattedMessage();
>> assertEquals("Should use initial param value", "Test message abc", actual);
>> }
>> }
>>
>> Modified: logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java
>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>> ==============================================================================
>> --- logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java (original)
>> +++ logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java Mon Aug 11 14:16:22 2014
>> @@ -138,6 +138,7 @@ public final class AsyncAppender extends
>> }
>> logEvent = ((RingBufferLogEvent) logEvent).createMemento();
>> }
>> + logEvent.getMessage().getFormattedMessage(); // LOG4J2-763: ask message to freeze parameters
>> final Log4jLogEvent coreEvent = (Log4jLogEvent) logEvent;
>> boolean appendSuccessful = false;
>> if (blocking) {
>>
>> Modified: logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java
>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>> ==============================================================================
>> --- logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java (original)
>> +++ logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java Mon Aug 11 14:16:22 2014
>> @@ -226,6 +226,7 @@ public class AsyncLogger extends Logger
>>
>> @Override
>> public void logMessage(final String fqcn, final Level level, final Marker marker, final Message message, final Throwable thrown) {
>> + // TODO refactor to reduce size to <= 35 bytecodes to allow JVM to inline it
>> Info info = threadlocalInfo.get();
>> if (info == null) {
>> info = new Info(new RingBufferLogEventTranslator(), Thread.currentThread().getName(), false);
>> @@ -245,6 +246,7 @@ public class AsyncLogger extends Logger
>> config.loggerConfig.log(getName(), fqcn, marker, level, message, thrown);
>> return;
>> }
>> + message.getFormattedMessage(); // LOG4J2-763: ask message to freeze parameters
>> final boolean includeLocation = config.loggerConfig.isIncludeLocation();
>> info.translator.setValues(this, getName(), marker, fqcn, level, message, //
>> // don't construct ThrowableProxy until required
>>
>> Modified: logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java
>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java?rev=1617291&r1=1617290&r2=1617291&view=diff
>> ==============================================================================
>> --- logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java (original)
>> +++ logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java Mon Aug 11 14:16:22 2014
>> @@ -316,6 +316,7 @@ class AsyncLoggerConfigHelper {
>> * calling thread needs to process the event itself
>> */
>> public boolean callAppendersFromAnotherThread(final LogEvent event) {
>> + // TODO refactor to reduce size to <= 35 bytecodes to allow JVM to inline it
>> final Disruptor<Log4jEventWrapper> temp = disruptor;
>> if (temp == null) { // LOG4J2-639
>> LOGGER.fatal("Ignoring log event after log4j was shut down");
>> @@ -336,6 +337,8 @@ class AsyncLoggerConfigHelper {
>> if (event instanceof RingBufferLogEvent) {
>> logEvent = ((RingBufferLogEvent) event).createMemento();
>> }
>> + logEvent.getMessage().getFormattedMessage(); // LOG4J2-763: ask message to freeze parameters
>> +
>> // Note: do NOT use the temp variable above!
>> // That could result in adding a log event to the disruptor after it was shut down,
>> // which could cause the publishEvent method to hang and never return.
>>
>> Modified: logging/log4j/log4j2/trunk/src/changes/changes.xml
>> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/src/changes/changes.xml?rev=1617291&r1=1617290&r2=1617291&view=diff
>> ==============================================================================
>> --- logging/log4j/log4j2/trunk/src/changes/changes.xml (original)
>> +++ logging/log4j/log4j2/trunk/src/changes/changes.xml Mon Aug 11 14:16:22 2014
>> @@ -29,8 +29,7 @@
>> Startup takes a long time if you have empty packages attribute.
>> </action>
>> <action issue="LOG4J2-763" dev="rpopma" type="fix" due-to="Stephen Connolly">
>> - Improved FormattedMessage, StringFormattedMessage, LocalizedMessage, MessageFormatMessage and
>> - ObjectMessage for asynchronous logging to ensure the formatted message does not change even if
>> + Improved asynchronous loggers and appenders to ensure the formatted message does not change even if
>> parameters are modified by the application. (ParameterizedMessage was already safe.)
>> Improved documentation.
>> </action>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: svn commit: r1617291 - in /logging/log4j/log4j2/trunk: log4j-api/src/main/java/org/apache/logging/log4j/message/ log4j-api/src/test/java/org/apache/logging/log4j/message/ log4j-core/src/main/java/org/apache/logging/log4j/core/appender/ log4j-core/src/m...
Posted by Ralph Goers <ra...@dslextreme.com>.
I believe this breaks deserialization of ObjectMessage. It is being serialized as either the serialized form of the Object or as a String. Deserialization doesn't account for this.
Ralph
On Aug 11, 2014, at 7:16 AM, rpopma@apache.org wrote:
> Author: rpopma
> Date: Mon Aug 11 14:16:22 2014
> New Revision: 1617291
>
> URL: http://svn.apache.org/r1617291
> Log:
> LOG4J2-763: use different mechanism to solve this problem: instead of initializing the formatted message string in the message constructor, postpone this as long as possible until getFormattedMessage() is called. Async loggers and AsyncAppender now call message.getFormattedMessage() before passing the log event to the background thread. Added more tests.
>
> Modified:
> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/FormattedMessage.java
> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/LocalizedMessage.java
> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/MessageFormatMessage.java
> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/ObjectMessage.java
> logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/StringFormattedMessage.java
> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/FormattedMessageTest.java
> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/LocalizedMessageTest.java
> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/MessageFormatMessageTest.java
> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/ObjectMessageTest.java
> logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/StringFormattedMessageTest.java
> logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java
> logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java
> logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java
> logging/log4j/log4j2/trunk/src/changes/changes.xml
>
> Modified: logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/FormattedMessage.java
> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/FormattedMessage.java?rev=1617291&r1=1617290&r2=1617291&view=diff
> ==============================================================================
> --- logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/FormattedMessage.java (original)
> +++ logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/FormattedMessage.java Mon Aug 11 14:16:22 2014
> @@ -46,7 +46,6 @@ public class FormattedMessage implements
> this.messagePattern = messagePattern;
> this.argArray = arguments;
> this.throwable = throwable;
> - getFormattedMessage(); // LOG4J2-763 take snapshot of parameters at message construction time
> }
>
> public FormattedMessage(final String messagePattern, final Object[] arguments) {
>
> Modified: logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/LocalizedMessage.java
> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/LocalizedMessage.java?rev=1617291&r1=1617290&r2=1617291&view=diff
> ==============================================================================
> --- logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/LocalizedMessage.java (original)
> +++ logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/LocalizedMessage.java Mon Aug 11 14:16:22 2014
> @@ -78,7 +78,6 @@ public class LocalizedMessage implements
> this.baseName = baseName;
> this.resourceBundle = null;
> this.locale = locale;
> - getFormattedMessage(); // LOG4J2-763 take snapshot of parameters at message construction time
> }
>
> public LocalizedMessage(final ResourceBundle bundle, final Locale locale, final String key,
> @@ -89,7 +88,6 @@ public class LocalizedMessage implements
> this.baseName = null;
> this.resourceBundle = bundle;
> this.locale = locale;
> - getFormattedMessage(); // LOG4J2-763 take snapshot of parameters at message construction time
> }
>
> public LocalizedMessage(final Locale locale, final String key, final Object[] arguments) {
>
> Modified: logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/MessageFormatMessage.java
> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/MessageFormatMessage.java?rev=1617291&r1=1617290&r2=1617291&view=diff
> ==============================================================================
> --- logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/MessageFormatMessage.java (original)
> +++ logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/MessageFormatMessage.java Mon Aug 11 14:16:22 2014
> @@ -49,7 +49,6 @@ public class MessageFormatMessage implem
> if (arguments != null && arguments.length > 0 && arguments[arguments.length - 1] instanceof Throwable) {
> this.throwable = (Throwable) arguments[arguments.length - 1];
> }
> - getFormattedMessage(); // LOG4J2-763 take snapshot of parameters at message construction time
> }
>
> /**
>
> Modified: logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/ObjectMessage.java
> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/ObjectMessage.java?rev=1617291&r1=1617290&r2=1617291&view=diff
> ==============================================================================
> --- logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/ObjectMessage.java (original)
> +++ logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/ObjectMessage.java Mon Aug 11 14:16:22 2014
> @@ -29,7 +29,7 @@ public class ObjectMessage implements Me
> private static final long serialVersionUID = -5903272448334166185L;
>
> private transient Object obj;
> - private final String objectString;
> + private transient String objectString;
>
> /**
> * Create the ObjectMessage.
> @@ -40,9 +40,6 @@ public class ObjectMessage implements Me
> obj = "null";
> }
> this.obj = obj;
> -
> - // LOG4J2-763: take snapshot of parameters at message construction time
> - objectString = String.valueOf(obj);
> }
>
> /**
> @@ -51,6 +48,10 @@ public class ObjectMessage implements Me
> */
> @Override
> public String getFormattedMessage() {
> + // LOG4J2-763: cache formatted string in case obj changes later
> + if (objectString == null) {
> + objectString = String.valueOf(obj);
> + }
> return objectString;
> }
>
> @@ -60,7 +61,7 @@ public class ObjectMessage implements Me
> */
> @Override
> public String getFormat() {
> - return objectString;
> + return getFormattedMessage();
> }
>
> /**
> @@ -69,7 +70,7 @@ public class ObjectMessage implements Me
> */
> @Override
> public Object[] getParameters() {
> - return new Object[]{obj};
> + return new Object[] { obj };
> }
>
> @Override
> @@ -82,8 +83,7 @@ public class ObjectMessage implements Me
> }
>
> final ObjectMessage that = (ObjectMessage) o;
> -
> - return !(obj != null ? !obj.equals(that.obj) : that.obj != null);
> + return obj == null ? that.obj == null : obj.equals(that.obj);
> }
>
> @Override
> @@ -93,7 +93,7 @@ public class ObjectMessage implements Me
>
> @Override
> public String toString() {
> - return "ObjectMessage[obj=" + objectString + ']';
> + return "ObjectMessage[obj=" + getFormattedMessage() + ']';
> }
>
> private void writeObject(final ObjectOutputStream out) throws IOException {
> @@ -101,7 +101,7 @@ public class ObjectMessage implements Me
> if (obj instanceof Serializable) {
> out.writeObject(obj);
> } else {
> - out.writeObject(obj.toString());
> + out.writeObject(String.valueOf(obj));
> }
> }
>
>
> Modified: logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/StringFormattedMessage.java
> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/StringFormattedMessage.java?rev=1617291&r1=1617290&r2=1617291&view=diff
> ==============================================================================
> --- logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/StringFormattedMessage.java (original)
> +++ logging/log4j/log4j2/trunk/log4j-api/src/main/java/org/apache/logging/log4j/message/StringFormattedMessage.java Mon Aug 11 14:16:22 2014
> @@ -48,7 +48,6 @@ public class StringFormattedMessage impl
> if (arguments != null && arguments.length > 0 && arguments[arguments.length - 1] instanceof Throwable) {
> this.throwable = (Throwable) arguments[arguments.length - 1];
> }
> - getFormattedMessage(); // LOG4J2-763 take snapshot of parameters at message construction time
> }
>
> /**
>
> Modified: logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/FormattedMessageTest.java
> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/FormattedMessageTest.java?rev=1617291&r1=1617290&r2=1617291&view=diff
> ==============================================================================
> --- logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/FormattedMessageTest.java (original)
> +++ logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/FormattedMessageTest.java Mon Aug 11 14:16:22 2014
> @@ -85,14 +85,27 @@ public class FormattedMessageTest {
> }
>
> @Test
> - public void testSafeWithMutableParams() { // LOG4J2-763
> + public void testUnsafeWithMutableParams() { // LOG4J2-763
> final String testMsg = "Test message %s";
> final Mutable param = new Mutable().set("abc");
> - FormattedMessage msg = new FormattedMessage(testMsg, param);
> + final FormattedMessage msg = new FormattedMessage(testMsg, param);
>
> // modify parameter before calling msg.getFormattedMessage
> param.set("XYZ");
> - String actual = msg.getFormattedMessage();
> + final String actual = msg.getFormattedMessage();
> + assertEquals("Expected most recent param value", "Test message XYZ", actual);
> + }
> +
> + @Test
> + public void testSafeAfterGetFormattedMessageIsCalled() { // LOG4J2-763
> + final String testMsg = "Test message %s";
> + final Mutable param = new Mutable().set("abc");
> + final FormattedMessage msg = new FormattedMessage(testMsg, param);
> +
> + // modify parameter after calling msg.getFormattedMessage
> + msg.getFormattedMessage(); // freeze the formatted message
> + param.set("XYZ");
> + final String actual = msg.getFormattedMessage();
> assertEquals("Should use initial param value", "Test message abc", actual);
> }
> }
>
> Modified: logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/LocalizedMessageTest.java
> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/LocalizedMessageTest.java?rev=1617291&r1=1617290&r2=1617291&view=diff
> ==============================================================================
> --- logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/LocalizedMessageTest.java (original)
> +++ logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/LocalizedMessageTest.java Mon Aug 11 14:16:22 2014
> @@ -65,15 +65,27 @@ public class LocalizedMessageTest {
> }
>
> @Test
> - public void testSafeWithMutableParams() { // LOG4J2-763
> + public void testUnsafeWithMutableParams() { // LOG4J2-763
> final String testMsg = "Test message %s";
> final Mutable param = new Mutable().set("abc");
> - LocalizedMessage msg = new LocalizedMessage(testMsg, param);
> + final LocalizedMessage msg = new LocalizedMessage(testMsg, param);
>
> // modify parameter before calling msg.getFormattedMessage
> param.set("XYZ");
> - String actual = msg.getFormattedMessage();
> - assertEquals("Should use initial param value", "Test message abc", actual);
> + final String actual = msg.getFormattedMessage();
> + assertEquals("Expected most recent param value", "Test message XYZ", actual);
> }
>
> + @Test
> + public void testSafeAfterGetFormattedMessageIsCalled() { // LOG4J2-763
> + final String testMsg = "Test message %s";
> + final Mutable param = new Mutable().set("abc");
> + final LocalizedMessage msg = new LocalizedMessage(testMsg, param);
> +
> + // modify parameter after calling msg.getFormattedMessage
> + msg.getFormattedMessage();
> + param.set("XYZ");
> + final String actual = msg.getFormattedMessage();
> + assertEquals("Should use initial param value", "Test message abc", actual);
> + }
> }
>
> Modified: logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/MessageFormatMessageTest.java
> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/MessageFormatMessageTest.java?rev=1617291&r1=1617290&r2=1617291&view=diff
> ==============================================================================
> --- logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/MessageFormatMessageTest.java (original)
> +++ logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/MessageFormatMessageTest.java Mon Aug 11 14:16:22 2014
> @@ -63,14 +63,27 @@ public class MessageFormatMessageTest {
> }
>
> @Test
> - public void testSafeWithMutableParams() { // LOG4J2-763
> + public void testUnsafeWithMutableParams() { // LOG4J2-763
> final String testMsg = "Test message {0}";
> final Mutable param = new Mutable().set("abc");
> - MessageFormatMessage msg = new MessageFormatMessage(testMsg, param);
> + final MessageFormatMessage msg = new MessageFormatMessage(testMsg, param);
>
> // modify parameter before calling msg.getFormattedMessage
> param.set("XYZ");
> - String actual = msg.getFormattedMessage();
> + final String actual = msg.getFormattedMessage();
> + assertEquals("Expected most recent param value", "Test message XYZ", actual);
> + }
> +
> + @Test
> + public void testSafeAfterGetFormattedMessageIsCalled() { // LOG4J2-763
> + final String testMsg = "Test message {0}";
> + final Mutable param = new Mutable().set("abc");
> + final MessageFormatMessage msg = new MessageFormatMessage(testMsg, param);
> +
> + // modify parameter after calling msg.getFormattedMessage
> + msg.getFormattedMessage();
> + param.set("XYZ");
> + final String actual = msg.getFormattedMessage();
> assertEquals("Should use initial param value", "Test message abc", actual);
> }
> }
>
> Modified: logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/ObjectMessageTest.java
> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/ObjectMessageTest.java?rev=1617291&r1=1617290&r2=1617291&view=diff
> ==============================================================================
> --- logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/ObjectMessageTest.java (original)
> +++ logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/ObjectMessageTest.java Mon Aug 11 14:16:22 2014
> @@ -41,13 +41,25 @@ public class ObjectMessageTest {
> }
>
> @Test
> - public void testSafeWithMutableParams() { // LOG4J2-763
> + public void testUnsafeWithMutableParams() { // LOG4J2-763
> final Mutable param = new Mutable().set("abc");
> - ObjectMessage msg = new ObjectMessage(param);
> + final ObjectMessage msg = new ObjectMessage(param);
>
> // modify parameter before calling msg.getFormattedMessage
> param.set("XYZ");
> - String actual = msg.getFormattedMessage();
> + final String actual = msg.getFormattedMessage();
> + assertEquals("Expected most recent param value", "XYZ", actual);
> + }
> +
> + @Test
> + public void testSafeAfterGetFormattedMessageIsCalled() { // LOG4J2-763
> + final Mutable param = new Mutable().set("abc");
> + final ObjectMessage msg = new ObjectMessage(param);
> +
> + // modify parameter after calling msg.getFormattedMessage
> + msg.getFormattedMessage();
> + param.set("XYZ");
> + final String actual = msg.getFormattedMessage();
> assertEquals("Should use initial param value", "abc", actual);
> }
> }
>
> Modified: logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/StringFormattedMessageTest.java
> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/StringFormattedMessageTest.java?rev=1617291&r1=1617290&r2=1617291&view=diff
> ==============================================================================
> --- logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/StringFormattedMessageTest.java (original)
> +++ logging/log4j/log4j2/trunk/log4j-api/src/test/java/org/apache/logging/log4j/message/StringFormattedMessageTest.java Mon Aug 11 14:16:22 2014
> @@ -62,14 +62,27 @@ public class StringFormattedMessageTest
> }
>
> @Test
> - public void testSafeWithMutableParams() { // LOG4J2-763
> + public void testUnsafeWithMutableParams() { // LOG4J2-763
> final String testMsg = "Test message %s";
> final Mutable param = new Mutable().set("abc");
> - StringFormattedMessage msg = new StringFormattedMessage(testMsg, param);
> + final StringFormattedMessage msg = new StringFormattedMessage(testMsg, param);
>
> // modify parameter before calling msg.getFormattedMessage
> param.set("XYZ");
> - String actual = msg.getFormattedMessage();
> + final String actual = msg.getFormattedMessage();
> + assertEquals("Should use initial param value", "Test message XYZ", actual);
> + }
> +
> + @Test
> + public void testSafeAfterGetFormattedMessageIsCalled() { // LOG4J2-763
> + final String testMsg = "Test message %s";
> + final Mutable param = new Mutable().set("abc");
> + final StringFormattedMessage msg = new StringFormattedMessage(testMsg, param);
> +
> + // modify parameter after calling msg.getFormattedMessage
> + msg.getFormattedMessage();
> + param.set("XYZ");
> + final String actual = msg.getFormattedMessage();
> assertEquals("Should use initial param value", "Test message abc", actual);
> }
> }
>
> Modified: logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java
> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java?rev=1617291&r1=1617290&r2=1617291&view=diff
> ==============================================================================
> --- logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java (original)
> +++ logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java Mon Aug 11 14:16:22 2014
> @@ -138,6 +138,7 @@ public final class AsyncAppender extends
> }
> logEvent = ((RingBufferLogEvent) logEvent).createMemento();
> }
> + logEvent.getMessage().getFormattedMessage(); // LOG4J2-763: ask message to freeze parameters
> final Log4jLogEvent coreEvent = (Log4jLogEvent) logEvent;
> boolean appendSuccessful = false;
> if (blocking) {
>
> Modified: logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java
> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java?rev=1617291&r1=1617290&r2=1617291&view=diff
> ==============================================================================
> --- logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java (original)
> +++ logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java Mon Aug 11 14:16:22 2014
> @@ -226,6 +226,7 @@ public class AsyncLogger extends Logger
>
> @Override
> public void logMessage(final String fqcn, final Level level, final Marker marker, final Message message, final Throwable thrown) {
> + // TODO refactor to reduce size to <= 35 bytecodes to allow JVM to inline it
> Info info = threadlocalInfo.get();
> if (info == null) {
> info = new Info(new RingBufferLogEventTranslator(), Thread.currentThread().getName(), false);
> @@ -245,6 +246,7 @@ public class AsyncLogger extends Logger
> config.loggerConfig.log(getName(), fqcn, marker, level, message, thrown);
> return;
> }
> + message.getFormattedMessage(); // LOG4J2-763: ask message to freeze parameters
> final boolean includeLocation = config.loggerConfig.isIncludeLocation();
> info.translator.setValues(this, getName(), marker, fqcn, level, message, //
> // don't construct ThrowableProxy until required
>
> Modified: logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java
> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java?rev=1617291&r1=1617290&r2=1617291&view=diff
> ==============================================================================
> --- logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java (original)
> +++ logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java Mon Aug 11 14:16:22 2014
> @@ -316,6 +316,7 @@ class AsyncLoggerConfigHelper {
> * calling thread needs to process the event itself
> */
> public boolean callAppendersFromAnotherThread(final LogEvent event) {
> + // TODO refactor to reduce size to <= 35 bytecodes to allow JVM to inline it
> final Disruptor<Log4jEventWrapper> temp = disruptor;
> if (temp == null) { // LOG4J2-639
> LOGGER.fatal("Ignoring log event after log4j was shut down");
> @@ -336,6 +337,8 @@ class AsyncLoggerConfigHelper {
> if (event instanceof RingBufferLogEvent) {
> logEvent = ((RingBufferLogEvent) event).createMemento();
> }
> + logEvent.getMessage().getFormattedMessage(); // LOG4J2-763: ask message to freeze parameters
> +
> // Note: do NOT use the temp variable above!
> // That could result in adding a log event to the disruptor after it was shut down,
> // which could cause the publishEvent method to hang and never return.
>
> Modified: logging/log4j/log4j2/trunk/src/changes/changes.xml
> URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/src/changes/changes.xml?rev=1617291&r1=1617290&r2=1617291&view=diff
> ==============================================================================
> --- logging/log4j/log4j2/trunk/src/changes/changes.xml (original)
> +++ logging/log4j/log4j2/trunk/src/changes/changes.xml Mon Aug 11 14:16:22 2014
> @@ -29,8 +29,7 @@
> Startup takes a long time if you have empty packages attribute.
> </action>
> <action issue="LOG4J2-763" dev="rpopma" type="fix" due-to="Stephen Connolly">
> - Improved FormattedMessage, StringFormattedMessage, LocalizedMessage, MessageFormatMessage and
> - ObjectMessage for asynchronous logging to ensure the formatted message does not change even if
> + Improved asynchronous loggers and appenders to ensure the formatted message does not change even if
> parameters are modified by the application. (ParameterizedMessage was already safe.)
> Improved documentation.
> </action>
>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org