suspected tiny bug in logging statement

[Redeeman]

I got this:
2022-04-11 19:18:15.106 [pool-2-thread-1] WARN o.d.transaction.DefaultTransaction - rolled back transaction because of exception: {}
i guess the {} should be removed, or assigned in

[komu]

Hi, thanks for the report!

I've been staring at the offending line for quite some time and can't figure out what the problem is. The exception is logged here:

dalesbred/dalesbred/src/main/java/org/dalesbred/transaction/DefaultTransaction.java

Lines 58 to 62 in 4f53ff6

	} catch (Exception e) {
	connection.rollback();
	log.warn("rolled back transaction because of exception: {}", e, e);
	throw Throwables.propagate(e, SQLException.class);
	}

That looks just like it should be: first the message template itself, then e as the parameter for the message and then e second time as the exception to be logged.

I wrote a short standalone program to check this:

fun main() {
    val log = LoggerFactory.getLogger("my-logger")
    val e1 = Exception("first")
    val e2 = Exception("second")
    log.error("testing format string: {}", e1, e2)
}

Output is:

09:04:58.026 [main] ERROR my-logger - testing format string: {}
java.lang.Exception: second
	at org.dalesbred.LogbackTestKt.main(LogbackTest.kt:9)
	at org.dalesbred.LogbackTestKt.main(LogbackTest.kt)

If I change the format call to log.error("testing format string: {}", e1.toString(), e2), then I get the expected result:

09:05:49.035 [main] ERROR my-logger - testing format string: java.lang.Exception: first
java.lang.Exception: second
	at org.dalesbred.LogbackTestKt.main(LogbackTest.kt:9)
	at org.dalesbred.LogbackTestKt.main(LogbackTest.kt)

Calling toString on the exception kind of defeats the purpose of using format string in the first place.

I spent some time inside debugger to find out what goes wrong and it seems to be a bug in logback. First it correctly detects the last parameter as the exception of the log-event, extracts it from the parameter list and trims the parameter list to include only the first parameter. Everything goes as it should be. However, next it calls org.slf4j.helpers.MessageFormatter.arrayFormat which removes the from the remaining list again. This causes the parameter list to be empty and the resulting message to be incorrect.

After having a feeling for this issue I did some searching and found issue LOGBACK-1302. There's also a PR qos-ch/slf4j#166 which fixes the problem, but it's been open since 2016, so I wouldn't hold my breath on it landing soon. It's quite disappointing.

Since it seems like no fix is coming soon, I'll work around the problem in Dalesbred by calling toString() manually on the exceptions.