[Dynatrace] Logging verbosity: Move metadata discrepancy logging to WarnThenDebug

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

@@ -60,18 +60,18 @@ public final class DynatraceExporterV2 extends AbstractDynatraceExporter {
 
     private static final Pattern IS_NULL_ERROR_RESPONSE = Pattern.compile("\"error\":\\s?null");
 
-    private static final WarnThenDebugLogger stackTraceWarnThenDebugLogger = new WarnThenDebugLogger(
-            DynatraceExporterV2.class);
-
-    private static final WarnThenDebugLogger nanGaugeWarnThenDebugLogger = new WarnThenDebugLogger(
-            DynatraceExporterV2.class);
-
     private static final Map<String, String> staticDimensions = Collections.singletonMap("dt.metrics.source",
             "micrometer");
 
-    // This should be non-static for MockLoggerFactory.injectLogger() in tests.
+    // Loggers must be non-static for MockLoggerFactory.injectLogger() in tests.
     private final InternalLogger logger = InternalLoggerFactory.getInstance(DynatraceExporterV2.class);
 
+    private final WarnThenDebugLogger stackTraceLogger = new WarnThenDebugLoggers.StackTraceLogger();
+
+    private final WarnThenDebugLogger nanGaugeLogger = new WarnThenDebugLoggers.NanGaugeLogger();
+
+    private final WarnThenDebugLogger metadataDiscrepancyLogger = new WarnThenDebugLoggers.MetadataDiscrepancyLogger();
+
     private MetricLinePreConfiguration preConfiguration;
 
     private boolean skipExport = false;
@@ -219,7 +219,7 @@ private String createGaugeLine(Meter meter, Map<String, String> seenMetadata, Me
                 // NaN's are currently dropped on the Dynatrace side, so dropping them
                 // on the client side here will not change the metrics in Dynatrace.
 
-                nanGaugeWarnThenDebugLogger.log(() -> String.format(
+                nanGaugeLogger.log(() -> String.format(
                         "Meter '%s' returned a value of NaN, which will not be exported. This can be a deliberate value or because the weak reference to the backing object expired.",
                         meter.getId().getName()));
                 return null;
@@ -418,9 +418,11 @@ private void send(List<String> metricLines) {
                         response.code(), getTruncatedBody(response)));
         }
         catch (Throwable throwable) {
-            logger.warn("Failed metric ingestion: " + throwable);
-            stackTraceWarnThenDebugLogger.log("Stack trace for previous 'Failed metric ingestion' warning log: ",
-                    throwable);
+            // the "general" logger logs the message, the WarnThenDebugLogger logs the
+            // stack trace.
+            logger.warn("Failed metric ingestion: {}", throwable.toString());
+            stackTraceLogger.log(String.format("Stack trace for previous 'Failed metric ingestion' warning log: %s",
+                    throwable.getMessage()), throwable);
         }
     }
 
@@ -501,10 +503,10 @@ private void storeMetadata(MetricLineBuilder.MetadataStep metadataStep, Map<Stri
                 // set for this metric key.
                 if (!previousMetadataLine.equals(metadataLine)) {
                     seenMetadata.put(key, null);
-                    logger.warn(
-                            "Metadata discrepancy detected:\n" + "original metadata:\t{}\n" + "tried to set new:\t{}\n"
-                                    + "Metadata for metric key {} will not be sent.",
-                            previousMetadataLine, metadataLine, key);
+                    metadataDiscrepancyLogger.log(() -> String.format(
+                            "Metadata discrepancy detected:\n" + "original metadata:\t%s\n" + "tried to set new:\t%s\n"
+                                    + "Metadata for metric key %s will not be sent.",
+                            previousMetadataLine, metadataLine, key));
                 }
             }
             // else:

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

@@ -0,0 +1,55 @@
+/*
+ * Copyright 2024 VMware, Inc.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ * https://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+package io.micrometer.dynatrace.v2;
+
+import io.micrometer.common.util.internal.logging.WarnThenDebugLogger;
+
+/**
+ * This internal class holds loggers that are used in {@link DynatraceExporterV2}. They
+ * are all just extending the default {@link WarnThenDebugLogger}. It is necessary to
+ * extend them, because the {@link WarnThenDebugLogger} does not allow creating a new
+ * logger with just a name (a class object has to be passed). If the WarnThenDebugLogger
+ * is created with the same class type multiple times, the same instance will be returned.
+ * This would mean that in a scenario with multiple loggers, only the first call would log
+ * the warning, and all subsequent calls will log at debug.
+ */
+class WarnThenDebugLoggers {
+
+    static class StackTraceLogger extends WarnThenDebugLogger {
+
+        public StackTraceLogger() {
+            super(StackTraceLogger.class);
+        }
+
+    }
+
+    static class NanGaugeLogger extends WarnThenDebugLogger {
+
+        public NanGaugeLogger() {
+            super(NanGaugeLogger.class);
+        }
+
+    }
+
+    static class MetadataDiscrepancyLogger extends WarnThenDebugLogger {
+
+        public MetadataDiscrepancyLogger() {
+            super(MetadataDiscrepancyLogger.class);
+        }
+
+    }
+
+}

implementations/micrometer-registry-dynatrace/src/test/java/io/micrometer/dynatrace/v2/DynatraceExporterV2Test.java

@@ -27,7 +27,6 @@
 import io.micrometer.dynatrace.DynatraceApiVersion;
 import io.micrometer.dynatrace.DynatraceConfig;
 import io.micrometer.dynatrace.DynatraceMeterRegistry;
-import org.junit.jupiter.api.AfterEach;
 import org.junit.jupiter.api.BeforeEach;
 import org.junit.jupiter.api.Test;
 import org.mockito.ArgumentCaptor;
@@ -45,7 +44,7 @@
 import java.util.regex.Pattern;
 import java.util.stream.Collectors;
 
-import static io.micrometer.common.util.internal.logging.InternalLogLevel.ERROR;
+import static io.micrometer.common.util.internal.logging.InternalLogLevel.*;
 import static io.micrometer.core.instrument.MockClock.clock;
 import static java.lang.Double.*;
 import static java.util.concurrent.TimeUnit.MILLISECONDS;
@@ -64,9 +63,9 @@
  */
 class DynatraceExporterV2Test {
 
-    private static final MockLoggerFactory FACTORY = new MockLoggerFactory();
+    private MockLoggerFactory loggerFactory;
 
-    private static final MockLogger LOGGER = FACTORY.getLogger(DynatraceExporterV2.class);
+    private MockLogger logger;
 
     private static final Map<String, String> SEEN_METADATA = new HashMap<>();
 
@@ -80,6 +79,8 @@ class DynatraceExporterV2Test {
 
     private DynatraceExporterV2 exporter;
 
+    private static final String subsequentLogsAsDebug = "Note that subsequent logs will be logged at debug level.";
+
     @BeforeEach
     void setUp() {
         this.config = createDefaultDynatraceConfig();
@@ -90,18 +91,19 @@ void setUp() {
                                                                   // library will not
                                                                   // complain.
         this.httpClient = mock(HttpSender.class);
-        this.exporter = FACTORY.injectLogger(() -> createExporter(httpClient));
+
+        // ensures new MockLoggers are created for each test.
+        // Since there are some asserts on log lines, different test runs do not reuse the
+        // same loggers and thus do not interfere.
+        this.loggerFactory = new MockLoggerFactory();
+        this.exporter = loggerFactory.injectLogger(() -> createExporter(httpClient));
+        this.logger = loggerFactory.getLogger(DynatraceExporterV2.class);
 
         this.meterRegistry = DynatraceMeterRegistry.builder(config).clock(clock).httpClient(httpClient).build();
 
         SEEN_METADATA.clear();
     }
 
-    @AfterEach
-    void tearDown() {
-        LOGGER.clear();
-    }
-
     @Test
     void toGaugeLine() {
         meterRegistry.gauge("my.gauge", 1.23);
@@ -118,6 +120,27 @@ void toGaugeLineShouldDropNanValue() {
         assertThat(exporter.toGaugeLine(gauge, SEEN_METADATA)).isEmpty();
     }
 
+    @Test
+    void toGaugeLineShouldDropNanValue_testLogWarnThenDebug() {
+        MockLogger nanGaugeLogger = loggerFactory.getLogger(WarnThenDebugLoggers.NanGaugeLogger.class);
+
+        String expectedMessage = "Meter 'my.gauge' returned a value of NaN, which will not be exported. This can be a deliberate value or because the weak reference to the backing object expired.";
+
+        LogEvent warnEvent = new LogEvent(WARN, String.join(" ", expectedMessage, subsequentLogsAsDebug), null);
+        LogEvent debugEvent = new LogEvent(DEBUG, expectedMessage, null);
+
+        meterRegistry.gauge("my.gauge", NaN);
+        Gauge gauge = meterRegistry.find("my.gauge").gauge();
+
+        // first export; log at warn
+        assertThat(exporter.toGaugeLine(gauge, SEEN_METADATA)).isEmpty();
+        assertThat(nanGaugeLogger.getLogEvents()).hasSize(1).containsExactly(warnEvent);
+
+        // second export; log at debug
+        assertThat(exporter.toGaugeLine(gauge, SEEN_METADATA)).isEmpty();
+        assertThat(nanGaugeLogger.getLogEvents()).hasSize(2).containsExactly(warnEvent, debugEvent);
+    }
+
     @Test
     void toGaugeLineShouldDropInfiniteValues() {
         meterRegistry.gauge("my.gauge", POSITIVE_INFINITY);
@@ -652,10 +675,67 @@ void failOnSendShouldHaveProperLogging() throws Throwable {
         Gauge gauge = meterRegistry.find("my.gauge").gauge();
         exporter.export(Collections.singletonList(gauge));
 
-        assertThat(LOGGER.getLogEvents())
+        assertThat(logger.getLogEvents())
             .contains(new LogEvent(ERROR, "Failed metric ingestion: Error Code=500, Response Body=simulated", null));
     }
 
+    @Test
+    void failOnSendWithExceptionShouldHaveProperLogging_warnThenDebug() {
+        MockLogger stackTraceLogger = loggerFactory.getLogger(WarnThenDebugLoggers.StackTraceLogger.class);
+
+        Throwable expectedException = new RuntimeException("test exception", new Throwable("root cause exception"));
+        when(httpClient.post(config.uri())).thenThrow(expectedException);
+
+        // the "general" logger just logs the message, the WarnThenDebugLogger contains
+        // the exception & stack trace.
+        String expectedWarnThenDebugMessage = "Stack trace for previous 'Failed metric ingestion' warning log:";
+        // these two will be logged by the WarnThenDebugLogger:
+        // the warning message is suffixed with "Note that subsequent logs will be logged
+        // at debug level.".
+        LogEvent warnThenDebugWarningLog = new LogEvent(WARN,
+                String.join(" ", expectedWarnThenDebugMessage, expectedException.getMessage(), subsequentLogsAsDebug),
+                expectedException);
+        LogEvent warnThenDebugDebugLog = new LogEvent(DEBUG,
+                String.join(" ", expectedWarnThenDebugMessage, expectedException.getMessage()), expectedException);
+
+        // this will be logged by the "general" logger in a single line (once per export)
+        LogEvent expectedExceptionLogMessage = new LogEvent(WARN,
+                "Failed metric ingestion: java.lang.RuntimeException: " + expectedException.getMessage(), null);
+
+        meterRegistry.gauge("my.gauge", 1d);
+        Gauge gauge = meterRegistry.find("my.gauge").gauge();
+
+        // first export
+        exporter.export(Collections.singletonList(gauge));
+
+        // after the first export, the general logger only has the WARN event, but not the
+        // debug event.
+        assertThat(logger.getLogEvents()).containsOnlyOnce(expectedExceptionLogMessage);
+
+        long countExceptionLogsFirstExport = logger.getLogEvents()
+            .stream()
+            .filter(event -> event.equals(expectedExceptionLogMessage))
+            .count();
+        assertThat(countExceptionLogsFirstExport).isEqualTo(1);
+
+        // the WarnThenDebugLogger only has one event so far.
+        assertThat(stackTraceLogger.getLogEvents()).hasSize(1).containsExactly(warnThenDebugWarningLog);
+
+        // second export
+        exporter.export(Collections.singletonList(gauge));
+
+        // after the second export, the general logger contains the warning log twice
+        long countExceptionLogsSecondExport = logger.getLogEvents()
+            .stream()
+            .filter(event -> event.equals(expectedExceptionLogMessage))
+            .count();
+        assertThat(countExceptionLogsSecondExport).isEqualTo(2);
+
+        // the WarnThenDebugLogger now has two logs.
+        assertThat(stackTraceLogger.getLogEvents()).hasSize(2)
+            .containsExactly(warnThenDebugWarningLog, warnThenDebugDebugLog);
+    }
+
     @Test
     void endpointPickedUpBetweenExportsAndChangedPropertiesFile() throws Throwable {
         String randomUuid = UUID.randomUUID().toString();
@@ -942,6 +1022,48 @@ void conflictingMetadataIsIgnored() {
         });
     }
 
+    @Test
+    void conflictingMetadataIsIgnored_testLogWarnThenDebug() {
+        MockLogger metadataDiscrepancyLogger = loggerFactory
+            .getLogger(WarnThenDebugLoggers.MetadataDiscrepancyLogger.class);
+
+        String expectedLogMessage = "Metadata discrepancy detected:\n"
+                + "original metadata:\t#my.count count dt.meta.description=count\\ 1\\ description,dt.meta.unit=Bytes\n"
+                + "tried to set new:\t#my.count count dt.meta.description=count\\ description\n"
+                + "Metadata for metric key my.count will not be sent.";
+        LogEvent warnEvent = new LogEvent(WARN, String.join(" ", expectedLogMessage, subsequentLogsAsDebug), null);
+        LogEvent debugEvent = new LogEvent(DEBUG, expectedLogMessage, null);
+
+        HttpSender.Request.Builder builder = mock(HttpSender.Request.Builder.class);
+        when(httpClient.post(anyString())).thenReturn(builder);
+
+        // the unit and description are different between counters, while the name stays
+        // the same.
+        Counter counter1 = Counter.builder("my.count")
+            .description("count 1 description")
+            .baseUnit("Bytes")
+            .tag("counter-number", "counter1")
+            .register(meterRegistry);
+        Counter counter2 = Counter.builder("my.count")
+            .description("count description")
+            .baseUnit("not Bytes")
+            .tag("counter-number", "counter2")
+            .register(meterRegistry);
+
+        counter1.increment(5.234);
+        counter2.increment(2.345);
+
+        // first export
+        exporter.export(meterRegistry.getMeters());
+
+        assertThat(metadataDiscrepancyLogger.getLogEvents()).hasSize(1).containsExactly(warnEvent);
+
+        // second export
+        exporter.export(meterRegistry.getMeters());
+        assertThat(metadataDiscrepancyLogger.getLogEvents()).hasSize(2).containsExactly(warnEvent, debugEvent);
+
+    }
+
     @Test
     void metadataIsNotExportedWhenTurnedOff() {
         HttpSender.Request.Builder builder = spy(HttpSender.Request.build(config.uri(), httpClient));