Use LRU set to reduce repeat deprecation messages

This commit adds an LRU set to used to determine if a keyed deprecation
message should be written to the deprecation logs, or only added to the
response headers on the thread context.

Relates #25474
This commit is contained in:
Jason Tedor 2017-06-29 16:36:43 -04:00 committed by GitHub
parent cac2eec7d2
commit d219a85b33
7 changed files with 173 additions and 51 deletions

View File

@ -31,8 +31,10 @@ import java.time.ZonedDateTime;
import java.time.format.DateTimeFormatter;
import java.time.format.DateTimeFormatterBuilder;
import java.time.format.SignStyle;
import java.util.Collections;
import java.util.HashMap;
import java.util.Iterator;
import java.util.LinkedHashMap;
import java.util.Locale;
import java.util.Map;
import java.util.Objects;
@ -118,12 +120,32 @@ public class DeprecationLogger {
}
/**
* Logs a deprecated message.
* Logs a deprecation message, adding a formatted warning message as a response header on the thread context.
*/
public void deprecated(String msg, Object... params) {
deprecated(THREAD_CONTEXT, msg, params);
}
// LRU set of keys used to determine if a deprecation message should be emitted to the deprecation logs
private Set<String> keys = Collections.newSetFromMap(Collections.synchronizedMap(new LinkedHashMap<String, Boolean>() {
@Override
protected boolean removeEldestEntry(final Map.Entry eldest) {
return size() > 128;
}
}));
/**
* Adds a formatted warning message as a response header on the thread context, and logs a deprecation message if the associated key has
* not recently been seen.
*
* @param key the key used to determine if this deprecation should be logged
* @param msg the message to log
* @param params parameters to the message
*/
public void deprecatedAndMaybeLog(final String key, final String msg, final Object... params) {
deprecated(THREAD_CONTEXT, msg, keys.add(key), params);
}
/*
* RFC7234 specifies the warning format as warn-code <space> warn-agent <space> "warn-text" [<space> "warn-date"]. Here, warn-code is a
* three-digit number with various standard warn codes specified. The warn code 299 is apt for our purposes as it represents a
@ -270,8 +292,12 @@ public class DeprecationLogger {
* @param message The deprecation message.
* @param params The parameters used to fill in the message, if any exist.
*/
@SuppressLoggerChecks(reason = "safely delegates to logger")
void deprecated(final Set<ThreadContext> threadContexts, final String message, final Object... params) {
deprecated(threadContexts, message, true, params);
}
@SuppressLoggerChecks(reason = "safely delegates to logger")
void deprecated(final Set<ThreadContext> threadContexts, final String message, final boolean log, final Object... params) {
final Iterator<ThreadContext> iterator = threadContexts.iterator();
if (iterator.hasNext()) {
@ -287,8 +313,9 @@ public class DeprecationLogger {
// ignored; it should be removed shortly
}
}
logger.warn(formattedMessage);
} else {
}
if (log) {
logger.warn(message, params);
}
}

View File

