[wip] Improve exception handling

logbook-api/pom.xml

@@ -21,6 +21,11 @@
             <groupId>com.fasterxml.jackson.core</groupId>
             <artifactId>jackson-databind</artifactId>
         </dependency>
+        <dependency>
+            <groupId>ch.qos.logback</groupId>
+            <artifactId>logback-classic</artifactId>
+            <scope>test</scope>
+        </dependency>
     </dependencies>
 
     <build>

logbook-api/src/main/java/org/zalando/logbook/attributes/AttributeExtractor.java

@@ -4,17 +4,25 @@
 import org.zalando.logbook.HttpRequest;
 import org.zalando.logbook.HttpResponse;
 
+import javax.annotation.Nonnull;
+
 import static org.apiguardian.api.API.Status.STABLE;
 
 @API(status = STABLE)
 public interface AttributeExtractor {
 
+    default void logException(final Exception exception) {
+        // do nothing by default
+    }
+
     @SuppressWarnings("RedundantThrows")
+    @Nonnull
     default HttpAttributes extract(final HttpRequest request) throws Exception {
         return HttpAttributes.EMPTY;
     }
 
     @SuppressWarnings({"unused", "RedundantThrows"})
+    @Nonnull
     default HttpAttributes extract(final HttpRequest request, final HttpResponse response) throws Exception {
         return HttpAttributes.EMPTY;
     }

logbook-api/src/main/java/org/zalando/logbook/attributes/CompositeAttributeExtractor.java

@@ -4,6 +4,7 @@
 import org.zalando.logbook.HttpRequest;
 import org.zalando.logbook.HttpResponse;
 
+import javax.annotation.Nonnull;
 import java.util.Collection;
 import java.util.HashMap;
 import java.util.Map;
@@ -13,21 +14,46 @@ public final class CompositeAttributeExtractor implements AttributeExtractor {
 
     private final Collection<AttributeExtractor> attributeExtractors;
 
+    @Nonnull
     @Override
-    public HttpAttributes extract(final HttpRequest request) throws Exception {
+    public HttpAttributes extract(final HttpRequest request) {
         final Map<String, String> map = new HashMap<>();
         for (final AttributeExtractor attributeExtractor : attributeExtractors) {
-            map.putAll(attributeExtractor.extract(request));
+            map.putAll(safeRequestExtractor(attributeExtractor, request));
         }
         return new HttpAttributes(map);
     }
 
+    @Nonnull
     @Override
-    public HttpAttributes extract(final HttpRequest request, HttpResponse response) throws Exception {
+    public HttpAttributes extract(final HttpRequest request, HttpResponse response) {
         final Map<String, String> map = new HashMap<>();
         for (final AttributeExtractor attributeExtractor : attributeExtractors) {
-            map.putAll(attributeExtractor.extract(request, response));
+            map.putAll(safeRequestExtractor(attributeExtractor, request, response));
         }
         return new HttpAttributes(map);
     }
+
+    @Nonnull
+    private HttpAttributes safeRequestExtractor(final AttributeExtractor attributeExtractor,
+                                                final HttpRequest request) {
+        try {
+            return attributeExtractor.extract(request);
+        } catch (Exception e) {
+            attributeExtractor.logException(e);
+            return HttpAttributes.EMPTY;
+        }
+    }
+
+    @Nonnull
+    private HttpAttributes safeRequestExtractor(final AttributeExtractor attributeExtractor,
+                                                final HttpRequest request,
+                                                final HttpResponse response) {
+        try {
+            return attributeExtractor.extract(request, response);
+        } catch (Exception e) {
+            attributeExtractor.logException(e);
+            return HttpAttributes.EMPTY;
+        }
+    }
 }

logbook-api/src/main/java/org/zalando/logbook/attributes/JwtFirstMatchingClaimExtractor.java

@@ -3,7 +3,10 @@
 import com.fasterxml.jackson.core.JsonProcessingException;
 import com.fasterxml.jackson.databind.ObjectMapper;
 import lombok.AllArgsConstructor;
+import lombok.extern.slf4j.Slf4j;
 import org.apiguardian.api.API;
+import org.slf4j.Marker;
+import org.slf4j.MarkerFactory;
 import org.zalando.logbook.HttpHeaders;
 import org.zalando.logbook.HttpRequest;
 
@@ -27,11 +30,13 @@
  * claim is found.
  */
 @API(status = STABLE)
+@Slf4j
 @AllArgsConstructor
 public final class JwtFirstMatchingClaimExtractor implements AttributeExtractor {
 
     private static final String BEARER_JWT_PATTERN = "Bearer [a-z0-9-_]+\\.([a-z0-9-_]+)\\.[a-z0-9-_]+";
-    private static final Pattern pattern = Pattern.compile(BEARER_JWT_PATTERN, Pattern.CASE_INSENSITIVE);
+    private static final Pattern PATTERN = Pattern.compile(BEARER_JWT_PATTERN, Pattern.CASE_INSENSITIVE);
+    private static final Marker LOG_MARKER = MarkerFactory.getMarker("JwtFirstMatchingClaimExtractor");
 
     // RFC 7519 section-4.1.2: The "sub" (subject) claim identifies the principal that is the subject of the JWT.
     public static final String DEFAULT_SUBJECT_CLAIM = "sub";
@@ -47,6 +52,9 @@ public final class JwtFirstMatchingClaimExtractor implements AttributeExtractor
     @Nonnull
     private final String claimKey;
 
+    @Nonnull
+    private final Boolean shouldLogErrors;
+
     @API(status = STABLE)
     public static final class Builder {
 
@@ -58,38 +66,56 @@ public static final class Builder {
     private static JwtFirstMatchingClaimExtractor create(
             @Nullable final ObjectMapper objectMapper,
             @Nullable final List<String> claimNames,
-            @Nullable final String claimKey
+            @Nullable final String claimKey,
+            @Nullable final Boolean shouldLogErrors
     ) {
         return new JwtFirstMatchingClaimExtractor(
                 Optional.ofNullable(objectMapper).orElse(new ObjectMapper()),
                 Optional.ofNullable(claimNames).orElse(Collections.singletonList(DEFAULT_SUBJECT_CLAIM)),
-                Optional.ofNullable(claimKey).orElse(DEFAULT_CLAIM_KEY)
+                Optional.ofNullable(claimKey).orElse(DEFAULT_CLAIM_KEY),
+                Optional.ofNullable(shouldLogErrors).orElse(false)
         );
     }
 
-    @Nonnull
     @Override
-    public HttpAttributes extract(final HttpRequest request) throws JsonProcessingException {
-        HttpHeaders headers = request.getHeaders();
-
-        if (claimNames.isEmpty() || headers == null) return HttpAttributes.EMPTY;
-
-        String authHeader = headers.getFirst("Authorization");
-        if (authHeader == null) return HttpAttributes.EMPTY;
-
-        Matcher matcher = pattern.matcher(authHeader);
-        if (!matcher.matches()) return HttpAttributes.EMPTY;
+    public void logException(final Exception exception) {
+        if (shouldLogErrors)
+            log.trace(
+                    LOG_MARKER,
+                    "Encountered error while extracting attributes: `{}`",
+                    (Optional.ofNullable(exception.getCause()).orElse(exception)).getMessage()
+            );
+    }
 
-        String payload = new String(Base64.getUrlDecoder().decode(matcher.group(1)));
-        HashMap<?, ?> claims = objectMapper.readValue(payload, HashMap.class);
-        return claimNames.stream()
-                .map(claims::get)
-                .filter(Objects::nonNull)
-                .findFirst()
-                .map(this::toHttpAttribute)
-                .orElse(HttpAttributes.EMPTY);
+    @Nonnull
+    @Override
+    public HttpAttributes extract(final HttpRequest request) {
+        try {
+            HttpHeaders headers = request.getHeaders();
+
+            if (claimNames.isEmpty() || headers == null) return HttpAttributes.EMPTY;
+
+            String authHeader = headers.getFirst("Authorization");
+            if (authHeader == null) return HttpAttributes.EMPTY;
+
+            Matcher matcher = PATTERN.matcher(authHeader);
+            if (!matcher.matches()) return HttpAttributes.EMPTY;
+
+            String payload = new String(Base64.getUrlDecoder().decode(matcher.group(1)));
+            HashMap<?, ?> claims = objectMapper.readValue(payload, HashMap.class);
+            return claimNames.stream()
+                    .map(claims::get)
+                    .filter(Objects::nonNull)
+                    .findFirst()
+                    .map(this::toHttpAttribute)
+                    .orElse(HttpAttributes.EMPTY);
+        } catch (Exception e) {
+            logException(e);
+            return HttpAttributes.EMPTY;
+        }
     }
 
+    @Nonnull
     private HttpAttributes toHttpAttribute(final Object value) {
         try {
             final String valueAsString = (value instanceof String) ?

logbook-api/src/test/java/org/zalando/logbook/attributes/AttributeExtractorTest.java

@@ -0,0 +1,27 @@
+package org.zalando.logbook.attributes;
+
+import org.junit.jupiter.api.Test;
+
+import static org.assertj.core.api.Assertions.assertThat;
+import static org.junit.jupiter.api.Assertions.assertDoesNotThrow;
+import static org.mockito.ArgumentMatchers.any;
+import static org.mockito.Mockito.doCallRealMethod;
+import static org.mockito.Mockito.mock;
+import static org.mockito.Mockito.when;
+
+final class AttributeExtractorTest {
+
+    @Test
+    void testAttributeExtractorDefaultMethods() throws Exception {
+        final AttributeExtractor attributeExtractor = mock(AttributeExtractor.class);
+
+        doCallRealMethod().when(attributeExtractor).logException(any());
+        when(attributeExtractor.extract(any())).thenCallRealMethod();
+        when(attributeExtractor.extract(any(), any())).thenCallRealMethod();
+
+        assertDoesNotThrow(() -> attributeExtractor.logException(mock()));
+        assertThat(attributeExtractor.extract(mock())).isEqualTo(HttpAttributes.EMPTY);
+        assertThat(attributeExtractor.extract(mock(), mock())).isEqualTo(HttpAttributes.EMPTY);
+    }
+
+}

logbook-api/src/test/java/org/zalando/logbook/attributes/CompositeAttributeExtractorTest.java

@@ -10,6 +10,8 @@
 import java.util.Map;
 
 import static org.assertj.core.api.Assertions.assertThat;
+import static org.mockito.ArgumentMatchers.any;
+import static org.mockito.Mockito.doAnswer;
 import static org.mockito.Mockito.mock;
 import static org.mockito.Mockito.when;
 
@@ -21,25 +23,47 @@ void compositeAttributeExtractorShouldExtractAttributes() throws Exception {
         final HttpResponse response = mock(HttpResponse.class);
         final AttributeExtractor extractor1 = mock(AttributeExtractor.class);
         final AttributeExtractor extractor2 = mock(AttributeExtractor.class);
+        final AttributeExtractor extractor3 = mock(AttributeExtractor.class);
+        final AttributeExtractor extractor0 = mock(AttributeExtractor.class);
         final List<AttributeExtractor> extractors = new ArrayList<>();
 
         extractors.add(extractor1);
         extractors.add(extractor2);
+        extractors.add(extractor3);
+        extractors.add(extractor0);
 
         final CompositeAttributeExtractor composite = new CompositeAttributeExtractor(extractors);
 
+        when(extractor0.extract(request)).thenThrow(new Exception("ext4-req"));
+        when(extractor0.extract(request, response)).thenThrow(new Exception("ext4-resp"));
+        final List<String> loggedMessages = new ArrayList<>();
+        doAnswer(invocation -> {
+            final Exception exception = (Exception) invocation.getArguments()[0];
+            loggedMessages.add(exception.getMessage());
+            return null;
+        }).when(extractor0).logException(any());
+
         when(extractor1.extract(request)).thenReturn(HttpAttributes.of("ext1-req-key", "ext1-req-val"));
         when(extractor1.extract(request, response)).thenReturn(HttpAttributes.of("ext1-resp-key", "ext1-resp-val"));
 
         when(extractor2.extract(request)).thenReturn(HttpAttributes.of("ext2-req-key", "ext2-req-val"));
         // This should overwrite the value set by extractor1
         when(extractor2.extract(request, response)).thenReturn(HttpAttributes.of("ext1-resp-key", "ext2-resp-val"));
 
+        when(extractor3.extract(request)).thenThrow(new Exception("ext3-req"));
+        when(extractor3.extract(request, response)).thenThrow(new Exception("ext3-resp"));
+
         Map<String, String> expected = new HashMap<>();
         expected.put("ext1-req-key", "ext1-req-val");
         expected.put("ext2-req-key", "ext2-req-val");
 
         assertThat(composite.extract(request)).isEqualTo(new HttpAttributes(expected));
+        assertThat(loggedMessages).hasSize(1);
+        assertThat(loggedMessages.get(0)).isEqualTo("ext4-req");
+
+        loggedMessages.clear();
         assertThat(composite.extract(request, response)).isEqualTo(HttpAttributes.of("ext1-resp-key", "ext2-resp-val"));
+        assertThat(loggedMessages).hasSize(1);
+        assertThat(loggedMessages.get(0)).isEqualTo("ext4-resp");
     }
 }

logbook-api/src/test/java/org/zalando/logbook/attributes/HttpAttributesTest.java

@@ -45,6 +45,8 @@ void singletonHttpAttributesShouldBeImmutable() {
         final HttpAttributes attributes = HttpAttributes.of("key", "val");
 
         assertThat(attributes).isEqualTo(map1Clone);
+        assertThat(map1Clone).isEqualTo(attributes);
+
         assertThat(attributes.isEmpty()).isFalse();
         assertThat(attributes).isEqualTo(new HttpAttributes(map1Clone));
         assertThat(attributes.hashCode()).isEqualTo(map1Clone.hashCode());
@@ -60,6 +62,8 @@ void arbitraryHttpAttributesShouldBeImmutable() {
         final HttpAttributes attributes = new HttpAttributes(mapWithTwoKeys);
 
         assertThat(attributes).isEqualTo(map2Clone);
+        assertThat(map2Clone).isEqualTo(attributes);
+
         assertThat(attributes.isEmpty()).isFalse();
         assertThat(attributes).isEqualTo(new HttpAttributes(map2Clone));
         assertThat(attributes.hashCode()).isEqualTo(map2Clone.hashCode());