SpringApplication.java (and other classes?) logging indicates wrong class.

[rjlasko]

Hello Spring Devs!

I am a longtime Spring user, but a recent initiate into the world of Spring Boot.

To start, I am not certain if I have encountered a genuine issue with Spring Boot, or if i have missed a configuration somewhere. A brief look at the SpringBoot code base suggests that this is the result of an intentional design decision. The problem is that I think that the effect is to lead developers and system maintainers using the SpringBoot framework to be mislead about where (some) logs may be generated, at least in this case.

When running a class that I have defined as a @SpringBootTest, I've noticed a several logs emitted that claim to be from my test class, but simply aren't so. Here is an output of my logs generated by running one of these tests.

-------------------------------------------------------
 T E S T S
-------------------------------------------------------
Running com.mypackage.MyTest

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::        (v1.5.4.RELEASE)

2017-06-21 12:51:14.412 [main] INFO  com.mypackage.MyTest:48 - Starting MyTest on myLaptop with PID 55561 (started by me in /Users/me/workspace/project)
2017-06-21 12:51:14.412 [main] DEBUG com.mypackage.MyTest:51 - Running with Spring Boot v1.5.4.RELEASE, Spring v4.3.5.RELEASE
2017-06-21 12:51:14.413 [main] INFO   com.mypackage.MyTest:597 - The following profiles are active: test
2017-06-21 12:51:14.471 [main] INFO   com.mypackage.MyTest:57 - Started MyTest in 0.18 seconds (JVM running for 2.055)
Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.105 sec - in com.mypackage.MyTest
Running com.mypackage.MyTest

The problem is this: I don't have any log statements in MyTest.java, so here I was trying to track down logging statements that were not even in my code base.

Here is a copy of my class...

package com.mypackage;

import org.junit.Test;
import org.junit.runner.RunWith;
import org.springframework.boot.test.context.SpringBootTest;
import org.springframework.test.context.ActiveProfiles;
import org.springframework.test.context.junit4.SpringRunner;
@RunWith(SpringRunner.class)
@SpringBootTest
@ActiveProfiles({ "test" })
public class MyTest {
    @Test
    public void contextLoads() {
        // intentionally doing nothing
    }
}

Eventually, I tracked down one of the offending logs having text, "The following profiles are active:", and found that it was actually located in org.springframework.boot.SpringApplication on the stated line number. I can only assume that the same thing applies to the other logs that I noted here. In this case (line #3), I would expect the correct behavior to indicate that the log message was coming from the SpringApplication class. Yes, I understand that the unit test is acting as a SpringApplication, but I don't think that is an argument for the log statement to lie about which class generated a log indicating what the active profiles were. I know that my class set the stated profile, but the log should reflect where that setting was detected, which is within SpringApplication.java.

thanks!

[rjlasko]

I would also like to point out that to disable this log, I would need to disable the logging on the class that I am testing. Truthfully, i would prefer to disable logging on org.springframework.boot.SpringApplication.

[wilkinsona]

Thanks for the detailed analysis. This behaviour is indeed due to an intentional design decision and I think it's unlikely to change. Using the application's main class for the logging makes it very clear which application is starting. That can be useful when reviewing logs from tests and at runtime.

I would also like to point out that to disable this log, I would need to disable the logging on the class that I am testing

That's not the case. You can set logStartupInfo to false to disable this logging.

[rjlasko]

Thanks for the tip on the setting. I found your StackOverflow comment on this, and up-voted it!