Logbook fault tolerancy (#1739)

* Make DefaultLogbook fault tolerant

This change is aimed to make the DefaultLogbook not fail the request processing, if there are issues while writing request or response logs. Instead, it will fallback to Noop stage

* Make httpclient(5),okhttp(2) and spring interceptors fault-tolerant

This change introduces a fallback in interceptors to noop stage, when there are exceptions while writing request or response logs.

* Change log level to warn and add more info about the error

Fix test

* Adjust log message

logbook-core/src/main/java/org/zalando/logbook/core/DefaultLogbook.java

@@ -2,6 +2,7 @@
 
 import lombok.AllArgsConstructor;
 import lombok.Getter;
+import lombok.RequiredArgsConstructor;
 import lombok.extern.slf4j.Slf4j;
 import org.zalando.logbook.Correlation;
 import org.zalando.logbook.CorrelationId;
@@ -45,35 +46,20 @@ public RequestWritingStage process(final HttpRequest originalRequest) throws IOE
 
     @Override
     public RequestWritingStage process(final HttpRequest originalRequest, final Strategy strategy) throws IOException {
-
         if (sink.isActive() && predicate.test(originalRequest)) {
-            final Precorrelation precorrelation = newPrecorrelation(originalRequest);
-            final HttpRequest processedRequest = strategy.process(originalRequest);
-
-            final HttpAttributes requestAttributes = extractAttributesOrEmpty(processedRequest);
-            final HttpRequest request = new CachingHttpRequest(processedRequest, requestAttributes);
-            final HttpRequest filteredRequest = requestFilter.filter(request);
-
-            return new RequestWritingStage() {
-                @Override
-                public ResponseProcessingStage write() throws IOException {
-                    strategy.write(precorrelation, filteredRequest, sink);
-
-                    return this;
-                }
-
-                @Override
-                public ResponseWritingStage process(final HttpResponse originalResponse) throws IOException {
-                    final HttpResponse processedResponse = strategy.process(filteredRequest, originalResponse);
-
-                    return () -> {
-                        final HttpAttributes responseAttributes = extractAttributesOrEmpty(processedRequest, processedResponse);
-                        final HttpResponse response = new CachingHttpResponse(processedResponse, responseAttributes);
-                        final HttpResponse filteredResponse = responseFilter.filter(response);
-                        strategy.write(precorrelation.correlate(), filteredRequest, filteredResponse, sink);
-                    };
-                }
-            };
+            try {
+                final Precorrelation precorrelation = newPrecorrelation(originalRequest);
+                final HttpRequest processedRequest = strategy.process(originalRequest);
+
+                final HttpAttributes requestAttributes = extractAttributesOrEmpty(processedRequest);
+                final HttpRequest request = new CachingHttpRequest(processedRequest, requestAttributes);
+                final HttpRequest filteredRequest = requestFilter.filter(request);
+
+                return new DefaultRequestWritingStage(strategy, precorrelation, processedRequest, filteredRequest);
+            } catch (RuntimeException e) {
+                log.warn("Unable to prepare request for logging. Will skip the request & response logging step.", e);
+                return Stages.noop();
+            }
         } else {
             return Stages.noop();
         }
@@ -144,4 +130,41 @@ static final class SimpleCorrelation implements Correlation {
 
     }
 
+    @RequiredArgsConstructor
+    private class DefaultRequestWritingStage implements RequestWritingStage {
+
+        private final Strategy strategy;
+        private final Precorrelation precorrelation;
+        private final HttpRequest processedRequest;
+        private final HttpRequest filteredRequest;
+
+        @Override
+        public ResponseProcessingStage write() throws IOException {
+            try {
+                strategy.write(precorrelation, filteredRequest, sink);
+            } catch (RuntimeException e) {
+                log.warn("Unable to log request. Will skip the request & response logging step.", e);
+                return Stages.noop();
+            }
+
+            return this;
+        }
+
+        @Override
+        public ResponseWritingStage process(final HttpResponse originalResponse) throws IOException {
+            final HttpResponse processedResponse = this.strategy.process(filteredRequest, originalResponse);
+
+            return () -> {
+                try {
+                    final HttpAttributes responseAttributes = extractAttributesOrEmpty(processedRequest, processedResponse);
+                    final HttpResponse response = new CachingHttpResponse(processedResponse, responseAttributes);
+                    final HttpResponse filteredResponse = responseFilter.filter(response);
+                    strategy.write(precorrelation.correlate(), filteredRequest, filteredResponse, sink);
+                } catch (RuntimeException e) {
+                    log.warn("Unable to log response. Will skip the response logging step.", e);
+                }
+            };
+        }
+    }
+
 }

logbook-core/src/test/java/org/zalando/logbook/core/DefaultLogbookTest.java

@@ -5,10 +5,12 @@
 import org.mockito.ArgumentCaptor;
 import org.mockito.stubbing.Answer;
 import org.zalando.logbook.BodyFilter;
+import org.zalando.logbook.Correlation;
 import org.zalando.logbook.HeaderFilter;
 import org.zalando.logbook.HttpRequest;
 import org.zalando.logbook.HttpResponse;
 import org.zalando.logbook.Logbook;
+import org.zalando.logbook.Precorrelation;
 import org.zalando.logbook.QueryFilter;
 import org.zalando.logbook.Sink;
 import org.zalando.logbook.attributes.AttributeExtractor;
@@ -23,6 +25,7 @@
 import static org.assertj.core.api.Assertions.assertThat;
 import static org.assertj.core.api.Assertions.assertThatCode;
 import static org.mockito.ArgumentMatchers.any;
+import static org.mockito.Mockito.doThrow;
 import static org.mockito.Mockito.mock;
 import static org.mockito.Mockito.never;
 import static org.mockito.Mockito.verify;
@@ -157,4 +160,49 @@ void shouldNotThrowWhenUsingCompositeAttributeExtractor() {
         ).doesNotThrowAnyException();
     }
 
