Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add user information to slowlog #105621

Merged
merged 5 commits into from
Mar 11, 2024
Merged

Add user information to slowlog #105621

Show file tree
Hide file tree
Changes from 2 commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
c6de455
Add user/auth information to slowlog
jfreden Feb 13, 2024
7200f76
fixup! Address code review comments
jfreden Feb 23, 2024
d3f0f15
fixup! Code review comments
jfreden Mar 4, 2024
4f9a985
Add SlowLogFieldProvider tests to IndicesServiceTests
jfreden Mar 4, 2024
c54e0ad
Merge branch 'main' into user_in_slowlog
elasticmachine Mar 11, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
72 changes: 53 additions & 19 deletions docs/reference/index-modules/slowlog.asciidoc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -58,33 +58,55 @@ 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",
jakelandis marked this conversation as resolved.
Show resolved Hide resolved
"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": "1eb56087c321442e8c9040dbe51fbcdf",
jakelandis marked this conversation as resolved.
Show resolved Hide resolved
"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
jakelandis marked this conversation as resolved.
Show resolved Hide resolved
in Search Slow logs in the **elasticsearch.slowlog.id** field.

[discrete]
[[index-slow-log]]
=== Index Slow log
Expand Down Expand Up @@ -119,6 +141,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
Expand Down
2 changes: 2 additions & 0 deletions server/src/main/java/org/elasticsearch/common/settings/IndexScopedSettings.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down
7 changes: 4 additions & 3 deletions server/src/main/java/org/elasticsearch/index/IndexModule.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down
65 changes: 59 additions & 6 deletions server/src/main/java/org/elasticsearch/index/IndexingSlowLog.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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
Expand All @@ -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();
Expand Down Expand Up @@ -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);
}

Expand Down
33 changes: 23 additions & 10 deletions server/src/main/java/org/elasticsearch/index/SearchSlowLog.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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),
Expand Down Expand Up @@ -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);
jakelandis marked this conversation as resolved.
Show resolved Hide resolved
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);
Expand Down Expand Up @@ -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);
}

Expand Down
35 changes: 35 additions & 0 deletions server/src/main/java/org/elasticsearch/index/SlowLogFieldProvider.java
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -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();
}
31 changes: 29 additions & 2 deletions server/src/main/java/org/elasticsearch/indices/IndicesService.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -736,7 +737,8 @@ private synchronized IndexService createIndexService(
directoryFactories,
() -> allowExpensiveQueries,
indexNameExpressionResolver,
recoveryStateFactories
recoveryStateFactories,
loadSlowLogFieldProvider()
);
for (IndexingOperationListener operationListener : indexingOperationListeners) {
indexModule.addIndexOperationListener(operationListener);
Expand Down Expand Up @@ -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);
Expand Down Expand Up @@ -1390,6 +1393,30 @@ int numPendingDeletes(Index index) {
}
}

private SlowLogFieldProvider loadSlowLogFieldProvider() {
List<? extends SlowLogFieldProvider> slowLogFieldProviders = pluginsService.loadServiceProviders(SlowLogFieldProvider.class);
return new SlowLogFieldProvider() {
jakelandis marked this conversation as resolved.
Show resolved Hide resolved
@Override
public void init(IndexSettings indexSettings) {
slowLogFieldProviders.forEach(provider -> provider.init(indexSettings));
}

@Override
public Map<String, String> indexSlowLogFields() {
return slowLogFieldProviders.stream()
.flatMap(provider -> provider.indexSlowLogFields().entrySet().stream())
.collect(Collectors.toMap(Map.Entry::getKey, Map.Entry::getValue));
}

@Override
public Map<String, String> 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
Expand Down
Loading