From e73ead819da10a89c692b4f504067a9b5043528b Mon Sep 17 00:00:00 2001 From: Patrik Ivarsson <83230533+pativa@users.noreply.github.com> Date: Tue, 28 Jan 2025 04:33:25 +0100 Subject: [PATCH 1/4] Add test verifying log42j updateLoggers is called (#5822) This will ensure it is not removed in the future because it is needed even if it is not apparent. See gh-872 and gh-867 for related history. Signed-off-by: Patrik Ivarsson --- .../binder/logging/Log4j2MetricsTest.java | 22 +++++++++++++++++++ 1 file changed, 22 insertions(+) diff --git a/micrometer-core/src/test/java/io/micrometer/core/instrument/binder/logging/Log4j2MetricsTest.java b/micrometer-core/src/test/java/io/micrometer/core/instrument/binder/logging/Log4j2MetricsTest.java index a2dcdb18da..29d4746b46 100644 --- a/micrometer-core/src/test/java/io/micrometer/core/instrument/binder/logging/Log4j2MetricsTest.java +++ b/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"); From cb2957d949883e407380b13306ee0443460107ac Mon Sep 17 00:00:00 2001 From: Jonatan Ivanov Date: Tue, 28 Jan 2025 15:21:19 -0800 Subject: [PATCH 2/4] Back-port LoggingMeterRegistry tests Closes gh-5833 --- .../logging/LoggingMeterRegistryTest.java | 224 ++++++++++++++++-- 1 file changed, 207 insertions(+), 17 deletions(-) diff --git a/micrometer-core/src/test/java/io/micrometer/core/instrument/logging/LoggingMeterRegistryTest.java b/micrometer-core/src/test/java/io/micrometer/core/instrument/logging/LoggingMeterRegistryTest.java index 72fb2d42f2..1c50109c67 100644 --- a/micrometer-core/src/test/java/io/micrometer/core/instrument/logging/LoggingMeterRegistryTest.java +++ b/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,28 +38,42 @@ * @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 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); @@ -61,11 +81,11 @@ void providedSinkFromConstructorShouldBeUsed() { @Test void providedSinkFromConstructorShouldBeUsedWithDefaults() { - String expectedString = "my.gauage{tag-1=tag-2} value=1"; + String expectedString = "my.gauge{key1=test} value=1"; AtomicReference 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,175 @@ 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 milliseconds 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 milliseconds/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 milliseconds/s mean="); + } + + private static class TestConfig implements LoggingRegistryConfig { + + private final Map 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 logs; + + RecordingLoggingMeterRegistry(LoggingRegistryConfig config, Clock clock) { + this(config, clock, new ArrayList<>()); + } + + private RecordingLoggingMeterRegistry(LoggingRegistryConfig config, Clock clock, List logs) { + super(config, clock, logs::add); + this.logs = logs; + } + + List getLogs() { + return logs; + } + + } + } From 5156f798f3f93038c7b9f8ea75d0f14284b51c33 Mon Sep 17 00:00:00 2001 From: Jonatan Ivanov Date: Tue, 28 Jan 2025 15:29:39 -0800 Subject: [PATCH 3/4] Fix unit discrepancy between Timer and FunctionTimer in LoggingMeterRegistry Closes gh-5816 --- .../core/instrument/logging/LoggingMeterRegistry.java | 2 +- .../core/instrument/logging/LoggingMeterRegistryTest.java | 5 ++--- 2 files changed, 3 insertions(+), 4 deletions(-) diff --git a/micrometer-core/src/main/java/io/micrometer/core/instrument/logging/LoggingMeterRegistry.java b/micrometer-core/src/main/java/io/micrometer/core/instrument/logging/LoggingMeterRegistry.java index 6cbea5b75b..d2d408e143 100644 --- a/micrometer-core/src/main/java/io/micrometer/core/instrument/logging/LoggingMeterRegistry.java +++ b/micrometer-core/src/main/java/io/micrometer/core/instrument/logging/LoggingMeterRegistry.java @@ -162,7 +162,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))); }); diff --git a/micrometer-core/src/test/java/io/micrometer/core/instrument/logging/LoggingMeterRegistryTest.java b/micrometer-core/src/test/java/io/micrometer/core/instrument/logging/LoggingMeterRegistryTest.java index 1c50109c67..7dc34b02bc 100644 --- a/micrometer-core/src/test/java/io/micrometer/core/instrument/logging/LoggingMeterRegistryTest.java +++ b/micrometer-core/src/test/java/io/micrometer/core/instrument/logging/LoggingMeterRegistryTest.java @@ -271,8 +271,7 @@ 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 milliseconds/s mean=1s"); + assertThat(recordingRegistry.getLogs()).containsExactly("my.function-timer{} throughput=0.5/s mean=1s"); } @Test @@ -319,7 +318,7 @@ void publishShouldPrintMetersWithZeroStepCountWhenLogsInactiveIsEnabled() { 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 milliseconds/s mean="); + "my.function-counter{} throughput=0/s", "my.function-timer{} throughput=0/s mean="); } private static class TestConfig implements LoggingRegistryConfig { From 04eef90adebf3c0977c7d0c1a6aa815d97c0c0f4 Mon Sep 17 00:00:00 2001 From: Jonatan Ivanov Date: Tue, 28 Jan 2025 15:46:02 -0800 Subject: [PATCH 4/4] Fix LongTaskTimer output for LoggingMeterRegistryTest Closes gh-5834 --- .../core/instrument/logging/LoggingMeterRegistry.java | 3 ++- .../core/instrument/logging/LoggingMeterRegistryTest.java | 2 +- 2 files changed, 3 insertions(+), 2 deletions(-) diff --git a/micrometer-core/src/main/java/io/micrometer/core/instrument/logging/LoggingMeterRegistry.java b/micrometer-core/src/main/java/io/micrometer/core/instrument/logging/LoggingMeterRegistry.java index d2d408e143..2a6dae114f 100644 --- a/micrometer-core/src/main/java/io/micrometer/core/instrument/logging/LoggingMeterRegistry.java +++ b/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()); diff --git a/micrometer-core/src/test/java/io/micrometer/core/instrument/logging/LoggingMeterRegistryTest.java b/micrometer-core/src/test/java/io/micrometer/core/instrument/logging/LoggingMeterRegistryTest.java index 7dc34b02bc..54219122ab 100644 --- a/micrometer-core/src/test/java/io/micrometer/core/instrument/logging/LoggingMeterRegistryTest.java +++ b/micrometer-core/src/test/java/io/micrometer/core/instrument/logging/LoggingMeterRegistryTest.java @@ -228,7 +228,7 @@ void publishShouldPrintActiveCountAndDurationWhenMeterIsLongTaskTimer() { IntStream.rangeClosed(1, 30).forEach(t -> timer.start()); clock.add(config.step()); recordingRegistry.publish(); - assertThat(recordingRegistry.getLogs()).containsExactly("my.ltt{} active=30 milliseconds duration=30m"); + assertThat(recordingRegistry.getLogs()).containsExactly("my.ltt{} active=30 duration=30m"); } @Test