Make StatusLogger self-contained and testable

[vy]

Motivated by #2204 and making log4j-api-2.x adaptable by Log4j 3, this work revamps the StatusLogger to make it self-contained and testable. Noteworthy changes are as follows:

Simplifications and improvements for self-contained implementation

• Dependencies on PropertiesUtil and LoaderUtil are eliminated. To do so, simple system property and resource from classpath readers are implemented. See the new StatusLogger.Config class.
• Dependency on SimpleLogger is eliminated. The default listener is fixed to a StatusConsoleListener which dumps StatusData#getFormattedStatus() output to a PrintStream.
• [behavioural change] StatusConfiguration does not create a new StatusListener each time anymore. That is, there will not be a dedicated StatusConsoleListener for every each LoggerContext. Existing behaviour was already problematic:
  • Each StatusConfiguration created was resetting the StatusLogger listener level (hence, last one always wins)
  • Created StatusConsoleListeners weren't cleaned up
  • Even though there was a dedicated listener for each LoggerContext, there is always a single StatusLogger, defeating the purpose of per-LoggerContext listeners
• Hence, we embraced a simpler model: There is one default StatusConsoleListener for the StatusLogger singleton. If user overrides the StatusLogger configuration in a log4j2.xml, last read configuration will be the effective one.
• Several StatusLogger javadocs are rewritten.
• LowLevelLogUtil is removed.
• AbstractLogger doesn't act on log4j2.messageFactory and log4j2.flowMessageFactory properties anymore; its message and flow message factories are fixed to ParameterizedMessageFactory and DefaultFlowMessageFactory, respectively. This was necessary to avoid cyclic instantiation: PropertiesUtil is using StatusLogger, which extends AbstractLogger, which indirectly reaches back to PropertiesUtil for these two functionalities removed.

Testing-related changes

• StatusLogger is made extendable (to enable mocking/spying)
• StatusLogger static instance is made replaceable (to enable substituting the implementation for tests)
• Leveraging these, @UsingStatusLoggerMock introduced

TODO

• Introduce log4j2.messageFactory and log4j2.flowMessageFactory properties back
• Update docs
• Fix last remaining failing tests (already fixed some)
• Check if there are any refactoring opportunities for @UsingStatusListener

Review kit

1. Start with reviewing changes in o.a.l.l.status package: StatusLogger, StatusData, StatusConsoleListener, etc.
2. Review StatusConfiguration
3. Review o.a.l.l.test.junit.StatusLoggerMockExtension to see testing conveniences
4. Review the rest

[rgoers]

I will go through this as I can. It might take a couple of days depending on my available time. However, the description of the solution above seems to aim right on target.

[ppkarwasz]

This looks almost ready.

Remark the PropertiesUtil.Environment does not log anything about broken property sources to prevent a recursive initialization. Now we can start logging again.

[jvz]

I like this approach so far!

[vy]

@ppkarwasz, I have introduced the fallback listener concept back in cd3fadb. Would you mind reviewing it, please?

[ppkarwasz]

LGTM

[lauredogit]

Hi,
This change caused an issue when running on Java 8 and having configured a DateFormat for the StatusLogger (e.g. via log4j2.StatusLogger.DateFormat).

It will cause a StackOverflowError such as:

Caused by: java.lang.StackOverflowError
	at org.apache.logging.log4j.message.ParameterFormatter.analyzePattern(ParameterFormatter.java:93)
	at org.apache.logging.log4j.message.ParameterizedMessage.<init>(ParameterizedMessage.java:142)
	at org.apache.logging.log4j.message.ParameterizedMessage.<init>(ParameterizedMessage.java:176)
	at org.apache.logging.log4j.message.ParameterizedNoReferenceMessageFactory.newMessage(ParameterizedNoReferenceMessageFactory.java:105)
	at org.apache.logging.log4j.message.AbstractMessageFactory.newMessage(AbstractMessageFactory.java:103)
	at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2686)
	at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:2460)
	at org.apache.logging.log4j.spi.AbstractLogger.warn(AbstractLogger.java:3674)
	at org.apache.logging.log4j.spi.AbstractLogger.handleLogMessageException(AbstractLogger.java:2927)
	at org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2909)
	at org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2859)
	at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2841)
	at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2687)
	at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:2460)
	at org.apache.logging.log4j.spi.AbstractLogger.warn(AbstractLogger.java:3674)
	at org.apache.logging.log4j.spi.AbstractLogger.handleLogMessageException(AbstractLogger.java:2927)

