Assert status logger does not warn on Log4j usage

Today if you start Elasticsearch with the status logger configured to
the warn level, or use a transport client with the default status logger
level, you will see warn messages about deprecation loggers being
created with different message factories and that formatting might be
broken. This happens because the deprecation logger is constructed using
the message factory from its parent, an artifact leftover from the first
Log4j 2 implementation that used a custom message factory. When that
custom message factory was removed, this constructor invocation should
have been changed to not explicitly use the message factory from the
parent. This commit fixes this invocation. However, we also had some
status checking to all tests to ensure that there are no warn status log
messages that might indicate a configuration problem with Log4j 2. These
assertions blow up badly without the fix for the deprecation logger
construction, and also caught a misconfiguration in one of the logging
tests.

Relates #21339

core/src/main/java/org/elasticsearch/common/logging/DeprecationLogger.java

@@ -102,7 +102,7 @@ public class DeprecationLogger {
         } else {
             name = "deprecation." + name;
         }
-        this.logger = LogManager.getLogger(name, parentLogger.getMessageFactory());
+        this.logger = LogManager.getLogger(name);
     }
 
     /**

core/src/test/java/org/elasticsearch/bootstrap/MaxMapCountCheckTests.java

@@ -74,6 +74,7 @@ public class MaxMapCountCheckTests extends ESTestCase {
             when(reader.readLine()).thenThrow(ioException);
             final Logger logger = ESLoggerFactory.getLogger("testGetMaxMapCountIOException");
             final MockLogAppender appender = new MockLogAppender();
+            appender.start();
             appender.addExpectation(
                     new ParameterizedMessageLoggingExpectation(
                             "expected logged I/O exception",
@@ -87,6 +88,7 @@ public class MaxMapCountCheckTests extends ESTestCase {
             appender.assertAllExpectationsMatched();
             verify(reader).close();
             Loggers.removeAppender(logger, appender);
+            appender.stop();
         }
 
         {
@@ -94,6 +96,7 @@ public class MaxMapCountCheckTests extends ESTestCase {
             when(reader.readLine()).thenReturn("eof");
             final Logger logger = ESLoggerFactory.getLogger("testGetMaxMapCountNumberFormatException");
             final MockLogAppender appender = new MockLogAppender();
+            appender.start();
             appender.addExpectation(
                     new ParameterizedMessageLoggingExpectation(
                             "expected logged number format exception",
@@ -107,6 +110,7 @@ public class MaxMapCountCheckTests extends ESTestCase {
             appender.assertAllExpectationsMatched();
             verify(reader).close();
             Loggers.removeAppender(logger, appender);
+            appender.stop();
         }
 
     }

core/src/test/java/org/elasticsearch/cluster/service/ClusterServiceTests.java

@@ -742,6 +742,7 @@ public class ClusterServiceTests extends ESTestCase {
     @TestLogging("org.elasticsearch.cluster.service:TRACE") // To ensure that we log cluster state events on TRACE level
     public void testClusterStateUpdateLogging() throws Exception {
         MockLogAppender mockAppender = new MockLogAppender();
+        mockAppender.start();
         mockAppender.addExpectation(
                 new MockLogAppender.SeenEventExpectation(
                         "test1",
@@ -838,6 +839,7 @@ public class ClusterServiceTests extends ESTestCase {
             latch.await();
         } finally {
             Loggers.removeAppender(clusterLogger, mockAppender);
+            mockAppender.stop();
         }
         mockAppender.assertAllExpectationsMatched();
     }
@@ -845,6 +847,7 @@ public class ClusterServiceTests extends ESTestCase {
     @TestLogging("org.elasticsearch.cluster.service:WARN") // To ensure that we log cluster state events on WARN level
     public void testLongClusterStateUpdateLogging() throws Exception {
         MockLogAppender mockAppender = new MockLogAppender();
+        mockAppender.start();
         mockAppender.addExpectation(
                 new MockLogAppender.UnseenEventExpectation(
                         "test1 shouldn't see because setting is too low",
@@ -968,6 +971,7 @@ public class ClusterServiceTests extends ESTestCase {
             latch.await();
         } finally {
             Loggers.removeAppender(clusterLogger, mockAppender);
+            mockAppender.stop();
         }
         mockAppender.assertAllExpectationsMatched();
     }

core/src/test/java/org/elasticsearch/index/engine/InternalEngineTests.java

@@ -1516,6 +1516,7 @@ public class InternalEngineTests extends ESTestCase {
     public void testIndexWriterInfoStream() throws IllegalAccessException {
         assumeFalse("who tests the tester?", VERBOSE);
         MockAppender mockAppender = new MockAppender("testIndexWriterInfoStream");
+        mockAppender.start();
 
         Logger rootLogger = LogManager.getRootLogger();
         Level savedLevel = rootLogger.getLevel();
@@ -1538,6 +1539,7 @@ public class InternalEngineTests extends ESTestCase {
 
         } finally {
             Loggers.removeAppender(rootLogger, mockAppender);
+            mockAppender.stop();
             Loggers.setLevel(rootLogger, savedLevel);
         }
     }
@@ -1546,6 +1548,7 @@ public class InternalEngineTests extends ESTestCase {
     public void testIndexWriterIFDInfoStream() throws IllegalAccessException {
         assumeFalse("who tests the tester?", VERBOSE);
         MockAppender mockAppender = new MockAppender("testIndexWriterIFDInfoStream");
+        mockAppender.start();
 
         final Logger iwIFDLogger = Loggers.getLogger("org.elasticsearch.index.engine.Engine.IFD");
 
@@ -1569,6 +1572,7 @@ public class InternalEngineTests extends ESTestCase {
 
         } finally {
             Loggers.removeAppender(iwIFDLogger, mockAppender);
+            mockAppender.stop();
             Loggers.setLevel(iwIFDLogger, (Level) null);
         }
     }

core/src/test/java/org/elasticsearch/indices/settings/UpdateSettingsIT.java

@@ -379,6 +379,7 @@ public class UpdateSettingsIT extends ESIntegTestCase {
 
     public void testUpdateAutoThrottleSettings() throws IllegalAccessException {
         MockAppender mockAppender = new MockAppender("testUpdateAutoThrottleSettings");
+        mockAppender.start();
         Logger rootLogger = LogManager.getRootLogger();
         Level savedLevel = rootLogger.getLevel();
         Loggers.addAppender(rootLogger, mockAppender);
@@ -414,6 +415,7 @@ public class UpdateSettingsIT extends ESIntegTestCase {
             assertThat(getSettingsResponse.getSetting("test", MergeSchedulerConfig.AUTO_THROTTLE_SETTING.getKey()), equalTo("false"));
         } finally {
             Loggers.removeAppender(rootLogger, mockAppender);
+            mockAppender.stop();
             Loggers.setLevel(rootLogger, savedLevel);
         }
     }
@@ -468,6 +470,7 @@ public class UpdateSettingsIT extends ESIntegTestCase {
     // #6882: make sure we can change index.merge.scheduler.max_thread_count live
     public void testUpdateMergeMaxThreadCount() throws IllegalAccessException {
         MockAppender mockAppender = new MockAppender("testUpdateMergeMaxThreadCount");
+        mockAppender.start();
         Logger rootLogger = LogManager.getRootLogger();
         Level savedLevel = rootLogger.getLevel();
         Loggers.addAppender(rootLogger, mockAppender);
@@ -505,6 +508,7 @@ public class UpdateSettingsIT extends ESIntegTestCase {
 
         } finally {
             Loggers.removeAppender(rootLogger, mockAppender);
+            mockAppender.stop();
             Loggers.setLevel(rootLogger, savedLevel);
         }
     }

qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/config/log4j2.properties

@@ -1,5 +1,3 @@
-status = error
-
 appender.console.type = Console
 appender.console.name = console
 appender.console.layout.type = PatternLayout

qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/deprecation/log4j2.properties

@@ -1,5 +1,3 @@
-status = error
-
 appender.console.type = Console
 appender.console.name = console
 appender.console.layout.type = PatternLayout

qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/find_appender/log4j2.properties

@@ -1,5 +1,3 @@
-status = error
-
 appender.console.type = Console
 appender.console.name = console
 appender.console.layout.type = PatternLayout

qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/hierarchy/log4j2.properties

@@ -1,5 +1,3 @@
-status = error
-
 appender.console.type = Console
 appender.console.name = console
 appender.console.layout.type = PatternLayout
@@ -7,7 +5,6 @@ appender.console.layout.pattern = %m%n
 
 rootLogger.level = info
 rootLogger.appenderRef.console.ref = console
-rootLogger.appenderRef.file.ref = file
 
 logger.x.name = x
 logger.x.level = trace

qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/location_info/log4j2.properties

@@ -1,5 +1,3 @@
-status = error
-
 appender.console.type = Console
 appender.console.name = console
 appender.console.layout.type = PatternLayout

test/framework/src/main/java/org/elasticsearch/test/ESTestCase.java

@@ -29,8 +29,11 @@ import com.carrotsearch.randomizedtesting.generators.RandomNumbers;
 import com.carrotsearch.randomizedtesting.generators.RandomPicks;
 import com.carrotsearch.randomizedtesting.generators.RandomStrings;
 import com.carrotsearch.randomizedtesting.rules.TestRuleAdapter;
-
+import org.apache.logging.log4j.Level;
 import org.apache.logging.log4j.Logger;
+import org.apache.logging.log4j.status.StatusConsoleListener;
+import org.apache.logging.log4j.status.StatusData;
+import org.apache.logging.log4j.status.StatusLogger;
 import org.apache.lucene.uninverting.UninvertingReader;
 import org.apache.lucene.util.LuceneTestCase;
 import org.apache.lucene.util.LuceneTestCase.SuppressCodecs;
@@ -113,10 +116,12 @@ import java.util.function.BooleanSupplier;
 import java.util.function.Consumer;
 import java.util.function.Predicate;
 import java.util.function.Supplier;
+import java.util.stream.Collectors;
 
 import static java.util.Collections.emptyList;
 import static java.util.Collections.singletonList;
 import static org.elasticsearch.common.util.CollectionUtils.arrayAsArrayList;
+import static org.hamcrest.Matchers.empty;
 import static org.hamcrest.Matchers.equalTo;
 
 /**
@@ -147,7 +152,6 @@ public abstract class ESTestCase extends LuceneTestCase {
         portGenerator.set(0);
     }
 
-
     static {
         System.setProperty("log4j.shutdownHookEnabled", "false");
         // we can not shutdown logging when tests are running or the next test that runs within the
@@ -240,6 +244,24 @@ public abstract class ESTestCase extends LuceneTestCase {
         checkStaticState();
     }
 
+    private static final List<StatusData> statusData = new ArrayList<>();
+    static {
+        // ensure that the status logger is set to the warn level so we do not miss any warnings with our Log4j usage
+        StatusLogger.getLogger().setLevel(Level.WARN);
+        // Log4j will write out status messages indicating problems with the Log4j usage to the status logger; we hook into this logger and
+        // assert that no such messages were written out as these would indicate a problem with our logging configuration
+        StatusLogger.getLogger().registerListener(new StatusConsoleListener(Level.WARN) {
+
+            @Override
+            public void log(StatusData data) {
+                synchronized (statusData) {
+                    statusData.add(data);
+                }
+            }
+
+        });
+    }
+
     // separate method so that this can be checked again after suite scoped cluster is shut down
     protected static void checkStaticState() throws Exception {
         MockPageCacheRecycler.ensureAllPagesAreReleased();
@@ -247,6 +269,21 @@ public abstract class ESTestCase extends LuceneTestCase {
         // field cache should NEVER get loaded.
         String[] entries = UninvertingReader.getUninvertedStats();
         assertEquals("fieldcache must never be used, got=" + Arrays.toString(entries), 0, entries.length);
+
+        // ensure no one changed the status logger level on us
+        assertThat(StatusLogger.getLogger().getLevel(), equalTo(Level.WARN));
+        synchronized (statusData) {
+            try {
+                // ensure that there are no status logger messages which would indicate a problem with our Log4j usage; we map the
+                // StatusData instances to Strings as otherwise their toString output is useless
+                assertThat(
+                    statusData.stream().map(status -> status.getMessage().getFormattedMessage()).collect(Collectors.toList()),
+                    empty());
+            } finally {
+                // we clear the list so that status data from other tests do not interfere with tests within the same JVM
+                statusData.clear();
+            }
+        }
     }
 
     // this must be a separate method from other ensure checks above so suite scoped integ tests can call...TODO: fix that
@@ -943,4 +980,5 @@ public abstract class ESTestCase extends LuceneTestCase {
             this.charFilter = charFilter;
         }
     }
+
 }

test/framework/src/main/resources/log4j2-test.properties

@@ -1,5 +1,3 @@
-status = error
-
 appender.console.type = Console
 appender.console.name = console
 appender.console.layout.type = PatternLayout
@@ -7,4 +5,3 @@ appender.console.layout.pattern = [%d{ISO8601}][%-5p][%-25c{1.}] %marker%m%n
 
 rootLogger.level = ${sys:tests.es.logger.level:-info}
 rootLogger.appenderRef.console.ref = console
-                                                                                                   e