[LOG4J2-3585] Exception in Parameterized Message not logged using LocationAwareLogger API

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 2.17.1
• Component/s: SLF4J Bridge

Environment

Windows 10, Tomcat 9, Java 8

• Assignee: Piotr Karwasz
• Reporter: Marian Barton
• Created: 31/Aug/22 14:33
• Updated: 26/Sep/22 11:30
• Resolved: 01/Sep/22 04:08

Description

Versions:

• slf4j-api version 1.7.36
• log4j-core/log4j-slf4j-impl: 2.17.1

Action:

Logging a message using LocationAwareLogger.log including an exception as unused last parameter in the params array.

Result:

The message is constructed correctly but the exception is being ignored and not logged.

Expected:

According to the SLF4J FAQ, passing an exception as unused parameter in the last place should result in it being interpreted as Exception and logged as such.

Example:

// Method in wrapping custom logger
public void error(final String message, final Object... argArray) {
    logger.log(null, FQCN, LocationAwareLogger.ERROR_INT, message, argArray, null);
}

// Call from another class to that method
String someString = "insertedString";
LOGGER.log("Test {}", someString, someException);

// Result - no exception logged, only message
2022-Aug.-31 12:41:59,829 [https-openssl-nio-443-exec-4] some.Class
  ERROR Test insertedString

// this works though
public void error(final String message, final Object... argArray) {
    logger.error(message, argArray);
}

The same call works when not using the LocationAwareLogger log method but the standard logger.error(String message, Object... argArray) method. But since I am using a wrapping logger I have to use the LocationAwareLogger interface in order to conserve the location information.

Possible solution:

I debugged a bit to try and find the issue and I might have found the problem inside the org.apache.logging.slf4j.Log4jLogger.log method:

@Override
public void log(final Marker marker, final String fqcn, final int level, final String message, final Object[] params, Throwable throwable) {
    final Level log4jLevel = getLevel(level);
    final org.apache.logging.log4j.Marker log4jMarker = getMarker(marker);
    if (!logger.isEnabled(log4jLevel, log4jMarker, message, params)) {
        return;
    }
    final Message msg;
    if (CONVERTER != null && eventLogger && marker != null && marker.contains(EVENT_MARKER)) {
        msg = CONVERTER.convertEvent(message, params, throwable);
    } else if (params == null) {
        msg = new SimpleMessage(message);
    } else {
        msg = new ParameterizedMessage(message, params, throwable);
        if (throwable != null) {
            throwable = msg.getThrowable();
        }
    }
    logger.logMessage(fqcn, log4jLevel, log4jMarker, msg, throwable);
}

The problem here specifically being this part:

} else {
    msg = new ParameterizedMessage(message, params, throwable);
    if (throwable != null) {
        throwable = msg.getThrowable();
    }
}

Log4J successfully detects this as and creates a ParameterizedMessage. This instance also correctly found the Throwable from the parameters and set it to its throwable property.

Now I think the bug here is that the if condition is inverted. As I have no Throwable explicitly passed to this method (because it is passed via the params), it is currently null. In this case SLF4J should check if a Throwable is set and if not try to get it from the ParameterizedMessage, because there it was successfully detected inside the constructor.

The correct implementation would therefore be:

} else {
    msg = new ParameterizedMessage(message, params, throwable);
    if (throwable == null) {
        throwable = msg.getThrowable();
    }
}

If the throwable is not set here, it remains inside the ParameterizedMessage and is ignored by Log4J, as Log4J appears to only respect the explicit Throwable parameter.

Any questions, feedback and help are/is appreciated.

Issue Links

• duplicates: LOG4J2-2863 LocationAwareLogger implementation fails to extract throwable from message