-
Notifications
You must be signed in to change notification settings - Fork 4.1k
CASSANDRA-21474: NoSpamLogger uses unbounded cache that could lead to memory exhaustion #4993
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.
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
base: trunk
Are you sure you want to change the base?
Changes from all commits
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -17,6 +17,7 @@ | |
| */ | ||
| package org.apache.cassandra.utils; | ||
|
|
||
| import java.util.concurrent.ForkJoinPool; | ||
| import java.util.concurrent.TimeUnit; | ||
| import java.util.concurrent.atomic.AtomicLong; | ||
| import java.util.function.Supplier; | ||
|
|
@@ -27,6 +28,12 @@ | |
| import org.slf4j.Logger; | ||
|
|
||
| import static org.apache.cassandra.utils.Clock.Global; | ||
| import com.github.benmanes.caffeine.cache.Cache; | ||
| import com.github.benmanes.caffeine.cache.Caffeine; | ||
| import com.github.benmanes.caffeine.cache.Expiry; | ||
| import com.github.benmanes.caffeine.cache.Ticker; | ||
|
|
||
| import static org.apache.cassandra.config.CassandraRelevantProperties.NOSPAM_LOGGER_MAX_STATEMENTS_PER_LOGGER; | ||
|
|
||
| /** | ||
| * Logging that limits each log statement to firing based on time since the statement last fired. | ||
|
|
@@ -36,8 +43,11 @@ | |
| * result in the original time being used. No warning is provided if there is a mismatch. | ||
| * | ||
| * If the statement is cached and used to log directly then only a volatile read will be required in the common case. | ||
| * If the Logger is cached then there is a single concurrent hash map lookup + the volatile read. | ||
| * If neither the logger nor the statement is cached then it is two concurrent hash map lookups + the volatile read. | ||
| * If the Logger is cached then there is a single Caffeine cache lookup + the volatile read. | ||
| * If neither the logger nor the statement is cached then it is a NonBlockingHashMap lookup + a Caffeine cache lookup + the volatile read. | ||
| * | ||
| * The implementation uses Caffeine cache with time-based expiration to automatically evict log statements | ||
| * after their minimum interval has passed, preventing unbounded memory growth from dynamic log messages. | ||
| * | ||
| */ | ||
| public class NoSpamLogger | ||
|
|
@@ -64,6 +74,9 @@ public static void unsafeSetClock(Clock clock) | |
| CLOCK = clock; | ||
| } | ||
|
|
||
| @VisibleForTesting | ||
| static Ticker TICKER = Ticker.systemTicker(); | ||
|
|
||
| public class NoSpamLogStatement extends AtomicLong | ||
| { | ||
| private static final long serialVersionUID = 1L; | ||
|
|
@@ -157,6 +170,11 @@ public boolean error(Object... objects) | |
| { | ||
| return NoSpamLogStatement.this.error(CLOCK.nanoTime(), objects); | ||
| } | ||
|
|
||
| public long expiry() | ||
| { | ||
| return minIntervalNanos; | ||
| } | ||
| } | ||
|
|
||
| private static final NonBlockingHashMap<Logger, NoSpamLogger> wrappedLoggers = new NonBlockingHashMap<>(); | ||
|
|
@@ -167,6 +185,28 @@ static void clearWrappedLoggersForTest() | |
| wrappedLoggers.clear(); | ||
| } | ||
|
|
||
| /** | ||
| * Forces eviction of entries from the {@link NoSpamLogStatement} cache for this logger instance. | ||
| * This is useful for testing to ensure cache size limits are enforced immediately. | ||
| */ | ||
| @VisibleForTesting | ||
| void cleanUpStatementsForTest() | ||
| { | ||
| lastMessage.cleanUp(); | ||
| } | ||
|
|
||
| /** | ||
| * Returns the current size of the lastMessage cache for this logger instance. | ||
| * This is useful for testing cache eviction behavior. | ||
| * | ||
| * @return the number of log statements currently cached for this logger | ||
| */ | ||
| @VisibleForTesting | ||
| long getStatementsCount() | ||
| { | ||
| return lastMessage.estimatedSize(); | ||
| } | ||
|
|
||
| public static NoSpamLogger getLogger(Logger logger, long minInterval, TimeUnit unit) | ||
| { | ||
| NoSpamLogger wrapped = wrappedLoggers.get(logger); | ||
|
|
@@ -222,7 +262,41 @@ public static NoSpamLogStatement getStatement(Logger logger, String message, lon | |
|
|
||
| private final Logger wrapped; | ||
| private final long minIntervalNanos; | ||
| private final NonBlockingHashMap<String, NoSpamLogStatement> lastMessage = new NonBlockingHashMap<>(); | ||
|
|
||
| /** | ||
| * Cache of NoSpamLogStatement instances per NoSpamLogger instance. | ||
| * Bounded by size and time to prevent memory exhaustion from dynamic log messages. | ||
| * Uses Caffeine with W-TinyLFU eviction policy. | ||
| * Uses custom per-entry expiry based on each statement's minIntervalNanos. | ||
| */ | ||
| private final Cache<String, NoSpamLogStatement> lastMessage = Caffeine.newBuilder() | ||
| .maximumSize(NOSPAM_LOGGER_MAX_STATEMENTS_PER_LOGGER.getLong()) | ||
| .expireAfter(new Expiry<String, NoSpamLogStatement>() | ||
| { | ||
| @Override | ||
| public long expireAfterCreate(String key, NoSpamLogStatement value, long currentTime) | ||
| { | ||
| return value.expiry(); | ||
| } | ||
|
|
||
| @Override | ||
| public long expireAfterUpdate(String key, NoSpamLogStatement value, | ||
| long currentTime, long currentDuration) | ||
| { | ||
| return value.expiry(); | ||
| } | ||
|
|
||
| @Override | ||
| public long expireAfterRead(String key, NoSpamLogStatement value, | ||
| long currentTime, long currentDuration) | ||
| { | ||
| return currentDuration; | ||
| } | ||
| }) | ||
| .ticker(TICKER) | ||
| .executor(ForkJoinPool.commonPool()) | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. @viktoriiakotovets I am not completely sure about this executor here. If you look what executors we use for Caffeine caches we never used this one. It would be appropriate if you did some basic research for the justification why we should use this executor specifically or change it to something more fitting.
Member
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. right, we don't want to use @smiklosovic , which existing executor would you recommend ? or should we create a new one ?
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. If we want a dedicated executor for this then I would go with I lean towards a dedicated one because I do not like the fact that I would also most probably use That being said, we would need to walk an extra mile here to be sure that we shutdown the executor upon shutdown of a node. AFAIK Caffeine is not shutting down the executor we hand it so we would need to be sure that we shut it down when not used anymore, likely in something like StorageService.drain() or similar. btw isnt |
||
| .recordStats() | ||
| .build(); | ||
|
|
||
| private NoSpamLogger(Logger wrapped, long minInterval, TimeUnit timeUnit) | ||
| { | ||
|
|
@@ -302,14 +376,6 @@ public NoSpamLogStatement getStatement(String s, long minIntervalNanos) | |
|
|
||
| public NoSpamLogStatement getStatement(String key, String s, long minIntervalNanos) | ||
| { | ||
| NoSpamLogStatement statement = lastMessage.get(key); | ||
| if (statement == null) | ||
| { | ||
| statement = new NoSpamLogStatement(s, minIntervalNanos); | ||
| NoSpamLogStatement temp = lastMessage.putIfAbsent(key, statement); | ||
| if (temp != null) | ||
| statement = temp; | ||
| } | ||
| return statement; | ||
| return lastMessage.get(key, k -> new NoSpamLogStatement(s, minIntervalNanos)); | ||
| } | ||
| } | ||
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
fwiw, you might prefer
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
sure, but that might need upgrade to 3.2.2 first