Merge branch '1.13.x' into 1.14.x

micrometer-core/src/main/java/io/micrometer/core/instrument/logging/LoggingMeterRegistry.java

@@ -42,6 +42,7 @@
 import java.util.stream.StreamSupport;
 
 import static io.micrometer.core.instrument.util.DoubleFormat.decimalOrNan;
+import static io.micrometer.core.instrument.util.DoubleFormat.wholeOrDecimal;
 import static java.util.stream.Collectors.joining;
 
 /**
@@ -146,7 +147,7 @@ protected void publish() {
                     int activeTasks = longTaskTimer.activeTasks();
                     if (!config.logInactive() && activeTasks == 0)
                         return;
-                    loggingSink.accept(print.id() + " active=" + print.value(activeTasks) + " duration="
+                    loggingSink.accept(print.id() + " active=" + wholeOrDecimal(activeTasks) + " duration="
                             + print.time(longTaskTimer.duration(getBaseTimeUnit())));
                 }, timeGauge -> {
                     double value = timeGauge.value(getBaseTimeUnit());
@@ -162,7 +163,7 @@ protected void publish() {
                     double count = timer.count();
                     if (!config.logInactive() && count == 0)
                         return;
-                    loggingSink.accept(print.id() + " throughput=" + print.rate(count) + " mean="
+                    loggingSink.accept(print.id() + " throughput=" + print.unitlessRate(count) + " mean="
                             + print.time(timer.mean(getBaseTimeUnit())));
                 }, meter -> loggingSink.accept(writeMeter(meter, print)));
             });

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

@@ -36,6 +36,7 @@
 import java.io.IOException;
 import java.time.Duration;
 import java.util.Iterator;
+import java.util.concurrent.atomic.AtomicInteger;
 
 import static java.util.Collections.emptyList;
 import static org.assertj.core.api.Assertions.assertThat;
@@ -186,6 +187,27 @@ void asyncLogShouldNotBeDuplicated() throws IOException {
             .until(() -> registry.get("log4j2.events").tags("level", "info").counter().count() == 3);
     }
 
+    // see https://github.com/micrometer-metrics/micrometer/pull/872
+    @Test
+    void shouldTriggerLoggersUpdateOnOpenAndClose() {
+        LoggerContext context = new LoggerContext("test");
+
+        AtomicInteger reconfigureCount = new AtomicInteger();
+        context.addPropertyChangeListener(event -> {
+            if (event.getNewValue() instanceof Configuration) {
+                reconfigureCount.incrementAndGet();
+            }
+        });
+
+        Log4j2Metrics metrics = new Log4j2Metrics(emptyList(), context);
+
+        assertThat(reconfigureCount.get()).isEqualTo(0);
+        metrics.bindTo(registry);
+        assertThat(reconfigureCount.get()).isEqualTo(1);
+        metrics.close();
+        assertThat(reconfigureCount.get()).isEqualTo(2);
+    }
+
     @Test
     void metricsFilterIsReused() {
         LoggerContext loggerContext = new LoggerContext("test");

micrometer-core/src/test/java/io/micrometer/core/instrument/logging/LoggingMeterRegistryTest.java

@@ -15,15 +15,21 @@
  */
 package io.micrometer.core.instrument.logging;
 
+import com.google.common.util.concurrent.AtomicDouble;
 import io.micrometer.core.instrument.*;
+import io.micrometer.core.instrument.Meter.Type;
 import io.micrometer.core.instrument.binder.BaseUnits;
+import org.junit.jupiter.api.BeforeEach;
 import org.junit.jupiter.api.Test;
 
-import java.util.Arrays;
-import java.util.Collections;
+import java.util.*;
 import java.util.concurrent.atomic.AtomicInteger;
 import java.util.concurrent.atomic.AtomicReference;
+import java.util.stream.IntStream;
 
