Enhance logging in ConsulFailoverInterceptor

src/main/java/org/kiwiproject/consul/util/failover/ConsulFailoverInterceptor.java

@@ -2,11 +2,12 @@
 
 import static com.google.common.base.Preconditions.checkArgument;
 
+import com.google.common.annotations.VisibleForTesting;
 import com.google.common.net.HostAndPort;
 import okhttp3.Interceptor;
 import okhttp3.Request;
 import okhttp3.Response;
-import org.jetbrains.annotations.NotNull;
+import org.checkerframework.checker.nullness.qual.NonNull;
 import org.kiwiproject.consul.ConsulException;
 import org.kiwiproject.consul.util.failover.strategy.BlacklistingConsulFailoverStrategy;
 import org.kiwiproject.consul.util.failover.strategy.ConsulFailoverStrategy;
@@ -81,7 +82,7 @@ public int maxFailoverAttempts() {
         return maxFailoverAttempts;
     }
 
-    @NotNull
+    @NonNull
     @Override
     public Response intercept(Chain chain) {
 
@@ -95,31 +96,30 @@ public Response intercept(Chain chain) {
             // Initially, we have an inflight request
             Request previousRequest = originalRequest;
 
-            Optional<Request> nextRequest;
-
             // Note:
             // The previousResponse is never used here and is always null when calling computeNextStage.
             // See discussion in issue #195 ("previousResponse is always null in ConsulFailoverInterceptor#intercept")
             // Link: https://github.com/kiwiproject/consul-client/issues/195
 
+            Optional<Request> maybeNextRequest;
             var currentAttempt = 1;
 
             // Get the next viable request
-            while ((nextRequest = strategy.computeNextStage(previousRequest, null)).isPresent()) {
+            while ((maybeNextRequest = strategy.computeNextStage(previousRequest, null)).isPresent()) {
                 // Get the response from the last viable request
                 Exception exception;
+                Request nextRequest = maybeNextRequest.orElseThrow(IllegalStateException::new);
                 try {
 
                     // Cache for the next cycle if needed
-                    final Request next = nextRequest.get();
-                    previousRequest = next;
+                    previousRequest = nextRequest;
 
                     // Anything other than an exception is valid here.
                     // This is because a 400-series error is a valid code (Permission Denied/Key Not Found)
-                    return chain.proceed(next);
+                    return chain.proceed(nextRequest);
                 } catch (Exception ex) {
-                    LOG.debug("Failed to connect to {}", nextRequest.get().url(), ex);
-                    strategy.markRequestFailed(nextRequest.get());
+                    logExceptionThrownOnRequest(LOG, ex, nextRequest);
+                    strategy.markRequestFailed(nextRequest);
                     exception = ex;
                 }
 
@@ -137,4 +137,16 @@ public Response intercept(Chain chain) {
                     "Consul failover strategy has determined that there are no viable hosts remaining.");
         }
     }
+
+    @VisibleForTesting
+    static void logExceptionThrownOnRequest(Logger logger, Exception ex, Request request) {
+        var url = request.url();
+        if (logger.isDebugEnabled()) {
+            logger.debug("Got error when connecting to {}", url, ex);
+        } else {
+            logger.warn("Got {} when connecting to {} (enable DEBUG level to see stack trace)",
+                    ex.getClass().getName(),
+                    url);
+        }
+    }
 }

src/test/java/org/kiwiproject/consul/util/failover/ConsulFailoverInterceptorTest.java

@@ -13,6 +13,7 @@
 import static org.mockito.Mockito.verifyNoMoreInteractions;
 import static org.mockito.Mockito.when;
 
+import okhttp3.HttpUrl;
 import okhttp3.Interceptor.Chain;
 import okhttp3.Request;
 import okhttp3.Response;
@@ -22,7 +23,9 @@
 import org.junit.jupiter.params.provider.ValueSource;
 import org.kiwiproject.consul.ConsulException;
 import org.kiwiproject.consul.util.failover.strategy.ConsulFailoverStrategy;
+import org.slf4j.Logger;
 
+import javax.net.ssl.SSLProtocolException;
 import java.io.IOException;
 import java.util.Optional;
 
@@ -89,7 +92,7 @@ void shouldThrowException_WhenNextStageIsEmpty() {
     void shouldReturnResponse_WhenGetResponse_BeforeExceedingMaxFailoverAttempts() throws IOException {
         when(strategy.isRequestViable(any(Request.class))).thenReturn(true);
 
-        var request = mock(Request.class, RETURNS_DEEP_STUBS);
+        var request = newMockRequest();
         when(strategy.computeNextStage(any(Request.class), isNull(Response.class)))
                 .thenReturn(Optional.of(request));
 
@@ -116,7 +119,7 @@ void shouldReturnResponse_WhenGetResponse_BeforeExceedingMaxFailoverAttempts() t
     void shouldThrowException_WhenMaxFailoverAttemptsExceeded() throws IOException {
         when(strategy.isRequestViable(any(Request.class))).thenReturn(true);
 
-        var request = mock(Request.class, RETURNS_DEEP_STUBS);
+        var request = newMockRequest();
         when(strategy.computeNextStage(any(Request.class), isNull(Response.class)))
                 .thenReturn(Optional.of(request));
 
@@ -133,4 +136,52 @@ void shouldThrowException_WhenMaxFailoverAttemptsExceeded() throws IOException {
         //noinspection resource
         verify(chain, times(10)).proceed(any(Request.class));
     }
+
+    @Test
+    void shouldLogExceptionThrownOnRequest_WhenAtWarnLevel() {
+        var logger = newLoggerWithDebugEnabled(false);
+        var request = newMockRequest();
+        var exception = newSslProtocolException();
+
+        ConsulFailoverInterceptor.logExceptionThrownOnRequest(logger, exception, request);
+
+        verify(logger).isDebugEnabled();
+        verify(logger).warn("Got {} when connecting to {} (enable DEBUG level to see stack trace)",
+                exception.getClass().getName(),
+                nextConsulHttpUrl());
+        verifyNoMoreInteractions(logger);
+    }
+
+    @Test
+    void shouldLogExceptionThrownOnRequest_WhenAtDebugLevel() {
+        var logger = newLoggerWithDebugEnabled(true);
+        var request = newMockRequest();
+        var exception = newSslProtocolException();
+
+        ConsulFailoverInterceptor.logExceptionThrownOnRequest(logger, exception, request);
+
+        verify(logger).isDebugEnabled();
+        verify(logger).debug("Got error when connecting to {}", nextConsulHttpUrl(), exception);
+        verifyNoMoreInteractions(logger);
+    }
+
+    private static Logger newLoggerWithDebugEnabled(boolean value) {
+        var logger = mock(Logger.class);
+        when(logger.isDebugEnabled()).thenReturn(value);
+        return logger;
+    }
+
+    private static Request newMockRequest() {
+        var request = mock(Request.class);
+        when(request.url()).thenReturn(nextConsulHttpUrl());
+        return request;
+    }
+
+    private static SSLProtocolException newSslProtocolException() {
+        return new SSLProtocolException("The certificate chain length (11) exceeds the maximum allowed length (10)");
+    }
+
+    private static HttpUrl nextConsulHttpUrl() {
+        return HttpUrl.parse("https://consul.acme.com:8501");
+    }
 }