-
Notifications
You must be signed in to change notification settings - Fork 24.3k
Commit
This commit does not belong to any branch on this repository, and may belong to a fork outside of the repository.
Browse files
Browse the repository at this point in the history
…#82767) * Make authz perf log msg configurable and disabled by default (#82648) In #75439 we added log messages for authorization performance. Real world experience indicates that some clusters generate these log messages even though the overall cluster performance is acceptable to the administrators, and the security (RBAC) configuration is within our recommendations. This commit changes the threshold levels for these messages by: - Increasing the default time values for each log level - Making the levels configurable - Disabling the log by default - Adding a dynamic setting to enable the logging if required * Fix compile issues from backport Co-authored-by: Tim Vernum <tim.vernum@elastic.co> Co-authored-by: Tim Vernum <tim@adjective.org>
- Loading branch information
3 people
committed
Jan 18, 2022
1 parent
3ccdcbe
commit c5bc0ac
Showing
4 changed files
with
407 additions
and
103 deletions.
There are no files selected for viewing
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
188 changes: 188 additions & 0 deletions
188
...rc/main/java/org/elasticsearch/xpack/security/authz/LoadAuthorizedIndicesTimeChecker.java
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,188 @@ | ||
| /* | ||
| * 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.authz; | ||
|
|
||
| import org.apache.logging.log4j.Level; | ||
| import org.apache.logging.log4j.Logger; | ||
| import org.elasticsearch.common.settings.ClusterSettings; | ||
| import org.elasticsearch.common.settings.Setting; | ||
| import org.elasticsearch.common.settings.Settings; | ||
| import org.elasticsearch.common.settings.SettingsException; | ||
| import org.elasticsearch.core.TimeValue; | ||
| import org.elasticsearch.xpack.core.security.authz.AuthorizationEngine; | ||
|
|
||
| import java.util.Collection; | ||
| import java.util.Set; | ||
| import java.util.concurrent.TimeUnit; | ||
| import java.util.function.Consumer; | ||
|
|
||
| /** | ||
| * Checks the time spent evaluating authorized indices for a request. | ||
| * Has configurable logging levels based on execution time. | ||
| */ | ||
| class LoadAuthorizedIndicesTimeChecker implements Consumer<Collection<String>> { | ||
|
|
||
| private final Logger logger; | ||
| private final long startNanos; | ||
| private final AuthorizationEngine.RequestInfo requestInfo; | ||
| private final Thresholds thresholds; | ||
|
|
||
| LoadAuthorizedIndicesTimeChecker(Logger logger, long startNanos, AuthorizationEngine.RequestInfo requestInfo, Thresholds thresholds) { | ||
| this.logger = logger; | ||
| this.startNanos = startNanos; | ||
| this.requestInfo = requestInfo; | ||
| this.thresholds = thresholds; | ||
| } | ||
|
|
||
| @Override | ||
| public void accept(Collection<String> indices) { | ||
| final long end = System.nanoTime(); | ||
| final long millis = TimeUnit.NANOSECONDS.toMillis(end - startNanos); | ||
| final Level level = thresholds.getLogLevel(millis); | ||
| if (level == Level.WARN) { | ||
| logger.warn( | ||
| "Resolving [{}] indices for action [{}] and user [{}] took [{}ms] which is greater than the threshold of {}ms;" | ||
| + " The index privileges for this user may be too complex for this cluster.", | ||
| indices.size(), | ||
| requestInfo.getAction(), | ||
| requestInfo.getAuthentication().getUser().principal(), | ||
| millis, | ||
| thresholds.warnThresholdMs | ||
| ); | ||
| } else { | ||
| logger.log( | ||
| level, | ||
| "Took [{}ms] to resolve [{}] indices for action [{}] and user [{}]", | ||
| millis, | ||
| indices.size(), | ||
| requestInfo.getAction(), | ||
| requestInfo.getAuthentication().getUser().principal() | ||
| ); | ||
| } | ||
| } | ||
|
|
||
| static final Setting<Boolean> LOGGING_ENABLED_SETTING = Setting.boolSetting( | ||
| "xpack.security.authz.timer.indices.enabled", | ||
| false, | ||
| Setting.Property.NodeScope, | ||
| Setting.Property.Dynamic | ||
| ); | ||
| static final Setting<TimeValue> DEBUG_THRESHOLD_SETTING = Setting.timeSetting( | ||
| "xpack.security.authz.timer.indices.threshold.debug", | ||
| TimeValue.timeValueMillis(20), | ||
| Setting.Property.NodeScope | ||
| ); | ||
| static final Setting<TimeValue> INFO_THRESHOLD_SETTING = Setting.timeSetting( | ||
| "xpack.security.authz.timer.indices.threshold.info", | ||
| TimeValue.timeValueMillis(100), | ||
| Setting.Property.NodeScope | ||
| ); | ||
| static final Setting<TimeValue> WARN_THRESHOLD_SETTING = Setting.timeSetting( | ||
| "xpack.security.authz.timer.indices.threshold.warn", | ||
| TimeValue.timeValueMillis(200), | ||
| Setting.Property.NodeScope | ||
| ); | ||
|
|
||
| static class Thresholds { | ||
| private final long debugThresholdMs; | ||
| private final long infoThresholdMs; | ||
| private final long warnThresholdMs; | ||
|
|
||
| Thresholds(TimeValue debugThreshold, TimeValue infoThreshold, TimeValue warnThreshold) { | ||
| this.debugThresholdMs = debugThreshold.millis(); | ||
| this.infoThresholdMs = infoThreshold.millis(); | ||
| this.warnThresholdMs = warnThreshold.millis(); | ||
| } | ||
|
|
||
| public Level getLogLevel(long millis) { | ||
| if (millis > warnThresholdMs) { | ||
| return Level.WARN; | ||
| } | ||
| if (millis > infoThresholdMs) { | ||
| return Level.INFO; | ||
| } | ||
| if (millis > debugThresholdMs) { | ||
| return Level.DEBUG; | ||
| } | ||
| return Level.TRACE; | ||
| } | ||
|
|
||
| long getDebugThresholdMs() { | ||
| return debugThresholdMs; | ||
| } | ||
|
|
||
| long getInfoThresholdMs() { | ||
| return infoThresholdMs; | ||
| } | ||
|
|
||
| long getWarnThresholdMs() { | ||
| return warnThresholdMs; | ||
| } | ||
| } | ||
|
|
||
| static final Consumer<Collection<String>> NO_OP_CONSUMER = ignore -> {}; | ||
|
|
||
| static class Factory { | ||
| private final Logger logger; | ||
| private volatile boolean loggingEnabled; | ||
| private final Thresholds thresholds; | ||
|
|
||
| Factory(Logger logger, Settings settings, ClusterSettings clusterSettings) { | ||
| this.logger = logger; | ||
| this.loggingEnabled = LOGGING_ENABLED_SETTING.get(settings); | ||
| clusterSettings.addSettingsUpdateConsumer(LOGGING_ENABLED_SETTING, enabled -> this.loggingEnabled = enabled); | ||
|
|
||
| TimeValue debugThreshold = DEBUG_THRESHOLD_SETTING.get(settings); | ||
| TimeValue infoThreshold = INFO_THRESHOLD_SETTING.get(settings); | ||
| TimeValue warnThreshold = WARN_THRESHOLD_SETTING.get(settings); | ||
|
|
||
| if (infoThreshold.compareTo(debugThreshold) < 0) { | ||
| throw new SettingsException( | ||
| "Setting [{}] ({}) cannot be less than the setting [{}] ({})", | ||
| INFO_THRESHOLD_SETTING.getKey(), | ||
| infoThreshold, | ||
| DEBUG_THRESHOLD_SETTING.getKey(), | ||
| debugThreshold | ||
| ); | ||
| } | ||
| if (warnThreshold.compareTo(infoThreshold) < 0) { | ||
| throw new SettingsException( | ||
| "Setting [{}] ({}) cannot be less than the setting [{}] ({})", | ||
| WARN_THRESHOLD_SETTING.getKey(), | ||
| warnThreshold, | ||
| INFO_THRESHOLD_SETTING.getKey(), | ||
| infoThreshold | ||
| ); | ||
| } | ||
|
|
||
| this.thresholds = new Thresholds(debugThreshold, infoThreshold, warnThreshold); | ||
| } | ||
|
|
||
| public static Set<Setting<?>> getSettings() { | ||
| return org.elasticsearch.core.Set.of( | ||
| LOGGING_ENABLED_SETTING, | ||
| DEBUG_THRESHOLD_SETTING, | ||
| INFO_THRESHOLD_SETTING, | ||
| WARN_THRESHOLD_SETTING | ||
| ); | ||
| } | ||
|
|
||
| public Consumer<Collection<String>> newTimer(AuthorizationEngine.RequestInfo requestInfo) { | ||
| if (loggingEnabled) { | ||
| return new LoadAuthorizedIndicesTimeChecker(logger, System.nanoTime(), requestInfo, thresholds); | ||
| } else { | ||
| return NO_OP_CONSUMER; | ||
| } | ||
| } | ||
|
|
||
| public Thresholds getThresholds() { | ||
| return thresholds; | ||
| } | ||
| } | ||
|
|
||
| } |
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Oops, something went wrong.