+import static java.util.Collections.emptyList;
+import static java.util.concurrent.TimeUnit.MILLISECONDS;
+import static java.util.concurrent.TimeUnit.SECONDS;
 import static org.assertj.core.api.Assertions.assertThat;
 
 /**
@@ -32,40 +38,54 @@
  * @author Jon Schneider
  * @author Johnny Lim
  * @author Matthieu Borgraeve
+ * @author Jonatan Ivanov
  */
 class LoggingMeterRegistryTest {
 
-    private final LoggingMeterRegistry registry = new LoggingMeterRegistry();
+    private final MockClock clock = new MockClock();
+
+    private TestConfig config;
+
+    private LoggingMeterRegistry registry;
+
+    private RecordingLoggingMeterRegistry recordingRegistry;
+
+    @BeforeEach
+    void setUp() {
+        config = new TestConfig();
+        registry = new LoggingMeterRegistry();
+        recordingRegistry = new RecordingLoggingMeterRegistry(config, clock);
+    }
 
     @Test
     void defaultMeterIdPrinter() {
         LoggingMeterRegistry registry = LoggingMeterRegistry.builder(LoggingRegistryConfig.DEFAULT).build();
-        Counter counter = registry.counter("my.gauage", "tag-1", "tag-2");
+        Counter counter = registry.counter("my.counter", "key1", "test");
         LoggingMeterRegistry.Printer printer = registry.new Printer(counter);
 
-        assertThat(printer.id()).isEqualTo("my.gauage{tag-1=tag-2}");
+        assertThat(printer.id()).isEqualTo("my.counter{key1=test}");
     }
 
     @Test
     void providedSinkFromConstructorShouldBeUsed() {
-        String expectedString = "my.gauage{tag-1=tag-2} value=1";
+        String expectedString = "my.gauge{key1=test} value=1";
         AtomicReference<String> actual = new AtomicReference<>();
         AtomicInteger gaugeValue = new AtomicInteger(1);
         LoggingMeterRegistry registry = new LoggingMeterRegistry(LoggingRegistryConfig.DEFAULT, Clock.SYSTEM,
                 actual::set);
-        registry.gauge("my.gauage", Tags.of("tag-1", "tag-2"), gaugeValue);
+        registry.gauge("my.gauge", Tags.of("key1", "test"), gaugeValue);
 
         registry.publish();
         assertThat(actual.get()).isEqualTo(expectedString);
     }
 
     @Test
     void providedSinkFromConstructorShouldBeUsedWithDefaults() {
-        String expectedString = "my.gauage{tag-1=tag-2} value=1";
+        String expectedString = "my.gauge{key1=test} value=1";
         AtomicReference<String> actual = new AtomicReference<>();
         AtomicInteger gaugeValue = new AtomicInteger(1);
         LoggingMeterRegistry registry = new LoggingMeterRegistry(actual::set);
-        registry.gauge("my.gauage", Tags.of("tag-1", "tag-2"), gaugeValue);
+        registry.gauge("my.gauge", Tags.of("key1", "test"), gaugeValue);
 
         registry.publish();
         assertThat(actual.get()).isEqualTo(expectedString);
@@ -76,10 +96,10 @@ void customMeterIdPrinter() {
         LoggingMeterRegistry registry = LoggingMeterRegistry.builder(LoggingRegistryConfig.DEFAULT)
             .meterIdPrinter(meter -> meter.getId().getName())
             .build();
-        Counter counter = registry.counter("my.gauage", "tag-1", "tag-2");
+        Counter counter = registry.counter("my.counter", "key1", "value");
         LoggingMeterRegistry.Printer printer = registry.new Printer(counter);
 
-        assertThat(printer.id()).isEqualTo("my.gauage");
+        assertThat(printer.id()).isEqualTo("my.counter");
     }
 
     @Test
@@ -109,23 +129,25 @@ void time() {
     }
 
     @Test
-    void writeMeterUnitlessValue() {
-        final String expectedResult = "meter.1{} value=0";
+    void writeMeterUnitLessValue() {
+        String expectedResult = "meter.1{} value=0, throughput=0.5/s";
 
         Measurement m1 = new Measurement(() -> 0d, Statistic.VALUE);
-        Meter meter = Meter.builder("meter.1", Meter.Type.OTHER, Collections.singletonList(m1)).register(registry);
+        Measurement m2 = new Measurement(() -> 30d, Statistic.COUNT);
+        Meter meter = Meter.builder("meter.1", Meter.Type.OTHER, List.of(m1, m2)).register(registry);
         LoggingMeterRegistry.Printer printer = registry.new Printer(meter);
         assertThat(registry.writeMeter(meter, printer)).isEqualTo(expectedResult);
     }
 
     @Test
     void writeMeterMultipleValues() {
-        final String expectedResult = "sheepWatch{color=black} value=5 sheep, max=1023 sheep, total=1.1s";
+        String expectedResult = "sheepWatch{color=black} value=5 sheep, max=1023 sheep, total=1.1s, throughput=0.5 sheep/s";
 
         Measurement m1 = new Measurement(() -> 5d, Statistic.VALUE);
         Measurement m2 = new Measurement(() -> 1023d, Statistic.MAX);
         Measurement m3 = new Measurement(() -> 1100d, Statistic.TOTAL_TIME);
-        Meter meter = Meter.builder("sheepWatch", Meter.Type.OTHER, Arrays.asList(m1, m2, m3))
+        Measurement m4 = new Measurement(() -> 30d, Statistic.COUNT);
+        Meter meter = Meter.builder("sheepWatch", Meter.Type.OTHER, List.of(m1, m2, m3, m4))
             .tag("color", "black")
             .description("Meter for shepherds.")
             .baseUnit("sheep")
@@ -136,7 +158,7 @@ void writeMeterMultipleValues() {
 
     @Test
     void writeMeterByteValues() {
-        final String expectedResult = "bus-throughput{} throughput=5 B/s, value=64 B, value=2.125 KiB, value=8 MiB, value=1 GiB";
+        String expectedResult = "bus-throughput{} throughput=5 B/s, value=64 B, value=2.125 KiB, value=8 MiB, value=1 GiB";
 
         Measurement m1 = new Measurement(() -> 300d, Statistic.COUNT);
         Measurement m2 = new Measurement(() -> (double) (1 << 6), Statistic.VALUE);
@@ -154,6 +176,7 @@ void writeMeterByteValues() {
     void printerValueWhenGaugeIsNaNShouldPrintNaN() {
         registry.gauge("my.gauge", Double.NaN);
         Gauge gauge = registry.find("my.gauge").gauge();
+        assertThat(gauge).isNotNull();
         LoggingMeterRegistry.Printer printer = registry.new Printer(gauge);
         assertThat(printer.value(Double.NaN)).isEqualTo("NaN");
     }
@@ -162,8 +185,174 @@ void printerValueWhenGaugeIsNaNShouldPrintNaN() {
     void printerValueWhenGaugeIsInfinityShouldPrintInfinity() {
         registry.gauge("my.gauge", Double.POSITIVE_INFINITY);
         Gauge gauge = registry.find("my.gauge").gauge();
+        assertThat(gauge).isNotNull();
         LoggingMeterRegistry.Printer printer = registry.new Printer(gauge);
         assertThat(printer.value(Double.POSITIVE_INFINITY)).isEqualTo("∞");
     }
 
+    @Test
+    void publishShouldPrintDeltaCountAndThroughputWithBaseUnitWhenMeterIsCounter() {
+        Counter.builder("my.counter").baseUnit("sheep").register(recordingRegistry).increment(30);
+        clock.add(config.step());
+        recordingRegistry.publish();
+        assertThat(recordingRegistry.getLogs()).containsExactly("my.counter{} throughput=0.5 sheep/s");
+    }
+
+    @Test
+    void publishShouldPrintDeltaCountAsDecimalWhenMeterIsCounterAndCountIsDecimal() {
+        recordingRegistry.counter("my.counter").increment(0.5);
+        clock.add(config.step());
+        recordingRegistry.publish();
+        assertThat(recordingRegistry.getLogs()).containsExactly("my.counter{} throughput=0.008333/s");
+    }
+
+    @Test
+    void publishShouldPrintValueWhenMeterIsGauge() {
+        Gauge.builder("my.gauge", () -> 100).baseUnit("C").register(recordingRegistry);
+        recordingRegistry.publish();
+        assertThat(recordingRegistry.getLogs()).containsExactly("my.gauge{} value=100 C");
+    }
+
+    @Test
+    void publishShouldPrintDeltaCountAndThroughputWhenMeterIsTimer() {
+        var timer = recordingRegistry.timer("my.timer");
+        IntStream.rangeClosed(1, 30).forEach(t -> timer.record(1, SECONDS));
+        clock.add(config.step());
+        recordingRegistry.publish();
+        assertThat(recordingRegistry.getLogs()).containsExactly("my.timer{} throughput=0.5/s mean=1s max=1s");
+    }
+
+    @Test
+    void publishShouldPrintActiveCountAndDurationWhenMeterIsLongTaskTimer() {
+        var timer = recordingRegistry.more().longTaskTimer("my.ltt");
+        IntStream.rangeClosed(1, 30).forEach(t -> timer.start());
+        clock.add(config.step());
+        recordingRegistry.publish();
+        assertThat(recordingRegistry.getLogs()).containsExactly("my.ltt{} active=30 duration=30m");
+    }
+
+    @Test
+    void publishShouldPrintValueWhenMeterIsTimeGauge() {
+        recordingRegistry.more().timeGauge("my.time-gauge", Tags.empty(), this, MILLISECONDS, x -> 100);
+        clock.add(config.step());
+        recordingRegistry.publish();
+        assertThat(recordingRegistry.getLogs()).containsExactly("my.time-gauge{} value=0.1s");
+    }
+
+    @Test
+    void publishShouldPrintDeltaCountAndThroughputWhenMeterIsSummary() {
+        var summary = recordingRegistry.summary("my.summary");
+        IntStream.rangeClosed(1, 30).forEach(t -> summary.record(1));
+        clock.add(config.step());
+        recordingRegistry.publish();
+        assertThat(recordingRegistry.getLogs()).containsExactly("my.summary{} throughput=0.5/s mean=1 max=1");
+    }
+
+    @Test
+    void publishShouldPrintDeltaCountAndThroughputWithBaseUnitWhenMeterIsFunctionCounter() {
+        FunctionCounter.builder("my.function-counter", new AtomicDouble(), d -> 30)
+            .baseUnit("sheep")
+            .register(recordingRegistry);
+        clock.add(config.step());
+        recordingRegistry.publish();
+        assertThat(recordingRegistry.getLogs()).containsExactly("my.function-counter{} throughput=0.5 sheep/s");
+    }
+
+    @Test
+    void publishShouldPrintDeltaCountAsDecimalWhenMeterIsFunctionCounterAndCountIsDecimal() {
+        recordingRegistry.more().counter("my.function-counter", emptyList(), new AtomicDouble(), d -> 0.5);
+        clock.add(config.step());
+        recordingRegistry.publish();
+        assertThat(recordingRegistry.getLogs()).containsExactly("my.function-counter{} throughput=0.008333/s");
+    }
+
+    @Test
+    void publishShouldPrintDeltaCountAndThroughputWhenMeterIsFunctionTimer() {
+        recordingRegistry.more().timer("my.function-timer", emptyList(), new AtomicDouble(), d -> 30, d -> 30, SECONDS);
+        clock.add(config.step());
+        recordingRegistry.publish();
+        assertThat(recordingRegistry.getLogs()).containsExactly("my.function-timer{} throughput=0.5/s mean=1s");
+    }
+
+    @Test
+    void publishShouldPrintValueWhenMeterIsGeneric() {
+        Meter.builder("my.meter", Type.OTHER, List.of(new Measurement(() -> 42.0, Statistic.UNKNOWN)))
+            .register(recordingRegistry);
+        recordingRegistry.publish();
+        assertThat(recordingRegistry.getLogs()).containsExactly("my.meter{} unknown=42");
+    }
+
+    @Test
+    void publishShouldNotPrintAnythingWhenRegistryIsDisabled() {
+        config.set("enabled", "false");
+        recordingRegistry.counter("my.counter").increment();
+        clock.add(config.step());
+        recordingRegistry.publish();
+        assertThat(recordingRegistry.getMeters()).hasSize(1);
+        assertThat(recordingRegistry.getLogs()).isEmpty();
+    }
+
+    @Test
+    void publishShouldNotPrintAnythingWhenStepCountIsZeroAndLogsInactiveIsDisabled() {
+        recordingRegistry.counter("my.counter");
+        recordingRegistry.timer("my.timer");
+        recordingRegistry.summary("my.summary");
+        recordingRegistry.more().counter("my.function-counter", emptyList(), new AtomicDouble(), d -> 0);
+        recordingRegistry.more().timer("my.function-timer", emptyList(), new AtomicDouble(), d -> 0, d -> 0, SECONDS);
+        clock.add(config.step());
+        recordingRegistry.publish();
+        assertThat(recordingRegistry.getMeters()).hasSize(5);
+        assertThat(recordingRegistry.getLogs()).isEmpty();
+    }
+
+    @Test
+    void publishShouldPrintMetersWithZeroStepCountWhenLogsInactiveIsEnabled() {
+        config.set("logInactive", "true");
+        recordingRegistry.counter("my.counter");
+        recordingRegistry.timer("my.timer");
+        recordingRegistry.summary("my.summary");
+        recordingRegistry.more().counter("my.function-counter", emptyList(), new AtomicDouble(), d -> 0);
+        recordingRegistry.more().timer("my.function-timer", emptyList(), new AtomicDouble(), d -> 0, d -> 0, SECONDS);
+        clock.add(config.step());
+        recordingRegistry.publish();
+        assertThat(recordingRegistry.getMeters()).hasSize(5);
+        assertThat(recordingRegistry.getLogs()).containsExactlyInAnyOrder("my.counter{} throughput=0/s",
+                "my.timer{} throughput=0/s mean= max=", "my.summary{} throughput=0/s mean=0 max=0",
+                "my.function-counter{} throughput=0/s", "my.function-timer{} throughput=0/s mean=");
+    }
+
+    private static class TestConfig implements LoggingRegistryConfig {
+
+        private final Map<String, String> keys = new HashMap<>();
+
+        @Override
+        public String get(String key) {
+            return keys.get(key);
+        }
+
+        public void set(String key, String value) {
+            keys.put(prefix() + "." + key, value);
+        }
+
+    }
+
+    private static class RecordingLoggingMeterRegistry extends LoggingMeterRegistry {
+
+        private final List<String> logs;
+
+        RecordingLoggingMeterRegistry(LoggingRegistryConfig config, Clock clock) {
+            this(config, clock, new ArrayList<>());
+        }
+
+        private RecordingLoggingMeterRegistry(LoggingRegistryConfig config, Clock clock, List<String> logs) {
+            super(config, clock, logs::add);
+            this.logs = logs;
+        }
+
+        List<String> getLogs() {
+            return logs;
+        }
+
+    }
+
 }