Rebind Log4j2Metrics when LoggerContext#reconfigure is called

[ddavidzhang]

Describe the bug
Now，log4j2Metrics is registed when server starting up. But when Log4j2 LoggerContexted is reconfigured because of config being changed, the filter will not work.

Environment

• Micrometer version : 1.9.15 and 1.12.3
• Micrometer registry : prometheus
• OS: ALL
• Java version: jdk 8 and jdk 21

To Reproduce
How to reproduce the bug:
After a spring server starts up, we change some log4j2's config, logging level for example and Log4j2's reconfigure will be triggered. After this, the filter in log4j2Metrics will not work.

Expected behavior
log4j2Metrics always work

[shakuzen]

I'm not familiar with how the details of how reconfiguring works. Could you share a snippet of code demonstrating what is being done? Ideally if it can be put in a unit test that is minimal (i.e. doesn't involve Spring), we can add it to our tests when we address this and ensure it works now and going forward. I wonder if there is a way we can register a callback that is run when reconfiguration happens.

[ddavidzhang]

I just change some config (any) at Nacos, and that will trigger a RefreshEvent of Spring. Then, the logging system of Spring will load loadConfiguration again.
I'm also not familiar with how the details of how reconfiguring works.
The "LoggerContext.setConfiguration" is called, or "LoggerContext.reconfigure" is called.
The following are the stack:

setConfiguration:601, LoggerContext (org.apache.logging.log4j.core)
start:285, LoggerContext (org.apache.logging.log4j.core)
start:87, AsyncLoggerContext (org.apache.logging.log4j.core.async)
loadConfiguration:228, Log4J2LoggingSystem (org.springframework.boot.logging.log4j2)
loadConfiguration:194, Log4J2LoggingSystem (org.springframework.boot.logging.log4j2)
initializeWithSpecificConfig:66, AbstractLoggingSystem (org.springframework.boot.logging)
initialize:57, AbstractLoggingSystem (org.springframework.boot.logging)
initialize:170, Log4J2LoggingSystem (org.springframework.boot.logging.log4j2)
reinitializeLoggingSystem:168, PropertySourceBootstrapConfiguration (org.springframework.cloud.bootstrap.config)
doInitialize:148, PropertySourceBootstrapConfiguration (org.springframework.cloud.bootstrap.config)
initialize:110, PropertySourceBootstrapConfiguration (org.springframework.cloud.bootstrap.config)
applyInitializers:604, SpringApplication (org.springframework.boot)
prepareContext:373, SpringApplication (org.springframework.boot)
run:306, SpringApplication (org.springframework.boot)
run:164, SpringApplicationBuilder (org.springframework.boot.builder)
addConfigFilesToEnvironment:78, LegacyContextRefresher (org.springframework.cloud.context.refresh)
updateEnvironment:56, LegacyContextRefresher (org.springframework.cloud.context.refresh)
refreshEnvironment:101, ContextRefresher (org.springframework.cloud.context.refresh)
refresh:94, ContextRefresher (org.springframework.cloud.context.refresh)
handle:72, RefreshEventListener (org.springframework.cloud.endpoint.event)
onApplicationEvent:61, RefreshEventListener (org.springframework.cloud.endpoint.event)
doInvokeListener:178, SimpleApplicationEventMulticaster (org.springframework.context.event)
invokeListener:171, SimpleApplicationEventMulticaster (org.springframework.context.event)
multicastEvent:145, SimpleApplicationEventMulticaster (org.springframework.context.event)
publishEvent:421, AbstractApplicationContext (org.springframework.context.support)
publishEvent:378, AbstractApplicationContext (org.springframework.context.support)
innerReceive:118, NacosContextRefresher$1 (com.alibaba.cloud.nacos.refresh)
receiveConfigInfo:40, AbstractSharedListener (com.alibaba.nacos.api.config.listener)
lambda$safeNotifyListener$1:334, CacheData (com.alibaba.nacos.client.config.impl)
run:-1, 1979102041 (com.alibaba.nacos.client.config.impl.CacheData$$Lambda$1931)
call:511, Executors$RunnableAdapter (java.util.concurrent)
run$$$capture:266, FutureTask (java.util.concurrent)
run:-1, FutureTask (java.util.concurrent)
 - Async stack trace
