Add user information to slowlog

docs/reference/index-modules/slowlog.asciidoc

@@ -58,33 +58,56 @@ The search slow log file is configured in the `log4j2.properties` file.
 [discrete]
 ==== Identifying search slow log origin
 
-It is often useful to identify what triggered a slow running query. If a call was initiated with an `X-Opaque-ID` header, then the user ID
-is included in Search Slow logs as an additional **id** field
+It is often useful to identify what triggered a slow running query.
+To include information about the user that triggered a slow search,
+use the `index.search.slowlog.include.user` setting.
+
+[source,console]
+--------------------------------------------------
+PUT /my-index-000001/_settings
+{
+  "index.search.slowlog.include.user": true
+}
+--------------------------------------------------
+// TEST[setup:my_index]
+
+This will result in user information being included in the slow log.
 
 [source,js]
 ---------------------------
 {
-  "type": "index_search_slowlog",
-  "timestamp": "2030-08-30T11:59:37,786+02:00",
-  "level": "WARN",
-  "component": "i.s.s.query",
-  "cluster.name": "distribution_run",
-  "node.name": "node-0",
-  "message": "[index6][0]",
-  "took": "78.4micros",
-  "took_millis": "0",
-  "total_hits": "0 hits",
-  "stats": "[]",
-  "search_type": "QUERY_THEN_FETCH",
-  "total_shards": "1",
-  "source": "{\"query\":{\"match_all\":{\"boost\":1.0}}}",
-  "id": "MY_USER_ID",
-  "cluster.uuid": "Aq-c-PAeQiK3tfBYtig9Bw",
-  "node.id": "D7fUYfnfTLa2D7y-xw6tZg"
+  "@timestamp": "2024-02-21T12:42:37.255Z",
+  "log.level": "WARN",
+  "auth.type": "REALM",
+  "elasticsearch.slowlog.id": "tomcat-123",
+  "elasticsearch.slowlog.message": "[index6][0]",
+  "elasticsearch.slowlog.search_type": "QUERY_THEN_FETCH",
+  "elasticsearch.slowlog.source": "{\"query\":{\"match_all\":{\"boost\":1.0}}}",
+  "elasticsearch.slowlog.stats": "[]",
+  "elasticsearch.slowlog.took": "747.3micros",
+  "elasticsearch.slowlog.took_millis": 0,
+  "elasticsearch.slowlog.total_hits": "1 hits",
+  "elasticsearch.slowlog.total_shards": 1,
+  "user.name": "elastic",
+  "user.realm": "reserved",
+  "ecs.version": "1.2.0",
+  "service.name": "ES_ECS",
+  "event.dataset": "elasticsearch.index_search_slowlog",
+  "process.thread.name": "elasticsearch[runTask-0][search][T#5]",
+  "log.logger": "index.search.slowlog.query",
+  "elasticsearch.cluster.uuid": "Ui23kfF1SHKJwu_hI1iPPQ",
+  "elasticsearch.node.id": "JK-jn-XpQ3OsDUsq5ZtfGg",
+  "elasticsearch.node.name": "node-0",
+  "elasticsearch.cluster.name": "distribution_run"
 }
+
 ---------------------------
 // NOTCONSOLE
 
+If a call was initiated with an `X-Opaque-ID` header, then the ID is included
+in Search Slow logs in the **elasticsearch.slowlog.id** field. See
+<<x-opaque-id, X-Opaque-Id HTTP header>> for details and best practices.
+
 [discrete]
 [[index-slow-log]]
 === Index Slow log
@@ -119,6 +142,18 @@ PUT /my-index-000001/_settings
 --------------------------------------------------
 // TEST[setup:my_index]
 
+To include information about the user that triggered a slow indexing event,
+use the `index.indexing.slowlog.include.user` setting.
+
+[source,console]
+--------------------------------------------------
+PUT /my-index-000001/_settings
+{
+  "index.indexing.slowlog.include.user": true
+}
+--------------------------------------------------
+// TEST[setup:my_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, while setting it to

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

