Skip to content

Commit

Permalink
[dynatrace/v2] reduce log verbosity (#5306)
Browse files Browse the repository at this point in the history 
simplifies the logging in the Dynatrace exporter v2. Most of the loggers' log levels were reduced to INFO. This allows collecting logs (mainly at the INFO level) without drowning out business code WARN and ERROR logs (e.g., when filtering for only ERROR logs).
  • Loading branch information
@pirgeo
pirgeo authored Jul 17, 2024
1 parent fd5d799 commit 4d8cab7
Show file tree
Hide file tree
Showing 3 changed files with 23 additions and 223 deletions.
44 changes: 19 additions & 25 deletions ...eter-registry-dynatrace/src/main/java/io/micrometer/dynatrace/v2/DynatraceExporterV2.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -21,7 +21,6 @@
import io.micrometer.common.util.StringUtils;
import io.micrometer.common.util.internal.logging.InternalLogger;
import io.micrometer.common.util.internal.logging.InternalLoggerFactory;
import io.micrometer.common.util.internal.logging.WarnThenDebugLogger;
import io.micrometer.core.instrument.Timer;
import io.micrometer.core.instrument.*;
import io.micrometer.core.instrument.distribution.HistogramSnapshot;
Expand Down Expand Up @@ -66,12 +65,6 @@ public final class DynatraceExporterV2 extends AbstractDynatraceExporter {
// 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;
Expand Down Expand Up @@ -223,10 +216,9 @@ private String createGaugeLine(Meter meter, Map<String, String> seenMetadata, Me
// collected, but the meter has not been removed from the registry.
// NaN's are currently dropped on the Dynatrace side, so dropping them
// on the client side here will not change the metrics in Dynatrace.

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()));
logger.debug(
"Meter '{}' 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;
}
MetricLineBuilder.GaugeStep gaugeStep = createTypeStep(meter).gauge();
Expand All @@ -236,7 +228,8 @@ private String createGaugeLine(Meter meter, Map<String, String> seenMetadata, Me
return gaugeStep.value(value).timestamp(Instant.ofEpochMilli(clock.wallTime())).build();
}
catch (MetricException e) {
logger.warn(METER_EXCEPTION_LOG_FORMAT, meter.getId(), e.getMessage());
// logging at info to not drown out warnings/errors from business code.
logger.info(METER_EXCEPTION_LOG_FORMAT, meter.getId(), e.getMessage());
}

return null;
Expand All @@ -255,7 +248,8 @@ private String createCounterLine(Meter meter, Map<String, String> seenMetadata,
return counterStep.delta(measurement.getValue()).timestamp(Instant.ofEpochMilli(clock.wallTime())).build();
}
catch (MetricException e) {
logger.warn(METER_EXCEPTION_LOG_FORMAT, meter.getId(), e.getMessage());
// logging at info to not drown out warnings/errors from business code.
logger.info(METER_EXCEPTION_LOG_FORMAT, meter.getId(), e.getMessage());
}

return null;
Expand Down Expand Up @@ -312,7 +306,8 @@ private Stream<String> createSummaryLine(Meter meter, Map<String, String> seenMe
.build());
}
catch (MetricException e) {
logger.warn(METER_EXCEPTION_LOG_FORMAT, meter.getId(), e.getMessage());
// logging at info to not drown out warnings/errors from business code.
logger.info(METER_EXCEPTION_LOG_FORMAT, meter.getId(), e.getMessage());
}

return Stream.empty();
Expand Down Expand Up @@ -431,15 +426,14 @@ private void send(List<String> metricLines) {
.withPlainText(body)
.send()
.onSuccess(response -> handleSuccess(lineCount, response))
.onError(response -> logger.error("Failed metric ingestion: Error Code={}, Response Body={}",
response.code(), getTruncatedBody(response)));
.onError(response -> {
logger.info("Failed metric ingestion: Error Code={}, Response Body={}", response.code(),
getTruncatedBody(response));
});
}
catch (Throwable 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);
// logging at info to not drown out warnings/errors from business code.
logger.info("Failed metric ingestion: {}", throwable.toString());
}
}

Expand Down Expand Up @@ -520,10 +514,10 @@ private void storeMetadata(MetricLineBuilder.MetadataStep metadataStep, Map<Stri
// set for this metric key.
if (!previousMetadataLine.equals(metadataLine)) {
seenMetadata.put(key, null);
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));
logger.debug(
"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);
}
}
// else:
Expand Down
54 changes: 0 additions & 54 deletions ...ter-registry-dynatrace/src/main/java/io/micrometer/dynatrace/v2/WarnThenDebugLoggers.java
View file