<init>:151, FutureTask (java.util.concurrent)
newTaskFor:87, AbstractExecutorService (java.util.concurrent)
submit:111, AbstractExecutorService (java.util.concurrent)
safeNotifyListener:365, CacheData (com.alibaba.nacos.client.config.impl)
checkListenerMd5:285, CacheData (com.alibaba.nacos.client.config.impl)
refreshContentAndCheck:454, ClientWorker (com.alibaba.nacos.client.config.impl)
refreshContentAndCheck:436, ClientWorker (com.alibaba.nacos.client.config.impl)
access$600:95, ClientWorker (com.alibaba.nacos.client.config.impl)
executeConfigListen:800, ClientWorker$ConfigRpcTransportClient (com.alibaba.nacos.client.config.impl)
lambda$startInternal$2:704, ClientWorker$ConfigRpcTransportClient (com.alibaba.nacos.client.config.impl)
call:511, Executors$RunnableAdapter (java.util.concurrent)
run$$$capture:266, FutureTask (java.util.concurrent)
run:-1, FutureTask (java.util.concurrent)
 - Async stack trace
<init>:151, FutureTask (java.util.concurrent)
<init>:209, ScheduledThreadPoolExecutor$ScheduledFutureTask (java.util.concurrent)
schedule:532, ScheduledThreadPoolExecutor (java.util.concurrent)
startInternal:697, ClientWorker$ConfigRpcTransportClient (com.alibaba.nacos.client.config.impl)
start:136, ConfigTransportClient (com.alibaba.nacos.client.config.impl)
<init>:428, ClientWorker (com.alibaba.nacos.client.config.impl)
<init>:83, NacosConfigService (com.alibaba.nacos.client.config)
newInstance0:-2, NativeConstructorAccessorImpl (sun.reflect)
newInstance:62, NativeConstructorAccessorImpl (sun.reflect)
newInstance:45, DelegatingConstructorAccessorImpl (sun.reflect)
newInstance:423, Constructor (java.lang.reflect)
createConfigService:43, ConfigFactory (com.alibaba.nacos.api.config)
createConfigService:44, NacosFactory (com.alibaba.nacos.api)
createConfigService:55, NacosConfigManager (com.alibaba.cloud.nacos)
<init>:43, NacosConfigManager (com.alibaba.cloud.nacos)
registerConfigManager:198, NacosConfigDataLocationResolver (com.alibaba.cloud.nacos.configdata)
resolveProfileSpecific:153, NacosConfigDataLocationResolver (com.alibaba.cloud.nacos.configdata)
lambda$resolve$2:120, ConfigDataLocationResolvers (org.springframework.boot.context.config)
resolve:126, ConfigDataLocationResolvers (org.springframework.boot.context.config)
resolve:119, ConfigDataLocationResolvers (org.springframework.boot.context.config)
resolve:107, ConfigDataLocationResolvers (org.springframework.boot.context.config)
resolve:106, ConfigDataImporter (org.springframework.boot.context.config)
resolve:98, ConfigDataImporter (org.springframework.boot.context.config)
resolveAndLoad:86, ConfigDataImporter (org.springframework.boot.context.config)
withProcessedImports:116, ConfigDataEnvironmentContributors (org.springframework.boot.context.config)
processWithProfiles:311, ConfigDataEnvironment (org.springframework.boot.context.config)
processAndApply:232, ConfigDataEnvironment (org.springframework.boot.context.config)
postProcessEnvironment:102, ConfigDataEnvironmentPostProcessor (org.springframework.boot.context.config)
postProcessEnvironment:94, ConfigDataEnvironmentPostProcessor (org.springframework.boot.context.config)
onApplicationEnvironmentPreparedEvent:102, EnvironmentPostProcessorApplicationListener (org.springframework.boot.env)
onApplicationEvent:87, EnvironmentPostProcessorApplicationListener (org.springframework.boot.env)
doInvokeListener:178, SimpleApplicationEventMulticaster (org.springframework.context.event)
invokeListener:171, SimpleApplicationEventMulticaster (org.springframework.context.event)
multicastEvent:145, SimpleApplicationEventMulticaster (org.springframework.context.event)
multicastEvent:133, SimpleApplicationEventMulticaster (org.springframework.context.event)
environmentPrepared:85, EventPublishingRunListener (org.springframework.boot.context.event)
lambda$environmentPrepared$2:66, SpringApplicationRunListeners (org.springframework.boot)
forEach:1259, ArrayList (java.util)
doWithListeners:120, SpringApplicationRunListeners (org.springframework.boot)
doWithListeners:114, SpringApplicationRunListeners (org.springframework.boot)
environmentPrepared:65, SpringApplicationRunListeners (org.springframework.boot)
prepareEnvironment:343, SpringApplication (org.springframework.boot)
run:301, SpringApplication (org.springframework.boot)
run:164, SpringApplicationBuilder (org.springframework.boot.builder)
bootstrapServiceContext:195, BootstrapApplicationListener (org.springframework.cloud.bootstrap)
onApplicationEvent:114, BootstrapApplicationListener (org.springframework.cloud.bootstrap)
onApplicationEvent:77, BootstrapApplicationListener (org.springframework.cloud.bootstrap)
doInvokeListener:178, SimpleApplicationEventMulticaster (org.springframework.context.event)
invokeListener:171, SimpleApplicationEventMulticaster (org.springframework.context.event)
multicastEvent:145, SimpleApplicationEventMulticaster (org.springframework.context.event)
multicastEvent:133, SimpleApplicationEventMulticaster (org.springframework.context.event)
environmentPrepared:85, EventPublishingRunListener (org.springframework.boot.context.event)
lambda$environmentPrepared$2:66, SpringApplicationRunListeners (org.springframework.boot)
forEach:1259, ArrayList (java.util)
doWithListeners:120, SpringApplicationRunListeners (org.springframework.boot)
doWithListeners:114, SpringApplicationRunListeners (org.springframework.boot)
environmentPrepared:65, SpringApplicationRunListeners (org.springframework.boot)
prepareEnvironment:343, SpringApplication (org.springframework.boot)
run:301, SpringApplication (org.springframework.boot)
run:1303, SpringApplication (org.springframework.boot)
run:1292, SpringApplication (org.springframework.boot)
main:24, AuthorizationApplication (com.springboot.cloud.sysadmin.authorization)

