Add Logback's throwable-consuming semantics as an option

[SeasonPanPan]

Description

Hello, we used to use logback in our springboot project, recently migrated to log4j2 and we found that a lot of the exception stack is gone.

For example, in the following example, using logback, you can clearly see the error stack, but log4j2 only has one sentence "java.lang.NullPointerException", I read the source code of log4j2 and feel that this should be a bug. I also test it with version:2.23.1, and the same error.
Additionally, I found that these classes are correct: MessageFormatMessage and StringFormattedMessage.

If you can confirm that this is a bug, I'd be pleasure to submit a PR to fix it.

Configuration

Version: 2.23.1

Operating system: windows/Linux

JDK: "1.8.0_291"

Logs

==> log4j2 result:

20:32:33.887 [main] [ERROR] com.pandas.springboot.demo.DemoApplicationTests - fail to process null, the error is:java.lang.NullPointerException

==> logback result:
2024-03-11 20:37:35.173 ERROR 16840 --- [           main] c.p.s.demo.DemoApplicationTests          : fail to process null, the error is:{}

java.lang.NullPointerException: null
	at com.pandas.springboot.demo.DemoApplicationTests.log(DemoApplicationTests.java:20) [test-classes/:na]
	at com.pandas.springboot.demo.DemoApplicationTests.testLog(DemoApplicationTests.java:15) [test-classes/:na]
	

Reproduction

@SpringBootTest
public class DemoApplicationTests {

	private static final Logger log = LoggerFactory.getLogger(DemoApplicationTests.class);

	@Test
	public void testLog() {
		log(null);
	}

	private static void log(String param) {
		try {
			int b = param.length();
		} catch (Exception e) {
			log.error("fail to process {}, the error is:{}", param, e);
		}
	}
}

[vy]

@SeasonPanPan, could you provide us a minimal log4j2.xml and a minimal pom.xml that we can reproduce the problem using your DemoApplicationTests shared above?

minimal: containing only what is necessary to reproduce the issue and nothing more

[SeasonPanPan]

@vy This is the log4j2.xml

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN">
    <Appenders>
        <Console name="Console" target="SYSTEM_OUT">
            <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] [%-5level] %logger{36} - %msg%n"/>
        </Console>
    </Appenders>
    <Loggers>
        <Root level="info">
            <AppenderRef ref="Console"/>
        </Root>
    </Loggers>
</Configuration>

pom.xml

<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
	xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 https://maven.apache.org/xsd/maven-4.0.0.xsd">
	<modelVersion>4.0.0</modelVersion>
	<parent>
		<groupId>org.springframework.boot</groupId>
		<artifactId>spring-boot-starter-parent</artifactId>
		<version>2.5.0</version>
		<relativePath/> <!-- lookup parent from repository -->
	</parent>
	<groupId>com.example</groupId>
	<artifactId>demo</artifactId>
	<version>0.0.1-SNAPSHOT</version>
	<name>springboot demo</name>
	<description>Demo project for Spring Boot</description>
	<properties>
		<java.version>1.8</java.version>
	</properties>
	<dependencies>
		<dependency>
			<groupId>org.springframework.boot</groupId>
			<artifactId>spring-boot-starter-web</artifactId>
			<exclusions>
				<exclusion>
					<groupId>org.springframework.boot</groupId>
					<artifactId>spring-boot-starter-logging</artifactId>
				</exclusion>
			</exclusions>
		</dependency>

		<dependency>
			<groupId>org.springframework.boot</groupId>
			<artifactId>spring-boot-starter-log4j2</artifactId>
		</dependency>
		<dependency>
			<groupId>org.apache.logging.log4j</groupId>
			<artifactId>log4j-api</artifactId>
			<version>2.19.0</version>
		</dependency>
		<dependency>
			<groupId>org.apache.logging.log4j</groupId>
			<artifactId>log4j-core</artifactId>
			<version>2.19.0</version>
		</dependency>

		<dependency>
			<groupId>org.springframework.boot</groupId>
			<artifactId>spring-boot-starter-test</artifactId>
			<scope>test</scope>
		</dependency>
		
	</dependencies>
