[Dynatrace] Logging verbosity: Move metadata discrepancy logging to W…

…arnThenDebug (micrometer-metrics#4583)

Move Metadata discrepancy logging to WarnThenDebug because this is an instrumentation mismatch with the Dynatrace model that end users cannot fix, so flooding them with warn logs is not productive.

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,54 @@
+/*
+ * 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). Creating the
+ * WarnThenDebugLogger with the same class multiple times makes it impossible to test, as
+ * the MockLoggerFactory will ignore multiple loggers with the same name.
+ */
+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));