Logging: Make node name consistent in logger (#31588)

First, some background: we have 15 different methods to get a logger in
Elasticsearch but they can be broken down into three broad categories
based on what information is provided when building the logger.

Just a class like:
```
private static final Logger logger = ESLoggerFactory.getLogger(ActionModule.class);
```
or:
```
protected final Logger logger = Loggers.getLogger(getClass());
```

The class and settings:
```
this.logger = Loggers.getLogger(getClass(), settings);
```

Or more information like:
```
Loggers.getLogger("index.store.deletes", settings, shardId)
```

The goal of the "class and settings" variant is to attach the node name
to the logger. Because we don't always have the settings available, we
often use the "just a class" variant and get loggers without node names
attached. There isn't any real consistency here. Some loggers get the
node name because it is convenient and some do not.

This change makes the node name available to all loggers all the time.
Almost. There are some caveats are testing that I'll get to. But in
*production* code the node name is node available to all loggers. This
means we can stop using the "class and settings" variants to fetch
loggers which was the real goal here, but a pleasant side effect is that
the ndoe name is now consitent on every log line and optional by editing
the logging pattern. This is all powered by setting the node name
statically on a logging formatter very early in initialization.

Now to tests: tests can't set the node name statically because
subclasses of `ESIntegTestCase` run many nodes in the same jvm, even in
the same class loader. Also, lots of tests don't run with a real node so
they don't *have* a node name at all. To support multiple nodes in the
same JVM tests suss out the node name from the thread name which works
surprisingly well and easy to test in a nice way. For those threads
that are not part of an `ESIntegTestCase` node we stick whatever useful
information we can get form the thread name in the place of the node
name. This allows us to keep the logger format consistent.

Author: nik9000

benchmarks/src/main/resources/log4j2.properties

@@ -1,7 +1,7 @@
 appender.console.type = Console
 appender.console.name = console
 appender.console.layout.type = PatternLayout
-appender.console.layout.pattern = [%d{ISO8601}][%-5p][%-25c] %marker%m%n
+appender.console.layout.pattern = [%d{ISO8601}][%-5p][%-25c] [%node_name]%marker %m%n
 
 # Do not log at all if it is not really critical - we're in a benchmark
 rootLogger.level = error

client/benchmark/src/main/resources/log4j2.properties

@@ -1,7 +1,7 @@
 appender.console.type = Console
 appender.console.name = console
 appender.console.layout.type = PatternLayout
-appender.console.layout.pattern = [%d{ISO8601}][%-5p][%-25c] %marker%m%n
+appender.console.layout.pattern = [%d{ISO8601}][%-5p][%-25c] [%node_name]%marker %m%n
 
 rootLogger.level = info
 rootLogger.appenderRef.console.ref = console

distribution/src/config/log4j2.properties

@@ -7,13 +7,13 @@ logger.action.level = debug
 appender.console.type = Console
 appender.console.name = console
 appender.console.layout.type = PatternLayout
-appender.console.layout.pattern = [%d{ISO8601}][%-5p][%-25c{1.}] %marker%m%n
+appender.console.layout.pattern = [%d{ISO8601}][%-5p][%-25c{1.}] [%node_name]%marker %m%n
 
 appender.rolling.type = RollingFile
 appender.rolling.name = rolling
 appender.rolling.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}.log
 appender.rolling.layout.type = PatternLayout
-appender.rolling.layout.pattern = [%d{ISO8601}][%-5p][%-25c{1.}] %marker%.-10000m%n
+appender.rolling.layout.pattern = [%d{ISO8601}][%-5p][%-25c{1.}] [%node_name]%marker %.-10000m%n
 appender.rolling.filePattern = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}-%d{yyyy-MM-dd}-%i.log.gz
 appender.rolling.policies.type = Policies
 appender.rolling.policies.time.type = TimeBasedTriggeringPolicy
