Make DynamicLogLevelProcessor extensible

KarstenSchnitter · KarstenSchnitter · commit a0b0935c66a4 · 2020-11-15T19:44:43.000+01:00
Expose JWT validation and processing for subclasses. This
allows custom extensions for dynamic log level processing.

Fixes a clean-up issue with package based filtering.
diff --git a/cf-java-logging-support-servlet/src/main/java/com/sap/hcp/cf/logging/servlet/dynlog/DynamicLogLevelProcessor.java b/cf-java-logging-support-servlet/src/main/java/com/sap/hcp/cf/logging/servlet/dynlog/DynamicLogLevelProcessor.java
@@ -1,5 +1,6 @@
 package com.sap.hcp.cf.logging.servlet.dynlog;
 
+import java.security.interfaces.RSAPublicKey;
 import java.util.Arrays;
 import java.util.List;
 
@@ -15,6 +16,9 @@
  * HTTP-request-header. If this token is provided and does contain a correct
  * signature, valid timestamps and a log-level-value, the log-level for the
  * thread triggered by this request will be changed to the provided value.
+ * 
+ * You can extend this processor to extract custom claims from the JWT. Override
+ * {@link DynamicLogLevelProcessor#processJWT(DecodedJWT)} for this.
  */
 public class DynamicLogLevelProcessor {
 
@@ -23,33 +27,74 @@ public class DynamicLogLevelProcessor {
                                                                                 "ERROR");
     private final TokenDecoder tokenDecoder;
 
+    /**
+     * @deprecated Use
+     *             {@link DynamicLogLevelProcessor#DynamicLogLevelProcessor(RSAPublicKey)}
+     *             instead.
+     * @param dynLogConfig
+     *            then {@link DynLogConfiguration} to read the public RSA key
+     *            for JWT validation from.
+     */
+    @Deprecated
     public DynamicLogLevelProcessor(DynLogConfiguration dynLogConfig) {
-        this.tokenDecoder = new TokenDecoder(dynLogConfig.getRsaPublicKey());
+        this(dynLogConfig.getRsaPublicKey());
     }
 
+    public DynamicLogLevelProcessor(RSAPublicKey publicJwtKey) {
+        this.tokenDecoder = new TokenDecoder(publicJwtKey);
+    }
+
+    /**
+     * Decodes and validate the JWT. Configures the dynamic log levels by
+     * setting the corresponding fields in the MDC.
+     * 
+     * @param logLevelToken
+     *            the HTTP Header containing the JWT for dynamic log levels
+     */
     public void copyDynamicLogLevelToMDC(String logLevelToken) {
         if (logLevelToken == null) {
             return;
         } else {
             try {
                 DecodedJWT jwt = tokenDecoder.validateAndDecodeToken(logLevelToken);
-                String dynamicLogLevel = jwt.getClaim("level").asString();
-                String packages = jwt.getClaim("packages").asString();
-                if (ALLOWED_DYNAMIC_LOGLEVELS.contains(dynamicLogLevel)) {
-                    MDC.put(DynamicLogLevelHelper.MDC_DYNAMIC_LOG_LEVEL_KEY, dynamicLogLevel);
-                    MDC.put(DynamicLogLevelHelper.MDC_DYNAMIC_LOG_LEVEL_PREFIXES, packages);
-                } else {
-                    throw new DynamicLogLevelException("Dynamic Log-Level [" + dynamicLogLevel +
-                                                       "] provided in header is not valid. Allowed Values are " +
-                                                       ALLOWED_DYNAMIC_LOGLEVELS.toString());
-                }
-            } catch (DynamicLogLevelException e) {
-                LOGGER.warn("DynamicLogLevelProcessor could not write dynamic log level to MDC", e);
+                processJWT(jwt);
+            } catch (DynamicLogLevelException cause) {
+                LOGGER.warn("DynamicLogLevelProcessor could not write dynamic log level to MDC", cause);
             }
         }
     }
 
+    /**
+     * Extracts the relevant claims for dynamic log level configuration from the
+     * decoded token. In case of faulty content, i.e. unknown log level a
+     * {@link DynamicLogLevelException} is thrown. You can override this method
+     * to implement own interaction with the JWT, e.g. extraction and validation
+     * of additional claims.
+     * 
+     * @param jwt
+     *            the decoded JWT from the HTTP header
+     * @throws DynamicLogLevelException
+     *             if validation of JWT claims fail
+     */
+    protected void processJWT(DecodedJWT jwt) throws DynamicLogLevelException {
+        String dynamicLogLevel = jwt.getClaim("level").asString();
+        String packages = jwt.getClaim("packages").asString();
+        if (ALLOWED_DYNAMIC_LOGLEVELS.contains(dynamicLogLevel)) {
+            MDC.put(DynamicLogLevelHelper.MDC_DYNAMIC_LOG_LEVEL_KEY, dynamicLogLevel);
+            MDC.put(DynamicLogLevelHelper.MDC_DYNAMIC_LOG_LEVEL_PREFIXES, packages);
+        } else {
+            throw new DynamicLogLevelException("Dynamic Log-Level [" + dynamicLogLevel +
+                                               "] provided in header is not valid. Allowed Values are " +
+                                               ALLOWED_DYNAMIC_LOGLEVELS.toString());
+        }
+    }
+
+    /**
+     * Removes the MDC fields for dynamic log levels. This needs to be called to
+     * remove the changed log level configuration.
+     */
     public void removeDynamicLogLevelFromMDC() {
         MDC.remove(DynamicLogLevelHelper.MDC_DYNAMIC_LOG_LEVEL_KEY);
+        MDC.remove(DynamicLogLevelHelper.MDC_DYNAMIC_LOG_LEVEL_PREFIXES);
     }
 }
diff --git a/cf-java-logging-support-servlet/src/main/java/com/sap/hcp/cf/logging/servlet/filter/RequestLoggingFilter.java b/cf-java-logging-support-servlet/src/main/java/com/sap/hcp/cf/logging/servlet/filter/RequestLoggingFilter.java
@@ -105,7 +105,8 @@ public RequestLoggingFilter(RequestRecordFactory requestRecordFactory,
 
             @Override
             protected DynamicLogLevelProcessor initialize() throws ConcurrentException {
-                return new DynamicLogLevelProcessor(getDynLogEnvironment().get());
+                return getDynLogEnvironment().map(DynLogEnvironment::getRsaPublicKey).map(DynamicLogLevelProcessor::new)
+                                             .get();
             }
         };
     }