+    @Test
+    void shouldNotThrowWhenRequestFilterThrowsWhilePreparingRequestWritingStage() throws Exception {
+        when(headerFilter.filter(any())).thenThrow(new RuntimeException("Filtering failed"));
+
+        final Logbook logbook = Logbook.builder()
+                .headerFilter(headerFilter)
+                .sink(sink)
+                .build();
+
+        Logbook.RequestWritingStage readingStage = logbook.process(request);
+        assertThat(readingStage).isEqualTo(Stages.noop());
+
+        verify(sink, never()).write(any(Precorrelation.class), any(HttpRequest.class));
+        verify(sink, never()).write(any(Correlation.class), any(HttpRequest.class), any(HttpResponse.class));
+        verify(sink, never()).writeBoth(any(), any(), any());
+    }
+
+    @Test
+    void shouldNotThrowWhenRequestWritingFailsWithRuntimeException() throws Exception {
+        doThrow(new RuntimeException("Writing request went wrong")).when(sink).write(any(Precorrelation.class), any());
+
+        final Logbook logbook = Logbook.builder()
+                .sink(sink)
+                .build();
+
+        Logbook.ResponseProcessingStage stage = logbook.process(request).write();
+        assertThat(stage).isEqualTo(Stages.noop());
+
+        verify(sink, never()).write(any(Correlation.class), any(HttpRequest.class), any(HttpResponse.class));
+        verify(sink, never()).writeBoth(any(), any(), any());
+    }
+
+    @Test
+    void shouldNotThrowWhenResponseWritingFailsWithRuntimeException() throws Exception {
+        doThrow(new RuntimeException("Writing response went wrong")).when(sink).write(any(Correlation.class), any(), any());
+
+        final Logbook logbook = Logbook.builder()
+                .sink(sink)
+                .build();
+
+        assertThatCode(() ->
+                logbook.process(request).write().process(response).write()
+        ).doesNotThrowAnyException();
+    }
+
 }

logbook-httpclient/src/main/java/org/zalando/logbook/httpclient/LogbookHttpAsyncResponseConsumer.java

@@ -1,5 +1,6 @@
 package org.zalando.logbook.httpclient;
 
+import lombok.extern.slf4j.Slf4j;
 import org.apache.http.HttpException;
 import org.apache.http.HttpResponse;
 import org.apache.http.nio.protocol.HttpAsyncResponseConsumer;
