Logger: Replace static sampling with configurable

src/main/java/org/prebid/server/auction/requestfactory/Ortb2RequestFactory.java

@@ -558,7 +558,7 @@ private Future<Account> wrapFailure(Throwable exception, String accountId, HttpR
         if (exception instanceof UnauthorizedAccountException) {
             return Future.failedFuture(exception);
         } else if (exception instanceof PreBidException) {
-            unknownAccountLogger.warn(accountErrorMessage(exception.getMessage(), httpRequest), 100);
+            unknownAccountLogger.warn(accountErrorMessage(exception.getMessage(), httpRequest), logSamplingRate);
         } else {
             metrics.updateAccountRequestRejectedByFailedFetch(accountId);
             logger.warn("Error occurred while fetching account: {}", exception.getMessage());

src/main/java/org/prebid/server/handler/openrtb2/AmpHandler.java

@@ -370,14 +370,14 @@ private void handleResult(AsyncResult<RawResponseContext> responseResult,
                 conditionalLogger.info(
                         "%s, Referer: %s"
                                 .formatted(message, routingContext.request().headers().get(HttpUtil.REFERER_HEADER)),
-                        100);
+                        logSamplingRate);
 
                 status = HttpResponseStatus.BAD_REQUEST;
                 body = message;
             } else if (exception instanceof UnauthorizedAccountException) {
                 metricRequestStatus = MetricName.badinput;
                 final String message = exception.getMessage();
-                conditionalLogger.info(message, 100);
+                conditionalLogger.info(message, logSamplingRate);
 
                 errorMessages = Collections.singletonList(message);
 

src/main/java/org/prebid/server/log/ConditionalLogger.java

@@ -8,7 +8,6 @@
 import java.util.concurrent.ConcurrentMap;
 import java.util.concurrent.ThreadLocalRandom;
 import java.util.concurrent.TimeUnit;
-import java.util.concurrent.atomic.AtomicInteger;
 import java.util.function.Consumer;
 
 public class ConditionalLogger {
@@ -19,125 +18,75 @@ public class ConditionalLogger {
     private final String key;
     private final Logger logger;
 
-    private final ConcurrentMap<String, AtomicInteger> messageToCount;
-    private final ConcurrentMap<String, Long> messageToWait;
+    private final ConcurrentMap<String, Instant> messageToWait;
 
     public ConditionalLogger(String key, Logger logger) {
         this.key = key; // can be null
         this.logger = Objects.requireNonNull(logger);
 
-        messageToCount = Caffeine.newBuilder()
-                .maximumSize(CACHE_MAXIMUM_SIZE)
-                .expireAfterWrite(EXPIRE_CACHE_DURATION, TimeUnit.HOURS)
-                .<String, AtomicInteger>build()
-                .asMap();
-
         messageToWait = Caffeine.newBuilder()
                 .maximumSize(CACHE_MAXIMUM_SIZE)
                 .expireAfterWrite(EXPIRE_CACHE_DURATION, TimeUnit.HOURS)
-                .<String, Long>build()
+                .<String, Instant>build()
                 .asMap();
     }
 
     public ConditionalLogger(Logger logger) {
         this(null, logger);
     }
 
-    public void infoWithKey(String key, String message, int limit) {
-        log(key, limit, logger -> logger.info(message));
+    public void debug(String message, long duration, TimeUnit unit) {
+        log(message, duration, unit, logger::debug);
     }
 
-    public void info(String message, int limit) {
-        log(message, limit, logger -> logger.info(message));
+    public void debug(String message, double samplingRate) {
+        log(message, samplingRate, logger::debug);
     }
 
     public void info(String message, long duration, TimeUnit unit) {
-        log(message, duration, unit, logger -> logger.info(message));
+        log(message, duration, unit, logger::info);
     }
 
     public void info(String message, double samplingRate) {
-        if (samplingRate >= 1.0d || ThreadLocalRandom.current().nextDouble() < samplingRate) {
-            logger.warn(message);
-        }
+        log(message, samplingRate, logger::info);
     }
 
-    public void errorWithKey(String key, String message, int limit) {
-        log(key, limit, logger -> logger.error(message));
+    public void warn(String message, long duration, TimeUnit unit) {
+        log(message, duration, unit, logger::warn);
     }
 
-    public void error(String message, int limit) {
-        log(message, limit, logger -> logger.error(message));
+    public void warn(String message, double samplingRate) {
+        log(message, samplingRate, logger::warn);
     }
 
     public void error(String message, long duration, TimeUnit unit) {
-        log(message, duration, unit, logger -> logger.error(message));
+        log(message, duration, unit, logger::error);
     }
 
     public void error(String message, double samplingRate) {
-        if (samplingRate >= 1.0d || ThreadLocalRandom.current().nextDouble() < samplingRate) {
-            logger.error(message);
-        }
-    }
-
-    public void debug(String message, int limit) {
-        log(message, limit, logger -> logger.debug(message));
-    }
-
-    public void debug(String message, long duration, TimeUnit unit) {
-        log(message, duration, unit, logger -> logger.debug(message));
+        log(message, samplingRate, logger::error);
     }
 
-    public void debug(String message, double samplingRate) {
+    private static void log(String message, double samplingRate, Consumer<String> logger) {
         if (samplingRate >= 1.0d || ThreadLocalRandom.current().nextDouble() < samplingRate) {
-            logger.debug(message);
+            logger.accept(message);
         }
     }
 
-    public void warn(String message, int limit) {
-        log(message, limit, logger -> logger.warn(message));
-    }
-
-    public void warn(String message, long duration, TimeUnit unit) {
-        log(message, duration, unit, logger -> logger.warn(message));
-    }
-
-    public void warn(String message, double samplingRate) {
-        if (samplingRate >= 1.0d || ThreadLocalRandom.current().nextDouble() < samplingRate) {
-            logger.warn(message);
-        }
-    }
-
-    /**
-     * Calls {@link Consumer} if the given limit for specified key is not exceeded.
-     */
-    private void log(String key, int limit, Consumer<Logger> consumer) {
-        final String resolvedKey = ObjectUtils.defaultIfNull(this.key, key);
-        final AtomicInteger count = messageToCount.computeIfAbsent(resolvedKey, ignored -> new AtomicInteger());
-        if (count.incrementAndGet() >= limit) {
-            count.set(0);
-            consumer.accept(logger);
-        }
-    }
+    private void log(String message, long duration, TimeUnit unit, Consumer<String> logger) {
+        final String key = ObjectUtils.defaultIfNull(this.key, message);
+        final Instant currentTime = Instant.now();
+        final Instant endTime = messageToWait.computeIfAbsent(
+                key, ignored -> calculateEndTime(currentTime, duration, unit));
 
-    /**
-     * Calls {@link Consumer} if the given time for specified key is not exceeded.
-     */
-    private void log(String key, long duration, TimeUnit unit, Consumer<Logger> consumer) {
-        final long currentTime = Instant.now().toEpochMilli();
-        final String resolvedKey = ObjectUtils.defaultIfNull(this.key, key);
-        final long endTime = messageToWait.computeIfAbsent(resolvedKey, ignored -> calculateEndTime(duration, unit));
-
-        if (currentTime >= endTime) {
-            messageToWait.replace(resolvedKey, endTime, calculateEndTime(duration, unit));
-            consumer.accept(logger);
+        // we skip 1st ever log event for the key
+        if (currentTime.isAfter(endTime) || currentTime.equals(endTime)) {
+            messageToWait.replace(key, endTime, calculateEndTime(currentTime, duration, unit));
+            logger.accept(message);
         }
     }
 
-    /**
-     * Returns time in millis as current time incremented by specified duration.
-     */
-    private static long calculateEndTime(long duration, TimeUnit unit) {
-        final long durationInMillis = unit.toMillis(duration);
-        return Instant.now().plusMillis(durationInMillis).toEpochMilli();
+    private static Instant calculateEndTime(Instant currentTime, long duration, TimeUnit unit) {
+        return currentTime.plusMillis(unit.toMillis(duration));
     }
 }

src/main/java/org/prebid/server/privacy/gdpr/TcfDefinerService.java

@@ -386,25 +386,25 @@ private TCString decodeTcString(String consentString, RequestLogInfo requestLogI
         }
     }
 
-    private static void logWarn(String consent, String message, RequestLogInfo requestLogInfo) {
+    private void logWarn(String consent, String message, RequestLogInfo requestLogInfo) {
         if (requestLogInfo == null || requestLogInfo.getRequestType() == null) {
             final String exceptionMessage = "Parsing consent string:\"%s\" failed for undefined type with exception %s"
                     .formatted(consent, message);
-            undefinedCorruptConsentLogger.info(exceptionMessage, 100);
+            undefinedCorruptConsentLogger.info(exceptionMessage, samplingRate);
             return;
         }
 
         switch (requestLogInfo.getRequestType()) {
             case amp -> ampCorruptConsentLogger.info(
-                    logMessage(consent, MetricName.amp.toString(), requestLogInfo, message), 100);
+                    logMessage(consent, MetricName.amp.toString(), requestLogInfo, message), samplingRate);
             case openrtb2app -> appCorruptConsentLogger.info(
-                    logMessage(consent, MetricName.openrtb2app.toString(), requestLogInfo, message), 100);
+                    logMessage(consent, MetricName.openrtb2app.toString(), requestLogInfo, message), samplingRate);
             case openrtb2dooh -> doohCorruptConsentLogger.info(
-                    logMessage(consent, MetricName.openrtb2dooh.toString(), requestLogInfo, message), 100);
+                    logMessage(consent, MetricName.openrtb2dooh.toString(), requestLogInfo, message), samplingRate);
             case openrtb2web -> siteCorruptConsentLogger.info(
-                    logMessage(consent, MetricName.openrtb2web.toString(), requestLogInfo, message), 100);
+                    logMessage(consent, MetricName.openrtb2web.toString(), requestLogInfo, message), samplingRate);
             default -> undefinedCorruptConsentLogger.info(
-                    logMessage(consent, "video or sync or setuid", requestLogInfo, message), 100);
+                    logMessage(consent, "video or sync or setuid", requestLogInfo, message), samplingRate);
         }
     }
 

src/test/java/org/prebid/server/log/ConditionalLoggerTest.java

@@ -8,22 +8,21 @@
 import org.junit.jupiter.api.BeforeEach;
 import org.junit.jupiter.api.Test;
 import org.junit.jupiter.api.extension.ExtendWith;
-import org.mockito.Mock;
+import org.mockito.Spy;
 import org.mockito.junit.jupiter.MockitoExtension;
 
 import java.util.concurrent.TimeUnit;
 
 import static org.mockito.ArgumentMatchers.argThat;
 import static org.mockito.Mockito.times;
 import static org.mockito.Mockito.verify;
-import static org.mockito.Mockito.verifyNoMoreInteractions;
 
 @ExtendWith(MockitoExtension.class)
 @ExtendWith(VertxExtension.class)
 public class ConditionalLoggerTest {
 
-    @Mock
-    private Logger logger;
+    @Spy
+    private Logger logger = LoggerFactory.getLogger(ConditionalLoggerTest.class);
 
     private Vertx vertx;
 
@@ -41,45 +40,18 @@ public void tearDown(VertxTestContext context) {
     }
 
     @Test
-    public void infoWithKeyShouldCallLoggerWithExpectedCount() {
+    public void infoShouldCallLoggerForEachLog() {
         // when
-        for (int i = 0; i < 10; i++) {
-            conditionalLogger.infoWithKey("key", "Log Message1", 2);
-            conditionalLogger.infoWithKey("key", "Log Message2", 2);
-        }
-
-        // then
-        verify(logger, times(10)).info("Log Message2");
-        verifyNoMoreInteractions(logger);
-    }
-
-    @Test
-    public void infoShouldCallLoggerWithExpectedCount() {
-        // when
-        for (int i = 0; i < 10; i++) {
-            conditionalLogger.info("Log Message", 2);
-        }
-
-        // then
-        verify(logger, times(5)).info("Log Message");
-    }
-
-    @Test
-    public void infoShouldCallLoggerBySpecifiedKeyWithExpectedCount() {
-        // given
-        conditionalLogger = new ConditionalLogger("key1", logger);
-
-        // when
-        for (int i = 0; i < 10; i++) {
-            conditionalLogger.info("Log Message" + i, 2);
+        for (int i = 0; i < 5; i++) {
+            conditionalLogger.info("Log Message" + i, 0, TimeUnit.MILLISECONDS);
         }
 
         // then
         verify(logger, times(5)).info(argThat(o -> o.toString().startsWith("Log Message")));
     }
 
     @Test
-    public void infoShouldCallLoggerWithExpectedTimeout() {
+    public void infoShouldSkipLogsForDuration() {
         // when
         for (int i = 0; i < 5; i++) {
             conditionalLogger.info("Log Message", 200, TimeUnit.MILLISECONDS);
@@ -91,7 +63,7 @@ public void infoShouldCallLoggerWithExpectedTimeout() {
     }
 
     @Test
-    public void infoShouldCallLoggerBySpecifiedKeyWithExpectedTimeout() {
+    public void infoShouldSkipLogsForKeyForDuration() {
         // given
         conditionalLogger = new ConditionalLogger("key1", logger);