@@ -228,7 +229,7 @@ private void doFilterRequest(HttpServletRequest httpRequest, HttpServletResponse
              */
         } finally {
             deactivateDynamicLogLevels();
-			resetLogContext();
+            resetLogContext();
         }
     }
 
@@ -244,7 +245,7 @@ private void deactivateDynamicLogLevels() {
     }
 
     private void resetLogContext() {
-        for (HttpHeader header : HttpHeaders.propagated()) {
+        for (HttpHeader header: HttpHeaders.propagated()) {
             LogContext.remove(header.getField());
         }
         LogContext.resetContextFields();
diff --git a/cf-java-logging-support-servlet/src/test/java/com/sap/hcp/cf/logging/servlet/dynlog/DynamicLogLevelProcessorTest.java b/cf-java-logging-support-servlet/src/test/java/com/sap/hcp/cf/logging/servlet/dynlog/DynamicLogLevelProcessorTest.java
@@ -1,70 +1,92 @@
 package com.sap.hcp.cf.logging.servlet.dynlog;
 
-import static org.junit.Assert.assertEquals;
+import static org.junit.Assert.*;
 
 import java.security.KeyPair;
 import java.security.KeyPairGenerator;
 import java.security.NoSuchAlgorithmException;
 import java.security.NoSuchProviderException;
+import java.security.PublicKey;
+import java.security.interfaces.RSAPublicKey;
 import java.util.Date;
 
-import javax.xml.bind.DatatypeConverter;
-
 import org.junit.After;
 import org.junit.Before;
 import org.junit.Test;
 import org.junit.runner.RunWith;
-import org.mockito.Mock;
 import org.mockito.Mockito;
 import org.mockito.runners.MockitoJUnitRunner;
 import org.slf4j.MDC;
 
+import com.auth0.jwt.interfaces.DecodedJWT;
 import com.sap.hcp.cf.logging.common.helper.DynamicLogLevelHelper;
-import com.sap.hcp.cf.logging.common.helper.Environment;
 
 @RunWith(MockitoJUnitRunner.class)
 public class DynamicLogLevelProcessorTest extends Mockito {
 
-    @Mock
-    private Environment environment;
-
     private DynamicLogLevelProcessor processor;
 
     private String token;
 
+    private KeyPair keyPair;
+
     @Before
     public void setup() throws NoSuchAlgorithmException, NoSuchProviderException, DynamicLogLevelException {
-        KeyPair keyPair = KeyPairGenerator.getInstance("RSA").generateKeyPair();
-        String keyBase64 = DatatypeConverter.printBase64Binary(keyPair.getPublic().getEncoded());
+        this.keyPair = KeyPairGenerator.getInstance("RSA").generateKeyPair();
         Date issuedAt = new Date();
         Date expiresAt = new Date(new Date().getTime() + 10000);
-		this.token = TokenCreator.createToken(keyPair, "issuer", issuedAt, expiresAt, "TRACE", "myPrefix");
-        when(environment.getVariable("DYN_LOG_LEVEL_KEY")).thenReturn(keyBase64);
-        when(environment.getVariable("DYN_LOG_HEADER")).thenReturn("SAP-LOG-LEVEL");
-        processor = new DynamicLogLevelProcessor(new DynLogEnvironment(environment));
+        this.token = TokenCreator.createToken(keyPair, "issuer", issuedAt, expiresAt, "TRACE", "myPrefix");
+        this.processor = new DynamicLogLevelProcessor(getRSAPublicKey(keyPair));
+    }
+
+    private static RSAPublicKey getRSAPublicKey(KeyPair keyPair) {
+        PublicKey publicKey = keyPair.getPublic();
+        if (publicKey instanceof RSAPublicKey) {
+            return (RSAPublicKey) publicKey;
+        }
+        return null;
     }
 
     @After
-    public void tearDown() {
+    public void removeDynamicLogLevelFromMDC() {
+        processor.removeDynamicLogLevelFromMDC();
     }
 
     @Test
-    public void testCopyDynamicLogLevelToMDC() throws Exception {
+    public void copiesDynamicLogLevelToMDC() throws Exception {
         processor.copyDynamicLogLevelToMDC(token);
         assertEquals("TRACE", MDC.get(DynamicLogLevelHelper.MDC_DYNAMIC_LOG_LEVEL_KEY));
     }
 
     @Test
-    public void testDeleteDynamicLogLevelFromMDC() throws Exception {
+    public void deletesDynamicLogLevelFromMDC() throws Exception {
         processor.copyDynamicLogLevelToMDC(token);
         processor.removeDynamicLogLevelFromMDC();
         assertEquals(null, MDC.get(DynamicLogLevelHelper.MDC_DYNAMIC_LOG_LEVEL_KEY));
     }
 
-	@Test
-	public void testCopyDynamicLogPackagesToMDC() throws Exception {
-		processor.copyDynamicLogLevelToMDC(token);
-		assertEquals("myPrefix", MDC.get(DynamicLogLevelHelper.MDC_DYNAMIC_LOG_LEVEL_PREFIXES));
+    @Test
+    public void copiesDynamicLogPackagesToMDC() throws Exception {
+        processor.copyDynamicLogLevelToMDC(token);
+        assertEquals("myPrefix", MDC.get(DynamicLogLevelHelper.MDC_DYNAMIC_LOG_LEVEL_PREFIXES));
+    }
+
+    @Test
+    public void doesNotCopyDynamicLogLevelOnInvalidJwt() throws Exception {
+        KeyPair invalidKeyPair = KeyPairGenerator.getInstance("RSA").generateKeyPair();
+        new DynamicLogLevelProcessor(getRSAPublicKey(invalidKeyPair)).copyDynamicLogLevelToMDC(token);
+        assertEquals(null, MDC.get(DynamicLogLevelHelper.MDC_DYNAMIC_LOG_LEVEL_KEY));
+    }
 
-	}
+    @Test
+    public void doesNotCopyDynamicLogLevelOnCustomException() throws Exception {
+        DynamicLogLevelProcessor myProcessor = new DynamicLogLevelProcessor(getRSAPublicKey(keyPair)) {
+            @Override
+            protected void processJWT(DecodedJWT jwt) throws DynamicLogLevelException {
+                throw new DynamicLogLevelException("Always fail in this test-case.");
+            }
+        };
+        myProcessor.copyDynamicLogLevelToMDC(token);
+        assertEquals(null, MDC.get(DynamicLogLevelHelper.MDC_DYNAMIC_LOG_LEVEL_KEY));
+    }
 }

Original file line number	Diff line number	Diff line change
`@@ -105,7 +105,8 @@ public RequestLoggingFilter(RequestRecordFactory requestRecordFactory,`
`105`	`105`
`106`	`106`	`@Override`
`107`	`107`	`protected DynamicLogLevelProcessor initialize() throws ConcurrentException {`
`108`		`- return new DynamicLogLevelProcessor(getDynLogEnvironment().get());`
	`108`	`+ return getDynLogEnvironment().map(DynLogEnvironment::getRsaPublicKey).map(DynamicLogLevelProcessor::new)`
	`109`	`+ .get();`
`109`	`110`	`}`
`110`	`111`	`};`
`111`	`112`	`}`
`@@ -228,7 +229,7 @@ private void doFilterRequest(HttpServletRequest httpRequest, HttpServletResponse`
`228`	`229`	`*/`
`229`	`230`	`} finally {`
`230`	`231`	`deactivateDynamicLogLevels();`
`231`		`- resetLogContext();`
	`232`	`+ resetLogContext();`
`232`	`233`	`}`
`233`	`234`	`}`
`234`	`235`
`@@ -244,7 +245,7 @@ private void deactivateDynamicLogLevels() {`
`244`	`245`	`}`
`245`	`246`
`246`	`247`	`private void resetLogContext() {`
`247`		`- for (HttpHeader header : HttpHeaders.propagated()) {`
	`248`	`+ for (HttpHeader header: HttpHeaders.propagated()) {`
`248`	`249`	`LogContext.remove(header.getField());`
`249`	`250`	`}`
`250`	`251`	`LogContext.resetContextFields();`