Rebind `Log4j2Metrics` when `LoggerContext#reconfigure` is called #5756

ddavidzhang · 2024-12-23T02:28:42Z

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 · 2024-12-23T04:35:40Z

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 · 2024-12-23T05:35:39Z

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 · 2024-12-23T05:39:47Z

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 · 2024-12-23T06:27:30Z

Adding a listener of PropertyChangeEvent may be a solution

ddavidzhang · 2024-12-23T11:49:50Z

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 · 2025-01-17T09:46:46Z

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 · 2025-01-17T09:53:14Z

@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 · 2025-01-17T11:38:40Z

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

ddavidzhang added the waiting-for-triage label Dec 23, 2024

shakuzen added help wanted An issue that a contributor can help us with instrumentation An issue that is related to instrumenting a component enhancement A general enhancement module: micrometer-core An issue that is related to our core module and removed waiting-for-triage labels Jan 17, 2025

shakuzen changed the title ~~log4j2Metrics not work when Log4j2 reconfigured~~ Rebind Log4j2Metrics when LoggerContext#reconfigure is called Jan 17, 2025

shakuzen added this to the 1.x milestone Jan 17, 2025

pativa linked a pull request Jan 17, 2025 that will close this issue

Rebind log4j2 metrics if configuration is changed #5810

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Rebind `Log4j2Metrics` when `LoggerContext#reconfigure` is called #5756

Rebind `Log4j2Metrics` when `LoggerContext#reconfigure` is called #5756

ddavidzhang commented Dec 23, 2024

shakuzen commented Dec 23, 2024

ddavidzhang commented Dec 23, 2024 •

edited

Loading

ddavidzhang commented Dec 23, 2024

ddavidzhang commented Dec 23, 2024

ddavidzhang commented Dec 23, 2024

pativa commented Jan 17, 2025

shakuzen commented Jan 17, 2025

pativa commented Jan 17, 2025

Rebind Log4j2Metrics when LoggerContext#reconfigure is called #5756

Rebind Log4j2Metrics when LoggerContext#reconfigure is called #5756

Comments

ddavidzhang commented Dec 23, 2024

shakuzen commented Dec 23, 2024

ddavidzhang commented Dec 23, 2024 • edited Loading

ddavidzhang commented Dec 23, 2024

ddavidzhang commented Dec 23, 2024

ddavidzhang commented Dec 23, 2024

pativa commented Jan 17, 2025

shakuzen commented Jan 17, 2025

pativa commented Jan 17, 2025

Rebind `Log4j2Metrics` when `LoggerContext#reconfigure` is called #5756

Rebind `Log4j2Metrics` when `LoggerContext#reconfigure` is called #5756

ddavidzhang commented Dec 23, 2024 •

edited

Loading