You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@logging.apache.org by vy...@apache.org on 2021/07/23 12:09:41 UTC
[logging-log4j2] branch master updated: LOG4J2-2816 Handle
Disruptor event translation exceptions.
This is an automated email from the ASF dual-hosted git repository.
vy pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/logging-log4j2.git
The following commit(s) were added to refs/heads/master by this push:
new 028a4ed LOG4J2-2816 Handle Disruptor event translation exceptions.
028a4ed is described below
commit 028a4ed2d5b0bc59208896cd006bd4a4d363a17e
Author: Volkan Yazici <vo...@gmail.com>
AuthorDate: Fri Jul 23 13:54:02 2021 +0200
LOG4J2-2816 Handle Disruptor event translation exceptions.
---
.../log4j/core/async/RingBufferLogEvent.java | 11 ++
.../core/async/RingBufferLogEventHandler.java | 8 +-
.../core/async/RingBufferLogEventTranslator.java | 17 +--
.../AsyncLoggerEventTranslationExceptionTest.java | 148 +++++++++++++++++++++
.../log4j/core/async/RingBufferLogEventTest.java | 70 ++++++----
src/changes/changes.xml | 4 +
6 files changed, 225 insertions(+), 33 deletions(-)
diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEvent.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEvent.java
index c7370d6..2f85883 100644
--- a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEvent.java
+++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEvent.java
@@ -63,6 +63,7 @@ public class RingBufferLogEvent implements LogEvent, ReusableMessage, CharSequen
}
}
+ private boolean populated;
private int threadPriority;
private long threadId;
private final MutableInstant instant = new MutableInstant();
@@ -108,6 +109,7 @@ public class RingBufferLogEvent implements LogEvent, ReusableMessage, CharSequen
this.contextData = mutableContextData;
this.contextStack = aContextStack;
this.asyncLogger = anAsyncLogger;
+ this.populated = true;
}
private void initTime(final Clock clock) {
@@ -156,6 +158,13 @@ public class RingBufferLogEvent implements LogEvent, ReusableMessage, CharSequen
}
/**
+ * @return {@code true} if this event is populated with data, {@code false} otherwise
+ */
+ public boolean isPopulated() {
+ return populated;
+ }
+
+ /**
* Returns {@code true} if this event is the end of a batch, {@code false} otherwise.
*
* @return {@code true} if this event is the end of a batch, {@code false} otherwise
@@ -384,6 +393,8 @@ public class RingBufferLogEvent implements LogEvent, ReusableMessage, CharSequen
* Release references held by ring buffer to allow objects to be garbage-collected.
*/
public void clear() {
+ this.populated = false;
+
this.asyncLogger = null;
this.loggerName = null;
this.marker = null;
diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEventHandler.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEventHandler.java
index 5331821..0cc1bdc 100644
--- a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEventHandler.java
+++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEventHandler.java
@@ -43,7 +43,13 @@ public class RingBufferLogEventHandler implements
public void onEvent(final RingBufferLogEvent event, final long sequence,
final boolean endOfBatch) throws Exception {
try {
- event.execute(endOfBatch);
+ // RingBufferLogEvents are populated by an EventTranslator. If an exception is thrown during event
+ // translation, the event may not be fully populated, but Disruptor requires that the associated sequence
+ // still be published since a slot has already been claimed in the ring buffer. Ignore any such unpopulated
+ // events. The exception that occurred during translation will have already been propagated.
+ if (event.isPopulated()) {
+ event.execute(endOfBatch);
+ }
}
finally {
event.clear();
diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEventTranslator.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEventTranslator.java
index c536c04..3268a90 100644
--- a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEventTranslator.java
+++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEventTranslator.java
@@ -56,14 +56,15 @@ public class RingBufferLogEventTranslator implements
// @Override
@Override
public void translateTo(final RingBufferLogEvent event, final long sequence) {
-
- event.setValues(asyncLogger, loggerName, marker, fqcn, level, message, thrown,
- // config properties are taken care of in the EventHandler thread
- // in the AsyncLogger#actualAsyncLog method
- INJECTOR.injectContextData(null, (StringMap) event.getContextData()), contextStack,
- threadId, threadName, threadPriority, location, clock, nanoClock);
-
- clear(); // clear the translator
+ try {
+ event.setValues(asyncLogger, loggerName, marker, fqcn, level, message, thrown,
+ // config properties are taken care of in the EventHandler thread
+ // in the AsyncLogger#actualAsyncLog method
+ INJECTOR.injectContextData(null, (StringMap) event.getContextData()), contextStack,
+ threadId, threadName, threadPriority, location, clock, nanoClock);
+ } finally {
+ clear(); // clear the translator
+ }
}
/**
diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerEventTranslationExceptionTest.java b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerEventTranslationExceptionTest.java
new file mode 100644
index 0000000..b57ea3f
--- /dev/null
+++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerEventTranslationExceptionTest.java
@@ -0,0 +1,148 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one or more
+ * contributor license agreements. See the NOTICE file distributed with
+ * this work for additional information regarding copyright ownership.
+ * The ASF licenses this file to You under the Apache license, Version 2.0
+ * (the "License"); you may not use this file except in compliance with
+ * the License. You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the license for the specific language governing permissions and
+ * limitations under the license.
+ */
+package org.apache.logging.log4j.core.async;
+
+import com.lmax.disruptor.ExceptionHandler;
+import org.apache.logging.log4j.Level;
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.Logger;
+import org.apache.logging.log4j.categories.AsyncLoggers;
+import org.apache.logging.log4j.core.CoreLoggerContexts;
+import org.apache.logging.log4j.core.util.Constants;
+import org.apache.logging.log4j.message.Message;
+import org.apache.logging.log4j.message.ReusableSimpleMessage;
+import org.apache.logging.log4j.spi.AbstractLogger;
+import org.junit.experimental.categories.Category;
+import org.junit.jupiter.api.AfterAll;
+import org.junit.jupiter.api.BeforeAll;
+import org.junit.jupiter.api.Test;
+
+import static org.junit.jupiter.api.Assertions.*;
+
+/**
+ * Test an exception thrown in {@link RingBufferLogEventTranslator#translateTo(RingBufferLogEvent, long)}
+ * does not cause another exception to be thrown later in the background thread
+ * in {@link RingBufferLogEventHandler#onEvent(RingBufferLogEvent, long, boolean)}.
+ *
+ * @see <a href="https://issues.apache.org/jira/browse/LOG4J2-2816">LOG4J2-2816</a>
+ */
+@Category(AsyncLoggers.class)
+class AsyncLoggerEventTranslationExceptionTest {
+
+ @BeforeAll
+ public static void beforeAll() {
+ System.setProperty(Constants.LOG4J_CONTEXT_SELECTOR, AsyncLoggerContextSelector.class.getName());
+ System.setProperty("AsyncLogger.ExceptionHandler", TestExceptionHandler.class.getName());
+ }
+
+ @AfterAll
+ public static void afterAll() {
+ System.clearProperty(Constants.LOG4J_CONTEXT_SELECTOR);
+ System.clearProperty("AsyncLogger.ExceptionHandler");
+ }
+
+ @Test
+ void testEventTranslationExceptionDoesNotCauseAsyncEventException() {
+
+ final Logger log = LogManager.getLogger("com.foo.Bar");
+
+ assertTrue(
+ TestExceptionHandler.INSTANTIATED,
+ "TestExceptionHandler was not configured properly");
+
+ final Message exceptionThrowingMessage = new ExceptionThrowingMessage();
+ assertThrows(
+ TestMessageException.class,
+ () -> ((AbstractLogger) log).logMessage(
+ "com.foo.Bar",
+ Level.INFO,
+ null,
+ exceptionThrowingMessage,
+ null));
+
+ CoreLoggerContexts.stopLoggerContext(); // stop async thread
+
+ assertFalse(
+ TestExceptionHandler.EVENT_EXCEPTION_ENCOUNTERED,
+ "ExceptionHandler encountered an event exception");
+
+ }
+
+ public static final class TestExceptionHandler implements ExceptionHandler<RingBufferLogEvent> {
+
+ private static boolean INSTANTIATED = false;
+
+ private static boolean EVENT_EXCEPTION_ENCOUNTERED = false;
+
+ public TestExceptionHandler() {
+ INSTANTIATED = true;
+ }
+
+ @Override
+ public void handleEventException(final Throwable error, final long sequence, final RingBufferLogEvent event) {
+ EVENT_EXCEPTION_ENCOUNTERED = true;
+ }
+
+ @Override
+ public void handleOnStartException(final Throwable error) {
+ fail("Unexpected start exception: " + error.getMessage());
+ }
+
+ @Override
+ public void handleOnShutdownException(final Throwable error) {
+ fail("Unexpected shutdown exception: " + error.getMessage());
+ }
+
+ }
+
+ private static class TestMessageException extends RuntimeException {}
+
+ private static final class ExceptionThrowingMessage extends ReusableSimpleMessage {
+
+ @Override
+ public String getFormattedMessage() {
+ throw new TestMessageException();
+ }
+
+ @Override
+ public String getFormat() {
+ throw new TestMessageException();
+ }
+
+ @Override
+ public Object[] getParameters() {
+ throw new TestMessageException();
+ }
+
+ @Override
+ public void formatTo(final StringBuilder buffer) {
+ throw new TestMessageException();
+ }
+
+ @Override
+ public Object[] swapParameters(final Object[] emptyReplacement) {
+ throw new TestMessageException();
+ }
+
+ @Override
+ public short getParameterCount() {
+ throw new TestMessageException();
+ }
+
+ }
+
+}
diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/async/RingBufferLogEventTest.java b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/RingBufferLogEventTest.java
index ef6a1ad..3dd4b06 100644
--- a/log4j-core/src/test/java/org/apache/logging/log4j/core/async/RingBufferLogEventTest.java
+++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/RingBufferLogEventTest.java
@@ -17,33 +17,32 @@
package org.apache.logging.log4j.core.async;
-import java.io.ByteArrayInputStream;
-import java.io.ByteArrayOutputStream;
-import java.io.IOException;
-import java.io.ObjectInputStream;
-import java.io.ObjectOutputStream;
-import java.util.Arrays;
-
import org.apache.logging.log4j.Level;
import org.apache.logging.log4j.Marker;
import org.apache.logging.log4j.MarkerManager;
import org.apache.logging.log4j.ThreadContext.ContextStack;
-import org.apache.logging.log4j.core.test.categories.AsyncLoggers;
import org.apache.logging.log4j.core.LogEvent;
+import org.apache.logging.log4j.core.impl.ThrowableProxy;
+import org.apache.logging.log4j.core.test.categories.AsyncLoggers;
import org.apache.logging.log4j.core.time.internal.DummyNanoClock;
import org.apache.logging.log4j.core.time.internal.FixedPreciseClock;
-import org.apache.logging.log4j.message.ParameterConsumer;
-import org.apache.logging.log4j.message.ReusableMessageFactory;
-import org.apache.logging.log4j.util.FilteredObjectInputStream;
-import org.apache.logging.log4j.util.StringMap;
-import org.apache.logging.log4j.core.impl.ThrowableProxy;
import org.apache.logging.log4j.message.Message;
+import org.apache.logging.log4j.message.ReusableMessageFactory;
import org.apache.logging.log4j.message.SimpleMessage;
import org.apache.logging.log4j.spi.MutableThreadContextStack;
+import org.apache.logging.log4j.util.FilteredObjectInputStream;
+import org.apache.logging.log4j.util.StringMap;
import org.junit.Assert;
import org.junit.Test;
import org.junit.experimental.categories.Category;
+import java.io.ByteArrayInputStream;
+import java.io.ByteArrayOutputStream;
+import java.io.IOException;
+import java.io.ObjectInputStream;
+import java.io.ObjectOutputStream;
+import java.util.Arrays;
+
import static org.hamcrest.CoreMatchers.sameInstance;
import static org.junit.Assert.*;
@@ -58,7 +57,35 @@ public class RingBufferLogEventTest {
final LogEvent logEvent = new RingBufferLogEvent();
Assert.assertNotSame(logEvent, logEvent.toImmutable());
}
-
+
+ /**
+ * @see <a href="https://issues.apache.org/jira/browse/LOG4J2-2816">LOG4J2-2816</a>
+ */
+ @Test
+ public void testIsPopulated() {
+ final RingBufferLogEvent evt = new RingBufferLogEvent();
+
+ assertFalse(evt.isPopulated());
+
+ final String loggerName = null;
+ final Marker marker = null;
+ final String fqcn = null;
+ final Level level = null;
+ final Message data = null;
+ final Throwable t = null;
+ final ContextStack contextStack = null;
+ final String threadName = null;
+ final StackTraceElement location = null;
+ evt.setValues(null, loggerName, marker, fqcn, level, data, t, (StringMap) evt.getContextData(),
+ contextStack, -1, threadName, -1, location, new FixedPreciseClock(), new DummyNanoClock(1));
+
+ assertTrue(evt.isPopulated());
+
+ evt.clear();
+
+ assertFalse(evt.isPopulated());
+ }
+
@Test
public void testGetLevelReturnsOffIfNullLevelSet() {
final RingBufferLogEvent evt = new RingBufferLogEvent();
@@ -192,8 +219,8 @@ public class RingBufferLogEventTest {
final Marker marker = MarkerManager.getMarker("marked man");
final String fqcn = "f.q.c.n";
final Level level = Level.TRACE;
- ReusableMessageFactory factory = new ReusableMessageFactory();
- Message message = factory.newMessage("Hello {}!", "World");
+ final ReusableMessageFactory factory = new ReusableMessageFactory();
+ final Message message = factory.newMessage("Hello {}!", "World");
try {
final Throwable t = new InternalError("not a real error");
final ContextStack contextStack = new MutableThreadContextStack(Arrays.asList("a", "b"));
@@ -221,8 +248,8 @@ public class RingBufferLogEventTest {
final Marker marker = MarkerManager.getMarker("marked man");
final String fqcn = "f.q.c.n";
final Level level = Level.TRACE;
- ReusableMessageFactory factory = new ReusableMessageFactory();
- Message message = factory.newMessage("Hello {}!", "World");
+ final ReusableMessageFactory factory = new ReusableMessageFactory();
+ final Message message = factory.newMessage("Hello {}!", "World");
try {
final Throwable t = new InternalError("not a real error");
final ContextStack contextStack = new MutableThreadContextStack(Arrays.asList("a", "b"));
@@ -253,11 +280,6 @@ public class RingBufferLogEventTest {
@Test
public void testForEachParameterNothingSet() {
final RingBufferLogEvent evt = new RingBufferLogEvent();
- evt.forEachParameter(new ParameterConsumer<Void>() {
- @Override
- public void accept(Object parameter, int parameterIndex, Void state) {
- fail("Should not have been called");
- }
- }, null);
+ evt.forEachParameter((parameter, parameterIndex, state) -> fail("Should not have been called"), null);
}
}
diff --git a/src/changes/changes.xml b/src/changes/changes.xml
index c61d77a..ff1b534 100644
--- a/src/changes/changes.xml
+++ b/src/changes/changes.xml
@@ -217,8 +217,12 @@
Allow a PatternSelector to be specified on GelfLayout.
</action>
<!-- FIXES -->
+ <action issue="LOG4J2-2816" dev="vy" type="fix" due-to="Jacob Shields">
+ Handle Disruptor event translation exceptions.
+ </action>
<action issue="LOG4J2-3121" dev="ggregory" type="fix" due-to="Markus Spann">
log4j2 config modified at run-time may trigger incomplete MBean re-initialization due to InstanceAlreadyExistsException.
+ </action>
<action issue="LOG4J2-3107" dev="vy" type="fix" due-to="Markus Spann">
SmtpManager.createManagerName ignores port.
</action>