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:23 UTC
[logging-log4j2] branch release-2.x updated (b68b299 -> 751cebd)
This is an automated email from the ASF dual-hosted git repository.
vy pushed a change to branch release-2.x
in repository https://gitbox.apache.org/repos/asf/logging-log4j2.git.
discard b68b299 LOG4J2-620 ReconfigurationDeadlockTest rewrite to prevent spurious failures.
new 751cebd LOG4J2-620 ReconfigurationDeadlockTest rewrite to prevent spurious failures.
This update added new revisions after undoing existing revisions.
That is to say, some revisions that were in the old version of the
branch are not in the new version. This situation occurs
when a user --force pushes a change and generates a repository
containing something like this:
* -- * -- B -- O -- O -- O (b68b299)
\
N -- N -- N refs/heads/release-2.x (751cebd)
You should already have received notification emails for all of the O
revisions, and so the following emails describe only the N revisions
from the common base, B.
Any revisions marked "omit" are not gone; other references still
refer to them. Any revisions marked "discard" are gone forever.
The 1 revisions listed above as "new" are entirely new to this
repository and will be described in separate emails. The revisions
listed as "add" were already present in the repository and have only
been added to this reference.
Summary of changes:
.../core/config/ReconfigurationDeadlockTest.java | 61 +++++++++++++++-
.../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, 71 insertions(+), 203 deletions(-)
delete mode 100644 log4j-core/src/test/java/org/apache/logging/log4j/test/SomethingThatUsesLogging.java
delete mode 100644 log4j-core/src/test/java/org/apache/logging/log4j/test/appender/DeadlockAppender.java
delete mode 100644 log4j-core/src/test/java/org/apache/logging/log4j/test/appender/UsesLoggingAppender.java
[logging-log4j2] 01/01: LOG4J2-620 ReconfigurationDeadlockTest
rewrite to prevent spurious failures.
Posted by vy...@apache.org.
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>