</project>

[ppkarwasz]

@SeasonPanPan ,

==> log4j2 result:

20:32:33.887 [main] [ERROR] com.pandas.springboot.demo.DemoApplicationTests - fail to process null, the error is:java.lang.NullPointerException

==> logback result:
2024-03-11 20:37:35.173 ERROR 16840 --- [           main] c.p.s.demo.DemoApplicationTests          : fail to process null, the error is:{}

java.lang.NullPointerException: null
	at com.pandas.springboot.demo.DemoApplicationTests.log(DemoApplicationTests.java:20) [test-classes/:na]
	at com.pandas.springboot.demo.DemoApplicationTests.testLog(DemoApplicationTests.java:15) [test-classes/:na]
	

In my opinion logging a Throwable as message parameter is a bad practice. You should use one of these forms:

log.error("Failed to process {}, the error is: {}", param, e.getMessage());
log.error("Failed to process {}.", param, e);
log.error("Failed to process {}, the error is: {}", param, e.getMessage(), e);

Logback and Log4j Core differ in the way they treat the unconventional call:

log.error("Failed to process {}, the error is: {}", param, e);

but in both cases the result is not what you would expect:

• Logback removes e from the list of parameter, so you end up with a missing parameter,
• Log4j Core respects your wish to have two parameters, so you end up without a throwable in the log event.

In November last year I proposed a change of semantics for dealing with throwables in this dev@logging thread, but we didn't reach a consensus. Feel free to follow up on that.

[SeasonPanPan]

@ppkarwasz I understand how to use log4j, but some developers don't write code properly, some old codes still in our repository. I will tell my team that we couldn't migrate smoothly from logback to log4j2.
Thank you.

[SeasonPanPan]

Also, I found an incompatibility issue, from version 2.19.0 to 2.23.1, for example:

@Test
public void testLog() {
    log.info("first param is {}, second param is {}", "Log4j2");
}

It works ok with v2.19.0, but throw an exception with v2.23.1.
Although the standard way to write is to provide 2 parameters, in fact, there are many developers who write code that is not standardized, but it used to work fine.

2024-03-12T23:55:03.063Z main ERROR Unable to format msg: first param is {}, second param is {} java.lang.IllegalArgumentException: found 2 argument placeholders, but provided 1 for pattern `first param is {}, second param is {}`
	at org.apache.logging.log4j.message.ParameterFormatter.formatMessage(ParameterFormatter.java:248)
	at org.apache.logging.log4j.message.ParameterizedMessage.formatTo(ParameterizedMessage.java:282)
	at org.apache.logging.log4j.core.pattern.MessagePatternConverter$SimpleMessagePatternConverter.format(MessagePatternConverter.java:120)
	at org.apache.logging.log4j.core.pattern.PatternFormatter.format(PatternFormatter.java:44)
	at org.apache.logging.log4j.core.layout.PatternLayout$PatternFormatterPatternSerializer.toSerializable(PatternLayout.java:397)
	at org.apache.logging.log4j.core.layout.PatternLayout.toText(PatternLayout.java:252)
	at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:238)
	at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:58)
	at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.directEncodeEvent(AbstractOutputStreamAppender.java:227)
	at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(AbstractOutputStreamAppender.java:220)
	at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:211)
	at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:160)
	at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:133)
	at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:124)
	at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:88)
	at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:705)
	at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:663)
	at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:639)
	at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:575)
	at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:92)
	at org.apache.logging.log4j.core.Logger.log(Logger.java:169)
	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:2637)
	at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:2402)
	at org.apache.logging.slf4j.Log4jLogger.info(Log4jLogger.java:184)

[ppkarwasz]

@SeasonPanPan,

