diff --git a/implementations/micrometer-registry-dynatrace/src/main/java/io/micrometer/dynatrace/v2/DynatraceExporterV2.java b/implementations/micrometer-registry-dynatrace/src/main/java/io/micrometer/dynatrace/v2/DynatraceExporterV2.java index a014e63235..b32cb11220 100644 --- a/implementations/micrometer-registry-dynatrace/src/main/java/io/micrometer/dynatrace/v2/DynatraceExporterV2.java +++ b/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 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 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 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 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: diff --git a/implementations/micrometer-registry-dynatrace/src/main/java/io/micrometer/dynatrace/v2/WarnThenDebugLoggers.java b/implementations/micrometer-registry-dynatrace/src/main/java/io/micrometer/dynatrace/v2/WarnThenDebugLoggers.java new file mode 100644 index 0000000000..bef7df8311 --- /dev/null +++ b/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); + } + + } + +} diff --git a/implementations/micrometer-registry-dynatrace/src/test/java/io/micrometer/dynatrace/v2/DynatraceExporterV2Test.java b/implementations/micrometer-registry-dynatrace/src/test/java/io/micrometer/dynatrace/v2/DynatraceExporterV2Test.java index 33069fb6ec..47dc8691cf 100644 --- a/implementations/micrometer-registry-dynatrace/src/test/java/io/micrometer/dynatrace/v2/DynatraceExporterV2Test.java +++ b/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 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));