iterator = threadContexts.iterator();
if (iterator.hasNext()) {
- final String formattedMessage = LoggerMessageFormat.format(message, params);
- final String warningHeaderValue = formatWarning(formattedMessage);
- assert WARNING_HEADER_PATTERN.matcher(warningHeaderValue).matches();
- assert extractWarningValueFromWarningHeader(warningHeaderValue).equals(escapeAndEncode(formattedMessage));
+
while (iterator.hasNext()) {
try {
final ThreadContext next = iterator.next();
@@ -244,7 +246,16 @@ public class DeprecationLogger {
@SuppressLoggerChecks(reason = "safely delegates to logger")
@Override
public Void run() {
- logger.warn(message, params);
+ /**
+ * There should be only one threadContext (in prod env), @see DeprecationLogger#setThreadContext
+ */
+ String opaqueId = threadContexts.stream()
+ .filter(t -> t.isClosed() == false)
+ .findFirst()
+ .map(t -> t.getHeader(Task.X_OPAQUE_ID))
+ .orElse("");
+
+ logger.warn(new DeprecatedMessage(message, opaqueId, params));
return null;
}
});
diff --git a/server/src/main/java/org/elasticsearch/common/logging/ESJsonLayout.java b/server/src/main/java/org/elasticsearch/common/logging/ESJsonLayout.java
index af7cd81f202..af1c3097d5f 100644
--- a/server/src/main/java/org/elasticsearch/common/logging/ESJsonLayout.java
+++ b/server/src/main/java/org/elasticsearch/common/logging/ESJsonLayout.java
@@ -24,6 +24,7 @@ import org.apache.logging.log4j.core.LogEvent;
import org.apache.logging.log4j.core.config.Node;
import org.apache.logging.log4j.core.config.plugins.Plugin;
import org.apache.logging.log4j.core.config.plugins.PluginAttribute;
+import org.apache.logging.log4j.core.config.plugins.PluginBuilderFactory;
import org.apache.logging.log4j.core.config.plugins.PluginFactory;
import org.apache.logging.log4j.core.layout.AbstractStringLayout;
import org.apache.logging.log4j.core.layout.ByteBufferDestination;
@@ -31,66 +32,183 @@ import org.apache.logging.log4j.core.layout.PatternLayout;
import org.elasticsearch.common.Strings;
import java.nio.charset.Charset;
+import java.nio.charset.StandardCharsets;
+import java.util.LinkedHashMap;
import java.util.Map;
+import java.util.Set;
+import java.util.stream.Collectors;
+import java.util.stream.Stream;
/**
* Formats log events as strings in a json format.
*
* The class is wrapping the {@link PatternLayout} with a pattern to format into json. This gives more flexibility and control over how the
* log messages are formatted in {@link org.apache.logging.log4j.core.layout.JsonLayout}
+ * There are fields which are always present in the log line:
+ *
+ * - type - the type of logs. These represent appenders and help docker distinguish log streams.
+ * - timestamp - ISO8601 with additional timezone ID
+ * - level - INFO, WARN etc
+ * - component - logger name, most of the times class name
+ * - cluster.name - taken from sys:es.logs.cluster_name system property because it is always set
+ * - node.name - taken from NodeNamePatternConverter, as it can be set in runtime as hostname when not set in elasticsearch.yml
+ * - node_and_cluster_id - in json as node.id and cluster.uuid - taken from NodeAndClusterIdConverter and present
+ * once clusterStateUpdate is first received
+ * - message - a json escaped message. Multiline messages will be converted to single line with new line explicitly
+ * replaced to \n
+ * - exceptionAsJson - in json as a stacktrace field. Only present when throwable is passed as a parameter when using a logger.
+ * Taken from JsonThrowablePatternConverter
+ *
+ *
+ * It is possible to add more or override them with esmessagefield
+ * appender.logger.layout.esmessagefields=message,took,took_millis,total_hits,types,stats,search_type,total_shards,source,id
+ * Each of these will be expanded into a json field with a value taken {@link ESLogMessage} field. In the example above
+ * ... "message": %ESMessageField{message}, "took": %ESMessageField{took} ...
+ * the message passed to a logger will be overriden with a value from %ESMessageField{message}
+ *
+ * The value taken from %ESMessageField{message} has to be a simple escaped JSON value and is populated in subclasses of
+ * ESLogMessage
*/
@Plugin(name = "ESJsonLayout", category = Node.CATEGORY, elementType = Layout.ELEMENT_TYPE, printObject = true)
public class ESJsonLayout extends AbstractStringLayout {
- /**
- * Fields used in a pattern to format a json log line:
- *
- * - type - the type of logs. These represent appenders and help docker distinguish log streams.
- * - timestamp - ISO8601 with additional timezone ID
- * - level - INFO, WARN etc
- * - component - logger name, most of the times class name
- * - cluster.name - taken from sys:es.logs.cluster_name system property because it is always set
- * - node.name - taken from NodeNamePatternConverter, as it can be set in runtime as hostname when not set in elasticsearch.yml
- * - node_and_cluster_id - in json as node.id and cluster.uuid - taken from NodeAndClusterIdConverter and present
- * once clusterStateUpdate is first received
- * - message - a json escaped message. Multiline messages will be converted to single line with new line explicitly
- * replaced to \n
- * - exceptionAsJson - in json as a stacktrace field. Only present when throwable is passed as a parameter when using a logger.
- * Taken from JsonThrowablePatternConverter
- *
- */
- private static final String PATTERN = "{" +
- "\"type\": \"${TYPE}\", " +
- "\"timestamp\": \"%d{yyyy-MM-dd'T'HH:mm:ss,SSSZ}\", " +
- "\"level\": \"%p\", " +
- "\"component\": \"%c{1.}\", " +
- "\"cluster.name\": \"${sys:es.logs.cluster_name}\", " +
- "\"node.name\": \"%node_name\", " +
- "%notEmpty{%node_and_cluster_id, } " +
- "\"message\": \"%notEmpty{%enc{%marker}{JSON} }%enc{%.-10000m}{JSON}\" " +
- "%exceptionAsJson " +
- "}%n";
private final PatternLayout patternLayout;
- protected ESJsonLayout(String typeName, Charset charset) {
+ protected ESJsonLayout(String typeName, Charset charset, String[] esmessagefields) {
super(charset);
this.patternLayout = PatternLayout.newBuilder()
- .withPattern(pattern(typeName))
+ .withPattern(pattern(typeName, esmessagefields))
.withAlwaysWriteExceptions(false)
.build();
}
- private String pattern(String type) {
+ private String pattern(String type, String[] esMessageFields) {
if (Strings.isEmpty(type)) {
throw new IllegalArgumentException("layout parameter 'type_name' cannot be empty");
}
- return PATTERN.replace("${TYPE}", type);
+ Map map = new LinkedHashMap<>();
+ map.put("type", inQuotes(type));
+ map.put("timestamp", inQuotes("%d{yyyy-MM-dd'T'HH:mm:ss,SSSZZ}"));
+ map.put("level", inQuotes("%p"));
+ map.put("component", inQuotes("%c{1.}"));
+ map.put("cluster.name", inQuotes("${sys:es.logs.cluster_name}"));
+ map.put("node.name", inQuotes("%node_name"));
+ map.put("message", inQuotes("%notEmpty{%enc{%marker}{JSON} }%enc{%.-10000m}{JSON}"));
+
+ for (String key : esMessageFields) {
+ map.put(key, inQuotes("%ESMessageField{" + key + "}"));
+ }
+ return createPattern(map, Stream.of(esMessageFields).collect(Collectors.toSet()));
+ }
+
+
+ private String createPattern(Map map, Set esMessageFields) {
+ StringBuilder sb = new StringBuilder();
+ sb.append("{");
+ String separator = "";
+ for (Map.Entry entry : map.entrySet()) {
+
+ if (esMessageFields.contains(entry.getKey())) {
+ sb.append("%notEmpty{");
+ sb.append(separator);
+ appendField(sb, entry);
+ sb.append("}");
+ } else {
+ sb.append(separator);
+ appendField(sb, entry);
+ }
+
+ separator = ", ";
+ }
+ sb.append(notEmpty(", %node_and_cluster_id "));
+ sb.append("%exceptionAsJson ");
+ sb.append("}");
+ sb.append(System.lineSeparator());
+
+ return sb.toString();
+ }
+
+ private void appendField(StringBuilder sb, Map.Entry entry) {
+ sb.append(jsonKey(entry.getKey()));
+ sb.append(entry.getValue().toString());
+ }
+
+ private String notEmpty(String value) {
+ return "%notEmpty{" + value + "}";
+ }
+
+ private CharSequence jsonKey(String s) {
+ return inQuotes(s) + ": ";
+ }
+
+ private String inQuotes(String s) {
+ return "\"" + s + "\"";
}
@PluginFactory
- public static ESJsonLayout createLayout(@PluginAttribute("type_name") String type,
- @PluginAttribute(value = "charset", defaultString = "UTF-8") Charset charset) {
- return new ESJsonLayout(type, charset);
+ public static ESJsonLayout createLayout(String type,
+ Charset charset,
+ String[] esmessagefields) {
+ return new ESJsonLayout(type, charset, esmessagefields);
+ }
+
+ PatternLayout getPatternLayout() {
+ return patternLayout;
+ }
+
+ public static class Builder> extends AbstractStringLayout.Builder
+ implements org.apache.logging.log4j.core.util.Builder {
+
+ @PluginAttribute("type_name")
+ String type;
+
+ @PluginAttribute(value = "charset", defaultString = "UTF-8")
+ Charset charset;
+
+ @PluginAttribute("esmessagefields")
+ private String esMessageFields;
+
+ public Builder() {
+ setCharset(StandardCharsets.UTF_8);
+ }
+
+ @Override
+ public ESJsonLayout build() {
+ String[] split = Strings.isNullOrEmpty(esMessageFields) ? new String[]{} : esMessageFields.split(",");
+ return ESJsonLayout.createLayout(type, charset, split);
+ }
+
+ public Charset getCharset() {
+ return charset;
+ }
+
+ public B setCharset(final Charset charset) {
+ this.charset = charset;
+ return asBuilder();
+ }
+
+ public String getType() {
+ return type;
+ }
+
+ public B setType(final String type) {
+ this.type = type;
+ return asBuilder();
+ }
+
+ public String getESMessageFields() {
+ return esMessageFields;
+ }
+
+ public B setESMessageFields(String esmessagefields) {
+ this.esMessageFields = esmessagefields;
+ return asBuilder();
+ }
+ }
+
+ @PluginBuilderFactory
+ public static > B newBuilder() {
+ return new ESJsonLayout.Builder().asBuilder();
}
@Override
diff --git a/server/src/main/java/org/elasticsearch/common/logging/ESLogMessage.java b/server/src/main/java/org/elasticsearch/common/logging/ESLogMessage.java
new file mode 100644
index 00000000000..aeb8bdc8197
--- /dev/null
+++ b/server/src/main/java/org/elasticsearch/common/logging/ESLogMessage.java
@@ -0,0 +1,67 @@
+/*
+ * 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.ParameterizedMessage;
+import org.elasticsearch.common.SuppressLoggerChecks;
+
+import java.util.Map;
+import java.util.stream.Collectors;
+import java.util.stream.Stream;
+
+/**
+ * A base class for custom log4j logger messages. Carries additional fields which will populate JSON fields in logs.
+ */
+public abstract class ESLogMessage extends ParameterizedMessage {
+ private final Map fields;
+
+ /**
+ * This is an abstract class, so this is safe. The check is done on DeprecationMessage.
+ * Other subclasses are not allowing varargs
+ */
+ @SuppressLoggerChecks(reason = "Safe as this is abstract class")
+ public ESLogMessage(Map fields, String messagePattern, Object... args) {
+ super(messagePattern, args);
+ this.fields = fields;
+ }
+
+ public String getValueFor(String key) {
+ Object value = fields.get(key);
+ return value!=null ? value.toString() : null;
+ }
+
+ public static String inQuotes(String s) {
+ if(s == null)
+ return inQuotes("");
+ return "\"" + s + "\"";
+ }
+
+ public static String inQuotes(Object s) {
+ if(s == null)
+ return inQuotes("");
+ return inQuotes(s.toString());
+ }
+
+ public static String asJsonArray(Stream stream) {
+ return "[" + stream
+ .map(ESLogMessage::inQuotes)
+ .collect(Collectors.joining(", ")) + "]";
+ }
+}
diff --git a/server/src/main/java/org/elasticsearch/common/logging/ESMessageFieldConverter.java b/server/src/main/java/org/elasticsearch/common/logging/ESMessageFieldConverter.java
new file mode 100644
index 00000000000..40d702bc76b
--- /dev/null
+++ b/server/src/main/java/org/elasticsearch/common/logging/ESMessageFieldConverter.java
@@ -0,0 +1,67 @@
+/*
+ * 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.core.LogEvent;
+import org.apache.logging.log4j.core.config.Configuration;
+import org.apache.logging.log4j.core.config.plugins.Plugin;
+import org.apache.logging.log4j.core.pattern.ConverterKeys;
+import org.apache.logging.log4j.core.pattern.LogEventPatternConverter;
+import org.apache.logging.log4j.core.pattern.PatternConverter;
+import org.apache.logging.log4j.util.StringBuilders;
+import org.elasticsearch.common.Strings;
+
+/**
+ * Pattern converter to populate ESMessageField in a pattern.
+ * It will only populate these if the event have message of type ESLogMessage
.
+ */
+@Plugin(category = PatternConverter.CATEGORY, name = "ESMessageField")
+@ConverterKeys({"ESMessageField"})
+public final class ESMessageFieldConverter extends LogEventPatternConverter {
+
+ private String key;
+
+ /**
+ * Called by log4j2 to initialize this converter.
+ */
+ public static ESMessageFieldConverter newInstance(final Configuration config, final String[] options) {
+ final String key = options[0];
+
+ return new ESMessageFieldConverter(key);
+ }
+
+ public ESMessageFieldConverter(String key) {
+ super("ESMessageField", "ESMessageField");
+ this.key = key;
+ }
+
+ @Override
+ public void format(LogEvent event, StringBuilder toAppendTo) {
+ if (event.getMessage() instanceof ESLogMessage) {
+ ESLogMessage logMessage = (ESLogMessage) event.getMessage();
+ final String value = logMessage.getValueFor(key);
+ if (Strings.isNullOrEmpty(value) == false) {
+ StringBuilders.appendValue(toAppendTo, value);
+ return;
+ }
+ }
+ StringBuilders.appendValue(toAppendTo, "");
+ }
+}
diff --git a/server/src/main/java/org/elasticsearch/common/util/concurrent/ThreadContext.java b/server/src/main/java/org/elasticsearch/common/util/concurrent/ThreadContext.java
index 80a9a30032e..258bf5df1ee 100644
--- a/server/src/main/java/org/elasticsearch/common/util/concurrent/ThreadContext.java
+++ b/server/src/main/java/org/elasticsearch/common/util/concurrent/ThreadContext.java
@@ -23,6 +23,7 @@ import org.apache.logging.log4j.Logger;
import org.apache.lucene.util.CloseableThreadLocal;
import org.elasticsearch.action.support.ContextPreservingActionListener;
import org.elasticsearch.client.OriginSettingClient;
+import org.elasticsearch.common.collect.MapBuilder;
import org.elasticsearch.common.io.stream.StreamInput;
import org.elasticsearch.common.io.stream.StreamOutput;
import org.elasticsearch.common.io.stream.Writeable;
@@ -30,6 +31,7 @@ import org.elasticsearch.common.settings.Setting;
import org.elasticsearch.common.settings.Setting.Property;
import org.elasticsearch.common.settings.Settings;
import org.elasticsearch.http.HttpTransportSettings;
+import org.elasticsearch.tasks.Task;
import java.io.Closeable;
import java.io.IOException;
@@ -130,7 +132,20 @@ public final class ThreadContext implements Closeable, Writeable {
*/
public StoredContext stashContext() {
final ThreadContextStruct context = threadLocal.get();
- threadLocal.set(null);
+ /**
+ * X-Opaque-ID should be preserved in a threadContext in order to propagate this across threads.
+ * This is needed so the DeprecationLogger in another thread can see the value of X-Opaque-ID provided by a user.
+ * Otherwise when context is stash, it should be empty.
+ */
+ if (context.requestHeaders.containsKey(Task.X_OPAQUE_ID)) {
+ ThreadContextStruct threadContextStruct =
+ DEFAULT_CONTEXT.putHeaders(MapBuilder.newMapBuilder()
+ .put(Task.X_OPAQUE_ID, context.requestHeaders.get(Task.X_OPAQUE_ID))
+ .immutableMap());
+ threadLocal.set(threadContextStruct);
+ } else {
+ threadLocal.set(null);
+ }
return () -> {
// If the node and thus the threadLocal get closed while this task
// is still executing, we don't want this runnable to fail with an
@@ -403,7 +418,7 @@ public final class ThreadContext implements Closeable, Writeable {
/**
* Returns true
if the context is closed, otherwise true
*/
- boolean isClosed() {
+ public boolean isClosed() {
return threadLocal.closed.get();
}
diff --git a/server/src/main/java/org/elasticsearch/index/IndexingSlowLog.java b/server/src/main/java/org/elasticsearch/index/IndexingSlowLog.java
index b4b471e220a..faeb9d3bc26 100644
--- a/server/src/main/java/org/elasticsearch/index/IndexingSlowLog.java
+++ b/server/src/main/java/org/elasticsearch/index/IndexingSlowLog.java
@@ -19,10 +19,12 @@
package org.elasticsearch.index;
-import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.Logger;
+import org.apache.logging.log4j.util.StringBuilders;
import org.elasticsearch.common.Booleans;
import org.elasticsearch.common.Strings;
+import org.elasticsearch.common.logging.ESLogMessage;
import org.elasticsearch.common.logging.Loggers;
import org.elasticsearch.common.settings.Setting;
import org.elasticsearch.common.settings.Setting.Property;
@@ -35,7 +37,9 @@ import org.elasticsearch.index.shard.ShardId;
import java.io.IOException;
import java.io.UncheckedIOException;
+import java.util.HashMap;
import java.util.Locale;
+import java.util.Map;
import java.util.concurrent.TimeUnit;
public final class IndexingSlowLog implements IndexingOperationListener {
@@ -149,34 +153,58 @@ public final class IndexingSlowLog implements IndexingOperationListener {
final ParsedDocument doc = indexOperation.parsedDoc();
final long tookInNanos = result.getTook();
if (indexWarnThreshold >= 0 && tookInNanos > indexWarnThreshold) {
- indexLogger.warn("{}", new SlowLogParsedDocumentPrinter(index, doc, tookInNanos, reformat, maxSourceCharsToLog));
+ indexLogger.warn( new IndexingSlowLogMessage(index, doc, tookInNanos, reformat, maxSourceCharsToLog));
} else if (indexInfoThreshold >= 0 && tookInNanos > indexInfoThreshold) {
- indexLogger.info("{}", new SlowLogParsedDocumentPrinter(index, doc, tookInNanos, reformat, maxSourceCharsToLog));
+ indexLogger.info(new IndexingSlowLogMessage(index, doc, tookInNanos, reformat, maxSourceCharsToLog));
} else if (indexDebugThreshold >= 0 && tookInNanos > indexDebugThreshold) {
- indexLogger.debug("{}", new SlowLogParsedDocumentPrinter(index, doc, tookInNanos, reformat, maxSourceCharsToLog));
+ indexLogger.debug(new IndexingSlowLogMessage(index, doc, tookInNanos, reformat, maxSourceCharsToLog));
} else if (indexTraceThreshold >= 0 && tookInNanos > indexTraceThreshold) {
- indexLogger.trace("{}", new SlowLogParsedDocumentPrinter(index, doc, tookInNanos, reformat, maxSourceCharsToLog));
+ indexLogger.trace( new IndexingSlowLogMessage(index, doc, tookInNanos, reformat, maxSourceCharsToLog));
}
}
}
- static final class SlowLogParsedDocumentPrinter {
- private final ParsedDocument doc;
- private final long tookInNanos;
- private final boolean reformat;
- private final int maxSourceCharsToLog;
- private final Index index;
+ static final class IndexingSlowLogMessage extends ESLogMessage {
- SlowLogParsedDocumentPrinter(Index index, ParsedDocument doc, long tookInNanos, boolean reformat, int maxSourceCharsToLog) {
- this.doc = doc;
- this.index = index;
- this.tookInNanos = tookInNanos;
- this.reformat = reformat;
- this.maxSourceCharsToLog = maxSourceCharsToLog;
+ IndexingSlowLogMessage(Index index, ParsedDocument doc, long tookInNanos, boolean reformat, int maxSourceCharsToLog) {
+ super(prepareMap(index,doc,tookInNanos,reformat,maxSourceCharsToLog),
+ message(index,doc,tookInNanos,reformat,maxSourceCharsToLog));
}
- @Override
- public String toString() {
+ private static Map prepareMap(Index index, ParsedDocument doc, long tookInNanos, boolean reformat,
+ int maxSourceCharsToLog) {
+ Map map = new HashMap<>();
+ map.put("message", index);
+ map.put("took", TimeValue.timeValueNanos(tookInNanos));
+ map.put("took_millis", ""+TimeUnit.NANOSECONDS.toMillis(tookInNanos));
+ map.put("doc_type", doc.type());
+ map.put("id", doc.id());
+ map.put("routing", doc.routing());
+
+ if (maxSourceCharsToLog == 0 || doc.source() == null || doc.source().length() == 0) {
+ return map;
+ }
+ try {
+ String source = XContentHelper.convertToJson(doc.source(), reformat, doc.getXContentType());
+ String trim = Strings.cleanTruncate(source, maxSourceCharsToLog).trim();
+ StringBuilder sb = new StringBuilder(trim);
+ StringBuilders.escapeJson(sb,0);
+ map.put("source", sb.toString());
+ } catch (IOException e) {
+ StringBuilder sb = new StringBuilder("_failed_to_convert_[" + e.getMessage()+"]");
+ StringBuilders.escapeJson(sb,0);
+ map.put("source", sb.toString());
+ /*
+ * We choose to fail to write to the slow log and instead let this percolate up to the post index listener loop where this
+ * will be logged at the warn level.
+ */
+ final String message = String.format(Locale.ROOT, "failed to convert source for slow log entry [%s]", map.toString());
+ throw new UncheckedIOException(message, e);
+ }
+ return map;
+ }
+
+ private static String message(Index index, ParsedDocument doc, long tookInNanos, boolean reformat, int maxSourceCharsToLog) {
StringBuilder sb = new StringBuilder();
sb.append(index).append(" ");
sb.append("took[").append(TimeValue.timeValueNanos(tookInNanos)).append("], ");
diff --git a/server/src/main/java/org/elasticsearch/index/SearchSlowLog.java b/server/src/main/java/org/elasticsearch/index/SearchSlowLog.java
index abd67a47049..bafacc21f93 100644
--- a/server/src/main/java/org/elasticsearch/index/SearchSlowLog.java
+++ b/server/src/main/java/org/elasticsearch/index/SearchSlowLog.java
@@ -19,9 +19,11 @@
package org.elasticsearch.index;
-import org.apache.logging.log4j.Logger;
+import com.fasterxml.jackson.core.io.JsonStringEncoder;
import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.Logger;
import org.elasticsearch.common.Strings;
+import org.elasticsearch.common.logging.ESLogMessage;
import org.elasticsearch.common.logging.Loggers;
import org.elasticsearch.common.settings.Setting;
import org.elasticsearch.common.settings.Setting.Property;
@@ -31,8 +33,12 @@ import org.elasticsearch.index.shard.SearchOperationListener;
import org.elasticsearch.search.internal.SearchContext;
import org.elasticsearch.tasks.Task;
+import java.nio.charset.Charset;
import java.util.Collections;
+import java.util.HashMap;
+import java.util.Map;
import java.util.concurrent.TimeUnit;
+import java.util.stream.Stream;
public final class SearchSlowLog implements SearchOperationListener {
private long queryWarnThreshold;
@@ -121,49 +127,75 @@ public final class SearchSlowLog implements SearchOperationListener {
Loggers.setLevel(queryLogger, level.name());
Loggers.setLevel(fetchLogger, level.name());
}
+
@Override
public void onQueryPhase(SearchContext context, long tookInNanos) {
if (queryWarnThreshold >= 0 && tookInNanos > queryWarnThreshold) {
- queryLogger.warn("{}", new SlowLogSearchContextPrinter(context, tookInNanos));
+ queryLogger.warn(new SearchSlowLogMessage(context, tookInNanos));
} else if (queryInfoThreshold >= 0 && tookInNanos > queryInfoThreshold) {
- queryLogger.info("{}", new SlowLogSearchContextPrinter(context, tookInNanos));
+ queryLogger.info(new SearchSlowLogMessage(context, tookInNanos));
} else if (queryDebugThreshold >= 0 && tookInNanos > queryDebugThreshold) {
- queryLogger.debug("{}", new SlowLogSearchContextPrinter(context, tookInNanos));
+ queryLogger.debug(new SearchSlowLogMessage(context, tookInNanos));
} else if (queryTraceThreshold >= 0 && tookInNanos > queryTraceThreshold) {
- queryLogger.trace("{}", new SlowLogSearchContextPrinter(context, tookInNanos));
+ queryLogger.trace(new SearchSlowLogMessage(context, tookInNanos));
}
}
@Override
public void onFetchPhase(SearchContext context, long tookInNanos) {
if (fetchWarnThreshold >= 0 && tookInNanos > fetchWarnThreshold) {
- fetchLogger.warn("{}", new SlowLogSearchContextPrinter(context, tookInNanos));
+ fetchLogger.warn(new SearchSlowLogMessage(context, tookInNanos));
} else if (fetchInfoThreshold >= 0 && tookInNanos > fetchInfoThreshold) {
- fetchLogger.info("{}", new SlowLogSearchContextPrinter(context, tookInNanos));
+ fetchLogger.info(new SearchSlowLogMessage(context, tookInNanos));
} else if (fetchDebugThreshold >= 0 && tookInNanos > fetchDebugThreshold) {
- fetchLogger.debug("{}", new SlowLogSearchContextPrinter(context, tookInNanos));
+ fetchLogger.debug(new SearchSlowLogMessage(context, tookInNanos));
} else if (fetchTraceThreshold >= 0 && tookInNanos > fetchTraceThreshold) {
- fetchLogger.trace("{}", new SlowLogSearchContextPrinter(context, tookInNanos));
+ fetchLogger.trace(new SearchSlowLogMessage(context, tookInNanos));
}
}
- static final class SlowLogSearchContextPrinter {
- private final SearchContext context;
- private final long tookInNanos;
+ static final class SearchSlowLogMessage extends ESLogMessage {
- SlowLogSearchContextPrinter(SearchContext context, long tookInNanos) {
- this.context = context;
- this.tookInNanos = tookInNanos;
+ SearchSlowLogMessage(SearchContext context, long tookInNanos) {
+ super(prepareMap(context, tookInNanos), message(context, tookInNanos));
}
- @Override
- public String toString() {
+ private static Map prepareMap(SearchContext context, long tookInNanos) {
+ Map messageFields = new HashMap<>();
+ messageFields.put("message", context.indexShard().shardId());
+ messageFields.put("took", TimeValue.timeValueNanos(tookInNanos));
+ messageFields.put("took_millis", TimeUnit.NANOSECONDS.toMillis(tookInNanos));
+ if (context.queryResult().getTotalHits() != null) {
+ messageFields.put("total_hits", context.queryResult().getTotalHits());
+ } else {
+ messageFields.put("total_hits", "-1");
+ }
+ messageFields.put("stats", asJsonArray(context.groupStats() != null ? context.groupStats().stream() : Stream.empty()));
+ messageFields.put("search_type", context.searchType());
+ messageFields.put("total_shards", context.numberOfShards());
+
+ if (context.request().source() != null) {
+ byte[] sourceEscaped = JsonStringEncoder.getInstance()
+ .quoteAsUTF8(context.request().source().toString(FORMAT_PARAMS));
+ String source = new String(sourceEscaped, Charset.defaultCharset());
+
+ messageFields.put("source", source);
+ } else {
+ messageFields.put("source", "{}");
+ }
+
+ messageFields.put("id", context.getTask().getHeader(Task.X_OPAQUE_ID));
+ return messageFields;
+ }
+
+ // Message will be used in plaintext logs
+ private static String message(SearchContext context, long tookInNanos) {
StringBuilder sb = new StringBuilder();
sb.append(context.indexShard().shardId())
- .append(" ")
- .append("took[").append(TimeValue.timeValueNanos(tookInNanos)).append("], ")
- .append("took_millis[").append(TimeUnit.NANOSECONDS.toMillis(tookInNanos)).append("], ")
- .append("total_hits[");
+ .append(" ")
+ .append("took[").append(TimeValue.timeValueNanos(tookInNanos)).append("], ")
+ .append("took_millis[").append(TimeUnit.NANOSECONDS.toMillis(tookInNanos)).append("], ")
+ .append("total_hits[");
if (context.queryResult().getTotalHits() != null) {
sb.append(context.queryResult().getTotalHits());
} else {
diff --git a/server/src/test/java/org/elasticsearch/common/logging/DeprecationLoggerTests.java b/server/src/test/java/org/elasticsearch/common/logging/DeprecationLoggerTests.java
index 740430ac099..ad1412dfa44 100644
--- a/server/src/test/java/org/elasticsearch/common/logging/DeprecationLoggerTests.java
+++ b/server/src/test/java/org/elasticsearch/common/logging/DeprecationLoggerTests.java
@@ -26,6 +26,7 @@ import org.apache.logging.log4j.simple.SimpleLoggerContextFactory;
import org.apache.logging.log4j.spi.ExtendedLogger;
import org.apache.logging.log4j.spi.LoggerContext;
import org.apache.logging.log4j.spi.LoggerContextFactory;
+import org.elasticsearch.common.SuppressLoggerChecks;
import org.elasticsearch.common.settings.Settings;
import org.elasticsearch.common.util.concurrent.ThreadContext;
import org.elasticsearch.test.ESTestCase;
@@ -56,6 +57,7 @@ import static org.hamcrest.Matchers.equalTo;
import static org.hamcrest.Matchers.hasSize;
import static org.hamcrest.Matchers.not;
import static org.hamcrest.core.Is.is;
+import static org.mockito.Matchers.any;
import static org.mockito.Mockito.doAnswer;
import static org.mockito.Mockito.mock;
import static org.mockito.Mockito.when;
@@ -318,7 +320,7 @@ public class DeprecationLoggerTests extends ESTestCase {
assertTrue(warningHeadersSize <= 1024);
}
}
-
+ @SuppressLoggerChecks(reason = "Safe as this is using mockito")
public void testLogPermissions() {
AtomicBoolean supplierCalled = new AtomicBoolean(false);
@@ -330,7 +332,7 @@ public class DeprecationLoggerTests extends ESTestCase {
supplierCalled.set(true);
createTempDir(); // trigger file permission, like rolling logs would
return null;
- }).when(mockLogger).warn("foo", new Object[] {"bar"});
+ }).when(mockLogger).warn(new DeprecatedMessage("foo", any()));
final LoggerContext context = new SimpleLoggerContext() {
@Override
public ExtendedLogger getLogger(String name) {
diff --git a/server/src/test/java/org/elasticsearch/index/IndexingSlowLogTests.java b/server/src/test/java/org/elasticsearch/index/IndexingSlowLogTests.java
index 72a1cb4a87d..49747993ec1 100644
--- a/server/src/test/java/org/elasticsearch/index/IndexingSlowLogTests.java
+++ b/server/src/test/java/org/elasticsearch/index/IndexingSlowLogTests.java
@@ -29,7 +29,7 @@ import org.elasticsearch.common.settings.Settings;
import org.elasticsearch.common.unit.TimeValue;
import org.elasticsearch.common.xcontent.XContentType;
import org.elasticsearch.common.xcontent.json.JsonXContent;
-import org.elasticsearch.index.IndexingSlowLog.SlowLogParsedDocumentPrinter;
+import org.elasticsearch.index.IndexingSlowLog.IndexingSlowLogMessage;
import org.elasticsearch.index.mapper.ParsedDocument;
import org.elasticsearch.index.mapper.SeqNoFieldMapper;
import org.elasticsearch.test.ESTestCase;
@@ -38,13 +38,39 @@ import java.io.IOException;
import java.io.UncheckedIOException;
import static org.hamcrest.Matchers.containsString;
+import static org.hamcrest.Matchers.emptyOrNullString;
import static org.hamcrest.Matchers.equalTo;
import static org.hamcrest.Matchers.hasToString;
import static org.hamcrest.Matchers.instanceOf;
+import static org.hamcrest.Matchers.is;
import static org.hamcrest.Matchers.not;
import static org.hamcrest.Matchers.startsWith;
public class IndexingSlowLogTests extends ESTestCase {
+
+ public void testSlowLogMessageHasJsonFields() throws IOException {
+ BytesReference source = BytesReference.bytes(JsonXContent.contentBuilder()
+ .startObject().field("foo", "bar").endObject());
+ ParsedDocument pd = new ParsedDocument(new NumericDocValuesField("version", 1),
+ SeqNoFieldMapper.SequenceIDFields.emptySeqID(), "id",
+ "test", "routingValue", null, source, XContentType.JSON, null);
+ Index index = new Index("foo", "123");
+ // Turning off document logging doesn't log source[]
+ IndexingSlowLogMessage p = new IndexingSlowLogMessage(index, pd, 10, true, 0);
+
+ assertThat(p.getValueFor("message"),equalTo("[foo/123]"));
+ assertThat(p.getValueFor("took"),equalTo("10nanos"));
+ assertThat(p.getValueFor("took_millis"),equalTo("0"));
+ assertThat(p.getValueFor("doc_type"),equalTo("test"));
+ assertThat(p.getValueFor("id"),equalTo("id"));
+ assertThat(p.getValueFor("routing"),equalTo("routingValue"));
+ assertThat(p.getValueFor("source"), is(emptyOrNullString()));
+
+ // Turning on document logging logs the whole thing
+ p = new IndexingSlowLogMessage(index, pd, 10, true, Integer.MAX_VALUE);
+ assertThat(p.getValueFor("source"), containsString("{\\\"foo\\\":\\\"bar\\\"}"));
+ }
+
public void testSlowLogParsedDocumentPrinterSourceToLog() throws IOException {
BytesReference source = BytesReference.bytes(JsonXContent.contentBuilder()
.startObject().field("foo", "bar").endObject());
@@ -53,32 +79,32 @@ public class IndexingSlowLogTests extends ESTestCase {
"test", null, null, source, XContentType.JSON, null);
Index index = new Index("foo", "123");
// Turning off document logging doesn't log source[]
- SlowLogParsedDocumentPrinter p = new SlowLogParsedDocumentPrinter(index, pd, 10, true, 0);
- assertThat(p.toString(), not(containsString("source[")));
+ IndexingSlowLogMessage p = new IndexingSlowLogMessage(index, pd, 10, true, 0);
+ assertThat(p.getFormattedMessage(), not(containsString("source[")));
// Turning on document logging logs the whole thing
- p = new SlowLogParsedDocumentPrinter(index, pd, 10, true, Integer.MAX_VALUE);
- assertThat(p.toString(), containsString("source[{\"foo\":\"bar\"}]"));
+ p = new IndexingSlowLogMessage(index, pd, 10, true, Integer.MAX_VALUE);
+ assertThat(p.getFormattedMessage(), containsString("source[{\"foo\":\"bar\"}]"));
// And you can truncate the source
- p = new SlowLogParsedDocumentPrinter(index, pd, 10, true, 3);
- assertThat(p.toString(), containsString("source[{\"f]"));
+ p = new IndexingSlowLogMessage(index, pd, 10, true, 3);
+ assertThat(p.getFormattedMessage(), containsString("source[{\"f]"));
// And you can truncate the source
- p = new SlowLogParsedDocumentPrinter(index, pd, 10, true, 3);
- assertThat(p.toString(), containsString("source[{\"f]"));
- assertThat(p.toString(), startsWith("[foo/123] took"));
+ p = new IndexingSlowLogMessage(index, pd, 10, true, 3);
+ assertThat(p.getFormattedMessage(), containsString("source[{\"f]"));
+ assertThat(p.getFormattedMessage(), startsWith("[foo/123] took"));
// Throwing a error if source cannot be converted
source = new BytesArray("invalid");
- pd = new ParsedDocument(new NumericDocValuesField("version", 1),
+ ParsedDocument doc = new ParsedDocument(new NumericDocValuesField("version", 1),
SeqNoFieldMapper.SequenceIDFields.emptySeqID(), "id",
"test", null, null, source, XContentType.JSON, null);
- p = new SlowLogParsedDocumentPrinter(index, pd, 10, true, 3);
- final UncheckedIOException e = expectThrows(UncheckedIOException.class, p::toString);
+ final UncheckedIOException e = expectThrows(UncheckedIOException.class,
+ ()->new IndexingSlowLogMessage(index, doc, 10, true, 3));
assertThat(e, hasToString(containsString("_failed_to_convert_[Unrecognized token 'invalid':"
- + " was expecting ('true', 'false' or 'null')\n"
+ + " was expecting ('true', 'false' or 'null')\\n"
+ " at [Source: org.elasticsearch.common.bytes.BytesReference$MarkSupportingStreamInputWrapper")));
assertNotNull(e.getCause());
assertThat(e.getCause(), instanceOf(JsonParseException.class));
@@ -128,22 +154,6 @@ public class IndexingSlowLogTests extends ESTestCase {
assertTrue(log.isReformat());
}
- public void testReformatIsFalseAndSourceIsTrim() {
- String json = "\n\n{ \"fieldName\": 123 } \n ";
- BytesReference source = new BytesArray(json);
- ParsedDocument pd = new ParsedDocument(new NumericDocValuesField("version", 1),
- SeqNoFieldMapper.SequenceIDFields.emptySeqID(), "id",
- "test", null, null, source, XContentType.JSON, null);
- Index index = new Index("foo", "123");
- // Turning off reformatting so the document is in logs as provided
- SlowLogParsedDocumentPrinter p = new SlowLogParsedDocumentPrinter(index, pd, 10, false, 1000);
- String logLine = p.toString();
-
- //expect the new lines and white characters to be trimmed
- assertThat(logLine, containsString("source[{"));
- assertThat(logLine.split("\n").length, equalTo(1));
- }
-
public void testLevelSetting() {
SlowLogLevel level = randomFrom(SlowLogLevel.values());
IndexMetaData metaData = newIndexMeta("index", Settings.builder()
diff --git a/server/src/test/java/org/elasticsearch/index/SearchSlowLogTests.java b/server/src/test/java/org/elasticsearch/index/SearchSlowLogTests.java
index c054b2008db..21585400415 100644
--- a/server/src/test/java/org/elasticsearch/index/SearchSlowLogTests.java
+++ b/server/src/test/java/org/elasticsearch/index/SearchSlowLogTests.java
@@ -39,12 +39,14 @@ import org.elasticsearch.tasks.Task;
import org.elasticsearch.test.ESSingleNodeTestCase;
import org.elasticsearch.test.TestSearchContext;
import org.elasticsearch.threadpool.ThreadPool;
+import org.hamcrest.Matchers;
import java.io.IOException;
import java.util.Collections;
import static org.hamcrest.Matchers.containsString;
import static org.hamcrest.Matchers.endsWith;
+import static org.hamcrest.Matchers.equalTo;
import static org.hamcrest.Matchers.hasToString;
import static org.hamcrest.Matchers.instanceOf;
import static org.hamcrest.Matchers.not;
@@ -155,6 +157,25 @@ public class SearchSlowLogTests extends ESSingleNodeTestCase {
};
}
+ public void testSlowLogHasJsonFields() throws IOException {
+ IndexService index = createIndex("foo");
+ SearchContext searchContext = createSearchContext(index);
+ SearchSourceBuilder source = SearchSourceBuilder.searchSource().query(QueryBuilders.matchAllQuery());
+ searchContext.request().source(source);
+ searchContext.setTask(new SearchTask(0, "n/a", "n/a", "test", null,
+ Collections.singletonMap(Task.X_OPAQUE_ID, "my_id")));
+ SearchSlowLog.SearchSlowLogMessage p = new SearchSlowLog.SearchSlowLogMessage(searchContext, 10);
+
+ assertThat(p.getValueFor("message"), equalTo("[foo][0]"));
+ assertThat(p.getValueFor("took"), equalTo("10nanos"));
+ assertThat(p.getValueFor("took_millis"), equalTo("0"));
+ assertThat(p.getValueFor("total_hits"), equalTo("-1"));
+ assertThat(p.getValueFor("stats"), equalTo("[]"));
+ assertThat(p.getValueFor("search_type"), Matchers.nullValue());
+ assertThat(p.getValueFor("total_shards"), equalTo("1"));
+ assertThat(p.getValueFor("source"), equalTo("{\\\"query\\\":{\\\"match_all\\\":{\\\"boost\\\":1.0}}}"));
+ }
+
public void testSlowLogSearchContextPrinterToLog() throws IOException {
IndexService index = createIndex("foo");
SearchContext searchContext = createSearchContext(index);
@@ -162,11 +183,11 @@ public class SearchSlowLogTests extends ESSingleNodeTestCase {
searchContext.request().source(source);
searchContext.setTask(new SearchTask(0, "n/a", "n/a", "test", null,
Collections.singletonMap(Task.X_OPAQUE_ID, "my_id")));
- SearchSlowLog.SlowLogSearchContextPrinter p = new SearchSlowLog.SlowLogSearchContextPrinter(searchContext, 10);
- assertThat(p.toString(), startsWith("[foo][0]"));
+ SearchSlowLog.SearchSlowLogMessage p = new SearchSlowLog.SearchSlowLogMessage(searchContext, 10);
+ assertThat(p.getFormattedMessage(), startsWith("[foo][0]"));
// Makes sure that output doesn't contain any new lines
- assertThat(p.toString(), not(containsString("\n")));
- assertThat(p.toString(), endsWith("id[my_id], "));
+ assertThat(p.getFormattedMessage(), not(containsString("\n")));
+ assertThat(p.getFormattedMessage(), endsWith("id[my_id], "));
}
public void testLevelSetting() {
diff --git a/test/framework/src/main/java/org/elasticsearch/common/logging/JsonLogLine.java b/test/framework/src/main/java/org/elasticsearch/common/logging/JsonLogLine.java
index fa8f3d7d270..15f4b17ba6f 100644
--- a/test/framework/src/main/java/org/elasticsearch/common/logging/JsonLogLine.java
+++ b/test/framework/src/main/java/org/elasticsearch/common/logging/JsonLogLine.java
@@ -30,7 +30,7 @@ import java.util.List;
* Parsing log lines with this class confirms the json format of logs
*/
public class JsonLogLine {
- public static final ObjectParser PARSER = createParser(false);
+ public static final ObjectParser PARSER = createParser(true);
private String type;
private String timestamp;
diff --git a/test/framework/src/main/java/org/elasticsearch/common/logging/JsonLogsStream.java b/test/framework/src/main/java/org/elasticsearch/common/logging/JsonLogsStream.java
index 28ad649f55a..ad6fedca2d9 100644
--- a/test/framework/src/main/java/org/elasticsearch/common/logging/JsonLogsStream.java
+++ b/test/framework/src/main/java/org/elasticsearch/common/logging/JsonLogsStream.java
@@ -30,6 +30,8 @@ import java.io.UncheckedIOException;
import java.nio.file.Files;
import java.nio.file.Path;
import java.util.Iterator;
+import java.util.LinkedHashMap;
+import java.util.Map;
import java.util.Spliterator;
import java.util.Spliterators;
import java.util.stream.Stream;
@@ -57,10 +59,20 @@ public class JsonLogsStream {
return from(Files.newBufferedReader(path));
}
+ public static Stream