From fbe27664a65ca7ab5b7dbe1c328ab27423e4313c Mon Sep 17 00:00:00 2001 From: Jason Tedor Date: Tue, 13 Sep 2016 14:46:34 -0400 Subject: [PATCH] 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 --- .../common/logging/ESLoggerFactory.java | 32 +-- .../elasticsearch/common/logging/Loggers.java | 3 +- .../common/logging/PrefixLogger.java | 70 ++++++ .../common/logging/PrefixMessageFactory.java | 221 ------------------ .../index/engine/InternalEngineTests.java | 11 +- .../indices/settings/UpdateSettingsIT.java | 2 +- .../elasticsearch/test/MockLogAppender.java | 2 +- .../main/resources/config/log4j2.properties | 10 +- .../common/logging/EvilLoggerTests.java | 34 ++- .../common/logging/config/log4j2.properties | 6 +- .../logging/config/second/log4j2.properties | 2 +- .../logging/config/third/log4j2.properties | 2 +- .../logging/deprecation/log4j2.properties | 6 +- .../logging/find_appender/log4j2.properties | 2 +- .../logging/location_info/log4j2.properties | 4 +- .../common/logging/prefix/log4j2.properties | 20 ++ .../src/main/resources/log4j2-test.properties | 2 +- 17 files changed, 158 insertions(+), 271 deletions(-) create mode 100644 core/src/main/java/org/elasticsearch/common/logging/PrefixLogger.java delete mode 100644 core/src/main/java/org/elasticsearch/common/logging/PrefixMessageFactory.java create mode 100644 qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/prefix/log4j2.properties diff --git a/core/src/main/java/org/elasticsearch/common/logging/ESLoggerFactory.java b/core/src/main/java/org/elasticsearch/common/logging/ESLoggerFactory.java index 853df3d31ad..71fed8ca2a0 100644 --- a/core/src/main/java/org/elasticsearch/common/logging/ESLoggerFactory.java +++ b/core/src/main/java/org/elasticsearch/common/logging/ESLoggerFactory.java @@ -22,17 +22,18 @@ package org.elasticsearch.common.logging; 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 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 abstract class ESLoggerFactory { return LogManager.getRootLogger(); } - private ESLoggerFactory() { - // Utility class can't be built. - } - } diff --git a/core/src/main/java/org/elasticsearch/common/logging/Loggers.java b/core/src/main/java/org/elasticsearch/common/logging/Loggers.java index 31abfb2ec6e..422941e5c8b 100644 --- a/core/src/main/java/org/elasticsearch/common/logging/Loggers.java +++ b/core/src/main/java/org/elasticsearch/common/logging/Loggers.java @@ -97,7 +97,8 @@ public class Loggers { } public static Logger getLogger(Logger parentLogger, String s) { - return ESLoggerFactory.getLogger(parentLogger.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) { diff --git a/core/src/main/java/org/elasticsearch/common/logging/PrefixLogger.java b/core/src/main/java/org/elasticsearch/common/logging/PrefixLogger.java new file mode 100644 index 00000000000..32de2afde36 --- /dev/null +++ b/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> 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 = 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); + } + +} diff --git a/core/src/main/java/org/elasticsearch/common/logging/PrefixMessageFactory.java b/core/src/main/java/org/elasticsearch/common/logging/PrefixMessageFactory.java deleted file mode 100644 index a141ceb75aa..00000000000 --- a/core/src/main/java/org/elasticsearch/common/logging/PrefixMessageFactory.java +++ /dev/null @@ -1,221 +0,0 @@ -/* - * 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.message.Message; -import org.apache.logging.log4j.message.MessageFactory2; -import org.apache.logging.log4j.message.ObjectMessage; -import org.apache.logging.log4j.message.ParameterizedMessage; -import org.apache.logging.log4j.message.SimpleMessage; - -public class PrefixMessageFactory implements MessageFactory2 { - - private String prefix = ""; - - public String getPrefix() { - return prefix; - } - - public void setPrefix(String prefix) { - this.prefix = prefix; - } - - @Override - public Message newMessage(Object message) { - return new PrefixObjectMessage(prefix, message); - } - - private static class PrefixObjectMessage extends ObjectMessage { - - private final String prefix; - private final Object object; - private String prefixObjectString; - - private PrefixObjectMessage(String prefix, Object object) { - super(object); - this.prefix = prefix; - this.object = object; - } - - @Override - public String getFormattedMessage() { - if (prefixObjectString == null) { - prefixObjectString = prefix + super.getFormattedMessage(); - } - return prefixObjectString; - } - - @Override - public void formatTo(StringBuilder buffer) { - buffer.append(prefix); - super.formatTo(buffer); - } - - @Override - public Object[] getParameters() { - return new Object[]{prefix, object}; - } - - } - - @Override - public Message newMessage(String message) { - return new PrefixSimpleMessage(prefix, message); - } - - private static class PrefixSimpleMessage extends SimpleMessage { - - private final String prefix; - private String prefixMessage; - - PrefixSimpleMessage(String prefix, String message) { - super(message); - this.prefix = prefix; - } - - PrefixSimpleMessage(String prefix, CharSequence charSequence) { - super(charSequence); - this.prefix = prefix; - } - - @Override - public String getFormattedMessage() { - if (prefixMessage == null) { - prefixMessage = prefix + super.getFormattedMessage(); - } - return prefixMessage; - } - - @Override - public void formatTo(StringBuilder buffer) { - buffer.append(prefix); - super.formatTo(buffer); - } - - @Override - public int length() { - return prefixMessage.length(); - } - - @Override - public char charAt(int index) { - return prefixMessage.charAt(index); - } - - @Override - public CharSequence subSequence(int start, int end) { - return prefixMessage.subSequence(start, end); - } - - } - - @Override - public Message newMessage(String message, Object... params) { - return new PrefixParameterizedMessage(prefix, message, params); - } - - private static class PrefixParameterizedMessage extends ParameterizedMessage { - - private static ThreadLocal threadLocalStringBuilder = ThreadLocal.withInitial(StringBuilder::new); - - private final String prefix; - private String formattedMessage; - - private PrefixParameterizedMessage(String prefix, String messagePattern, Object... arguments) { - super(messagePattern, arguments); - this.prefix = prefix; - } - - @Override - public String getFormattedMessage() { - if (formattedMessage == null) { - final StringBuilder buffer = threadLocalStringBuilder.get(); - buffer.setLength(0); - formatTo(buffer); - formattedMessage = buffer.toString(); - } - return formattedMessage; - } - - @Override - public void formatTo(StringBuilder buffer) { - buffer.append(prefix); - super.formatTo(buffer); - } - - } - - @Override - public Message newMessage(CharSequence charSequence) { - return new PrefixSimpleMessage(prefix, charSequence); - } - - @Override - public Message newMessage(String message, Object p0) { - return new PrefixParameterizedMessage(prefix, message, p0); - } - - @Override - public Message newMessage(String message, Object p0, Object p1) { - return new PrefixParameterizedMessage(prefix, message, p0, p1); - } - - @Override - public Message newMessage(String message, Object p0, Object p1, Object p2) { - return new PrefixParameterizedMessage(prefix, message, p0, p1, p2); - } - - @Override - public Message newMessage(String message, Object p0, Object p1, Object p2, Object p3) { - return new PrefixParameterizedMessage(prefix, message, p0, p1, p2, p3); - } - - @Override - public Message newMessage(String message, Object p0, Object p1, Object p2, Object p3, Object p4) { - return new PrefixParameterizedMessage(prefix, message, p0, p1, p2, p3, p4); - } - - @Override - public Message newMessage(String message, Object p0, Object p1, Object p2, Object p3, Object p4, Object p5) { - return new PrefixParameterizedMessage(prefix, message, p0, p1, p2, p3, p4, p5); - } - - @Override - public Message newMessage(String message, Object p0, Object p1, Object p2, Object p3, Object p4, Object p5, Object p6) { - return new PrefixParameterizedMessage(prefix, message, p0, p1, p2, p3, p4, p5, p6); - } - - @Override - public Message newMessage(String message, Object p0, Object p1, Object p2, Object p3, Object p4, Object p5, Object p6, Object p7) { - return new PrefixParameterizedMessage(prefix, message, p0, p1, p2, p3, p4, p5, p6, p7); - } - - @Override - public Message newMessage( - String message, Object p0, Object p1, Object p2, Object p3, Object p4, Object p5, Object p6, Object p7, Object p8) { - return new PrefixParameterizedMessage(prefix, message, p0, p1, p2, p3, p4, p5, p6, p7, p8); - } - - @Override - public Message newMessage( - String message, Object p0, Object p1, Object p2, Object p3, Object p4, Object p5, Object p6, Object p7, Object p8, Object p9) { - return new PrefixParameterizedMessage(prefix, message, p0, p1, p2, p3, p4, p5, p6, p7, p8, p9); - } -} diff --git a/core/src/test/java/org/elasticsearch/index/engine/InternalEngineTests.java b/core/src/test/java/org/elasticsearch/index/engine/InternalEngineTests.java index 1c35ea1f281..f0d02f35840 100644 --- a/core/src/test/java/org/elasticsearch/index/engine/InternalEngineTests.java +++ b/core/src/test/java/org/elasticsearch/index/engine/InternalEngineTests.java @@ -61,7 +61,6 @@ import org.elasticsearch.common.bytes.BytesArray; import org.elasticsearch.common.bytes.BytesReference; import org.elasticsearch.common.io.FileSystemUtils; import org.elasticsearch.common.logging.Loggers; -import org.elasticsearch.common.logging.PrefixMessageFactory; import org.elasticsearch.common.lucene.Lucene; import org.elasticsearch.common.lucene.uid.Versions; import org.elasticsearch.common.settings.Settings; @@ -1510,13 +1509,13 @@ public class InternalEngineTests extends ESTestCase { public boolean sawIndexWriterIFDMessage; public MockAppender(final String name) throws IllegalAccessException { - super(name, RegexFilter.createFilter(".*(\n.*)*", new String[0], true, null, null), null); + super(name, RegexFilter.createFilter(".*(\n.*)*", new String[0], false, null, null), null); } @Override public void append(LogEvent event) { final String formattedMessage = event.getMessage().getFormattedMessage(); - if (event.getLevel() == Level.TRACE && formattedMessage.contains("[index][1] ")) { + if (event.getLevel() == Level.TRACE && event.getMarker().getName().contains("[index][1] ")) { if (event.getLoggerName().endsWith("lucene.iw") && formattedMessage.contains("IW: apply all deletes during flush")) { sawIndexWriterMessage = true; @@ -1556,7 +1555,7 @@ public class InternalEngineTests extends ESTestCase { } finally { Loggers.removeAppender(rootLogger, mockAppender); - Loggers.setLevel(rootLogger, savedLevel.toString()); + Loggers.setLevel(rootLogger, savedLevel); } } @@ -1566,13 +1565,13 @@ public class InternalEngineTests extends ESTestCase { MockAppender mockAppender = new MockAppender("testIndexWriterIFDInfoStream"); final Logger iwIFDLogger; - if (LogManager.getContext(false).hasLogger("org.elasticsearch.index.engine.lucene.iw.ifd", new PrefixMessageFactory())) { + if (LogManager.getContext(false).hasLogger("org.elasticsearch.index.engine.lucene.iw.ifd")) { // Works when running this test inside Intellij: iwIFDLogger = LogManager.getLogger("org.elasticsearch.index.engine.lucene.iw.ifd"); assertNotNull(iwIFDLogger); } else { // Works when running this test from command line: - assertTrue(LogManager.getContext(false).hasLogger("index.engine.lucene.iw.ifd", new PrefixMessageFactory())); + assertTrue(LogManager.getContext(false).hasLogger("index.engine.lucene.iw.ifd")); iwIFDLogger = LogManager.getLogger("index.engine.lucene.iw.ifd"); } diff --git a/core/src/test/java/org/elasticsearch/indices/settings/UpdateSettingsIT.java b/core/src/test/java/org/elasticsearch/indices/settings/UpdateSettingsIT.java index 3c60c209712..9c5b4e92043 100644 --- a/core/src/test/java/org/elasticsearch/indices/settings/UpdateSettingsIT.java +++ b/core/src/test/java/org/elasticsearch/indices/settings/UpdateSettingsIT.java @@ -358,7 +358,7 @@ public class UpdateSettingsIT extends ESIntegTestCase { public boolean sawUpdateAutoThrottle; public MockAppender(final String name) throws IllegalAccessException { - super(name, RegexFilter.createFilter(".*(\n.*)*", new String[0], true, null, null), null); + super(name, RegexFilter.createFilter(".*(\n.*)*", new String[0], false, null, null), null); } @Override diff --git a/core/src/test/java/org/elasticsearch/test/MockLogAppender.java b/core/src/test/java/org/elasticsearch/test/MockLogAppender.java index 786319e2aee..42977105058 100644 --- a/core/src/test/java/org/elasticsearch/test/MockLogAppender.java +++ b/core/src/test/java/org/elasticsearch/test/MockLogAppender.java @@ -40,7 +40,7 @@ public class MockLogAppender extends AbstractAppender { private List expectations; public MockLogAppender() throws IllegalAccessException { - super("mock", RegexFilter.createFilter(".*(\n.*)*", new String[0], true, null, null), null); + super("mock", RegexFilter.createFilter(".*(\n.*)*", new String[0], false, null, null), null); expectations = new ArrayList<>(); } diff --git a/distribution/src/main/resources/config/log4j2.properties b/distribution/src/main/resources/config/log4j2.properties index 2cfe038cc84..caf4c392481 100644 --- a/distribution/src/main/resources/config/log4j2.properties +++ b/distribution/src/main/resources/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] %m%n +appender.console.layout.pattern = [%d{ISO8601}][%-5p][%-25c] %marker%m%n appender.rolling.type = RollingFile appender.rolling.name = rolling appender.rolling.fileName = ${sys:es.logs}.log appender.rolling.layout.type = PatternLayout -appender.rolling.layout.pattern = [%d{ISO8601}][%-5p][%-25c] %.10000m%n +appender.rolling.layout.pattern = [%d{ISO8601}][%-5p][%-25c] %marker%.10000m%n appender.rolling.filePattern = ${sys:es.logs}-%d{yyyy-MM-dd}.log appender.rolling.policies.type = Policies appender.rolling.policies.time.type = TimeBasedTriggeringPolicy @@ -28,7 +28,7 @@ appender.deprecation_rolling.type = RollingFile appender.deprecation_rolling.name = deprecation_rolling appender.deprecation_rolling.fileName = ${sys:es.logs}_deprecation.log appender.deprecation_rolling.layout.type = PatternLayout -appender.deprecation_rolling.layout.pattern = [%d{ISO8601}][%-5p][%-25c] %.10000m%n +appender.deprecation_rolling.layout.pattern = [%d{ISO8601}][%-5p][%-25c] %marker%.10000m%n appender.deprecation_rolling.filePattern = ${sys:es.logs}_deprecation-%i.log.gz appender.deprecation_rolling.policies.type = Policies appender.deprecation_rolling.policies.size.type = SizeBasedTriggeringPolicy @@ -45,7 +45,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}_index_search_slowlog.log appender.index_search_slowlog_rolling.layout.type = PatternLayout -appender.index_search_slowlog_rolling.layout.pattern = [%d{ISO8601}][%-5p][%-25c] %.10000m%n +appender.index_search_slowlog_rolling.layout.pattern = [%d{ISO8601}][%-5p][%-25c] %marker%.10000m%n appender.index_search_slowlog_rolling.filePattern = ${sys:es.logs}_index_search_slowlog-%d{yyyy-MM-dd}.log appender.index_search_slowlog_rolling.policies.type = Policies appender.index_search_slowlog_rolling.policies.time.type = TimeBasedTriggeringPolicy @@ -61,7 +61,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}_index_indexing_slowlog.log appender.index_indexing_slowlog_rolling.layout.type = PatternLayout -appender.index_indexing_slowlog_rolling.layout.pattern = [%d{ISO8601}][%-5p][%-25c] %.10000m%n +appender.index_indexing_slowlog_rolling.layout.pattern = [%d{ISO8601}][%-5p][%-25c] %marker%.10000m%n appender.index_indexing_slowlog_rolling.filePattern = ${sys:es.logs}_index_indexing_slowlog-%d{yyyy-MM-dd}.log appender.index_indexing_slowlog_rolling.policies.type = Policies appender.index_indexing_slowlog_rolling.policies.time.type = TimeBasedTriggeringPolicy diff --git a/qa/evil-tests/src/test/java/org/elasticsearch/common/logging/EvilLoggerTests.java b/qa/evil-tests/src/test/java/org/elasticsearch/common/logging/EvilLoggerTests.java index 73fef7432f9..851c3346734 100644 --- a/qa/evil-tests/src/test/java/org/elasticsearch/common/logging/EvilLoggerTests.java +++ b/qa/evil-tests/src/test/java/org/elasticsearch/common/logging/EvilLoggerTests.java @@ -27,6 +27,7 @@ import org.apache.logging.log4j.core.LoggerContext; import org.apache.logging.log4j.core.appender.ConsoleAppender; import org.apache.logging.log4j.core.appender.CountingNoOpAppender; import org.apache.logging.log4j.core.config.Configurator; +import org.apache.logging.log4j.message.ParameterizedMessage; import org.elasticsearch.common.io.PathUtils; import org.elasticsearch.common.settings.Settings; import org.elasticsearch.env.Environment; @@ -34,8 +35,9 @@ import org.elasticsearch.test.ESTestCase; import org.elasticsearch.test.hamcrest.RegexMatcher; import javax.management.MBeanServerPermission; - import java.io.IOException; +import java.io.PrintWriter; +import java.io.StringWriter; import java.nio.file.Files; import java.nio.file.Path; import java.security.AccessControlException; @@ -46,6 +48,7 @@ import java.util.regex.Matcher; import java.util.regex.Pattern; import static org.hamcrest.Matchers.equalTo; +import static org.hamcrest.Matchers.startsWith; public class EvilLoggerTests extends ESTestCase { @@ -108,6 +111,35 @@ public class EvilLoggerTests extends ESTestCase { assertThat(countingNoOpAppender.getName(), equalTo("counting_no_op")); } + public void testPrefixLogger() throws IOException, IllegalAccessException { + setupLogging("prefix"); + + final String prefix = randomBoolean() ? null : randomAsciiOfLength(16); + final Logger logger = Loggers.getLogger("prefix", prefix); + logger.info("test"); + logger.info("{}", "test"); + final Exception e = new Exception("exception"); + logger.info(new ParameterizedMessage("{}", "test"), e); + + final String path = System.getProperty("es.logs") + ".log"; + final List events = Files.readAllLines(PathUtils.get(path)); + + final StringWriter sw = new StringWriter(); + final PrintWriter pw = new PrintWriter(sw); + e.printStackTrace(pw); + final int stackTraceLength = sw.toString().split(System.getProperty("line.separator")).length; + final int expectedLogLines = 3; + assertThat(events.size(), equalTo(expectedLogLines + stackTraceLength)); + for (int i = 0; i < expectedLogLines; i++) { + if (prefix == null) { + assertThat(events.get(i), startsWith("test")); + } else { + assertThat(events.get(i), startsWith("[" + prefix + "] test")); + } + } + } + + public void testLog4jShutdownHack() { final AtomicBoolean denied = new AtomicBoolean(); final SecurityManager sm = System.getSecurityManager(); diff --git a/qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/config/log4j2.properties b/qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/config/log4j2.properties index ec99b136237..aca53f81c1b 100644 --- a/qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/config/log4j2.properties +++ b/qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/config/log4j2.properties @@ -3,13 +3,13 @@ status = error appender.console.type = Console appender.console.name = console appender.console.layout.type = PatternLayout -appender.console.layout.pattern = [%d{ISO8601}][%-5p][%-25c] %m%n +appender.console.layout.pattern = [%d{ISO8601}][%-5p][%-25c] %marker%m%n appender.file.type = File appender.file.name = file appender.file.fileName = ${sys:es.logs}.log appender.file.layout.type = PatternLayout -appender.file.layout.pattern = [%p][%l] %m%n +appender.file.layout.pattern = [%p][%l] %marker%m%n rootLogger.level = info rootLogger.appenderRef.console.ref = console @@ -25,7 +25,7 @@ appender.deprecation_file.type = File appender.deprecation_file.name = deprecation_file appender.deprecation_file.fileName = ${sys:es.logs}_deprecation.log appender.deprecation_file.layout.type = PatternLayout -appender.deprecation_file.layout.pattern = [%p][%l] %m%n +appender.deprecation_file.layout.pattern = [%p][%l] %marker%m%n logger.deprecation.name = deprecation logger.deprecation.level = warn diff --git a/qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/config/second/log4j2.properties b/qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/config/second/log4j2.properties index 2ade4c896c3..9d59e79c08a 100644 --- a/qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/config/second/log4j2.properties +++ b/qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/config/second/log4j2.properties @@ -1,7 +1,7 @@ appender.console2.type = Console appender.console2.name = console2 appender.console2.layout.type = PatternLayout -appender.console2.layout.pattern = [%d{ISO8601}][%-5p][%-25c] %m%n +appender.console2.layout.pattern = [%d{ISO8601}][%-5p][%-25c] %marke%m%n logger.second.name = second logger.second.level = debug diff --git a/qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/config/third/log4j2.properties b/qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/config/third/log4j2.properties index 8699f574d53..ed794cb7c3b 100644 --- a/qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/config/third/log4j2.properties +++ b/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] %m%n +appender.console3.layout.pattern = [%d{ISO8601}][%-5p][%-25c] %marker%m%n logger.third.name = third logger.third.level = debug diff --git a/qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/deprecation/log4j2.properties b/qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/deprecation/log4j2.properties index 5abca54e392..744e554ff91 100644 --- a/qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/deprecation/log4j2.properties +++ b/qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/deprecation/log4j2.properties @@ -3,13 +3,13 @@ status = error appender.console.type = Console appender.console.name = console appender.console.layout.type = PatternLayout -appender.console.layout.pattern = [%d{ISO8601}][%-5p][%-25c] %m%n +appender.console.layout.pattern = [%d{ISO8601}][%-5p][%-25c] %marker%m%n appender.file.type = File appender.file.name = file appender.file.fileName = ${sys:es.logs}.log appender.file.layout.type = PatternLayout -appender.file.layout.pattern = [%p][%l] %m%n +appender.file.layout.pattern = [%p][%l] %marker%m%n rootLogger.level = info rootLogger.appenderRef.console.ref = console @@ -19,7 +19,7 @@ appender.deprecation_file.type = File appender.deprecation_file.name = deprecation_file appender.deprecation_file.fileName = ${sys:es.logs}_deprecation.log appender.deprecation_file.layout.type = PatternLayout -appender.deprecation_file.layout.pattern = [%p][%l] %m%n +appender.deprecation_file.layout.pattern = [%p][%l] %marker%m%n logger.deprecation.name = deprecation logger.deprecation.level = warn diff --git a/qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/find_appender/log4j2.properties b/qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/find_appender/log4j2.properties index 5b50bda0c3c..80a28771620 100644 --- a/qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/find_appender/log4j2.properties +++ b/qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/find_appender/log4j2.properties @@ -3,7 +3,7 @@ status = error appender.console.type = Console appender.console.name = console appender.console.layout.type = PatternLayout -appender.console.layout.pattern = [%d{ISO8601}][%-5p][%-25c] %m%n +appender.console.layout.pattern = [%d{ISO8601}][%-5p][%-25c] %marker%m%n logger.has_console_appender.name = has_console_appender logger.has_console_appender.level = trace diff --git a/qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/location_info/log4j2.properties b/qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/location_info/log4j2.properties index fe42489470b..d1a2c534b83 100644 --- a/qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/location_info/log4j2.properties +++ b/qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/location_info/log4j2.properties @@ -3,13 +3,13 @@ status = error appender.console.type = Console appender.console.name = console appender.console.layout.type = PatternLayout -appender.console.layout.pattern = [%d{ISO8601}][%-5p][%-25c] %m%n +appender.console.layout.pattern = [%d{ISO8601}][%-5p][%-25c] %marker%m%n appender.file.type = File appender.file.name = file appender.file.fileName = ${sys:es.logs}.log appender.file.layout.type = PatternLayout -appender.file.layout.pattern = [%p][%l] %m%n +appender.file.layout.pattern = [%p][%l] %marker%m%n rootLogger.level = info rootLogger.appenderRef.console.ref = console diff --git a/qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/prefix/log4j2.properties b/qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/prefix/log4j2.properties new file mode 100644 index 00000000000..1f18b38d91e --- /dev/null +++ b/qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/prefix/log4j2.properties @@ -0,0 +1,20 @@ +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.file.type = File +appender.file.name = file +appender.file.fileName = ${sys:es.logs}.log +appender.file.layout.type = PatternLayout +appender.file.layout.pattern = %marker%m%n + +rootLogger.level = info +rootLogger.appenderRef.console.ref = console +rootLogger.appenderRef.file.ref = file + +logger.prefix.name = prefix +logger.prefix.level = info +logger.prefix.appenderRef.console.ref = console +logger.prefix.appenderRef.file.ref = file +logger.prefix.additivity = false diff --git a/test/framework/src/main/resources/log4j2-test.properties b/test/framework/src/main/resources/log4j2-test.properties index 9cfe3e326aa..f5ab7ae8a2b 100644 --- a/test/framework/src/main/resources/log4j2-test.properties +++ b/test/framework/src/main/resources/log4j2-test.properties @@ -3,7 +3,7 @@ status = error appender.console.type = Console appender.console.name = console appender.console.layout.type = PatternLayout -appender.console.layout.pattern = [%d{ISO8601}][%-5p][%-25c] %m%n +appender.console.layout.pattern = [%d{ISO8601}][%-5p][%-25c] %marker%m%n rootLogger.level = info rootLogger.appenderRef.console.ref = console