@ -19,6 +19,7 @@
package org.elasticsearch.common.settings;
import org.apache.logging.log4j.Logger;
import org.apache.lucene.util.SetOnce;
import org.elasticsearch.ElasticsearchException;
import org.elasticsearch.ElasticsearchParseException;
import org.elasticsearch.action.support.ToXContentToBytes;
@ -342,14 +343,27 @@ public class Setting<T> extends ToXContentToBytes {
return settings.get(getKey(), defaultValue.apply(settings));
}
private static SetOnce<DeprecationLogger> deprecationLogger = new SetOnce<>();
// we have to initialize lazily otherwise a logger would be constructed before logging is initialized
private static synchronized DeprecationLogger getDeprecationLogger() {
if (deprecationLogger.get() == null) {
deprecationLogger.set(new DeprecationLogger(Loggers.getLogger(Settings.class)));
}
return deprecationLogger.get();
}
/** Logs a deprecation warning if the setting is deprecated and used. */
protected void checkDeprecation(Settings settings) {
void checkDeprecation(Settings settings) {
// They're using the setting, so we need to tell them to stop
if (this.isDeprecated() && this.exists(settings) && settings.addDeprecatedSetting(this)) {
if (this.isDeprecated() && this.exists(settings)) {
// It would be convenient to show its replacement key, but replacement is often not so simple
final DeprecationLogger deprecationLogger = new DeprecationLogger(Loggers.getLogger(getClass()));
deprecationLogger.deprecated("[{}] setting was deprecated in Elasticsearch and will be removed in a future release! " +
"See the breaking changes documentation for the next major version.", getKey());
final String key = getKey();
getDeprecationLogger().deprecatedAndMaybeLog(
key,
"[{}] setting was deprecated in Elasticsearch and will be removed in a future release! "
+ "See the breaking changes documentation for the next major version.",
key);
}
}

View File

@ -93,22 +93,6 @@ public final class Settings implements ToXContent {
/** The first level of setting names. This is constructed lazily in {@link #names()}. */
private final SetOnce<Set<String>> firstLevelNames = new SetOnce<>();
/**
* The set of deprecated settings tracked by this settings object.
*/
private final Set<String> deprecatedSettings = Collections.newSetFromMap(new ConcurrentHashMap<>());
/**
* Add the setting as a tracked deprecated setting.
*
* @param setting the deprecated setting to track
* @return true if the setting was not already tracked as a deprecated setting, otherwise false
*/
boolean addDeprecatedSetting(final Setting setting) {
assert setting.isDeprecated() && setting.exists(this) : setting.getKey();
return deprecatedSettings.add(setting.getKey());
}
/**
* Setting names found in this Settings for both string and secure settings.
* This is constructed lazily in {@link #keySet()}.

View File

@ -154,22 +154,6 @@ public class SettingTests extends ESTestCase {
assertNull(ab2.get());
}
public void testDeprecatedSetting() {
final Setting<Boolean> deprecatedSetting = Setting.boolSetting("deprecated.foo.bar", false, Property.Deprecated);
final Settings settings = Settings.builder().put("deprecated.foo.bar", true).build();
final int iterations = randomIntBetween(0, 128);
for (int i = 0; i < iterations; i++) {
deprecatedSetting.get(settings);
}
if (iterations > 0) {
/*
* This tests that we log the deprecation warning exactly one time, otherwise we would have to assert the deprecation warning
* for each usage of the setting.
*/
assertSettingDeprecationsAndWarnings(new Setting[]{deprecatedSetting});
}
}
public void testDefault() {
TimeValue defaultValue = TimeValue.timeValueMillis(randomIntBetween(0, 1000000));
Setting<TimeValue> setting =

View File

@ -31,6 +31,7 @@ import org.apache.logging.log4j.message.ParameterizedMessage;
import org.elasticsearch.cli.UserException;
import org.elasticsearch.cluster.ClusterName;
import org.elasticsearch.common.io.PathUtils;
import org.elasticsearch.common.settings.Setting;
import org.elasticsearch.common.settings.Settings;
import org.elasticsearch.env.Environment;
import org.elasticsearch.node.Node;
@ -42,6 +43,7 @@ import java.io.PrintWriter;
import java.io.StringWriter;
import java.nio.file.Files;
import java.nio.file.Path;
import java.util.ArrayList;
import java.util.List;
import java.util.regex.Matcher;
import java.util.regex.Pattern;
@ -94,22 +96,102 @@ public class EvilLoggerTests extends ESTestCase {
public void testDeprecationLogger() throws IOException, UserException {
setupLogging("deprecation");
final DeprecationLogger deprecationLogger = new DeprecationLogger(ESLoggerFactory.getLogger("deprecation"));
final DeprecationLogger deprecationLogger =
new DeprecationLogger(ESLoggerFactory.getLogger("deprecation"));
final int deprecatedIterations = randomIntBetween(0, 256);
for (int i = 0; i < deprecatedIterations; i++) {
deprecationLogger.deprecated("This is a deprecation message");
assertWarnings("This is a deprecation message");
}
deprecationLogger.deprecated("This is a deprecation message");
final String deprecationPath =
System.getProperty("es.logs.base_path") +
System.getProperty("file.separator") +
System.getProperty("es.logs.cluster_name") +
"_deprecation.log";
final List<String> deprecationEvents = Files.readAllLines(PathUtils.get(deprecationPath));
assertThat(deprecationEvents.size(), equalTo(1));
assertThat(deprecationEvents.size(), equalTo(deprecatedIterations));
for (int i = 0; i < deprecatedIterations; i++) {
assertLogLine(
deprecationEvents.get(i),
Level.WARN,
"org.elasticsearch.common.logging.DeprecationLogger.deprecated",
"This is a deprecation message");
}
}
public void testDeprecationLoggerMaybeLog() throws IOException, UserException {
setupLogging("deprecation");
final DeprecationLogger deprecationLogger =
new DeprecationLogger(ESLoggerFactory.getLogger("deprecation"));
final int iterations = randomIntBetween(1, 16);
for (int i = 0; i < iterations; i++) {
deprecationLogger.deprecatedAndMaybeLog("key", "This is a maybe logged deprecation message");
assertWarnings("This is a maybe logged deprecation message");
}
for (int k = 0; k < 128; k++) {
for (int i = 0; i < iterations; i++) {
deprecationLogger.deprecatedAndMaybeLog("key" + k, "This is a maybe logged deprecation message" + k);
assertWarnings("This is a maybe logged deprecation message" + k);
}
}
for (int i = 0; i < iterations; i++) {
deprecationLogger.deprecatedAndMaybeLog("key", "This is a maybe logged deprecation message");
assertWarnings("This is a maybe logged deprecation message");
}
final String deprecationPath =
System.getProperty("es.logs.base_path") +
System.getProperty("file.separator") +
System.getProperty("es.logs.cluster_name") +
"_deprecation.log";
final List<String> deprecationEvents = Files.readAllLines(PathUtils.get(deprecationPath));
assertThat(deprecationEvents.size(), equalTo(1 + 128 + 1));
assertLogLine(
deprecationEvents.get(0),
Level.WARN,
"org.elasticsearch.common.logging.DeprecationLogger.deprecated",
"This is a deprecation message");
assertWarnings("This is a deprecation message");
deprecationEvents.get(0),
Level.WARN,
"org.elasticsearch.common.logging.DeprecationLogger.deprecated",
"This is a maybe logged deprecation message");
for (int k = 0; k < 128; k++) {
assertLogLine(
deprecationEvents.get(1 + k),
Level.WARN,
"org.elasticsearch.common.logging.DeprecationLogger.deprecated",
"This is a maybe logged deprecation message" + k);
}
}
public void testDeprecatedSettings() throws IOException, UserException {
setupLogging("settings");
final Setting<Boolean> setting = Setting.boolSetting("deprecated.foo", false, Setting.Property.Deprecated);
final Settings settings = Settings.builder().put("deprecated.foo", true).build();
final int iterations = randomIntBetween(0, 128);
for (int i = 0; i < iterations; i++) {
setting.get(settings);
assertSettingDeprecationsAndWarnings(new Setting<?>[]{setting});
}
final String deprecationPath =
System.getProperty("es.logs.base_path") +
System.getProperty("file.separator") +
System.getProperty("es.logs.cluster_name") +
"_deprecation.log";
final List<String> deprecationEvents = Files.readAllLines(PathUtils.get(deprecationPath));
if (iterations > 0) {
assertThat(deprecationEvents.size(), equalTo(1));
assertLogLine(
deprecationEvents.get(0),
Level.WARN,
"org.elasticsearch.common.logging.DeprecationLogger.deprecated",
"\\[deprecated.foo\\] setting was deprecated in Elasticsearch and will be removed in a future release! " +
"See the breaking changes documentation for the next major version.");
}
}
public void testFindAppender() throws IOException, UserException {

View File

@ -0,0 +1,25 @@
appender.console.type = Console
appender.console.name = console
appender.console.layout.type = PatternLayout
appender.console.layout.pattern = [%d{ISO8601}][%-5p][%-25c] %marker%m%n
appender.file.type = File
appender.file.name = file
appender.file.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}.log
appender.file.layout.type = PatternLayout
appender.file.layout.pattern = [%p][%l] %marker%m%n
rootLogger.level = info
rootLogger.appenderRef.console.ref = console
rootLogger.appenderRef.file.ref = file
appender.deprecation_file.type = File
appender.deprecation_file.name = deprecation_file
appender.deprecation_file.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_deprecation.log
appender.deprecation_file.layout.type = PatternLayout
appender.deprecation_file.layout.pattern = [%p][%l] %marker%m%n
logger.deprecation.name = org.elasticsearch.deprecation.common.settings
logger.deprecation.level = warn
logger.deprecation.appenderRef.deprecation_file.ref = deprecation_file
logger.deprecation.additivity = false

View File

@ -30,7 +30,6 @@ import org.elasticsearch.common.settings.Settings;
import org.elasticsearch.common.xcontent.XContentBuilder;
import org.elasticsearch.common.xcontent.json.JsonXContent;
import org.elasticsearch.plugins.Plugin;
import org.elasticsearch.test.ESIntegTestCase;
import org.hamcrest.Matcher;
import java.io.IOException;
@ -55,7 +54,6 @@ import static org.hamcrest.Matchers.hasSize;
/**
* Tests {@code DeprecationLogger} uses the {@code ThreadContext} to add response headers.
*/
@ESIntegTestCase.ClusterScope(scope = ESIntegTestCase.Scope.TEST)
public class DeprecationHttpIT extends HttpSmokeTestCase {
@Override
@ -127,6 +125,14 @@ public class DeprecationHttpIT extends HttpSmokeTestCase {
doTestDeprecationWarningsAppearInHeaders();
}
public void testDeprecationHeadersDoNotGetStuck() throws Exception {
doTestDeprecationWarningsAppearInHeaders();
doTestDeprecationWarningsAppearInHeaders();
if (rarely()) {
doTestDeprecationWarningsAppearInHeaders();
}
}
/**
* Run a request that receives a predictably randomized number of deprecation warnings.
* <p>