Restores the original default format of search slow log

In 5.0, the search slow log switched to the multi-line format with no option to get back to the origin single-line format that was used prior to 5.0 by default. This commit removes the reformat option from the search slow log and returns the search slow log back to the single-line format.

Closes #21711

core/src/main/java/org/elasticsearch/common/settings/IndexScopedSettings.java

@@ -87,7 +87,6 @@ public final class IndexScopedSettings extends AbstractScopedSettings {
         SearchSlowLog.INDEX_SEARCH_SLOWLOG_THRESHOLD_QUERY_INFO_SETTING,
         SearchSlowLog.INDEX_SEARCH_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING,
         SearchSlowLog.INDEX_SEARCH_SLOWLOG_LEVEL,
-        SearchSlowLog.INDEX_SEARCH_SLOWLOG_REFORMAT,
         IndexingSlowLog.INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_WARN_SETTING,
         IndexingSlowLog.INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_DEBUG_SETTING,
         IndexingSlowLog.INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_INFO_SETTING,

core/src/main/java/org/elasticsearch/index/SearchSlowLog.java

@@ -25,14 +25,14 @@ import org.elasticsearch.common.logging.Loggers;
 import org.elasticsearch.common.settings.Setting;
 import org.elasticsearch.common.settings.Setting.Property;
 import org.elasticsearch.common.unit.TimeValue;
+import org.elasticsearch.common.xcontent.ToXContent;
 import org.elasticsearch.index.shard.SearchOperationListener;
 import org.elasticsearch.search.internal.SearchContext;
 
+import java.util.Collections;
 import java.util.concurrent.TimeUnit;
 
 public final class SearchSlowLog implements SearchOperationListener {
-    private boolean reformat;
-
     private long queryWarnThreshold;
     private long queryInfoThreshold;
     private long queryDebugThreshold;
@@ -73,20 +73,17 @@ public final class SearchSlowLog implements SearchOperationListener {
     public static final Setting<TimeValue> INDEX_SEARCH_SLOWLOG_THRESHOLD_FETCH_TRACE_SETTING =
         Setting.timeSetting(INDEX_SEARCH_SLOWLOG_PREFIX + ".threshold.fetch.trace", TimeValue.timeValueNanos(-1),
             TimeValue.timeValueMillis(-1), Property.Dynamic, Property.IndexScope);
-    public static final Setting<Boolean> INDEX_SEARCH_SLOWLOG_REFORMAT =
-        Setting.boolSetting(INDEX_SEARCH_SLOWLOG_PREFIX + ".reformat", true, Property.Dynamic, Property.IndexScope);
     public static final Setting<SlowLogLevel> INDEX_SEARCH_SLOWLOG_LEVEL =
         new Setting<>(INDEX_SEARCH_SLOWLOG_PREFIX + ".level", SlowLogLevel.TRACE.name(), SlowLogLevel::parse, Property.Dynamic,
             Property.IndexScope);
 
+    private static final ToXContent.Params FORMAT_PARAMS = new ToXContent.MapParams(Collections.singletonMap("pretty", "false"));
+
     public SearchSlowLog(IndexSettings indexSettings) {
 
         this.queryLogger = Loggers.getLogger(INDEX_SEARCH_SLOWLOG_PREFIX + ".query", indexSettings.getSettings());
         this.fetchLogger = Loggers.getLogger(INDEX_SEARCH_SLOWLOG_PREFIX + ".fetch", indexSettings.getSettings());
 
-        indexSettings.getScopedSettings().addSettingsUpdateConsumer(INDEX_SEARCH_SLOWLOG_REFORMAT, this::setReformat);
-        this.reformat = indexSettings.getValue(INDEX_SEARCH_SLOWLOG_REFORMAT);
-
         indexSettings.getScopedSettings().addSettingsUpdateConsumer(INDEX_SEARCH_SLOWLOG_THRESHOLD_QUERY_WARN_SETTING, this::setQueryWarnThreshold);
         this.queryWarnThreshold = indexSettings.getValue(INDEX_SEARCH_SLOWLOG_THRESHOLD_QUERY_WARN_SETTING).nanos();
         indexSettings.getScopedSettings().addSettingsUpdateConsumer(INDEX_SEARCH_SLOWLOG_THRESHOLD_QUERY_INFO_SETTING, this::setQueryInfoThreshold);
@@ -117,38 +114,36 @@ public final class SearchSlowLog implements SearchOperationListener {
     @Override
     public void onQueryPhase(SearchContext context, long tookInNanos) {
         if (queryWarnThreshold >= 0 && tookInNanos > queryWarnThreshold) {
-            queryLogger.warn("{}", new SlowLogSearchContextPrinter(context, tookInNanos, reformat));
+            queryLogger.warn("{}", new SlowLogSearchContextPrinter(context, tookInNanos));
         } else if (queryInfoThreshold >= 0 && tookInNanos > queryInfoThreshold) {
-            queryLogger.info("{}", new SlowLogSearchContextPrinter(context, tookInNanos, reformat));
+            queryLogger.info("{}", new SlowLogSearchContextPrinter(context, tookInNanos));
         } else if (queryDebugThreshold >= 0 && tookInNanos > queryDebugThreshold) {
-            queryLogger.debug("{}", new SlowLogSearchContextPrinter(context, tookInNanos, reformat));
+            queryLogger.debug("{}", new SlowLogSearchContextPrinter(context, tookInNanos));
         } else if (queryTraceThreshold >= 0 && tookInNanos > queryTraceThreshold) {
-            queryLogger.trace("{}", new SlowLogSearchContextPrinter(context, tookInNanos, reformat));
+            queryLogger.trace("{}", new SlowLogSearchContextPrinter(context, tookInNanos));
         }
     }
 
     @Override
     public void onFetchPhase(SearchContext context, long tookInNanos) {
         if (fetchWarnThreshold >= 0 && tookInNanos > fetchWarnThreshold) {
-            fetchLogger.warn("{}", new SlowLogSearchContextPrinter(context, tookInNanos, reformat));
+            fetchLogger.warn("{}", new SlowLogSearchContextPrinter(context, tookInNanos));
         } else if (fetchInfoThreshold >= 0 && tookInNanos > fetchInfoThreshold) {
-            fetchLogger.info("{}", new SlowLogSearchContextPrinter(context, tookInNanos, reformat));
+            fetchLogger.info("{}", new SlowLogSearchContextPrinter(context, tookInNanos));
         } else if (fetchDebugThreshold >= 0 && tookInNanos > fetchDebugThreshold) {
-            fetchLogger.debug("{}", new SlowLogSearchContextPrinter(context, tookInNanos, reformat));
+            fetchLogger.debug("{}", new SlowLogSearchContextPrinter(context, tookInNanos));
         } else if (fetchTraceThreshold >= 0 && tookInNanos > fetchTraceThreshold) {
-            fetchLogger.trace("{}", new SlowLogSearchContextPrinter(context, tookInNanos, reformat));
+            fetchLogger.trace("{}", new SlowLogSearchContextPrinter(context, tookInNanos));
         }
     }
 
     static final class SlowLogSearchContextPrinter {
         private final SearchContext context;
         private final long tookInNanos;
-        private final boolean reformat;
 
-        public SlowLogSearchContextPrinter(SearchContext context, long tookInNanos, boolean reformat) {
+        public SlowLogSearchContextPrinter(SearchContext context, long tookInNanos) {
             this.context = context;
             this.tookInNanos = tookInNanos;
-            this.reformat = reformat;
         }
 
         @Override
@@ -172,7 +167,7 @@ public final class SearchSlowLog implements SearchOperationListener {
             }
             sb.append("search_type[").append(context.searchType()).append("], total_shards[").append(context.numberOfShards()).append("], ");
             if (context.request().source() != null) {
-                sb.append("source[").append(context.request().source()).append("], ");
+                sb.append("source[").append(context.request().source().toString(FORMAT_PARAMS)).append("], ");
             } else {
                 sb.append("source[], ");
             }
@@ -180,10 +175,6 @@ public final class SearchSlowLog implements SearchOperationListener {
         }
     }
 
-    private void setReformat(boolean reformat) {
-        this.reformat = reformat;
-    }
-
     private void setQueryWarnThreshold(TimeValue warnThreshold) {
         this.queryWarnThreshold = warnThreshold.nanos();
     }
@@ -216,10 +207,6 @@ public final class SearchSlowLog implements SearchOperationListener {
         this.fetchTraceThreshold = traceThreshold.nanos();
     }
 
-    boolean isReformat() {
-        return reformat;
-    }
-
     long getQueryWarnThreshold() {
         return queryWarnThreshold;
     }

core/src/test/java/org/elasticsearch/index/SearchSlowLogTests.java

@@ -27,9 +27,9 @@ import org.elasticsearch.common.settings.Settings;
 import org.elasticsearch.common.unit.TimeValue;
 import org.elasticsearch.common.util.BigArrays;
 import org.elasticsearch.index.query.QueryBuilder;
+import org.elasticsearch.index.query.QueryBuilders;
 import org.elasticsearch.index.query.QueryShardContext;
 import org.elasticsearch.index.shard.ShardId;
-import org.elasticsearch.script.ScriptService;
 import org.elasticsearch.search.Scroll;
 import org.elasticsearch.search.builder.SearchSourceBuilder;
 import org.elasticsearch.search.internal.SearchContext;
@@ -40,6 +40,8 @@ import org.elasticsearch.threadpool.ThreadPool;
 
 import java.io.IOException;
 
+import static org.hamcrest.Matchers.not;
+import static org.hamcrest.Matchers.containsString;
 import static org.hamcrest.Matchers.startsWith;
 
 public class SearchSlowLogTests extends ESSingleNodeTestCase {
@@ -48,9 +50,8 @@ public class SearchSlowLogTests extends ESSingleNodeTestCase {
         BigArrays bigArrays = indexService.getBigArrays();
         ThreadPool threadPool = indexService.getThreadPool();
         return new TestSearchContext(threadPool, bigArrays, indexService) {
-            @Override
+            final ShardSearchRequest request = new ShardSearchRequest() {
-            public ShardSearchRequest request() {
+                private SearchSourceBuilder searchSourceBuilder;
-                return new ShardSearchRequest() {
                 @Override
                 public ShardId shardId() {
                     return new ShardId(indexService.index(), 0);
@@ -63,12 +64,12 @@ public class SearchSlowLogTests extends ESSingleNodeTestCase {
 
                 @Override
                 public SearchSourceBuilder source() {
-                        return null;
+                    return searchSourceBuilder;
                 }
 
                 @Override
                 public void source(SearchSourceBuilder source) {
-
+                    searchSourceBuilder = source;
                 }
 
                 @Override
@@ -120,48 +121,22 @@ public class SearchSlowLogTests extends ESSingleNodeTestCase {
                 public void rewrite(QueryShardContext context) throws IOException {
                 }
             };
+            @Override
+            public ShardSearchRequest request() {
+                return request;
             }
         };
     }
 
     public void testSlowLogSearchContextPrinterToLog() throws IOException {
         IndexService index = createIndex("foo");
-        // Turning off document logging doesn't log source[]
         SearchContext searchContext = createSearchContext(index);
-        SearchSlowLog.SlowLogSearchContextPrinter p = new SearchSlowLog.SlowLogSearchContextPrinter(searchContext, 10, true);
+        SearchSourceBuilder source = SearchSourceBuilder.searchSource().query(QueryBuilders.matchAllQuery());
+        searchContext.request().source(source);
+        SearchSlowLog.SlowLogSearchContextPrinter p = new SearchSlowLog.SlowLogSearchContextPrinter(searchContext, 10);
         assertThat(p.toString(), startsWith("[foo][0]"));
-    }
+        // Makes sure that output doesn't contain any new lines
-
+        assertThat(p.toString(), not(containsString("\n")));
-    public void testReformatSetting() {
-        IndexMetaData metaData = newIndexMeta("index", Settings.builder()
-            .put(IndexMetaData.SETTING_VERSION_CREATED, Version.CURRENT)
-            .put(SearchSlowLog.INDEX_SEARCH_SLOWLOG_REFORMAT.getKey(), false)
-            .build());
-        IndexSettings settings = new IndexSettings(metaData, Settings.EMPTY);
-        SearchSlowLog log = new SearchSlowLog(settings);
-        assertFalse(log.isReformat());
-        settings.updateIndexMetaData(newIndexMeta("index", Settings.builder().put(SearchSlowLog.INDEX_SEARCH_SLOWLOG_REFORMAT.getKey(), "true").build()));
-        assertTrue(log.isReformat());
-
-        settings.updateIndexMetaData(newIndexMeta("index", Settings.builder().put(SearchSlowLog.INDEX_SEARCH_SLOWLOG_REFORMAT.getKey(), "false").build()));
-        assertFalse(log.isReformat());
-
-        settings.updateIndexMetaData(newIndexMeta("index", Settings.EMPTY));
-        assertTrue(log.isReformat());
-
-        metaData = newIndexMeta("index", Settings.builder()
-            .put(IndexMetaData.SETTING_VERSION_CREATED, Version.CURRENT)
-            .build());
-        settings = new IndexSettings(metaData, Settings.EMPTY);
-        log = new SearchSlowLog(settings);
-        assertTrue(log.isReformat());
-        try {
-            settings.updateIndexMetaData(newIndexMeta("index", Settings.builder().put(SearchSlowLog.INDEX_SEARCH_SLOWLOG_REFORMAT.getKey(), "NOT A BOOLEAN").build()));
-            fail();
-        } catch (IllegalArgumentException ex) {
-            assertEquals(ex.getMessage(), "Failed to parse value [NOT A BOOLEAN] cannot be parsed to boolean [ true/1/on/yes OR false/0/off/no ]");
-        }
-        assertTrue(log.isReformat());
     }
 
     public void testLevelSetting() {
@@ -192,7 +167,6 @@ public class SearchSlowLogTests extends ESSingleNodeTestCase {
             .build());
         settings = new IndexSettings(metaData, Settings.EMPTY);
         log = new SearchSlowLog(settings);
-        assertTrue(log.isReformat());
         try {
             settings.updateIndexMetaData(newIndexMeta("index", Settings.builder().put(SearchSlowLog.INDEX_SEARCH_SLOWLOG_LEVEL.getKey(), "NOT A LEVEL").build()));
             fail();

docs/reference/index-modules/slowlog.asciidoc

@@ -85,7 +85,11 @@ All of the above settings are _dynamic_ and are set per-index.
 By default Elasticsearch will log the first 1000 characters of the _source in
 the slowlog. You can change that with `index.indexing.slowlog.source`. Setting
 it to `false` or `0` will skip logging the source entirely an setting it to
-`true` will log the entire source regardless of size.
+`true` will log the entire source regardless of size. The original `_source` is
+reformatted by default to make sure that it fits on a single log line. If preserving
+the original document format is important, you can turn off reformatting by setting
+`index.indexing.slowlog.reformat` to `false`, which will cause the source to be
+logged "as is" and can potentially span multiple log lines.
 
 The index slow log file is configured by default in the `log4j2.properties`
 file: