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
ffe57d9
Rebind log4j2 metrics if configuration is changed
pativa Jan 23, 2025
26fc0f4
Updates to Log4j2Metrics from code review
pativa Jan 24, 2025
3e7b1f0
fix cleanup of loggerConfig
pativa Jan 24, 2025
5e9c78f
code review: add additional assert
pativa Jan 28, 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
65 changes: 46 additions & 19 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.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;

Expand Down Expand Up @@ -63,6 +66,8 @@ public class Log4j2Metrics implements MeterBinder, AutoCloseable {

private final ConcurrentMap<MeterRegistry, MetricsFilter> metricsFilters = new ConcurrentHashMap<>();

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

public Log4j2Metrics() {
this(emptyList());
}
Expand All @@ -79,11 +84,29 @@ public Log4j2Metrics(Iterable<Tag> 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()) {
Configuration newConfiguration = (Configuration) listener.getNewValue();
registerMetricsFilter(newConfiguration, registry);
loggerContext.updateLoggers(newConfiguration);
if (listener.getOldValue() instanceof Configuration) {
removeMetricsFilter((Configuration) listener.getOldValue());
}
}
};

changeListeners.add(changeListener);
Copy link
Member

Choose a reason for hiding this comment

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

I'm curious about the choice of changeListeners being a List. Would it be better to use a ConcurrentMap keyed on the MeterRegistry passed to bindTo like the MetricsFilter map? In most expected usage, it won't matter either way, but maybe it's safer and more consistent to have only one listener per registry unless I'm missing some reason that may not be what we want.

Copy link
Contributor Author

@pativa pativa Jan 28, 2025 •
edited
Loading

Choose a reason for hiding this comment

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

Ok, so this will be kind of a weird case, but using a ConcurrentMap the following test (where we bind the Log42Metrics instance to the same MeterRegistry multiple times) would fail. I don't know what the best behavior when binding to the same registry twice would be, but currently it will count the logs twice (which might be what could be said to be expected?)

    @Test
    void bindingTwice() {
        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(2);

            context.reconfigure();

            logger.error("second");
            // this succeeds, first I was thinking this might fail, but the next check does not succeed
            assertThat(registry.get("log4j2.events").tags("level", "error").counter().count()).isEqualTo(4);
        }

        // no additional events should be counted now
        context.reconfigure();

        logger.error("third");
        // this fails, as the closing of the class hasn't properly removed the listeners,
        // so when reconfiguring a filter is added again and the result is 5
        assertThat(registry.get("log4j2.events").tags("level", "error").counter().count()).isEqualTo(4);
    }

If we use a

private final ConcurrentMap<MeterRegistry, PropertyChangeListener> changeListeners = new ConcurrentHashMap<>();

the following may not be enough to clean the loggerContext anymore:

changeListeners.values().forEach(loggerContext::removePropertyChangeListener);

As the same changeListener may have been registered multiple times, and only one would be removed by log4j2.

Using the current setup with a List does not fail the test.

Other solutions to the above would be to not allow binding the filter to the same registry twice (e.g. throwing exception?) or not counting twice when binding again (e.g. ignore the second call to bindTo() with the same MeterRegistry).

Copy link
Member

@shakuzen shakuzen Jan 29, 2025 •
edited
Loading

Choose a reason for hiding this comment

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

While we don't document it anywhere as far as I know, binding multiple times to the same registry I think we should generally classify the behavior as unspecified, meaning no guarantee what the outcome will be for any given binder implementation. I'm not sure why someone would intentionally bind multiple times to the same registry, and I think we can wait to hear from a user before we go to the effort of trying to support that. Thus I think doing nothing in particular would be an option here, but if we want to be extra cautious we can decide what the behavior should be in this case. I would go with ignoring the second call to bindTo with the same registry and logging a warning if we want to handle this case at all. Pinging @jonatan-ivanov to see what he thinks on this.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Yeah, I would be fine with any handling for the case that bindTo is called twice, it's just important that the cleanup works regardless.

Ignoring the second call / logging a warning would work fine, as long as we don't register the PropertyChangeListener twice (as the second listener also has to be removed).

loggerContext.addPropertyChangeListener(changeListener);
}

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

loggerContext.getConfiguration()
.getLoggers()
configuration.getLoggers()
.values()
.stream()
.filter(loggerConfig -> !loggerConfig.isAdditive())
Expand All @@ -104,8 +127,6 @@ public void bindTo(MeterRegistry registry) {
}
loggerConfig.addFilter(getOrCreateMetricsFilterAndStart(registry));
});

loggerContext.updateLoggers(configuration);
}

private MetricsFilter getOrCreateMetricsFilterAndStart(MeterRegistry registry) {
Expand All @@ -118,28 +139,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();
pativa marked this conversation as resolved.
Show resolved Hide resolved
}
}

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 {
Expand Down
53 changes: 53 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 @@ -229,4 +229,57 @@ void multipleRegistriesCanBeBound() {

}

@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);
pativa marked this conversation as resolved.
Show resolved Hide resolved
}

}