BasicBinder Trace Logging Causes Duplicated Message
Description
Attachments
Activity
Nathan Xu May 27, 2021 at 5:14 PM
Finally a new version of jboss-logging was released (3.4.2.Final). I created a PR here in Hibernate to bump the dependency minor version:
Nathan Xu October 26, 2020 at 11:20 PM
Finally the jboss-logging PR was merged.
Nathan Xu August 7, 2020 at 7:01 PM
PR created at . Fingers crossed. Once it was merged and published, I am gonna update the dependency version to fix the issue.
Nathan Xu August 7, 2020 at 6:25 PMEdited
I narrowed down the root cause. It was due to the following bug in the org.jboss.logging:jboss-logging:3.3.2.Final (which is one of the dependencies of Hibernate):
Changing the highlighted pat to this.messageFactory.newMessage(String.valueOf(message))
would fix the bug.
The bug only shows up in log4j2. It seems not an issue for log4j, though.
I am gonna create a PR at soon.
Nathan Xu August 7, 2020 at 8:35 AM
thanks. seems a pretty inspiring exposure of some universal pattern. will try to reproduce the issue to solve it.
When binding a parameter that includes the text {} the BasicBinder String.format call will include the value as part of the messagePattern passed to the logger. When using log4j {} is interpreted as a variable to be replaced by a argument, and since no arguments are supplied the entire message is considered to be an argument.
As a result, when a log message should be: binding parameter [2] as [VARCHAR] - [{}]
it ends up getting logged as: binding parameter [2] as [VARCHAR] - [binding parameter [2] as [VARCHAR] - [{}]]