`

[ddavidzhang]

I'm not familiar with how the details of how reconfiguring works. Could you share a snippet of code demonstrating what is being done? Ideally if it can be put in a unit test that is minimal (i.e. doesn't involve Spring), we can add it to our tests when we address this and ensure it works now and going forward. I wonder if there is a way we can register a callback that is run when reconfiguration happens.

I can try to make some tests about this

[ddavidzhang]

Adding a listener of PropertyChangeEvent may be a solution

[ddavidzhang]

I'm not familiar with how the details of how reconfiguring works. Could you share a snippet of code demonstrating what is being done? Ideally if it can be put in a unit test that is minimal (i.e. doesn't involve Spring), we can add it to our tests when we address this and ensure it works now and going forward. I wonder if there is a way we can register a callback that is run when reconfiguration happens.

I can try to make some tests about this

I add some code as below，and it works for my project. The problem is involved by Spring's Refresh Event, I cannot give some unit tests.

@Component
public class Log4J2MetricConfig {
    MeterRegistry meterRegistry;
    Log4j2Metrics binder;

    public Log4J2MetricConfig(MeterRegistry meterRegistry, Log4j2Metrics binder) {
        this.meterRegistry = meterRegistry;
        this.binder = binder;
    }

    @EventListener
    public void handleContextRefreshEvent(RefreshEvent refreshedEvent) {
        if ("Refresh Nacos config".equals(refreshedEvent.getEventDesc())) {
            binder.bindTo(meterRegistry);
        }
    }
}

[pativa]

Hi,

We have a similar issue with the log4j2 metrics. In our log4j2 configuration file, we use monitorInterval (documentation) in order to reload configuration from an external source. When the configuration is reloaded, metrics are no longer counted.

Here is a failing testcase that I believe recreates the issue.

@Test
void doesNotRebindWhenConfigurationIsReloaded() {
	MeterRegistry registry = new SimpleMeterRegistry();
	LoggerContext context = (LoggerContext) LogManager.getContext(false);

	try (Log4j2Metrics metrics = new Log4j2Metrics(emptyList(), context)) {
		metrics.bindTo(registry);

		Logger logger = context.getLogger(getClass());
		Configurator.setLevel(logger, Level.INFO);

		logger.info("first");

		// This will reload the configuration, metrics will not be rebound and the counter will not be incremented
		context.reconfigure();

		logger.info("second");

		// This equals to 1 because the metrics are not rebound
		assertThat(registry.get("log4j2.events").tags("level", "info").counter().count()).isEqualTo(2);
	}
}

I think there might be something that can be done using log4j2 configuration listeners.

[shakuzen]

@pativa thank you for the unit test to reproduce this. If you have an idea for a good solution, feel free to send a pull request. We would be happy to review. I have marked this issue as help wanted.

[pativa]

Sure, I checked it out and think I have a working fix. I'll create a PR!

[pativa]

I realized while the proposed solution solves the case that I posted about (reconfiguring the logger context), it does not actually solve the original problem in this issue (configuring a logger through Spring Boot).

The solution in my PR does not work for programatically added loggers after the context is set up, which is what Spring Boot does, see https://github.com/philwebb/spring-boot/blob/086d289636bfa009cb4ae9dd6587e0d8df3c405c/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/logging/log4j2/Log4J2LoggingSystem.java#L233

The problem is that Log4j2Metrics only registers MetricsFilter when a new Configuration is loaded, but now when a new logger is added to an existing configuration.

I can make another PR for this if you want, after #5822 is merged.

[shakuzen]

As far as I understand, in the original case, the configuration will be re-loaded, but perhaps there are other cases where it won't. We can take it up as a separate issue/additional enhancement.