[
https://issues.apache.org/jira/browse/LOG4J2-3680?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Peter De Maeyer updated LOG4J2-3680:
------------------------------------
Description:
When we updated from 2.20.0 to 2.22.1 (I had to pick 2.22.0 in the *Affects
Version/s* because 2.22.1 does not exists in the Jira project), we noticed a
regression in the serilialization of log events. The below test succeeds with
2.20.0, but fails with 2.22.1. I had a look at the source code, and I think
it's because of changes in the {{ObjectMessage.read/writeObject}}
implementation.
{code:java}
import static org.apache.logging.log4j.LogManager.getLogger;
import static org.junit.jupiter.api.Assertions.assertEquals;
import java.io.ByteArrayInputStream;
import java.io.ByteArrayOutputStream;
import java.io.IOException;
import java.io.ObjectInputStream;
import java.io.ObjectOutputStream;
import java.io.Serializable;
import java.util.ArrayList;
import java.util.List;
import org.apache.logging.log4j.core.Appender;
import org.apache.logging.log4j.core.ErrorHandler;
import org.apache.logging.log4j.core.Layout;
import org.apache.logging.log4j.core.LogEvent;
import org.apache.logging.log4j.core.Logger;
import org.junit.jupiter.api.AfterEach;
import org.junit.jupiter.api.BeforeEach;
import org.junit.jupiter.api.Test;
class Log4jSerializationTest {
private final Logger logger = (Logger)
getLogger(Log4jSerializationTest.class);
private final RecordingAppender appender = new
RecordingAppender(Log4jSerializationTest.class.getName());
@BeforeEach
void addRecordingAppender() {
appender.start();
logger.addAppender(appender);
}
@AfterEach
void removeRecordingAppender() {
logger.removeAppender(appender);
appender.stop();
}
@Test
void logEventSerialization() {
RuntimeException exception = new RuntimeException("induced by test");
logger.error(exception, exception);
LogEvent event = appender.getEvents().get(0);
assertEquals(RuntimeException.class.getName() + ": induced by test",
event.getMessage().getFormattedMessage());
}
static class RecordingAppender implements Appender {
private final List<LogEvent> events = new ArrayList();
private State state = State.STOPPED;
private final String name;
private ErrorHandler handler;
public RecordingAppender(String name) {
this.name = name;
}
@Override
public State getState() {
return state;
}
@Override
public void initialize() {
state = State.INITIALIZED;
}
@Override
public boolean isStarted() {
return state == State.STARTED;
}
@Override
public boolean isStopped() {
return !isStarted();
}
@Override
public void start() {
events.clear();
state = State.STARTED;
}
@Override
public void stop() {
events.clear();
state = State.STOPPED;
}
@Override
public synchronized void append(LogEvent event) {
// The event is a mutable one, Log4j2 emits the same event instance
but changes the message each time.
// If we want to hold on to the event details, we need to clone the
event.
// LogEvent is not an instance of Cloneable, but it IS an instance
of Serializable.
// So we clone by serializing and deserializing.
ByteArrayOutputStream out = new ByteArrayOutputStream();
try (ObjectOutputStream objectOut = new ObjectOutputStream(out)) {
objectOut.writeObject(event);
} catch (IOException e) {
throw new RuntimeException(e);
}
LogEvent clone;
try (ObjectInputStream objectInput = new ObjectInputStream(new
ByteArrayInputStream(out.toByteArray()))) {
clone = (LogEvent) objectInput.readObject();
} catch (IOException | ClassNotFoundException e) {
throw new RuntimeException(e);
}
events.add(clone);
}
@Override
public ErrorHandler getHandler() {
return handler;
}
@Override
public Layout<? extends Serializable> getLayout() {
return null;
}
@Override
public String getName() {
return name;
}
@Override
public boolean ignoreExceptions() {
return true;
}
@Override
public void setHandler(ErrorHandler handler) {
this.handler = handler;
}
public synchronized List<LogEvent> getEvents() {
return events;
}
}
}
{code}
was:
When we updated from 2.20.0 to 2.22.1 (I had to pick 2.22.0 in the *Affects
Version/s* because 2.22.1 does not exists in the Jira project), we noticed a
regression in the serilialization of log events. The following test succeeds
with 2.20.0, but fails with 2.22.1. I had a look at the source code, and I
think it's because of changes in the {{ObjectMessage.read/writeObject}}
implementation.
{code:java}
import static org.apache.logging.log4j.LogManager.getLogger;
import static org.junit.jupiter.api.Assertions.assertEquals;
import java.io.ByteArrayInputStream;
import java.io.ByteArrayOutputStream;
import java.io.IOException;
import java.io.ObjectInputStream;
import java.io.ObjectOutputStream;
import java.io.Serializable;
import java.util.ArrayList;
import java.util.List;
import org.apache.logging.log4j.core.Appender;
import org.apache.logging.log4j.core.ErrorHandler;
import org.apache.logging.log4j.core.Layout;
import org.apache.logging.log4j.core.LogEvent;
import org.apache.logging.log4j.core.Logger;
import org.junit.jupiter.api.AfterEach;
import org.junit.jupiter.api.BeforeEach;
import org.junit.jupiter.api.Test;
class Log4jSerializationTest {
private final Logger logger = (Logger)
getLogger(Log4jSerializationTest.class);
private final RecordingAppender appender = new
RecordingAppender(Log4jSerializationTest.class.getName());
@BeforeEach
void addRecordingAppender() {
appender.start();
logger.addAppender(appender);
}
@AfterEach
void removeRecordingAppender() {
logger.removeAppender(appender);
appender.stop();
}
@Test
void logEventSerialization() {
RuntimeException exception = new RuntimeException("induced by test");
logger.error(exception, exception);
LogEvent event = appender.getEvents().get(0);
assertEquals(RuntimeException.class.getName() + ": induced by test",
event.getMessage().getFormattedMessage());
}
static class RecordingAppender implements Appender {
private final List<LogEvent> events = new ArrayList();
private State state = State.STOPPED;
private final String name;
private ErrorHandler handler;
public RecordingAppender(String name) {
this.name = name;
}
@Override
public State getState() {
return state;
}
@Override
public void initialize() {
state = State.INITIALIZED;
}
@Override
public boolean isStarted() {
return state == State.STARTED;
}
@Override
public boolean isStopped() {
return !isStarted();
}
@Override
public void start() {
events.clear();
state = State.STARTED;
}
@Override
public void stop() {
events.clear();
state = State.STOPPED;
}
@Override
public synchronized void append(LogEvent event) {
// The event is a mutable one, Log4j2 emits the same event instance
but changes the message each time.
// If we want to hold on to the event details, we need to clone the
event.
// LogEvent is not an instance of Cloneable, but it IS an instance
of Serializable.
// So we clone by serializing and deserializing.
ByteArrayOutputStream out = new ByteArrayOutputStream();
try (ObjectOutputStream objectOut = new ObjectOutputStream(out)) {
objectOut.writeObject(event);
} catch (IOException e) {
throw new RuntimeException(e);
}
LogEvent clone;
try (ObjectInputStream objectInput = new ObjectInputStream(new
ByteArrayInputStream(out.toByteArray()))) {
clone = (LogEvent) objectInput.readObject();
} catch (IOException | ClassNotFoundException e) {
throw new RuntimeException(e);
}
events.add(clone);
}
@Override
public ErrorHandler getHandler() {
return handler;
}
@Override
public Layout<? extends Serializable> getLayout() {
return null;
}
@Override
public String getName() {
return name;
}
@Override
public boolean ignoreExceptions() {
return true;
}
@Override
public void setHandler(ErrorHandler handler) {
this.handler = handler;
}
public synchronized List<LogEvent> getEvents() {
return events;
}
}
}
{code}
> Some log events are no longer serialized correctly
> --------------------------------------------------
>
> Key: LOG4J2-3680
> URL: https://issues.apache.org/jira/browse/LOG4J2-3680
> Project: Log4j 2
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.22.0
> Reporter: Peter De Maeyer
> Priority: Major
>
> When we updated from 2.20.0 to 2.22.1 (I had to pick 2.22.0 in the *Affects
> Version/s* because 2.22.1 does not exists in the Jira project), we noticed a
> regression in the serilialization of log events. The below test succeeds with
> 2.20.0, but fails with 2.22.1. I had a look at the source code, and I think
> it's because of changes in the {{ObjectMessage.read/writeObject}}
> implementation.
> {code:java}
> import static org.apache.logging.log4j.LogManager.getLogger;
> import static org.junit.jupiter.api.Assertions.assertEquals;
> import java.io.ByteArrayInputStream;
> import java.io.ByteArrayOutputStream;
> import java.io.IOException;
> import java.io.ObjectInputStream;
> import java.io.ObjectOutputStream;
> import java.io.Serializable;
> import java.util.ArrayList;
> import java.util.List;
> import org.apache.logging.log4j.core.Appender;
> import org.apache.logging.log4j.core.ErrorHandler;
> import org.apache.logging.log4j.core.Layout;
> import org.apache.logging.log4j.core.LogEvent;
> import org.apache.logging.log4j.core.Logger;
> import org.junit.jupiter.api.AfterEach;
> import org.junit.jupiter.api.BeforeEach;
> import org.junit.jupiter.api.Test;
> class Log4jSerializationTest {
> private final Logger logger = (Logger)
> getLogger(Log4jSerializationTest.class);
> private final RecordingAppender appender = new
> RecordingAppender(Log4jSerializationTest.class.getName());
> @BeforeEach
> void addRecordingAppender() {
> appender.start();
> logger.addAppender(appender);
> }
> @AfterEach
> void removeRecordingAppender() {
> logger.removeAppender(appender);
> appender.stop();
> }
> @Test
> void logEventSerialization() {
> RuntimeException exception = new RuntimeException("induced by test");
> logger.error(exception, exception);
> LogEvent event = appender.getEvents().get(0);
> assertEquals(RuntimeException.class.getName() + ": induced by test",
> event.getMessage().getFormattedMessage());
> }
> static class RecordingAppender implements Appender {
> private final List<LogEvent> events = new ArrayList();
> private State state = State.STOPPED;
> private final String name;
> private ErrorHandler handler;
> public RecordingAppender(String name) {
> this.name = name;
> }
> @Override
> public State getState() {
> return state;
> }
> @Override
> public void initialize() {
> state = State.INITIALIZED;
> }
> @Override
> public boolean isStarted() {
> return state == State.STARTED;
> }
> @Override
> public boolean isStopped() {
> return !isStarted();
> }
> @Override
> public void start() {
> events.clear();
> state = State.STARTED;
> }
> @Override
> public void stop() {
> events.clear();
> state = State.STOPPED;
> }
> @Override
> public synchronized void append(LogEvent event) {
> // The event is a mutable one, Log4j2 emits the same event
> instance but changes the message each time.
> // If we want to hold on to the event details, we need to clone
> the event.
> // LogEvent is not an instance of Cloneable, but it IS an
> instance of Serializable.
> // So we clone by serializing and deserializing.
> ByteArrayOutputStream out = new ByteArrayOutputStream();
> try (ObjectOutputStream objectOut = new ObjectOutputStream(out)) {
> objectOut.writeObject(event);
> } catch (IOException e) {
> throw new RuntimeException(e);
> }
> LogEvent clone;
> try (ObjectInputStream objectInput = new ObjectInputStream(new
> ByteArrayInputStream(out.toByteArray()))) {
> clone = (LogEvent) objectInput.readObject();
> } catch (IOException | ClassNotFoundException e) {
> throw new RuntimeException(e);
> }
> events.add(clone);
> }
> @Override
> public ErrorHandler getHandler() {
> return handler;
> }
> @Override
> public Layout<? extends Serializable> getLayout() {
> return null;
> }
> @Override
> public String getName() {
> return name;
> }
> @Override
> public boolean ignoreExceptions() {
> return true;
> }
> @Override
> public void setHandler(ErrorHandler handler) {
> this.handler = handler;
> }
> public synchronized List<LogEvent> getEvents() {
> return events;
> }
> }
> }
> {code}
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