@@ -38,7 +38,7 @@ appender.deprecation_rolling.type = RollingFile
 appender.deprecation_rolling.name = deprecation_rolling
 appender.deprecation_rolling.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_deprecation.log
 appender.deprecation_rolling.layout.type = PatternLayout
-appender.deprecation_rolling.layout.pattern = [%d{ISO8601}][%-5p][%-25c{1.}] %marker%.-10000m%n
+appender.deprecation_rolling.layout.pattern = [%d{ISO8601}][%-5p][%-25c{1.}] [%node_name]%marker %.-10000m%n
 appender.deprecation_rolling.filePattern = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_deprecation-%i.log.gz
 appender.deprecation_rolling.policies.type = Policies
 appender.deprecation_rolling.policies.size.type = SizeBasedTriggeringPolicy
@@ -55,7 +55,7 @@ appender.index_search_slowlog_rolling.type = RollingFile
 appender.index_search_slowlog_rolling.name = index_search_slowlog_rolling
 appender.index_search_slowlog_rolling.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_index_search_slowlog.log
 appender.index_search_slowlog_rolling.layout.type = PatternLayout
-appender.index_search_slowlog_rolling.layout.pattern = [%d{ISO8601}][%-5p][%-25c] %marker%.-10000m%n
+appender.index_search_slowlog_rolling.layout.pattern = [%d{ISO8601}][%-5p][%-25c] [%node_name]%marker %.-10000m%n
 appender.index_search_slowlog_rolling.filePattern = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_index_search_slowlog-%i.log.gz
 appender.index_search_slowlog_rolling.policies.type = Policies
 appender.index_search_slowlog_rolling.policies.size.type = SizeBasedTriggeringPolicy
@@ -72,7 +72,7 @@ appender.index_indexing_slowlog_rolling.type = RollingFile
 appender.index_indexing_slowlog_rolling.name = index_indexing_slowlog_rolling
 appender.index_indexing_slowlog_rolling.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_index_indexing_slowlog.log
 appender.index_indexing_slowlog_rolling.layout.type = PatternLayout
-appender.index_indexing_slowlog_rolling.layout.pattern = [%d{ISO8601}][%-5p][%-25c] %marker%.-10000m%n
+appender.index_indexing_slowlog_rolling.layout.pattern = [%d{ISO8601}][%-5p][%-25c] [%node_name]%marker %.-10000m%n
 appender.index_indexing_slowlog_rolling.filePattern = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_index_indexing_slowlog-%i.log.gz
 appender.index_indexing_slowlog_rolling.policies.type = Policies
 appender.index_indexing_slowlog_rolling.policies.size.type = SizeBasedTriggeringPolicy

docs/reference/index-modules/slowlog.asciidoc

@@ -50,7 +50,7 @@ appender.index_search_slowlog_rolling.type = RollingFile
 appender.index_search_slowlog_rolling.name = index_search_slowlog_rolling
 appender.index_search_slowlog_rolling.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_index_search_slowlog.log
 appender.index_search_slowlog_rolling.layout.type = PatternLayout
-appender.index_search_slowlog_rolling.layout.pattern = [%d{ISO8601}][%-5p][%-25c] %marker%.-10000m%n
+appender.index_search_slowlog_rolling.layout.pattern = [%d{ISO8601}][%-5p][%-25c] [%node_name]%marker %.-10000m%n
 appender.index_search_slowlog_rolling.filePattern = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_index_search_slowlog-%i.log.gz
 appender.index_search_slowlog_rolling.policies.type = Policies
 appender.index_search_slowlog_rolling.policies.size.type = SizeBasedTriggeringPolicy
@@ -103,7 +103,7 @@ appender.index_indexing_slowlog_rolling.type = RollingFile
 appender.index_indexing_slowlog_rolling.name = index_indexing_slowlog_rolling
 appender.index_indexing_slowlog_rolling.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_index_indexing_slowlog.log
 appender.index_indexing_slowlog_rolling.layout.type = PatternLayout
