diff --git a/distribution/src/config/log4j2.properties b/distribution/src/config/log4j2.properties index 5551b08df8212..d040afae82e53 100644 --- a/distribution/src/config/log4j2.properties +++ b/distribution/src/config/log4j2.properties @@ -113,7 +113,7 @@ logger.deprecation.appenderRef.deprecation_rolling_old.ref = deprecation_rolling logger.deprecation.appenderRef.header_warning.ref = header_warning logger.deprecation.additivity = false -######## Search Request slowlog JSON #################### +######## Search Request Slowlog JSON #################### appender.search_request_slowlog_json_appender.type = RollingFile appender.search_request_slowlog_json_appender.name = search_request_slowlog_json_appender appender.search_request_slowlog_json_appender.fileName = ${sys:opensearch.logs.base_path}${sys:file.separator}${sys:opensearch.logs\ @@ -121,7 +121,7 @@ appender.search_request_slowlog_json_appender.fileName = ${sys:opensearch.logs.b appender.search_request_slowlog_json_appender.filePermissions = rw-r----- appender.search_request_slowlog_json_appender.layout.type = OpenSearchJsonLayout appender.search_request_slowlog_json_appender.layout.type_name = search_request_slowlog -appender.search_request_slowlog_json_appender.layout.opensearchmessagefields=message,took,took_millis,phase_took,search_type,total_shards,source,id +appender.search_request_slowlog_json_appender.layout.opensearchmessagefields=message,took,took_millis,phase_took,total_hits,search_type,shards,source,id appender.search_request_slowlog_json_appender.filePattern = ${sys:opensearch.logs.base_path}${sys:file.separator}${sys:opensearch.logs\ .cluster_name}_index_search_slowlog-%i.json.gz @@ -131,7 +131,7 @@ appender.search_request_slowlog_json_appender.policies.size.size = 1GB appender.search_request_slowlog_json_appender.strategy.type = DefaultRolloverStrategy appender.search_request_slowlog_json_appender.strategy.max = 4 ################################################# -######## Search slowlog - old style pattern #### +######## Search Request Slowlog Log File - old style pattern #### appender.search_request_slowlog_log_appender.type = RollingFile appender.search_request_slowlog_log_appender.name = search_request_slowlog_log_appender appender.search_request_slowlog_log_appender.fileName = ${sys:opensearch.logs.base_path}${sys:file.separator}${sys:opensearch.logs.cluster_name}\ 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 87918e0128798..bec7d010f0c22 100644 --- a/server/src/main/java/org/opensearch/action/search/AbstractSearchAsyncAction.java +++ b/server/src/main/java/org/opensearch/action/search/AbstractSearchAsyncAction.java @@ -436,20 +436,20 @@ public final void executeNextPhase(SearchPhase currentPhase, SearchPhase nextPha } private void onPhaseEnd(SearchRequestContext searchRequestContext) { - this.searchRequestOperationsListener.ifPresent(searchRequestOperations -> { - searchRequestOperations.onPhaseEnd(this, searchRequestContext); - }); + this.searchRequestOperationsListener.ifPresent( + searchRequestOperations -> searchRequestOperations.onPhaseEnd(this, searchRequestContext) + ); } private void onPhaseStart(SearchPhase phase) { setCurrentPhase(phase); - this.searchRequestOperationsListener.ifPresent(searchRequestOperations -> { searchRequestOperations.onPhaseStart(this); }); + this.searchRequestOperationsListener.ifPresent(searchRequestOperations -> searchRequestOperations.onPhaseStart(this)); } private void onRequestEnd(SearchRequestContext searchRequestContext) { - this.searchRequestOperationsListener.ifPresent(searchRequestOperations -> { - searchRequestOperations.onRequestEnd(this, searchRequestContext); - }); + this.searchRequestOperationsListener.ifPresent( + searchRequestOperations -> searchRequestOperations.onRequestEnd(this, searchRequestContext) + ); } private void executePhase(SearchPhase phase) { @@ -707,6 +707,19 @@ public void sendSearchResponse(InternalSearchResponse internalSearchResponse, At searchContextId = null; } } + searchRequestContext.setTotalHits(internalSearchResponse.hits().getTotalHits()); + searchRequestContext.setShardStats( + Map.of( + "total", + results.getNumShards(), + "successful", + successfulOps.get(), + "skipped", + skippedOps.get(), + "failed", + failures.length + ) + ); onPhaseEnd(searchRequestContext); onRequestEnd(searchRequestContext); listener.onResponse(buildSearchResponse(internalSearchResponse, failures, scrollId, searchContextId)); diff --git a/server/src/main/java/org/opensearch/action/search/SearchRequestContext.java b/server/src/main/java/org/opensearch/action/search/SearchRequestContext.java index afabf0dec6dfd..f931e1f123bee 100644 --- a/server/src/main/java/org/opensearch/action/search/SearchRequestContext.java +++ b/server/src/main/java/org/opensearch/action/search/SearchRequestContext.java @@ -8,6 +8,8 @@ package org.opensearch.action.search; +import org.apache.lucene.search.TotalHits; + import java.util.HashMap; import java.util.Map; @@ -19,9 +21,12 @@ public class SearchRequestContext { private long absoluteStartNanos; private final Map phaseTookMap; + private TotalHits totalHits; + private Map shardStats; public SearchRequestContext() { this.phaseTookMap = new HashMap<>(); + this.totalHits = null; } protected void updatePhaseTookMap(String phaseName, Long tookTime) { @@ -40,4 +45,43 @@ protected long absoluteStartNanos() { return absoluteStartNanos; } + protected void setTotalHits(TotalHits totalHits) { + this.totalHits = totalHits; + } + + protected TotalHits totalHits() { + return totalHits; + } + + protected void setShardStats(Map shardStats) { + this.shardStats = shardStats; + } + + protected Map shardStats() { + return shardStats; + } + + public final String SEARCH_REQUEST_SLOWLOG_SHARD_TOTAL = "total"; + public final String SEARCH_REQUEST_SLOWLOG_SHARD_SUCCESSFUL = "successful"; + public final String SEARCH_REQUEST_SLOWLOG_SHARD_SKIPPED = "skipped"; + public final String SEARCH_REQUEST_SLOWLOG_SHARD_FAILED = "failed"; + + protected String formattedShardStats() { + if (shardStats != null) { + return String.format( + "{%s: %s, %s: %s, %s: %s, %s: %s}", + SEARCH_REQUEST_SLOWLOG_SHARD_TOTAL, + shardStats.get(SEARCH_REQUEST_SLOWLOG_SHARD_TOTAL), + SEARCH_REQUEST_SLOWLOG_SHARD_SUCCESSFUL, + shardStats.get(SEARCH_REQUEST_SLOWLOG_SHARD_SUCCESSFUL), + SEARCH_REQUEST_SLOWLOG_SHARD_SKIPPED, + shardStats.get(SEARCH_REQUEST_SLOWLOG_SHARD_SKIPPED), + SEARCH_REQUEST_SLOWLOG_SHARD_FAILED, + shardStats.get(SEARCH_REQUEST_SLOWLOG_SHARD_FAILED) + ); + } else { + return "{}"; + } + + } } diff --git a/server/src/main/java/org/opensearch/action/search/SearchRequestSlowLog.java b/server/src/main/java/org/opensearch/action/search/SearchRequestSlowLog.java index ab4c4bb850343..491bbedf86086 100644 --- a/server/src/main/java/org/opensearch/action/search/SearchRequestSlowLog.java +++ b/server/src/main/java/org/opensearch/action/search/SearchRequestSlowLog.java @@ -151,13 +151,13 @@ public void onRequestEnd(SearchPhaseContext context, SearchRequestContext search long tookInNanos = System.nanoTime() - searchRequestContext.absoluteStartNanos(); if (warnThreshold >= 0 && tookInNanos > warnThreshold && level.isLevelEnabledFor(SlowLogLevel.WARN)) { - logger.warn(new SearchRequestSlowLogMessage(context, tookInNanos, searchRequestContext.phaseTookMap())); + logger.warn(new SearchRequestSlowLogMessage(context, tookInNanos, searchRequestContext)); } else if (infoThreshold >= 0 && tookInNanos > infoThreshold && level.isLevelEnabledFor(SlowLogLevel.INFO)) { - logger.info(new SearchRequestSlowLogMessage(context, tookInNanos, searchRequestContext.phaseTookMap())); + logger.info(new SearchRequestSlowLogMessage(context, tookInNanos, searchRequestContext)); } else if (debugThreshold >= 0 && tookInNanos > debugThreshold && level.isLevelEnabledFor(SlowLogLevel.DEBUG)) { - logger.debug(new SearchRequestSlowLogMessage(context, tookInNanos, searchRequestContext.phaseTookMap())); + logger.debug(new SearchRequestSlowLogMessage(context, tookInNanos, searchRequestContext)); } else if (traceThreshold >= 0 && tookInNanos > traceThreshold && level.isLevelEnabledFor(SlowLogLevel.TRACE)) { - logger.trace(new SearchRequestSlowLogMessage(context, tookInNanos, searchRequestContext.phaseTookMap())); + logger.trace(new SearchRequestSlowLogMessage(context, tookInNanos, searchRequestContext)); } } @@ -168,21 +168,29 @@ public void onRequestEnd(SearchPhaseContext context, SearchRequestContext search */ static final class SearchRequestSlowLogMessage extends OpenSearchLogMessage { - SearchRequestSlowLogMessage(SearchPhaseContext context, long tookInNanos, Map phaseTookMap) { - super(prepareMap(context, tookInNanos, phaseTookMap), message(context, tookInNanos, phaseTookMap)); + SearchRequestSlowLogMessage(SearchPhaseContext context, long tookInNanos, SearchRequestContext searchRequestContext) { + super(prepareMap(context, tookInNanos, searchRequestContext), message(context, tookInNanos, searchRequestContext)); } - private static Map prepareMap(SearchPhaseContext context, long tookInNanos, Map phaseTookMap) { + private static Map prepareMap( + SearchPhaseContext context, + long tookInNanos, + SearchRequestContext searchRequestContext + ) { final 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("phase_took", searchRequestContext.phaseTookMap().toString()); + if (searchRequestContext.totalHits() != null) { + messageFields.put("total_hits", searchRequestContext.totalHits()); + } else { + messageFields.put("total_hits", "-1"); + } messageFields.put("search_type", context.getRequest().searchType()); - messageFields.put("total_shards", context.getNumShards()); + messageFields.put("shards", searchRequestContext.formattedShardStats()); if (context.getRequest().source() != null) { String source = escapeJson(context.getRequest().source().toString(FORMAT_PARAMS)); - messageFields.put("source", source); } else { messageFields.put("source", "{}"); @@ -193,13 +201,18 @@ private static Map prepareMap(SearchPhaseContext context, long t } // Message will be used in plaintext logs - private static String message(SearchPhaseContext context, long tookInNanos, Map phaseTookMap) { + private static String message(SearchPhaseContext context, long tookInNanos, SearchRequestContext searchRequestContext) { final 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("phase_took_millis[").append(searchRequestContext.phaseTookMap().toString()).append("], "); + if (searchRequestContext.totalHits() != null) { + sb.append("total_hits[").append(searchRequestContext.totalHits()).append("], "); + } else { + sb.append("total_hits[-1]"); + } sb.append("search_type[").append(context.getRequest().searchType()).append("], "); - sb.append("total_shards[").append(context.getNumShards()).append("], "); + sb.append("shards[").append(searchRequestContext.formattedShardStats()).append("], "); if (context.getRequest().source() != null) { sb.append("source[").append(context.getRequest().source().toString(FORMAT_PARAMS)).append("], "); } else { 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 d47ebb6146847..e1439b0aba7d6 100644 --- a/server/src/main/java/org/opensearch/action/search/TransportSearchAction.java +++ b/server/src/main/java/org/opensearch/action/search/TransportSearchAction.java @@ -1257,7 +1257,12 @@ private List createSearchListenerList(SearchReq searchListenersList.add(timeProvider); } - searchListenersList.add(searchRequestSlowLog); + if (searchRequestSlowLog.getWarnThreshold() >= 0 + && searchRequestSlowLog.getInfoThreshold() >= 0 + && searchRequestSlowLog.getDebugThreshold() >= 0 + && searchRequestSlowLog.getTraceThreshold() >= 0) { + searchListenersList.add(searchRequestSlowLog); + } return searchListenersList; } diff --git a/server/src/test/java/org/opensearch/action/search/SearchRequestSlowLogTests.java b/server/src/test/java/org/opensearch/action/search/SearchRequestSlowLogTests.java index b76410e2b4ab0..7148c411a1199 100644 --- a/server/src/test/java/org/opensearch/action/search/SearchRequestSlowLogTests.java +++ b/server/src/test/java/org/opensearch/action/search/SearchRequestSlowLogTests.java @@ -35,6 +35,7 @@ import org.apache.logging.log4j.LogManager; import org.apache.logging.log4j.Logger; import org.apache.logging.log4j.core.LoggerContext; +import org.apache.lucene.search.TotalHits; import org.opensearch.cluster.service.ClusterService; import org.opensearch.common.logging.Loggers; import org.opensearch.common.logging.MockAppender; @@ -49,7 +50,6 @@ import org.junit.BeforeClass; import java.io.IOException; -import java.util.HashMap; import java.util.Map; import static org.hamcrest.Matchers.containsString; @@ -101,25 +101,75 @@ public void testMultipleSlowLoggersUseSingleLog4jLogger() { assertThat(numberOfLoggersAfter, equalTo(numberOfLoggersBefore)); } - public void testSearchRequestSlowLogHasJsonFields() throws IOException { + public void testSearchRequestSlowLogHasJsonFields_EmptySearchRequestContext() 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); + SearchRequestContext searchRequestContext = new SearchRequestContext(); SearchRequestSlowLog.SearchRequestSlowLogMessage p = new SearchRequestSlowLog.SearchRequestSlowLogMessage( searchPhaseContext, 10, - phaseTookMap + searchRequestContext ); assertThat(p.getValueFor("took"), equalTo("10nanos")); assertThat(p.getValueFor("took_millis"), equalTo("0")); - assertThat(p.getValueFor("phase_took"), equalTo(phaseTookMap.toString())); + assertThat(p.getValueFor("phase_took"), equalTo("{}")); + assertThat(p.getValueFor("total_hits"), equalTo("-1")); assertThat(p.getValueFor("search_type"), equalTo("QUERY_THEN_FETCH")); - assertThat(p.getValueFor("total_shards"), equalTo("1")); + assertThat(p.getValueFor("shards"), equalTo("{}")); + assertThat(p.getValueFor("source"), equalTo("{\\\"query\\\":{\\\"match_all\\\":{\\\"boost\\\":1.0}}}")); + assertThat(p.getValueFor("id"), equalTo(null)); + } + + public void testSearchRequestSlowLogHasJsonFields_NotEmptySearchRequestContext() throws IOException { + SearchSourceBuilder source = SearchSourceBuilder.searchSource().query(QueryBuilders.matchAllQuery()); + SearchRequest searchRequest = new SearchRequest().source(source); + SearchPhaseContext searchPhaseContext = new MockSearchPhaseContext(1, searchRequest); + SearchRequestContext searchRequestContext = new SearchRequestContext(); + searchRequestContext.updatePhaseTookMap(SearchPhaseName.FETCH.getName(), 10L); + searchRequestContext.updatePhaseTookMap(SearchPhaseName.QUERY.getName(), 50L); + searchRequestContext.updatePhaseTookMap(SearchPhaseName.EXPAND.getName(), 5L); + searchRequestContext.setTotalHits(new TotalHits(3L, TotalHits.Relation.EQUAL_TO)); + searchRequestContext.setShardStats(Map.of("total", 10, "successful", 8, "skipped", 1, "failed", 1)); + SearchRequestSlowLog.SearchRequestSlowLogMessage p = new SearchRequestSlowLog.SearchRequestSlowLogMessage( + searchPhaseContext, + 10, + searchRequestContext + ); + + assertThat(p.getValueFor("took"), equalTo("10nanos")); + assertThat(p.getValueFor("took_millis"), equalTo("0")); + assertThat(p.getValueFor("phase_took"), equalTo("{expand=5, fetch=10, query=50}")); + assertThat(p.getValueFor("total_hits"), equalTo("3 hits")); + assertThat(p.getValueFor("search_type"), equalTo("QUERY_THEN_FETCH")); + assertThat(p.getValueFor("shards"), equalTo("{total: 10, successful: 8, skipped: 1, failed: 1}")); + assertThat(p.getValueFor("source"), equalTo("{\\\"query\\\":{\\\"match_all\\\":{\\\"boost\\\":1.0}}}")); + assertThat(p.getValueFor("id"), equalTo(null)); + } + + public void testSearchRequestSlowLogHasJsonFields_PartialContext() throws IOException { + SearchSourceBuilder source = SearchSourceBuilder.searchSource().query(QueryBuilders.matchAllQuery()); + SearchRequest searchRequest = new SearchRequest().source(source); + SearchPhaseContext searchPhaseContext = new MockSearchPhaseContext(1, searchRequest); + SearchRequestContext searchRequestContext = new SearchRequestContext(); + searchRequestContext.updatePhaseTookMap(SearchPhaseName.FETCH.getName(), 10L); + searchRequestContext.updatePhaseTookMap(SearchPhaseName.QUERY.getName(), 50L); + searchRequestContext.updatePhaseTookMap(SearchPhaseName.EXPAND.getName(), 5L); + searchRequestContext.setTotalHits(new TotalHits(3L, TotalHits.Relation.EQUAL_TO)); + searchRequestContext.setShardStats(Map.of("successful", 8, "skipped", 1)); + SearchRequestSlowLog.SearchRequestSlowLogMessage p = new SearchRequestSlowLog.SearchRequestSlowLogMessage( + searchPhaseContext, + 10, + searchRequestContext + ); + + assertThat(p.getValueFor("took"), equalTo("10nanos")); + assertThat(p.getValueFor("took_millis"), equalTo("0")); + assertThat(p.getValueFor("phase_took"), equalTo("{expand=5, fetch=10, query=50}")); + assertThat(p.getValueFor("total_hits"), equalTo("3 hits")); + assertThat(p.getValueFor("search_type"), equalTo("QUERY_THEN_FETCH")); + assertThat(p.getValueFor("shards"), equalTo("{total: null, successful: 8, skipped: 1, failed: null}")); assertThat(p.getValueFor("source"), equalTo("{\\\"query\\\":{\\\"match_all\\\":{\\\"boost\\\":1.0}}}")); assertThat(p.getValueFor("id"), equalTo(null)); } @@ -128,17 +178,25 @@ public void testSearchRequestSlowLogSearchContextPrinterToLog() throws IOExcepti 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); + SearchRequestContext searchRequestContext = new SearchRequestContext(); + searchRequestContext.updatePhaseTookMap(SearchPhaseName.FETCH.getName(), 10L); + searchRequestContext.updatePhaseTookMap(SearchPhaseName.QUERY.getName(), 50L); + searchRequestContext.updatePhaseTookMap(SearchPhaseName.EXPAND.getName(), 5L); + searchRequestContext.setTotalHits(new TotalHits(3L, TotalHits.Relation.EQUAL_TO)); + searchRequestContext.setShardStats(Map.of("total", 10, "successful", 8, "skipped", 1, "failed", 1)); SearchRequestSlowLog.SearchRequestSlowLogMessage p = new SearchRequestSlowLog.SearchRequestSlowLogMessage( searchPhaseContext, 100000, - phaseTookMap + searchRequestContext ); assertThat(p.getFormattedMessage(), startsWith("took[100micros]")); + assertThat(p.getFormattedMessage(), containsString("took_millis[0]")); + assertThat(p.getFormattedMessage(), containsString("phase_took_millis[{expand=5, fetch=10, query=50}]")); + assertThat(p.getFormattedMessage(), containsString("total_hits[3 hits]")); + assertThat(p.getFormattedMessage(), containsString("search_type[QUERY_THEN_FETCH]")); + assertThat(p.getFormattedMessage(), containsString("shards[{total: 10, successful: 8, skipped: 1, failed: 1}]")); + assertThat(p.getFormattedMessage(), containsString("source[{\"query\":{\"match_all\":{\"boost\":1.0}}}]")); // Makes sure that output doesn't contain any new lines assertThat(p.getFormattedMessage(), not(containsString("\n"))); assertThat(p.getFormattedMessage(), endsWith("id[]"));