Fix #13883 handle logged null throwable

[gregw]

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 ?

[olamy]

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);

[TWiStErRob]

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.

[joakime]

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.

[joakime]

Not necessary here, you are in a catch block already.

[joakime]

Not necessary here, you are in a catch block already.
The Throwable will exist.

[joakime]

Not necessary here, you are in a catch block already.
The Throwable will exist.

[joakime]

Not necessary here, you are in a catch block already.
The Throwable will exist.

[joakime]

Not necessary here, you are in a catch block already.
The Throwable will exist.

[joakime]

Not necessary here, you are in a catch block already.
The Throwable will exist.

[joakime]

Not necessary here, you are in a catch block already.
The Throwable will exist.

[joakime]

Not necessary here, you are in a catch block already.
The Throwable will exist.

[joakime]

Not necessary here, you are in a catch block already.
The Throwable will exist.

[joakime]

Not necessary here, you are in a catch block already.
The Throwable will exist.

[sbordet]

I agree with @joakime that we should only use the builder style only when necessary.

[gregw]

@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]

@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!

[gregw]

@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.

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.

[joakime]

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.
Not enough (or too many) {}, it's an error.
If there is 1 more param than {} then the last one better be a Throwable, otherwise it's an error.

[gregw]

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. Not enough (or too many) {}, it's an error. If there is 1 more param than {} then the last one better be a Throwable, otherwise it's an error.

@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 {}

[joakime]

@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 {}...
Note the colorization of the {}, on my color scheme this means there is no associated method parameter that fits this {}.

If you have a parameter, and attempt to use {} on it...
Note the colorization of the {}, the left hand one has an associated method parameter, the second one doesn't.

The proper usage. (no error)

[gregw]

@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 {}... Note the colorization of the {}, on my color scheme this means there is no associated method parameter that fits this {}.

I don't agree with intellij's colorization in this case. LOG.debug("whoops {}", ex); is a perfectly valid usage of the API. It is a little ambiguous, hence the reason this PR is a good idea. Using the fluent API removes the ambiguity if a passed Throwable is a cause or an argument.

[gregw]

@joakime @sbordet Also with the fluent style, code like this is much nicer as it avoids duplicating the log call!

[joakime]

I don't agree with intellij's colorization in this case. LOG.debug("whoops {}", ex); is a perfectly valid usage of the API. It is a little ambiguous, hence the reason this PR is a good idea. Using the fluent API removes the ambiguity if a passed Throwable is a cause or an argument.

There's no ambiguity, the API for LOG.debug("whoops {}", ex) is for the method Logger.debug(String msg, Throwable t)

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.

• slf4j (last arg Throwable is special) - https://slf4j.org/faq.html#paramException
• log4j (last arg Throwable is special) same behavior in log4j1 and log4j2 - https://logging.apache.org/log4j/2.x/manual/api.html#best-practice-exception
• java.util.logging (Throwable specific methods) - https://docs.oracle.com/en/java/javase/17/docs/api/java.logging/java/util/logging/Logger.html
• commons-logging (Throwable specific methods) - https://commons.apache.org/proper/commons-logging/apidocs/org/apache/commons/logging/Log.html

[joakime]

Be gentle with fluent style, it will cause more object creation.

[gregw]

@joakime you are just re-enforcing my point that there is ambiguity in that API because they have both debug(String, Throwable) and debug(String, Object) and debug(String, Object...) !

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.

[gregw]

@sbordet Can I get this reviewed before you go away. I think these changes are good:

• consistently use the same API for handling causes
• There is no visual or real ambiguity about if a throwable should be logged as a string or a cause
• trivial additional builder cost only if debug is turned on

[sbordet]

I am not thrilled, but also there are some obvious goodnesses, so LGTM.