You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@flink.apache.org by ch...@apache.org on 2022/04/07 15:24:58 UTC
[flink] branch master updated: [FLINK-26710][tests] Refactor TestLoggerResource to not swallow messages
This is an automated email from the ASF dual-hosted git repository.
chesnay pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/flink.git
The following commit(s) were added to refs/heads/master by this push:
new 4d6732587cb [FLINK-26710][tests] Refactor TestLoggerResource to not swallow messages
4d6732587cb is described below
commit 4d6732587cbc53d018b35a749d8a0079b338c45b
Author: Niklas Semmler <me...@users.noreply.github.com>
AuthorDate: Thu Apr 7 17:24:50 2022 +0200
[FLINK-26710][tests] Refactor TestLoggerResource to not swallow messages
---
.../testutils/logging/TestLoggerResource.java | 108 +++++++++++++++--
.../testutils/logging/TestLoggerResourceTest.java | 135 +++++++++++++++++++++
2 files changed, 232 insertions(+), 11 deletions(-)
diff --git a/flink-test-utils-parent/flink-test-utils-junit/src/main/java/org/apache/flink/testutils/logging/TestLoggerResource.java b/flink-test-utils-parent/flink-test-utils-junit/src/main/java/org/apache/flink/testutils/logging/TestLoggerResource.java
index a207d825620..de9d4e103a0 100644
--- a/flink-test-utils-parent/flink-test-utils-junit/src/main/java/org/apache/flink/testutils/logging/TestLoggerResource.java
+++ b/flink-test-utils-parent/flink-test-utils-junit/src/main/java/org/apache/flink/testutils/logging/TestLoggerResource.java
@@ -20,20 +20,32 @@ package org.apache.flink.testutils.logging;
import org.apache.logging.log4j.Level;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.core.Appender;
+import org.apache.logging.log4j.core.Filter;
import org.apache.logging.log4j.core.LogEvent;
import org.apache.logging.log4j.core.LoggerContext;
import org.apache.logging.log4j.core.appender.AbstractAppender;
import org.apache.logging.log4j.core.config.AppenderRef;
import org.apache.logging.log4j.core.config.LoggerConfig;
+import org.apache.logging.log4j.core.filter.ThresholdFilter;
import org.junit.rules.ExternalResource;
+import javax.annotation.Nullable;
+
import java.util.ArrayList;
import java.util.List;
+import java.util.UUID;
import java.util.concurrent.ConcurrentLinkedQueue;
/**
* Utility for auditing logged messages.
*
+ * <p>Note: If a parent logger is already defined with a less specific log level, then using the
+ * {@link TestLoggerResource} can increase the number of log messages received by this logger.
+ *
+ * <p>Example: You define a logger for org.apache.runtime with log level INFO and then use {@link
+ * TestLoggerResource} to listen on org.apache.runtime.feature with log level DEBUG. In this case,
+ * the log output for the parent logger will include DEBUG messages org.apache.runtime.feature.
+ *
* <p>Implementation note: Make sure to not expose log4j dependencies in the interface of this class
* to ease updates in logging infrastructure.
*/
@@ -43,11 +55,16 @@ public class TestLoggerResource extends ExternalResource {
private final String loggerName;
private final org.slf4j.event.Level level;
+ @Nullable private LoggerConfig backupLoggerConfig = null;
private ConcurrentLinkedQueue<String> loggingEvents;
public TestLoggerResource(Class<?> clazz, org.slf4j.event.Level level) {
- this.loggerName = clazz.getCanonicalName();
+ this(clazz.getCanonicalName(), level);
+ }
+
+ private TestLoggerResource(String loggerName, org.slf4j.event.Level level) {
+ this.loggerName = loggerName;
this.level = level;
}
@@ -55,12 +72,36 @@ public class TestLoggerResource extends ExternalResource {
return new ArrayList<>(loggingEvents);
}
+ private static String generateRandomString() {
+ return UUID.randomUUID().toString().replace("-", "");
+ }
+
@Override
protected void before() throws Throwable {
loggingEvents = new ConcurrentLinkedQueue<>();
- Appender testAppender =
- new AbstractAppender("test-appender", null, null, false) {
+ final LoggerConfig previousLoggerConfig =
+ LOGGER_CONTEXT.getConfiguration().getLoggerConfig(loggerName);
+
+ final Level previousLevel = previousLoggerConfig.getLevel();
+ final Level userDefinedLevel = Level.getLevel(level.name());
+
+ // Set log level to least specific. This ensures that the parent still receives all log
+ // lines.
+ // WARN is more specific than INFO is more specific than DEBUG etc.
+ final Level newLevel =
+ userDefinedLevel.isMoreSpecificThan(previousLevel)
+ ? previousLevel
+ : userDefinedLevel;
+
+ // Filter log lines according to user requirements.
+ final Filter levelFilter =
+ ThresholdFilter.createFilter(
+ userDefinedLevel, Filter.Result.ACCEPT, Filter.Result.DENY);
+
+ final Appender testAppender =
+ new AbstractAppender(
+ "test-appender-" + generateRandomString(), levelFilter, null, false) {
@Override
public void append(LogEvent event) {
loggingEvents.add(event.getMessage().getFormattedMessage());
@@ -68,27 +109,72 @@ public class TestLoggerResource extends ExternalResource {
};
testAppender.start();
- AppenderRef appenderRef = AppenderRef.createAppenderRef(testAppender.getName(), null, null);
- LoggerConfig logger =
+ final LoggerConfig loggerConfig =
LoggerConfig.createLogger(
- false,
- Level.getLevel(level.name()),
- "test",
+ true,
+ newLevel,
+ loggerName,
null,
- new AppenderRef[] {appenderRef},
+ new AppenderRef[] {},
null,
LOGGER_CONTEXT.getConfiguration(),
null);
- logger.addAppender(testAppender, null, null);
+ loggerConfig.addAppender(testAppender, null, null);
+
+ if (previousLoggerConfig.getName().equals(loggerName)) {
+ // remove the previous logger config for the duration of the test
+ backupLoggerConfig = previousLoggerConfig;
+ LOGGER_CONTEXT.getConfiguration().removeLogger(loggerName);
+
+ // combine appender set
+ // Note: The appender may still receive more or less messages depending on the log level
+ // difference between the two logger
+ for (Appender appender : previousLoggerConfig.getAppenders().values()) {
+ loggerConfig.addAppender(appender, null, null);
+ }
+ }
- LOGGER_CONTEXT.getConfiguration().addLogger(loggerName, logger);
+ LOGGER_CONTEXT.getConfiguration().addLogger(loggerName, loggerConfig);
LOGGER_CONTEXT.updateLoggers();
}
@Override
protected void after() {
LOGGER_CONTEXT.getConfiguration().removeLogger(loggerName);
+ if (backupLoggerConfig != null) {
+ LOGGER_CONTEXT.getConfiguration().addLogger(loggerName, backupLoggerConfig);
+ backupLoggerConfig = null;
+ }
LOGGER_CONTEXT.updateLoggers();
loggingEvents = null;
}
+
+ /** Enables the use of {@link TestLoggerResource} for try-with-resources statement. */
+ public static SingleTestResource asSingleTestResource(
+ String loggerName, org.slf4j.event.Level level) throws Throwable {
+ return new SingleTestResource(loggerName, level);
+ }
+
+ /**
+ * SingleTestResource re-uses the code in {@link TestLoggerResource} for try-with-resources
+ * statement.
+ */
+ public static class SingleTestResource implements AutoCloseable {
+ final TestLoggerResource resource;
+
+ private SingleTestResource(String loggerName, org.slf4j.event.Level level)
+ throws Throwable {
+ resource = new TestLoggerResource(loggerName, level);
+ resource.before();
+ }
+
+ @Override
+ public void close() throws Exception {
+ resource.after();
+ }
+
+ public List<String> getMessages() {
+ return resource.getMessages();
+ }
+ }
}
diff --git a/flink-test-utils-parent/flink-test-utils-junit/src/test/java/org/apache/flink/testutils/logging/TestLoggerResourceTest.java b/flink-test-utils-parent/flink-test-utils-junit/src/test/java/org/apache/flink/testutils/logging/TestLoggerResourceTest.java
new file mode 100644
index 00000000000..52508b797e8
--- /dev/null
+++ b/flink-test-utils-parent/flink-test-utils-junit/src/test/java/org/apache/flink/testutils/logging/TestLoggerResourceTest.java
@@ -0,0 +1,135 @@
+/*
+ * 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.flink.testutils.logging;
+
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.Logger;
+import org.junit.jupiter.api.Test;
+import org.slf4j.event.Level;
+
+import java.util.List;
+
+import static org.assertj.core.api.Assertions.assertThat;
+
+/**
+ * {@link TestLoggerResourceTest} ensures that the use of {@link TestLoggerResource} combined with
+ * other loggers (including multiple instances of itself) does not lead to unexpected behavior.
+ */
+class TestLoggerResourceTest {
+ private static final String parentLoggerName =
+ TestLoggerResourceTest.class.getName() + ".parent";
+ private static final String childLoggerName = parentLoggerName + ".child";
+ private static final Logger parentLogger = LogManager.getLogger(parentLoggerName);
+ private static final Logger childLogger = LogManager.getLogger(childLoggerName);
+
+ @Test
+ void loggerWithoutChild() throws Throwable {
+ try (TestLoggerResource.SingleTestResource parentResource =
+ TestLoggerResource.asSingleTestResource(parentLoggerName, Level.INFO)) {
+ parentLogger.info("parent-info");
+ parentLogger.debug("parent-debug");
+ final List<String> msgs = parentResource.getMessages();
+ assertThat(msgs).containsExactly("parent-info");
+ }
+ }
+
+ @Test
+ void loggerIsAlreadyDefinedOriginalInfoNewDebug() throws Throwable {
+ try (TestLoggerResource.SingleTestResource outerResource =
+ TestLoggerResource.asSingleTestResource(parentLoggerName, Level.INFO);
+ TestLoggerResource.SingleTestResource innerResource =
+ TestLoggerResource.asSingleTestResource(parentLoggerName, Level.DEBUG)) {
+ parentLogger.info("parent-info");
+ parentLogger.debug("parent-debug");
+ final List<String> msgsInner = innerResource.getMessages();
+ assertThat(msgsInner).containsExactly("parent-info", "parent-debug");
+ final List<String> msgsOuter = outerResource.getMessages();
+ assertThat(msgsOuter).containsExactly("parent-info");
+ }
+ }
+
+ @Test
+ void loggerIsAlreadyDefinedOriginalDebugNewInfo() throws Throwable {
+ try (TestLoggerResource.SingleTestResource outerResource =
+ TestLoggerResource.asSingleTestResource(parentLoggerName, Level.DEBUG);
+ TestLoggerResource.SingleTestResource innerResource =
+ TestLoggerResource.asSingleTestResource(parentLoggerName, Level.INFO)) {
+ parentLogger.info("parent-info");
+ parentLogger.debug("parent-debug");
+ final List<String> msgsInner = innerResource.getMessages();
+ assertThat(msgsInner).containsExactly("parent-info");
+ final List<String> msgsOuter = outerResource.getMessages();
+ assertThat(msgsOuter).containsExactly("parent-info", "parent-debug");
+ }
+ }
+
+ @Test
+ void parentInfoLevelChildInfoLevel() throws Throwable {
+ try (TestLoggerResource.SingleTestResource parentResource =
+ TestLoggerResource.asSingleTestResource(parentLoggerName, Level.INFO);
+ TestLoggerResource.SingleTestResource childResource =
+ TestLoggerResource.asSingleTestResource(childLoggerName, Level.INFO)) {
+ parentLogger.info("parent-info");
+ parentLogger.debug("parent-debug");
+ childLogger.info("child-info");
+ childLogger.debug("child-debug");
+ final List<String> parentMsgs = parentResource.getMessages();
+ assertThat(parentMsgs).containsExactly("parent-info", "child-info");
+ final List<String> childMsgs = childResource.getMessages();
+ assertThat(childMsgs).containsExactly("child-info");
+ }
+ }
+
+ @Test
+ void parentDebugLevelChildInfoLevel() throws Throwable {
+ try (TestLoggerResource.SingleTestResource parentResource =
+ TestLoggerResource.asSingleTestResource(parentLoggerName, Level.DEBUG);
+ TestLoggerResource.SingleTestResource childResource =
+ TestLoggerResource.asSingleTestResource(childLoggerName, Level.INFO)) {
+ parentLogger.info("parent-info");
+ parentLogger.debug("parent-debug");
+ childLogger.info("child-info");
+ childLogger.debug("child-debug");
+ final List<String> parentMsgs = parentResource.getMessages();
+ assertThat(parentMsgs)
+ .containsExactly("parent-info", "parent-debug", "child-info", "child-debug");
+ final List<String> childMsgs = childResource.getMessages();
+ assertThat(childMsgs).containsExactly("child-info");
+ }
+ }
+
+ @Test
+ void parentInfoLevelChildDebugLevel() throws Throwable {
+ // Note: Here we receive debug messages for the parent logger even though its own log level
+ // is set to INFO. To change this, we would need to add a filter to the appender.
+ try (TestLoggerResource.SingleTestResource parentResource =
+ TestLoggerResource.asSingleTestResource(parentLoggerName, Level.INFO);
+ TestLoggerResource.SingleTestResource childResource =
+ TestLoggerResource.asSingleTestResource(childLoggerName, Level.DEBUG)) {
+ parentLogger.info("parent-info");
+ parentLogger.debug("parent-debug");
+ childLogger.info("child-info");
+ childLogger.debug("child-debug");
+ final List<String> parentMsgs = parentResource.getMessages();
+ assertThat(parentMsgs).containsExactly("parent-info", "child-info");
+ final List<String> childMsgs = childResource.getMessages();
+ assertThat(childMsgs).containsExactly("child-info", "child-debug");
+ }
+ }
+}