Merge branch '1.9.x' into 1.10.x

Author: shakuzen

benchmarks/benchmarks-core/build.gradle

@@ -14,12 +14,15 @@ dependencies {
 
     jmh 'org.openjdk.jmh:jmh-core:latest.release'
 
+    jmh 'ch.qos.logback:logback-classic'
+
     // Nebula doesn't like having jmhAnnotationProcessor without jmh so we just add it twice.
     jmh 'org.openjdk.jmh:jmh-generator-annprocess:latest.release'
     jmhAnnotationProcessor 'org.openjdk.jmh:jmh-generator-annprocess:latest.release'
 }
 
 jmh {
+    jmhVersion = '1.36'
     fork = 1
     warmupIterations = 1
     iterations = 1

benchmarks/benchmarks-core/gradle.lockfile

@@ -0,0 +1,67 @@
+/*
+ * Copyright 2023 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.benchmark.core;
+
+import io.micrometer.core.instrument.MeterRegistry;
+import io.micrometer.core.instrument.binder.logging.LogbackMetrics;
+import io.micrometer.core.instrument.simple.SimpleMeterRegistry;
+import org.openjdk.jmh.annotations.*;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
+import java.util.concurrent.TimeUnit;
+
+@Fork(1)
+@Measurement(iterations = 2)
+@Warmup(iterations = 2)
+@BenchmarkMode(Mode.SampleTime)
+@OutputTimeUnit(TimeUnit.MICROSECONDS)
+@State(Scope.Benchmark)
+public class LogbackMetricsBenchmark {
+
+    Logger logger;
+
+    @Param({ "false", "true" })
+    boolean registerLogbackMetrics;
+
+    MeterRegistry meterRegistry;
+
+    LogbackMetrics logbackMetrics;
+
+    @Setup
+    public void setup() {
+        meterRegistry = new SimpleMeterRegistry();
+        if (registerLogbackMetrics) {
+            logbackMetrics = new LogbackMetrics();
+            logbackMetrics.bindTo(meterRegistry);
+        }
+
+        logger = LoggerFactory.getLogger(LogbackMetricsBenchmark.class);
+    }
+
+    @TearDown
+    public void teardown() throws Exception {
+        if (logbackMetrics != null) {
+            logbackMetrics.close();
+        }
+    }
+
+    @Benchmark
+    public void logSomething() {
+        logger.info("benchmark logging");
+    }
+
+}

benchmarks/benchmarks-core/src/jmh/java/io/micrometer/benchmark/core/LogbackMetricsBenchmark.java

@@ -16,6 +16,7 @@
 	<suppress checks="JavadocPackageCheck" files="[\\/]src[\\/]test[\\/].*" />
 
 	<suppress id="SLF4JIllegalImportCheck" files="implementations[\\/].+" />
+	<suppress id="SLF4JIllegalImportCheck" files="benchmarks[\\/].+" />
 
 	<suppress id="sysout" files="ClearCustomMetricDescriptors.java"/>
 	<suppress id="sysout" files="HttpSender.java"/>

config/checkstyle/checkstyle-suppressions.xml

@@ -185,8 +185,14 @@ public FilterReply decide(Marker marker, Logger logger, Level level, String form
             return FilterReply.NEUTRAL;
         }
 
-        // cannot use logger.isEnabledFor(level), as it would cause a StackOverflowError
-        // by calling this filter again!
+        LogbackMetrics.ignoreMetrics(() -> recordMetrics(logger, level));
+
+        return FilterReply.NEUTRAL;
+    }
+
+    private void recordMetrics(Logger logger, Level level) {
+        // Calling logger.isEnabledFor(level) might be sub-optimal since it cals this
+        // filter again. This behavior caused a StackOverflowError in the past.
         if (level.isGreaterOrEqual(logger.getEffectiveLevel())) {
             switch (level.toInt()) {
                 case Level.ERROR_INT:
@@ -205,9 +211,9 @@ public FilterReply decide(Marker marker, Logger logger, Level level, String form
                     traceCounter.increment();
                     break;
             }
+
         }
 
-        return FilterReply.NEUTRAL;
     }
 
 }

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

@@ -78,15 +78,15 @@ void isLevelEnabledDoesntContributeToCounts() {
         assertThat(registry.get("logback.events").tags("level", "error").counter().count()).isEqualTo(0.0);
     }
 
-    @Issue("#411")
+    @Issue("#411, #3623")
     @Test
     void ignoringLogMetricsInsideCounters() {
         registry = new LoggingCounterMeterRegistry();
         try (LogbackMetrics logbackMetrics = new LogbackMetrics()) {
             logbackMetrics.bindTo(registry);
-            registry.counter("my.counter").increment();
+            LoggerFactory.getLogger("test").info("This should be counted once");
         }
-        assertThat(registry.get("logback.events").tags("level", "info").counter().count()).isZero();
+        assertThat(registry.get("logback.events").tags("level", "info").counter().count()).isOne();
     }
 
     @Issue("#421")
@@ -153,10 +153,8 @@ private static class LoggingCounter extends CumulativeCounter {
 
         @Override
         public void increment() {
-            LogbackMetrics.ignoreMetrics(() -> {
-                logger.info("beep");
-                super.increment();
-            });
+            logger.info("beep"); // this is necessary to test gh-3623
+            super.increment();
         }
 
     }