Spring Boot - @Slf4j Logging Behavior differs in Test and in real Application-CodePudding

I have a sample class like this,

import lombok.extern.slf4j.Slf4j;

@Slf4j
public class TestLogging {

    public void printLogLevel(){

        if(log.isErrorEnabled()){
            log.error("Error Enabled");
        }

        if(log.isTraceEnabled()){
            log.trace("Trace Enabled");
        }

        if(log.isInfoEnabled()){
            log.info("Info Enabled");
        }

        if(log.isDebugEnabled()){
            log.debug("DEBUG enabled");
        }
    }
}

I have written a test case like this,

import org.junit.Test;

public class TestLoggingTest {
    TestLogging testLogging = new TestLogging();

    @Test
    public void testLoggingLevel(){
        testLogging.printLogLevel();
    }
}

When I run this test the below items gets printed to console.

19:48:54.661 [main] ERROR com.tejas.springlogging.TestLogging - Error Enabled
19:48:54.665 [main] INFO com.tejas.springlogging.TestLogging - Info Enabled
19:48:54.666 [main] DEBUG com.tejas.springlogging.TestLogging - DEBUG enabled

But when I run the printLogLevel() from application like this,

@SpringBootApplication
@Slf4j
public class SpringLoggingApplication {

    public static void main(String[] args) {
        SpringApplication.run(SpringLoggingApplication.class, args);

        TestLogging testLogging = new TestLogging();
        testLogging.printLogLevel();
    }

}

The below lines gets printed to console.

2021-10-12 20:05:27.183 ERROR 8924 --- [           main] com.tejas.springlogging.TestLogging      : Error Enabled
2021-10-12 20:05:27.183  INFO 8924 --- [           main] com.tejas.springlogging.TestLogging      : Info Enabled

Below are the dependencies I have used for this testing.

        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter</artifactId>
        </dependency>

        <dependency>
            <groupId>org.projectlombok</groupId>
            <artifactId>lombok</artifactId>
            <scope>optional</scope>
        </dependency>

        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-test</artifactId>
            <scope>test</scope>
        </dependency>
        <dependency>
            <groupId>org.junit.vintage</groupId>
            <artifactId>junit-vintage-engine</artifactId>
            <scope>test</scope>
            <exclusions>
                <exclusion>
                    <groupId>org.hamcrest</groupId>
                    <artifactId>hamcrest-core</artifactId>
                </exclusion>
            </exclusions>
        </dependency>

and this is the parent pom version.

    <parent>
        <groupId>org.springframework.boot</groupId>
        <artifactId>spring-boot-starter-parent</artifactId>
        <version>2.5.5</version>
        <relativePath/> <!-- lookup parent from repository -->
    </parent>

Now the question is, why there is a difference when I call the printLogLevel() method from test and from application. The debug level gets printed only from test. May I know why?

EDIT: Adding @SpringBootTest fixes this issue as suggest by @narendra, but it works only with junit5. I want the fix in junit4

CodePudding user response：

In application, it is using Slf4j in Spring application context, and because of this it uses Spring's default pattern for logging. The default log level is INFO.

See Log Format for Spring.

This pattern is different from SLF4j default pattern.

With no configuration, the default output includes the relative time in milliseconds, thread name, the level, logger name, and the message followed by the line separator for the host. In log4j terms it amounts to the "%r [%t] %level %logger - %m%n" pattern. Sample output follows.
 176 [main] INFO examples.Sort - Populating an array of 2 elements in reverse order.  
 225 [main] INFO examples.SortAlgo - Entered the sort method.
 304 [main] INFO examples.SortAlgo - Dump of integer array:
 317 [main] INFO examples.SortAlgo - Element [0] = 0

The default log level would depend on initialization of logger for plain SLF4j logging.

Solution: You can add SpringBootTest to test class for uniform logging pattern.

CodePudding user response：

@Slf4j annotation has nothing to do with Spring. Its a lombok annotation that gets into action during the compile time (while spring boot is a runtime framework). So putting this annotation is essentially the same as placing a static field that holds the reference to the initialized slf4j logger.

Now slf4j by itself doesn't print anything, instead it relies on the underlying logging libraries which are actually able to print actual log messages.

So the changes are that you have something like logback-spring.xml or logback.xml in the sources of the application and the logging framework that SLF4J delegates to gets initialized from. Spring boot also has some sane defaults when it comes to logging. Since spring boot can also integrate with, say, log4j2, its hard to tell what exactly is happening in your application, so you should check that.

Now, during the test, the situation is different. You've shown a unit test that has nothing do to with spring. So it runs "on-its-own" with slf4j enabled.

And the actual behavior of logger again depends on how did you configure slf4j for tests.