fix duplicated logging issue in Log4j2Logger

[NathanQingyangXu]

The issue was found in a ticket of Hibernate: https://hibernate.atlassian.net/browse/HHH-14139

See the ticket for details.

[NathanQingyangXu]

Without the above fix, the following newMessage() overloaded method would be chosen:

    public Message newMessage(Object message) {
        return new ObjectMessage(message);
    }

That explains why the following logging statement

log.trace("hello {}");

would end up with the following strange output:

hello hello {}

because the object per se would be chosen as the sole parameter for the placeholder (i.e. {}):

public class ObjectMessage implements Message, StringBuilderFormattable {
... ...
    public Object[] getParameters() {
        return new Object[]{this.obj};
    }
... ...

[jamezp]

I'm not able to reproduce this with log4j2. Is it only reproducible with the chain of log4j2, slf4j and logback?

[NathanQingyangXu]

I found the issue while working on a hibernate-orm bug. Seems an obvious bug from code logic. Do you require me to attach a testing case for the PR?

…

On Wed., Oct. 21, 2020, 16:46 James R. Perkins, ***@***.***> wrote: I'm not able to reproduce this with log4j2. Is it only reproducible with the chain of log4j2, slf4j and logback? — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#36 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AB6UYAVGJIGRLO7IAY2FJYLSL5CDHANCNFSM4PX5A3PQ> .

[jamezp]

I found the issue while working on a hibernate-orm bug. Seems an obvious bug from code logic. Do you require me to attach a testing case for the PR?

No, there is no test required. I was just trying to reproduce it as I added some tests. Since it does allow objects to be passed we likely need to allow it. I just need to read about how log4j uses it.

[jamezp]

I think we should do something like:

this.messageFactory.newMessage((message instanceof String) ? (String) message : message)

[jamezp]

Or actually maybe should use a CharSequence instead of a string.

[NathanQingyangXu]

I think the gist of this PR is to maintain consistency in the following two cases:

• non-empty parameter list is provided;
• empty parameter list is provided;

We solved the first case by

this.messageFactory.newMessage(String.valueOf(message), parameters)

because of the following method signature:

    public Message newMessage(String message, Object... params) {
        return new MessageFormatMessage(message, params);
    }

I think we should strive to invoke the same method in case 2. For that reason, I think the original PR makes sense.
String.valueOf() is much stronger than String casting and I do think its usage should be retained consistently.

What is the issue in this PR?
Because we wanna avoid invoking this.messageFactory.newMessage(message) for it would lead to the following statement:

public Message newMessage(Object message) {
        return new ObjectMessage(message);
    }

However, in log4j2 (not in log4j), there exists the following methods in org.apache.logging.log4j.message.ObjectMessage class:

    public Object getParameter() {
        return this.obj;
    }

    public Object[] getParameters() {
        return new Object[]{this.obj};
    }

That is the root cause of the bug. Suppose the following message is provided without any parameter:

binding parameter [someName] as [VARCHAR] - [{}]

the message per se would be treated as the parameter for the {} placeholder and the final logging statement would be:

binding parameter [someName] as [VARCHAR] - [binding parameter [someName] as [VARCHAR] - [{}]]

Thus the bug and the gist of this PR.

[NathanQingyangXu]

Another approach is the following statement:

this.messageFactory.newMessage(String.valueOf(message), parameters == null ? new String[0] : parameters),

[NathanQingyangXu]

I adopted the above approach. It enjoys the benefit that same method would be used consistently regardless of whether parameter is empty or not.

[jamezp]

Sorry for all the delays on this. I finally had a chance to look at what the ObjectMessage does and I think your initial approach was correct. I apologize for that. If we always use the MessageFormatMessage then it's processed through a formatter where as just using the SimpleMessage just the message will be returned and won't be processed through a formatter.

[NathanQingyangXu]

I'm not able to reproduce this with log4j2. Is it only reproducible with the chain of log4j2, slf4j and logback?

Originally I faced the same issue to reproduce it. Please see the comments in https://hibernate.atlassian.net/browse/HHH-14139 on how to reproduce it.
When you can reproduce it, the bug is self-explanatory.

[NathanQingyangXu]

No worries. Do you want me to revert back to the initial code changes, then?

…

On Thu., Oct. 22, 2020, 18:06 James R. Perkins, ***@***.***> wrote: ***@***.**** commented on this pull request. ------------------------------ In src/main/java/org/jboss/logging/Log4j2Logger.java <#36 (comment)> : > @@ -52,7 +52,7 @@ protected void doLog(final Level level, final String loggerClassName, final Obje if (this.logger.isEnabled(translatedLevel)) { try { this.logger.logMessage(loggerClassName, translatedLevel, null, - (parameters == null || parameters.length == 0) ? this.messageFactory.newMessage(message) : this.messageFactory.newMessage(String.valueOf(message), parameters), + (parameters == null || parameters.length == 0) ? this.messageFactory.newMessage(String.valueOf(message)) : this.messageFactory.newMessage(String.valueOf(message), parameters), Sorry for all the delays on this. I finally had a chance to look at what the ObjectMessage does and I think your initial approach was correct. I apologize for that. If we always use the MessageFormatMessage then it's processed through a formatter where as just using the SimpleMessage just the message will be returned and won't be processed through a formatter. — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#36 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AB6UYATI6F7W6ZCEHG6Z3O3SMCUGXANCNFSM4PX5A3PQ> .

[jamezp]

Sorry for the delay again @NathanQingyangXu. Yes I think your original idea was best IMO. I really appreciate all the work and detailed descriptions on this!

[NathanQingyangXu]

Sorry for the delay again @NathanQingyangXu. Yes I think your original idea was best IMO. I really appreciate all the work and detailed descriptions on this!

I reverted back the original status. My fault to create the PR based on my master branch so I cannot force push and for that reason I've to commit the third time to have it reverted back.