Dynatrace registry: Truncate log output (#3148)

* Dynatrace registry: Truncate log output

* Only log stack trace in debug

* Add indicator for truncation with StringUtils

* Use truncation with indicator

* Use WarnThenDebugLogger

* Log 'send' exception message always and log once

* Use entire length before abbreviating

Author: arminru

implementations/micrometer-registry-dynatrace/src/main/java/io/micrometer/dynatrace/v2/DynatraceExporterV2.java

@@ -16,13 +16,16 @@
 package io.micrometer.dynatrace.v2;
 
 import com.dynatrace.metric.util.*;
+
 import io.micrometer.core.instrument.*;
 import io.micrometer.core.instrument.distribution.HistogramSnapshot;
 import io.micrometer.core.instrument.distribution.ValueAtPercentile;
 import io.micrometer.core.instrument.util.AbstractPartition;
+import io.micrometer.core.instrument.util.StringUtils;
 import io.micrometer.core.ipc.http.HttpSender;
 import io.micrometer.core.util.internal.logging.InternalLogger;
 import io.micrometer.core.util.internal.logging.InternalLoggerFactory;
+import io.micrometer.core.util.internal.logging.WarnThenDebugLogger;
 import io.micrometer.dynatrace.AbstractDynatraceExporter;
 import io.micrometer.dynatrace.DynatraceConfig;
 import io.micrometer.dynatrace.types.DynatraceSummarySnapshot;
@@ -55,8 +58,11 @@ public final class DynatraceExporterV2 extends AbstractDynatraceExporter {
     private static final Pattern EXTRACT_LINES_OK = Pattern.compile("\"linesOk\":\\s?(\\d+)");
     private static final Pattern EXTRACT_LINES_INVALID = Pattern.compile("\"linesInvalid\":\\s?(\\d+)");
     private static final Pattern IS_NULL_ERROR_RESPONSE = Pattern.compile("\"error\":\\s?null");
+    private static final int LOG_RESPONSE_BODY_TRUNCATION_LIMIT = 1_000;
+    private static final String LOG_RESPONSE_BODY_TRUNCATION_INDICATOR = " (truncated)";
 
     private final InternalLogger logger = InternalLoggerFactory.getInstance(DynatraceExporterV2.class);
+    private static final WarnThenDebugLogger warnThenDebugLoggerSendStack = new WarnThenDebugLogger(DynatraceExporterV2.class);
     private static final Map<String, String> staticDimensions = Collections.singletonMap("dt.metrics.source", "micrometer");
 
     private final MetricBuilderFactory metricBuilderFactory;
@@ -310,9 +316,12 @@ private void send(List<String> metricLines) {
                     .withPlainText(body)
                     .send()
                     .onSuccess(response -> handleSuccess(metricLines.size(), response))
-                    .onError(response -> logger.error("Failed metric ingestion: Error Code={}, Response Body={}", response.code(), response.body()));
+                    .onError(response -> logger.error("Failed metric ingestion: Error Code={}, Response Body={}",
+                        response.code(),
+                        StringUtils.truncate(response.body(), LOG_RESPONSE_BODY_TRUNCATION_LIMIT, LOG_RESPONSE_BODY_TRUNCATION_INDICATOR)));
         } catch (Throwable throwable) {
-            logger.error("Failed metric ingestion: " + throwable.getMessage(), throwable);
+            logger.warn("Failed metric ingestion: " + throwable);
+            warnThenDebugLoggerSendStack.log("Stack trace for previous 'Failed metric ingestion' warning log: ", throwable);
         }
     }
 
@@ -325,16 +334,18 @@ private void handleSuccess(int totalSent, HttpSender.Response response) {
                     logger.debug("Sent {} metric lines, linesOk: {}, linesInvalid: {}.",
                             totalSent, linesOkMatchResult.group(1), linesInvalidMatchResult.group(1));
                 } else {
-                    logger.warn("Unable to parse response: {}", response.body());
+                    logger.warn("Unable to parse response: {}",
+                        StringUtils.truncate(response.body(), LOG_RESPONSE_BODY_TRUNCATION_LIMIT, LOG_RESPONSE_BODY_TRUNCATION_INDICATOR));
                 }
             } else {
-                logger.warn("Unable to parse response: {}", response.body());
+                logger.warn("Unable to parse response: {}",
+                    StringUtils.truncate(response.body(), LOG_RESPONSE_BODY_TRUNCATION_LIMIT, LOG_RESPONSE_BODY_TRUNCATION_INDICATOR));
             }
         } else {
             // common pitfall if URI is supplied in V1 format (without endpoint path)
             logger.error("Expected status code 202, got {}.\nResponse Body={}\nDid you specify the ingest path (e.g.: /api/v2/metrics/ingest)?",
                     response.code(),
-                    response.body()
+                    StringUtils.truncate(response.body(), LOG_RESPONSE_BODY_TRUNCATION_LIMIT, LOG_RESPONSE_BODY_TRUNCATION_INDICATOR)
             );
         }
     }

