added new constructor and tests (#7514)

Author: the-clam

sdk/common/src/main/java/io/opentelemetry/sdk/internal/ThrottlingLogger.java

@@ -8,6 +8,7 @@
 import static java.util.concurrent.TimeUnit.MINUTES;
 
 import io.opentelemetry.sdk.common.Clock;
+import java.util.Locale;
 import java.util.concurrent.TimeUnit;
 import java.util.concurrent.atomic.AtomicBoolean;
 import java.util.logging.Level;
@@ -21,28 +22,52 @@
  * at any time.
  */
 public class ThrottlingLogger {
-  private static final double RATE_LIMIT = 5;
-  private static final double THROTTLED_RATE_LIMIT = 1;
-  private static final TimeUnit rateTimeUnit = MINUTES;
+  private static final double DEFAULT_RATE_LIMIT = 5;
+  private static final double DEFAULT_THROTTLED_RATE_LIMIT = 1;
+  private static final TimeUnit DEFAULT_RATE_TIME_UNIT = MINUTES;
 
   private final Logger delegate;
   private final AtomicBoolean throttled = new AtomicBoolean(false);
   private final RateLimiter fastRateLimiter;
   private final RateLimiter throttledRateLimiter;
 
+  private final double rateLimit;
+  private final double throttledRateLimit;
+  private final TimeUnit rateTimeUnit;
+
   /** Create a new logger which will enforce a max number of messages per minute. */
   public ThrottlingLogger(Logger delegate) {
     this(delegate, Clock.getDefault());
   }
 
+  /** Alternate way to create logger that allows setting custom intervals and units. * */
+  public ThrottlingLogger(
+      Logger delegate, double rateLimit, double throttledRateLimit, TimeUnit rateTimeUnit) {
+    this(delegate, Clock.getDefault(), rateLimit, throttledRateLimit, rateTimeUnit);
+  }
+
   // visible for testing
   ThrottlingLogger(Logger delegate, Clock clock) {
+    this(delegate, clock, DEFAULT_RATE_LIMIT, DEFAULT_THROTTLED_RATE_LIMIT, DEFAULT_RATE_TIME_UNIT);
+  }
+
+  ThrottlingLogger(
+      Logger delegate,
+      Clock clock,
+      double rateLimit,
+      double throttledRateLimit,
+      TimeUnit rateTimeUnit) {
     this.delegate = delegate;
+    this.rateLimit = rateLimit;
+    this.throttledRateLimit = throttledRateLimit;
+    this.rateTimeUnit = rateTimeUnit;
     this.fastRateLimiter =
-        new RateLimiter(RATE_LIMIT / rateTimeUnit.toSeconds(1), RATE_LIMIT, clock);
+        new RateLimiter(this.rateLimit / this.rateTimeUnit.toSeconds(1), this.rateLimit, clock);
     this.throttledRateLimiter =
         new RateLimiter(
-            THROTTLED_RATE_LIMIT / rateTimeUnit.toSeconds(1), THROTTLED_RATE_LIMIT, clock);
+            this.throttledRateLimit / this.rateTimeUnit.toSeconds(1),
+            this.throttledRateLimit,
+            clock);
   }
 
   /** Log a message at the given level. */
@@ -69,9 +94,15 @@ public void log(Level level, String message, @Nullable Throwable throwable) {
 
     if (throttled.compareAndSet(false, true)) {
       // spend the balance in the throttled one, so that it starts at zero.
-      throttledRateLimiter.trySpend(THROTTLED_RATE_LIMIT);
-      delegate.log(
-          level, "Too many log messages detected. Will only log once per minute from now on.");
+      throttledRateLimiter.trySpend(throttledRateLimit);
+      String timeUnitString = rateTimeUnit.toString().toLowerCase(Locale.ROOT);
+      String throttleMessage =
+          String.format(
+              Locale.ROOT,
+              "Too many log messages detected. Will only log %.0f time(s) per %s from now on.",
+              throttledRateLimit,
+              timeUnitString.substring(0, timeUnitString.length() - 1));
+      delegate.log(level, throttleMessage);
       doLog(level, message, throwable);
     }
   }

sdk/common/src/test/java/io/opentelemetry/sdk/internal/ThrottlingLoggerTest.java

@@ -15,6 +15,7 @@
 import io.opentelemetry.sdk.common.Clock;
 import io.opentelemetry.sdk.testing.time.TestClock;
 import java.time.Duration;
+import java.util.concurrent.TimeUnit;
 import java.util.logging.Level;
 import java.util.logging.Logger;
 import org.junit.jupiter.api.Test;
@@ -45,6 +46,23 @@ void delegation() {
         .isSameAs(throwable);
   }
 
+  @Test
+  void delegationCustom() {
+    ThrottlingLogger logger = new ThrottlingLogger(realLogger, 10, 2, TimeUnit.HOURS);
+
+    logger.log(Level.WARNING, "oh no!");
+    logger.log(Level.INFO, "oh yes!");
+    RuntimeException throwable = new RuntimeException();
+    logger.log(Level.SEVERE, "secrets", throwable);
+
+    logs.assertContains(loggingEvent -> loggingEvent.getLevel().equals(WARN), "oh no!");
+    logs.assertContains(loggingEvent -> loggingEvent.getLevel().equals(INFO), "oh yes!");
+    assertThat(
+            logs.assertContains(loggingEvent -> loggingEvent.getLevel().equals(ERROR), "secrets")
+                .getThrowable())
+        .isSameAs(throwable);
+  }
+
   @Test
   void logsBelowLevelDontCount() {
     ThrottlingLogger logger =
@@ -76,7 +94,26 @@ void fiveInAMinuteTriggersLimiting() {
     assertThat(logs.getEvents()).hasSize(7);
     logs.assertDoesNotContain("oh no I should be suppressed!");
     logs.assertContains(
-        "Too many log messages detected. Will only log once per minute from now on.");
+        "Too many log messages detected. Will only log 1 time(s) per minute from now on.");
+    logs.assertContains("oh no I should trigger suppression!");
+  }
+
+  @Test
+  void tenInAnHourTriggersLimiting() {
+    Clock clock = TestClock.create();
+    ThrottlingLogger logger = new ThrottlingLogger(realLogger, clock, 10, 2, TimeUnit.HOURS);
+
+    for (int i = 0; i < 10; i++) {
+      logger.log(Level.WARNING, "oh no!");
+    }
+
+    logger.log(Level.WARNING, "oh no I should trigger suppression!");
+    logger.log(Level.WARNING, "oh no I should be suppressed!");
+
+    assertThat(logs.getEvents()).hasSize(12);
+    logs.assertDoesNotContain("oh no I should be suppressed!");
+    logs.assertContains(
+        "Too many log messages detected. Will only log 2 time(s) per hour from now on.");
     logs.assertContains("oh no I should trigger suppression!");
   }
 
@@ -130,7 +167,7 @@ void afterAMinuteLetOneThrough() {
     logs.assertDoesNotContain("oh no I should be suppressed!");
     logs.assertContains("oh no I should trigger suppression!");
     logs.assertContains(
-        "Too many log messages detected. Will only log once per minute from now on.");
+        "Too many log messages detected. Will only log 1 time(s) per minute from now on.");
 
     clock.advance(Duration.ofMillis(60_001));
     logger.log(Level.WARNING, "oh no!");
@@ -145,6 +182,41 @@ void afterAMinuteLetOneThrough() {
     assertThat(logs.getEvents().get(8).getMessage()).isEqualTo("oh no!");
   }
 
+  @Test
+  void afterAnHourLetTwoThrough() {
+    TestClock clock = TestClock.create();
+    ThrottlingLogger logger = new ThrottlingLogger(realLogger, clock, 10, 2, TimeUnit.HOURS);
+
+    for (int i = 0; i < 10; i++) {
+      logger.log(Level.WARNING, "oh no!");
+    }
+
+    logger.log(Level.WARNING, "oh no I should trigger suppression!");
+    logger.log(Level.WARNING, "oh no I should be suppressed!");
+
+    assertThat(logs.getEvents()).hasSize(12);
+    logs.assertDoesNotContain("oh no I should be suppressed!");
+    logs.assertContains("oh no I should trigger suppression!");
+    logs.assertContains(
+        "Too many log messages detected. Will only log 2 time(s) per hour from now on.");
+
+    clock.advance(Duration.ofMinutes(61));
+    logger.log(Level.WARNING, "oh no!");
+    logger.log(Level.WARNING, "oh no!");
+    logger.log(Level.WARNING, "oh no I should be suppressed!");
+    assertThat(logs.getEvents()).hasSize(14);
+    assertThat(logs.getEvents().get(13).getMessage()).isEqualTo("oh no!");
+
+    clock.advance(Duration.ofMinutes(61));
+    logger.log(Level.WARNING, "oh no!");
+    logger.log(Level.WARNING, "oh no!");
+    logger.log(Level.WARNING, "oh no I should be suppressed!");
+    assertThat(logs.getEvents()).hasSize(16);
+    assertThat(logs.getEvents().get(15).getMessage()).isEqualTo("oh no!");
+
+    logs.assertDoesNotContain("oh no I should be suppressed!");
+  }
+
   @Test
   void allowOnlyOneLogPerMinuteAfterSuppression() {
     TestClock clock = TestClock.create();
@@ -181,4 +253,45 @@ void allowOnlyOneLogPerMinuteAfterSuppression() {
     assertThat(logs.getEvents()).hasSize(8);
     assertThat(logs.getEvents().get(7).getMessage()).isEqualTo("allowed 1");
   }
+
+  @Test
+  void allowOnlyTwoLogPerHourAfterSuppression() {
+    TestClock clock = TestClock.create();
+    ThrottlingLogger logger = new ThrottlingLogger(realLogger, clock, 10, 2, TimeUnit.HOURS);
+
+    for (int i = 0; i < 10; i++) {
+      logger.log(Level.WARNING, "oh no!");
+    }
+
+    logger.log(Level.WARNING, "oh no I should trigger suppression!");
+    logger.log(Level.WARNING, "oh no I should be suppressed!");
+
+    assertThat(logs.getEvents()).hasSize(12);
+
+    clock.advance(Duration.ofMinutes(10));
+    logger.log(Level.WARNING, "suppression 1");
+    clock.advance(Duration.ofMinutes(10));
+    logger.log(Level.WARNING, "suppression 2");
+    clock.advance(Duration.ofMinutes(10));
+    clock.advance(Duration.ofSeconds(1));
+    logger.log(Level.WARNING, "allowed 1");
+    clock.advance(Duration.ofMinutes(10));
+    logger.log(Level.WARNING, "suppression 3");
+    clock.advance(Duration.ofMinutes(10));
+    logger.log(Level.WARNING, "suppression 4");
+    clock.advance(Duration.ofMinutes(10));
+    clock.advance(Duration.ofSeconds(1));
+    logger.log(Level.WARNING, "allowed 2");
+
+    logs.assertDoesNotContain("suppression 1");
+    logs.assertDoesNotContain("suppression 2");
+    logs.assertDoesNotContain("suppression 3");
+    logs.assertDoesNotContain("suppression 4");
+    logs.assertContains("allowed 1");
+    logs.assertContains("allowed 2");
+
+    assertThat(logs.getEvents()).hasSize(14);
+    assertThat(logs.getEvents().get(12).getMessage()).isEqualTo("allowed 1");
+    assertThat(logs.getEvents().get(13).getMessage()).isEqualTo("allowed 2");
+  }
 }