Fix prefix logging

Today we add a prefix when logging within Elasticsearch. This prefix
contains the node name, and index and shard-level components if
appropriate.

Due to some implementation details with Log4j 2 , this does not work for
integration tests; instead what we see is the node name for the last
node to startup. The implementation detail here is that Log4j 2 there is
only one logger for a name, message factory pair, and the key derived
from the message factory is the class name of the message factory. So,
when the last node starts up and starts setting prefixes on its message
factories, it will impact the loggers for the other nodes.

Additionally, the prefixes are lost when logging an exception. This is
due to another implementation detail in Log4j 2. Namely, since we log
exceptions using a parameterized message, Log4j 2 decides that that
means that we do not want to use the message factory that we have
provided (the prefix message factory) and so logs the exception without
the prefix.

This commit fixes both of these issues.

Relates #20429

Author: jasontedor

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

@@ -22,17 +22,18 @@
 import org.apache.logging.log4j.Level;
 import org.apache.logging.log4j.LogManager;
 import org.apache.logging.log4j.Logger;
-import org.apache.logging.log4j.message.MessageFactory;
+import org.apache.logging.log4j.spi.ExtendedLogger;
 import org.elasticsearch.common.settings.Setting;
 import org.elasticsearch.common.settings.Setting.Property;
 
-import java.util.Locale;
-import java.util.function.Function;
-
 /**
  * Factory to get {@link Logger}s
  */
-public abstract class ESLoggerFactory {
+public final class ESLoggerFactory {
+
+    private ESLoggerFactory() {
+
+    }
 
     public static final Setting<Level> LOG_DEFAULT_LEVEL_SETTING =
         new Setting<>("logger.level", Level.INFO.name(), Level::valueOf, Property.NodeScope);
@@ -42,23 +43,12 @@ public abstract class ESLoggerFactory {
 
     public static Logger getLogger(String prefix, String name) {
         name = name.intern();
-        final Logger logger = getLogger(new PrefixMessageFactory(), name);
-        final MessageFactory factory = logger.getMessageFactory();
-        // in some cases, we initialize the logger before we are ready to set the prefix
-        // we can not re-initialize the logger, so the above getLogger might return an existing
-        // instance without the prefix set; thus, we hack around this by resetting the prefix
-        if (prefix != null && factory instanceof PrefixMessageFactory) {
-            ((PrefixMessageFactory) factory).setPrefix(prefix.intern());
-        }
-        return logger;
-    }
-
-    public static Logger getLogger(MessageFactory messageFactory, String name) {
-        return LogManager.getLogger(name, messageFactory);
+        final Logger logger = LogManager.getLogger(name);
+        return new PrefixLogger((ExtendedLogger)logger, name, prefix);
     }
 
     public static Logger getLogger(String name) {
-        return getLogger((String)null, name);
+        return getLogger(null, name);
     }
 
     public static DeprecationLogger getDeprecationLogger(String name) {
@@ -73,8 +63,4 @@ public static Logger getRootLogger() {
         return LogManager.getRootLogger();
     }
 
-    private ESLoggerFactory() {
-        // Utility class can't be built.
-    }
-
 }

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

@@ -97,7 +97,8 @@ public static Logger getLogger(String loggerName, Settings settings, String... p
     }
 
     public static Logger getLogger(Logger parentLogger, String s) {
-        return ESLoggerFactory.getLogger(parentLogger.<MessageFactory>getMessageFactory(), getLoggerName(parentLogger.getName() + s));
+        assert parentLogger instanceof PrefixLogger;
+        return ESLoggerFactory.getLogger(((PrefixLogger)parentLogger).prefix(), getLoggerName(parentLogger.getName() + s));
     }
 
     public static Logger getLogger(String s) {

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

@@ -0,0 +1,70 @@
+/*
+ * Licensed to Elasticsearch under one or more contributor
+ * license agreements. See the NOTICE file distributed with
+ * this work for additional information regarding copyright
+ * ownership. Elasticsearch 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.elasticsearch.common.logging;
+
+import org.apache.logging.log4j.Level;
+import org.apache.logging.log4j.Marker;
+import org.apache.logging.log4j.MarkerManager;
+import org.apache.logging.log4j.message.Message;
+import org.apache.logging.log4j.spi.ExtendedLogger;
+import org.apache.logging.log4j.spi.ExtendedLoggerWrapper;
+
+import java.lang.ref.WeakReference;
+import java.util.WeakHashMap;
+
+class PrefixLogger extends ExtendedLoggerWrapper {
+
+    // we can not use the built-in Marker tracking (MarkerManager) because the MarkerManager holds
+    // a permanent reference to the marker; however, we have transient markers from index-level and
+    // shard-level components so this would effectively be a memory leak
+    private static final WeakHashMap<String, WeakReference<Marker>> markers = new WeakHashMap<>();
+
+    private final Marker marker;
+
+    public String prefix() {
+        return marker.getName();
+    }
+
+    PrefixLogger(final ExtendedLogger logger, final String name, final String prefix) {
+        super(logger, name, null);
+
+        final String actualPrefix = (prefix == null ? "" : prefix).intern();
+        final Marker actualMarker;
+        // markers is not thread-safe, so we synchronize access
+        synchronized (markers) {
+            final WeakReference<Marker> marker = markers.get(actualPrefix);
+            final Marker maybeMarker = marker == null ? null : marker.get();
+            if (maybeMarker == null) {
+                actualMarker = new MarkerManager.Log4jMarker(actualPrefix);
+                markers.put(actualPrefix, new WeakReference<>(actualMarker));
+            } else {
+                actualMarker = maybeMarker;
+            }
+        }
+        this.marker = actualMarker;
+    }
+
+    @Override
+    public void logMessage(final String fqcn, final Level level, final Marker marker, final Message message, final Throwable t) {
+        assert marker == null;
+        super.logMessage(fqcn, level, this.marker, message, t);
+    }
+
+}