From 0db90a7ea5ebea75fae2c3d0f0fabfdc1204ede4 Mon Sep 17 00:00:00 2001 From: David Zane Date: Mon, 16 Oct 2023 13:32:53 -0700 Subject: [PATCH] Request level coordinator slow logs Signed-off-by: David Zane --- .../search/AbstractSearchAsyncAction.java | 7 +- .../SearchRequestOperationsListener.java | 26 ++ .../action/search/SearchRequestSlowLog.java | 269 ++++++++++++++++++ .../action/search/TransportSearchAction.java | 3 + .../common/settings/ClusterSettings.java | 8 + .../org/opensearch/index/SlowLogLevel.java | 2 +- .../action/search/MockSearchPhaseContext.java | 7 +- .../search/SearchRequestSlowLogTests.java | 253 ++++++++++++++++ 8 files changed, 572 insertions(+), 3 deletions(-) create mode 100644 server/src/main/java/org/opensearch/action/search/SearchRequestSlowLog.java create mode 100644 server/src/test/java/org/opensearch/action/search/SearchRequestSlowLogTests.java diff --git a/server/src/main/java/org/opensearch/action/search/AbstractSearchAsyncAction.java b/server/src/main/java/org/opensearch/action/search/AbstractSearchAsyncAction.java index 14f57218ae1dc..10b07c8d92c53 100644 --- a/server/src/main/java/org/opensearch/action/search/AbstractSearchAsyncAction.java +++ b/server/src/main/java/org/opensearch/action/search/AbstractSearchAsyncAction.java @@ -441,6 +441,10 @@ private void onPhaseStart(SearchPhase phase) { this.searchRequestOperationsListener.ifPresent(searchRequestOperations -> { searchRequestOperations.onPhaseStart(this); }); } + private void onRequestEnd() { + this.searchRequestOperationsListener.ifPresent(searchRequestOperations -> { searchRequestOperations.onRequestEnd(this); }); + } + private void executePhase(SearchPhase phase) { try { onPhaseStart(phase); @@ -696,9 +700,10 @@ public void sendSearchResponse(InternalSearchResponse internalSearchResponse, At searchContextId = null; } } + onPhaseEnd(); + onRequestEnd(); listener.onResponse(buildSearchResponse(internalSearchResponse, failures, scrollId, searchContextId)); } - onPhaseEnd(); setCurrentPhase(null); } diff --git a/server/src/main/java/org/opensearch/action/search/SearchRequestOperationsListener.java b/server/src/main/java/org/opensearch/action/search/SearchRequestOperationsListener.java index 89d725b56bded..808da38648387 100644 --- a/server/src/main/java/org/opensearch/action/search/SearchRequestOperationsListener.java +++ b/server/src/main/java/org/opensearch/action/search/SearchRequestOperationsListener.java @@ -26,6 +26,10 @@ public interface SearchRequestOperationsListener { void onPhaseFailure(SearchPhaseContext context); + default void onRequestStart(long startTimeNanos) {}; + + default void onRequestEnd(SearchPhaseContext context) {}; + /** * Holder of Composite Listeners * @@ -73,5 +77,27 @@ public void onPhaseFailure(SearchPhaseContext context) { } } } + + @Override + public void onRequestStart(long startTimeNanos) { + for (SearchRequestOperationsListener listener : listeners) { + try { + listener.onRequestStart(startTimeNanos); + } catch (Exception e) { + logger.warn(() -> new ParameterizedMessage("onRequestStart listener [{}] failed", listener), e); + } + } + } + + @Override + public void onRequestEnd(SearchPhaseContext context) { + for (SearchRequestOperationsListener listener : listeners) { + try { + listener.onRequestEnd(context); + } catch (Exception e) { + logger.warn(() -> new ParameterizedMessage("onRequestEnd listener [{}] failed", listener), e); + } + } + } } } diff --git a/server/src/main/java/org/opensearch/action/search/SearchRequestSlowLog.java b/server/src/main/java/org/opensearch/action/search/SearchRequestSlowLog.java new file mode 100644 index 0000000000000..6ad1f4b443c46 --- /dev/null +++ b/server/src/main/java/org/opensearch/action/search/SearchRequestSlowLog.java @@ -0,0 +1,269 @@ +/* + * SPDX-License-Identifier: Apache-2.0 + * + * The OpenSearch Contributors require contributions made to + * this file be licensed under the Apache-2.0 license or a + * compatible open source license. + */ + +/* + * 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. + */ + +/* + * Modifications Copyright OpenSearch Contributors. See + * GitHub history for details. + */ + +package org.opensearch.action.search; + +import com.fasterxml.jackson.core.io.JsonStringEncoder; + +import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.Logger; +import org.opensearch.cluster.service.ClusterService; +import org.opensearch.common.logging.Loggers; +import org.opensearch.common.logging.OpenSearchLogMessage; +import org.opensearch.common.settings.Setting; +import org.opensearch.common.unit.TimeValue; +import org.opensearch.core.xcontent.ToXContent; +import org.opensearch.index.SlowLogLevel; +import org.opensearch.tasks.Task; + +import java.nio.charset.Charset; +import java.util.Collections; +import java.util.HashMap; +import java.util.Map; +import java.util.concurrent.TimeUnit; + +/** + * The search time slow log implementation + * + * @opensearch.internal + */ +public final class SearchRequestSlowLog implements SearchRequestOperationsListener { + private static final Charset UTF_8 = Charset.forName("UTF-8"); + + private long absoluteStartNanos; + + private long warnThreshold; + private long infoThreshold; + private long debugThreshold; + private long traceThreshold; + Map phaseTookMap; + + private final Logger logger; + + static final String CLUSTER_SEARCH_REQUEST_SLOWLOG_PREFIX = "cluster.search.request.slowlog.threshold"; + + public static final Setting CLUSTER_SEARCH_REQUEST_SLOWLOG_THRESHOLD_WARN_SETTING = Setting.timeSetting( + CLUSTER_SEARCH_REQUEST_SLOWLOG_PREFIX + ".warn", + TimeValue.timeValueNanos(-1), + TimeValue.timeValueMillis(-1), + Setting.Property.Dynamic, + Setting.Property.NodeScope + ); + public static final Setting CLUSTER_SEARCH_REQUEST_SLOWLOG_THRESHOLD_INFO_SETTING = Setting.timeSetting( + CLUSTER_SEARCH_REQUEST_SLOWLOG_PREFIX + ".info", + TimeValue.timeValueNanos(-1), + TimeValue.timeValueMillis(-1), + Setting.Property.Dynamic, + Setting.Property.NodeScope + ); + public static final Setting CLUSTER_SEARCH_REQUEST_SLOWLOG_THRESHOLD_DEBUG_SETTING = Setting.timeSetting( + CLUSTER_SEARCH_REQUEST_SLOWLOG_PREFIX + ".debug", + TimeValue.timeValueNanos(-1), + TimeValue.timeValueMillis(-1), + Setting.Property.Dynamic, + Setting.Property.NodeScope + ); + public static final Setting CLUSTER_SEARCH_REQUEST_SLOWLOG_THRESHOLD_TRACE_SETTING = Setting.timeSetting( + CLUSTER_SEARCH_REQUEST_SLOWLOG_PREFIX + ".trace", + TimeValue.timeValueNanos(-1), + TimeValue.timeValueMillis(-1), + Setting.Property.Dynamic, + Setting.Property.NodeScope + ); + public static final Setting CLUSTER_SEARCH_REQUEST_SLOWLOG_LEVEL = new Setting<>( + CLUSTER_SEARCH_REQUEST_SLOWLOG_PREFIX + ".level", + SlowLogLevel.TRACE.name(), + SlowLogLevel::parse, + Setting.Property.Dynamic, + Setting.Property.NodeScope + ); + + private static final ToXContent.Params FORMAT_PARAMS = new ToXContent.MapParams(Collections.singletonMap("pretty", "false")); + private SlowLogLevel level; + + public SearchRequestSlowLog(ClusterService clusterService) { + this.logger = LogManager.getLogger(CLUSTER_SEARCH_REQUEST_SLOWLOG_PREFIX + ".SearchRequestSlowLog"); + Loggers.setLevel(this.logger, SlowLogLevel.TRACE.name()); + + this.warnThreshold = clusterService.getClusterSettings().get(CLUSTER_SEARCH_REQUEST_SLOWLOG_THRESHOLD_WARN_SETTING).nanos(); + clusterService.getClusterSettings() + .addSettingsUpdateConsumer(CLUSTER_SEARCH_REQUEST_SLOWLOG_THRESHOLD_WARN_SETTING, this::setWarnThreshold); + this.infoThreshold = clusterService.getClusterSettings().get(CLUSTER_SEARCH_REQUEST_SLOWLOG_THRESHOLD_INFO_SETTING).nanos(); + clusterService.getClusterSettings() + .addSettingsUpdateConsumer(CLUSTER_SEARCH_REQUEST_SLOWLOG_THRESHOLD_INFO_SETTING, this::setInfoThreshold); + this.debugThreshold = clusterService.getClusterSettings().get(CLUSTER_SEARCH_REQUEST_SLOWLOG_THRESHOLD_DEBUG_SETTING).nanos(); + clusterService.getClusterSettings() + .addSettingsUpdateConsumer(CLUSTER_SEARCH_REQUEST_SLOWLOG_THRESHOLD_DEBUG_SETTING, this::setDebugThreshold); + this.traceThreshold = clusterService.getClusterSettings().get(CLUSTER_SEARCH_REQUEST_SLOWLOG_THRESHOLD_TRACE_SETTING).nanos(); + clusterService.getClusterSettings() + .addSettingsUpdateConsumer(CLUSTER_SEARCH_REQUEST_SLOWLOG_THRESHOLD_TRACE_SETTING, this::setTraceThreshold); + + this.level = clusterService.getClusterSettings().get(CLUSTER_SEARCH_REQUEST_SLOWLOG_LEVEL); + clusterService.getClusterSettings().addSettingsUpdateConsumer(CLUSTER_SEARCH_REQUEST_SLOWLOG_LEVEL, this::setLevel); + + this.phaseTookMap = new HashMap<>(); + } + + private void setLevel(SlowLogLevel level) { + this.level = level; + } + + @Override + public void onPhaseStart(SearchPhaseContext context) {} + + @Override + public void onPhaseEnd(SearchPhaseContext context) { + long tookInNanos = System.nanoTime() - context.getCurrentPhase().getStartTimeInNanos(); + phaseTookMap.put(context.getCurrentPhase().getName(), TimeUnit.NANOSECONDS.toMillis(tookInNanos)); + } + + @Override + public void onPhaseFailure(SearchPhaseContext context) {} + + @Override + public void onRequestStart(long startTimeNanos) { + this.absoluteStartNanos = startTimeNanos; + } + + private long getRequestStart() { + return absoluteStartNanos; + } + + @Override + public void onRequestEnd(SearchPhaseContext context) { + long tookInNanos = System.nanoTime() - absoluteStartNanos; + + if (warnThreshold >= 0 && tookInNanos > warnThreshold && level.isLevelEnabledFor(SlowLogLevel.WARN)) { + logger.warn(new SearchRequestSlowLogMessage(context, tookInNanos, phaseTookMap)); + } else if (infoThreshold >= 0 && tookInNanos > infoThreshold && level.isLevelEnabledFor(SlowLogLevel.INFO)) { + logger.info(new SearchRequestSlowLogMessage(context, tookInNanos, phaseTookMap)); + } else if (debugThreshold >= 0 && tookInNanos > debugThreshold && level.isLevelEnabledFor(SlowLogLevel.DEBUG)) { + logger.debug(new SearchRequestSlowLogMessage(context, tookInNanos, phaseTookMap)); + } else if (traceThreshold >= 0 && tookInNanos > traceThreshold && level.isLevelEnabledFor(SlowLogLevel.TRACE)) { + logger.trace(new SearchRequestSlowLogMessage(context, tookInNanos, phaseTookMap)); + } + }; + + /** + * Search slow log message + * + * @opensearch.internal + */ + static final class SearchRequestSlowLogMessage extends OpenSearchLogMessage { + + SearchRequestSlowLogMessage(SearchPhaseContext context, long tookInNanos, Map phaseTookMap) { + super(prepareMap(context, tookInNanos, phaseTookMap), message(context, tookInNanos, phaseTookMap)); + } + + private static Map prepareMap(SearchPhaseContext context, long tookInNanos, Map phaseTookMap) { + Map messageFields = new HashMap<>(); + messageFields.put("took", TimeValue.timeValueNanos(tookInNanos)); + messageFields.put("took_millis", TimeUnit.NANOSECONDS.toMillis(tookInNanos)); + messageFields.put("phase_took", phaseTookMap); + messageFields.put("search_type", context.getRequest().searchType()); + messageFields.put("total_shards", context.getNumShards()); + + if (context.getRequest().source() != null) { + String source = escapeJson(context.getRequest().source().toString(FORMAT_PARAMS)); + + 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(SearchPhaseContext context, long tookInNanos, Map phaseTookMap) { + StringBuilder sb = new StringBuilder(); + sb.append("took[").append(TimeValue.timeValueNanos(tookInNanos)).append("], "); + sb.append("took_millis[").append(TimeUnit.NANOSECONDS.toMillis(tookInNanos)).append("], "); + sb.append("phase_took_millis[").append(phaseTookMap.toString()).append("], "); + sb.append("search_type[").append(context.getRequest().searchType()).append("], "); + sb.append("total_shards[").append(context.getNumShards()).append("], "); + if (context.getRequest().source() != null) { + sb.append("source[").append(context.getRequest().source().toString(FORMAT_PARAMS)).append("], "); + } else { + sb.append("source[], "); + } + if (context.getTask().getHeader(Task.X_OPAQUE_ID) != null) { + sb.append("id[").append(context.getTask().getHeader(Task.X_OPAQUE_ID)).append("], "); + } else { + sb.append("id[]"); + } + return sb.toString(); + } + + private static String escapeJson(String text) { + byte[] sourceEscaped = JsonStringEncoder.getInstance().quoteAsUTF8(text); + return new String(sourceEscaped, UTF_8); + } + } + + private void setWarnThreshold(TimeValue warnThreshold) { + this.warnThreshold = warnThreshold.nanos(); + } + + private void setInfoThreshold(TimeValue infoThreshold) { + this.infoThreshold = infoThreshold.nanos(); + } + + private void setDebugThreshold(TimeValue debugThreshold) { + this.debugThreshold = debugThreshold.nanos(); + } + + private void setTraceThreshold(TimeValue traceThreshold) { + this.traceThreshold = traceThreshold.nanos(); + } + + protected long getWarnThreshold() { + return warnThreshold; + } + + protected long getInfoThreshold() { + return infoThreshold; + } + + protected long getDebugThreshold() { + return debugThreshold; + } + + protected long getTraceThreshold() { + return traceThreshold; + } + + SlowLogLevel getLevel() { + return level; + } +} diff --git a/server/src/main/java/org/opensearch/action/search/TransportSearchAction.java b/server/src/main/java/org/opensearch/action/search/TransportSearchAction.java index 284f71bd9da62..f34fec342ecfb 100644 --- a/server/src/main/java/org/opensearch/action/search/TransportSearchAction.java +++ b/server/src/main/java/org/opensearch/action/search/TransportSearchAction.java @@ -475,6 +475,7 @@ private void executeRequest( } else { searchRequestOperationsListener = null; } + searchRequestOperationsListener.onRequestStart(relativeStartNanos); PipelinedRequest searchRequest; ActionListener listener; @@ -1216,6 +1217,8 @@ private List createSearchListenerList(SearchReq searchListenersList.add(timeProvider); } + searchListenersList.add(new SearchRequestSlowLog(clusterService)); + return searchListenersList; } diff --git a/server/src/main/java/org/opensearch/common/settings/ClusterSettings.java b/server/src/main/java/org/opensearch/common/settings/ClusterSettings.java index bb0910c4e5f9c..1eaf1fbac0404 100644 --- a/server/src/main/java/org/opensearch/common/settings/ClusterSettings.java +++ b/server/src/main/java/org/opensearch/common/settings/ClusterSettings.java @@ -35,6 +35,7 @@ import org.opensearch.action.admin.cluster.configuration.TransportAddVotingConfigExclusionsAction; import org.opensearch.action.admin.indices.close.TransportCloseIndexAction; import org.opensearch.action.search.CreatePitController; +import org.opensearch.action.search.SearchRequestSlowLog; import org.opensearch.action.search.TransportSearchAction; import org.opensearch.action.support.AutoCreateIndex; import org.opensearch.action.support.DestructiveOperations; @@ -677,6 +678,13 @@ public void apply(Settings value, Settings current, Settings previous) { TaskCancellationMonitoringSettings.IS_ENABLED_SETTING, TaskCancellationMonitoringSettings.DURATION_MILLIS_SETTING, + // Search request slow log settings + SearchRequestSlowLog.CLUSTER_SEARCH_REQUEST_SLOWLOG_THRESHOLD_WARN_SETTING, + SearchRequestSlowLog.CLUSTER_SEARCH_REQUEST_SLOWLOG_THRESHOLD_INFO_SETTING, + SearchRequestSlowLog.CLUSTER_SEARCH_REQUEST_SLOWLOG_THRESHOLD_DEBUG_SETTING, + SearchRequestSlowLog.CLUSTER_SEARCH_REQUEST_SLOWLOG_THRESHOLD_TRACE_SETTING, + SearchRequestSlowLog.CLUSTER_SEARCH_REQUEST_SLOWLOG_LEVEL, + // Remote cluster state settings RemoteClusterStateService.REMOTE_CLUSTER_STATE_ENABLED_SETTING, RemoteStoreNodeService.REMOTE_STORE_COMPATIBILITY_MODE_SETTING, diff --git a/server/src/main/java/org/opensearch/index/SlowLogLevel.java b/server/src/main/java/org/opensearch/index/SlowLogLevel.java index 0a28edd59d491..aa9ec4713d16e 100644 --- a/server/src/main/java/org/opensearch/index/SlowLogLevel.java +++ b/server/src/main/java/org/opensearch/index/SlowLogLevel.java @@ -54,7 +54,7 @@ public static SlowLogLevel parse(String level) { return valueOf(level.toUpperCase(Locale.ROOT)); } - boolean isLevelEnabledFor(SlowLogLevel levelToBeUsed) { + public boolean isLevelEnabledFor(SlowLogLevel levelToBeUsed) { // example: this.info(2) tries to log with levelToBeUsed.warn(3) - should allow return this.specificity <= levelToBeUsed.specificity; } diff --git a/server/src/test/java/org/opensearch/action/search/MockSearchPhaseContext.java b/server/src/test/java/org/opensearch/action/search/MockSearchPhaseContext.java index b5e1050b968ee..04a00a09dcbc4 100644 --- a/server/src/test/java/org/opensearch/action/search/MockSearchPhaseContext.java +++ b/server/src/test/java/org/opensearch/action/search/MockSearchPhaseContext.java @@ -65,11 +65,16 @@ public final class MockSearchPhaseContext implements SearchPhaseContext { final List failures = Collections.synchronizedList(new ArrayList<>()); SearchTransportService searchTransport; final Set releasedSearchContexts = new HashSet<>(); - final SearchRequest searchRequest = new SearchRequest(); + final SearchRequest searchRequest; final AtomicReference searchResponse = new AtomicReference<>(); public MockSearchPhaseContext(int numShards) { + this(numShards, new SearchRequest()); + } + + public MockSearchPhaseContext(int numShards, SearchRequest searchRequest) { this.numShards = numShards; + this.searchRequest = searchRequest; numSuccess = new AtomicInteger(numShards); } diff --git a/server/src/test/java/org/opensearch/action/search/SearchRequestSlowLogTests.java b/server/src/test/java/org/opensearch/action/search/SearchRequestSlowLogTests.java new file mode 100644 index 0000000000000..0d6bd5e99dba6 --- /dev/null +++ b/server/src/test/java/org/opensearch/action/search/SearchRequestSlowLogTests.java @@ -0,0 +1,253 @@ +/* + * SPDX-License-Identifier: Apache-2.0 + * + * The OpenSearch Contributors require contributions made to + * this file be licensed under the Apache-2.0 license or a + * compatible open source license. + */ + +/* + * 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. + */ + +/* + * Modifications Copyright OpenSearch Contributors. See + * GitHub history for details. + */ + +package org.opensearch.action.search; + +import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.Logger; +import org.apache.logging.log4j.core.LoggerContext; +import org.opensearch.cluster.service.ClusterService; +import org.opensearch.common.logging.Loggers; +import org.opensearch.common.logging.MockAppender; +import org.opensearch.common.settings.ClusterSettings; +import org.opensearch.common.settings.Settings; +import org.opensearch.common.unit.TimeValue; +import org.opensearch.index.SlowLogLevel; +import org.opensearch.index.query.QueryBuilders; +import org.opensearch.search.builder.SearchSourceBuilder; +import org.opensearch.test.OpenSearchSingleNodeTestCase; +import org.junit.AfterClass; +import org.junit.BeforeClass; + +import java.io.IOException; +import java.util.HashMap; +import java.util.Map; + +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; +import static org.hamcrest.Matchers.startsWith; + +public class SearchRequestSlowLogTests extends OpenSearchSingleNodeTestCase { + static MockAppender appender; + static Logger logger = LogManager.getLogger(SearchRequestSlowLog.CLUSTER_SEARCH_REQUEST_SLOWLOG_PREFIX + ".SearchRequestSlowLog"); + + @BeforeClass + public static void init() throws IllegalAccessException { + appender = new MockAppender("trace_appender"); + appender.start(); + Loggers.addAppender(logger, appender); + } + + @AfterClass + public static void cleanup() { + Loggers.removeAppender(logger, appender); + appender.stop(); + } + + public void testMultipleSlowLoggersUseSingleLog4jLogger() { + LoggerContext context = (LoggerContext) LogManager.getContext(false); + + SearchPhaseContext searchPhaseContext1 = new MockSearchPhaseContext(1); + ClusterService clusterService1 = new ClusterService( + Settings.EMPTY, + new ClusterSettings(Settings.EMPTY, ClusterSettings.BUILT_IN_CLUSTER_SETTINGS), + null + ); + SearchRequestSlowLog searchRequestSlowLog1 = new SearchRequestSlowLog(clusterService1); + int numberOfLoggersBefore = context.getLoggers().size(); + + SearchPhaseContext searchPhaseContext2 = new MockSearchPhaseContext(1); + ClusterService clusterService2 = new ClusterService( + Settings.EMPTY, + new ClusterSettings(Settings.EMPTY, ClusterSettings.BUILT_IN_CLUSTER_SETTINGS), + null + ); + SearchRequestSlowLog searchRequestSlowLog2 = new SearchRequestSlowLog(clusterService2); + + int numberOfLoggersAfter = context.getLoggers().size(); + assertThat(numberOfLoggersAfter, equalTo(numberOfLoggersBefore)); + } + + public void testSearchRequestSlowLogHasJsonFields() throws IOException { + SearchSourceBuilder source = SearchSourceBuilder.searchSource().query(QueryBuilders.matchAllQuery()); + SearchRequest searchRequest = new SearchRequest().source(source); + SearchPhaseContext searchPhaseContext = new MockSearchPhaseContext(1, searchRequest); + Map phaseTookMap = new HashMap<>(); + phaseTookMap.put(SearchPhaseName.FETCH.getName(), 10L); + phaseTookMap.put(SearchPhaseName.QUERY.getName(), 50L); + phaseTookMap.put(SearchPhaseName.EXPAND.getName(), 5L); + SearchRequestSlowLog.SearchRequestSlowLogMessage p = new SearchRequestSlowLog.SearchRequestSlowLogMessage( + searchPhaseContext, + 10, + phaseTookMap + ); + + assertThat(p.getValueFor("took"), equalTo("10nanos")); + assertThat(p.getValueFor("took_millis"), equalTo("0")); + assertThat(p.getValueFor("phase_took"), equalTo(phaseTookMap.toString())); + assertThat(p.getValueFor("search_type"), equalTo("QUERY_THEN_FETCH")); + assertThat(p.getValueFor("total_shards"), equalTo("1")); + assertThat(p.getValueFor("source"), equalTo("{\\\"query\\\":{\\\"match_all\\\":{\\\"boost\\\":1.0}}}")); + assertThat(p.getValueFor("id"), equalTo(null)); + } + + public void testSearchRequestSlowLogSearchContextPrinterToLog() throws IOException { + SearchSourceBuilder source = SearchSourceBuilder.searchSource().query(QueryBuilders.matchAllQuery()); + SearchRequest searchRequest = new SearchRequest().source(source); + SearchPhaseContext searchPhaseContext = new MockSearchPhaseContext(1, searchRequest); + Map phaseTookMap = new HashMap<>(); + phaseTookMap.put(SearchPhaseName.FETCH.getName(), 10L); + phaseTookMap.put(SearchPhaseName.QUERY.getName(), 50L); + phaseTookMap.put(SearchPhaseName.EXPAND.getName(), 5L); + SearchRequestSlowLog.SearchRequestSlowLogMessage p = new SearchRequestSlowLog.SearchRequestSlowLogMessage( + searchPhaseContext, + 100000, + phaseTookMap + ); + + assertThat(p.getFormattedMessage(), startsWith("took[100micros]")); + // Makes sure that output doesn't contain any new lines + assertThat(p.getFormattedMessage(), not(containsString("\n"))); + assertThat(p.getFormattedMessage(), endsWith("id[]")); + } + + public void testLevelSettingWarn() { + SlowLogLevel level = SlowLogLevel.WARN; + Settings.Builder settingsBuilder = Settings.builder(); + settingsBuilder.put(SearchRequestSlowLog.CLUSTER_SEARCH_REQUEST_SLOWLOG_LEVEL.getKey(), level); + Settings settings = settingsBuilder.build(); + ClusterSettings clusterSettings = new ClusterSettings(settings, ClusterSettings.BUILT_IN_CLUSTER_SETTINGS); + ClusterService clusterService = new ClusterService(settings, clusterSettings, null); + SearchRequestSlowLog searchRequestSlowLog = new SearchRequestSlowLog(clusterService); + assertEquals(level, searchRequestSlowLog.getLevel()); + } + + public void testLevelSettingDebug() { + SlowLogLevel level = SlowLogLevel.DEBUG; + Settings.Builder settingsBuilder = Settings.builder(); + settingsBuilder.put(SearchRequestSlowLog.CLUSTER_SEARCH_REQUEST_SLOWLOG_LEVEL.getKey(), level); + Settings settings = settingsBuilder.build(); + ClusterSettings clusterSettings = new ClusterSettings(settings, ClusterSettings.BUILT_IN_CLUSTER_SETTINGS); + ClusterService clusterService = new ClusterService(settings, clusterSettings, null); + SearchRequestSlowLog searchRequestSlowLog = new SearchRequestSlowLog(clusterService); + assertEquals(level, searchRequestSlowLog.getLevel()); + } + + public void testLevelSettingFail() { + String level = "NOT A LEVEL"; + Settings.Builder settingsBuilder = Settings.builder(); + settingsBuilder.put(SearchRequestSlowLog.CLUSTER_SEARCH_REQUEST_SLOWLOG_LEVEL.getKey(), level); + Settings settings = settingsBuilder.build(); + ClusterSettings clusterSettings = new ClusterSettings(settings, ClusterSettings.BUILT_IN_CLUSTER_SETTINGS); + ClusterService clusterService = new ClusterService(settings, clusterSettings, null); + + try { + new SearchRequestSlowLog(clusterService); + fail(); + } catch (IllegalArgumentException ex) { + final String expected = "No enum constant org.opensearch.index.SlowLogLevel.NOT A LEVEL"; + assertThat(ex, hasToString(containsString(expected))); + assertThat(ex, instanceOf(IllegalArgumentException.class)); + } + } + + public void testSetThresholds() { + Settings.Builder settingsBuilder = Settings.builder(); + settingsBuilder.put(SearchRequestSlowLog.CLUSTER_SEARCH_REQUEST_SLOWLOG_THRESHOLD_WARN_SETTING.getKey(), "400ms"); + settingsBuilder.put(SearchRequestSlowLog.CLUSTER_SEARCH_REQUEST_SLOWLOG_THRESHOLD_INFO_SETTING.getKey(), "300ms"); + settingsBuilder.put(SearchRequestSlowLog.CLUSTER_SEARCH_REQUEST_SLOWLOG_THRESHOLD_DEBUG_SETTING.getKey(), "200ms"); + settingsBuilder.put(SearchRequestSlowLog.CLUSTER_SEARCH_REQUEST_SLOWLOG_THRESHOLD_TRACE_SETTING.getKey(), "100ms"); + Settings settings = settingsBuilder.build(); + ClusterSettings clusterSettings = new ClusterSettings(settings, ClusterSettings.BUILT_IN_CLUSTER_SETTINGS); + ClusterService clusterService = new ClusterService(settings, clusterSettings, null); + SearchRequestSlowLog searchRequestSlowLog = new SearchRequestSlowLog(clusterService); + assertEquals(TimeValue.timeValueMillis(400).nanos(), searchRequestSlowLog.getWarnThreshold()); + assertEquals(TimeValue.timeValueMillis(300).nanos(), searchRequestSlowLog.getInfoThreshold()); + assertEquals(TimeValue.timeValueMillis(200).nanos(), searchRequestSlowLog.getDebugThreshold()); + assertEquals(TimeValue.timeValueMillis(100).nanos(), searchRequestSlowLog.getTraceThreshold()); + assertEquals(SlowLogLevel.TRACE, searchRequestSlowLog.getLevel()); + } + + public void testSetThresholdsUnits() { + Settings.Builder settingsBuilder = Settings.builder(); + settingsBuilder.put(SearchRequestSlowLog.CLUSTER_SEARCH_REQUEST_SLOWLOG_THRESHOLD_WARN_SETTING.getKey(), "400s"); + settingsBuilder.put(SearchRequestSlowLog.CLUSTER_SEARCH_REQUEST_SLOWLOG_THRESHOLD_INFO_SETTING.getKey(), "300ms"); + settingsBuilder.put(SearchRequestSlowLog.CLUSTER_SEARCH_REQUEST_SLOWLOG_THRESHOLD_DEBUG_SETTING.getKey(), "200micros"); + settingsBuilder.put(SearchRequestSlowLog.CLUSTER_SEARCH_REQUEST_SLOWLOG_THRESHOLD_TRACE_SETTING.getKey(), "100nanos"); + Settings settings = settingsBuilder.build(); + ClusterSettings clusterSettings = new ClusterSettings(settings, ClusterSettings.BUILT_IN_CLUSTER_SETTINGS); + ClusterService clusterService = new ClusterService(settings, clusterSettings, null); + SearchRequestSlowLog searchRequestSlowLog = new SearchRequestSlowLog(clusterService); + assertEquals(TimeValue.timeValueSeconds(400).nanos(), searchRequestSlowLog.getWarnThreshold()); + assertEquals(TimeValue.timeValueMillis(300).nanos(), searchRequestSlowLog.getInfoThreshold()); + assertEquals(TimeValue.timeValueNanos(200000).nanos(), searchRequestSlowLog.getDebugThreshold()); + assertEquals(TimeValue.timeValueNanos(100).nanos(), searchRequestSlowLog.getTraceThreshold()); + assertEquals(SlowLogLevel.TRACE, searchRequestSlowLog.getLevel()); + } + + public void testSetThresholdsDefaults() { + Settings.Builder settingsBuilder = Settings.builder(); + settingsBuilder.put(SearchRequestSlowLog.CLUSTER_SEARCH_REQUEST_SLOWLOG_THRESHOLD_WARN_SETTING.getKey(), "400ms"); + settingsBuilder.put(SearchRequestSlowLog.CLUSTER_SEARCH_REQUEST_SLOWLOG_THRESHOLD_DEBUG_SETTING.getKey(), "200ms"); + Settings settings = settingsBuilder.build(); + ClusterSettings clusterSettings = new ClusterSettings(settings, ClusterSettings.BUILT_IN_CLUSTER_SETTINGS); + ClusterService clusterService = new ClusterService(settings, clusterSettings, null); + SearchRequestSlowLog searchRequestSlowLog = new SearchRequestSlowLog(clusterService); + assertEquals(TimeValue.timeValueMillis(400).nanos(), searchRequestSlowLog.getWarnThreshold()); + assertEquals(TimeValue.timeValueMillis(-1).nanos(), searchRequestSlowLog.getInfoThreshold()); + assertEquals(TimeValue.timeValueMillis(200).nanos(), searchRequestSlowLog.getDebugThreshold()); + assertEquals(TimeValue.timeValueMillis(-1).nanos(), searchRequestSlowLog.getTraceThreshold()); + assertEquals(SlowLogLevel.TRACE, searchRequestSlowLog.getLevel()); + } + + public void testSetThresholdsError() { + Settings.Builder settingsBuilder = Settings.builder(); + settingsBuilder.put(SearchRequestSlowLog.CLUSTER_SEARCH_REQUEST_SLOWLOG_THRESHOLD_WARN_SETTING.getKey(), "NOT A TIME VALUE"); + Settings settings = settingsBuilder.build(); + ClusterSettings clusterSettings = new ClusterSettings(settings, ClusterSettings.BUILT_IN_CLUSTER_SETTINGS); + ClusterService clusterService = new ClusterService(settings, clusterSettings, null); + + try { + new SearchRequestSlowLog(clusterService); + fail(); + } catch (IllegalArgumentException ex) { + final String expected = + "failed to parse setting [cluster.search.request.slowlog.threshold.warn] with value [NOT A TIME VALUE] as a time value"; + assertThat(ex, hasToString(containsString(expected))); + assertThat(ex, instanceOf(IllegalArgumentException.class)); + } + } +}