Skip to content

Commit

Permalink
Remove isEndOfBatch check from Log4j2Metrics
Browse files Browse the repository at this point in the history
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
  • Loading branch information
jonatan-ivanov committed Oct 20, 2023
1 parent 5cef8e4 commit 61b3074
Show file tree
Hide file tree
Showing 2 changed files with 11 additions and 21 deletions.
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -55,7 +54,7 @@ public class Log4j2Metrics implements MeterBinder, AutoCloseable {

private final LoggerContext loggerContext;

private List<MetricsFilter> metricsFilters = new ArrayList<>();
private final List<MetricsFilter> metricsFilters = new ArrayList<>();

public Log4j2Metrics() {
this(emptyList());
Expand All @@ -75,7 +74,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()
Expand All @@ -97,14 +96,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;
Expand Down Expand Up @@ -135,7 +134,7 @@ public void close() {

@NonNullApi
@NonNullFields
class MetricsFilter extends AbstractFilter {
static class MetricsFilter extends AbstractFilter {

private final Counter fatalCounter;

Expand All @@ -149,10 +148,7 @@ class MetricsFilter extends AbstractFilter {

private final Counter traceCounter;

private final boolean isAsyncLogger;

MetricsFilter(MeterRegistry registry, Iterable<Tag> tags, boolean isAsyncLogger) {
this.isAsyncLogger = isAsyncLogger;
MetricsFilter(MeterRegistry registry, Iterable<Tag> tags) {
fatalCounter = Counter.builder(METER_NAME)
.tags(tags)
.tags("level", "fatal")
Expand Down Expand Up @@ -198,18 +194,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:
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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);
}

}

0 comments on commit 61b3074

Please sign in to comment.