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 2020/09/23 12:28:24 UTC
[logging-log4j2] 01/01: LOG4J2-620 ReconfigurationDeadlockTest
rewrite to prevent spurious failures.
This is an automated email from the ASF dual-hosted git repository.
vy pushed a commit to branch release-2.x
in repository https://gitbox.apache.org/repos/asf/logging-log4j2.git
commit 751cebdb59e1046e080ee96a21233602355c65de
Author: Volkan Yazici <vo...@gmail.com>
AuthorDate: Wed Sep 23 12:13:40 2020 +0200
LOG4J2-620 ReconfigurationDeadlockTest rewrite to prevent spurious failures.
---
.../core/config/ReconfigurationDeadlockTest.java | 209 +++++++++++++--------
.../log4j/test/SomethingThatUsesLogging.java | 36 ----
.../log4j/test/appender/DeadlockAppender.java | 85 ---------
.../log4j/test/appender/UsesLoggingAppender.java | 67 -------
.../test/resources/reconfiguration-deadlock.xml | 25 ++-
5 files changed, 143 insertions(+), 279 deletions(-)
diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/config/ReconfigurationDeadlockTest.java b/log4j-core/src/test/java/org/apache/logging/log4j/core/config/ReconfigurationDeadlockTest.java
index 5a6d5a2..91a8673 100644
--- a/log4j-core/src/test/java/org/apache/logging/log4j/core/config/ReconfigurationDeadlockTest.java
+++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/config/ReconfigurationDeadlockTest.java
@@ -16,107 +16,162 @@
*/
package org.apache.logging.log4j.core.config;
-import java.io.File;
-
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
+import org.apache.logging.log4j.core.Appender;
+import org.apache.logging.log4j.core.Core;
+import org.apache.logging.log4j.core.Filter;
+import org.apache.logging.log4j.core.Layout;
+import org.apache.logging.log4j.core.LogEvent;
+import org.apache.logging.log4j.core.appender.AbstractAppender;
+import org.apache.logging.log4j.core.config.plugins.Plugin;
+import org.apache.logging.log4j.core.config.plugins.PluginAttribute;
+import org.apache.logging.log4j.core.config.plugins.PluginElement;
+import org.apache.logging.log4j.core.config.plugins.PluginFactory;
+import org.apache.logging.log4j.core.config.plugins.validation.constraints.Required;
import org.apache.logging.log4j.junit.LoggerContextSource;
-import org.apache.logging.log4j.message.ThreadDumpMessage;
-import org.junit.jupiter.api.Test;
-
-import static org.junit.jupiter.api.Assertions.*;
+import org.junit.jupiter.api.AfterEach;
+import org.junit.jupiter.api.Assertions;
+import org.junit.jupiter.api.BeforeEach;
+import org.junit.jupiter.api.RepeatedTest;
+import java.io.File;
+import java.util.List;
+import java.util.concurrent.CountDownLatch;
+import java.util.concurrent.ExecutorService;
+import java.util.concurrent.Executors;
+import java.util.concurrent.Future;
+import java.util.concurrent.TimeUnit;
+import java.util.stream.Collectors;
+import java.util.stream.IntStream;
+
+/**
+ * Performs reconfiguration whilst logging.
+ *
+ * @see <a href="https://issues.apache.org/jira/browse/LOG4J2-620">LOG4J2-620</a>
+ * @see TestAppender
+ */
@LoggerContextSource("reconfiguration-deadlock.xml")
public class ReconfigurationDeadlockTest {
- private static final int THREAD_COUNT = 5;
- private static final boolean[] finished = new boolean[THREAD_COUNT];
- private static LoggerThread[] threads = new LoggerThread[THREAD_COUNT];
-
- @Test
- public void testReconfig() throws InterruptedException {
+ private static final int WORKER_COUNT = 100;
- final Updater updater = new Updater();
- for (int i = 0; i < THREAD_COUNT; ++i) {
- threads[i] = new LoggerThread(i);
- threads[i].setDaemon(true);
- }
- for (int i = 0; i < THREAD_COUNT; ++i) {
+ private ExecutorService executor;
- threads[i].start();
- }
- updater.setDaemon(true);
- updater.start();
- Thread.sleep(100);
- boolean stillWaiting = true;
- for (int i = 0; i < 200; ++i) {
- int index = 0;
- for (; index < THREAD_COUNT; ++index) {
- if (!finished[index]) {
- break;
- }
- }
- if (index == THREAD_COUNT) {
- stillWaiting = false;
- break;
- }
- Thread.sleep(100);
- }
- updater.shutdown = true;
- if (stillWaiting) {
- final ThreadDumpMessage message = new ThreadDumpMessage("Waiting");
- System.err.print(message.getFormattedMessage());
- }
- for (int i = 0; i < THREAD_COUNT; ++i) {
- if (threads[i].isAlive()) {
- threads[i].interrupt();
- }
- }
- assertFalse(stillWaiting, "loggerThread didn't finish");
+ @BeforeEach
+ public void startExecutor() {
+ executor = Executors.newFixedThreadPool(WORKER_COUNT);
+ }
+ @AfterEach
+ public void stopExecutor() throws InterruptedException {
+ executor.shutdownNow();
+ final boolean terminated = executor.awaitTermination(30, TimeUnit.SECONDS);
+ Assertions.assertTrue(terminated, "couldn't terminate the executor");
}
- private static class LoggerThread extends Thread {
+ @RepeatedTest(100)
+ public void reconfiguration_should_not_cause_deadlock_for_ongoing_logging() throws Exception {
- private final Logger logger = LogManager.getRootLogger();
- private final int index;
+ // Try to update the config file to ensure that we can indeed update it.
+ updateConfigFileModTime();
- public LoggerThread(final int i) {
- index = i;
- }
- @Override
- public void run() {
- int i = 0;
+ // Start the workers.
+ final CountDownLatch workerStartLatch = new CountDownLatch(WORKER_COUNT);
+ List<Future<?>> workerFutures = initiateWorkers(workerStartLatch, executor);
+
+ // Await workers to start and update the config file.
+ workerStartLatch.await(10, TimeUnit.SECONDS);
+ updateConfigFileModTime();
+
+ // Verify that all workers have finished okay.
+ for (int workerIndex = 0; workerIndex < WORKER_COUNT; workerIndex++) {
+ final Future<?> workerFuture = workerFutures.get(workerIndex);
try {
- for (i=0; i < 30; ++i) {
- logger.error("Thread: " + index + ", Test: " + i++);
- }
- } catch (final Exception ie) {
- return;
+ Object workerResult = workerFuture.get(30, TimeUnit.SECONDS);
+ Assertions.assertNull(workerResult);
+ } catch (final Throwable failure) {
+ final String message = String.format(
+ "check for worker %02d/%02d has failed",
+ (workerIndex + 1), WORKER_COUNT);
+ throw new AssertionError(message, failure);
}
- finished[index] = true;
}
+
}
- private static class Updater extends Thread {
+ private static void updateConfigFileModTime() {
+ final File file = new File("target/test-classes/reconfiguration-deadlock.xml");
+ final boolean fileModified = file.setLastModified(System.currentTimeMillis());
+ Assertions.assertTrue(fileModified, "couldn't update file modification time");
+ }
+
+ @SuppressWarnings("SameParameterValue")
+ private static List<Future<?>> initiateWorkers(
+ final CountDownLatch workerStartLatch,
+ final ExecutorService executor) {
+ final Logger logger = LogManager.getRootLogger();
+ return IntStream
+ .range(0, WORKER_COUNT)
+ .mapToObj((final int workerIndex) -> executor.submit(() -> {
+ int i = 0;
+ for (; i < 1_000; i++) {
+ logger.error("worker={}, iteration={}", workerIndex, i);
+ }
+ workerStartLatch.countDown();
+ for (; i < 5_000; i++) {
+ logger.error("worker={}, iteration={}", workerIndex, i);
+ }
+ }))
+ .collect(Collectors.toList());
+ }
- public volatile boolean shutdown = false;
+ /**
+ * A dummy appender doing nothing but burning CPU cycles whilst randomly accessing the logger.
+ */
+ @Plugin(name = "ReconfigurationDeadlockTestAppender",
+ category = Core.CATEGORY_NAME,
+ elementType = Appender.ELEMENT_TYPE,
+ printObject = true)
+ public static final class TestAppender extends AbstractAppender {
+
+ private final Logger logger;
+
+ private TestAppender(
+ final String name,
+ final Filter filter,
+ final Layout<?> layout,
+ final boolean ignoreExceptions) {
+ super(name, filter, layout, ignoreExceptions, Property.EMPTY_ARRAY);
+ this.logger = LogManager.getRootLogger();
+ }
+ @PluginFactory
+ public static TestAppender createAppender(
+ @PluginAttribute("name") @Required(message = "A name for the Appender must be specified") final String name,
+ @PluginAttribute("ignoreExceptions") final boolean ignore,
+ @PluginElement("Layout") final Layout<?> layout,
+ @PluginElement("Filter") final Filter filter) {
+ return new TestAppender(name, filter, layout, ignore);
+ }
+
+ /**
+ * Does nothing but burning CPU cycles and accessing to the logger.
+ */
@Override
- public void run() {
- while (!shutdown) {
- try {
- Thread.sleep(1000);
- } catch (final InterruptedException e) {
- e.printStackTrace();
- }
- // for running from IDE
- final File file = new File("target/test-classes/reconfiguration-deadlock.xml");
- if (file.exists()) {
- file.setLastModified(System.currentTimeMillis());
- }
+ public void append(final LogEvent event) {
+ boolean endOfBatch;
+ final int eventHashCode = event.hashCode();
+ switch (Math.abs(eventHashCode % 4)) {
+ case 0: endOfBatch = logger.isTraceEnabled(); break;
+ case 1: endOfBatch = logger.isDebugEnabled(); break;
+ case 2: endOfBatch = logger.isInfoEnabled(); break;
+ case 3: endOfBatch = logger.isWarnEnabled(); break;
+ default: throw new IllegalStateException();
}
+ event.setEndOfBatch(endOfBatch);
}
+
}
}
diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/test/SomethingThatUsesLogging.java b/log4j-core/src/test/java/org/apache/logging/log4j/test/SomethingThatUsesLogging.java
deleted file mode 100644
index 11715fd..0000000
--- a/log4j-core/src/test/java/org/apache/logging/log4j/test/SomethingThatUsesLogging.java
+++ /dev/null
@@ -1,36 +0,0 @@
-/*
- * 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.test;
-
-import org.apache.logging.log4j.Level;
-import org.apache.logging.log4j.LogManager;
-import org.apache.logging.log4j.Logger;
-/**
- *
- */
-public class SomethingThatUsesLogging {
-
- private final Logger logger;
-
- public SomethingThatUsesLogging() {
- logger = LogManager.getLogger();
- }
-
- public void doSomething() {
- logger.isEnabled(Level.DEBUG);
- }
-}
diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/test/appender/DeadlockAppender.java b/log4j-core/src/test/java/org/apache/logging/log4j/test/appender/DeadlockAppender.java
deleted file mode 100644
index 588ae57..0000000
--- a/log4j-core/src/test/java/org/apache/logging/log4j/test/appender/DeadlockAppender.java
+++ /dev/null
@@ -1,85 +0,0 @@
-/*
- * 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.test.appender;
-
-import java.util.concurrent.TimeUnit;
-
-import org.apache.logging.log4j.LogManager;
-import org.apache.logging.log4j.Logger;
-import org.apache.logging.log4j.LoggingException;
-import org.apache.logging.log4j.core.Appender;
-import org.apache.logging.log4j.core.LogEvent;
-import org.apache.logging.log4j.core.appender.AbstractAppender;
-import org.apache.logging.log4j.core.config.Property;
-import org.apache.logging.log4j.core.config.plugins.Plugin;
-import org.apache.logging.log4j.core.config.plugins.PluginAttribute;
-import org.apache.logging.log4j.core.config.plugins.PluginFactory;
-import org.apache.logging.log4j.core.config.plugins.validation.constraints.Required;
-
-/**
- *
- */
-@Plugin(name="Deadlock", category ="Core", elementType=Appender.ELEMENT_TYPE, printObject=true)
-public class DeadlockAppender extends AbstractAppender {
-
- private WorkerThread thread = null;
-
- private DeadlockAppender(final String name) {
- super(name, null, null, false, Property.EMPTY_ARRAY);
- thread = new WorkerThread();
- }
-
- @Override
- public void start() {
- super.start();
-
- }
-
- @Override
- public boolean stop(final long timeout, final TimeUnit timeUnit) {
- setStopping();
- super.stop(timeout, timeUnit, false);
- thread.start();
- try {
- thread.join();
- } catch (final Exception ex) {
- System.out.println("Thread interrupted");
- }
- setStopped();
- return true;
- }
-
- @Override
- public void append(final LogEvent event) {
- throw new LoggingException("Always fail");
- }
-
- @PluginFactory
- public static DeadlockAppender createAppender(
- @PluginAttribute("name") @Required(message = "A name for the Appender must be specified") final String name) {
- return new DeadlockAppender(name);
- }
-
- private class WorkerThread extends Thread {
-
- @Override
- public void run() {
- final Logger logger = LogManager.getLogger("org.apache.logging.log4j.test.WorkerThread");
- logger.debug("Worker is running");
- }
- }
-}
diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/test/appender/UsesLoggingAppender.java b/log4j-core/src/test/java/org/apache/logging/log4j/test/appender/UsesLoggingAppender.java
deleted file mode 100644
index ff43419..0000000
--- a/log4j-core/src/test/java/org/apache/logging/log4j/test/appender/UsesLoggingAppender.java
+++ /dev/null
@@ -1,67 +0,0 @@
-/*
- * 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.test.appender;
-
-import org.apache.logging.log4j.core.Appender;
-import org.apache.logging.log4j.core.Core;
-import org.apache.logging.log4j.core.Filter;
-import org.apache.logging.log4j.core.Layout;
-import org.apache.logging.log4j.core.LogEvent;
-import org.apache.logging.log4j.core.appender.AbstractAppender;
-import org.apache.logging.log4j.core.config.Property;
-import org.apache.logging.log4j.core.config.plugins.Plugin;
-import org.apache.logging.log4j.core.config.plugins.PluginAttribute;
-import org.apache.logging.log4j.core.config.plugins.PluginElement;
-import org.apache.logging.log4j.core.config.plugins.PluginFactory;
-import org.apache.logging.log4j.core.config.plugins.validation.constraints.Required;
-import org.apache.logging.log4j.test.SomethingThatUsesLogging;
-
-/**
- *
- */
-@Plugin(name = "UsesLoggingAppender", category = Core.CATEGORY_NAME, elementType = Appender.ELEMENT_TYPE, printObject = true)
-public final class UsesLoggingAppender extends AbstractAppender {
-
- private final SomethingThatUsesLogging thing;
-
- private UsesLoggingAppender(final String name, final Filter filter, final Layout<?> layout, final boolean ignoreExceptions) {
- super(name, filter, layout, ignoreExceptions, Property.EMPTY_ARRAY);
- thing = new SomethingThatUsesLogging();
- }
-
- @PluginFactory
- public static UsesLoggingAppender createAppender(
- @PluginAttribute("name") @Required(message = "A name for the Appender must be specified") final String name,
- @PluginAttribute("ignoreExceptions") final boolean ignore,
- @PluginElement("Layout") final Layout<?> layout,
- @PluginElement("Filter") final Filter filter) {
- return new UsesLoggingAppender(name, filter, layout, ignore);
- }
-
- @Override
- public void append(final LogEvent event) {
- try {
- for (int i = 0; i < 50; i++) {
- Thread.sleep(10);
- thing.doSomething();
- }
- } catch (final InterruptedException e) {
- e.printStackTrace();
- }
- // System.out.print("Log: " + getLayout().toSerializable(event));
- }
-}
diff --git a/log4j-core/src/test/resources/reconfiguration-deadlock.xml b/log4j-core/src/test/resources/reconfiguration-deadlock.xml
index 5ef897c..d313a4e 100644
--- a/log4j-core/src/test/resources/reconfiguration-deadlock.xml
+++ b/log4j-core/src/test/resources/reconfiguration-deadlock.xml
@@ -1,19 +1,16 @@
<?xml version="1.0" encoding="UTF-8"?>
-<Configuration status="error" monitorInterval="5">
- <Appenders>
- <UsesLoggingAppender name="myAppender">
+<configuration status="error" monitorInterval="5">
+ <appenders>
+ <ReconfigurationDeadlockTestAppender name="testAppender">
<PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n" />
- </UsesLoggingAppender>
+ </ReconfigurationDeadlockTestAppender>
<Console name="STDOUT">
<PatternLayout pattern="%m%n"/>
</Console>
- </Appenders>
- <Loggers>
- <Logger name="Dump" level="trace" additivity="false">
- <AppenderRef ref="STDOUT" />
- </Logger>
- <Root level="ERROR">
- <AppenderRef ref="myAppender" />
- </Root>
- </Loggers>
-</Configuration>
\ No newline at end of file
+ </appenders>
+ <loggers>
+ <root level="ERROR">
+ <appenderRef ref="testAppender" />
+ </root>
+ </loggers>
+</configuration>