From 660bf860cc5a1741a18917859eef4b9aab9f9db4 Mon Sep 17 00:00:00 2001 From: Tommy Ludwig <8924140+shakuzen@users.noreply.github.com> Date: Tue, 2 Apr 2024 17:15:47 +0900 Subject: [PATCH] Warn when a MeterFilter is configured after a meter is registered In normal usage we would expect this should not happen, but there is nothing enforcing or encouraging it to not happen. This warns users via logging that it is happening and advises to correct it, if possible. Otherwise, we want to learn about why it is not fixable. The problem with configuring MeterFilters after a Meter has been registered is that such filters will not be applied to previously registered meters. This can result in a mix of metrics with all filters applied and only some filters applied, which is potentially hard to notice. --- gradle/libs.versions.toml | 1 + micrometer-core/build.gradle | 1 + .../core/instrument/MeterRegistry.java | 18 ++++++++ .../core/instrument/MeterRegistryTest.java | 45 ++++++++++++++++++- 4 files changed, 63 insertions(+), 2 deletions(-) diff --git a/gradle/libs.versions.toml b/gradle/libs.versions.toml index 1e56079c88..2aae465d9f 100644 --- a/gradle/libs.versions.toml +++ b/gradle/libs.versions.toml @@ -164,6 +164,7 @@ jsr107 = { module = "org.jsr107.ri:cache-ri-impl", version.ref = "jsr107" } jsr305 = { module = "com.google.code.findbugs:jsr305", version.ref = "jsr305" } junitBom = { module = "org.junit:junit-bom", version.ref = "junit" } junitJupiter = { module = "org.junit.jupiter:junit-jupiter", version.ref = "junit" } +junitLoggingExtention = "com.innoq:junit5-logging-extension:0.2.0" junitPlatformLauncher = { module = "org.junit.platform:junit-platform-launcher", version.ref = "junit-platform" } kafkaClients = { module = "org.apache.kafka:kafka-clients", version.ref = "kafka" } kafkaStreams = { module = "org.apache.kafka:kafka-streams", version.ref = "kafka" } diff --git a/micrometer-core/build.gradle b/micrometer-core/build.gradle index fa70508afd..a1f8fa480f 100644 --- a/micrometer-core/build.gradle +++ b/micrometer-core/build.gradle @@ -156,6 +156,7 @@ dependencies { } // Needed for LogbackMetrics tests testImplementation libs.slf4jApi + testImplementation(libs.junitLoggingExtention) testImplementation 'org.mockito:mockito-core' diff --git a/micrometer-core/src/main/java/io/micrometer/core/instrument/MeterRegistry.java b/micrometer-core/src/main/java/io/micrometer/core/instrument/MeterRegistry.java index bacdd0dd56..8b710cdd1e 100644 --- a/micrometer-core/src/main/java/io/micrometer/core/instrument/MeterRegistry.java +++ b/micrometer-core/src/main/java/io/micrometer/core/instrument/MeterRegistry.java @@ -16,6 +16,8 @@ package io.micrometer.core.instrument; import io.micrometer.common.lang.Nullable; +import io.micrometer.common.util.internal.logging.InternalLogger; +import io.micrometer.common.util.internal.logging.InternalLoggerFactory; import io.micrometer.core.annotation.Incubating; import io.micrometer.core.instrument.Meter.Id; import io.micrometer.core.instrument.config.MeterFilter; @@ -776,6 +778,22 @@ public Config commonTags(String... tags) { * @return This configuration instance. */ public synchronized Config meterFilter(MeterFilter filter) { + if (!meterMap.isEmpty()) { + InternalLogger logger = InternalLoggerFactory.getInstance(MeterRegistry.this.getClass()); + String baseMessage = "A MeterFilter is being configured after a Meter has been registered to this registry. This is unexpected and should be corrected so all MeterFilters are configured before any Meters are registered. If that is not possible or you have a use case where it should be allowed, contact the Micrometer maintainers."; + if (logger.isDebugEnabled()) { + String stackTrace = Arrays.stream(Thread.currentThread().getStackTrace()) + // skip getStackTrace frame and the call within this method + .skip(2) + .map(StackTraceElement::toString) + .collect(Collectors.joining("\n\tat ")); + logger.debug(baseMessage + "\n" + stackTrace); + } + else { + logger.warn(baseMessage + + " Enable DEBUG level on this logger to see a stack trace of the call configuring this MeterFilter."); + } + } MeterFilter[] newFilters = new MeterFilter[filters.length + 1]; System.arraycopy(filters, 0, newFilters, 0, filters.length); newFilters[filters.length] = filter; diff --git a/micrometer-core/src/test/java/io/micrometer/core/instrument/MeterRegistryTest.java b/micrometer-core/src/test/java/io/micrometer/core/instrument/MeterRegistryTest.java index 58abd569e1..db9e6e0b95 100644 --- a/micrometer-core/src/test/java/io/micrometer/core/instrument/MeterRegistryTest.java +++ b/micrometer-core/src/test/java/io/micrometer/core/instrument/MeterRegistryTest.java @@ -15,6 +15,11 @@ */ package io.micrometer.core.instrument; +import ch.qos.logback.classic.Level; +import ch.qos.logback.classic.Logger; +import ch.qos.logback.classic.spi.ILoggingEvent; +import com.innoq.junit.jupiter.logging.Logging; +import com.innoq.junit.jupiter.logging.LoggingEvents; import io.micrometer.core.Issue; import io.micrometer.core.instrument.config.MeterFilter; import io.micrometer.core.instrument.config.MeterFilterReply; @@ -23,12 +28,13 @@ import io.micrometer.core.instrument.noop.NoopCounter; import io.micrometer.core.instrument.noop.NoopTimer; import io.micrometer.core.instrument.simple.SimpleMeterRegistry; +import org.assertj.core.api.InstanceOfAssertFactories; import org.junit.jupiter.api.Test; +import org.slf4j.LoggerFactory; import javax.annotation.Nonnull; -import static org.assertj.core.api.Assertions.assertThat; -import static org.assertj.core.api.Assertions.assertThatThrownBy; +import static org.assertj.core.api.Assertions.*; /** * Tests for {@link MeterRegistry}. @@ -221,4 +227,39 @@ void acceptPercentilesNullOrEmpty() { LongTaskTimer.builder("timer.percentiles.empty").publishPercentiles(new double[] {}).register(registry); } + @Test + void meterRegistrationBeforeMeterFilterConfig(@Logging LoggingEvents logEvents) { + registry.counter("counter"); + registry.config().meterFilter(MeterFilter.commonTags(Tags.of("common", "tag"))); + + assertThat(logEvents.withLevel(Level.DEBUG)).isEmpty(); + assertThat(logEvents.withLevel(Level.WARN)).singleElement() + .extracting(ILoggingEvent::getFormattedMessage, as(InstanceOfAssertFactories.STRING)) + .contains("A MeterFilter is being configured after a Meter has been registered to this registry.") + .doesNotContain("MeterRegistryTest.meterRegistrationBeforeMeterFilterConfig") + .doesNotContain("\tat "); + } + + @Test + void meterRegistrationBeforeMeterFilterConfigWithDebugLogging(@Logging LoggingEvents logEvents) { + Level priorLevel = ((Logger) LoggerFactory.getLogger(SimpleMeterRegistry.class)).getLevel(); + ((Logger) LoggerFactory.getLogger(SimpleMeterRegistry.class)).setLevel(Level.DEBUG); + try { + registry.counter("counter"); + registry.config().meterFilter(MeterFilter.commonTags(Tags.of("common", "tag"))); + + assertThat(logEvents.withLevel(Level.WARN)).isEmpty(); + assertThat(logEvents.withLevel(Level.DEBUG)).singleElement() + .extracting(ILoggingEvent::getFormattedMessage, as(InstanceOfAssertFactories.STRING)) + .contains("A MeterFilter is being configured after a Meter has been registered to this registry.") + // this test method (filter config call site) is in stack trace + .contains("meterRegistrationBeforeMeterFilterConfigWithDebugLogging") + .contains("\tat ") // stack trace output + ; + } + finally { + ((Logger) LoggerFactory.getLogger(SimpleMeterRegistry.class)).setLevel(priorLevel); + } + } + }