Aren't loggers in Java supposed to execute functions in the arguments only if the log level is reached? So here in my example I would have assumed that "Did additional work" would only appear once. What am I missing here?
import lombok.extern.slf4j.Slf4j;
import org.junit.jupiter.api.Test;
@Slf4j
public class LogTest {
@Test
void test() {
runDebug();
runInfo();
}
private void runInfo() {
log.info("hi @ info {}", additional());
}
public void runDebug() {
log.debug("hello @ debug {}", additional());
}
private String additional() {
log.info("Did additional work...");
return "sup";
}
}
Console output:
15:10:28.249 [main] INFO test.LogTest -- Did additional work...
15:10:28.252 [main] INFO test.LogTest -- Did additional work...
15:10:28.252 [main] INFO test.LogTest -- hi @ info sup
PS. I read SonarQube: Invoke method(s) only conditionally and SonarQube: "Invoke method(s) only conditionally". I think I understood those, but in my case it doesn't seem to work correctly. In my work project I have a similar case and SonarQube is saying it's an issue.
As Rob Spoor's answer says, it is impossible for an argument not to be evaluated before being passed to a method, and log.debug
gets called only after all its arguments are evaluated. However, most logging libraries (other than Slf4j) allow you to pass lambdas, and the logging method only evaluates the lambda if the level is high enough such that the log would be printed. For example, log4j2 allows this:
log.debug("hello @ debug {}", () -> additional());
or even more succinctly:
log.debug(() -> "hello @ debug " + additional());
Similarly, java.util.logging allows this:
log.log(DEBUG, () -> "hello @ debug " + additional());
Unfortunately, in slf4j the syntax for passing a lambda is very verbose:
log.atDebug().setMessage("hello @ debug {}").addArgument(() -> additional()).log();
Thus, people who don't want to use this new "fluent" API due to its verbosity would have to use the old-style way (which is still much shorter than the new way):
if (log.isDebugEnabled()) log.debug("hello @ debug {}", additional());