From 04f6d8cafe0d8212ccbb72344b33023a044ec675 Mon Sep 17 00:00:00 2001 From: Patrik Ivarsson <83230533+pativa@users.noreply.github.com> Date: Thu, 6 Feb 2025 05:48:29 +0100 Subject: [PATCH] Rebind log4j2 metrics if configuration is changed (#5810) This change ensures Log4j2 metrics are recorded when the configuration is updated (reconfigure'd). This also will log a warning and do nothing when binding an instance of Log4j2Metrics to the same registry multiple times. Fixes gh-5756 --------- Signed-off-by: Patrik Ivarsson Co-authored-by: Tommy Ludwig <8924140+shakuzen@users.noreply.github.com> --- .../binder/logging/Log4j2Metrics.java | 73 ++++++++++++----- .../binder/logging/Log4j2MetricsTest.java | 80 +++++++++++++++++++ 2 files changed, 134 insertions(+), 19 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..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; @@ -31,9 +33,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; @@ -57,12 +62,16 @@ 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; private final ConcurrentMap metricsFilters = new ConcurrentHashMap<>(); + private final List changeListeners = new CopyOnWriteArrayList<>(); + public Log4j2Metrics() { this(emptyList()); } @@ -78,13 +87,35 @@ 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); + + PropertyChangeListener changeListener = listener -> { + if (listener.getNewValue() instanceof Configuration && listener.getOldValue() != listener.getNewValue()) { + Configuration newConfiguration = (Configuration) listener.getNewValue(); + registerMetricsFilter(newConfiguration, registry); + loggerContext.updateLoggers(newConfiguration); + 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 +136,6 @@ public void bindTo(MeterRegistry registry) { loggerConfig.addFilter(metricsFilter); }); - - loggerContext.updateLoggers(configuration); } private MetricsFilter getOrCreateMetricsFilterAndStart(MeterRegistry registry) { @@ -119,28 +148,34 @@ private MetricsFilter getOrCreateMetricsFilterAndStart(MeterRegistry registry) { @Override public void close() { + changeListeners.forEach(loggerContext::removePropertyChangeListener); + changeListeners.clear(); + 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(loggerConfig::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..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 @@ -288,4 +288,84 @@ 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"); + assertThat(registry.get("log4j2.events").tags("level", "error").counter().count()).isEqualTo(1); + } + + // 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); + } + + @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); + } + }