Add trace log of the request for the query and fetch phases (#34479)

This change adds a logger for the query and fetch phases that prints all requests
before their execution at the trace level. This will help debugging cases where an issue
occurs during the execution since only completed queries are logged by the slow logs.

Author: jimczi

server/src/main/java/org/elasticsearch/search/SearchPhase.java

@@ -20,6 +20,7 @@
 package org.elasticsearch.search;
 
 import org.elasticsearch.search.internal.SearchContext;
+import org.elasticsearch.tasks.Task;
 
 /**
  * Represents a phase of a search request e.g. query, fetch etc.
@@ -35,4 +36,32 @@ public interface SearchPhase {
      * Executes the search phase
      */
     void execute(SearchContext context);
+
+    class SearchContextSourcePrinter {
+        private final SearchContext searchContext;
+
+        public SearchContextSourcePrinter(SearchContext searchContext) {
+            this.searchContext = searchContext;
+        }
+
+        @Override
+        public String toString() {
+            StringBuilder builder = new StringBuilder();
+            builder.append(searchContext.indexShard().shardId());
+            builder.append(" ");
+            if (searchContext.request() != null &&
+                    searchContext.request().source() != null) {
+                builder.append("source[").append(searchContext.request().source().toString()).append("], ");
+            } else {
+                builder.append("source[], ");
+            }
+            if (searchContext.getTask() != null &&
+                    searchContext.getTask().getHeader(Task.X_OPAQUE_ID) != null) {
+                builder.append("id[").append(searchContext.getTask().getHeader(Task.X_OPAQUE_ID)).append("], ");
+            } else {
+                builder.append("id[], ");
+            }
+            return builder.toString();
+        }
+    }
 }

server/src/main/java/org/elasticsearch/search/fetch/FetchPhase.java

@@ -19,6 +19,8 @@
 
 package org.elasticsearch.search.fetch;
 
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.Logger;
 import org.apache.lucene.index.LeafReaderContext;
 import org.apache.lucene.index.ReaderUtil;
 import org.apache.lucene.search.DocIdSetIterator;
@@ -70,6 +72,7 @@
  * after reducing all of the matches returned by the query phase
  */
 public class FetchPhase implements SearchPhase {
+    private static final Logger LOGGER = LogManager.getLogger(FetchPhase.class);
 
     private final FetchSubPhase[] fetchSubPhases;
 
@@ -84,6 +87,11 @@ public void preProcess(SearchContext context) {
 
     @Override
     public void execute(SearchContext context) {
+
+        if (LOGGER.isTraceEnabled()) {
+            LOGGER.trace("{}", new SearchContextSourcePrinter(context));
+        }
+
         final FieldsVisitor fieldsVisitor;
         Map<String, Set<String>> storedToRequestedFields = new HashMap<>();
         StoredFieldsContext storedFieldsContext = context.storedFieldsContext();

server/src/main/java/org/elasticsearch/search/query/QueryPhase.java

@@ -19,6 +19,8 @@
 
 package org.elasticsearch.search.query;
 
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.Logger;
 import org.apache.lucene.index.IndexReader;
 import org.apache.lucene.index.LeafReaderContext;
 import org.apache.lucene.queries.MinDocQuery;
@@ -72,6 +74,7 @@
  * (document ids and score or sort criteria) so that matches can be reduced on the coordinating node
  */
 public class QueryPhase implements SearchPhase {
+    private static final Logger LOGGER = LogManager.getLogger(QueryPhase.class);
 
     private final AggregationPhase aggregationPhase;
     private final SuggestPhase suggestPhase;
@@ -98,6 +101,11 @@ public void execute(SearchContext searchContext) throws QueryPhaseExecutionExcep
                     new DocValueFormat[0]);
             return;
         }
+
+        if (LOGGER.isTraceEnabled()) {
+            LOGGER.trace("{}", new SearchContextSourcePrinter(searchContext));
+        }
+
         // Pre-process aggregations as late as possible. In the case of a DFS_Q_T_F
         // request, preProcess is called on the DFS phase phase, this is why we pre-process them
         // here to make sure it happens during the QUERY phase

test/framework/src/main/java/org/elasticsearch/search/aggregations/AggregatorTestCase.java

@@ -55,6 +55,7 @@
 import org.elasticsearch.index.mapper.ObjectMapper.Nested;
 import org.elasticsearch.index.query.QueryShardContext;
 import org.elasticsearch.index.query.support.NestedScope;
+import org.elasticsearch.index.shard.IndexShard;
 import org.elasticsearch.index.shard.ShardId;
 import org.elasticsearch.indices.breaker.CircuitBreakerService;
 import org.elasticsearch.indices.breaker.NoneCircuitBreakerService;
@@ -127,6 +128,9 @@ protected AggregatorFactory<?> createAggregatorFactory(Query query,
                                                            MappedFieldType... fieldTypes) throws IOException {
         SearchContext searchContext = createSearchContext(indexSearcher, indexSettings);
         CircuitBreakerService circuitBreakerService = new NoneCircuitBreakerService();
+        IndexShard indexShard = mock(IndexShard.class);
+        when(indexShard.shardId()).thenReturn(new ShardId("test", "test", 0));
+        when(searchContext.indexShard()).thenReturn(indexShard);
         when(searchContext.aggregations())
             .thenReturn(new SearchContextAggregations(AggregatorFactories.EMPTY, bucketConsumer));
         when(searchContext.bigArrays()).thenReturn(
@@ -151,7 +155,6 @@ protected AggregatorFactory<?> createAggregatorFactory(Query query,
         QueryShardContext queryShardContext = queryShardContextMock(mapperService);
         when(queryShardContext.getIndexSettings()).thenReturn(indexSettings);
         when(searchContext.getQueryShardContext()).thenReturn(queryShardContext);
-
         Map<String, MappedFieldType> fieldNameToType = new HashMap<>();
         fieldNameToType.putAll(Arrays.stream(fieldTypes)
             .collect(Collectors.toMap(MappedFieldType::name, Function.identity())));