fix #5117: correcting the call to the actual consumer, showing bytes

CHANGELOG.md

@@ -3,6 +3,7 @@
 ### 6.7-SNAPSHOT
 
 #### Bugs
+* Fix #5117: corrected the trace httpclient logging of large response bodies
 * Fix #5125: TLS 1.3 only should be supported
 * Fix #5126: fallback to changeit only if null/empty does not work
 * Fix #5145: [java-generator] handle `additionalProperties: true` emitting a field of type `AnyType`

kubernetes-client-api/src/main/java/io/fabric8/kubernetes/client/http/BufferUtil.java

@@ -76,14 +76,14 @@ public static ByteBuffer copy(ByteBuffer buffer) {
 
   /**
    * Very rudimentary method to check if the provided ByteBuffer contains text.
-   * 
+   *
    * @return true if the buffer contains text, false otherwise.
    */
   public static boolean isPlainText(ByteBuffer originalBuffer) {
     if (originalBuffer == null) {
       return false;
     }
-    final ByteBuffer buffer = copy(originalBuffer);
+    final ByteBuffer buffer = originalBuffer.asReadOnlyBuffer();
     final CharsetDecoder decoder = StandardCharsets.UTF_8.newDecoder();
     try {
       decoder.decode(buffer);

kubernetes-client-api/src/main/java/io/fabric8/kubernetes/client/http/HttpLoggingInterceptor.java

@@ -74,38 +74,33 @@ private static final class DeferredLoggingConsumer
     private final HttpLogger httpLogger;
     private final HttpRequest originalRequest;
     private final AsyncBody.Consumer<List<ByteBuffer>> originalConsumer;
-    private final AtomicBoolean logResponseBody;
     private final AtomicLong responseBodySize;
     private final Queue<ByteBuffer> responseBody;
+    private final AtomicBoolean bodyTruncated = new AtomicBoolean();
 
     public DeferredLoggingConsumer(HttpLogger httpLogger, HttpRequest originalRequest,
         AsyncBody.Consumer<List<ByteBuffer>> originalConsumer) {
       this.httpLogger = httpLogger;
       this.originalRequest = originalRequest;
       this.originalConsumer = originalConsumer;
-      logResponseBody = new AtomicBoolean(true);
       responseBodySize = new AtomicLong(0);
       responseBody = new ConcurrentLinkedQueue<>();
     }
 
     @Override
     public void consume(List<ByteBuffer> value, AsyncBody asyncBody) throws Exception {
-      if (!logResponseBody.get() || responseBodySize.get() > MAX_BODY_SIZE) {
-        return;
+      try {
+        value.stream().forEach(bb -> {
+          if (responseBodySize.addAndGet(bb.remaining()) < MAX_BODY_SIZE && !bodyTruncated.get()
+              && BufferUtil.isPlainText(bb)) {
+            responseBody.add(bb);
+          } else {
+            bodyTruncated.set(true);
+          }
+        });
+      } finally {
+        originalConsumer.consume(value, asyncBody);
       }
-      if (!value.isEmpty()) {
-        if (BufferUtil.isPlainText(value.iterator().next())) {
-          value.stream().map(BufferUtil::copy).forEach(bb -> {
-            if (responseBodySize.addAndGet(bb.remaining()) < MAX_BODY_SIZE) {
-              responseBody.add(bb);
-            }
-
-          });
-        } else {
-          logResponseBody.set(false);
-        }
-      }
-      originalConsumer.consume(value, asyncBody);
     }
 
     @Override
@@ -125,7 +120,7 @@ private void processAsyncBody(AsyncBody asyncBody, HttpResponse<?> response) {
         // TODO: we also have access to the response.request, which may be different than originalRequest
         httpLogger.logRequest(originalRequest);
         httpLogger.logResponse(response);
-        httpLogger.logResponseBody(responseBody);
+        httpLogger.logResponseBody(responseBody, responseBodySize.get(), bodyTruncated.get());
         httpLogger.logEnd();
         responseBody.clear();
       });
@@ -156,15 +151,21 @@ void logResponse(HttpResponse<?> response) {
       }
     }
 
-    void logResponseBody(Queue<ByteBuffer> responseBody) {
-      if (logger.isTraceEnabled() && responseBody != null && !responseBody.isEmpty()) {
+    void logResponseBody(Queue<ByteBuffer> responseBody, long bytesReceived, boolean truncated) {
+      if (logger.isTraceEnabled()) {
         final StringBuilder bodyString = new StringBuilder();
-        while (!responseBody.isEmpty()) {
-          bodyString.append(StandardCharsets.UTF_8.decode(responseBody.poll()));
+        if (responseBody != null && !responseBody.isEmpty()) {
+          while (!responseBody.isEmpty()) {
+            bodyString.append(StandardCharsets.UTF_8.decode(responseBody.poll()));
+          }
         }
-        if (bodyString.length() > 0) {
-          logger.trace(bodyString.toString());
+
+        // we'll typically have bytes == content length,
+        // but it can be less if binary, truncated, or an error happened
+        if (truncated) {
+          bodyString.append("... body bytes ").append(bytesReceived);
         }
+        logger.trace(bodyString.toString());
       }
     }
 

kubernetes-client-api/src/test/java/io/fabric8/kubernetes/client/http/AbstractHttpLoggingInterceptorTest.java

@@ -30,6 +30,7 @@
 import org.junit.jupiter.api.BeforeEach;
 import org.junit.jupiter.api.DisplayName;
 import org.junit.jupiter.api.Test;
+import org.mockito.ArgumentCaptor;
 import org.mockito.InOrder;
 import org.mockito.Mockito;
 import org.slf4j.Logger;
@@ -42,6 +43,7 @@
 import java.util.Queue;
 import java.util.concurrent.TimeUnit;
 
+import static org.junit.jupiter.api.Assertions.assertTrue;
 import static org.mockito.ArgumentMatchers.anyInt;
 import static org.mockito.ArgumentMatchers.anyString;
 import static org.mockito.ArgumentMatchers.argThat;
@@ -179,6 +181,24 @@ public void httpResponseBodyLogged() throws Exception {
     inOrder.verify(logger).trace("-HTTP END-");
   }
 
+  @Test
+  @DisplayName("HTTP large response body is logged")
+  public void httpLargeResponseBodyLogged() throws Exception {
+    server.expect().withPath("/response-body-large")
+        .andReturn(200, Collections.nCopies(100000, "This is the large response body"))
+        .always();
+    httpClient.sendAsync(httpClient.newHttpRequestBuilder()
+        .uri(server.url("/response-body-large"))
+        .build(), String.class).get(10, TimeUnit.SECONDS);
+    verify(logger, timeout(1000L)).trace("-HTTP END-");
+    inOrder.verify(logger).trace("-HTTP START-");
+    inOrder.verify(logger).trace(eq("< {} {}"), anyInt(), anyString());
+    ArgumentCaptor<String> captor = ArgumentCaptor.forClass(String.class);
+    inOrder.verify(logger).trace(captor.capture());
+    assertTrue(captor.getValue().endsWith("... body bytes 3400001"));
+    inOrder.verify(logger).trace("-HTTP END-");
+  }
+
   @Test
   @DisplayName("HTTP binary response body is skipped")
   public void httpResponseBodySkipped() throws Exception {
@@ -203,6 +223,7 @@ public MockResponse toMockResponse(RecordedRequest recordedRequest) {
     verify(logger, timeout(1000L)).trace("-HTTP END-");
     inOrder.verify(logger).trace("-HTTP START-");
     inOrder.verify(logger).trace(eq("< {} {}"), anyInt(), anyString());
+    inOrder.verify(logger).trace("... body bytes 5");
     inOrder.verify(logger, times(1)).trace(anyString()); // only -HTTP END- was logged
     inOrder.verifyNoMoreInteractions();
   }