javaperformanceloggingsonarqube

SonarQube: Invoke method(s) only conditionally - logger executes not needed functions


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.


Solution

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