Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[dynatrace/v2] reduce log verbosity #5306

Merged
merged 2 commits into from
Jul 17, 2024
Merged

[dynatrace/v2] reduce log verbosity #5306

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
3bcaab3
reduce log verbosity
pirgeo Jul 16, 2024
fbd14d1
move metadata discrepancy logging to debug.
pirgeo Jul 16, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
44 changes: 19 additions & 25 deletions ...eter-registry-dynatrace/src/main/java/io/micrometer/dynatrace/v2/DynatraceExporterV2.java
View file
Open in desktop
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
Open in desktop

This file was deleted.

148 changes: 4 additions & 144 deletions ...-registry-dynatrace/src/test/java/io/micrometer/dynatrace/v2/DynatraceExporterV2Test.java
View file
Open in desktop
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