Refactor field names - all goes under elasticsearch.querylog (elastic#143182)

* Refactor field names - all goes under elasticsearch.querylog

Author: smalyshev

server/src/internalClusterTest/java/org/elasticsearch/search/SearchLoggingIT.java

@@ -20,6 +20,7 @@
 import org.elasticsearch.action.search.ClosePointInTimeRequest;
 import org.elasticsearch.action.search.OpenPointInTimeRequest;
 import org.elasticsearch.action.search.OpenPointInTimeResponse;
+import org.elasticsearch.action.search.SearchLogContext;
 import org.elasticsearch.action.search.SearchLogProducer;
 import org.elasticsearch.action.search.SearchPhaseExecutionException;
 import org.elasticsearch.action.search.SearchResponse;
@@ -32,6 +33,7 @@
 import org.elasticsearch.cluster.metadata.Template;
 import org.elasticsearch.common.logging.AccumulatingMockAppender;
 import org.elasticsearch.common.logging.Loggers;
+import org.elasticsearch.common.logging.activity.QueryLogging;
 import org.elasticsearch.common.settings.Settings;
 import org.elasticsearch.common.util.CollectionUtils;
 import org.elasticsearch.core.TimeValue;
@@ -63,8 +65,8 @@
 import static org.elasticsearch.action.search.SearchLogProducer.QUERY_FIELD_IS_SYSTEM;
 import static org.elasticsearch.action.search.SearchLogProducer.QUERY_FIELD_SEARCH_HITS;
 import static org.elasticsearch.action.search.SearchLogProducer.QUERY_FIELD_SEARCH_HITS_GTE;
-import static org.elasticsearch.common.logging.activity.ActivityLogProducer.ES_FIELDS_PREFIX;
 import static org.elasticsearch.common.logging.activity.ActivityLogProducer.EVENT_OUTCOME_FIELD;
+import static org.elasticsearch.common.logging.activity.QueryLogging.ES_QUERY_FIELDS_PREFIX;
 import static org.elasticsearch.common.logging.activity.QueryLogging.QUERY_FIELD_INDICES;
 import static org.elasticsearch.common.logging.activity.QueryLogging.QUERY_FIELD_QUERY;
 import static org.elasticsearch.common.logging.activity.QueryLogging.QUERY_FIELD_RESULT_COUNT;
@@ -77,19 +79,22 @@
 import static org.elasticsearch.test.ActivityLoggingUtils.assertMessageFailure;
 import static org.elasticsearch.test.ActivityLoggingUtils.assertMessageSuccess;
 import static org.elasticsearch.test.ActivityLoggingUtils.getMessageData;
+import static org.elasticsearch.test.ActivityLoggingUtils.getMessageField;
 import static org.elasticsearch.test.hamcrest.ElasticsearchAssertions.assertAcked;
 import static org.elasticsearch.test.hamcrest.ElasticsearchAssertions.assertFailures;
 import static org.elasticsearch.test.hamcrest.ElasticsearchAssertions.assertResponse;
 import static org.elasticsearch.test.hamcrest.ElasticsearchAssertions.assertSearchHitsWithoutFailures;
+import static org.hamcrest.Matchers.arrayContaining;
 import static org.hamcrest.Matchers.containsString;
 import static org.hamcrest.Matchers.equalTo;
 import static org.hamcrest.Matchers.greaterThan;
 import static org.hamcrest.Matchers.greaterThanOrEqualTo;
 import static org.hamcrest.Matchers.hasSize;
+import static org.hamcrest.Matchers.instanceOf;
 
 public class SearchLoggingIT extends AbstractSearchCancellationTestCase {
     static AccumulatingMockAppender appender;
-    static Logger queryLog = LogManager.getLogger(SearchLogProducer.QUERY_LOGGER_NAME);
+    static Logger queryLog = LogManager.getLogger(QueryLogging.QUERY_LOGGER_NAME);
     static Level origQueryLogLevel = queryLog.getLevel();
 
     @BeforeClass
@@ -144,21 +149,21 @@ public void testSearchLog() {
             assertSearchHitsWithoutFailures(prepareSearch().setQuery(simpleQueryStringQuery("fox")), "1");
             var event = appender.getLastEventAndReset();
             Map<String, String> message = getMessageData(event);
-            assertMessageSuccess(message, "search", "fox");
+            assertMessageSuccess(message, SearchLogContext.TYPE, "fox");
             assertThat(message.get(QUERY_FIELD_RESULT_COUNT), equalTo("1"));
             assertThat(message.get(QUERY_FIELD_INDICES), equalTo(""));
-            assertNull(message.get(ES_FIELDS_PREFIX + "timed_out"));
+            assertNull(message.get(ES_QUERY_FIELDS_PREFIX + "timed_out"));
         }
 
         // Match
         {
             assertSearchHitsWithoutFailures(prepareSearch(INDEX_NAME).setQuery(matchQuery("field1", "quick")), "1", "2", "3");
             var event = appender.getLastEventAndReset();
             Map<String, String> message = getMessageData(event);
-            assertMessageSuccess(message, "search", "quick");
+            assertMessageSuccess(message, SearchLogContext.TYPE, "quick");
             assertThat(message.get(QUERY_FIELD_RESULT_COUNT), equalTo("3"));
             assertThat(message.get(QUERY_FIELD_INDICES), equalTo(INDEX_NAME));
-            assertNull(message.get(ES_FIELDS_PREFIX + "timed_out"));
+            assertNull(message.get(ES_QUERY_FIELDS_PREFIX + "timed_out"));
         }
         // Total hits
         {
@@ -168,15 +173,34 @@ public void testSearchLog() {
             );
             var event = appender.getLastEventAndReset();
             Map<String, String> message = getMessageData(event);
-            assertMessageSuccess(message, "search", "quick");
+            assertMessageSuccess(message, SearchLogContext.TYPE, "quick");
             assertThat(message.get(QUERY_FIELD_RESULT_COUNT), equalTo("1"));
             assertThat(message.get(QUERY_FIELD_SEARCH_HITS), equalTo("2"));
             assertThat(message.get(QUERY_FIELD_SEARCH_HITS_GTE), equalTo("true"));
             assertThat(message.get(QUERY_FIELD_INDICES), equalTo(INDEX_NAME));
-            assertNull(message.get(ES_FIELDS_PREFIX + "timed_out"));
+            assertNull(message.get(ES_QUERY_FIELDS_PREFIX + "timed_out"));
         }
     }
 
+    public void testIndicesFieldIsArray() {
+        setupIndex();
+
+        assertSearchHitsWithoutFailures(prepareSearch(INDEX_NAME).setQuery(matchQuery("field1", "quick")), "1", "2", "3");
+        var event = appender.getLastEventAndReset();
+        Object indicesField = getMessageField(event, QUERY_FIELD_INDICES);
+        assertThat(indicesField, instanceOf(String[].class));
+        assertThat((String[]) indicesField, arrayContaining(INDEX_NAME));
+
+        // Test with more than one index
+        String secondIndex = INDEX_NAME + "_2";
+        assertAcked(prepareCreate(secondIndex));
+        assertSearchHitsWithoutFailures(prepareSearch(INDEX_NAME, secondIndex).setQuery(matchQuery("field1", "quick")), "1", "2", "3");
+        var event2 = appender.getLastEventAndReset();
+        Object indicesField2 = getMessageField(event2, QUERY_FIELD_INDICES);
+        assertThat(indicesField2, instanceOf(String[].class));
+        assertThat((String[]) indicesField2, arrayContaining(INDEX_NAME, secondIndex));
+    }
+
     public void testFailureLog() {
         assertAcked(prepareCreate(INDEX_NAME).setMapping("field1", "type=text,index_options=docs"));
         indexRandom(
@@ -192,7 +216,7 @@ public void testFailureLog() {
         );
         var event = appender.getLastEventAndReset();
         Map<String, String> message = getMessageData(event);
-        assertMessageFailure(message, "search", "quick brown", SearchPhaseExecutionException.class, "all shards failed");
+        assertMessageFailure(message, SearchLogContext.TYPE, "quick brown", SearchPhaseExecutionException.class, "all shards failed");
         assertThat(message.get(QUERY_FIELD_RESULT_COUNT), equalTo("0"));
         assertThat(message.get(QUERY_FIELD_INDICES), equalTo(INDEX_NAME));
     }
@@ -212,7 +236,7 @@ public void testSearchCancel() throws Exception {
         ensureSearchWasCancelled(searchResponse);
         var event = appender.getLastEventAndReset();
         Map<String, String> message = getMessageData(event);
-        assertMessageFailure(message, "search", "mockscript", SearchPhaseExecutionException.class, null);
+        assertMessageFailure(message, SearchLogContext.TYPE, "mockscript", SearchPhaseExecutionException.class, null);
         assertThat(message.get(QUERY_FIELD_RESULT_COUNT), equalTo("0"));
         assertThat(message.get(QUERY_FIELD_INDICES), equalTo("test"));
     }
@@ -229,9 +253,9 @@ public void testMultiSearch() {
         appender.events.forEach(ev -> {
             Map<String, String> message = getMessageData(ev);
             assertThat(message.get(EVENT_OUTCOME_FIELD), equalTo("success"));
-            assertThat(message.get(ES_FIELDS_PREFIX + "type"), equalTo("search"));
-            assertThat(Long.valueOf(message.get(ES_FIELDS_PREFIX + "took")), greaterThan(0L));
-            assertThat(Long.valueOf(message.get(ES_FIELDS_PREFIX + "took_millis")), greaterThanOrEqualTo(0L));
+            assertThat(message.get(ES_QUERY_FIELDS_PREFIX + "type"), equalTo(SearchLogContext.TYPE));
+            assertThat(Long.valueOf(message.get(ES_QUERY_FIELDS_PREFIX + "took")), greaterThan(0L));
+            assertThat(Long.valueOf(message.get(ES_QUERY_FIELDS_PREFIX + "took_millis")), greaterThanOrEqualTo(0L));
             assertThat(message.get(QUERY_FIELD_INDICES), equalTo(INDEX_NAME));
             if (message.get(QUERY_FIELD_QUERY).contains("quick")) {
                 assertThat(message.get(QUERY_FIELD_RESULT_COUNT), equalTo("3"));
@@ -256,7 +280,7 @@ public void testPitSearch() {
             );
             var event = appender.getLastEventAndReset();
             Map<String, String> message = getMessageData(event);
-            assertMessageSuccess(message, "search", "fox");
+            assertMessageSuccess(message, SearchLogContext.TYPE, "fox");
             assertThat(message.get(QUERY_FIELD_RESULT_COUNT), equalTo("1"));
             assertThat(message.get(QUERY_FIELD_INDICES), equalTo(INDEX_NAME));
         } finally {
@@ -345,7 +369,7 @@ public void testSearchHasAggregationsLog() {
         assertSearchHitsWithoutFailures(prepareSearch(INDEX_NAME).setQuery(matchQuery("field1", "quick")), "1", "2", "3");
         var eventNoAgg = appender.getLastEventAndReset();
         Map<String, String> messageNoAgg = getMessageData(eventNoAgg);
-        assertMessageSuccess(messageNoAgg, "search", "quick");
+        assertMessageSuccess(messageNoAgg, SearchLogContext.TYPE, "quick");
         assertThat(messageNoAgg.get(QUERY_FIELD_RESULT_COUNT), equalTo("3"));
         assertNull(messageNoAgg.get(SearchLogProducer.QUERY_FIELD_HAS_AGGREGATIONS));
 
@@ -356,7 +380,7 @@ public void testSearchHasAggregationsLog() {
         );
         var eventWithAgg = appender.getLastEventAndReset();
         Map<String, String> messageWithAgg = getMessageData(eventWithAgg);
-        assertMessageSuccess(messageWithAgg, "search", "match_all");
+        assertMessageSuccess(messageWithAgg, SearchLogContext.TYPE, "match_all");
         assertThat(messageWithAgg.get(QUERY_FIELD_RESULT_COUNT), equalTo("0"));
         assertThat(messageWithAgg.get(QUERY_FIELD_SEARCH_HITS), equalTo("3"));
         assertNull(messageWithAgg.get(QUERY_FIELD_SEARCH_HITS_GTE));
@@ -365,7 +389,7 @@ public void testSearchHasAggregationsLog() {
 
     public void testSearchTimedOutLog() {
         setupIndex();
-        final String timedOutField = ES_FIELDS_PREFIX + "timed_out";
+        final String timedOutField = ES_QUERY_FIELDS_PREFIX + "timed_out";
 
         // Search that times out (using plugin that throws TimeExceededException): timed_out must be true
         SearchResponse timedOutResponse = null;
@@ -383,7 +407,7 @@ public void testSearchTimedOutLog() {
         }
         var eventTimedOut = appender.getLastEventAndReset();
         Map<String, String> messageTimedOut = getMessageData(eventTimedOut);
-        assertMessageSuccess(messageTimedOut, "search", "timeout");
+        assertMessageSuccess(messageTimedOut, SearchLogContext.TYPE, "timeout");
         assertThat(messageTimedOut.get(timedOutField), equalTo("true"));
     }
 

server/src/main/java/org/elasticsearch/action/search/SearchLogContext.java

@@ -9,8 +9,6 @@
 
 package org.elasticsearch.action.search;
 
-import joptsimple.internal.Strings;
-
 import org.apache.lucene.search.TotalHits;
 import org.elasticsearch.common.io.stream.NamedWriteableRegistry;
 import org.elasticsearch.common.logging.activity.ActivityLoggerContext;
@@ -23,7 +21,7 @@
 import java.util.function.Predicate;
 
 public class SearchLogContext extends ActivityLoggerContext {
-    private static final String TYPE = "search";
+    public static final String TYPE = "dsl";
     private final SearchRequest request;
     private final @Nullable SearchResponse response;
     private final NamedWriteableRegistry namedWriteableRegistry;
@@ -108,8 +106,8 @@ public boolean isTimedOut() {
         return response != null && response.isTimedOut();
     }
 
-    public String getIndices() {
-        return Strings.join(getIndexNames(), ",");
+    public String[] getIndices() {
+        return getIndexNames();
     }
 
     public boolean hasAggregations() {

server/src/main/java/org/elasticsearch/action/search/SearchLogProducer.java

@@ -22,6 +22,7 @@
 import java.util.function.Predicate;
 
 import static org.elasticsearch.common.logging.activity.ActivityLogger.ACTIVITY_LOGGER_SETTINGS_PREFIX;
+import static org.elasticsearch.common.logging.activity.QueryLogging.ES_QUERY_FIELDS_PREFIX;
 
 public class SearchLogProducer implements ActivityLogProducer<SearchLogContext> {
 
@@ -58,7 +59,7 @@ public Optional<ESLogMessage> produce(SearchLogContext context, ActionLoggingFie
         if (logSystemSearches == false && isSystemSearch) {
             return Optional.empty();
         }
-        ESLogMessage msg = produceCommon(context, additionalFields);
+        ESLogMessage msg = produceCommon(context, ES_QUERY_FIELDS_PREFIX, additionalFields);
         msg.field(QueryLogging.QUERY_FIELD_QUERY, context.getQuery());
         msg.field(QueryLogging.QUERY_FIELD_INDICES, context.getIndices());
         msg.field(QueryLogging.QUERY_FIELD_RESULT_COUNT, context.getHits());

server/src/main/java/org/elasticsearch/action/search/TransportSearchAction.java

@@ -240,7 +240,6 @@ public TransportSearchAction(
         this.forceConnectTimeoutSecs = settings.getAsTime("search.ccs.force_connect_timeout", null);
         this.crossProjectModeDecider = new CrossProjectModeDecider(settings);
         this.activityLogger = new ActivityLogger<>(
-            "search",
             clusterService.getClusterSettings(),
             new SearchLogProducer(clusterService.getClusterSettings(), indexNameExpressionResolver.getSystemNamePredicate()),
             logWriterProvider,

server/src/main/java/org/elasticsearch/common/logging/activity/ActivityLogProducer.java

@@ -24,42 +24,43 @@
  */
 public interface ActivityLogProducer<Context extends ActivityLoggerContext> {
 
-    String ES_FIELDS_PREFIX = "elasticsearch.activitylog.";
     String X_OPAQUE_ID_FIELD = "http.request.headers.x_opaque_id";
     String EVENT_OUTCOME_FIELD = "event.outcome";
     String EVENT_DURATION_FIELD = "event.duration";
-    // Fields specific to querying logs - search, esql, etc. Common fields are in ES_FIELDS_PREFIX.
-    String ES_QUERY_FIELDS_PREFIX = "elasticsearch.activitylog.querying.";
-    String QUERY_LOGGER_NAME = "elasticsearch.querylog";
+    String TRACE_ID_FIELD = "trace.id";
 
     /**
      * Produces a {@link ESLogMessage} if the producer decides to log, or nothing otherwise.
      */
     Optional<ESLogMessage> produce(Context context, ActionLoggingFields additionalFields);
 
+    /**
+     * Since we only have query logging for now, set it as the default logger name for convenience.
+     */
     default String loggerName() {
-        return QUERY_LOGGER_NAME;
+        return QueryLogging.QUERY_LOGGER_NAME;
     }
 
     /**
      * Produces a {@link ESLogMessage} with common fields.
      */
-    default ESLogMessage produceCommon(Context context, ActionLoggingFields additionalFields) {
+    default ESLogMessage produceCommon(Context context, String prefix, ActionLoggingFields additionalFields) {
         var fields = new ESLogMessage();
         fields.withFields(additionalFields.logFields());
         fields.field(X_OPAQUE_ID_FIELD, context.getOpaqueId());
+        fields.field(TRACE_ID_FIELD, context.getTraceId());
         long tookInNanos = context.getTookInNanos();
         fields.field(EVENT_DURATION_FIELD, tookInNanos);
-        fields.field(ES_FIELDS_PREFIX + "took", tookInNanos);
-        fields.field(ES_FIELDS_PREFIX + "took_millis", TimeUnit.NANOSECONDS.toMillis(tookInNanos));
         fields.field(EVENT_OUTCOME_FIELD, context.isSuccess() ? "success" : "failure");
-        fields.field(ES_FIELDS_PREFIX + "type", context.getType());
+        fields.field(prefix + "took", tookInNanos);
+        fields.field(prefix + "took_millis", TimeUnit.NANOSECONDS.toMillis(tookInNanos));
+        fields.field(prefix + "type", context.getType());
         if (context.isSuccess() == false) {
             fields.field("error.type", context.getErrorType());
             fields.field("error.message", context.getErrorMessage());
         }
         if (context.isTimedOut()) {
-            fields.field(ES_FIELDS_PREFIX + "timed_out", true);
+            fields.field(prefix + "timed_out", true);
         }
         return fields;
     }

server/src/main/java/org/elasticsearch/common/logging/activity/ActivityLogger.java

@@ -73,7 +73,6 @@ public class ActivityLogger<Context extends ActivityLoggerContext> {
     );
 
     public ActivityLogger(
-        String name,
         ClusterSettings settings,
         ActivityLogProducer<Context> producer,
         ActivityLogWriterProvider writerProvider,

server/src/main/java/org/elasticsearch/common/logging/activity/ActivityLoggerContext.java

@@ -61,4 +61,8 @@ public String getErrorType() {
     public String getOpaqueId() {
         return task.getHeader(Task.X_OPAQUE_ID_HTTP_HEADER);
     }
+
+    public String getTraceId() {
+        return task.getHeader(Task.TRACE_ID);
+    }
 }

server/src/main/java/org/elasticsearch/common/logging/activity/QueryLogging.java

@@ -9,14 +9,28 @@
 
 package org.elasticsearch.common.logging.activity;
 
-import static org.elasticsearch.common.logging.activity.ActivityLogProducer.ES_FIELDS_PREFIX;
-
 /**
- * Constants specific to logging queries - search, esql, etc. Common fields are in ES_FIELDS_PREFIX.
+ * Constants specific to logging queries - DSL search, ESQL, etc.
  */
 public interface QueryLogging {
-    String ES_QUERY_FIELDS_PREFIX = ES_FIELDS_PREFIX + "querying.";
+    /**
+     * This is the prefix for all query logging specific fields.
+     */
+    String ES_QUERY_FIELDS_PREFIX = "elasticsearch.querylog.";
+    /**
+     * Query text.
+     */
     String QUERY_FIELD_QUERY = ES_QUERY_FIELDS_PREFIX + "query";
+    /**
+     * How many results the search or query actually returned.
+     */
     String QUERY_FIELD_RESULT_COUNT = ES_QUERY_FIELDS_PREFIX + "result_count";
+    /**
+     * Which indices were queried. May not apply to some modules like ESQL or SQL.
+     */
     String QUERY_FIELD_INDICES = ES_QUERY_FIELDS_PREFIX + "indices";
+    /**
+     * This is the name Log4j logger will use.
+     */
+    String QUERY_LOGGER_NAME = "elasticsearch.querylog";
 }