Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Rebind log4j2 metrics if configuration is changed #5810

Open
wants to merge 4 commits into
base: main
Choose a base branch
from
Open

Rebind log4j2 metrics if configuration is changed #5810

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
ec8bd27
Rebind log4j2 metrics if configuration is changed
pativa Jan 17, 2025
f2005b6
small test cleanup
pativa Jan 17, 2025
41d0e7e
Cleanup MetricsFilter from old configuration
pativa Jan 20, 2025
30c036c
add additional verification
pativa Jan 20, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
90 changes: 58 additions & 32 deletions ...ometer-core/src/main/java/io/micrometer/core/instrument/binder/logging/Log4j2Metrics.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -31,9 +31,12 @@
import org.apache.logging.log4j.core.filter.AbstractFilter;
import org.apache.logging.log4j.core.filter.CompositeFilter;

import java.beans.PropertyChangeListener;
import java.util.ArrayList;
import java.util.Arrays;
import java.util.HashMap;
import java.util.List;
import java.util.Map;

import static java.util.Collections.emptyList;

Expand Down Expand Up @@ -61,7 +64,9 @@ public class Log4j2Metrics implements MeterBinder, AutoCloseable {

private final LoggerContext loggerContext;

private final List<MetricsFilter> metricsFilters = new ArrayList<>();
private final Map<String, MetricsFilter> metricsFilters = new HashMap<>();
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't want to block progress on this pull request, but in reviewing it, I've noticed something I think should be fixed perhaps first. We used to just have a single MetricsFilter instance. That was changed in #2183 when MetricsFilter was changed to take a LoggerConfig. That was subsequently changed in 66f59e1 when the reason it was needed was fixed in log4j itself. I think we should have at that time changed back to using a single instance of MetricsFilter since its input is always the same for a given instance of Log4j2Metrics - the MeterRegistry and tags. We're needlessly making multiple instances of equivalent MetricsFilters. Let me know if I'm missing something. I'll prepare a change for maintenance branches to stop making extraneous instances of MetricsFilter. If we get that merged, you can rebase your pull request on top of it and it will hopefully simplify things a bit.
/cc @jonatan-ivanov

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The case where it wouldn't always be the same MeterRegistry is if the same instance of Log4j2Metrics is bound to different registries. This came up before recently on whether that's expected/should be supported in all cases. I'm not sure we came to a conclusion as it depends on the implementation of the MeterBinder. We'll have to discuss this.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I was wondering about why multiple MetricsFilter were needed, but as it was that way I left that implementation. But it would be considerably easier to handle this without having multiple MetricsFilter, yes (no reason to store it in a map and keeping track of which filter was used for which logger).

If you change it to having a single filter, I can rebase this branch onto that and simplify this implementation a bit.

Having a single MetricsFilter wouldn't support binding the same Log4j2Metrics to different registries though, as you say.


private final List<PropertyChangeListener> changeListeners = new ArrayList<>();

public Log4j2Metrics() {
this(emptyList());
Expand All @@ -79,65 +84,86 @@ public Log4j2Metrics(Iterable<Tag> tags, LoggerContext loggerContext) {
@Override
public void bindTo(MeterRegistry registry) {
Configuration configuration = loggerContext.getConfiguration();
addMetricsFilterToConfiguration(configuration, registry);
loggerContext.updateLoggers(configuration);

PropertyChangeListener changeListener = listener -> {
if (listener.getNewValue() instanceof Configuration && listener.getOldValue() != listener.getNewValue()) {
addMetricsFilterToConfiguration((Configuration) listener.getNewValue(), registry);
if (listener.getOldValue() instanceof Configuration) {
removeMetricsFilter((Configuration) listener.getOldValue());
}
}
};

loggerContext.addPropertyChangeListener(changeListener);
changeListeners.add(changeListener);
}

private void addMetricsFilterToConfiguration(Configuration configuration, MeterRegistry registry) {
LoggerConfig rootLoggerConfig = configuration.getRootLogger();
rootLoggerConfig.addFilter(createMetricsFilterAndStart(registry));

loggerContext.getConfiguration()
.getLoggers()
if (!containsMetricsFilter(rootLoggerConfig.getFilter())) {
rootLoggerConfig.addFilter(metricsFilters.computeIfAbsent(rootLoggerConfig.getName(),
name -> createMetricsFilterAndStart(registry)));
}

configuration.getLoggers()
.values()
.stream()
.filter(loggerConfig -> !loggerConfig.isAdditive())
.forEach(loggerConfig -> {
if (loggerConfig == rootLoggerConfig) {
return;
}
Filter logFilter = loggerConfig.getFilter();

if (logFilter instanceof CompositeFilter
&& Arrays.stream(((CompositeFilter) logFilter).getFiltersArray())
.anyMatch(innerFilter -> innerFilter instanceof MetricsFilter)) {
return;
}

if (logFilter instanceof MetricsFilter) {
return;
if (!containsMetricsFilter(loggerConfig.getFilter())) {
loggerConfig.addFilter(metricsFilters.computeIfAbsent(loggerConfig.getName(),
name -> createMetricsFilterAndStart(registry)));
}
loggerConfig.addFilter(createMetricsFilterAndStart(registry));
});
}

loggerContext.updateLoggers(configuration);
private boolean containsMetricsFilter(Filter logFilter) {
return logFilter instanceof MetricsFilter || (logFilter instanceof CompositeFilter
&& Arrays.stream(((CompositeFilter) logFilter).getFiltersArray())
.anyMatch(this::containsMetricsFilter));
}

private MetricsFilter createMetricsFilterAndStart(MeterRegistry registry) {
MetricsFilter metricsFilter = new MetricsFilter(registry, tags);
metricsFilter.start();
metricsFilters.add(metricsFilter);
return metricsFilter;
}

@Override
public void close() {
if (!metricsFilters.isEmpty()) {
Configuration configuration = loggerContext.getConfiguration();
LoggerConfig rootLoggerConfig = configuration.getRootLogger();
metricsFilters.forEach(rootLoggerConfig::removeFilter);

loggerContext.getConfiguration()
.getLoggers()
.values()
.stream()
.filter(loggerConfig -> !loggerConfig.isAdditive())
.forEach(loggerConfig -> {
if (loggerConfig != rootLoggerConfig) {
metricsFilters.forEach(loggerConfig::removeFilter);
}
});
changeListeners.forEach(loggerContext::removePropertyChangeListener);

Configuration configuration = loggerContext.getConfiguration();
removeMetricsFilter(configuration);
loggerContext.updateLoggers(configuration);
metricsFilters.forEach(MetricsFilter::stop);

metricsFilters.values().forEach(MetricsFilter::stop);
}
}

private void removeMetricsFilter(Configuration configuration) {
LoggerConfig rootLoggerConfig = configuration.getRootLogger();
rootLoggerConfig.removeFilter(metricsFilters.get(rootLoggerConfig.getName()));

loggerContext.getConfiguration()
.getLoggers()
.values()
.stream()
.filter(loggerConfig -> !loggerConfig.isAdditive())
.forEach(loggerConfig -> {
if (loggerConfig != rootLoggerConfig) {
loggerConfig.removeFilter(metricsFilters.get(loggerConfig.getName()));
}
});
}

@NonNullApi
@NonNullFields
static class MetricsFilter extends AbstractFilter {
Expand Down
57 changes: 57 additions & 0 deletions ...er-core/src/test/java/io/micrometer/core/instrument/binder/logging/Log4j2MetricsTest.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -23,6 +23,7 @@
import org.apache.logging.log4j.Level;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.core.Filter;
import org.apache.logging.log4j.core.LoggerContext;
import org.apache.logging.log4j.core.config.Configuration;
import org.apache.logging.log4j.core.config.ConfigurationSource;
Expand Down Expand Up @@ -184,4 +185,60 @@ void asyncLogShouldNotBeDuplicated() throws IOException {
.until(() -> registry.get("log4j2.events").tags("level", "info").counter().count() == 3);
}

@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);

// The filters should be the same instance, to verify that we don't
// continually create more filters when reloading
assertThat(oldFilter).isSameAs(newFilter);
}
}

@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);
}

}
Loading