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 10:13:30 UTC
[logging-log4j2] branch release-2.x updated: 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
The following commit(s) were added to refs/heads/release-2.x by this push:
new b68b299 LOG4J2-620 ReconfigurationDeadlockTest rewrite to prevent spurious failures.
b68b299 is described below
commit b68b29986115da7f487e7ee825e11ef95e3366a9
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 | 160 ++++++++++-----------
1 file changed, 78 insertions(+), 82 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..0431669 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,103 @@
*/
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.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 org.apache.logging.log4j.test.appender.UsesLoggingAppender
+ */
@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];
+ private static final int WORKER_COUNT = 100;
- @Test
- public void testReconfig() throws InterruptedException {
+ private ExecutorService executor;
- 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) {
-
- 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 {
-
- public volatile boolean shutdown = false;
-
- @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());
- }
- }
- }
+ 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());
}
}