Today there is an increasing amount of tools to check or reformat logging code:

• Palantir's LoggerInterpolationConsumesThrowable Error Prone rule seems to perfectly fit your problem and can pinpoint the location of problematic log statements,
• there is a very active OpenRewrite Logging Frameworks project that offers many recipes to automatically clean up logging code. I have opened a feature request Add recipe to clone an exception argument openrewrite/rewrite-logging-frameworks#141 to extend the existing CompleteExceptionLogging recipe to your use case. If you have many statements to fix, maybe it is easier to contribute this feature and rewrite your statements automatically.

2024-03-12T23:55:03.063Z main ERROR Unable to format msg: first param is {}, second param is {} >java.lang.IllegalArgumentException: found 2 argument placeholders, but provided 1 for pattern `first param is {}, second param is {}`
  at org.apache.logging.log4j.message.ParameterFormatter.formatMessage(ParameterFormatter.java:248)

This behavior was introduced in 2.21.0 and corrected in #2343, to provide a uniform way of handling missing log statement parameters (the same way StringFormattedMessage does it for String#format formatted messages).

In my personal experience, it is better to detect this kind of errors early in the release cycle. With the previous behavior I remember staring at a literal {} in a production log, because I forgot the relevant parameter in the code.

I am not strongly opinionated regarding this behavior though: we could still fill in the provided parameters, but keep the status logger error message. @vy, what do you think?

[SeasonPanPan]

@ppkarwasz I really appreciate your professional and rigorous way of coding. I'm inclined to the last method you mentioned about keep the status logger error message.

For example, regarding the last log4j2 vulnerability, many companies fix it by replacing the new version of log4j2 in production without enough time to test the compatibility of the new version of log4j2, because the 2.x version is backwards compatible by default. This exception change will cause the program to be unusable in certain scenarios.

I think your change could be more appropriate in version 3.x. What do you think? @vy @ppkarwasz

[rgoers]

@ppkarwasz @vy
I agree that the below is not ideal or what I would recommend but the exception does need be logged as a parameter. Changing this behavior now under the covers is very poor. I can attest that I have seen it in a bunch of code at my employer. Simply logging it as an error is NOT ok. In the case where the number of parameters match the number of placeholders they all need to be included as parameters. Only when the Throwable is "extra" should it be logged as a Throwable.

	private static void log(String param) {
		try {
			int b = param.length();
		} catch (Exception e) {
			log.error("fail to process {}, the error is:{}", param, e);
		}
	}

Logging a warning or error to the status log is perfectly acceptable to me for the following. As I recall we previously simply didn't replace the '{}' sequence. I would recommend allowing a configuration property to re-enable the previous behavior.

@Test
public void testLog() {
    log.info("first param is {}, second param is {}", "Log4j2");
}

I need to also add that when a Throwable is logged using LogBuilder's withThrowable() method it should NEVER be treated as an argument. Likewise when a throwable is included as an argument in the log() method it should ALWAYS be treated only as an argument. Note that DefaultLogBuilder enforces that.

I would personally welcome a PR that changed the behavior to work as I have mentioned here.

[vy]

@SeasonPanPan, thanks so much for the report. This issue is more convoluted than it meets the eye:

1. formatTo() behaviour of ParameterizedMessage and ReusableParameterizedMessage doesn't match
2. DEFAULT_MESSAGE_FACTORY_CLASS and DEFAULT_FLOW_MESSAGE_FACTORY_CLASS fields of AbstractLogger is not respectively read from log4j2.messageFactory and log4j2.flowMessageFactory properties anymore (Yet another bug!)
3. Log4j <2.20.0, 2.23.1, Logback... They all exhibit different behaviours.
4. etc.

Before implementing anything, I want to do some homework first. I will create a list of all corner cases, compare their behaviour across the two different Log4j versions cited above, and then decide on what shall change and in which way. This week I am swamped with other priorities. I believe I can start working on this sometime next week.