Monday, May 20, 2024

Spring Boot logs in JSON format, assert logged output in a test-case . . .

Development is fun and sometimes frustrating too. Everything comes with some kind or other issues attached.

Scenario

Lately, I had to switch Spring Boot out-of-the-box Logback to Log4j2 logging, and specifically to JSON format. One of the test-cases that I had written was to test a feature-flag-based conditional scenario. The conditional code that depends on the feature-flag which is exposed as an external property and injected via @ConfigurationProperties bean into a service, when disabled writes a log message at WARN level to indicate that the feature is disabled. The unit-test has a test case written to test the disabled scenario which also tests the expected log message by leveraging Spring provided OutputCaptureExtension. This annotation, when used at test class level or method level like: @ExtendWith(OutputCaptureExtension.class) makes output log available to the test-case for verification.

That test-case when I switched logging to JSON using Log4j2 failed due to output log unavailable.

Environment: Java 21, Spring Boot 3.2.5, maven 3.9.6 on macOS Catalina 10.15.7

This post is about few things learned along the way: Log4j2 JSON logging, Spring Boot's JUnit Jupiter extension to capture System output, and the Log4j2 JSON Layout property to let the output be captured and available.

JSON logs

To switch Spring boot application logging to JSON using Log4j2 the following dependencies need to be added to maven build file pom.xml. Also, make sure to run mvn dependency:tree and see if you see spring-boot-starter-logging. If you have that as a transitive dependency, exclude it from all dependencies that bring it in. In the following dependencies, I had Spring Modulith that I had to exclude it from.

<dependency> <groupId>org.springframework.modulith</groupId> <artifactId>spring-modulith-starter-core</artifactId> <exclusions> <exclusion> <groupId>org.springframework.boot</groupId> <artifactId>spring-boot-starter-logging</artifactId> </exclusion> </exclusions> </dependency> <!-- logging --> <dependency> <groupId>org.springframework.boot</groupId> <artifactId>spring-boot-starter-log4j2</artifactId> </dependency> <dependency> <groupId>org.apache.logging.log4j</groupId> <artifactId>log4j-layout-template-json</artifactId> </dependency> <dependency> <groupId>com.fasterxml.jackson.dataformat</groupId> <artifactId>jackson-dataformat-yaml</artifactId> </dependency>

Add the following configuration file: main/resources/log4j2.yml. Log4j2 supports XML and YML:

Configuration: name: default Appenders: Console: name: console_appender target: SYSTEM_OUT follow: true JSONLayout: compact: true objectMessageAsJsonObject: true eventEol: true stacktraceAsString: true properties: true KeyValuePair: - key: '@timestamp' value: '$${date:yyyy-MM-dd HH:mm:ss.SSS}' Loggers: Root: name: root.logger level: info AppenderRef: ref: console_appender

With the above changes, application logs will be in JSON format.

Assert Captured output in a test-case

If you have any test-case that was verifying the captured log output in a test-case, it would fail.

For instance, I had a test-case like the following which was verifying the log message logged by myService.method(). To make it work, the above highlighted property - follow: true needs to be added in the log4j2.yml configuration. The details about this console appender property is documented in the OutputCaptureExtension Java doc

import org.junit.jupiter.api.Test; import org.junit.jupiter.api.extension.ExtendWith; import org.mockito.InjectMocks; import org.mockito.Mock; import org.mockito.junit.jupiter.MockitoExtension; import org.springframework.boot.test.system.CapturedOutput; import org.springframework.boot.test.system.OutputCaptureExtension; import org.springframework.test.util.ReflectionTestUtils; import static org.assertj.core.api.Assertions.*; import static org.junit.jupiter.api.Assertions.assertAll; import static org.mockito.Mockito.verify; @ExtendWith(MockitoExtension.class) @ExtendWith(OutputCaptureExtension.class) class MyFeatureFlagTest { @InjectMocks private MyService myService; @Test void call_should_not_handleEvent_when_featureFlag_is_disabled(CapturedOutput output) { // given: mocked behavior ReflectionTestUtils.setField(myService, "featureFlag", false); // when: method under test is called myService.method(); // verify: the output captured assertAll( () -> assertThat(output).contains("The featureFlag is DISABLED."); } }

That's it.

References

No comments:

Post a Comment