From fc2913f80aa2f2846767d790b56108627ae76661 Mon Sep 17 00:00:00 2001 From: Patrik Ivarsson Date: Thu, 23 Jan 2025 21:26:04 +0100 Subject: [PATCH 1/5] Rebind log4j2 metrics if configuration is changed * Use `PropertyChangeListener` to rebind the `MetricsFilter` to log4j2 if configuration is reloaded * Keep track of the listener to deregister it when we close the binder Signed-off-by: Patrik Ivarsson --- .../binder/logging/Log4j2Metrics.java | 63 +++++++++++++------ .../binder/logging/Log4j2MetricsTest.java | 52 +++++++++++++++ 2 files changed, 95 insertions(+), 20 deletions(-) diff --git a/micrometer-core/src/main/java/io/micrometer/core/instrument/binder/logging/Log4j2Metrics.java b/micrometer-core/src/main/java/io/micrometer/core/instrument/binder/logging/Log4j2Metrics.java index e2292e9bb9..9c815c966d 100644 --- a/micrometer-core/src/main/java/io/micrometer/core/instrument/binder/logging/Log4j2Metrics.java +++ b/micrometer-core/src/main/java/io/micrometer/core/instrument/binder/logging/Log4j2Metrics.java @@ -31,9 +31,12 @@ import org.apache.logging.log4j.core.filter.AbstractFilter; import org.apache.logging.log4j.core.filter.CompositeFilter; -import java.util.*; +import java.beans.PropertyChangeListener; +import java.util.Arrays; +import java.util.List; import java.util.concurrent.ConcurrentHashMap; import java.util.concurrent.ConcurrentMap; +import java.util.concurrent.CopyOnWriteArrayList; import static java.util.Collections.emptyList; @@ -63,6 +66,8 @@ public class Log4j2Metrics implements MeterBinder, AutoCloseable { private final ConcurrentMap metricsFilters = new ConcurrentHashMap<>(); + private final List changeListeners = new CopyOnWriteArrayList<>(); + public Log4j2Metrics() { this(emptyList()); } @@ -79,12 +84,28 @@ public Log4j2Metrics(Iterable tags, LoggerContext loggerContext) { @Override public void bindTo(MeterRegistry registry) { Configuration configuration = loggerContext.getConfiguration(); + registerMetricsFilter(configuration, registry); + loggerContext.updateLoggers(configuration); + + PropertyChangeListener changeListener = listener -> { + if (listener.getNewValue() instanceof Configuration && listener.getOldValue() != listener.getNewValue()) { + registerMetricsFilter((Configuration) listener.getNewValue(), registry); + if (listener.getOldValue() instanceof Configuration) { + removeMetricsFilter((Configuration) listener.getOldValue()); + } + } + }; + + changeListeners.add(changeListener); + loggerContext.addPropertyChangeListener(changeListener); + } + + private void registerMetricsFilter(Configuration configuration, MeterRegistry registry) { LoggerConfig rootLoggerConfig = configuration.getRootLogger(); MetricsFilter metricsFilter = getOrCreateMetricsFilterAndStart(registry); rootLoggerConfig.addFilter(metricsFilter); - loggerContext.getConfiguration() - .getLoggers() + configuration.getLoggers() .values() .stream() .filter(loggerConfig -> !loggerConfig.isAdditive()) @@ -105,8 +126,6 @@ public void bindTo(MeterRegistry registry) { loggerConfig.addFilter(metricsFilter); }); - - loggerContext.updateLoggers(configuration); } private MetricsFilter getOrCreateMetricsFilterAndStart(MeterRegistry registry) { @@ -119,28 +138,32 @@ private MetricsFilter getOrCreateMetricsFilterAndStart(MeterRegistry registry) { @Override public void close() { + changeListeners.forEach(loggerContext::removePropertyChangeListener); + if (!metricsFilters.isEmpty()) { Configuration configuration = loggerContext.getConfiguration(); - LoggerConfig rootLoggerConfig = configuration.getRootLogger(); - metricsFilters.values().forEach(rootLoggerConfig::removeFilter); - - loggerContext.getConfiguration() - .getLoggers() - .values() - .stream() - .filter(loggerConfig -> !loggerConfig.isAdditive()) - .forEach(loggerConfig -> { - if (loggerConfig != rootLoggerConfig) { - metricsFilters.values().forEach(loggerConfig::removeFilter); - } - }); - + removeMetricsFilter(configuration); loggerContext.updateLoggers(configuration); + metricsFilters.values().forEach(MetricsFilter::stop); - metricsFilters.clear(); } } + private void removeMetricsFilter(Configuration configuration) { + LoggerConfig rootLoggerConfig = configuration.getRootLogger(); + metricsFilters.values().forEach(rootLoggerConfig::removeFilter); + + configuration.getLoggers() + .values() + .stream() + .filter(loggerConfig -> !loggerConfig.isAdditive()) + .forEach(loggerConfig -> { + if (loggerConfig != rootLoggerConfig) { + metricsFilters.values().forEach(rootLoggerConfig::removeFilter); + } + }); + } + @NonNullApi @NonNullFields static class MetricsFilter extends AbstractFilter { 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 d75c25a73d..66251ade99 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 @@ -288,4 +288,56 @@ void multipleRegistriesCanBeBoundWithNonRootLoggerContext() { assertThat(registry2.get("log4j2.events").tags("level", "info").counter().count()).isEqualTo(2); } + @Issue("#5756") + @Test + void rebindsMetricsWhenConfigurationIsReloaded() { + LoggerContext context = new LoggerContext("test"); + Logger logger = context.getLogger("com.test"); + Configuration oldConfiguration = context.getConfiguration(); + + try (Log4j2Metrics metrics = new Log4j2Metrics(emptyList(), context)) { + metrics.bindTo(registry); + + logger.error("first"); + assertThat(registry.get("log4j2.events").tags("level", "error").counter().count()).isEqualTo(1); + + // Should have added filter to configuration + Filter oldFilter = oldConfiguration.getRootLogger().getFilter(); + assertThat(oldFilter).isInstanceOf(Log4j2Metrics.MetricsFilter.class); + + // This will reload the configuration to default + context.reconfigure(); + + Configuration newConfiguration = context.getConfiguration(); + + // For this event to be counted, the metrics must be rebound + logger.error("second"); + assertThat(registry.get("log4j2.events").tags("level", "error").counter().count()).isEqualTo(2); + + // Should have removed filter from old configuration, adding it to the new + assertThat(oldConfiguration.getRootLogger().getFilter()).isNull(); + Filter newFilter = newConfiguration.getRootLogger().getFilter(); + assertThat(newFilter).isInstanceOf(Log4j2Metrics.MetricsFilter.class); + } + } + + @Test + void shouldNotRebindMetricsIfBinderIsClosed() { + LoggerContext context = new LoggerContext("test"); + Logger logger = context.getLogger("com.test"); + + try (Log4j2Metrics metrics = new Log4j2Metrics(emptyList(), context)) { + metrics.bindTo(registry); + logger.error("first"); + } + + // This will reload the configuration to default + context.reconfigure(); + + // This event should not be counted as the metrics binder is already closed + logger.error("second"); + + assertThat(registry.get("log4j2.events").tags("level", "error").counter().count()).isEqualTo(1); + } + } From 64ae25e4c1caf2f1e69fb61d60a1fa50ff03529d Mon Sep 17 00:00:00 2001 From: Patrik Ivarsson Date: Fri, 24 Jan 2025 08:39:21 +0100 Subject: [PATCH 2/5] Updates to Log4j2Metrics from code review Signed-off-by: Patrik Ivarsson --- .../core/instrument/binder/logging/Log4j2Metrics.java | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/micrometer-core/src/main/java/io/micrometer/core/instrument/binder/logging/Log4j2Metrics.java b/micrometer-core/src/main/java/io/micrometer/core/instrument/binder/logging/Log4j2Metrics.java index 9c815c966d..f8fa0fc698 100644 --- a/micrometer-core/src/main/java/io/micrometer/core/instrument/binder/logging/Log4j2Metrics.java +++ b/micrometer-core/src/main/java/io/micrometer/core/instrument/binder/logging/Log4j2Metrics.java @@ -89,7 +89,9 @@ public void bindTo(MeterRegistry registry) { PropertyChangeListener changeListener = listener -> { if (listener.getNewValue() instanceof Configuration && listener.getOldValue() != listener.getNewValue()) { - registerMetricsFilter((Configuration) listener.getNewValue(), registry); + Configuration newConfiguration = (Configuration) listener.getNewValue(); + registerMetricsFilter(newConfiguration, registry); + loggerContext.updateLoggers(newConfiguration); if (listener.getOldValue() instanceof Configuration) { removeMetricsFilter((Configuration) listener.getOldValue()); } @@ -139,6 +141,7 @@ private MetricsFilter getOrCreateMetricsFilterAndStart(MeterRegistry registry) { @Override public void close() { changeListeners.forEach(loggerContext::removePropertyChangeListener); + changeListeners.clear(); if (!metricsFilters.isEmpty()) { Configuration configuration = loggerContext.getConfiguration(); @@ -146,6 +149,7 @@ public void close() { loggerContext.updateLoggers(configuration); metricsFilters.values().forEach(MetricsFilter::stop); + metricsFilters.clear(); } } From 356c7dcfe11083fabb278a1c14fd3579f5ce0891 Mon Sep 17 00:00:00 2001 From: Patrik Ivarsson Date: Fri, 24 Jan 2025 10:13:58 +0100 Subject: [PATCH 3/5] fix cleanup of loggerConfig Signed-off-by: Patrik Ivarsson --- .../core/instrument/binder/logging/Log4j2Metrics.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/micrometer-core/src/main/java/io/micrometer/core/instrument/binder/logging/Log4j2Metrics.java b/micrometer-core/src/main/java/io/micrometer/core/instrument/binder/logging/Log4j2Metrics.java index f8fa0fc698..355c6452e0 100644 --- a/micrometer-core/src/main/java/io/micrometer/core/instrument/binder/logging/Log4j2Metrics.java +++ b/micrometer-core/src/main/java/io/micrometer/core/instrument/binder/logging/Log4j2Metrics.java @@ -163,7 +163,7 @@ private void removeMetricsFilter(Configuration configuration) { .filter(loggerConfig -> !loggerConfig.isAdditive()) .forEach(loggerConfig -> { if (loggerConfig != rootLoggerConfig) { - metricsFilters.values().forEach(rootLoggerConfig::removeFilter); + metricsFilters.values().forEach(loggerConfig::removeFilter); } }); } From cd4b6bf721c90f1a299062f697798f67f91dc4aa Mon Sep 17 00:00:00 2001 From: Patrik Ivarsson Date: Tue, 28 Jan 2025 15:57:40 +0100 Subject: [PATCH 4/5] code review: add additional assert Signed-off-by: Patrik Ivarsson --- .../core/instrument/binder/logging/Log4j2MetricsTest.java | 1 + 1 file changed, 1 insertion(+) 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 66251ade99..69c29f4b7e 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 @@ -329,6 +329,7 @@ void shouldNotRebindMetricsIfBinderIsClosed() { try (Log4j2Metrics metrics = new Log4j2Metrics(emptyList(), context)) { metrics.bindTo(registry); logger.error("first"); + assertThat(registry.get("log4j2.events").tags("level", "error").counter().count()).isEqualTo(1); } // This will reload the configuration to default From 66368f4d2e60f68161c0df2e69b0af905143d414 Mon Sep 17 00:00:00 2001 From: Tommy Ludwig <8924140+shakuzen@users.noreply.github.com> Date: Wed, 5 Feb 2025 13:15:25 +0900 Subject: [PATCH 5/5] Log warning and do nothing on double binding to same registry --- .../binder/logging/Log4j2Metrics.java | 8 ++++++ .../binder/logging/Log4j2MetricsTest.java | 27 +++++++++++++++++++ 2 files changed, 35 insertions(+) diff --git a/micrometer-core/src/main/java/io/micrometer/core/instrument/binder/logging/Log4j2Metrics.java b/micrometer-core/src/main/java/io/micrometer/core/instrument/binder/logging/Log4j2Metrics.java index 355c6452e0..0fa8aaa88c 100644 --- a/micrometer-core/src/main/java/io/micrometer/core/instrument/binder/logging/Log4j2Metrics.java +++ b/micrometer-core/src/main/java/io/micrometer/core/instrument/binder/logging/Log4j2Metrics.java @@ -17,6 +17,8 @@ import io.micrometer.common.lang.NonNullApi; import io.micrometer.common.lang.NonNullFields; +import io.micrometer.common.util.internal.logging.InternalLogger; +import io.micrometer.common.util.internal.logging.InternalLoggerFactory; import io.micrometer.core.instrument.Counter; import io.micrometer.core.instrument.MeterRegistry; import io.micrometer.core.instrument.Tag; @@ -60,6 +62,8 @@ public class Log4j2Metrics implements MeterBinder, AutoCloseable { private static final String METER_DESCRIPTION = "Number of log events"; + private static final InternalLogger logger = InternalLoggerFactory.getInstance(Log4j2Metrics.class); + private final Iterable tags; private final LoggerContext loggerContext; @@ -83,6 +87,10 @@ public Log4j2Metrics(Iterable tags, LoggerContext loggerContext) { @Override public void bindTo(MeterRegistry registry) { + if (metricsFilters.containsKey(registry)) { + logger.warn("This Log4j2Metrics instance has already been bound to the registry {}", registry); + return; + } Configuration configuration = loggerContext.getConfiguration(); registerMetricsFilter(configuration, registry); loggerContext.updateLoggers(configuration); 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 69c29f4b7e..e4987fabbb 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 @@ -341,4 +341,31 @@ void shouldNotRebindMetricsIfBinderIsClosed() { assertThat(registry.get("log4j2.events").tags("level", "error").counter().count()).isEqualTo(1); } + @Test + void bindingTwiceToSameRegistry_doesNotDoubleCount() { + LoggerContext context = new LoggerContext("test"); + Logger logger = context.getLogger("com.test"); + + try (Log4j2Metrics metrics = new Log4j2Metrics(emptyList(), context)) { + // binding twice + metrics.bindTo(registry); + metrics.bindTo(registry); + + logger.error("first"); + + assertThat(registry.get("log4j2.events").tags("level", "error").counter().count()).isEqualTo(1); + + context.reconfigure(); + + logger.error("second"); + assertThat(registry.get("log4j2.events").tags("level", "error").counter().count()).isEqualTo(2); + } + + // no additional events should be counted now + context.reconfigure(); + + logger.error("third"); + assertThat(registry.get("log4j2.events").tags("level", "error").counter().count()).isEqualTo(2); + } + }