Only remove Throwable if unconsumed by pattern.

[huxi]

This is a preparation for a LOGBACK-1183 fix while keeping the optimizations of LOGBACK-873 in place.

It replaces the package-private method Throwable getThrowableCandidate(Object[] argArray) with a public Throwable extractUnconsumedThrowable(String messagePattern, Object[] argArray) method.

The unit test that was actually verifying the wrong behavior before has been changed and extended for both cases:

• a Throwable at the end of the argument array is removed if is not "consumed" by the message pattern.
• a Throwable at the end of the argument array is left intact if it is "consumed" by the message pattern.

"consumed" means that a placeholder in the message pattern exists that will be replaced by the Throwable. If we assume an argument array {"bar", new Throwable()} then the pattern "foo {} {}" would "consume" the Throwable resulting in the formatted string "foo bar java.lang.Throwable" while the pattern "foo {}" would not consume the Throwable resulting in the formatted string "foo bar". This was the behavior of Logback below 1.1.

The extractUnconsumedThrowable method would then by used by Logback instead of EventArgUtil.extractThrowable.

I initially tried to fix LOGBACK-1183 solely in Logback but had to realize that SLF4J would later remove the Throwable anyway while formatting the message, regardless of whether or not EventArgUtil.extractThrowable left it intact in the argument array.

LoggingEvent in Logback would then see the following change: Original code:

    private Throwable extractThrowableAndRearrangeArguments(Object[] argArray) {
        Throwable extractedThrowable = EventArgUtil.extractThrowable(argArray);
        if (EventArgUtil.successfulExtraction(extractedThrowable)) {
            this.argumentArray = EventArgUtil.trimmedCopy(argArray);
        }
        return extractedThrowable;
    }

New code:

    private Throwable extractThrowableAndRearrangeArguments(String messagePattern, Object[] argArray) {
        Throwable extractedThrowable = MessageFormatter.extractUnconsumedThrowable(messagePattern, argArray);
        if (EventArgUtil.successfulExtraction(extractedThrowable)) {
            this.argumentArray = EventArgUtil.trimmedCopy(argArray);
        }
        return extractedThrowable;
    }

This private method is only called in the constructor. Original code:

        if (throwable == null) {
            throwable = extractThrowableAndRearrangeArguments(argArray);
        }

New code:

        if (throwable == null) {
            throwable = extractThrowableAndRearrangeArguments(message, argArray);
        }

Applying those two changes in Logback would fix LOGBACK-1183.

[ceki]

@huxi It is clear that you have given this more thought than I have.

I was under the impression that it was generally OK to consume the throwable if it's the last argument regardless of the {} placeholders in the pattern. There have been no complaints about this approach until LOGBACK-1183.

Do we really want to support the case covered by LoggerMessageFormattingRegressionTest.formattingRegression ?

[huxi]

@ceki It was supported previously, is supported in log4j2 and this regression actually bit me in production.

Counting the tokens is seriously fast, i.e. in no way comparable to the performance impact of actually formatting a message.

If you want to optimize message formatting further then try to get rid of trimmedCopy because that causes unnecessary GC pressure.

I re-implemented the SLF4J MessageFormatter in MessageFormatter and SafeString with enhanced abilities (error resilient, better formatting style than Java (e.g. byte[] formatted as hex, null can be distinguished from "null", empty Collection<String> can be distinguished from Collection<String> containing only a single empty String), etc.) and exhaustive tests.

I'm 100% OK if you want to "steal" any or all of that code. java.time support requires Java 8 so that would have to be removed and formatting of java.util.Date to UTC-ISO8601 String would hav to be re-implemented differently, for example.

[akhomchenko]

Agreement was reached that this issue (https://github.com/qos-ch/logback/pull/374) need to be fixed here.

[akhomchenko]

@ceki any help is required with this? I've also faced an issue with throwable trimmed by MessageFormatter

[fenik17]

@ceki i'm agree that it's a regression, and needs to be fixed.

I was under the impression that it was generally OK to consume the throwable if it's the last argument regardless of the {} placeholders in the pattern

If someone uses a placeholder in a template, he expects that placeholder will be replaced with text...

@huxi an approach from your patch has a big CPU overhead due to a double parse of the messagePattern. I think that it's enough to check the count of replaced placeholders (L variable) at the end of the arrayFormat() method. Something like this:

        if (L < argArray.length) {
            argArray = trimmedCopy(argArray); 
        }

[huxi]

@fenik17 I'm not sure what you mean about the big CPU overhead. I was aiming for a minimal change and counting is only performed if the last entry is actually a Throwable.

I think it's more questionable if trimming the array (i.e. creating a copy of the original array minus the last entry) is necessary at all - but I wanted to keep the scope of the PR manageable.

[akhomchenko]

Can I provide any help with this issue?

[jezovuk]

I was hit by this today (via Netty, in their AbstractChannelHandlerContext). Any chance of releasing the fix soon?

[ceki]

@jezovuk Can you please provide a reference/copy of the implicated lines of code in AbstractChannelHandlerContext?

[jezovuk]

https://github.com/netty/netty/blob/4.1/transport/src/main/java/io/netty/channel/AbstractChannelHandlerContext.java#L294

Copy of problematic code (log warn in else if branch within the catch block is problematic since it has two args, both Throwable):

private void invokeExceptionCaught(final Throwable cause) {
    if (invokeHandler()) {
        try {
	    handler().exceptionCaught(this, cause);
        } catch (Throwable error) {
	    if (logger.isDebugEnabled()) {
                logger.debug(
		    "An exception {}" +
                    "was thrown by a user handler's exceptionCaught() " +
                    "method while handling the following exception:",
                        ThrowableUtil.stackTraceToString(error), cause);
            } else if (logger.isWarnEnabled()) {
                logger.warn(
                    "An exception '{}' [enable DEBUG level for full stacktrace] " +
                    "was thrown by a user handler's exceptionCaught() " +
                    "method while handling the following exception:", error, cause);
            }
        }
    } else {
        fireExceptionCaught(cause);
    }
}

Example output of said log warn:

An exception '{}' [enable DEBUG level for full stacktrace] was thrown by a user handler's exceptionCaught() method while handling the following exception:
-- stack trace corresponding to 'cause' here --

[komu]

I got a bug report from a user of my library saying that exceptions are not printed correctly and after some investigation found this bug. The offending line in my code was:

log.warn("rolled back transaction because of exception: {}", e, e); 

Changing the code to the following fixes the problem, but feels like a silly thing to do:

log.warn("rolled back transaction because of exception: {}", e.toString(), e); 

Surely it might be better to not include the exception in the actual message and leave it to the format to decide, but it's something that people do anyway.