@@ -8,11 +9,11 @@
 import org.zalando.logbook.Logbook.ResponseProcessingStage;
 
 import java.io.IOException;
-import java.io.UncheckedIOException;
 
 import static org.apiguardian.api.API.Status.EXPERIMENTAL;
 
 @API(status = EXPERIMENTAL)
+@Slf4j
 public final class LogbookHttpAsyncResponseConsumer<T> extends ForwardingHttpAsyncResponseConsumer<T> {
 
     private final HttpAsyncResponseConsumer<T> consumer;
@@ -40,9 +41,13 @@ public void responseCompleted(final HttpContext context) {
         final ResponseProcessingStage stage = find(context);
 
         try {
-            stage.process(new RemoteResponse(response, decompressResponse)).write();
+            if (stage != null) {
+                stage.process(new RemoteResponse(response, decompressResponse)).write();
+            } else {
+                log.warn("Unable to log response: ResponseProcessingStage is null in HttpContext. Will skip the response logging step.");
+            }
         } catch (final IOException e) {
-            throw new UncheckedIOException(e);
+            log.warn("Unable to log response. Will skip the response logging step.", e);
         }
 
         delegate().responseCompleted(context);

logbook-httpclient/src/main/java/org/zalando/logbook/httpclient/LogbookHttpRequestInterceptor.java

@@ -1,5 +1,6 @@
 package org.zalando.logbook.httpclient;
 
+import lombok.extern.slf4j.Slf4j;
 import org.apache.http.HttpRequest;
 import org.apache.http.HttpRequestInterceptor;
 import org.apache.http.protocol.HttpContext;
@@ -12,6 +13,7 @@
 import static org.apiguardian.api.API.Status.STABLE;
 
 @API(status = STABLE)
+@Slf4j
 public final class LogbookHttpRequestInterceptor implements HttpRequestInterceptor {
 
     private final Logbook logbook;
@@ -22,9 +24,13 @@ public LogbookHttpRequestInterceptor(final Logbook logbook) {
 
     @Override
     public void process(final HttpRequest httpRequest, final HttpContext context) throws IOException {
-        final LocalRequest request = new LocalRequest(httpRequest);
-        final ResponseProcessingStage stage = logbook.process(request).write();
-        context.setAttribute(Attributes.STAGE, stage);
+        try {
+            final LocalRequest request = new LocalRequest(httpRequest);
+            final ResponseProcessingStage stage = logbook.process(request).write();
+            context.setAttribute(Attributes.STAGE, stage);
+        } catch (Exception e) {
+            log.warn("Unable to log request. Will skip the request & response logging step.", e);
+        }
     }
 
 }

logbook-httpclient/src/main/java/org/zalando/logbook/httpclient/LogbookHttpResponseInterceptor.java

@@ -1,5 +1,6 @@
 package org.zalando.logbook.httpclient;
 
+import lombok.extern.slf4j.Slf4j;
 import org.apache.http.HttpResponse;
 import org.apache.http.HttpResponseInterceptor;
 import org.apache.http.nio.client.HttpAsyncClient;
@@ -19,6 +20,7 @@
  * @see LogbookHttpAsyncResponseConsumer
  */
 @API(status = STABLE)
+@Slf4j
 public final class LogbookHttpResponseInterceptor implements HttpResponseInterceptor {
 
     private final boolean decompressResponse;
@@ -32,8 +34,20 @@ public LogbookHttpResponseInterceptor(boolean decompressResponse) {
 
     @Override
     public void process(final HttpResponse original, final HttpContext context) throws IOException {
+        try {
+            doProcess(original, context);
+        } catch (Exception e) {
+            log.warn("Unable to log response. Will skip the response logging step.", e);
+        }
+    }
+
+    private void doProcess(HttpResponse original, HttpContext context) throws IOException {
         final ResponseProcessingStage stage = find(context);
-        stage.process(new RemoteResponse(original, decompressResponse)).write();
+        if (stage != null) {
+            stage.process(new RemoteResponse(original, decompressResponse)).write();
+        } else {
+            log.warn("Unable to log response: ResponseProcessingStage is null in HttpContext. Will skip the response logging step.");
+        }
     }
 
     private ResponseProcessingStage find(final HttpContext context) {

logbook-httpclient/src/test/java/org/zalando/logbook/httpclient/AbstractHttpTest.java

@@ -2,6 +2,7 @@
 
 import com.github.restdriver.clientdriver.ClientDriver;
 import com.github.restdriver.clientdriver.ClientDriverFactory;
+import com.github.restdriver.clientdriver.ClientDriverResponse;
 import org.apache.http.HttpResponse;
 import org.apache.http.util.EntityUtils;
 import org.junit.jupiter.api.BeforeEach;
@@ -23,6 +24,7 @@
 import static java.lang.String.format;
 import static org.assertj.core.api.Assertions.assertThat;
 import static org.mockito.ArgumentMatchers.any;
+import static org.mockito.Mockito.doThrow;
 import static org.mockito.Mockito.mock;
 import static org.mockito.Mockito.never;
 import static org.mockito.Mockito.verify;
@@ -139,6 +141,32 @@ private void sendAndReceive() throws InterruptedException, ExecutionException, I
         sendAndReceive(null);
     }
 
+
+    @Test
+    void shouldNotThrowExceptionWhenLogbookRequestInterceptorHasException() throws IOException, ExecutionException, InterruptedException {
+        doThrow(new IOException("Writing request went wrong")).when(writer).write(any(Precorrelation.class), any());
+
+        driver.addExpectation(onRequestTo("/").withMethod(GET), new ClientDriverResponse().withStatus(500));
+
+        sendAndReceive();
+
+        verify(writer).write(any(Precorrelation.class), any());
+        verify(writer, never()).write(any(Correlation.class), any());
+    }
+
+
+    @Test
+    void shouldNotThrowExceptionWhenLogbookResponseInterceptorHasException() throws IOException, ExecutionException, InterruptedException {
+        doThrow(new IOException("Writing response went wrong")).when(writer).write(any(Correlation.class), any());
+
+        driver.addExpectation(onRequestTo("/").withMethod(GET), new ClientDriverResponse().withStatus(500));
+
+        sendAndReceive();
+
+        verify(writer).write(any(Precorrelation.class), any());
+        verify(writer).write(any(Correlation.class), any());
+    }
+
     protected abstract HttpResponse sendAndReceive(@Nullable String body)
             throws IOException, ExecutionException, InterruptedException;
 }

logbook-httpclient/src/test/java/org/zalando/logbook/httpclient/LogbookHttpAsyncResponseConsumerTest.java

@@ -22,7 +22,6 @@
 
 import javax.annotation.Nullable;
 import java.io.IOException;
-import java.io.UncheckedIOException;
 import java.util.concurrent.ExecutionException;
 
 import static com.github.restdriver.clientdriver.RestClientDriver.giveResponse;
@@ -31,10 +30,10 @@
 import static org.apache.http.entity.ContentType.TEXT_PLAIN;
 import static org.apache.http.nio.client.methods.HttpAsyncMethods.create;
 import static org.apache.http.nio.client.methods.HttpAsyncMethods.createConsumer;
-import static org.junit.jupiter.api.Assertions.assertThrows;
 import static org.mockito.ArgumentMatchers.any;
 import static org.mockito.Mockito.doThrow;
 import static org.mockito.Mockito.mock;
+import static org.mockito.Mockito.verify;
 import static org.mockito.Mockito.when;
 
 public final class LogbookHttpAsyncResponseConsumerTest extends AbstractHttpTest {
@@ -83,7 +82,7 @@ protected HttpResponse sendAndReceive(@Nullable final String body) throws IOExce
     }
 
     @Test
-    void shouldWrapIOException() throws IOException {
+    void shouldNotPropagateException() throws IOException {
         final HttpAsyncResponseConsumer<HttpResponse> unit = new LogbookHttpAsyncResponseConsumer<>(createConsumer(), false);
 
         final BasicHttpContext context = new BasicHttpContext();
@@ -95,8 +94,9 @@ void shouldWrapIOException() throws IOException {
 
         doThrow(new IOException()).when(last).write();
 
-        assertThrows(UncheckedIOException.class, () ->
-                unit.responseCompleted(context));
+        unit.responseCompleted(context);
+
+        verify(last).write();
     }
 
 }