PBJ: Improve CookieSync and Setuid logging and metrics

docs/metrics.md

@@ -115,6 +115,8 @@ Following metrics are collected and submitted if account is configured with `det
 - `usersync.bad_requests` - number of requests received with bidder not specified
 - `usersync.<bidder-name>.sets` - number of requests received resulted in `uid` cookie update for `<bidder-name>`
 - `usersync.<bidder-name>.tcf.blocked` - number of requests received that didn't result in `uid` cookie update for `<bidder-name>` because of lack of user consent for this action according to TCF
+- `usersync.<bidder-name>.tcf.invalid` - number of requests received that are lacking of a valid consent string for `<bidder-name>`
+- `usersync.all.tcf.invalid` - number of requests received that are lacking of a valid consent string for all requested bidders
 
 ## Privacy metrics
 - `privacy.tcf.(missing|invalid)` - number of requests lacking a valid consent string

src/main/java/org/prebid/server/handler/CookieSyncHandler.java

@@ -35,6 +35,7 @@
 import org.prebid.server.execution.TimeoutFactory;
 import org.prebid.server.json.DecodeException;
 import org.prebid.server.json.JacksonMapper;
+import org.prebid.server.log.ConditionalLogger;
 import org.prebid.server.metric.Metrics;
 import org.prebid.server.privacy.gdpr.TcfDefinerService;
 import org.prebid.server.privacy.gdpr.model.HostVendorTcfResponse;
@@ -65,6 +66,7 @@
 public class CookieSyncHandler implements Handler<RoutingContext> {
 
     private static final Logger logger = LoggerFactory.getLogger(CookieSyncHandler.class);
+    private static final ConditionalLogger BAD_REQUEST_LOGGER = new ConditionalLogger(logger);
 
     private static final Map<CharSequence, AsciiString> JSON_HEADERS_MAP = Collections.singletonMap(
             HttpUtil.CONTENT_TYPE_HEADER, HttpHeaderValues.APPLICATION_JSON);
@@ -211,9 +213,10 @@ private void handleCookieSyncContextResult(AsyncResult<CookieSyncContext> cookie
             final CookieSyncContext cookieSyncContext = cookieSyncContextResult.result();
 
             final TcfContext tcfContext = cookieSyncContext.getPrivacyContext().getTcfContext();
-            final Exception validationException = validateCookieSyncContext(cookieSyncContext);
-            if (validationException != null) {
-                handleErrors(validationException, routingContext, tcfContext);
+            try {
+                validateCookieSyncContext(cookieSyncContext);
+            } catch (InvalidRequestException | UnauthorizedUidsException ex) {
+                handleErrors(ex, routingContext, tcfContext);
                 return;
             }
 
@@ -223,28 +226,26 @@ private void handleCookieSyncContextResult(AsyncResult<CookieSyncContext> cookie
                             biddersToSync(cookieSyncContext),
                             cookieSyncContext));
         } else {
-            final Throwable error = cookieSyncContextResult.cause();
-            handleErrors(error, routingContext, null);
+            handleErrors(cookieSyncContextResult.cause(), routingContext, null);
         }
     }
 
-    private static Exception validateCookieSyncContext(CookieSyncContext cookieSyncContext) {
+    private void validateCookieSyncContext(CookieSyncContext cookieSyncContext) {
         final UidsCookie uidsCookie = cookieSyncContext.getUidsCookie();
         if (!uidsCookie.allowsSync()) {
-            return new UnauthorizedUidsException("Sync is not allowed for this uids");
+            throw new UnauthorizedUidsException("Sync is not allowed for this uids");
         }
 
         final CookieSyncRequest cookieSyncRequest = cookieSyncContext.getCookieSyncRequest();
         if (isGdprParamsNotConsistent(cookieSyncRequest)) {
-            return new InvalidRequestException("gdpr_consent is required if gdpr is 1");
+            throw new InvalidRequestException("gdpr_consent is required if gdpr is 1");
         }
 
         final TcfContext tcfContext = cookieSyncContext.getPrivacyContext().getTcfContext();
         if (StringUtils.equals(tcfContext.getGdpr(), "1") && BooleanUtils.isFalse(tcfContext.getIsConsentValid())) {
-            return new InvalidRequestException("Consent string is invalid");
+            metrics.updateUserSyncTcfInvalidMetricForAllBidders();
+            throw new InvalidRequestException("Consent string is invalid");
         }
-
-        return null;
     }
 
     private static boolean isGdprParamsNotConsistent(CookieSyncRequest request) {
@@ -642,8 +643,7 @@ private void handleErrors(Throwable error, RoutingContext routingContext, TcfCon
             metrics.updateUserSyncBadRequestMetric();
             status = HttpResponseStatus.BAD_REQUEST.code();
             body = String.format("Invalid request format: %s", message);
-            logger.info(message, error);
-
+            BAD_REQUEST_LOGGER.info(message, 0.01);
         } else if (error instanceof UnauthorizedUidsException) {
             metrics.updateUserSyncOptoutMetric();
             status = HttpResponseStatus.UNAUTHORIZED.code();

src/main/java/org/prebid/server/handler/SetuidHandler.java

@@ -137,10 +137,13 @@ private void handleSetuidContextResult(AsyncResult<SetuidContext> setuidContextR
                                            RoutingContext routingContext) {
         if (setuidContextResult.succeeded()) {
             final SetuidContext setuidContext = setuidContextResult.result();
+            final String bidder = setuidContext.getCookieName();
             final TcfContext tcfContext = setuidContext.getPrivacyContext().getTcfContext();
-            final Exception exception = validateSetuidContext(setuidContext);
-            if (exception != null) {
-                handleErrors(exception, routingContext, tcfContext);
+
+            try {
+                validateSetuidContext(setuidContext, bidder);
+            } catch (InvalidRequestException | UnauthorizedUidsException ex) {
+                handleErrors(ex, routingContext, tcfContext);
                 return;
             }
 
@@ -152,25 +155,24 @@ private void handleSetuidContextResult(AsyncResult<SetuidContext> setuidContextR
         }
     }
 
-    private Exception validateSetuidContext(SetuidContext setuidContext) {
+    private void validateSetuidContext(SetuidContext setuidContext, String bidder) {
         final String cookieName = setuidContext.getCookieName();
         final boolean isCookieNameBlank = StringUtils.isBlank(cookieName);
         if (isCookieNameBlank || !cookieNameToSyncType.containsKey(cookieName)) {
             final String cookieNameError = isCookieNameBlank ? "required" : "invalid";
-            return new InvalidRequestException(String.format("\"bidder\" query param is %s", cookieNameError));
+            throw new InvalidRequestException(String.format("\"bidder\" query param is %s", cookieNameError));
         }
 
         final TcfContext tcfContext = setuidContext.getPrivacyContext().getTcfContext();
         if (StringUtils.equals(tcfContext.getGdpr(), "1") && BooleanUtils.isFalse(tcfContext.getIsConsentValid())) {
-            return new InvalidRequestException("Consent string is invalid");
+            metrics.updateUserSyncTcfInvalidMetric(bidder);
+            throw new InvalidRequestException("Consent string is invalid");
         }
 
         final UidsCookie uidsCookie = setuidContext.getUidsCookie();
         if (!uidsCookie.allowsSync()) {
-            return new UnauthorizedUidsException("Sync is not allowed for this uids");
+            throw new UnauthorizedUidsException("Sync is not allowed for this uids");
         }
-
-        return null;
     }
 
     /**

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

@@ -56,6 +56,12 @@ public void info(String message, long duration, TimeUnit unit) {
         log(message, duration, unit, logger -> logger.info(message));
     }
 
+    public void info(String message, double samplingRate) {
+        if (samplingRate >= 1.0d || ThreadLocalRandom.current().nextDouble() < samplingRate) {
+            logger.warn(message);
+        }
+    }
+
     public void errorWithKey(String key, String message, int limit) {
         log(key, limit, logger -> logger.error(message));
     }

src/main/java/org/prebid/server/metric/Metrics.java

@@ -21,6 +21,8 @@
  */
 public class Metrics extends UpdatableMetrics {
 
+    private static final String ALL_REQUEST_BIDDERS = "all";
+
     private final AccountMetricsVerbosity accountMetricsVerbosity;
 
     private final Function<MetricName, RequestStatusMetrics> requestMetricsCreator;
@@ -285,6 +287,14 @@ public void updateUserSyncTcfBlockedMetric(String bidder) {
         userSync().forBidder(bidder).tcf().incCounter(MetricName.blocked);
     }
 
+    public void updateUserSyncTcfInvalidMetric(String bidder) {
+        userSync().forBidder(bidder).tcf().incCounter(MetricName.invalid);
+    }
+
+    public void updateUserSyncTcfInvalidMetricForAllBidders() {
+        userSync().forBidder(ALL_REQUEST_BIDDERS).tcf().incCounter(MetricName.invalid);
+    }
+
     public void updateCookieSyncRequestMetric() {
         incCounter(MetricName.cookie_sync_requests);
     }

src/test/java/org/prebid/server/handler/CookieSyncHandlerTest.java

@@ -49,6 +49,7 @@
 import java.time.Instant;
 import java.time.ZoneId;
 import java.util.Collection;
+import java.util.Collections;
 import java.util.HashMap;
 import java.util.HashSet;
 import java.util.List;
@@ -245,7 +246,7 @@ public void shouldRespondWithBadRequestStatusIfGdprConsentIsInvalid() {
         // given
         given(routingContext.getBody())
                 .willReturn(givenRequestBody(CookieSyncRequest.builder()
-                        .bidders(emptyList())
+                        .bidders(Collections.singletonList(RUBICON))
                         .gdpr(1)
                         .gdprConsent("invalid")
                         .build()));
@@ -258,6 +259,7 @@ public void shouldRespondWithBadRequestStatusIfGdprConsentIsInvalid() {
         cookieSyncHandler.handle(routingContext);
 
         // then
+        verify(metrics).updateUserSyncTcfInvalidMetricForAllBidders();
         verify(httpResponse).setStatusCode(eq(400));
         verify(httpResponse).end(eq("Invalid request format: Consent string is invalid"));
     }

src/test/java/org/prebid/server/handler/SetuidHandlerTest.java

@@ -209,6 +209,7 @@ public void shouldRespondWithBadRequestStatusIfGdprConsentIsInvalid() {
         setuidHandler.handle(routingContext);
 
         // then
+        verify(metrics).updateUserSyncTcfInvalidMetric(RUBICON);
         verify(httpResponse).setStatusCode(eq(400));
         verify(httpResponse).end(eq("Invalid request format: Consent string is invalid"));
     }