I'm trying to replace our custom logging setup with the new structured logging support. Our setup was using the logstash log format when running in K8s, but not when running tests (CI also runs in K8s, but we prefer "regular" log messages in there when looking at test results, and also when running locally), so we had a logback-spring.xml file like this (logstash format only when running on K8s and not during tests):
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<springProfile name="!kubernetes || test">
<include resource="org/springframework/boot/logging/logback/base.xml"/>
</springProfile>
<springProfile name="kubernetes && !test">
<appender name="jsonConsoleAppender" class="ch.qos.logback.core.ConsoleAppender">
<encoder class="net.logstash.logback.encoder.LogstashEncoder"/>
</appender>
<root level="INFO">
<appender-ref ref="jsonConsoleAppender"/>
</root>
</springProfile>
</configuration>
To replace this, I created application-kubernetes.properties like this:
spring.config.activate.on-profile=!test
logging.structured.format.console=logstash
On first glance this worked, but I noticed that during tests, where many different Spring contexts are being created (some of them have the test profile and some of them don't), when the very first context is initialized, whatever structured logging config is applied there holds for all the subsequent contexts created in the JVM, regardless of whether they declare a different config.
For example, consider the following two tests:
@Slf4j
@SpringBootTest("logging.structured.format.console=logstash")
class StructuredLoggingEnabledTest {
@Test
void contextLoads() {
log.info("SHOULD USE structured logging");
}
}
@Slf4j
@SpringBootTest
class StructuredLoggingDisabledTest {
@Test
void contextLoads() {
log.info("SHOULD NOT USE structured logging");
}
}
When running them individually, the logs are in the configured format. But when running both of them in one go, the logs are in whatever format the first test defines. Here, the test without structured logging runs first, causing the second test with structured logging to also use the default logging:
13:04:34.409 [main] INFO org.springframework.test.context.support.AnnotationConfigContextLoaderUtils -- Could not detect default configuration classes for test class [com.example.demo.StructuredLoggingDisabledTest]: StructuredLoggingDisabledTest does not declare any static, non-private, non-final, nested classes annotated with @Configuration.
13:04:34.488 [main] INFO org.springframework.boot.test.context.SpringBootTestContextBootstrapper -- Found @SpringBootConfiguration com.example.demo.Demo1Application for test class com.example.demo.StructuredLoggingDisabledTest
. ____ _ __ _ _
/\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
\\/ ___)| |_)| | | | | || (_| | ) ) ) )
' |____| .__|_| |_|_| |_\__, | / / / /
=========|_|==============|___/=/_/_/_/
:: Spring Boot :: (v3.4.0)
2024-12-15T13:04:34.769+01:00 INFO 26612 --- [demo1] [ main] c.e.demo.StructuredLoggingDisabledTest : Starting StructuredLoggingDisabledTest using Java 21.0.5 with PID 26612 (started by XXXX in C:\Projects\demo1)
2024-12-15T13:04:34.770+01:00 INFO 26612 --- [demo1] [ main] c.e.demo.StructuredLoggingDisabledTest : No active profile set, falling back to 1 default profile: "default"
2024-12-15T13:04:35.091+01:00 INFO 26612 --- [demo1] [ main] c.e.demo.StructuredLoggingDisabledTest : Started StructuredLoggingDisabledTest in 0.504 seconds (process running for 1.15)
2024-12-15T13:04:35.625+01:00 INFO 26612 --- [demo1] [ main] c.e.demo.StructuredLoggingDisabledTest : SHOULD NOT USE structured logging
[INFO] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.342 s -- in com.example.demo.StructuredLoggingDisabledTest
[INFO] Running com.example.demo.StructuredLoggingEnabledTest
2024-12-15T13:04:35.641+01:00 INFO 26612 --- [demo1] [ main] t.c.s.AnnotationConfigContextLoaderUtils : Could not detect default configuration classes for test class [com.example.demo.StructuredLoggingEnabledTest]: StructuredLoggingEnabledTest does not declare any static, non-private, non-final, nested classes annotated with @Configuration.
2024-12-15T13:04:35.642+01:00 INFO 26612 --- [demo1] [ main] .b.t.c.SpringBootTestContextBootstrapper : Found @SpringBootConfiguration com.example.demo.Demo1Application for test class com.example.demo.StructuredLoggingEnabledTest
2024-12-15T13:04:35.663+01:00 INFO 26612 --- [demo1] [ main] c.e.demo.StructuredLoggingEnabledTest : Starting StructuredLoggingEnabledTest using Java 21.0.5 with PID 26612 (started by XXXX in C:\Projects\demo1)
2024-12-15T13:04:35.663+01:00 INFO 26612 --- [demo1] [ main] c.e.demo.StructuredLoggingEnabledTest : No active profile set, falling back to 1 default profile: "default"
2024-12-15T13:04:35.731+01:00 INFO 26612 --- [demo1] [ main] c.e.demo.StructuredLoggingEnabledTest : Started StructuredLoggingEnabledTest in 0.086 seconds (process running for 1.79)
2024-12-15T13:04:35.733+01:00 INFO 26612 --- [demo1] [ main] c.e.demo.StructuredLoggingEnabledTest : SHOULD USE structured logging
Note that this doesn't just apply to structured logging being enabled or disabled, but any structured logging configuration. It is for example not possible to run one test with logging.structured.format.console=logstash and then another test with logging.structured.format.console=ecs. The first test run always wins, and its configuration applies to all subsequent tests.
Comment From: wilkinsona
Unfortunately, I don't think there's much that we can do about this. The logging configuration is scoped to the class loader and the class loader will, typically, be shared by all of the tests in a module. I believe you'd see similar problems if you tried to use any different logging configuration in different tests of the same module, not just different structured logging configuration.
Given that application contexts can be cached and re-used across tests and that the logging system is configured as part of context initialization, how did you expect things to behave here?
Comment From: kzander91
@wilkinsona I could swear that this worked previously using the logback-spring.xml approach, however now I am no longer able to reproduce it...
I believe you'd see similar problems if you tried to use any different logging configuration
Changing log levels back and forth across tests works, so it seems this statement isn't correct for every kind of logging config.
I'll close this as it turned out not to be a regression then, thanks for your input.
Comment From: wilkinsona
Changing log levels back and forth across tests works, so it seems this statement isn't correct for every kind of logging config.
I think there are cases where even changing log levels won't work:
TestOneruns. It creates a new context and setscom.exampletodebug. The context is cachedTestTworuns. It has different configuration and creates a new context. It setscom.exampletoinfoTestThreeruns and reuses the context fromTestOne. It will useinfolevel forcom.examplelogging rather thandebug