Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add Logback's throwable-consuming semantics as an option #2363

Open
SeasonPanPan opened this issue Mar 11, 2024 · 14 comments · May be fixed by #2381
Open

Add Logback's throwable-consuming semantics as an option #2363

SeasonPanPan opened this issue Mar 11, 2024 · 14 comments · May be fixed by #2381
Assignees
Labels
api Affects the public API bug Incorrect, unexpected, or unintended behavior of existing code
Milestone

Comments

@SeasonPanPan
Copy link
Contributor

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
Copy link
Member

vy commented Mar 11, 2024

@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
Copy link
Contributor Author

@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>

SeasonPanPan added a commit to SeasonPanPan/logging-log4j2 that referenced this issue Mar 12, 2024
SeasonPanPan added a commit to SeasonPanPan/logging-log4j2 that referenced this issue Mar 12, 2024
@ppkarwasz
Copy link
Contributor

@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
Copy link
Contributor Author

@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
Copy link
Contributor Author

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
Copy link
Contributor

@SeasonPanPan,

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

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
Copy link
Contributor Author

@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
Copy link
Member

rgoers commented Mar 14, 2024

@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
Copy link
Member

vy commented Mar 14, 2024

@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.

@vy vy self-assigned this Mar 14, 2024
@vy vy added bug Incorrect, unexpected, or unintended behavior of existing code api Affects the public API labels Mar 14, 2024
@vy vy added this to the 2.x milestone Mar 14, 2024
@vy vy changed the title [BUG] Exception stack works ok with logback , but a lot of the exception stack is gone with log4j2. Last throwable argument is not used while replacing message placeholders Mar 14, 2024
@ppkarwasz ppkarwasz changed the title Last throwable argument is not used while replacing message placeholders Add Logback's throwable-consuming semantics as an option Mar 14, 2024
@ppkarwasz ppkarwasz modified the milestones: 2.x, 2.24.0 Mar 14, 2024
@ppkarwasz
Copy link
Contributor

ppkarwasz commented Mar 14, 2024

@SeasonPanPan,

As Volkan mentioned, solving your migration issues require 3 ingredients that we will try to incorporate into 2.24.0:

@SeasonPanPan
Copy link
Contributor Author

SeasonPanPan commented Mar 16, 2024

@ppkarwasz @vy
Thank you for taking the time out of your busy schedules to review this issue. If possible, I'd be willing to take on part of the tasks to complete these ingredients.

@ppkarwasz
Copy link
Contributor

@SeasonPanPan,

Thank you for your proposal. #2379 might be a little bit Log4j specific, but I can assign you #2380 if it interests you.

@SeasonPanPan
Copy link
Contributor Author

@SeasonPanPan,

Thank you for your proposal. #2379 might be a little bit Log4j specific, but I can assign you #2380 if it interests you.

@ppkarwasz OK,assign to me

@ppkarwasz
Copy link
Contributor

Not sure how this works on Github. Maybe you need to comment on the issue, for me to be able to assign it to you.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
api Affects the public API bug Incorrect, unexpected, or unintended behavior of existing code
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants