From 640721c250bda8ee54d7a8b3815fa0d278f4f69b Mon Sep 17 00:00:00 2001 From: Steve Hawkins Date: Wed, 17 May 2023 08:53:34 -0400 Subject: [PATCH] fix #5117: correcting the call to the actual consumer, showing bytes --- CHANGELOG.md | 1 + .../kubernetes/client/http/BufferUtil.java | 4 +- .../client/http/HttpLoggingInterceptor.java | 49 ++++++++++--------- .../AbstractHttpLoggingInterceptorTest.java | 21 ++++++++ 4 files changed, 49 insertions(+), 26 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index c076f4a7c4e..4fb510278ab 100644 --- a/CHANGELOG.md +++ b/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` diff --git a/kubernetes-client-api/src/main/java/io/fabric8/kubernetes/client/http/BufferUtil.java b/kubernetes-client-api/src/main/java/io/fabric8/kubernetes/client/http/BufferUtil.java index ca68d180c9e..58ea0b555ac 100644 --- a/kubernetes-client-api/src/main/java/io/fabric8/kubernetes/client/http/BufferUtil.java +++ b/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); diff --git a/kubernetes-client-api/src/main/java/io/fabric8/kubernetes/client/http/HttpLoggingInterceptor.java b/kubernetes-client-api/src/main/java/io/fabric8/kubernetes/client/http/HttpLoggingInterceptor.java index 185ee87ab79..aa667841523 100644 --- a/kubernetes-client-api/src/main/java/io/fabric8/kubernetes/client/http/HttpLoggingInterceptor.java +++ b/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> originalConsumer; - private final AtomicBoolean logResponseBody; private final AtomicLong responseBodySize; private final Queue responseBody; + private final AtomicBoolean bodyTruncated = new AtomicBoolean(); public DeferredLoggingConsumer(HttpLogger httpLogger, HttpRequest originalRequest, AsyncBody.Consumer> 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 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 responseBody) { - if (logger.isTraceEnabled() && responseBody != null && !responseBody.isEmpty()) { + void logResponseBody(Queue 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()); } } diff --git a/kubernetes-client-api/src/test/java/io/fabric8/kubernetes/client/http/AbstractHttpLoggingInterceptorTest.java b/kubernetes-client-api/src/test/java/io/fabric8/kubernetes/client/http/AbstractHttpLoggingInterceptorTest.java index 1e53943db4c..6a4ba33221b 100644 --- a/kubernetes-client-api/src/test/java/io/fabric8/kubernetes/client/http/AbstractHttpLoggingInterceptorTest.java +++ b/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 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(); }