From 66f59e175022fe84f5ef699f4d9285e4096270a7 Mon Sep 17 00:00:00 2001 From: Jonatan Ivanov Date: Fri, 20 Oct 2023 15:51:54 -0700 Subject: [PATCH] Remove isEndOfBatch check from Log4j2Metrics In case of async loggers, the MetricsFilter#filter method is/was called multiple times. Because of this, a check was introduced in gh-2183 assuming that if the event has the isEndOfBatch flag set to true, that is the last filter method call for that event. Unfortunately, it turned out that this approach did not work, since it did not just filter out the unwanted multiple calls on one event but it also filtered out all the filter method calls on events that were not at the end of the async batch. So Log4j2Metrics counted batches of events, not the individual events. Fortunately multiple filter invocations was fixed in Log4j2, see apache/logging-log4j2#1550 and apache/logging-log4j2#1552. Since now there will be only one filter method call, the check introduced in gh-2183 can and should be removed (the call to the filter method is before the isEndOfBatch flag is set so the flag will always return false). Closes gh-2176 See gh-2183 See gh-4253 --- .../binder/logging/Log4j2Metrics.java | 35 ++++++++----------- .../binder/logging/Log4j2MetricsTest.java | 4 ++- 2 files changed, 17 insertions(+), 22 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 a4904d0631..e7b7d73b12 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 @@ -26,7 +26,6 @@ import org.apache.logging.log4j.core.Filter; import org.apache.logging.log4j.core.LogEvent; import org.apache.logging.log4j.core.LoggerContext; -import org.apache.logging.log4j.core.async.AsyncLoggerConfig; import org.apache.logging.log4j.core.config.Configuration; import org.apache.logging.log4j.core.config.LoggerConfig; import org.apache.logging.log4j.core.filter.AbstractFilter; @@ -39,7 +38,12 @@ import static java.util.Collections.emptyList; /** - * {@link MeterBinder} for Apache Log4j 2. + * {@link MeterBinder} for Apache Log4j 2. Please use at least 2.21.0 since there was a + * bug in earlier versions that prevented Micrometer to increment its counters correctly. + * See: + * logging-log4j2#1550 + * See: micrometer#2176 * * @author Steven Sheehy * @author Johnny Lim @@ -55,7 +59,7 @@ public class Log4j2Metrics implements MeterBinder, AutoCloseable { private final LoggerContext loggerContext; - private List metricsFilters = new ArrayList<>(); + private final List metricsFilters = new ArrayList<>(); public Log4j2Metrics() { this(emptyList()); @@ -75,7 +79,7 @@ public void bindTo(MeterRegistry registry) { Configuration configuration = loggerContext.getConfiguration(); LoggerConfig rootLoggerConfig = configuration.getRootLogger(); - rootLoggerConfig.addFilter(createMetricsFilterAndStart(registry, rootLoggerConfig)); + rootLoggerConfig.addFilter(createMetricsFilterAndStart(registry)); loggerContext.getConfiguration() .getLoggers() @@ -97,14 +101,14 @@ public void bindTo(MeterRegistry registry) { if (logFilter instanceof MetricsFilter) { return; } - loggerConfig.addFilter(createMetricsFilterAndStart(registry, loggerConfig)); + loggerConfig.addFilter(createMetricsFilterAndStart(registry)); }); loggerContext.updateLoggers(configuration); } - private MetricsFilter createMetricsFilterAndStart(MeterRegistry registry, LoggerConfig loggerConfig) { - MetricsFilter metricsFilter = new MetricsFilter(registry, tags, loggerConfig instanceof AsyncLoggerConfig); + private MetricsFilter createMetricsFilterAndStart(MeterRegistry registry) { + MetricsFilter metricsFilter = new MetricsFilter(registry, tags); metricsFilter.start(); metricsFilters.add(metricsFilter); return metricsFilter; @@ -135,7 +139,7 @@ public void close() { @NonNullApi @NonNullFields - class MetricsFilter extends AbstractFilter { + static class MetricsFilter extends AbstractFilter { private final Counter fatalCounter; @@ -149,10 +153,7 @@ class MetricsFilter extends AbstractFilter { private final Counter traceCounter; - private final boolean isAsyncLogger; - - MetricsFilter(MeterRegistry registry, Iterable tags, boolean isAsyncLogger) { - this.isAsyncLogger = isAsyncLogger; + MetricsFilter(MeterRegistry registry, Iterable tags) { fatalCounter = Counter.builder(METER_NAME) .tags(tags) .tags("level", "fatal") @@ -198,18 +199,10 @@ class MetricsFilter extends AbstractFilter { @Override public Result filter(LogEvent event) { - - if (!isAsyncLogger || isAsyncLoggerAndEndOfBatch(event)) { - incrementCounter(event); - } - + incrementCounter(event); return Result.NEUTRAL; } - private boolean isAsyncLoggerAndEndOfBatch(LogEvent event) { - return isAsyncLogger && event.isEndOfBatch(); - } - private void incrementCounter(LogEvent event) { switch (event.getLevel().getStandardLevel()) { case FATAL: 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 81f8008dc7..3036274017 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 @@ -174,8 +174,10 @@ void asyncLogShouldNotBeDuplicated() throws IOException { assertThat(registry.get("log4j2.events").tags("level", "info").counter().count()).isEqualTo(0); logger.info("Hello, world!"); + logger.info("Hello, world!"); + logger.info("Hello, world!"); await().atMost(Duration.ofSeconds(1)) - .until(() -> registry.get("log4j2.events").tags("level", "info").counter().count() == 1); + .until(() -> registry.get("log4j2.events").tags("level", "info").counter().count() == 3); } }