Implement service and endpoint for changing logging level temporarily (…

…#778) * Implement service and endpoint for changing logging level temporarily * Add tests * Rollback experimentation code * Fix docs Co-authored-by: rpanchyk <rpanchyk@rubiconproject.com>
prebid · Sep 11, 2020 · b46e78f · b46e78f
1 parent 3314ebf
commit b46e78f
Show file tree

Hide file tree

Showing 13 changed files with 357 additions and 3 deletions.
diff --git a/docs/config-app.md b/docs/config-app.md
@@ -117,6 +117,9 @@ But feel free to add additional bidder's specific options.
 ## Logging
 - `logging.http-interaction.max-limit` - maximum value for the number of interactions to log in one take.
 
+## Logging
+- `logging.change-level.max-duration-ms` - maximum duration (in milliseconds) for which logging level could be changed.
+
 ## Currency Converter
 - `currency-converter.external-rates.enabled` - if equals to `true` the currency conversion service will be enabled to fetch updated rates and convert bid currencies from external source. Also enables `/currency-rates` endpoint on admin port.
 - `currency-converter.external-rates.url` - the url for Prebid.org’s currency file. [More details](http://prebid.org/dev-docs/modules/currency.html)

diff --git a/docs/endpoints/logging/changelevel.md b/docs/endpoints/logging/changelevel.md
@@ -0,0 +1,10 @@
+# Change logging level endpoint
+
+This endpoint has a path `/logging/changelevel` by default (can be configured).
+
+This endpoint allows changing `org.prebid.server` logger level temporarily, mainly for troubleshooting production issues.
+
+### Query Params
+- `level` - desired logging level to set; must be one of `error`, `warn`, `info`, `debug`
+- `duration` - for how long to change level before it gets reset to original; there is an upper threshold for this 
+value set in [configuration](../../config-app.md)
diff --git a/src/main/java/org/prebid/server/handler/HttpInteractionLogHandler.java b/src/main/java/org/prebid/server/handler/HttpInteractionLogHandler.java
@@ -80,7 +80,7 @@ private int readLimit(MultiMap parameters) {
 
         if (limit < 1 || limit > maxLimit) {
             throw new InvalidRequestException(String.format(
-                    "Parameter '%s' must be between %d and %d", LIMIT_PARAMETER, 1, maxLimit));
+                    "Parameter '%s' must be between %d and %d", LIMIT_PARAMETER, 0, maxLimit));
         }
 
         return limit;

diff --git a/src/main/java/org/prebid/server/handler/LoggerControlKnobHandler.java b/src/main/java/org/prebid/server/handler/LoggerControlKnobHandler.java
@@ -0,0 +1,85 @@
+package org.prebid.server.handler;
+
+import io.netty.handler.codec.http.HttpResponseStatus;
+import io.vertx.core.Handler;
+import io.vertx.core.MultiMap;
+import io.vertx.ext.web.RoutingContext;
+import org.prebid.server.exception.InvalidRequestException;
+import org.prebid.server.log.LoggerControlKnob;
+
+import java.time.Duration;
+import java.util.Arrays;
+import java.util.Collections;
+import java.util.HashSet;
+import java.util.Objects;
+import java.util.Set;
+
+public class LoggerControlKnobHandler implements Handler<RoutingContext> {
+
+    private static final String LEVEL_PARAMETER = "level";
+    private static final String DURATION_PARAMETER = "duration";
+
+    private static final Set<String> ALLOWED_LEVELS = Collections.unmodifiableSet(new HashSet<>(Arrays.asList(
+            "error", "warn", "info", "debug")));
+
+    private final long maxDurationMs;
+    private final LoggerControlKnob loggerControlKnob;
+
+    public LoggerControlKnobHandler(long maxDurationMs, LoggerControlKnob loggerControlKnob) {
+        this.maxDurationMs = maxDurationMs;
+        this.loggerControlKnob = Objects.requireNonNull(loggerControlKnob);
+    }
+
+    @Override
+    public void handle(RoutingContext context) {
+        final MultiMap parameters = context.request().params();
+
+        try {
+            loggerControlKnob.changeLogLevel(readLevel(parameters), readDuration(parameters));
+        } catch (InvalidRequestException e) {
+            context.response().setStatusCode(HttpResponseStatus.BAD_REQUEST.code()).end(e.getMessage());
+            return;
+        }
+
+        context.response().end();
+    }
+
+    private String readLevel(MultiMap parameters) {
+        final String level = parameters.get(LEVEL_PARAMETER);
+
+        if (level == null) {
+            throw new InvalidRequestException(String.format("Missing required parameter '%s'", LEVEL_PARAMETER));
+        }
+
+        if (!ALLOWED_LEVELS.contains(level.toLowerCase())) {
+            throw new InvalidRequestException(String.format(
+                    "Invalid '%s' parameter value, allowed values '%s'", LEVEL_PARAMETER, ALLOWED_LEVELS));
+        }
+
+        return level;
+    }
+
+    private Duration readDuration(MultiMap parameters) {
+        final Integer duration = getIntParameter(DURATION_PARAMETER, parameters);
+
+        if (duration == null) {
+            throw new InvalidRequestException(String.format("Missing required parameter '%s'", DURATION_PARAMETER));
+        }
+
+        if (duration < 1 || duration > maxDurationMs) {
+            throw new InvalidRequestException(String.format(
+                    "Parameter '%s' must be between %d and %d", DURATION_PARAMETER, 0, maxDurationMs));
+        }
+
+        return Duration.ofMillis(duration);
+    }
+
+    private Integer getIntParameter(String parameterName, MultiMap parameters) {
+        final String value = parameters.get(parameterName);
+        try {
+            return value != null ? Integer.parseInt(value) : null;
+        } catch (NumberFormatException e) {
+            throw new InvalidRequestException(String.format("Invalid '%s' parameter value", parameterName));
+        }
+    }
+}
diff --git a/src/main/java/org/prebid/server/log/LoggerControlKnob.java b/src/main/java/org/prebid/server/log/LoggerControlKnob.java
@@ -0,0 +1,68 @@
+package org.prebid.server.log;
+
+import ch.qos.logback.classic.Level;
+import ch.qos.logback.classic.Logger;
+import io.vertx.core.Vertx;
+import org.slf4j.LoggerFactory;
+
+import java.time.Duration;
+import java.util.Objects;
+import java.util.concurrent.locks.Lock;
+import java.util.concurrent.locks.ReentrantLock;
+
+public class LoggerControlKnob {
+
+    private static final String PREBID_LOGGER = "org.prebid.server";
+
+    private final Vertx vertx;
+    private final Logger logger;
+    private final Level originalLevel;
+
+    private final Lock lock = new ReentrantLock();
+    private Long restoreTimerId = null;
+
+    public LoggerControlKnob(Vertx vertx) {
+        this.vertx = Objects.requireNonNull(vertx);
+
+        logger = getPrebidLogger();
+        originalLevel = logger != null ? logger.getLevel() : null;
+    }
+
+    public void changeLogLevel(String level, Duration duration) {
+        if (logger == null) {
+            return;
+        }
+
+        lock.lock();
+        try {
+            if (restoreTimerId != null) {
+                vertx.cancelTimer(restoreTimerId);
+                restoreTimerId = null;
+            }
+
+            logger.setLevel(Level.toLevel(level, originalLevel));
+            restoreTimerId = vertx.setTimer(duration.toMillis(), this::resetLoggerLevel);
+        } finally {
+            lock.unlock();
+        }
+    }
+
+    private static Logger getPrebidLogger() {
+        final org.slf4j.Logger prebidSlf4jLogger = LoggerFactory.getLogger(PREBID_LOGGER);
+        return prebidSlf4jLogger instanceof Logger ? (Logger) prebidSlf4jLogger : null;
+    }
+
+    private void resetLoggerLevel(long triggeredTimerId) {
+        lock.lock();
+        try {
+            if (restoreTimerId == null || triggeredTimerId != restoreTimerId) {
+                return;
+            }
+
+            logger.setLevel(originalLevel);
+            restoreTimerId = null;
+        } finally {
+            lock.unlock();
+        }
+    }
+}
diff --git a/src/main/java/org/prebid/server/spring/config/AdminEndpointsConfiguration.java b/src/main/java/org/prebid/server/spring/config/AdminEndpointsConfiguration.java
@@ -8,10 +8,12 @@
 import org.prebid.server.handler.CurrencyRatesHandler;
 import org.prebid.server.handler.CustomizedAdminEndpoint;
 import org.prebid.server.handler.HttpInteractionLogHandler;
+import org.prebid.server.handler.LoggerControlKnobHandler;
 import org.prebid.server.handler.SettingsCacheNotificationHandler;
 import org.prebid.server.handler.VersionHandler;
 import org.prebid.server.json.JacksonMapper;
 import org.prebid.server.log.HttpInteractionLogger;
+import org.prebid.server.log.LoggerControlKnob;
 import org.prebid.server.settings.CachingApplicationSettings;
 import org.prebid.server.settings.SettingsCache;
 import org.springframework.beans.factory.annotation.Autowired;
@@ -138,6 +140,24 @@ CustomizedAdminEndpoint loggingHttpInteractionEndpoint(
                 .withCredentials(adminEndpointCredentials);
     }
 
+    @Bean
+    @ConditionalOnExpression("${admin-endpoints.logging-changelevel.enabled} == true")
+    CustomizedAdminEndpoint loggingChangeLevelEndpoint(
+            @Value("${logging.change-level.max-duration-ms}") long maxDuration,
+            LoggerControlKnob loggerControlKnob,
+            @Value("${admin-endpoints.logging-changelevel.path}") String path,
+            @Value("${admin-endpoints.logging-changelevel.on-application-port}") boolean isOnApplicationPort,
+            @Value("${admin-endpoints.logging-changelevel.protected}") boolean isProtected,
+            @Autowired(required = false) Map<String, String> adminEndpointCredentials) {
+
+        return new CustomizedAdminEndpoint(
+                path,
+                new LoggerControlKnobHandler(maxDuration, loggerControlKnob),
+                isOnApplicationPort,
+                isProtected)
+                .withCredentials(adminEndpointCredentials);
+    }
+
     @Bean
     Map<String, String> adminEndpointCredentials(
             @Autowired(required = false) AdminEndpointCredentials adminEndpointCredentials) {

diff --git a/src/main/java/org/prebid/server/spring/config/ServiceConfiguration.java b/src/main/java/org/prebid/server/spring/config/ServiceConfiguration.java
@@ -42,6 +42,7 @@
 import org.prebid.server.identity.UUIDIdGenerator;
 import org.prebid.server.json.JacksonMapper;
 import org.prebid.server.log.HttpInteractionLogger;
+import org.prebid.server.log.LoggerControlKnob;
 import org.prebid.server.metric.Metrics;
 import org.prebid.server.optout.GoogleRecaptchaVerifier;
 import org.prebid.server.privacy.PrivacyExtractor;
@@ -579,4 +580,9 @@ ExternalConversionProperties externalConversionProperties(
     HttpInteractionLogger httpInteractionLogger() {
         return new HttpInteractionLogger();
     }
+
+    @Bean
+    LoggerControlKnob loggerControlKnob(Vertx vertx) {
+        return new LoggerControlKnob(vertx);
+    }
 }
diff --git a/src/main/resources/application.yaml b/src/main/resources/application.yaml
@@ -45,6 +45,11 @@ admin-endpoints:
     path: /logging/httpinteraction
     on-application-port: false
     protected: true
+  logging-changelevel:
+    enabled: false
+    path: /logging/changelevel
+    on-application-port: false
+    protected: true
 http-client:
   max-pool-size: 4000
   connect-timeout-ms: 2500
@@ -91,6 +96,8 @@ cookie-sync:
 logging:
   http-interaction:
     max-limit: 10000
+  change-level:
+    max-duration-ms: 60000
 currency-converter:
   external-rates:
     enabled: true

diff --git a/src/test/java/org/prebid/server/handler/HttpInteractionLogHandlerTest.java b/src/test/java/org/prebid/server/handler/HttpInteractionLogHandlerTest.java
@@ -167,7 +167,7 @@ public void shouldRespondWithErrorWhenLimitNotValid() {
 
         // then
         verify(httpResponse).setStatusCode(eq(400));
-        verify(httpResponse).end(eq("Parameter 'limit' must be between 1 and 5"));
+        verify(httpResponse).end(eq("Parameter 'limit' must be between 0 and 5"));
 
         verifyZeroInteractions(httpInteractionLogger);
     }