which is caused by

java.time.temporal.UnsupportedTemporalTypeException: Unsupported field: YearOfEra
        at java.time.Instant.getLong(Instant.java:603)
        at java.time.format.DateTimePrintContext.getValue(DateTimePrintContext.java:298)
        at java.time.format.DateTimeFormatterBuilder$NumberPrinterParser.format(DateTimeFormatterBuilder.java:2551)
        at java.time.format.DateTimeFormatterBuilder$CompositePrinterParser.format(DateTimeFormatterBuilder.java:2190)
        at java.time.format.DateTimeFormatter.formatTo(DateTimeFormatter.java:1746)
        at java.time.format.DateTimeFormatter.format(DateTimeFormatter.java:1720)
        at org.apache.logging.log4j.status.StatusData.getFormattedStatus(StatusData.java:170)
        at org.apache.logging.log4j.status.StatusConsoleListener.log(StatusConsoleListener.java:138)
        at org.apache.logging.log4j.status.StatusLogger.notifyListener(StatusLogger.java:555)
        at org.apache.logging.log4j.status.StatusLogger.notifyListeners(StatusLogger.java:549)
        at org.apache.logging.log4j.status.StatusLogger.logMessage(StatusLogger.java:526)
        at org.apache.logging.log4j.spi.AbstractLogger.log(AbstractLogger.java:2812)
        at org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2906)
        at org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2859)
        at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2841)
        at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2620)
        at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:2567)
        at org.apache.logging.log4j.spi.AbstractLogger.warn(AbstractLogger.java:3469)

because in org.apache.logging.log4j.status.StatusLogger.Config#readInstantFormatter, the code is merely

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

Lines 252 to 255 in f05864d

	private static DateTimeFormatter readInstantFormatter(final Properties fileProvidedProperties) {
	final String format = readProperty(fileProvidedProperties, STATUS_DATE_FORMAT);
	return format != null ? DateTimeFormatter.ofPattern(format) : null;
	}

with only DateTimeFormatter.ofPattern(format)

This works on Java 11, but on Java 8, it breaks as in https://stackoverflow.com/questions/25229124/unsupportedtemporaltypeexception-when-formatting-instant-to-string

A very simple fix is to use instead

        private static DateTimeFormatter readInstantFormatter(final Properties fileProvidedProperties) {
            final String format = readProperty(fileProvidedProperties, STATUS_DATE_FORMAT);
            return format != null ? DateTimeFormatter.ofPattern(format).withZone(ZoneId.systemDefault()) : null;
        }

Hence using
DateTimeFormatter.ofPattern(format).withZone(ZoneId.systemDefault())

[vy]

@lauredogit, thanks so much for the report. I will submit a fix. We are considering a 2.23.1 release sometime soon, maybe next week?

[lauredogit]

Perfect, thanks!

I think there are 2 distinct issues at play.

The easy one to fix is the actual UnsupportedTemporalTypeException on Java 8, which will be fixed easily by adding the ".withZone(ZoneId.systemDefault())".

However, the other issue is that having such an exception thrown by the StatusLogger was causing a StackOverflowError...
and this was not mitigated by AbstractLogger.logMessageTrackRecursion().

This can be investigated later on, though.

[ppkarwasz]

Well, logMessageTrackRecursion only tracks recursion, it doesn't do anything about it. Other parts of the system like async logger read the recursion level (and log synchronously for example).