Rebind log4j2 metrics if configuration is changed

[pativa]

Describe the issue

This PR is intended to fix #5756

When log4j2 metrics are reconfigured, metrics will no longer be recorded. For example, if monitorInterval (docs) is configured to 30 is used and configuration is reloaded after application start, metrics would only be recorded for the first 30 seconds.

---

By using a PropertyChangeListener, it looks like we can register the MetricsFilter in much the same way, but it will be rebound after reloading the configuration. All the previous tests seem to pass too when using this method of configuration.

[shakuzen]

Thank you for the quick turnaround time on submitting a pull request for this. It generally looks good to me. Will metrics filters still be configured on the old Configuration instance? Should that be the case? Does that not result in a memory leak of sorts?

[pativa]

Thank you for the quick turnaround time on submitting a pull request for this. It generally looks good to me. Will metrics filters still be configured on the old Configuration instance? Should that be the case? Does that not result in a memory leak of sorts?

Thanks for the review!

That is a good point! I don't think it would be any big issue, as the old configuration is already stopped here, but I do think it would be cleaner to clean up any old references to MetricsFilter when we rebind it.

I made a new commit here where I also do a cleanup of the old configuration instance. I also changed the changeListener to only do an update if the configuration instance is not the same object as the old instance (as no rebinding or cleanup should be needed then).

[pativa]

Kind of unrelated to this PR, so I haven't changed it, but the call to

loggerContext.updateLoggers(configuration);

Seems to be completely unnecessary. I don't know how expensive this operation is, but it seems to be unnecessary to trigger a reload as this class modifies the configuration in-place?

[jonatan-ivanov]

updateLoggers was removed in the past and was quickly restored it, see:

• Polish Log4j2Metrics #867
• Restore updateLoggers() in Log4j2Metrics.updateLoggers() #872

Basically it does two things:

1. It updates the internal "copy" of the config, since references are used in some cases, this might not be an issue but things can change (in Log4J2 or in Micrometer) so it's safer to call updateLoggers too
2. It emits a PropertyChangeEvent to notify components about the change

[shakuzen]

Thank you for all the quick turnaround on reviews and sorry for all the back-and-forth. Things look good to me overall. I left a couple more minor review comments.

[shakuzen]

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.

[pativa]

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).

[shakuzen]

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.

[pativa]

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).