-appender.index_indexing_slowlog_rolling.layout.pattern = [%d{ISO8601}][%-5p][%-25c] %marker%.-10000m%n
+appender.index_indexing_slowlog_rolling.layout.pattern = [%d{ISO8601}][%-5p][%-25c] [%node_name]%marker %.-10000m%n
 appender.index_indexing_slowlog_rolling.filePattern = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_index_indexing_slowlog-%i.log.gz
 appender.index_indexing_slowlog_rolling.policies.type = Policies
 appender.index_indexing_slowlog_rolling.policies.size.type = SizeBasedTriggeringPolicy

docs/reference/setup/logging-config.asciidoc

@@ -25,7 +25,7 @@ appender.rolling.type = RollingFile <1>
 appender.rolling.name = rolling
 appender.rolling.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}.log <2>
 appender.rolling.layout.type = PatternLayout
-appender.rolling.layout.pattern = [%d{ISO8601}][%-5p][%-25c{1.}] %marker%.-10000m%n
+appender.rolling.layout.pattern = [%d{ISO8601}][%-5p][%-25c{1.}] [%node_name]%marker %.-10000m%n
 appender.rolling.filePattern = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}-%d{yyyy-MM-dd}-%i.log.gz <3>
 appender.rolling.policies.type = Policies
 appender.rolling.policies.time.type = TimeBasedTriggeringPolicy <4>

qa/evil-tests/src/test/java/org/elasticsearch/bootstrap/EvilBootstrapChecksTests.java

@@ -87,7 +87,7 @@ public void testInvalidValue() {
         final boolean enforceLimits = randomBoolean();
         final IllegalArgumentException e = expectThrows(
                 IllegalArgumentException.class,
-                () -> BootstrapChecks.check(new BootstrapContext(Settings.EMPTY, null), enforceLimits, emptyList(), "testInvalidValue"));
+                () -> BootstrapChecks.check(new BootstrapContext(Settings.EMPTY, null), enforceLimits, emptyList()));
         final Matcher<String> matcher = containsString(
                 "[es.enforce.bootstrap.checks] must be [true] but was [" + value + "]");
         assertThat(e, hasToString(matcher));

qa/evil-tests/src/test/java/org/elasticsearch/common/logging/EvilLoggerTests.java

@@ -56,6 +56,7 @@
 import java.util.stream.Collectors;
 import java.util.stream.IntStream;
 
+import static org.hamcrest.Matchers.endsWith;
 import static org.hamcrest.Matchers.equalTo;
 import static org.hamcrest.Matchers.hasItem;
 import static org.hamcrest.Matchers.lessThan;
@@ -319,9 +320,11 @@ public void testPrefixLogger() throws IOException, IllegalAccessException, UserE
         assertThat(events.size(), equalTo(expectedLogLines + stackTraceLength));
         for (int i = 0; i < expectedLogLines; i++) {
             if (prefix == null) {
-                assertThat(events.get(i), startsWith("test"));
+                assertThat("Contents of [" + path + "] are wrong",
+                        events.get(i), startsWith("[" + getTestName() + "] test"));
             } else {
-                assertThat(events.get(i), startsWith("[" + prefix + "] test"));
+                assertThat("Contents of [" + path + "] are wrong",
+                        events.get(i), startsWith("[" + getTestName() + "][" + prefix + "] test"));
             }
         }
     }
@@ -357,6 +360,24 @@ public void testProperties() throws IOException, UserException {
         }
     }
 
