DefaultLogBuilder ignores a throwable inferred by created Message

[YanivKunda]

Description

When using DefaultLogBuilder log* methods, throwable information that might have been inferred by the created Message object is lost - and DefaultLogBuilder only passes the explicit throwable that was set via LogBuilder.withThrowable(Throwable). This is in contradiction to the regular use of Logger methods that accept message+args - which creates a Message using the configured factory, and then uses Message.getThrowable() to extract the throwable.

This was initially assumed as a bug in log4j-transform-maven-plugin (which converts regular Logger calls to LogBuilder): https://github.com/apache/logging-log4j-transform/issues/169 but I realized that it might be a stretch for the plugin to infer this data at build-time to be able to pass it to .withThrowable.

Suggested Fix

Change DefaultLogBuilder's logMessage(Message) code from logger.logMessage(level, marker, fqcn, location, message, throwable); to logger.logMessage(level, marker, fqcn, location, message, throwable != null ? throwable : message.getThrowable());

Configuration

Version: 2.24.3

Operating system: macOS Sonoma 14.7.2 JDK: eclipse-temurin 17.0.13

Logs

Consider the following code:

        Throwable throwable = new Exception("Oh oh");
        String messageFormat = "Hello, {}!";
        String arg = "Problem";
        logger.error(messageFormat, arg, throwable);
        logger.atError().log(messageFormat, arg, throwable);

results in the following output:

14:30:53.223 [main] ERROR net.kundas.Main - Hello, Problem!
java.lang.Exception: Oh oh
	at net.kundas.Main.main(Main.java:11) [classes/:?]
14:30:53.233 [main] ERROR net.kundas.Main - Hello, Problem!

Reproduction

I've tried recreating it in a unit test, but they seem to be using org.apache.logging.log4j.test.TestLogger, which does this inference in its log method:

        final Throwable t;
        if (throwable == null
                && params != null
                && params.length > 0
                && params[params.length - 1] instanceof Throwable) {
            t = (Throwable) params[params.length - 1];
        } else {
            t = throwable;
        }
        if (t != null) {
            sb.append(' ');
            final ByteArrayOutputStream baos = new ByteArrayOutputStream();
            t.printStackTrace(new PrintStream(baos));
            sb.append(baos);
        }

[vy]

@rgoers, both the report and the suggested workaround looks legitimate to me. WDYT?

[rgoers]

The current behavior is actually intentional.

There is a ton of ambiguity involved when the last parameter is a throwable. Log4j 2 included this behavior since it was present in SLF4J, which we were trying hard to be compatible with for the most part. But it was a really bad idea.

The problem here is that just because a throwable occurs as the last parameter does not necessarily mean it will be logged as a throwable. That depends on what the chosen layout chooses to do. In the case of the PatternLayout my recollection is that if there are enough parameters in the format string to include the throwable then it will end up only showing the exception message, otherwise the full stack trace gets printed. Log4j can't know anything about the behavior of a layout at compile time as it has no idea what the configuration will be.

As a consequence, when LogBuilder came along we decided to be explicit about when a throwable will be treated as a throwable - i.e - only when withThrowable is specified. I would be very reluctant to change this.

[garydgregory]

But it was a really bad idea.

I agree on that one! 😉

[YanivKunda]

As a consequence, when LogBuilder came along we decided to be explicit about when a throwable will be treated as a throwable - i.e - only when withThrowable is specified.

Does it mean that Message.getThrowable() is going to get deprecated? What abou this last-param-analysis logic? I assume it is going to remain as-is for backward-compatibility. I found 3 Message implementations that use it for their throwable field:

1. MessageFormatMessage
2. ParameterizedMessage
3. StringFormattedMessage

I'm not sure that my suggestion causes this unwanted compatibility to persist - it's just a fallback mechanism to the Message's throwable.

I understand wanting to keep the API cleaner with less "magic" happening or not in different implementation. However, I originally raised this as an issue with log4j-transform, which converts regular logger calls to LogBuilder, and it would be much harder to support this logic there - it might need to infer which mesage implementation is going to be used, and emulate it or delegate to it somehow in order to extract the throwable if applicable.

Can you suggest any workaround that doesn't involve converting all existing logger calls to use explicit Message instances or convert to LogBuilder?

[garydgregory]

Shouldn't we make this more sane for 3.0 and get rid of this special hidden behavior? It would better IMO.

[ppkarwasz]

The problem here is that just because a throwable occurs as the last parameter does not necessarily mean it will be logged as a throwable. That depends on what the chosen layout chooses to do.

It does not depend on the layout, since this is usually handled in AbstractLogger:

https://github.com/apache/logging-log4j2/blob/23290e480d7c9146af962d1a3707ab7b06648894/log4j-api/src/main/java/org/apache/logging/log4j/spi/AbstractLogger.java#L2630-L2640

The reported issue comes from the fact that the logMessage method with an additional StackTraceElement does not apply the same logic:

https://github.com/apache/logging-log4j2/blob/23290e480d7c9146af962d1a3707ab7b06648894/log4j-api/src/main/java/org/apache/logging/log4j/spi/AbstractLogger.java#L2847-L2863

The behavior is rather inconsistent: sometimes methods that accept Message also use it to produce a Throwable and sometimes they don't. In 3.0.0-beta3 the behavior should be consistent: if throwable is null, Message.getThrowable() is called.

[SgtOmer]

Is there a decision on this issue, whether to consistently calculate the effective throwable or to never calculate it? As we encountered this issue in our own code base, we want to know in what direction to adjust the standards moving forward. Thank you in advance.

[vy]

Is there a decision on this issue

@SgtOmer, not really. 😒

the behavior should be consistent: if throwable is null, Message.getThrowable() is called.

@ppkarwasz, that is a good idea, which is effectively what @YanivKunda was suggesting. I'm inclined to implement this in the next minor 2.x release – objections?