Remove ThreadLocal usage from LogbackMetrics (#6882)

Before this change, LogbackMetrics used Counter to keep track of the
number of emitted log events by level. This caused issues since there
are cases where incrementing a Counter can result in emitting
log events. Because of this, the MetricsTurboFilter in LogbackMetrics
had a chance to get into an infinite loop since it was triggered by
emitting log events and it incremented a Counter that also emitted
a log event which triggered MetricsTurboFilter again...

The scenario was the following:
1. Somebody emits a log event (e.g.: LOGGER.info("test");)
2. MetricsTurboFilter gets notified about it and increments a Counter
3. Incrementing the Counter triggers emitting another log event
4. MetricsTurboFilter gets notified about it and increments a Counter
...

To fix this issue, a ThreadLocal was used to ignore some of
the log events (the ones that were emitted by incrementing a Counter).

This change removes the ThreadLocal usage and instead of using Counter,
it keeps track of the number of emitted log events using a LongAdder.
Then it uses this LongAdder in a FunctionCounter. It assumes that
LongAdder does not emit any log events that will end up triggering
MetricsTurboFilter again.

Author: jonatan-ivanov

implementations/micrometer-registry-statsd/src/main/java/io/micrometer/statsd/StatsdMeterRegistry.java

@@ -148,13 +148,6 @@ private StatsdMeterRegistry(StatsdConfig config, HierarchicalNameMapper nameMapp
 
         if (config.enabled()) {
             this.sink = processor.sink();
-
-            try {
-                Class.forName("ch.qos.logback.classic.turbo.TurboFilter", false, getClass().getClassLoader());
-                this.sink = new LogbackMetricsSuppressingFluxSink(this.sink);
-            }
-            catch (ClassNotFoundException ignore) {
-            }
             start();
         }
     }

implementations/micrometer-registry-statsd/src/main/java/io/micrometer/statsd/internal/LogbackMetricsSuppressingFluxSink.java

@@ -26,7 +26,11 @@
 /**
  * This is an internal class only for use within Micrometer. This suppresses logback event
  * metrics during Sink operations to avoid infinite loops.
+ *
+ * @deprecated Should not be needed anymore since {@link LogbackMetrics} records logback
+ * events asynchronously and should not get into an infinite loop.
  */
+@Deprecated
 public class LogbackMetricsSuppressingFluxSink implements FluxSink<String> {
 
     private final FluxSink<String> delegate;

micrometer-core/src/main/java/io/micrometer/core/instrument/binder/logging/LogbackMetrics.java

@@ -22,6 +22,7 @@
 import ch.qos.logback.classic.turbo.TurboFilter;
 import ch.qos.logback.core.spi.FilterReply;
 import io.micrometer.core.instrument.Counter;
+import io.micrometer.core.instrument.FunctionCounter;
 import io.micrometer.core.instrument.MeterRegistry;
 import io.micrometer.core.instrument.Tag;
 import io.micrometer.core.instrument.binder.BaseUnits;
@@ -32,6 +33,7 @@
 
 import java.util.HashMap;
 import java.util.Map;
+import java.util.concurrent.atomic.LongAdder;
 
 import static java.util.Collections.emptyList;
 
@@ -41,12 +43,11 @@
  * to an appender will not affect the metrics.
  *
  * @author Jon Schneider
+ * @author Jonatan Ivanov
  */
 @NullMarked
 public class LogbackMetrics implements MeterBinder, AutoCloseable {
 
-    static ThreadLocal<Boolean> ignoreMetrics = new ThreadLocal<>();
-
     private final Iterable<Tag> tags;
 
     private final LoggerContext loggerContext;
@@ -114,20 +115,18 @@ public void bindTo(MeterRegistry registry) {
     }
 
     /**
-     * Used by {@link Counter#increment()} implementations that may cause a logback
-     * logging event to occur. Attempting to instrument that implementation would cause a
-     * {@link StackOverflowError}.
-     * @param r Don't record metrics on logging statements that occur inside of this
-     * runnable.
+     * This method was used by {@link Counter#increment()} implementations that may cause
+     * a logback logging event to occur. Attempting to instrument that implementation used
+     * to cause a {@link StackOverflowError}.
+     * @param r The runnable to execute, previously it also disabled recording metrics on
+     * logging statements that occur inside of this runnable but this is not needed
+     * anymore.
+     * @deprecated Should not be needed anymore since {@link LogbackMetrics} records
+     * logback events asynchronously and should not get into an infinite loop.
      */
+    @Deprecated
     public static void ignoreMetrics(Runnable r) {
-        ignoreMetrics.set(true);
-        try {
-            r.run();
-        }
-        finally {
-            ignoreMetrics.remove();
-        }
+        r.run();
     }
 
     @Override
@@ -148,46 +147,46 @@ class MetricsTurboFilter extends TurboFilter {
 
     private static final String METER_DESCRIPTION = "Number of log events that were enabled by the effective log level";
 
-    private final Counter errorCounter;
+    private final LongAdder errorCount = new LongAdder();
 
-    private final Counter warnCounter;
+    private final LongAdder warnCount = new LongAdder();
 
-    private final Counter infoCounter;
+    private final LongAdder infoCount = new LongAdder();
 
-    private final Counter debugCounter;
+    private final LongAdder debugCount = new LongAdder();
 
-    private final Counter traceCounter;
+    private final LongAdder traceCount = new LongAdder();
 
     MetricsTurboFilter(MeterRegistry registry, Iterable<Tag> tags) {
-        errorCounter = Counter.builder(METER_NAME)
+        FunctionCounter.builder(METER_NAME, errorCount, LongAdder::doubleValue)
             .tags(tags)
             .tags("level", "error")
             .description(METER_DESCRIPTION)
             .baseUnit(BaseUnits.EVENTS)
             .register(registry);
 
-        warnCounter = Counter.builder(METER_NAME)
+        FunctionCounter.builder(METER_NAME, warnCount, LongAdder::doubleValue)
             .tags(tags)
             .tags("level", "warn")
             .description(METER_DESCRIPTION)
             .baseUnit(BaseUnits.EVENTS)
             .register(registry);
 
-        infoCounter = Counter.builder(METER_NAME)
+        FunctionCounter.builder(METER_NAME, infoCount, LongAdder::doubleValue)
             .tags(tags)
             .tags("level", "info")
             .description(METER_DESCRIPTION)
             .baseUnit(BaseUnits.EVENTS)
             .register(registry);
 
-        debugCounter = Counter.builder(METER_NAME)
+        FunctionCounter.builder(METER_NAME, debugCount, LongAdder::doubleValue)
             .tags(tags)
             .tags("level", "debug")
             .description(METER_DESCRIPTION)
             .baseUnit(BaseUnits.EVENTS)
             .register(registry);
 
-        traceCounter = Counter.builder(METER_NAME)
+        FunctionCounter.builder(METER_NAME, traceCount, LongAdder::doubleValue)
             .tags(tags)
             .tags("level", "trace")
             .description(METER_DESCRIPTION)
@@ -209,32 +208,27 @@ public FilterReply decide(Marker marker, Logger logger, Level level, String form
             return FilterReply.NEUTRAL;
         }
 
-        Boolean ignored = LogbackMetrics.ignoreMetrics.get();
-        if (ignored != null && ignored) {
-            return FilterReply.NEUTRAL;
-        }
-
-        LogbackMetrics.ignoreMetrics(() -> recordMetrics(level));
+        recordMetrics(level);
 
         return FilterReply.NEUTRAL;
     }
 
     private void recordMetrics(Level level) {
         switch (level.toInt()) {
             case Level.ERROR_INT:
-                errorCounter.increment();
+                errorCount.increment();
                 break;
             case Level.WARN_INT:
-                warnCounter.increment();
+                warnCount.increment();
                 break;
             case Level.INFO_INT:
-                infoCounter.increment();
+                infoCount.increment();
                 break;
             case Level.DEBUG_INT:
-                debugCounter.increment();
+                debugCount.increment();
                 break;
             case Level.TRACE_INT:
-                traceCounter.increment();
+                traceCount.increment();
                 break;
         }
 

micrometer-core/src/test/java/io/micrometer/core/instrument/binder/logging/LogbackMetricsTest.java

@@ -19,10 +19,7 @@
 import ch.qos.logback.classic.Logger;
 import ch.qos.logback.classic.LoggerContext;
 import io.micrometer.core.Issue;
-import io.micrometer.core.instrument.Counter;
-import io.micrometer.core.instrument.Meter;
-import io.micrometer.core.instrument.MeterRegistry;
-import io.micrometer.core.instrument.MockClock;
+import io.micrometer.core.instrument.*;
 import io.micrometer.core.instrument.cumulative.CumulativeCounter;
 import io.micrometer.core.instrument.simple.SimpleConfig;
 import io.micrometer.core.instrument.simple.SimpleMeterRegistry;
@@ -32,8 +29,6 @@
 import org.junit.jupiter.api.Test;
 import org.slf4j.LoggerFactory;
 
-import java.util.concurrent.atomic.AtomicInteger;
-
 import static java.util.Collections.emptyList;
 import static org.assertj.core.api.Assertions.assertThat;
 
@@ -62,7 +57,7 @@ void closeLogbackMetrics() {
 
     @Test
     void logbackLevelMetrics() {
-        assertThat(registry.get("logback.events").counter().count()).isEqualTo(0.0);
+        assertThat(registry.get("logback.events").functionCounter().count()).isEqualTo(0.0);
 
         // tag::example[]
         logger.setLevel(Level.INFO);
@@ -71,8 +66,8 @@ void logbackLevelMetrics() {
         logger.error("error");
         logger.debug("debug"); // shouldn't record a metric
 
-        assertThat(registry.get("logback.events").tags("level", "warn").counter().count()).isEqualTo(1.0);
-        assertThat(registry.get("logback.events").tags("level", "debug").counter().count()).isEqualTo(0.0);
+        assertThat(registry.get("logback.events").tags("level", "warn").functionCounter().count()).isEqualTo(1.0);
+        assertThat(registry.get("logback.events").tags("level", "debug").functionCounter().count()).isEqualTo(0.0);
         // end::example[]
     }
 
@@ -81,7 +76,7 @@ void logbackLevelMetrics() {
     void isLevelEnabledDoesntContributeToCounts() {
         logger.isErrorEnabled();
 
-        assertThat(registry.get("logback.events").tags("level", "error").counter().count()).isEqualTo(0.0);
+        assertThat(registry.get("logback.events").tags("level", "error").functionCounter().count()).isEqualTo(0.0);
     }
 
     @Issue("#411, #3623")
@@ -92,7 +87,7 @@ void ignoringLogMetricsInsideCounters() {
             logbackMetrics.bindTo(registry);
             LoggerFactory.getLogger("test").info("This should be counted once");
         }
-        assertThat(registry.get("logback.events").tags("level", "info").counter().count()).isOne();
+        assertThat(registry.get("logback.events").tags("level", "info").functionCounter().count()).isOne();
     }
 
     @Issue("#421")
@@ -122,64 +117,13 @@ void reAddFilterToLoggerContextAfterReset() {
         assertThat(loggerContext.getTurboFilterList()).hasSize(1);
     }
 
-    @Issue("#2270")
-    @Test
-    void resetIgnoreMetricsWhenRunnableThrows() {
-        Counter infoLogCounter = registry.get("logback.events").tag("level", "info").counter();
-        logger.info("hi");
-        assertThat(infoLogCounter.count()).isEqualTo(1);
-        try {
-            LogbackMetrics.ignoreMetrics(() -> {
-                throw new RuntimeException();
-            });
-        }
-        catch (RuntimeException ignore) {
-        }
-        logger.info("hi");
-        assertThat(infoLogCounter.count()).isEqualTo(2);
-    }
-
-    @Issue("#3891")
-    @Test
-    void threadLocalNotUsedWhenLogLevelNotEnabled() {
-        ThreadLocal<Boolean> priorThreadLocal = LogbackMetrics.ignoreMetrics;
-        AtomicInteger interactions = new AtomicInteger();
-        try {
-            LogbackMetrics.ignoreMetrics = new ThreadLocal<Boolean>() {
-                @Override
-                public Boolean get() {
-                    interactions.incrementAndGet();
-                    return super.get();
-                }
-
-                @Override
-                public void set(Boolean value) {
-                    interactions.incrementAndGet();
-                    super.set(value);
-                }
-
-                @Override
-                public void remove() {
-                    interactions.incrementAndGet();
-                    super.remove();
-                }
-            };
-            logger.trace("trace");
-            logger.isErrorEnabled();
-            assertThat(interactions.get()).isZero();
-        }
-        finally {
-            LogbackMetrics.ignoreMetrics = priorThreadLocal;
-        }
-    }
-
     @Test
     @Issue("#4404")
     void slf4j2FluentApiIncrementsCounter() {
         org.slf4j.Logger logger = LoggerFactory.getLogger("test");
         logger.atWarn().setMessage("test warn log with fluent builder").log();
 
-        assertThat(registry.get("logback.events").tags("level", "warn").counter().count()).isEqualTo(1.0);
+        assertThat(registry.get("logback.events").tags("level", "warn").functionCounter().count()).isEqualTo(1.0);
     }
 
     @NullMarked

samples/micrometer-samples-jersey3/src/test/java/io/micrometer/samples/jersey3/Jersey3Test.java

@@ -70,7 +70,7 @@ void loggingMetricsAreCounted() {
             logbackMetrics.bindTo(registry);
             InternalLogger logger = InternalLoggerFactory.getInstance(Jersey3Test.class);
             logger.info("test");
-            assertThat(registry.get("logback.events").tags("level", "info").counter().count()).isPositive();
+            assertThat(registry.get("logback.events").tags("level", "info").functionCounter().count()).isPositive();
         }
     }