@@ -85,12 +85,14 @@ public final class IndexScopedSettings extends AbstractScopedSettings {
         SearchSlowLog.INDEX_SEARCH_SLOWLOG_THRESHOLD_QUERY_DEBUG_SETTING,
         SearchSlowLog.INDEX_SEARCH_SLOWLOG_THRESHOLD_QUERY_INFO_SETTING,
         SearchSlowLog.INDEX_SEARCH_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING,
+        SearchSlowLog.INDEX_SEARCH_SLOWLOG_INCLUDE_USER_SETTING,
         IndexingSlowLog.INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_WARN_SETTING,
         IndexingSlowLog.INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_DEBUG_SETTING,
         IndexingSlowLog.INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_INFO_SETTING,
         IndexingSlowLog.INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_TRACE_SETTING,
         IndexingSlowLog.INDEX_INDEXING_SLOWLOG_REFORMAT_SETTING,
         IndexingSlowLog.INDEX_INDEXING_SLOWLOG_MAX_SOURCE_CHARS_TO_LOG_SETTING,
+        IndexingSlowLog.INDEX_INDEXING_SLOWLOG_INCLUDE_USER_SETTING,
         MergePolicyConfig.INDEX_COMPOUND_FORMAT_SETTING,
         MergePolicyConfig.INDEX_MERGE_POLICY_TYPE_SETTING,
         MergePolicyConfig.INDEX_MERGE_POLICY_DELETES_PCT_ALLOWED_SETTING,

server/src/main/java/org/elasticsearch/index/IndexModule.java

@@ -194,13 +194,14 @@ public IndexModule(
         final Map<String, IndexStorePlugin.DirectoryFactory> directoryFactories,
         final BooleanSupplier allowExpensiveQueries,
         final IndexNameExpressionResolver expressionResolver,
-        final Map<String, IndexStorePlugin.RecoveryStateFactory> recoveryStateFactories
+        final Map<String, IndexStorePlugin.RecoveryStateFactory> recoveryStateFactories,
+        final SlowLogFieldProvider slowLogFieldProvider
     ) {
         this.indexSettings = indexSettings;
         this.analysisRegistry = analysisRegistry;
         this.engineFactory = Objects.requireNonNull(engineFactory);
-        this.searchOperationListeners.add(new SearchSlowLog(indexSettings));
-        this.indexOperationListeners.add(new IndexingSlowLog(indexSettings));
+        this.searchOperationListeners.add(new SearchSlowLog(indexSettings, slowLogFieldProvider));
+        this.indexOperationListeners.add(new IndexingSlowLog(indexSettings, slowLogFieldProvider));
         this.directoryFactories = Collections.unmodifiableMap(directoryFactories);
         this.allowExpensiveQueries = allowExpensiveQueries;
         this.expressionResolver = expressionResolver;

server/src/main/java/org/elasticsearch/index/IndexingSlowLog.java

@@ -69,6 +69,13 @@ public final class IndexingSlowLog implements IndexingOperationListener {
         Property.IndexScope
     );
 
+    public static final Setting<Boolean> INDEX_INDEXING_SLOWLOG_INCLUDE_USER_SETTING = Setting.boolSetting(
+        INDEX_INDEXING_SLOWLOG_PREFIX + ".include.user",
+        false,
+        Property.Dynamic,
+        Property.IndexScope
+    );
+
     /**
      * Legacy index setting, kept for 7.x BWC compatibility. This setting has no effect in 8.x. Do not use.
      * TODO: Remove in 9.0
@@ -96,6 +103,7 @@ public final class IndexingSlowLog implements IndexingOperationListener {
      * <em>characters</em> of the source.
      */
     private int maxSourceCharsToLog;
+    private final SlowLogFieldProvider slowLogFieldProvider;
 
     /**
      * Reads how much of the source to log. The user can specify any value they
@@ -117,7 +125,8 @@ public final class IndexingSlowLog implements IndexingOperationListener {
         Property.IndexScope
     );
 
-    IndexingSlowLog(IndexSettings indexSettings) {
+    IndexingSlowLog(IndexSettings indexSettings, SlowLogFieldProvider slowLogFieldProvider) {
+        this.slowLogFieldProvider = slowLogFieldProvider;
         this.indexLogger = LogManager.getLogger(INDEX_INDEXING_SLOWLOG_PREFIX + ".index");
         Loggers.setLevel(this.indexLogger, Level.TRACE);
         this.index = indexSettings.getIndex();
@@ -171,22 +180,66 @@ public void postIndex(ShardId shardId, Engine.Index indexOperation, Engine.Index
             final ParsedDocument doc = indexOperation.parsedDoc();
             final long tookInNanos = result.getTook();
             if (indexWarnThreshold >= 0 && tookInNanos > indexWarnThreshold) {
-                indexLogger.warn(IndexingSlowLogMessage.of(index, doc, tookInNanos, reformat, maxSourceCharsToLog));
+                indexLogger.warn(
+                    IndexingSlowLogMessage.of(
+                        this.slowLogFieldProvider.indexSlowLogFields(),
+                        index,
+                        doc,
+                        tookInNanos,
+                        reformat,
+                        maxSourceCharsToLog
+                    )
+                );
             } else if (indexInfoThreshold >= 0 && tookInNanos > indexInfoThreshold) {
-                indexLogger.info(IndexingSlowLogMessage.of(index, doc, tookInNanos, reformat, maxSourceCharsToLog));
+                indexLogger.info(
+                    IndexingSlowLogMessage.of(
+                        this.slowLogFieldProvider.indexSlowLogFields(),
+                        index,
+                        doc,
+                        tookInNanos,
+                        reformat,
+                        maxSourceCharsToLog
+                    )
+                );
             } else if (indexDebugThreshold >= 0 && tookInNanos > indexDebugThreshold) {
-                indexLogger.debug(IndexingSlowLogMessage.of(index, doc, tookInNanos, reformat, maxSourceCharsToLog));
+                indexLogger.debug(
+                    IndexingSlowLogMessage.of(
+                        this.slowLogFieldProvider.indexSlowLogFields(),
+                        index,
+                        doc,
+                        tookInNanos,
+                        reformat,
+                        maxSourceCharsToLog
+                    )
+                );
             } else if (indexTraceThreshold >= 0 && tookInNanos > indexTraceThreshold) {
-                indexLogger.trace(IndexingSlowLogMessage.of(index, doc, tookInNanos, reformat, maxSourceCharsToLog));
+                indexLogger.trace(
+                    IndexingSlowLogMessage.of(
+                        this.slowLogFieldProvider.indexSlowLogFields(),
+                        index,
+                        doc,
+                        tookInNanos,
+                        reformat,
+                        maxSourceCharsToLog
+                    )
+                );
             }
         }
     }
 
     static final class IndexingSlowLogMessage {
 
-        public static ESLogMessage of(Index index, ParsedDocument doc, long tookInNanos, boolean reformat, int maxSourceCharsToLog) {
+        public static ESLogMessage of(
+            Map<String, String> additionalFields,
+            Index index,
+            ParsedDocument doc,
+            long tookInNanos,
+            boolean reformat,
+            int maxSourceCharsToLog
+        ) {
 
             Map<String, Object> jsonFields = prepareMap(index, doc, tookInNanos, reformat, maxSourceCharsToLog);
+            jsonFields.putAll(additionalFields);
             return new ESLogMessage().withFields(jsonFields);
         }
 

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

@@ -44,7 +44,16 @@ public final class SearchSlowLog implements SearchOperationListener {
     private final Logger queryLogger;
     private final Logger fetchLogger;
 
+    private final SlowLogFieldProvider slowLogFieldProvider;
+
     static final String INDEX_SEARCH_SLOWLOG_PREFIX = "index.search.slowlog";
+
+    public static final Setting<Boolean> INDEX_SEARCH_SLOWLOG_INCLUDE_USER_SETTING = Setting.boolSetting(
+        INDEX_SEARCH_SLOWLOG_PREFIX + ".include.user",
+        false,
+        Property.Dynamic,
+        Property.IndexScope
+    );
     public static final Setting<TimeValue> INDEX_SEARCH_SLOWLOG_THRESHOLD_QUERY_WARN_SETTING = Setting.timeSetting(
         INDEX_SEARCH_SLOWLOG_PREFIX + ".threshold.query.warn",
         TimeValue.timeValueNanos(-1),
@@ -118,7 +127,10 @@ public final class SearchSlowLog implements SearchOperationListener {
 
     private static final ToXContent.Params FORMAT_PARAMS = new ToXContent.MapParams(Collections.singletonMap("pretty", "false"));
 
-    public SearchSlowLog(IndexSettings indexSettings) {
+    public SearchSlowLog(IndexSettings indexSettings, SlowLogFieldProvider slowLogFieldProvider) {
+        slowLogFieldProvider.init(indexSettings);
+        this.slowLogFieldProvider = slowLogFieldProvider;
+
         this.queryLogger = LogManager.getLogger(INDEX_SEARCH_SLOWLOG_PREFIX + ".query");
         this.fetchLogger = LogManager.getLogger(INDEX_SEARCH_SLOWLOG_PREFIX + ".fetch");
         Loggers.setLevel(this.fetchLogger, Level.TRACE);
@@ -154,33 +166,34 @@ public SearchSlowLog(IndexSettings indexSettings) {
     @Override
     public void onQueryPhase(SearchContext context, long tookInNanos) {
         if (queryWarnThreshold >= 0 && tookInNanos > queryWarnThreshold) {
-            queryLogger.warn(SearchSlowLogMessage.of(context, tookInNanos));
+            queryLogger.warn(SearchSlowLogMessage.of(this.slowLogFieldProvider.searchSlowLogFields(), context, tookInNanos));
         } else if (queryInfoThreshold >= 0 && tookInNanos > queryInfoThreshold) {
-            queryLogger.info(SearchSlowLogMessage.of(context, tookInNanos));
+            queryLogger.info(SearchSlowLogMessage.of(this.slowLogFieldProvider.searchSlowLogFields(), context, tookInNanos));
         } else if (queryDebugThreshold >= 0 && tookInNanos > queryDebugThreshold) {
-            queryLogger.debug(SearchSlowLogMessage.of(context, tookInNanos));
+            queryLogger.debug(SearchSlowLogMessage.of(this.slowLogFieldProvider.searchSlowLogFields(), context, tookInNanos));
         } else if (queryTraceThreshold >= 0 && tookInNanos > queryTraceThreshold) {
-            queryLogger.trace(SearchSlowLogMessage.of(context, tookInNanos));
+            queryLogger.trace(SearchSlowLogMessage.of(this.slowLogFieldProvider.searchSlowLogFields(), context, tookInNanos));
         }
     }
 
     @Override
     public void onFetchPhase(SearchContext context, long tookInNanos) {
         if (fetchWarnThreshold >= 0 && tookInNanos > fetchWarnThreshold) {
-            fetchLogger.warn(SearchSlowLogMessage.of(context, tookInNanos));
+            fetchLogger.warn(SearchSlowLogMessage.of(this.slowLogFieldProvider.searchSlowLogFields(), context, tookInNanos));
         } else if (fetchInfoThreshold >= 0 && tookInNanos > fetchInfoThreshold) {
-            fetchLogger.info(SearchSlowLogMessage.of(context, tookInNanos));
+            fetchLogger.info(SearchSlowLogMessage.of(this.slowLogFieldProvider.searchSlowLogFields(), context, tookInNanos));
         } else if (fetchDebugThreshold >= 0 && tookInNanos > fetchDebugThreshold) {
-            fetchLogger.debug(SearchSlowLogMessage.of(context, tookInNanos));
+            fetchLogger.debug(SearchSlowLogMessage.of(this.slowLogFieldProvider.searchSlowLogFields(), context, tookInNanos));
         } else if (fetchTraceThreshold >= 0 && tookInNanos > fetchTraceThreshold) {
-            fetchLogger.trace(SearchSlowLogMessage.of(context, tookInNanos));
+            fetchLogger.trace(SearchSlowLogMessage.of(this.slowLogFieldProvider.searchSlowLogFields(), context, tookInNanos));
         }
     }
 
     static final class SearchSlowLogMessage {
 
-        public static ESLogMessage of(SearchContext context, long tookInNanos) {
+        public static ESLogMessage of(Map<String, String> additionalFields, SearchContext context, long tookInNanos) {
             Map<String, Object> jsonFields = prepareMap(context, tookInNanos);
+            jsonFields.putAll(additionalFields);
             return new ESLogMessage().withFields(jsonFields);
         }
 

server/src/main/java/org/elasticsearch/index/SlowLogFieldProvider.java

@@ -0,0 +1,35 @@
+/*
+ * Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one
+ * or more contributor license agreements. Licensed under the Elastic License
+ * 2.0 and the Server Side Public License, v 1; you may not use this file except
+ * in compliance with, at your election, the Elastic License 2.0 or the Server
+ * Side Public License, v 1.
+ */
+
+package org.elasticsearch.index;
+
+import java.util.Map;
+
+/**
+ * Interface for providing additional fields to the slow log from a plugin.
+ * Intended to be loaded through SPI.
+ */
+public interface SlowLogFieldProvider {
+    /**
+     * Initialize field provider with index level settings to be able to listen for updates and set initial values
+     * @param indexSettings settings for the index
+     */
+    void init(IndexSettings indexSettings);
+
+    /**
+     * Slow log fields for indexing events
+     * @return map of field name to value
+     */
+    Map<String, String> indexSlowLogFields();
+
+    /**
+     * Slow log fields for search events
+     * @return map of field name to value
+     */
+    Map<String, String> searchSlowLogFields();
+}