This file was deleted.

148 changes: 4 additions & 144 deletions ...-registry-dynatrace/src/test/java/io/micrometer/dynatrace/v2/DynatraceExporterV2Test.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -17,9 +17,6 @@

import com.dynatrace.file.util.DynatraceFileBasedConfigurationProvider;
import io.micrometer.common.lang.Nullable;
import io.micrometer.common.util.internal.logging.LogEvent;
import io.micrometer.common.util.internal.logging.MockLogger;
import io.micrometer.common.util.internal.logging.MockLoggerFactory;
import io.micrometer.core.Issue;
import io.micrometer.core.instrument.Timer;
import io.micrometer.core.instrument.*;
Expand All @@ -44,7 +41,6 @@
import java.util.regex.Pattern;
import java.util.stream.Collectors;

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;
Expand All @@ -63,12 +59,6 @@
*/
class DynatraceExporterV2Test {

private static final String SUBSEQUENT_LOGS_AS_DEBUG = "Note that subsequent logs will be logged at debug level.";

private MockLoggerFactory loggerFactory;

private MockLogger logger;

private static final Map<String, String> SEEN_METADATA = new HashMap<>();

private DynatraceConfig config;
Expand All @@ -85,20 +75,12 @@ class DynatraceExporterV2Test {
void setUp() {
this.config = createDefaultDynatraceConfig();
this.clock = new MockClock();
this.clock.add(System.currentTimeMillis(), MILLISECONDS); // Set the clock to
// something recent so
// that the Dynatrace
// library will not
// complain.
// Set the clock to something recent so that the Dynatrace library will not
// complain.
this.clock.add(System.currentTimeMillis(), MILLISECONDS);
this.httpClient = mock(HttpSender.class);

// 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.exporter = createExporter(httpClient);
this.meterRegistry = DynatraceMeterRegistry.builder(config).clock(clock).httpClient(httpClient).build();

SEEN_METADATA.clear();
Expand All @@ -120,27 +102,6 @@ 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, SUBSEQUENT_LOGS_AS_DEBUG), 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);
Expand Down Expand Up @@ -665,66 +626,6 @@ void shouldSendHeadersAndBody() throws Throwable {
}));
}

@Test
void failOnSendShouldHaveProperLogging() throws Throwable {
HttpSender.Request.Builder builder = HttpSender.Request.build(config.uri(), httpClient);
when(httpClient.post(config.uri())).thenReturn(builder);
when(httpClient.send(isA(HttpSender.Request.class))).thenReturn(new HttpSender.Response(500, "simulated"));

meterRegistry.gauge("my.gauge", 1d);
Gauge gauge = meterRegistry.find("my.gauge").gauge();
exporter.export(Collections.singletonList(gauge));

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(), SUBSEQUENT_LOGS_AS_DEBUG), 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: " + expectedException,
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);

// the WarnThenDebugLogger only has one event so far.
assertThat(stackTraceLogger.getLogEvents()).containsExactly(warnThenDebugWarningLog);

// second export
exporter.export(Collections.singletonList(gauge));

// after the second export, the general logger contains the warning log twice
assertThat(logger.getLogEvents().stream().filter(event -> event.equals(expectedExceptionLogMessage)))
.hasSize(2);

// the WarnThenDebugLogger now has two logs.
assertThat(stackTraceLogger.getLogEvents()).containsExactly(warnThenDebugWarningLog, warnThenDebugDebugLog);
}

@Test
void endpointPickedUpBetweenExportsAndChangedPropertiesFile() throws Throwable {
String randomUuid = UUID.randomUUID().toString();
Expand Down Expand Up @@ -1011,47 +912,6 @@ 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, SUBSEQUENT_LOGS_AS_DEBUG), 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()).containsExactly(warnEvent);

// second export
exporter.export(meterRegistry.getMeters());
assertThat(metadataDiscrepancyLogger.getLogEvents()).containsExactly(warnEvent, debugEvent);
}

@Test
void metadataIsNotExportedWhenTurnedOff() {
HttpSender.Request.Builder builder = spy(HttpSender.Request.build(config.uri(), httpClient));
Expand Down

0 comments on commit 4d8cab7

Please sign in to comment.