[LOG4J2-3680] Some log events are no longer serialized correctly

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 2.22.0
• Fix Version/s: 2.23.0
• Component/s: Core
• Assignee: Piotr Karwasz
• Reporter: Peter De Maeyer
• Created: 01/Feb/24 10:11
• Updated: 08/Feb/24 14:49
• Resolved: 06/Feb/24 06:20

Description

We noticed a regression between 2.21.1 and 2.22.0 in the serilialization of log events. The below test succeeds with 2.21.1, but fails with 2.22.0. I had a look at the source code, and I think it's because of changes in the ObjectMessage.read/writeObject implementation.

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;
        }
    }
}