+    public void testNoNodeNameWarning() throws IOException, UserException {
+        setupLogging("no_node_name");
+
+        final String path =
+            System.getProperty("es.logs.base_path") +
+                System.getProperty("file.separator") +
+                System.getProperty("es.logs.cluster_name") + ".log";
+        final List<String> events = Files.readAllLines(PathUtils.get(path));
+        assertThat(events.size(), equalTo(2));
+        final String location = "org.elasticsearch.common.logging.LogConfigurator";
+        // the first message is a warning for unsupported configuration files
+        assertLogLine(events.get(0), Level.WARN, location, "\\[null\\] Some logging configurations have %marker but don't "
+                + "have %node_name. We will automatically add %node_name to the pattern to ease the migration for users "
+                + "who customize log4j2.properties but will stop this behavior in 7.0. You should manually replace "
+                + "`%node_name` with `\\[%node_name\\]%marker ` in these locations:");
+        assertThat(events.get(1), endsWith("no_node_name/log4j2.properties"));
+    }
+
     private void setupLogging(final String config) throws IOException, UserException {
         setupLogging(config, Settings.EMPTY);
     }

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

@@ -1,13 +1,13 @@
 appender.console.type = Console
 appender.console.name = console
 appender.console.layout.type = PatternLayout
-appender.console.layout.pattern = [%d{ISO8601}][%-5p][%-25c] %marker%m%n
+appender.console.layout.pattern = [%d{ISO8601}][%-5p][%-25c] [%test_thread_info]%marker %m%n
 
 appender.file.type = File
 appender.file.name = file
 appender.file.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}.log
 appender.file.layout.type = PatternLayout
-appender.file.layout.pattern = [%p][%l] %marker%m%n
+appender.file.layout.pattern = [%p][%l] [%test_thread_info]%marker %m%n
 
 rootLogger.level = info
 rootLogger.appenderRef.console.ref = console
@@ -23,10 +23,9 @@ appender.deprecation_file.type = File
 appender.deprecation_file.name = deprecation_file
 appender.deprecation_file.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_deprecation.log
 appender.deprecation_file.layout.type = PatternLayout
-appender.deprecation_file.layout.pattern = [%p][%l] %marker%m%n
+appender.deprecation_file.layout.pattern = [%p][%l] [%test_thread_info]%marker %m%n
 
 logger.deprecation.name = deprecation
 logger.deprecation.level = warn
 logger.deprecation.appenderRef.deprecation_file.ref = deprecation_file
 logger.deprecation.additivity = false
-

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

@@ -1,7 +1,7 @@
 appender.console3.type = Console
 appender.console3.name = console3
 appender.console3.layout.type = PatternLayout
-appender.console3.layout.pattern = [%d{ISO8601}][%-5p][%-25c] %marker%m%n
+appender.console3.layout.pattern = [%d{ISO8601}][%-5p][%-25c] [%test_thread_info]%marker %m%n
 
 logger.third.name = third
 logger.third.level = debug

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

@@ -1,13 +1,13 @@
 appender.console.type = Console
 appender.console.name = console
 appender.console.layout.type = PatternLayout
-appender.console.layout.pattern = [%d{ISO8601}][%-5p][%-25c] %marker%m%n
+appender.console.layout.pattern = [%d{ISO8601}][%-5p][%-25c] [%test_thread_info]%marker %m%n
 
 appender.file.type = File
 appender.file.name = file
 appender.file.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}.log
 appender.file.layout.type = PatternLayout
-appender.file.layout.pattern = [%p][%l] %marker%m%n
+appender.file.layout.pattern = [%p][%l] [%test_thread_info]%marker %m%n
 
 rootLogger.level = info
 rootLogger.appenderRef.console.ref = console
@@ -17,7 +17,7 @@ appender.deprecation_file.type = File
 appender.deprecation_file.name = deprecation_file
 appender.deprecation_file.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_deprecation.log
 appender.deprecation_file.layout.type = PatternLayout
-appender.deprecation_file.layout.pattern = [%p][%l] %marker%m%n
+appender.deprecation_file.layout.pattern = [%p][%l] [%test_thread_info]%marker %m%n
 
 logger.deprecation.name = deprecation
 logger.deprecation.level = warn