Missing Trowables in EventRecordingLogger
Hi, I was recently doing a code review for a coworker and saw that he was concatenating strings and not using the varargs method of building the log message. I asked him why he was doing that and he explained it was because he also had a Throwable that he wanted to be passed as argument to see the stacktrace. He was not aware of the change in SLF4J 1.6.0 which allows us to pass a Throwable as last argument to the varargs. "Unfortunately", when I was showing him implementations of this, I encountered the slf4j EventRecordingLogger and this implementation of the slf4j logger does not comply with this "new" behaviour. However I'm not sure if this is intentional. Assuming it's not intentional, I've created a fork and I've made the required changes. But before I spend "days" on this while it's intentional I thought: let's write a quick email about this and ask for guidance. I also saw that in the case of 2 Object arguments, the MessageFormatter seems to be suboptimal and is creating more objects then strictly required. For the 1 Object argument case it it's also doing too much, certainly in case someone calls it with a Throwable. I've now added a runtime check to it. Since overloading it with a Throwable version will change the way the method behaves in case the caller does not know if it's being given a Throwable or an Object. It would be very illogical to call this method with a Throwable, with the 1.6 way of dealing with Throwables, since what do you want to format then? But with the runtime check people won't loose their stacktraces, and otherwise in case the MessageFormatter is being used in a wrong way people will see their stacktraces being converted into one line because of a (minor? it's one instanceof call too many per call to the one Object logger variant) performance optimization. I've not yet created the test cases for the EventRecordingLogger, I'll do that in case it's indeed unintentional that it's loosing the Throwables. I've added two tests for the changes I made to the MessageFormatter. While I was at it I also applied some improvements IntelliJ suggested. You can see my changes on my fork: https://github.com/qos-ch/slf4j/compare/master...delgurth:eventrecordinglogg... I hope you are able to review my changes and shed your light on it. Kind regards, Wessel van Norel
Hi Wessel, Comments below. On 09/08/2019 01:09, Wessel van Norel wrote:
Hi,
I was recently doing a code review for a coworker and saw that he was concatenating strings and not using the varargs method of building the log message. I asked him why he was doing that and he explained it was because he also had a Throwable that he wanted to be passed as argument to see the stacktrace. He was not aware of the change in SLF4J 1.6.0 which allows us to pass a Throwable as last argument to the varargs.
"Unfortunately", when I was showing him implementations of this, I encountered the slf4j EventRecordingLogger and this implementation of the slf4j logger does not comply with this "new" behaviour. However I'm not sure if this is intentional.
It's not intentional.
Assuming it's not intentional, I've created a fork and I've made the required changes. But before I spend "days" on this while it's intentional I thought: let's write a quick email about this and ask for guidance.
Good idea.
I also saw that in the case of 2 Object arguments, the MessageFormatter seems to be suboptimal and is creating more objects then strictly required.
For the 1 Object argument case it it's also doing too much, certainly in case someone calls it with a Throwable. I've now added a runtime check to it. Since overloading it with a Throwable version will change the way the method behaves in case the caller does not know if it's being given a Throwable or an Object. It would be very illogical to call this method with a Throwable, with the 1.6 way of dealing with Throwables, since what do you want to format then?
But with the runtime check people won't loose their stacktraces, and otherwise in case the MessageFormatter is being used in a wrong way people will see their stacktraces being converted into one line because of a (minor? it's one instanceof call too many per call to the one Object logger variant) performance optimization.
Right.
I've not yet created the test cases for the EventRecordingLogger, I'll do that in case it's indeed unintentional that it's loosing the Throwables. I've added two tests for the changes I made to the MessageFormatter. While I was at it I also applied some improvements IntelliJ suggested.
Very good. In general, it is preferable if the more meaningful changes are separate from more cosmetic ones even if both are welcome.
You can see my changes on my fork:
https://github.com/qos-ch/slf4j/compare/master...delgurth:eventrecordinglogg...
I have made some comments there. In any case, I think the unit test as well the change to the org.slf4j.event.EventRecodingLogger.recordEvent method are warranted. I propose to discuss changes to MessageFormatter class separately. Also can you please create a Jira ticket describing the bug in EventRecodingLogger.recordEvent? Many thanks, -- Ceki
Hi Ceki, Thanks for your quick follow up. My comments will be below as well. On Sun, Aug 11, 2019 at 10:26 PM Ceki Gülcü <ceki@qos.ch> wrote:
Hi Wessel,
Comments below.
On 09/08/2019 01:09, Wessel van Norel wrote:
I've not yet created the test cases for the EventRecordingLogger, I'll do that in case it's indeed unintentional that it's loosing the Throwables. I've added two tests for the changes I made to the MessageFormatter. While I was at it I also applied some improvements IntelliJ suggested.
Very good. In general, it is preferable if the more meaningful changes are separate from more cosmetic ones even if both are welcome.
Sure no problem. Do you want a separate JIRA Ticket for it?
You can see my changes on my fork:
https://github.com/qos-ch/slf4j/compare/master...delgurth:eventrecordinglogg...
I have made some comments there.
From those remarks:
Instead, an analogous check can be placed in recordEvent() avoiding repetition.
Sounds like a good plan. But I'll have to think about how to deal with the 2 object argument calls. Since if just make an two element array out of it and then have to make it into a one element array and a throwable that's a bit wasteful, isn't it?
In any case, I think the unit test as well the change to the org.slf4j.event.EventRecodingLogger.recordEvent method are warranted. I propose to discuss changes to MessageFormatter class separately.
Ok. I'll create a Jira ticket about the MessageFormatter. The stacktrace as last parameter is great for users of slf4j, but for the API implementation it's a bit of a pain. Do you have a performance benchmark around slf4j or specific the messageformatter (since the javadoc says the slf4j version is 10 times faster then the version provided by java itself)? I found a recently created SLF4J JMH project: https://github.com/wsargent/slf4j-benchmark but I'm not sure if that project is doing the proper benchmarking. Also can you please create a Jira ticket describing the bug in
EventRecodingLogger.recordEvent?
Will do.
Many thanks,
-- Ceki
You're most welcome. Kind regards, Wessel _______________________________________________
slf4j-dev mailing list slf4j-dev@qos.ch http://mailman.qos.ch/mailman/listinfo/slf4j-dev
Hello, As you might have seen I've created the issue. I also created the pull request. While adding the test I found another bug inside this EventRecordingLogger. In one case the marker got lost. One of the things I noted while doing this is that the IntelliJ IDEA indent settings for java files is set to 2 spaces, but all code is formatted using 4 spaces. This comes from commit: https://github.com/qos-ch/slf4j/commit/b8b7aaf44d7bb7ecb897ff4327ce8f353d4ae.... Shouldn't it be changed to "4" for java and only be "2" for XML? Kind regards, Wessel
participants (2)
-
Ceki Gülcü -
Wessel van Norel