micrometer-core/src/main/java/io/micrometer/core/instrument/util/StringUtils.java

@@ -89,6 +89,25 @@ public static String truncate(String string, int maxLength) {
         return string;
     }
 
+    /**
+     * Truncate the String to the max length and append string to indicate if truncation was applied
+     *
+     * @param string String to truncate
+     * @param maxLength max length, which includes the length required for {@code truncationIndicator}
+     * @param truncationIndicator A string that is appended if {@code string} is truncated
+     * @return truncated String
+     */
+    public static String truncate(String string, int maxLength, String truncationIndicator) {
+        if (truncationIndicator.length() >= maxLength) {
+            throw new IllegalArgumentException("maxLength must be greater than length of truncationIndicator");
+        }
+        if (string.length() > maxLength) {
+            final int remainingLength = maxLength - truncationIndicator.length();
+            return string.substring(0, remainingLength) + truncationIndicator;
+        }
+        return string;
+    }
+
     private StringUtils() {
     }
 

micrometer-core/src/test/java/io/micrometer/core/instrument/util/StringUtilsTest.java

@@ -18,6 +18,7 @@
 import org.junit.jupiter.api.Test;
 
 import static org.assertj.core.api.Assertions.assertThat;
+import static org.junit.jupiter.api.Assertions.assertThrows;
 
 /**
  * Tests for {@link StringUtils}.
@@ -36,6 +37,36 @@ void truncateWhenLessThanMaxLengthShouldReturnItself() {
         assertThat(StringUtils.truncate("123", 5)).isEqualTo("123");
     }
 
+    @Test
+    void truncateWithIndicatorWhenGreaterThanMaxLengthShouldTruncate() {
+        assertThat(StringUtils.truncate("1234567890", 7, "...")).isEqualTo("1234...");
+    }
+
+    @Test
+    void truncateWithEmptyIndicatorWhenGreaterThanMaxLengthShouldTruncate() {
+        assertThat(StringUtils.truncate("1234567890", 7, "")).isEqualTo("1234567");
+    }
+
+    @Test
+    void truncateWithIndicatorWhenSameAsMaxLengthShouldReturnItself() {
+        assertThat(StringUtils.truncate("1234567", 7, "...")).isEqualTo("1234567");
+    }
+
+    @Test
+    void truncateWithIndicatorWhenLessThanMaxLengthShouldReturnItself() {
+        assertThat(StringUtils.truncate("123", 7, "...")).isEqualTo("123");
+    }
+
+    @Test
+    void truncateWithIndicatorThrowsOnInvalidLength1() {
+        assertThrows(IllegalArgumentException.class, () -> StringUtils.truncate("12345", 7, "[abbreviated]"));
+    }
+
+    @Test
+    void truncateWithIndicatorThrowsOnInvalidLength2() {
+        assertThrows(IllegalArgumentException.class, () -> StringUtils.truncate("1234567890", 7, "[abbreviated]"));
+    }
+
     @Test
     void isNotEmptyWhenNullShouldBeFalse() {
         assertThat(StringUtils.isNotEmpty(null)).isFalse();