diff --git a/src/main/java/org/prebid/server/auction/requestfactory/Ortb2RequestFactory.java b/src/main/java/org/prebid/server/auction/requestfactory/Ortb2RequestFactory.java index 1604783c3b8..2eaa340509c 100644 --- a/src/main/java/org/prebid/server/auction/requestfactory/Ortb2RequestFactory.java +++ b/src/main/java/org/prebid/server/auction/requestfactory/Ortb2RequestFactory.java @@ -558,7 +558,7 @@ private Future 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()); diff --git a/src/main/java/org/prebid/server/handler/openrtb2/AmpHandler.java b/src/main/java/org/prebid/server/handler/openrtb2/AmpHandler.java index a7b39dce659..1ee95db2813 100644 --- a/src/main/java/org/prebid/server/handler/openrtb2/AmpHandler.java +++ b/src/main/java/org/prebid/server/handler/openrtb2/AmpHandler.java @@ -370,14 +370,14 @@ private void handleResult(AsyncResult 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); diff --git a/src/main/java/org/prebid/server/log/ConditionalLogger.java b/src/main/java/org/prebid/server/log/ConditionalLogger.java index f3e17bb9ed0..1a9227bc63d 100644 --- a/src/main/java/org/prebid/server/log/ConditionalLogger.java +++ b/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,23 +18,16 @@ public class ConditionalLogger { private final String key; private final Logger logger; - private final ConcurrentMap messageToCount; - private final ConcurrentMap messageToWait; + private final ConcurrentMap 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) - .build() - .asMap(); - messageToWait = Caffeine.newBuilder() .maximumSize(CACHE_MAXIMUM_SIZE) .expireAfterWrite(EXPIRE_CACHE_DURATION, TimeUnit.HOURS) - .build() + .build() .asMap(); } @@ -43,101 +35,58 @@ 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 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 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 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 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)); } } diff --git a/src/main/java/org/prebid/server/privacy/gdpr/TcfDefinerService.java b/src/main/java/org/prebid/server/privacy/gdpr/TcfDefinerService.java index 0d86272d378..2fd8ff4d186 100644 --- a/src/main/java/org/prebid/server/privacy/gdpr/TcfDefinerService.java +++ b/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); } } diff --git a/src/test/groovy/org/prebid/server/functional/tests/AccountSpec.groovy b/src/test/groovy/org/prebid/server/functional/tests/AccountSpec.groovy index 6bfb51536cc..e2730e46e52 100644 --- a/src/test/groovy/org/prebid/server/functional/tests/AccountSpec.groovy +++ b/src/test/groovy/org/prebid/server/functional/tests/AccountSpec.groovy @@ -10,14 +10,19 @@ import org.prebid.server.functional.model.request.auction.Site import org.prebid.server.functional.service.PrebidServerException import org.prebid.server.functional.util.PBSUtils +import java.time.Instant + import static io.netty.handler.codec.http.HttpResponseStatus.UNAUTHORIZED class AccountSpec extends BaseSpec { def "PBS should reject request with inactive account"() { - given: "Pbs config with enforce-valid-account and default-account-config" - def pbsService = pbsServiceFactory.getService( - ["settings.enforce-valid-account": enforceValidAccount as String]) + given: "Start up time" + def start = Instant.now() + + and: "Pbs config with enforce-valid-account" + def pbsConfig = ["settings.enforce-valid-account": enforceValidAccount as String] + def pbsService = pbsServiceFactory.getService(pbsConfig) and: "Inactive account id" def accountId = PBSUtils.randomNumber @@ -34,13 +39,56 @@ class AccountSpec extends BaseSpec { then: "PBS should reject the entire auction" def exception = thrown(PrebidServerException) + def warningMessage = "Account $accountId is inactive" assert exception.statusCode == UNAUTHORIZED.code() - assert exception.responseBody == "Account $accountId is inactive" + assert exception.responseBody == warningMessage + + and: "PBs should emit warning logs" + def logsByTime = pbsService.getLogsByTime(start) + assert getLogsByText(logsByTime, warningMessage).size() == 1 + + cleanup: "Stop and remove pbs container" + pbsServiceFactory.removeContainer(pbsConfig) where: enforceValidAccount << [true, false] } + def "PBS shouldn't emit warning in logs when reject request with inactive account amd sampling-rate is disabled"() { + given: "Start up time" + def start = Instant.now() + + and: "Pbs config with logging.sampling-rate" + def pbsConfig = ["logging.sampling-rate": "0"] + def pbsService = pbsServiceFactory.getService(pbsConfig) + + and: "Inactive account id" + def accountId = PBSUtils.randomNumber + def account = new Account(uuid: accountId, config: new AccountConfig(status: AccountStatus.INACTIVE)) + accountDao.save(account) + + and: "Default basic BidRequest with inactive account id" + def bidRequest = BidRequest.defaultBidRequest.tap { + site.publisher.id = accountId + } + + when: "PBS processes auction request" + pbsService.sendAuctionRequest(bidRequest) + + then: "PBS should reject the entire auction" + def exception = thrown(PrebidServerException) + def warningMessage = "Account $accountId is inactive" + assert exception.statusCode == UNAUTHORIZED.code() + assert exception.responseBody == warningMessage + + and: "PBs shouldn't emit warning logs" + def logsByTime = pbsService.getLogsByTime(start) + assert !getLogsByText(logsByTime, warningMessage) + + cleanup: "Stop and remove pbs container" + pbsServiceFactory.removeContainer(pbsConfig) + } + def "PBS should reject request with unknown account when settings.enforce-valid-account = true"() { given: "Pbs config with enforce-valid-account and default-account-config" def pbsService = pbsServiceFactory.getService( diff --git a/src/test/java/org/prebid/server/log/ConditionalLoggerTest.java b/src/test/java/org/prebid/server/log/ConditionalLoggerTest.java index c1e6c56cf13..237c1852377 100644 --- a/src/test/java/org/prebid/server/log/ConditionalLoggerTest.java +++ b/src/test/java/org/prebid/server/log/ConditionalLoggerTest.java @@ -8,7 +8,7 @@ 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; @@ -16,14 +16,13 @@ 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,37 +40,10 @@ 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 @@ -79,7 +51,7 @@ public void infoShouldCallLoggerBySpecifiedKeyWithExpectedCount() { } @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);