The parameter -Dlog4j2.debug does not take effect in version 2.23.0, and StatusLogger.debug will no longer print logs

[panbingkun]

Description

When we upgraded log4j2 from version 2.22.1 to 2.23.0 in Spark, we found that logs that could have been printed before are no longer being printed.

Configuration

# This log4j config file is for integration test SparkConfPropagateSuite.
rootLogger.level = debug
rootLogger.appenderRef.stdout.ref = console

appender.console.type = Console
appender.console.name = console
appender.console.target = SYSTEM_ERR
appender.console.layout.type = PatternLayout
appender.console.layout.pattern = %d{HH:mm:ss.SSS} %p %c: %maxLen{%m}{512}%n%ex{8}%n

Version: [Log4j version]
2.23.0

Operating system: [OS and version]
Ubuntu 22.04.4 LTS And macos Sonama 14.3.1.

JDK: [JDK distribution and version]
JDK 17

Logs

The following are the logs printed in version 2.22.1:

...

TRACE StatusLogger DefaultConfiguration cleaning Appenders from 1 LoggerConfigs.
DEBUG StatusLogger Stopped org.apache.logging.log4j.core.config.DefaultConfiguration@384ad17b OK
TRACE StatusLogger Reregistering MBeans after reconfigure. Selector=org.apache.logging.log4j.core.selector.ClassLoaderContextSelector@5852c06f
TRACE StatusLogger Reregistering context (1/1): '5ffd2b27' org.apache.logging.log4j.core.LoggerContext@31190526
TRACE StatusLogger Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=5ffd2b27'
TRACE StatusLogger Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=5ffd2b27,component=StatusLogger'
TRACE StatusLogger Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=5ffd2b27,component=ContextSelector'
TRACE StatusLogger Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=5ffd2b27,component=Loggers,name=*'
TRACE StatusLogger Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=5ffd2b27,component=Appenders,name=*'
TRACE StatusLogger Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=5ffd2b27,component=AsyncAppenders,name=*'
TRACE StatusLogger Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=5ffd2b27,component=AsyncLoggerRingBuffer'
TRACE StatusLogger Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=5ffd2b27,component=Loggers,name=*,subtype=RingBuffer'
DEBUG StatusLogger Registering MBean org.apache.logging.log4j2:type=5ffd2b27
DEBUG StatusLogger Registering MBean org.apache.logging.log4j2:type=5ffd2b27,component=StatusLogger
DEBUG StatusLogger Registering MBean org.apache.logging.log4j2:type=5ffd2b27,component=ContextSelector
DEBUG StatusLogger Registering MBean org.apache.logging.log4j2:type=5ffd2b27,component=Loggers,name=
DEBUG StatusLogger Registering MBean org.apache.logging.log4j2:type=5ffd2b27,component=Appenders,name=console
TRACE StatusLogger Using default SystemClock for timestamps.
DEBUG StatusLogger org.apache.logging.log4j.core.util.SystemClock supports precise timestamps.
TRACE StatusLogger Using DummyNanoClock for nanosecond timestamps.
DEBUG StatusLogger Reconfiguration complete for context[name=5ffd2b27] at URI /Users/yangjie01/Tools/4.0/spark-4.0.0-SNAPSHOT-bin-3.3.6/conf/log4j2.properties (org.apache.logging.log4j.core.LoggerContext@31190526) with optional ClassLoader: null
DEBUG StatusLogger Shutdown hook enabled. Registering a new one.
...

In version 2.23.0, StatusLogger related logs are no longer printed, eg

DEBUG StatusLogger Reconfiguration complete for context[name=5ffd2b27] at URI /Users/yangjie01/Tools/4.0/spark-4.0.0-SNAPSHOT-bin-3.3.6/conf/log4j2.properties (org.apache.logging.log4j.core.LoggerContext@31190526) with optional ClassLoader: null

The above logs will no longer be output.

Reproduction

The relevant upgrade PR in Spark is
apache/spark#45292

I found that it was caused by the following changes:

• log4j2 version 2.22.1
  https://github.com/apache/logging-log4j2/blob/rel/2.22.1/log4j-api/src/main/java/org/apache/logging/log4j/spi/AbstractLogger.java#L252-L254
  

  https://github.com/apache/logging-log4j2/blob/rel/2.22.1/log4j-api/src/main/java/org/apache/logging/log4j/spi/AbstractLogger.java#L2336-L2346
  

  logging-log4j2/log4j-api/src/main/java/org/apache/logging/log4j/status/StatusLogger.java

  Lines 480 to 487 in 8469975

  	public boolean isEnabled(final Level level, final Marker marker) {
  	if (DEBUG_ENABLED) {
  	return true;
  	}
  	if (listeners.size() > 0) {
  	return listenersLevel >= level.intLevel();
  	}
  	return logger.isEnabled(level, marker);

  
  

  https://github.com/apache/logging-log4j2/blob/rel/2.22.1/log4j-api/src/main/java/org/apache/logging/log4j/status/StatusLogger.java#L82-L83
  

• log4j2 version 2.23.0
  https://github.com/apache/logging-log4j2/blob/rel/2.23.0/log4j-api/src/main/java/org/apache/logging/log4j/status/StatusLogger.java#L747-L752
  

• The related commit that caused this change is:
  

Is this change in line with our expectations? Or this is a bug?

[ppkarwasz]

@panbingkun,

In release 2.23.0 the StatusLogger was entirely rewritten to work around some circular dependency problems we were having.

This is clearly a bug (IMHO the implementation of StatusLogger#getLevel is faulty). Could you submit a PR?

[vy]

@panbingkun, no need to submit a PR. I am taking care of this.

[panbingkun]

@panbingkun,

In release 2.23.0 the StatusLogger was entirely rewritten to work around some circular dependency problems we were having.

This is clearly a bug (IMHO the implementation of StatusLogger#getLevel is faulty). Could you submit a PR?

Okay, thank you very much for your reply.
Let me wait for the next opportunity for the first submission of log4j2 😄

[panbingkun]

@panbingkun, no need to submit a PR. I am taking care of this.

Thanks.

[vy]

@panbingkun, I have merged the fix to 2.x branch. Could you give the 2.23.1-SNAPSHOT a try once this CI job successfully completes, and share the outcome, please?

[panbingkun]

@panbingkun, I have merged the fix to 2.x branch. Could you give the 2.23.1-SNAPSHOT a try once this CI job successfully completes, and share the outcome, please?

Sure, let we to do it now.

[vy]

Sure, let we to do it now.

@panbingkun, the CI job has successfully completed – needed a kick. Would you mind giving 2.23.1-SNAPSHOT a try and sharing the outcome, please?

[panbingkun]

Sure, let we to do it now.

@panbingkun, the CI job has successfully completed – needed a kick. Would you mind giving 2.23.1-SNAPSHOT a try and sharing the outcome, please?

@vy @ppkarwasz

After testing, it was found that it still did not output the expected log information.
I analyzed it and found that StatusLogger.isEnable is working well now, but the method StatusConsoleListener.log still seems to have some issues, as follows:

logging-log4j2/log4j-api/src/main/java/org/apache/logging/log4j/status/StatusConsoleListener.java

Lines 135 to 141 in c542041

	public void log(final StatusData data) {
	requireNonNull(data, "data");
	if (level.isLessSpecificThan(data.getLevel())) {
	final String formattedStatus = data.getFormattedStatus();
	stream.println(formattedStatus);
	}
	}

The above method does not consider whether the debugging mode is turned on,
So, I proposed a follow-up pr: #2340,
Because I only have a rough understanding of log4j2, if the above modifications are incorrect, please correct me. Thank you very much!