Merge pull request #648 from DataDog/mar-kolya/add-log-ratelimiter

Add log ratelimiter

dd-trace/src/main/java/datadog/trace/tracer/LogRateLimiter.java

@@ -0,0 +1,51 @@
+package datadog.trace.tracer;
+
+import java.util.concurrent.TimeUnit;
+import org.slf4j.Logger;
+
+/**
+ * Helper class to limit errors logged into application's error log.
+ *
+ * <p>TODO: can we make this class not public?
+ *
+ * <p>TODO: once we drop 1.7 support we should be able to use {@code java.time.Clock} instead of
+ * {@code System.currentTimeMillis} to simplify testing.
+ */
+public class LogRateLimiter {
+
+  private final Logger log;
+  private final long millisecondsBetweenLog;
+
+  private long nextAllowedLogTime = 0;
+
+  public LogRateLimiter(final Logger log, final long millisecondsBetweenLog) {
+    this.log = log;
+    this.millisecondsBetweenLog = millisecondsBetweenLog;
+  }
+
+  public synchronized void warn(String message, final Object... arguments) {
+    if (log.isDebugEnabled()) {
+      log.debug(message, arguments);
+    } else if (nextAllowedLogTime <= System.currentTimeMillis()) {
+      message +=
+          " (going silent for "
+              + TimeUnit.MILLISECONDS.toMinutes(millisecondsBetweenLog)
+              + " minutes)";
+      nextAllowedLogTime = System.currentTimeMillis() + millisecondsBetweenLog;
+      log.warn(message, arguments);
+    }
+  }
+
+  public synchronized void error(String message, final Object... arguments) {
+    if (log.isDebugEnabled()) {
+      log.debug(message, arguments);
+    } else if (nextAllowedLogTime <= System.currentTimeMillis()) {
+      message +=
+          " (going silent for "
+              + TimeUnit.MILLISECONDS.toMinutes(millisecondsBetweenLog)
+              + " minutes)";
+      nextAllowedLogTime = System.currentTimeMillis() + millisecondsBetweenLog;
+      log.error(message, arguments);
+    }
+  }
+}

dd-trace/src/test/groovy/datadog/trace/tracer/LogRateLimiterTest.groovy

@@ -0,0 +1,70 @@
+package datadog.trace.tracer
+
+import org.slf4j.Logger
+import spock.lang.Specification
+
+
+class LogRateLimiterTest extends Specification {
+
+  private static final String MESSAGE = "message"
+  private static final int REPEAT_COUNT = 10
+
+  def log = Mock(Logger)
+  def object = new Object()
+
+  def "test debugging enabled: #method"() {
+    setup:
+    log.isDebugEnabled() >> true
+    def logRateLimiter = new LogRateLimiter(log, 10)
+
+    when: "message is logged"
+    logRateLimiter."${method}"(MESSAGE, object)
+
+    then: "debug message is output"
+    1 * log.debug(MESSAGE, object)
+
+    where:
+    method | _
+    "warn" | _
+    "error" | _
+  }
+
+  def "test debugging disabled, no delay: #method"() {
+    setup: "debug is disabled and delay between log is zero"
+    log.isDebugEnabled() >> false
+    def logRateLimiter = new LogRateLimiter(log, 0)
+
+    when: "messages are logged"
+    for (int i = 0; i < REPEAT_COUNT; i++) {
+      logRateLimiter."${method}"(MESSAGE, object)
+    }
+
+    then: "all messages are output with appropriate log level"
+    REPEAT_COUNT * log."${method}"({it.contains(MESSAGE)}, object)
+
+    where:
+    method | _
+    "warn" | _
+    "error" | _
+  }
+
+  def "test debugging disabled, large delay: #method"() {
+    setup: "debug is disabled and delay between log is large"
+    log.isDebugEnabled() >> false
+    def logRateLimiter = new LogRateLimiter(log, 10000000)
+
+    when: "messages are logged"
+    for (int i = 0; i < REPEAT_COUNT; i++) {
+      logRateLimiter."${method}"(MESSAGE, object)
+    }
+
+    then: "message is output once"
+    1 * log."${method}"({it.contains(MESSAGE)}, object)
+
+    where:
+    method | _
+    "warn" | _
+    "error" | _
+  }
+
+}