Fix #13883 handle logged null throwable#13884
Conversation
| last, state, lockedStateString(), BufferUtil.toDetailString(closeContent), closedCallback, wake); | ||
| else | ||
| LOG.debug("onWriteComplete({},{}) {}->{} c={} cb={} w={}", | ||
| last, failure, state, lockedStateString(), BufferUtil.toDetailString(closeContent), closedCallback, wake, failure); |
There was a problem hiding this comment.
No need for failure as the last parameter as it's already in second position, as this will make 8 objects for 7 placeholders.
I remember one impl was checking parameters type and if exception doing something different (but we cannot rely on logging impl)
Something to try possibly is the fluent log api, not sure if this displays the stacktrace of Throwable though, as it might depend on the final logging implementation but worth to try:
LoggingEventBuilder loggingEventBuilder = LOG.atDebug();
if(failure != null) loggingEventBuilder = loggingEventBuilder.setCause(failure);
loggingEventBuilder.log("onWriteComplete({},null) {}->{} c={} cb={} w={}",
last, state, lockedStateString(), BufferUtil.toDetailString(closeContent), closedCallback, wake);
There was a problem hiding this comment.
The difference is whether the stack trace is logged though, isn't it?
{} will take the toString only, so we know the exception type and message, while putting it in as a last param makes the logger render the full Throwable nicely.
Of course it depends on your logging intentions.
There was a problem hiding this comment.
The LOG.atDebug().setCause(x)... code is only necessary when you are dealing with code that might have a null Throwable.
The following code blocks are 100% supported by slf4j and log4j2 when the Throwable is not null.
LOG.debug("message", x);
LOG.debug("message with {} params {}", param1, param2, x);Every code block that is in a catch (Throwable) doesn't need to use the LOG.atDebug().setCause(x)... technique, as the Throwable is guaranteed to be not null.
You can undo about 90%+ of the change you just made in this PR.
| { | ||
| if (LOG.isDebugEnabled()) | ||
| LOG.debug(x.getMessage(), x); | ||
| LOG.atDebug().setCause(x).log(x.getMessage()); |
There was a problem hiding this comment.
Not necessary here, you are in a catch block already.
| { | ||
| if (LOG.isDebugEnabled()) | ||
| LOG.debug("Could not initialize {}", processor, x); | ||
| LOG.atDebug().setCause(x).log("Could not initialize {}", processor); |
There was a problem hiding this comment.
Not necessary here, you are in a catch block already.
The Throwable will exist.
| { | ||
| if (LOG.isDebugEnabled()) | ||
| LOG.debug("Connection creation failed {}", reserved, x); | ||
| LOG.atDebug().setCause(x).log("Connection creation failed {}", reserved); |
There was a problem hiding this comment.
Not necessary here, you are in a catch block already.
The Throwable will exist.
| { | ||
| if (LOG.isDebugEnabled()) | ||
| LOG.debug("Authentication failed", x); | ||
| LOG.atDebug().setCause(x).log("Authentication failed"); |
There was a problem hiding this comment.
Not necessary here, you are in a catch block already.
The Throwable will exist.
| { | ||
| if (LOG.isDebugEnabled()) | ||
| LOG.debug("Unable to send headers on exchange {}", exchange, x); | ||
| LOG.atDebug().setCause(x).log("Unable to send headers on exchange {}", exchange); |
There was a problem hiding this comment.
Not necessary here, you are in a catch block already.
The Throwable will exist.
| { | ||
| if (LOG.isDebugEnabled()) | ||
| LOG.debug("failure while notifying listener {}", listener, x); | ||
| LOG.atDebug().setCause(x).log("failure while notifying listener {}", listener); |
There was a problem hiding this comment.
Not necessary here, you are in a catch block already.
The Throwable will exist.
| { | ||
| if (LOG.isDebugEnabled()) | ||
| LOG.debug("failure while notifying listener {}", listener, x); | ||
| LOG.atDebug().setCause(x).log("failure while notifying listener {}", listener); |
There was a problem hiding this comment.
Not necessary here, you are in a catch block already.
The Throwable will exist.
| { | ||
| if (LOG.isDebugEnabled()) | ||
| LOG.debug("failure while notifying listener {}", listener, x); | ||
| LOG.atDebug().setCause(x).log("failure while notifying listener {}", listener); |
There was a problem hiding this comment.
Not necessary here, you are in a catch block already.
The Throwable will exist.
| { | ||
| if (LOG.isDebugEnabled()) | ||
| LOG.debug("failure while notifying listener {}", listener, x); | ||
| LOG.atDebug().setCause(x).log("failure while notifying listener {}", listener); |
There was a problem hiding this comment.
Not necessary here, you are in a catch block already.
The Throwable will exist.
| { | ||
| if (LOG.isDebugEnabled()) | ||
| LOG.debug("failure while notifying listener {}", listener, x); | ||
| LOG.atDebug().setCause(x).log("failure while notifying listener {}", listener); |
There was a problem hiding this comment.
Not necessary here, you are in a catch block already.
The Throwable will exist.
|
@joakime @sbordet I was thinking of only using the builder style when it was strictly needed, but then that is an NP-complete problem to fully calculate. So in the end, I thought it was just best to use the fluent style whenever we want to add a cause. It will then be the default pattern we use and we don't have to think about what happens if the throwable is null. |
sbordet
left a comment
There was a problem hiding this comment.
@joakime @sbordet I was thinking of only using the builder style when it was strictly needed, but then that is an NP-complete problem to fully calculate.
I think you're exaggerating. There are probably just a handful of places outside of catch blocks or fail-style methods such as fail(Throwable) that we need to fix.
And I think a warning is way too severe of an event to emit for a DEBUG log that has an extra parameter that is null and won't actually log anything either way, so I'd categorize this as a LOG4J weirdness for which we should not really sweat too much.
We certainly do not want to have a utility wrapper also for logging!
Well if we used some kind of @NotNull annotation, then this would not be an issue. But what is wrong with using the fluent style anyway, as I think it is clearer than having to count "{}" to see if the last arg is treated as a cause or just an arg. |
IntelliJ tells you this btw. |
@joakime No it doesn't. It tells you if you have the number wrong. But it does not tell you which of the two correct interpretations you are using. Last arg can be a cause or an arg depending on the number of {} |
If you use the Throwable as the 
If you have a parameter, and attempt to use 
The proper usage. (no error) 
|
I don't agree with intellij's colorization in this case. |
…883-logNullThrowable # Conflicts: # jetty-core/jetty-server/src/main/java/org/eclipse/jetty/server/handler/ContextHandler.java
| (_enterScopeSetClassloaderFailed.compareAndSet(false, true) ? LOG.atWarn() : LOG.atDebug()) | ||
| .setCause(x) | ||
| .log("Error setting a context classloader on thread {}", Thread.currentThread()); |
There's no ambiguity, the API for There are no argument parameters or what you call "cause" in that use case. Here's the docs for how Throwable is treated in various logging libraries.
|
|
Be gentle with fluent style, it will cause more object creation. |
|
@joakime you are just re-enforcing my point that there is ambiguity in that API because they have both Best to avoid that ambiguity (be it perceived or actual). The fluent API allows for a clear statement of intent. The cost is a trivial even wrapper, which will not significantly change object allocation. |
|
@sbordet Can I get this reviewed before you go away. I think these changes are good:
|
sbordet
left a comment
There was a problem hiding this comment.
I am not thrilled, but also there are some obvious goodnesses, so LGTM.
| if (LOG.isDebugEnabled()) | ||
| LOG.debug("{} while invoking onTimeout listener {}", x.toString(), listener, x); | ||
| LOG.atDebug().setCause(x).log("{} while invoking onTimeout listener {}", x.toString(), listener); | ||
| else | ||
| LOG.warn("{} while invoking onTimeout listener {}", x.toString(), listener); |
There was a problem hiding this comment.
You should not change the level you log at based on what level is enabled on the logger. The isXxxxEnabled methods should generally only be used for performance optimisation, avoiding building objects to pass them to a logger that will then discard them.
| if (LOG.isDebugEnabled()) | ||
| LOG.debug("{} while invoking onError listener {}", x, listener, x); | ||
| LOG.atDebug().setCause(x).log("{} while invoking onError listener {}", x, listener); | ||
| else | ||
| LOG.warn("{} while invoking onError listener {}", x, listener); |
There was a problem hiding this comment.
You should not change the level you log at based on what level is enabled on the logger. The isXxxxEnabled methods should generally only be used for performance optimisation, avoiding building objects to pass them to a logger that will then discard them.
…883-logNullThrowable
We can fix issue #13883 with this, but a) it is a bit verbose and b) I'm sure there are other spots in the code.
Utility method maybe ?