From c6de455eb7acba79ca9e10b68204872db94378e7 Mon Sep 17 00:00:00 2001 From: Johannes Freden Jansson Date: Tue, 13 Feb 2024 13:08:49 +0100 Subject: [PATCH 1/4] Add user/auth information to slowlog --- docs/reference/index-modules/slowlog.asciidoc | 106 +++++- .../common/settings/IndexScopedSettings.java | 2 + .../org/elasticsearch/index/IndexModule.java | 7 +- .../elasticsearch/index/IndexingSlowLog.java | 65 +++- .../elasticsearch/index/SearchSlowLog.java | 33 +- .../index/SlowLogFieldProvider.java | 35 ++ .../elasticsearch/indices/IndicesService.java | 31 +- .../elasticsearch/index/IndexModuleTests.java | 18 +- .../index/IndexingSlowLogTests.java | 65 +++- .../index/SearchSlowLogTests.java | 45 ++- .../elasticsearch/test/cluster/LogType.java | 4 +- .../action/TransportResumeFollowAction.java | 2 + .../plugin/security/qa/slowlog/build.gradle | 10 + .../security/slowlog/SecuritySlowLogIT.java | 343 ++++++++++++++++++ .../security/src/main/java/module-info.java | 4 +- .../xpack/security/Security.java | 27 ++ .../slowlog/SecuritySlowLogFieldProvider.java | 57 +++ ...g.elasticsearch.index.SlowLogFieldProvider | 8 + .../xpack/security/SecurityTests.java | 4 +- .../xpack/watcher/WatcherPluginTests.java | 4 +- 20 files changed, 790 insertions(+), 80 deletions(-) create mode 100644 server/src/main/java/org/elasticsearch/index/SlowLogFieldProvider.java create mode 100644 x-pack/plugin/security/qa/slowlog/build.gradle create mode 100644 x-pack/plugin/security/qa/slowlog/src/javaRestTest/java/org/elasticsearch/xpack/security/slowlog/SecuritySlowLogIT.java create mode 100644 x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/slowlog/SecuritySlowLogFieldProvider.java create mode 100644 x-pack/plugin/security/src/main/resources/META-INF/services/org.elasticsearch.index.SlowLogFieldProvider diff --git a/docs/reference/index-modules/slowlog.asciidoc b/docs/reference/index-modules/slowlog.asciidoc index 55c0867e485f5..7e80bfad18ffd 100644 --- a/docs/reference/index-modules/slowlog.asciidoc +++ b/docs/reference/index-modules/slowlog.asciidoc @@ -58,29 +58,85 @@ 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": null, + "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.effective.name": "elastic", + "user.effective.realm": "reserved", + "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 also included +in Search Slow logs as an additional **elasticsearch.slowlog.id** field + +[source,js] +--------------------------- +{ + "@timestamp": "2024-02-21T12:42:37.255Z", + "log.level": "WARN", + "auth.type": "REALM", + "elasticsearch.slowlog.id": "MY_USER_ID", + "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.effective.name": "elastic", + "user.effective.realm": "reserved", + "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 @@ -119,6 +175,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 diff --git a/server/src/main/java/org/elasticsearch/common/settings/IndexScopedSettings.java b/server/src/main/java/org/elasticsearch/common/settings/IndexScopedSettings.java index 41dd840b0c0e7..452fc14025e2e 100644 --- a/server/src/main/java/org/elasticsearch/common/settings/IndexScopedSettings.java +++ b/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, diff --git a/server/src/main/java/org/elasticsearch/index/IndexModule.java b/server/src/main/java/org/elasticsearch/index/IndexModule.java index b768c2f5a7d28..06a5e13a208be 100644 --- a/server/src/main/java/org/elasticsearch/index/IndexModule.java +++ b/server/src/main/java/org/elasticsearch/index/IndexModule.java @@ -194,13 +194,14 @@ public IndexModule( final Map directoryFactories, final BooleanSupplier allowExpensiveQueries, final IndexNameExpressionResolver expressionResolver, - final Map recoveryStateFactories + final Map 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; diff --git a/server/src/main/java/org/elasticsearch/index/IndexingSlowLog.java b/server/src/main/java/org/elasticsearch/index/IndexingSlowLog.java index 7b0a46f022dad..14c2c5440bd24 100644 --- a/server/src/main/java/org/elasticsearch/index/IndexingSlowLog.java +++ b/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 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 { * characters 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 additionalFields, + Index index, + ParsedDocument doc, + long tookInNanos, + boolean reformat, + int maxSourceCharsToLog + ) { Map jsonFields = prepareMap(index, doc, tookInNanos, reformat, maxSourceCharsToLog); + jsonFields.putAll(additionalFields); return new ESLogMessage().withFields(jsonFields); } diff --git a/server/src/main/java/org/elasticsearch/index/SearchSlowLog.java b/server/src/main/java/org/elasticsearch/index/SearchSlowLog.java index c477f5e4978d5..eb227e6e1136d 100644 --- a/server/src/main/java/org/elasticsearch/index/SearchSlowLog.java +++ b/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 INDEX_SEARCH_SLOWLOG_INCLUDE_USER_SETTING = Setting.boolSetting( + INDEX_SEARCH_SLOWLOG_PREFIX + ".include.user", + false, + Property.Dynamic, + Property.IndexScope + ); public static final Setting 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 additionalFields, SearchContext context, long tookInNanos) { Map jsonFields = prepareMap(context, tookInNanos); + jsonFields.putAll(additionalFields); return new ESLogMessage().withFields(jsonFields); } diff --git a/server/src/main/java/org/elasticsearch/index/SlowLogFieldProvider.java b/server/src/main/java/org/elasticsearch/index/SlowLogFieldProvider.java new file mode 100644 index 0000000000000..c272ec23ef7e5 --- /dev/null +++ b/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 indexSlowLogFields(); + + /** + * Slow log fields for search events + * @return map of field name to value + */ + Map searchSlowLogFields(); +} diff --git a/server/src/main/java/org/elasticsearch/indices/IndicesService.java b/server/src/main/java/org/elasticsearch/indices/IndicesService.java index b47d10882a5c1..f218a7e170bcb 100644 --- a/server/src/main/java/org/elasticsearch/indices/IndicesService.java +++ b/server/src/main/java/org/elasticsearch/indices/IndicesService.java @@ -85,6 +85,7 @@ import org.elasticsearch.index.IndexNotFoundException; import org.elasticsearch.index.IndexService; import org.elasticsearch.index.IndexSettings; +import org.elasticsearch.index.SlowLogFieldProvider; import org.elasticsearch.index.analysis.AnalysisRegistry; import org.elasticsearch.index.bulk.stats.BulkStats; import org.elasticsearch.index.cache.request.ShardRequestCache; @@ -736,7 +737,8 @@ private synchronized IndexService createIndexService( directoryFactories, () -> allowExpensiveQueries, indexNameExpressionResolver, - recoveryStateFactories + recoveryStateFactories, + loadSlowLogFieldProvider() ); for (IndexingOperationListener operationListener : indexingOperationListeners) { indexModule.addIndexOperationListener(operationListener); @@ -812,7 +814,8 @@ public synchronized MapperService createIndexMapperServiceForValidation(IndexMet directoryFactories, () -> allowExpensiveQueries, indexNameExpressionResolver, - recoveryStateFactories + recoveryStateFactories, + loadSlowLogFieldProvider() ); pluginsService.forEach(p -> p.onIndexModule(indexModule)); return indexModule.newIndexMapperService(clusterService, parserConfig, mapperRegistry, scriptService); @@ -1390,6 +1393,30 @@ int numPendingDeletes(Index index) { } } + private SlowLogFieldProvider loadSlowLogFieldProvider() { + List slowLogFieldProviders = pluginsService.loadServiceProviders(SlowLogFieldProvider.class); + return new SlowLogFieldProvider() { + @Override + public void init(IndexSettings indexSettings) { + slowLogFieldProviders.forEach(provider -> provider.init(indexSettings)); + } + + @Override + public Map indexSlowLogFields() { + return slowLogFieldProviders.stream() + .flatMap(provider -> provider.indexSlowLogFields().entrySet().stream()) + .collect(Collectors.toMap(Map.Entry::getKey, Map.Entry::getValue)); + } + + @Override + public Map searchSlowLogFields() { + return slowLogFieldProviders.stream() + .flatMap(provider -> provider.searchSlowLogFields().entrySet().stream()) + .collect(Collectors.toMap(Map.Entry::getKey, Map.Entry::getValue)); + } + }; + } + /** * Checks if all pending deletes have completed. Used by tests to ensure we don't check directory contents * while deletion still ongoing. * The reason is that, on Windows, browsing the directory contents can interfere diff --git a/server/src/test/java/org/elasticsearch/index/IndexModuleTests.java b/server/src/test/java/org/elasticsearch/index/IndexModuleTests.java index 928a03eed2bd6..4e6f702b67252 100644 --- a/server/src/test/java/org/elasticsearch/index/IndexModuleTests.java +++ b/server/src/test/java/org/elasticsearch/index/IndexModuleTests.java @@ -232,7 +232,8 @@ public void testWrapperIsBound() throws IOException { Collections.emptyMap(), () -> true, indexNameExpressionResolver, - Collections.emptyMap() + Collections.emptyMap(), + mock(SlowLogFieldProvider.class) ); module.setReaderWrapper(s -> new Wrapper()); @@ -257,7 +258,8 @@ public void testRegisterIndexStore() throws IOException { indexStoreFactories, () -> true, indexNameExpressionResolver, - Collections.emptyMap() + Collections.emptyMap(), + mock(SlowLogFieldProvider.class) ); final IndexService indexService = newIndexService(module); @@ -280,7 +282,8 @@ public void testDirectoryWrapper() throws IOException { Map.of(), () -> true, indexNameExpressionResolver, - Collections.emptyMap() + Collections.emptyMap(), + mock(SlowLogFieldProvider.class) ); module.setDirectoryWrapper(new TestDirectoryWrapper()); @@ -631,7 +634,8 @@ public void testRegisterCustomRecoveryStateFactory() throws IOException { Collections.emptyMap(), () -> true, indexNameExpressionResolver, - recoveryStateFactories + recoveryStateFactories, + mock(SlowLogFieldProvider.class) ); final IndexService indexService = newIndexService(module); @@ -651,7 +655,8 @@ public void testIndexCommitListenerIsBound() throws IOException, ExecutionExcept Collections.emptyMap(), () -> true, indexNameExpressionResolver, - Collections.emptyMap() + Collections.emptyMap(), + mock(SlowLogFieldProvider.class) ); final AtomicLong lastAcquiredPrimaryTerm = new AtomicLong(); @@ -751,7 +756,8 @@ private static IndexModule createIndexModule( Collections.emptyMap(), () -> true, indexNameExpressionResolver, - Collections.emptyMap() + Collections.emptyMap(), + mock(SlowLogFieldProvider.class) ); } diff --git a/server/src/test/java/org/elasticsearch/index/IndexingSlowLogTests.java b/server/src/test/java/org/elasticsearch/index/IndexingSlowLogTests.java index fb83e817c052e..d8d5ab56c6e1d 100644 --- a/server/src/test/java/org/elasticsearch/index/IndexingSlowLogTests.java +++ b/server/src/test/java/org/elasticsearch/index/IndexingSlowLogTests.java @@ -39,6 +39,7 @@ import org.mockito.Mockito; import java.io.IOException; +import java.util.Map; import static org.hamcrest.Matchers.containsString; import static org.hamcrest.Matchers.emptyOrNullString; @@ -49,6 +50,7 @@ import static org.hamcrest.Matchers.not; import static org.hamcrest.Matchers.nullValue; import static org.hamcrest.Matchers.startsWith; +import static org.mockito.Mockito.mock; public class IndexingSlowLogTests extends ESTestCase { static MockAppender appender; @@ -71,7 +73,7 @@ public void testLevelPrecedence() { String uuid = UUIDs.randomBase64UUID(); IndexMetadata metadata = createIndexMetadata("index-precedence", settings(uuid)); IndexSettings settings = new IndexSettings(metadata, Settings.EMPTY); - IndexingSlowLog log = new IndexingSlowLog(settings); + IndexingSlowLog log = new IndexingSlowLog(settings, mock(SlowLogFieldProvider.class)); ParsedDocument doc = EngineTestCase.createParsedDoc("1", null); Engine.Index index = new Engine.Index(new Term("_id", Uid.encodeId("doc_id")), randomNonNegativeLong(), doc); @@ -132,7 +134,7 @@ public void testTwoLoggersDifferentLevel() { ), Settings.EMPTY ); - IndexingSlowLog log1 = new IndexingSlowLog(index1Settings); + IndexingSlowLog log1 = new IndexingSlowLog(index1Settings, mock(SlowLogFieldProvider.class)); IndexSettings index2Settings = new IndexSettings( createIndexMetadata( @@ -145,7 +147,7 @@ public void testTwoLoggersDifferentLevel() { ), Settings.EMPTY ); - IndexingSlowLog log2 = new IndexingSlowLog(index2Settings); + IndexingSlowLog log2 = new IndexingSlowLog(index2Settings, mock(SlowLogFieldProvider.class)); ParsedDocument doc = EngineTestCase.createParsedDoc("1", null); Engine.Index index = new Engine.Index(new Term("_id", Uid.encodeId("doc_id")), randomNonNegativeLong(), doc); @@ -169,12 +171,12 @@ public void testMultipleSlowLoggersUseSingleLog4jLogger() { LoggerContext context = (LoggerContext) LogManager.getContext(false); IndexSettings index1Settings = new IndexSettings(createIndexMetadata("index1", settings(UUIDs.randomBase64UUID())), Settings.EMPTY); - IndexingSlowLog log1 = new IndexingSlowLog(index1Settings); + IndexingSlowLog log1 = new IndexingSlowLog(index1Settings, mock(SlowLogFieldProvider.class)); int numberOfLoggersBefore = context.getLoggers().size(); IndexSettings index2Settings = new IndexSettings(createIndexMetadata("index2", settings(UUIDs.randomBase64UUID())), Settings.EMPTY); - IndexingSlowLog log2 = new IndexingSlowLog(index2Settings); + IndexingSlowLog log2 = new IndexingSlowLog(index2Settings, mock(SlowLogFieldProvider.class)); context = (LoggerContext) LogManager.getContext(false); int numberOfLoggersAfter = context.getLoggers().size(); @@ -210,7 +212,7 @@ public void testSlowLogMessageHasJsonFields() throws IOException { ); Index index = new Index("foo", "123"); // Turning off document logging doesn't log source[] - ESLogMessage p = IndexingSlowLogMessage.of(index, pd, 10, true, 0); + ESLogMessage p = IndexingSlowLogMessage.of(Map.of(), index, pd, 10, true, 0); assertThat(p.get("elasticsearch.slowlog.message"), equalTo("[foo/123]")); assertThat(p.get("elasticsearch.slowlog.took"), equalTo("10nanos")); @@ -220,7 +222,36 @@ public void testSlowLogMessageHasJsonFields() throws IOException { assertThat(p.get("elasticsearch.slowlog.source"), is(emptyOrNullString())); // Turning on document logging logs the whole thing - p = IndexingSlowLogMessage.of(index, pd, 10, true, Integer.MAX_VALUE); + p = IndexingSlowLogMessage.of(Map.of(), index, pd, 10, true, Integer.MAX_VALUE); + assertThat(p.get("elasticsearch.slowlog.source"), containsString("{\\\"foo\\\":\\\"bar\\\"}")); + } + + public void testSlowLogMessageHasAdditionalFields() throws IOException { + BytesReference source = BytesReference.bytes(JsonXContent.contentBuilder().startObject().field("foo", "bar").endObject()); + ParsedDocument pd = new ParsedDocument( + new NumericDocValuesField("version", 1), + SeqNoFieldMapper.SequenceIDFields.emptySeqID(), + "id", + "routingValue", + null, + source, + XContentType.JSON, + null + ); + Index index = new Index("foo", "123"); + // Turning off document logging doesn't log source[] + ESLogMessage p = IndexingSlowLogMessage.of(Map.of("field1", "value1", "field2", "value2"), index, pd, 10, true, 0); + assertThat(p.get("field1"), equalTo("value1")); + assertThat(p.get("field2"), equalTo("value2")); + assertThat(p.get("elasticsearch.slowlog.message"), equalTo("[foo/123]")); + assertThat(p.get("elasticsearch.slowlog.took"), equalTo("10nanos")); + assertThat(p.get("elasticsearch.slowlog.took_millis"), equalTo("0")); + assertThat(p.get("elasticsearch.slowlog.id"), equalTo("id")); + assertThat(p.get("elasticsearch.slowlog.routing"), equalTo("routingValue")); + assertThat(p.get("elasticsearch.slowlog.source"), is(emptyOrNullString())); + + // Turning on document logging logs the whole thing + p = IndexingSlowLogMessage.of(Map.of(), index, pd, 10, true, Integer.MAX_VALUE); assertThat(p.get("elasticsearch.slowlog.source"), containsString("{\\\"foo\\\":\\\"bar\\\"}")); } @@ -238,7 +269,7 @@ public void testEmptyRoutingField() throws IOException { ); Index index = new Index("foo", "123"); - ESLogMessage p = IndexingSlowLogMessage.of(index, pd, 10, true, 0); + ESLogMessage p = IndexingSlowLogMessage.of(Map.of(), index, pd, 10, true, 0); assertThat(p.get("routing"), nullValue()); } @@ -256,19 +287,19 @@ public void testSlowLogParsedDocumentPrinterSourceToLog() throws IOException { ); Index index = new Index("foo", "123"); // Turning off document logging doesn't log source[] - ESLogMessage p = IndexingSlowLogMessage.of(index, pd, 10, true, 0); + ESLogMessage p = IndexingSlowLogMessage.of(Map.of(), index, pd, 10, true, 0); assertThat(p.getFormattedMessage(), not(containsString("source["))); // Turning on document logging logs the whole thing - p = IndexingSlowLogMessage.of(index, pd, 10, true, Integer.MAX_VALUE); + p = IndexingSlowLogMessage.of(Map.of(), index, pd, 10, true, Integer.MAX_VALUE); assertThat(p.get("elasticsearch.slowlog.source"), equalTo("{\\\"foo\\\":\\\"bar\\\"}")); // And you can truncate the source - p = IndexingSlowLogMessage.of(index, pd, 10, true, 3); + p = IndexingSlowLogMessage.of(Map.of(), index, pd, 10, true, 3); assertThat(p.get("elasticsearch.slowlog.source"), equalTo("{\\\"f")); // And you can truncate the source - p = IndexingSlowLogMessage.of(index, pd, 10, true, 3); + p = IndexingSlowLogMessage.of(Map.of(), index, pd, 10, true, 3); assertThat(p.get("elasticsearch.slowlog.source"), containsString("{\\\"f")); assertThat(p.get("elasticsearch.slowlog.message"), startsWith("[foo/123]")); assertThat(p.get("elasticsearch.slowlog.took"), containsString("10nanos")); @@ -288,7 +319,7 @@ public void testSlowLogParsedDocumentPrinterSourceToLog() throws IOException { final XContentParseException e = expectThrows( XContentParseException.class, - () -> IndexingSlowLogMessage.of(index, doc, 10, true, 3) + () -> IndexingSlowLogMessage.of(Map.of(), index, doc, 10, true, 3) ); assertThat( e, @@ -311,7 +342,7 @@ public void testReformatSetting() { .build() ); IndexSettings settings = new IndexSettings(metadata, Settings.EMPTY); - IndexingSlowLog log = new IndexingSlowLog(settings); + IndexingSlowLog log = new IndexingSlowLog(settings, mock(SlowLogFieldProvider.class)); assertFalse(log.isReformat()); settings.updateIndexMetadata( newIndexMeta("index", Settings.builder().put(IndexingSlowLog.INDEX_INDEXING_SLOWLOG_REFORMAT_SETTING.getKey(), "true").build()) @@ -328,7 +359,7 @@ public void testReformatSetting() { metadata = newIndexMeta("index", Settings.builder().put(IndexMetadata.SETTING_VERSION_CREATED, IndexVersion.current()).build()); settings = new IndexSettings(metadata, Settings.EMPTY); - log = new IndexingSlowLog(settings); + log = new IndexingSlowLog(settings, mock(SlowLogFieldProvider.class)); assertTrue(log.isReformat()); try { settings.updateIndexMetadata( @@ -361,7 +392,7 @@ public void testSetLevels() { .build() ); IndexSettings settings = new IndexSettings(metadata, Settings.EMPTY); - IndexingSlowLog log = new IndexingSlowLog(settings); + IndexingSlowLog log = new IndexingSlowLog(settings, mock(SlowLogFieldProvider.class)); assertEquals(TimeValue.timeValueMillis(100).nanos(), log.getIndexTraceThreshold()); assertEquals(TimeValue.timeValueMillis(200).nanos(), log.getIndexDebugThreshold()); assertEquals(TimeValue.timeValueMillis(300).nanos(), log.getIndexInfoThreshold()); @@ -392,7 +423,7 @@ public void testSetLevels() { assertEquals(TimeValue.timeValueMillis(-1).nanos(), log.getIndexWarnThreshold()); settings = new IndexSettings(metadata, Settings.EMPTY); - log = new IndexingSlowLog(settings); + log = new IndexingSlowLog(settings, mock(SlowLogFieldProvider.class)); assertEquals(TimeValue.timeValueMillis(-1).nanos(), log.getIndexTraceThreshold()); assertEquals(TimeValue.timeValueMillis(-1).nanos(), log.getIndexDebugThreshold()); diff --git a/server/src/test/java/org/elasticsearch/index/SearchSlowLogTests.java b/server/src/test/java/org/elasticsearch/index/SearchSlowLogTests.java index 2fa3216ad5556..a50092a0b8d12 100644 --- a/server/src/test/java/org/elasticsearch/index/SearchSlowLogTests.java +++ b/server/src/test/java/org/elasticsearch/index/SearchSlowLogTests.java @@ -36,12 +36,14 @@ import java.util.Arrays; import java.util.Collections; import java.util.List; +import java.util.Map; import static org.hamcrest.Matchers.containsString; 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.mockito.Mockito.mock; public class SearchSlowLogTests extends ESSingleNodeTestCase { static MockAppender appender; @@ -92,7 +94,7 @@ public void testLevelPrecedence() { try (SearchContext ctx = searchContextWithSourceAndTask(createIndex("index"))) { String uuid = UUIDs.randomBase64UUID(); IndexSettings settings = new IndexSettings(createIndexMetadata("index", settings(uuid)), Settings.EMPTY); - SearchSlowLog log = new SearchSlowLog(settings); + SearchSlowLog log = new SearchSlowLog(settings, mock(SlowLogFieldProvider.class)); // For this test, when level is not breached, the level below should be used. { @@ -176,7 +178,7 @@ public void testTwoLoggersDifferentLevel() { ), Settings.EMPTY ); - SearchSlowLog log1 = new SearchSlowLog(settings1); + SearchSlowLog log1 = new SearchSlowLog(settings1, mock(SlowLogFieldProvider.class)); IndexSettings settings2 = new IndexSettings( createIndexMetadata( @@ -189,7 +191,7 @@ public void testTwoLoggersDifferentLevel() { ), Settings.EMPTY ); - SearchSlowLog log2 = new SearchSlowLog(settings2); + SearchSlowLog log2 = new SearchSlowLog(settings2, mock(SlowLogFieldProvider.class)); { // threshold set on WARN only, should not log @@ -212,7 +214,7 @@ public void testMultipleSlowLoggersUseSingleLog4jLogger() { try (SearchContext ctx1 = searchContextWithSourceAndTask(createIndex("index-1"))) { IndexSettings settings1 = new IndexSettings(createIndexMetadata("index-1", settings(UUIDs.randomBase64UUID())), Settings.EMPTY); - SearchSlowLog log1 = new SearchSlowLog(settings1); + SearchSlowLog log1 = new SearchSlowLog(settings1, mock(SlowLogFieldProvider.class)); int numberOfLoggersBefore = context.getLoggers().size(); try (SearchContext ctx2 = searchContextWithSourceAndTask(createIndex("index-2"))) { @@ -220,7 +222,7 @@ public void testMultipleSlowLoggersUseSingleLog4jLogger() { createIndexMetadata("index-2", settings(UUIDs.randomBase64UUID())), Settings.EMPTY ); - SearchSlowLog log2 = new SearchSlowLog(settings2); + SearchSlowLog log2 = new SearchSlowLog(settings2, mock(SlowLogFieldProvider.class)); int numberOfLoggersAfter = context.getLoggers().size(); assertThat(numberOfLoggersAfter, equalTo(numberOfLoggersBefore)); @@ -235,7 +237,7 @@ private IndexMetadata createIndexMetadata(String index, Settings.Builder put) { public void testSlowLogHasJsonFields() throws IOException { IndexService index = createIndex("foo"); try (SearchContext searchContext = searchContextWithSourceAndTask(index)) { - ESLogMessage p = SearchSlowLog.SearchSlowLogMessage.of(searchContext, 10); + ESLogMessage p = SearchSlowLog.SearchSlowLogMessage.of(Map.of(), searchContext, 10); assertThat(p.get("elasticsearch.slowlog.message"), equalTo("[foo][0]")); assertThat(p.get("elasticsearch.slowlog.took"), equalTo("10nanos")); @@ -248,6 +250,23 @@ public void testSlowLogHasJsonFields() throws IOException { } } + public void testSlowLogHasAdditionalFields() throws IOException { + IndexService index = createIndex("foo"); + try (SearchContext searchContext = searchContextWithSourceAndTask(index)) { + ESLogMessage p = SearchSlowLog.SearchSlowLogMessage.of(Map.of("field1", "value1", "field2", "value2"), searchContext, 10); + assertThat(p.get("field1"), equalTo("value1")); + assertThat(p.get("field2"), equalTo("value2")); + assertThat(p.get("elasticsearch.slowlog.message"), equalTo("[foo][0]")); + assertThat(p.get("elasticsearch.slowlog.took"), equalTo("10nanos")); + assertThat(p.get("elasticsearch.slowlog.took_millis"), equalTo("0")); + assertThat(p.get("elasticsearch.slowlog.total_hits"), equalTo("-1")); + assertThat(p.get("elasticsearch.slowlog.stats"), equalTo("[]")); + assertThat(p.get("elasticsearch.slowlog.search_type"), Matchers.nullValue()); + assertThat(p.get("elasticsearch.slowlog.total_shards"), equalTo("1")); + assertThat(p.get("elasticsearch.slowlog.source"), equalTo("{\\\"query\\\":{\\\"match_all\\\":{\\\"boost\\\":1.0}}}")); + } + } + public void testSlowLogsWithStats() throws IOException { IndexService index = createIndex("foo"); try (SearchContext searchContext = createSearchContext(index, "group1")) { @@ -257,7 +276,7 @@ public void testSlowLogsWithStats() throws IOException { new SearchShardTask(0, "n/a", "n/a", "test", null, Collections.singletonMap(Task.X_OPAQUE_ID_HTTP_HEADER, "my_id")) ); - ESLogMessage p = SearchSlowLog.SearchSlowLogMessage.of(searchContext, 10); + ESLogMessage p = SearchSlowLog.SearchSlowLogMessage.of(Map.of(), searchContext, 10); assertThat(p.get("elasticsearch.slowlog.stats"), equalTo("[\\\"group1\\\"]")); } @@ -267,7 +286,7 @@ public void testSlowLogsWithStats() throws IOException { searchContext.setTask( new SearchShardTask(0, "n/a", "n/a", "test", null, Collections.singletonMap(Task.X_OPAQUE_ID_HTTP_HEADER, "my_id")) ); - ESLogMessage p = SearchSlowLog.SearchSlowLogMessage.of(searchContext, 10); + ESLogMessage p = SearchSlowLog.SearchSlowLogMessage.of(Map.of(), searchContext, 10); assertThat(p.get("elasticsearch.slowlog.stats"), equalTo("[\\\"group1\\\", \\\"group2\\\"]")); } } @@ -275,7 +294,7 @@ public void testSlowLogsWithStats() throws IOException { public void testSlowLogSearchContextPrinterToLog() throws IOException { IndexService index = createIndex("foo"); try (SearchContext searchContext = searchContextWithSourceAndTask(index)) { - ESLogMessage p = SearchSlowLog.SearchSlowLogMessage.of(searchContext, 10); + ESLogMessage p = SearchSlowLog.SearchSlowLogMessage.of(Map.of(), searchContext, 10); assertThat(p.get("elasticsearch.slowlog.message"), equalTo("[foo][0]")); // Makes sure that output doesn't contain any new lines assertThat(p.get("elasticsearch.slowlog.source"), not(containsString("\n"))); @@ -295,7 +314,7 @@ public void testSetQueryLevels() { .build() ); IndexSettings settings = new IndexSettings(metadata, Settings.EMPTY); - SearchSlowLog log = new SearchSlowLog(settings); + SearchSlowLog log = new SearchSlowLog(settings, mock(SlowLogFieldProvider.class)); assertEquals(TimeValue.timeValueMillis(100).nanos(), log.getQueryTraceThreshold()); assertEquals(TimeValue.timeValueMillis(200).nanos(), log.getQueryDebugThreshold()); assertEquals(TimeValue.timeValueMillis(300).nanos(), log.getQueryInfoThreshold()); @@ -326,7 +345,7 @@ public void testSetQueryLevels() { assertEquals(TimeValue.timeValueMillis(-1).nanos(), log.getQueryWarnThreshold()); settings = new IndexSettings(metadata, Settings.EMPTY); - log = new SearchSlowLog(settings); + log = new SearchSlowLog(settings, mock(SlowLogFieldProvider.class)); assertEquals(TimeValue.timeValueMillis(-1).nanos(), log.getQueryTraceThreshold()); assertEquals(TimeValue.timeValueMillis(-1).nanos(), log.getQueryDebugThreshold()); @@ -401,7 +420,7 @@ public void testSetFetchLevels() { .build() ); IndexSettings settings = new IndexSettings(metadata, Settings.EMPTY); - SearchSlowLog log = new SearchSlowLog(settings); + SearchSlowLog log = new SearchSlowLog(settings, mock(SlowLogFieldProvider.class)); assertEquals(TimeValue.timeValueMillis(100).nanos(), log.getFetchTraceThreshold()); assertEquals(TimeValue.timeValueMillis(200).nanos(), log.getFetchDebugThreshold()); assertEquals(TimeValue.timeValueMillis(300).nanos(), log.getFetchInfoThreshold()); @@ -432,7 +451,7 @@ public void testSetFetchLevels() { assertEquals(TimeValue.timeValueMillis(-1).nanos(), log.getFetchWarnThreshold()); settings = new IndexSettings(metadata, Settings.EMPTY); - log = new SearchSlowLog(settings); + log = new SearchSlowLog(settings, mock(SlowLogFieldProvider.class)); assertEquals(TimeValue.timeValueMillis(-1).nanos(), log.getFetchTraceThreshold()); assertEquals(TimeValue.timeValueMillis(-1).nanos(), log.getFetchDebugThreshold()); diff --git a/test/test-clusters/src/main/java/org/elasticsearch/test/cluster/LogType.java b/test/test-clusters/src/main/java/org/elasticsearch/test/cluster/LogType.java index 96178e621e018..76468b9be9ed5 100644 --- a/test/test-clusters/src/main/java/org/elasticsearch/test/cluster/LogType.java +++ b/test/test-clusters/src/main/java/org/elasticsearch/test/cluster/LogType.java @@ -11,7 +11,9 @@ public enum LogType { SERVER("%s.log"), SERVER_JSON("%s_server.json"), - AUDIT("%s_audit.json"); + AUDIT("%s_audit.json"), + SEARCH_SLOW("%s_index_search_slowlog.json"), + INDEXING_SLOW("%s_index_indexing_slowlog.json"); private final String filenameFormat; diff --git a/x-pack/plugin/ccr/src/main/java/org/elasticsearch/xpack/ccr/action/TransportResumeFollowAction.java b/x-pack/plugin/ccr/src/main/java/org/elasticsearch/xpack/ccr/action/TransportResumeFollowAction.java index f13ac2f2845b0..cad1a37a3a17d 100644 --- a/x-pack/plugin/ccr/src/main/java/org/elasticsearch/xpack/ccr/action/TransportResumeFollowAction.java +++ b/x-pack/plugin/ccr/src/main/java/org/elasticsearch/xpack/ccr/action/TransportResumeFollowAction.java @@ -505,12 +505,14 @@ static String[] extractLeaderShardHistoryUUIDs(Map ccrIndexMetad 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_MAX_MERGE_AT_ONCE_SETTING, diff --git a/x-pack/plugin/security/qa/slowlog/build.gradle b/x-pack/plugin/security/qa/slowlog/build.gradle new file mode 100644 index 0000000000000..5bf7b0173fd69 --- /dev/null +++ b/x-pack/plugin/security/qa/slowlog/build.gradle @@ -0,0 +1,10 @@ +apply plugin: 'elasticsearch.internal-java-rest-test' + +dependencies { + javaRestTestImplementation project(':x-pack:plugin:core') + javaRestTestImplementation project(':x-pack:plugin:security') +} + +tasks.named('javaRestTest') { + usesDefaultDistribution() +} diff --git a/x-pack/plugin/security/qa/slowlog/src/javaRestTest/java/org/elasticsearch/xpack/security/slowlog/SecuritySlowLogIT.java b/x-pack/plugin/security/qa/slowlog/src/javaRestTest/java/org/elasticsearch/xpack/security/slowlog/SecuritySlowLogIT.java new file mode 100644 index 0000000000000..0678e878cf4df --- /dev/null +++ b/x-pack/plugin/security/qa/slowlog/src/javaRestTest/java/org/elasticsearch/xpack/security/slowlog/SecuritySlowLogIT.java @@ -0,0 +1,343 @@ +/* + * 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; you may not use this file except in compliance with the Elastic License + * 2.0. + */ + +package org.elasticsearch.xpack.security.slowlog; + +import org.apache.http.HttpHeaders; +import org.elasticsearch.client.Request; +import org.elasticsearch.client.RequestOptions; +import org.elasticsearch.client.Response; +import org.elasticsearch.common.io.Streams; +import org.elasticsearch.common.settings.SecureString; +import org.elasticsearch.common.settings.Settings; +import org.elasticsearch.common.util.concurrent.ThreadContext; +import org.elasticsearch.common.xcontent.XContentHelper; +import org.elasticsearch.core.Strings; +import org.elasticsearch.test.cluster.ElasticsearchCluster; +import org.elasticsearch.test.cluster.LogType; +import org.elasticsearch.test.cluster.local.distribution.DistributionType; +import org.elasticsearch.test.rest.ESRestTestCase; +import org.elasticsearch.xcontent.XContentType; +import org.junit.ClassRule; + +import java.io.IOException; +import java.nio.charset.StandardCharsets; +import java.util.ArrayList; +import java.util.Base64; +import java.util.List; +import java.util.Map; +import java.util.concurrent.TimeUnit; +import java.util.function.Consumer; + +import static org.hamcrest.collection.IsIn.in; +import static org.hamcrest.core.Every.everyItem; +import static org.hamcrest.core.IsNot.not; + +public class SecuritySlowLogIT extends ESRestTestCase { + + private record TestIndexData( + String name, + boolean searchSlowLogEnabled, + boolean indexSlowLogEnabled, + boolean searchSlowLogUserEnabled, + boolean indexSlowLogUserEnabled + ) {} + + private static int currentSearchLogIndex = 0; + private static int currentIndexLogIndex = 0; + + @ClassRule + public static ElasticsearchCluster cluster = ElasticsearchCluster.local() + .nodes(1) + .distribution(DistributionType.DEFAULT) + .setting("xpack.security.enabled", "true") + .user("admin_user", "admin-password") + .user("api_user", "api-password", "superuser", false) + .build(); + + @Override + protected Settings restAdminSettings() { + String token = basicAuthHeaderValue("admin_user", new SecureString("admin-password".toCharArray())); + return Settings.builder().put(ThreadContext.PREFIX + ".Authorization", token).build(); + } + + @Override + protected Settings restClientSettings() { + String token = basicAuthHeaderValue("api_user", new SecureString("api-password".toCharArray())); + return Settings.builder().put(ThreadContext.PREFIX + ".Authorization", token).build(); + } + + @Override + protected String getTestRestCluster() { + return cluster.getHttpAddresses(); + } + + public void testSlowLogWithApiUser() throws Exception { + List testIndices = randomTestIndexData(); + for (TestIndexData testData : testIndices) { + searchSomeData(testData.name); + indexSomeData(testData.name); + } + + Map expectedUser = Map.of( + "user.name", + "api_user", + "user.effective.name", + "api_user", + "user.realm", + "default_file", + "user.effective.realm", + "default_file", + "auth.type", + "REALM" + ); + + verifySearchSlowLogMatchesTestData(testIndices, expectedUser); + verifyIndexSlowLogMatchesTestData(testIndices, expectedUser); + } + + public void testSlowLogWithApiKey() throws Exception { + List testIndices = randomTestIndexData(); + String apiKeyName = randomAlphaOfLengthBetween(10, 15); + Map createApiKeyResponse = createApiKey( + apiKeyName, + basicAuthHeaderValue("admin_user", new SecureString("admin-password".toCharArray())) + ); + String apiKeyHeader = Base64.getEncoder() + .encodeToString( + (createApiKeyResponse.get("id") + ":" + createApiKeyResponse.get("api_key").toString()).getBytes(StandardCharsets.UTF_8) + ); + + for (TestIndexData testData : testIndices) { + final RequestOptions requestOptions = RequestOptions.DEFAULT.toBuilder() + .addHeader("Authorization", "ApiKey " + apiKeyHeader) + .build(); + searchSomeData(testData.name, requestOptions); + indexSomeData(testData.name, requestOptions); + } + + Map expectedUser = Map.of( + "user.name", + "admin_user", + "user.effective.name", + "admin_user", + "user.realm", + "_es_api_key", + "user.effective.realm", + "_es_api_key", + "auth.type", + "API_KEY", + "apikey.id", + createApiKeyResponse.get("id"), + "apikey.name", + apiKeyName + ); + + verifySearchSlowLogMatchesTestData(testIndices, expectedUser); + verifyIndexSlowLogMatchesTestData(testIndices, expectedUser); + } + + public void testSlowLogWithRunAs() throws Exception { + List testIndices = randomTestIndexData(); + + for (TestIndexData testData : testIndices) { + final RequestOptions requestOptions = RequestOptions.DEFAULT.toBuilder() + .addHeader("es-security-runas-user", "api_user") + .addHeader("Authorization", basicAuthHeaderValue("admin_user", new SecureString("admin-password".toCharArray()))) + .build(); + searchSomeData(testData.name, requestOptions); + indexSomeData(testData.name, requestOptions); + } + + Map expectedUser = Map.of( + "user.name", + "admin_user", + "user.effective.name", + "api_user", + "user.realm", + "default_file", + "user.effective.realm", + "default_file", + "auth.type", + "REALM" + ); + + verifySearchSlowLogMatchesTestData(testIndices, expectedUser); + verifyIndexSlowLogMatchesTestData(testIndices, expectedUser); + } + + public void testSlowLogWithServiceAccount() throws Exception { + List testIndices = randomTestIndexData(); + Map createServiceAccountResponse = createServiceAccountToken(); + @SuppressWarnings("unchecked") + String tokenValue = ((Map) createServiceAccountResponse.get("token")).get("value").toString(); + + for (TestIndexData testData : testIndices) { + final RequestOptions requestOptions = RequestOptions.DEFAULT.toBuilder() + .addHeader("Authorization", "Bearer " + tokenValue) + .build(); + searchSomeData(testData.name, requestOptions); + indexSomeData(testData.name, requestOptions); + } + + Map expectedUser = Map.of( + "user.name", + "elastic/enterprise-search-server", + "user.effective.name", + "elastic/enterprise-search-server", + "user.realm", + "_service_account", + "user.effective.realm", + "_service_account", + "auth.type", + "TOKEN" + ); + + verifySearchSlowLogMatchesTestData(testIndices, expectedUser); + verifyIndexSlowLogMatchesTestData(testIndices, expectedUser); + } + + private static void enableSearchSlowLog(String index, boolean includeUser) throws IOException { + final Request request = new Request("PUT", "/" + index + "/_settings"); + request.setJsonEntity( + "{\"index.search.slowlog.threshold.query." + + randomFrom("trace", "warn", "debug", "info") + + "\": \"0\", " + + "\"index.search.slowlog.include.user\": " + + includeUser + + "}" + ); + client().performRequest(request); + } + + private static void enableIndexingSlowLog(String index, boolean includeUser) throws IOException { + final Request request = new Request("PUT", "/" + index + "/_settings"); + request.setJsonEntity( + "{\"index.indexing.slowlog.threshold.index." + + randomFrom("trace", "warn", "debug", "info") + + "\": \"0\", " + + "\"index.indexing.slowlog.include.user\": " + + includeUser + + "}" + ); + client().performRequest(request); + } + + private static void indexSomeData(String index) throws IOException { + indexSomeData(index, RequestOptions.DEFAULT.toBuilder().build()); + } + + private static void searchSomeData(String index) throws IOException { + searchSomeData(index, RequestOptions.DEFAULT.toBuilder().build()); + } + + private static void indexSomeData(String index, RequestOptions requestOptions) throws IOException { + final Request request = new Request("PUT", "/" + index + "/_doc/1"); + request.setOptions(requestOptions); + request.setJsonEntity("{ \"foobar\" : true }"); + client().performRequest(request); + } + + private static void searchSomeData(String index, RequestOptions requestOptions) throws IOException { + Request request = new Request("GET", "/" + index + "/_search"); + request.setOptions(requestOptions); + client().performRequest(request); + } + + private static void setupTestIndex(TestIndexData testIndexData) throws IOException { + indexSomeData(testIndexData.name); + if (testIndexData.indexSlowLogEnabled) { + enableIndexingSlowLog(testIndexData.name, testIndexData.indexSlowLogUserEnabled); + } + if (testIndexData.searchSlowLogEnabled) { + enableSearchSlowLog(testIndexData.name, testIndexData.searchSlowLogUserEnabled); + } + } + + private static List randomTestIndexData() throws IOException { + List testData = new ArrayList<>(); + for (int i = 0; i < randomIntBetween(1, 10); i++) { + TestIndexData randomTestData = new TestIndexData( + "search-" + randomAlphaOfLengthBetween(5, 10).toLowerCase() + "-" + i, + randomBoolean(), + randomBoolean(), + randomBoolean(), + randomBoolean() + ); + setupTestIndex(randomTestData); + testData.add(randomTestData); + } + return testData; + } + + private void verifySearchSlowLogMatchesTestData(List testIndices, Map expectedUserData) + throws Exception { + verifySlowLog(logLines -> { + for (TestIndexData testIndex : testIndices) { + if (testIndex.searchSlowLogEnabled) { + Map logLine = logLines.get(currentSearchLogIndex); + if (testIndex.searchSlowLogUserEnabled) { + assertThat(expectedUserData.entrySet(), everyItem(in(logLine.entrySet()))); + } else { + assertThat(expectedUserData.entrySet(), everyItem(not(in(logLine.entrySet())))); + } + currentSearchLogIndex++; + } + } + }, LogType.SEARCH_SLOW); + } + + private void verifyIndexSlowLogMatchesTestData(List testIndices, Map expectedUserData) throws Exception { + verifySlowLog(logLines -> { + for (TestIndexData testIndex : testIndices) { + if (testIndex.indexSlowLogEnabled) { + Map logLine = logLines.get(currentIndexLogIndex); + if (testIndex.indexSlowLogUserEnabled) { + assertThat(expectedUserData.entrySet(), everyItem(in(logLine.entrySet()))); + } else { + assertThat(expectedUserData.entrySet(), everyItem(not(in(logLine.entrySet())))); + } + currentIndexLogIndex++; + } + } + }, LogType.INDEXING_SLOW); + } + + private static void verifySlowLog(Consumer>> logVerifier, LogType logType) throws Exception { + assertBusy(() -> { + try (var slowLog = cluster.getNodeLog(0, logType)) { + final List lines = Streams.readAllLines(slowLog); + logVerifier.accept( + lines.stream().map(line -> XContentHelper.convertToMap(XContentType.JSON.xContent(), line, true)).toList() + ); + } + }, 5, TimeUnit.SECONDS); + } + + private static Map createApiKey(String name, String authHeader) throws IOException { + final Request request = new Request("POST", "/_security/api_key"); + + request.setJsonEntity(Strings.format(""" + {"name":"%s"}""", name)); + + request.setOptions(request.getOptions().toBuilder().addHeader(HttpHeaders.AUTHORIZATION, authHeader)); + final Response response = client().performRequest(request); + assertOK(response); + return responseAsMap(response); + } + + private static Map createServiceAccountToken() throws IOException { + final Request createServiceTokenRequest = new Request( + "POST", + "/_security/service/elastic/enterprise-search-server/credential/token" + ); + final Response createServiceTokenResponse = adminClient().performRequest(createServiceTokenRequest); + assertOK(createServiceTokenResponse); + + return responseAsMap(createServiceTokenResponse); + } +} diff --git a/x-pack/plugin/security/src/main/java/module-info.java b/x-pack/plugin/security/src/main/java/module-info.java index 4b99ab5ed6b2c..9806650f99094 100644 --- a/x-pack/plugin/security/src/main/java/module-info.java +++ b/x-pack/plugin/security/src/main/java/module-info.java @@ -65,8 +65,10 @@ exports org.elasticsearch.xpack.security.action.user to org.elasticsearch.server; exports org.elasticsearch.xpack.security.action.settings to org.elasticsearch.server; exports org.elasticsearch.xpack.security.operator to org.elasticsearch.internal.operator, org.elasticsearch.internal.security; - exports org.elasticsearch.xpack.security.authc to org.elasticsearch.xcontent; + exports org.elasticsearch.xpack.security.slowlog to org.elasticsearch.server; + + provides org.elasticsearch.index.SlowLogFieldProvider with org.elasticsearch.xpack.security.slowlog.SecuritySlowLogFieldProvider; provides org.elasticsearch.cli.CliToolProvider with diff --git a/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/Security.java b/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/Security.java index 3beff69849a58..f1ddbe9ef8ce7 100644 --- a/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/Security.java +++ b/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/Security.java @@ -174,13 +174,16 @@ import org.elasticsearch.xpack.core.security.action.user.HasPrivilegesAction; import org.elasticsearch.xpack.core.security.action.user.ProfileHasPrivilegesAction; import org.elasticsearch.xpack.core.security.action.user.PutUserAction; +import org.elasticsearch.xpack.core.security.authc.Authentication; import org.elasticsearch.xpack.core.security.authc.AuthenticationFailureHandler; +import org.elasticsearch.xpack.core.security.authc.AuthenticationField; import org.elasticsearch.xpack.core.security.authc.AuthenticationServiceField; import org.elasticsearch.xpack.core.security.authc.DefaultAuthenticationFailureHandler; import org.elasticsearch.xpack.core.security.authc.InternalRealmsSettings; import org.elasticsearch.xpack.core.security.authc.Realm; import org.elasticsearch.xpack.core.security.authc.RealmConfig; import org.elasticsearch.xpack.core.security.authc.RealmSettings; +import org.elasticsearch.xpack.core.security.authc.Subject; import org.elasticsearch.xpack.core.security.authc.support.UsernamePasswordToken; import org.elasticsearch.xpack.core.security.authz.AuthorizationEngine; import org.elasticsearch.xpack.core.security.authz.AuthorizationServiceField; @@ -2003,6 +2006,30 @@ private void reloadRemoteClusterCredentials(Settings settingsWithKeystore) { future.actionGet(); } + public Map getAuthContextForSlowLog() { + if (this.securityContext.get() != null && this.securityContext.get().getAuthentication() != null) { + Authentication authentication = this.securityContext.get().getAuthentication(); + Subject authenticatingSubject = authentication.getAuthenticatingSubject(); + Subject effetctiveSubject = authentication.getEffectiveSubject(); + Map authContext = new HashMap<>(); + if (authenticatingSubject.getUser() != null) { + authContext.put("user.name", authenticatingSubject.getUser().principal()); + authContext.put("user.realm", authenticatingSubject.getRealm().getName()); + } + if (effetctiveSubject.getUser() != null) { + authContext.put("user.effective.name", effetctiveSubject.getUser().principal()); + authContext.put("user.effective.realm", effetctiveSubject.getRealm().getName()); + } + authContext.put("auth.type", authentication.getAuthenticationType().name()); + if (authentication.isApiKey()) { + authContext.put("apikey.id", authenticatingSubject.getMetadata().get(AuthenticationField.API_KEY_ID_KEY).toString()); + authContext.put("apikey.name", authenticatingSubject.getMetadata().get(AuthenticationField.API_KEY_NAME_KEY).toString()); + } + return authContext; + } + return Map.of(); + } + static final class ValidateLicenseForFIPS implements BiConsumer { private final boolean inFipsMode; private final LicenseService licenseService; diff --git a/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/slowlog/SecuritySlowLogFieldProvider.java b/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/slowlog/SecuritySlowLogFieldProvider.java new file mode 100644 index 0000000000000..072b750bb0b49 --- /dev/null +++ b/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/slowlog/SecuritySlowLogFieldProvider.java @@ -0,0 +1,57 @@ +/* + * 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; you may not use this file except in compliance with the Elastic License + * 2.0. + */ + +package org.elasticsearch.xpack.security.slowlog; + +import org.elasticsearch.index.IndexSettings; +import org.elasticsearch.index.SlowLogFieldProvider; +import org.elasticsearch.xpack.security.Security; + +import java.util.Map; + +import static org.elasticsearch.index.IndexingSlowLog.INDEX_INDEXING_SLOWLOG_INCLUDE_USER_SETTING; +import static org.elasticsearch.index.SearchSlowLog.INDEX_SEARCH_SLOWLOG_INCLUDE_USER_SETTING; + +public class SecuritySlowLogFieldProvider implements SlowLogFieldProvider { + private final Security plugin; + private boolean includeUserInIndexing = false; + private boolean includeUserInSearch = false; + + public SecuritySlowLogFieldProvider(Security plugin) { + this.plugin = plugin; + } + + public SecuritySlowLogFieldProvider() { + plugin = null; + } + + @Override + public void init(IndexSettings indexSettings) { + indexSettings.getScopedSettings() + .addSettingsUpdateConsumer(INDEX_SEARCH_SLOWLOG_INCLUDE_USER_SETTING, newValue -> this.includeUserInSearch = newValue); + this.includeUserInSearch = indexSettings.getValue(INDEX_SEARCH_SLOWLOG_INCLUDE_USER_SETTING); + indexSettings.getScopedSettings() + .addSettingsUpdateConsumer(INDEX_INDEXING_SLOWLOG_INCLUDE_USER_SETTING, newValue -> this.includeUserInIndexing = newValue); + this.includeUserInIndexing = indexSettings.getValue(INDEX_INDEXING_SLOWLOG_INCLUDE_USER_SETTING); + } + + @Override + public Map indexSlowLogFields() { + if (includeUserInIndexing) { + return plugin.getAuthContextForSlowLog(); + } + return Map.of(); + } + + @Override + public Map searchSlowLogFields() { + if (includeUserInSearch) { + return plugin.getAuthContextForSlowLog(); + } + return Map.of(); + } +} diff --git a/x-pack/plugin/security/src/main/resources/META-INF/services/org.elasticsearch.index.SlowLogFieldProvider b/x-pack/plugin/security/src/main/resources/META-INF/services/org.elasticsearch.index.SlowLogFieldProvider new file mode 100644 index 0000000000000..41f0ec83ac3f1 --- /dev/null +++ b/x-pack/plugin/security/src/main/resources/META-INF/services/org.elasticsearch.index.SlowLogFieldProvider @@ -0,0 +1,8 @@ +# +# 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; you may not use this file except in compliance with the Elastic License +# 2.0. +# + +org.elasticsearch.xpack.security.slowlog.SecuritySlowLogFieldProvider diff --git a/x-pack/plugin/security/src/test/java/org/elasticsearch/xpack/security/SecurityTests.java b/x-pack/plugin/security/src/test/java/org/elasticsearch/xpack/security/SecurityTests.java index 4aefc436d82f5..60d3ff0b6ef32 100644 --- a/x-pack/plugin/security/src/test/java/org/elasticsearch/xpack/security/SecurityTests.java +++ b/x-pack/plugin/security/src/test/java/org/elasticsearch/xpack/security/SecurityTests.java @@ -41,6 +41,7 @@ import org.elasticsearch.index.IndexSettings; import org.elasticsearch.index.IndexVersion; import org.elasticsearch.index.IndexVersions; +import org.elasticsearch.index.SlowLogFieldProvider; import org.elasticsearch.index.analysis.AnalysisRegistry; import org.elasticsearch.index.engine.InternalEngineFactory; import org.elasticsearch.indices.TestIndexNameExpressionResolver; @@ -373,7 +374,8 @@ public void testOnIndexModuleIsNoOpWithSecurityDisabled() throws Exception { Collections.emptyMap(), () -> true, TestIndexNameExpressionResolver.newInstance(threadPool.getThreadContext()), - Collections.emptyMap() + Collections.emptyMap(), + mock(SlowLogFieldProvider.class) ); security.onIndexModule(indexModule); // indexReaderWrapper is a SetOnce so if Security#onIndexModule had already set an ReaderWrapper we would get an exception here diff --git a/x-pack/plugin/watcher/src/test/java/org/elasticsearch/xpack/watcher/WatcherPluginTests.java b/x-pack/plugin/watcher/src/test/java/org/elasticsearch/xpack/watcher/WatcherPluginTests.java index 64bf5b5d99fdb..bee2d6aa22355 100644 --- a/x-pack/plugin/watcher/src/test/java/org/elasticsearch/xpack/watcher/WatcherPluginTests.java +++ b/x-pack/plugin/watcher/src/test/java/org/elasticsearch/xpack/watcher/WatcherPluginTests.java @@ -10,6 +10,7 @@ import org.elasticsearch.env.TestEnvironment; import org.elasticsearch.index.IndexModule; import org.elasticsearch.index.IndexSettings; +import org.elasticsearch.index.SlowLogFieldProvider; import org.elasticsearch.index.analysis.AnalysisRegistry; import org.elasticsearch.index.engine.InternalEngineFactory; import org.elasticsearch.indices.SystemIndexDescriptor; @@ -66,7 +67,8 @@ public void testWatcherDisabledTests() throws Exception { Collections.emptyMap(), () -> true, TestIndexNameExpressionResolver.newInstance(), - Collections.emptyMap() + Collections.emptyMap(), + mock(SlowLogFieldProvider.class) ); // this will trip an assertion if the watcher indexing operation listener is null (which it is) but we try to add it watcher.onIndexModule(indexModule); From 7200f76b9244851ecbc60e3ecbdade8ecb62425d Mon Sep 17 00:00:00 2001 From: Johannes Freden Jansson Date: Fri, 23 Feb 2024 08:50:50 +0100 Subject: [PATCH 2/4] fixup! Address code review comments --- docs/reference/index-modules/slowlog.asciidoc | 40 ++----------------- .../security/slowlog/SecuritySlowLogIT.java | 21 +--------- .../xpack/security/Security.java | 3 +- 3 files changed, 6 insertions(+), 58 deletions(-) diff --git a/docs/reference/index-modules/slowlog.asciidoc b/docs/reference/index-modules/slowlog.asciidoc index 7e80bfad18ffd..691ca93019430 100644 --- a/docs/reference/index-modules/slowlog.asciidoc +++ b/docs/reference/index-modules/slowlog.asciidoc @@ -79,7 +79,7 @@ This will result in user information being included in the slow log. "@timestamp": "2024-02-21T12:42:37.255Z", "log.level": "WARN", "auth.type": "REALM", - "elasticsearch.slowlog.id": null, + "elasticsearch.slowlog.id": "1eb56087c321442e8c9040dbe51fbcdf", "elasticsearch.slowlog.message": "[index6][0]", "elasticsearch.slowlog.search_type": "QUERY_THEN_FETCH", "elasticsearch.slowlog.source": "{\"query\":{\"match_all\":{\"boost\":1.0}}}", @@ -88,8 +88,6 @@ This will result in user information being included in the slow log. "elasticsearch.slowlog.took_millis": 0, "elasticsearch.slowlog.total_hits": "1 hits", "elasticsearch.slowlog.total_shards": 1, - "user.effective.name": "elastic", - "user.effective.realm": "reserved", "user.name": "elastic", "user.realm": "reserved", "ecs.version": "1.2.0", @@ -106,40 +104,8 @@ This will result in user information being included in the slow log. --------------------------- // NOTCONSOLE -If a call was initiated with an `X-Opaque-ID` header, then the ID is also included -in Search Slow logs as an additional **elasticsearch.slowlog.id** field - -[source,js] ---------------------------- -{ - "@timestamp": "2024-02-21T12:42:37.255Z", - "log.level": "WARN", - "auth.type": "REALM", - "elasticsearch.slowlog.id": "MY_USER_ID", - "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.effective.name": "elastic", - "user.effective.realm": "reserved", - "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. [discrete] [[index-slow-log]] diff --git a/x-pack/plugin/security/qa/slowlog/src/javaRestTest/java/org/elasticsearch/xpack/security/slowlog/SecuritySlowLogIT.java b/x-pack/plugin/security/qa/slowlog/src/javaRestTest/java/org/elasticsearch/xpack/security/slowlog/SecuritySlowLogIT.java index 0678e878cf4df..d966845f9c1c1 100644 --- a/x-pack/plugin/security/qa/slowlog/src/javaRestTest/java/org/elasticsearch/xpack/security/slowlog/SecuritySlowLogIT.java +++ b/x-pack/plugin/security/qa/slowlog/src/javaRestTest/java/org/elasticsearch/xpack/security/slowlog/SecuritySlowLogIT.java @@ -83,18 +83,7 @@ public void testSlowLogWithApiUser() throws Exception { indexSomeData(testData.name); } - Map expectedUser = Map.of( - "user.name", - "api_user", - "user.effective.name", - "api_user", - "user.realm", - "default_file", - "user.effective.realm", - "default_file", - "auth.type", - "REALM" - ); + Map expectedUser = Map.of("user.name", "api_user", "user.realm", "default_file", "auth.type", "REALM"); verifySearchSlowLogMatchesTestData(testIndices, expectedUser); verifyIndexSlowLogMatchesTestData(testIndices, expectedUser); @@ -123,12 +112,8 @@ public void testSlowLogWithApiKey() throws Exception { Map expectedUser = Map.of( "user.name", "admin_user", - "user.effective.name", - "admin_user", "user.realm", "_es_api_key", - "user.effective.realm", - "_es_api_key", "auth.type", "API_KEY", "apikey.id", @@ -187,12 +172,8 @@ public void testSlowLogWithServiceAccount() throws Exception { Map expectedUser = Map.of( "user.name", "elastic/enterprise-search-server", - "user.effective.name", - "elastic/enterprise-search-server", "user.realm", "_service_account", - "user.effective.realm", - "_service_account", "auth.type", "TOKEN" ); diff --git a/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/Security.java b/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/Security.java index f1ddbe9ef8ce7..2926539f41476 100644 --- a/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/Security.java +++ b/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/Security.java @@ -2016,7 +2016,8 @@ public Map getAuthContextForSlowLog() { authContext.put("user.name", authenticatingSubject.getUser().principal()); authContext.put("user.realm", authenticatingSubject.getRealm().getName()); } - if (effetctiveSubject.getUser() != null) { + // Only include effective user if different from authenticating user (run-as) + if (effetctiveSubject.getUser() != null && effetctiveSubject.equals(authenticatingSubject) == false) { authContext.put("user.effective.name", effetctiveSubject.getUser().principal()); authContext.put("user.effective.realm", effetctiveSubject.getRealm().getName()); } From d3f0f1529d818c4557333aafb6aa68bdd4a81a29 Mon Sep 17 00:00:00 2001 From: Johannes Freden Jansson Date: Mon, 4 Mar 2024 11:28:17 +0100 Subject: [PATCH 3/4] fixup! Code review comments --- docs/reference/index-modules/slowlog.asciidoc | 5 +- .../xpack/security}/SecuritySlowLogIT.java | 70 ++++++++++++++++++- .../plugin/security/qa/slowlog/build.gradle | 10 --- .../xpack/security/Security.java | 6 ++ .../slowlog/SecuritySlowLogFieldProvider.java | 8 +-- 5 files changed, 82 insertions(+), 17 deletions(-) rename x-pack/plugin/security/qa/{slowlog/src/javaRestTest/java/org/elasticsearch/xpack/security/slowlog => security-basic/src/javaRestTest/java/org/elasticsearch/xpack/security}/SecuritySlowLogIT.java (82%) delete mode 100644 x-pack/plugin/security/qa/slowlog/build.gradle diff --git a/docs/reference/index-modules/slowlog.asciidoc b/docs/reference/index-modules/slowlog.asciidoc index 691ca93019430..c29296b59ad4a 100644 --- a/docs/reference/index-modules/slowlog.asciidoc +++ b/docs/reference/index-modules/slowlog.asciidoc @@ -79,7 +79,7 @@ This will result in user information being included in the slow log. "@timestamp": "2024-02-21T12:42:37.255Z", "log.level": "WARN", "auth.type": "REALM", - "elasticsearch.slowlog.id": "1eb56087c321442e8c9040dbe51fbcdf", + "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}}}", @@ -105,7 +105,8 @@ This will result in user information being included in the slow log. // 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. +in Search Slow logs in the **elasticsearch.slowlog.id** field. See +<> for details and best practices. [discrete] [[index-slow-log]] diff --git a/x-pack/plugin/security/qa/slowlog/src/javaRestTest/java/org/elasticsearch/xpack/security/slowlog/SecuritySlowLogIT.java b/x-pack/plugin/security/qa/security-basic/src/javaRestTest/java/org/elasticsearch/xpack/security/SecuritySlowLogIT.java similarity index 82% rename from x-pack/plugin/security/qa/slowlog/src/javaRestTest/java/org/elasticsearch/xpack/security/slowlog/SecuritySlowLogIT.java rename to x-pack/plugin/security/qa/security-basic/src/javaRestTest/java/org/elasticsearch/xpack/security/SecuritySlowLogIT.java index d966845f9c1c1..704799a45824c 100644 --- a/x-pack/plugin/security/qa/slowlog/src/javaRestTest/java/org/elasticsearch/xpack/security/slowlog/SecuritySlowLogIT.java +++ b/x-pack/plugin/security/qa/security-basic/src/javaRestTest/java/org/elasticsearch/xpack/security/SecuritySlowLogIT.java @@ -5,7 +5,7 @@ * 2.0. */ -package org.elasticsearch.xpack.security.slowlog; +package org.elasticsearch.xpack.security; import org.apache.http.HttpHeaders; import org.elasticsearch.client.Request; @@ -89,6 +89,59 @@ public void testSlowLogWithApiUser() throws Exception { verifyIndexSlowLogMatchesTestData(testIndices, expectedUser); } + public void testSlowLogWithUserWithFullName() throws Exception { + List testIndices = randomTestIndexData(); + createUserWithFullName("full_name", "full-name-password", "Full Name", new String[] { "superuser" }); + for (TestIndexData testData : testIndices) { + final RequestOptions requestOptions = RequestOptions.DEFAULT.toBuilder() + .addHeader("Authorization", basicAuthHeaderValue("full_name", new SecureString("full-name-password".toCharArray()))) + .build(); + searchSomeData(testData.name, requestOptions); + indexSomeData(testData.name, requestOptions); + } + + Map expectedUser = Map.of( + "user.name", + "full_name", + "user.full_name", + "Full Name", + "user.realm", + "default_native", + "auth.type", + "REALM" + ); + + verifySearchSlowLogMatchesTestData(testIndices, expectedUser); + verifyIndexSlowLogMatchesTestData(testIndices, expectedUser); + } + + public void testSlowLogWithUserWithFullNameWithRunAs() throws Exception { + List testIndices = randomTestIndexData(); + createUserWithFullName("full_name", "full-name-password", "Full Name", new String[] { "superuser" }); + for (TestIndexData testData : testIndices) { + final RequestOptions requestOptions = RequestOptions.DEFAULT.toBuilder() + .addHeader("es-security-runas-user", "full_name") + .addHeader("Authorization", basicAuthHeaderValue("admin_user", new SecureString("admin-password".toCharArray()))) + .build(); + searchSomeData(testData.name, requestOptions); + indexSomeData(testData.name, requestOptions); + } + + Map expectedUser = Map.of( + "user.name", + "admin_user", + "user.effective.full_name", + "Full Name", + "user.realm", + "default_file", + "auth.type", + "REALM" + ); + + verifySearchSlowLogMatchesTestData(testIndices, expectedUser); + verifyIndexSlowLogMatchesTestData(testIndices, expectedUser); + } + public void testSlowLogWithApiKey() throws Exception { List testIndices = randomTestIndexData(); String apiKeyName = randomAlphaOfLengthBetween(10, 15); @@ -239,6 +292,21 @@ private static void setupTestIndex(TestIndexData testIndexData) throws IOExcepti } } + private static void createUserWithFullName(String user, String password, String fullName, String[] roles) throws IOException { + Request request = new Request("POST", "/_security/user/" + user); + request.setJsonEntity( + "{ \"full_name\" : \"" + + fullName + + "\", \"roles\": [\"" + + String.join("\",\"", roles) + + "\"], \"password\": \"" + + password + + "\" }" + ); + Response response = client().performRequest(request); + assertOK(response); + } + private static List randomTestIndexData() throws IOException { List testData = new ArrayList<>(); for (int i = 0; i < randomIntBetween(1, 10); i++) { diff --git a/x-pack/plugin/security/qa/slowlog/build.gradle b/x-pack/plugin/security/qa/slowlog/build.gradle deleted file mode 100644 index 5bf7b0173fd69..0000000000000 --- a/x-pack/plugin/security/qa/slowlog/build.gradle +++ /dev/null @@ -1,10 +0,0 @@ -apply plugin: 'elasticsearch.internal-java-rest-test' - -dependencies { - javaRestTestImplementation project(':x-pack:plugin:core') - javaRestTestImplementation project(':x-pack:plugin:security') -} - -tasks.named('javaRestTest') { - usesDefaultDistribution() -} diff --git a/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/Security.java b/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/Security.java index 2926539f41476..360ecc81f0172 100644 --- a/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/Security.java +++ b/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/Security.java @@ -2015,11 +2015,17 @@ public Map getAuthContextForSlowLog() { if (authenticatingSubject.getUser() != null) { authContext.put("user.name", authenticatingSubject.getUser().principal()); authContext.put("user.realm", authenticatingSubject.getRealm().getName()); + if (authenticatingSubject.getUser().fullName() != null) { + authContext.put("user.full_name", authenticatingSubject.getUser().fullName()); + } } // Only include effective user if different from authenticating user (run-as) if (effetctiveSubject.getUser() != null && effetctiveSubject.equals(authenticatingSubject) == false) { authContext.put("user.effective.name", effetctiveSubject.getUser().principal()); authContext.put("user.effective.realm", effetctiveSubject.getRealm().getName()); + if (effetctiveSubject.getUser().fullName() != null) { + authContext.put("user.effective.full_name", effetctiveSubject.getUser().fullName()); + } } authContext.put("auth.type", authentication.getAuthenticationType().name()); if (authentication.isApiKey()) { diff --git a/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/slowlog/SecuritySlowLogFieldProvider.java b/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/slowlog/SecuritySlowLogFieldProvider.java index 072b750bb0b49..1610aedd1d363 100644 --- a/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/slowlog/SecuritySlowLogFieldProvider.java +++ b/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/slowlog/SecuritySlowLogFieldProvider.java @@ -21,12 +21,12 @@ public class SecuritySlowLogFieldProvider implements SlowLogFieldProvider { private boolean includeUserInIndexing = false; private boolean includeUserInSearch = false; - public SecuritySlowLogFieldProvider(Security plugin) { - this.plugin = plugin; + public SecuritySlowLogFieldProvider() { + throw new IllegalStateException("Provider must be constructed using PluginsService"); } - public SecuritySlowLogFieldProvider() { - plugin = null; + public SecuritySlowLogFieldProvider(Security plugin) { + this.plugin = plugin; } @Override From 4f9a98587b73f0dae99e9bb6fb1524a19ceaf7d4 Mon Sep 17 00:00:00 2001 From: Johannes Freden Jansson Date: Mon, 4 Mar 2024 14:19:31 +0100 Subject: [PATCH 4/4] Add SlowLogFieldProvider tests to IndicesServiceTests --- .../elasticsearch/indices/IndicesService.java | 3 +- .../indices/IndicesServiceTests.java | 79 +++++++++++++++++++ ...g.elasticsearch.index.SlowLogFieldProvider | 10 +++ 3 files changed, 91 insertions(+), 1 deletion(-) create mode 100644 server/src/test/resources/META-INF/services/org.elasticsearch.index.SlowLogFieldProvider diff --git a/server/src/main/java/org/elasticsearch/indices/IndicesService.java b/server/src/main/java/org/elasticsearch/indices/IndicesService.java index f218a7e170bcb..3319b29df6dfa 100644 --- a/server/src/main/java/org/elasticsearch/indices/IndicesService.java +++ b/server/src/main/java/org/elasticsearch/indices/IndicesService.java @@ -1393,7 +1393,8 @@ int numPendingDeletes(Index index) { } } - private SlowLogFieldProvider loadSlowLogFieldProvider() { + // pkg-private for testing + SlowLogFieldProvider loadSlowLogFieldProvider() { List slowLogFieldProviders = pluginsService.loadServiceProviders(SlowLogFieldProvider.class); return new SlowLogFieldProvider() { @Override diff --git a/server/src/test/java/org/elasticsearch/indices/IndicesServiceTests.java b/server/src/test/java/org/elasticsearch/indices/IndicesServiceTests.java index 60545ac71b2bf..ee1bdf927a11b 100644 --- a/server/src/test/java/org/elasticsearch/indices/IndicesServiceTests.java +++ b/server/src/test/java/org/elasticsearch/indices/IndicesServiceTests.java @@ -38,6 +38,7 @@ import org.elasticsearch.index.IndexService; import org.elasticsearch.index.IndexSettings; import org.elasticsearch.index.IndexVersion; +import org.elasticsearch.index.SlowLogFieldProvider; import org.elasticsearch.index.engine.Engine; import org.elasticsearch.index.engine.EngineConfig; import org.elasticsearch.index.engine.EngineFactory; @@ -192,6 +193,50 @@ public void onIndexModule(IndexModule indexModule) { } } + public static class TestSlowLogFieldProvider implements SlowLogFieldProvider { + + private static Map fields = Map.of(); + + static void setFields(Map fields) { + TestSlowLogFieldProvider.fields = fields; + } + + @Override + public void init(IndexSettings indexSettings) {} + + @Override + public Map indexSlowLogFields() { + return fields; + } + + @Override + public Map searchSlowLogFields() { + return fields; + } + } + + public static class TestAnotherSlowLogFieldProvider implements SlowLogFieldProvider { + + private static Map fields = Map.of(); + + static void setFields(Map fields) { + TestAnotherSlowLogFieldProvider.fields = fields; + } + + @Override + public void init(IndexSettings indexSettings) {} + + @Override + public Map indexSlowLogFields() { + return fields; + } + + @Override + public Map searchSlowLogFields() { + return fields; + } + } + @Override protected boolean resetNodeAfterTest() { return true; @@ -746,4 +791,38 @@ public void testBuildAliasFilterDataStreamAliases() { assertThat(result, is(AliasFilter.EMPTY)); } } + + public void testLoadSlowLogFieldProvider() { + TestSlowLogFieldProvider.setFields(Map.of("key1", "value1")); + TestAnotherSlowLogFieldProvider.setFields(Map.of("key2", "value2")); + + var indicesService = getIndicesService(); + SlowLogFieldProvider fieldProvider = indicesService.loadSlowLogFieldProvider(); + + // The map of fields from the two providers are merged to a single map of fields + assertEquals(Map.of("key1", "value1", "key2", "value2"), fieldProvider.searchSlowLogFields()); + assertEquals(Map.of("key1", "value1", "key2", "value2"), fieldProvider.indexSlowLogFields()); + + TestSlowLogFieldProvider.setFields(Map.of("key1", "value1")); + TestAnotherSlowLogFieldProvider.setFields(Map.of("key1", "value2")); + + // There is an overlap of field names, since this isn't deterministic and probably a + // programming error (two providers provide the same field) throw an exception + assertThrows(IllegalStateException.class, fieldProvider::searchSlowLogFields); + assertThrows(IllegalStateException.class, fieldProvider::indexSlowLogFields); + + TestSlowLogFieldProvider.setFields(Map.of("key1", "value1")); + TestAnotherSlowLogFieldProvider.setFields(Map.of()); + + // One provider has no fields + assertEquals(Map.of("key1", "value1"), fieldProvider.searchSlowLogFields()); + assertEquals(Map.of("key1", "value1"), fieldProvider.indexSlowLogFields()); + + TestSlowLogFieldProvider.setFields(Map.of()); + TestAnotherSlowLogFieldProvider.setFields(Map.of()); + + // Both providers have no fields + assertEquals(Map.of(), fieldProvider.searchSlowLogFields()); + assertEquals(Map.of(), fieldProvider.indexSlowLogFields()); + } } diff --git a/server/src/test/resources/META-INF/services/org.elasticsearch.index.SlowLogFieldProvider b/server/src/test/resources/META-INF/services/org.elasticsearch.index.SlowLogFieldProvider new file mode 100644 index 0000000000000..fcd1211eee0c5 --- /dev/null +++ b/server/src/test/resources/META-INF/services/org.elasticsearch.index.SlowLogFieldProvider @@ -0,0 +1,10 @@ +# +# 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. +# + +org.elasticsearch.indices.IndicesServiceTests$TestSlowLogFieldProvider +org.elasticsearch.indices.IndicesServiceTests$TestAnotherSlowLogFieldProvider