Add logging event validation features

README.md

@@ -385,6 +385,109 @@ Maven:
 </dependency>
 ```
 
+### 📝 Logback support
+
+`CapturedLoggingTraits` captures the log statements emitted during a test and asserts them against a [validation-file-assertions](https://github.com/cronn/validation-file-assertions) file.
+This makes it easy to lock down exactly what your code logs — the levels, the messages, the MDC context, and any exceptions — and to catch regressions when logging output changes unexpectedly.
+
+`CapturedLoggingTraits` is a mixin interface. Implement it in your test class and wrap the relevant section of your tests in `withCapturedConsoleLogging(...)`. The captured logging events are rendered to a stable, human-readable format and compared with a validation file:
+
+```java
+class OrderServiceTest implements CapturedLoggingTraits {
+
+    private static final Logger log = LoggerFactory.getLogger("sample.logger");
+
+    @Test
+    void logsEachLevel() {
+        withCapturedConsoleLogging(() -> {
+            log.debug("a debug message");
+            log.info("an info message");
+            log.warn("a warning message");
+            log.error("an error message");
+        });
+    }
+}
+```
+
+The example above produces:
+
+```text
+[sample.logger] [DEBUG] a debug message
+[sample.logger] [INFO ] an info message
+[sample.logger] [WARN ] a warning message
+[sample.logger] [ERROR] an error message
+```
+
+Logging events with configured MDC values are automatically rendered into the log lines:
+
+```text
+[sample.logger] [ERROR] Something went wrong
+    java.lang.IllegalStateException: boom
+[sample.logger] [INFO ] {user=alice, requestId=abc-123} handling request
+```
+
+To run assertions against logging events instead of validation file comparisons, you can also use `LogbackCaptor` to access the logging events:
+
+```java
+@Test
+void captureLogsAsList() throws Exception {
+    LogbackCaptor captor = getLogbackCaptor();
+    captor.captureLoggingDuring(() -> {
+        log.info("This is informative");
+        try (MDC.MDCCloseable userId = MDC.putCloseable("user.id", "123")) {
+            log.warn("This is a warning for a user");
+        }
+    });
+
+    // Check that the MDC value is present with an assertion
+    assertThat(captor.getCapturedLoggingEvents())
+        .anyMatch(it -> it.getMDCPropertyMap().containsKey("user.id"));
+}
+```
+
+To avoid bloated validation files with many unrelated logging events, we recommend to configure an `EventFilter` restricted to a specific list of interesting loggers.
+The default list can be configured by overriding the `defaultCapturedLoggingEventFilter()` method from `CapturedLoggingTraits`, as well as on each capture call:
+
+```java
+// only warnings and above
+withCapturedConsoleLogging(() -> { ... }, EventFilter.atLeastWarning());
+
+// only events from a specific logger
+withCapturedConsoleLogging(() -> { ... }, EventFilter.forClass(OrderService.class));
+
+// only events at INFO or higher
+withCapturedConsoleLogging(() -> { ... }, Level.INFO);
+```
+
+When a test captures more than one block, pass a suffix to write each to its own validation file:
+
+```java
+withCapturedConsoleLogging(() -> log.info("first block"), "first");
+withCapturedConsoleLogging(() -> log.info("second block"), "second");
+```
+
+Behavior can be customized by overriding the interface defaults, for example `capturedLoggerName()` (defaults to the root logger), `defaultCapturedLoggingLevel()` (defaults to `DEBUG`), `capturedLoggingRenderingOptions()` (control whether the logger name and level are included and how the logger name is padded), `defaultCapturedLoggingEventFilter()`, or `defaultValidationNormalizerForCapturedLogging()` to normalize non-deterministic parts of the output before comparison. Any exception thrown by the action is propagated after the log has been captured.
+
+Gradle:
+```groovy
+testImplementation("de.cronn:test-utils:{version}") {
+    capabilities {
+        requireCapability("de.cronn:test-utils-logback-support")
+    }
+}
+```
+
+Maven:
+```xml
+<dependency>
+    <groupId>de.cronn</groupId>
+    <artifactId>test-utils</artifactId>
+    <version>{version}</version>
+    <scope>test</scope>
+    <classifier>logback-support</classifier>
+</dependency>
+```
+
 ### 🛡️ Authorization Test Support
 
 AuthorizationTestUtil generates an authorization matrix for a running Spring MVC application as a Markdown table.

build.gradle

@@ -48,6 +48,7 @@ sourceSets {
 	springSupport {}
 	jpaQueryCapturingSupport {}
 	authorizationTestSupport {}
+	logbackSupport {}
 }
 
 java {
@@ -78,6 +79,10 @@ java {
 		usingSourceSet(sourceSets.authorizationTestSupport)
 		withSourcesJar()
 	}
+	registerFeature("logbackSupport") {
+		usingSourceSet(sourceSets.logbackSupport)
+		withSourcesJar()
+	}
 }
 
 test {
@@ -132,6 +137,10 @@ dependencies {
 	authorizationTestSupportImplementation "org.springframework.boot:spring-boot-web-server"
 	authorizationTestSupportApi "org.junit.jupiter:junit-jupiter-api"
 
+	logbackSupportApi "ch.qos.logback:logback-classic:1.5.38"
+	logbackSupportApi "de.cronn:commons-lang:1.6"
+	logbackSupportApi "de.cronn:validation-file-assertions:0.9.0"
+
 	testImplementation "org.assertj:assertj-core"
 	testImplementation "org.mockito:mockito-core"
 	testImplementation "org.junit.platform:junit-platform-launcher"

settings.gradle

@@ -13,3 +13,4 @@ include ":spring-boot-tests:hibernate"
 include ":spring-boot-tests:postgres"
 include ":spring-boot-tests:jpa-query-capturing"
 include ":spring-boot-tests:authorization-test"
+include ":spring-boot-tests:logback"

spring-boot-tests/logback/build.gradle

@@ -0,0 +1,21 @@
+plugins {
+    id "java-library"
+}
+
+dependencies {
+    testImplementation platform("org.springframework.boot:spring-boot-dependencies:${rootProject.ext.springBootVersion}")
+    testImplementation "org.springframework.boot:spring-boot-starter-test"
+    testImplementation "org.assertj:assertj-core"
+    testImplementation(project(":")) {
+        capabilities {
+            requireCapability("de.cronn:test-utils-logback-support")
+        }
+    }
+    runtimeOnly "org.junit.platform:junit-platform-launcher"
+}
+
+test {
+    inputs.dir("data/test/validation")
+    outputs.dir("data/test/output")
+    outputs.dir("data/test/tmp")
+}

spring-boot-tests/logback/data/test/validation/CapturedLoggingTraitsTest_capturedFromGivenLevel_logging.txt

@@ -0,0 +1 @@
+[                           sample.logger] [INFO ] captured info

spring-boot-tests/logback/data/test/validation/CapturedLoggingTraitsTest_multilineMessage_logging.txt

@@ -0,0 +1,3 @@
+[                           sample.logger] [INFO ] first line
+                                                   second line
+[                           sample.logger] [INFO ] another message

spring-boot-tests/logback/data/test/validation/CapturedLoggingTraitsTest_multipleBlocksWithSuffix_first.txt

@@ -0,0 +1 @@
+[                           sample.logger] [INFO ] first block

spring-boot-tests/logback/data/test/validation/CapturedLoggingTraitsTest_multipleBlocksWithSuffix_second.txt

@@ -0,0 +1 @@
+[                           sample.logger] [INFO ] second block

spring-boot-tests/logback/data/test/validation/CapturedLoggingTraitsTest_multipleLevels_logging.txt

@@ -0,0 +1,4 @@
+[                           sample.logger] [DEBUG] a debug message
+[                           sample.logger] [INFO ] an info message
+[                           sample.logger] [WARN ] a warning message
+[                           sample.logger] [ERROR] an error message

spring-boot-tests/logback/data/test/validation/CapturedLoggingTraitsTest_onlyFromGivenClass_logging.txt

@@ -0,0 +1 @@
+[tutils.logback.CapturedLoggingTraitsTest] [INFO ] from the test class, captured

spring-boot-tests/logback/data/test/validation/CapturedLoggingTraitsTest_onlyWarningsAndAbove_logging.txt

@@ -0,0 +1,2 @@
+[                           sample.logger] [WARN ] this is captured
+[                           sample.logger] [ERROR] this too

spring-boot-tests/logback/data/test/validation/CapturedLoggingTraitsTest_singleMessage_logging.txt

@@ -0,0 +1 @@
+[                           sample.logger] [INFO ] Hello world

spring-boot-tests/logback/data/test/validation/CapturedLoggingTraitsTest_withException_logging.txt

@@ -0,0 +1,2 @@
+[                           sample.logger] [ERROR] Something went wrong
+                  java.lang.IllegalStateException: boom

spring-boot-tests/logback/data/test/validation/CapturedLoggingTraitsTest_withMdc_logging.txt

@@ -0,0 +1,2 @@
+[                           sample.logger] [INFO ] {user=alice, requestId=abc-123} handling request
+[                           sample.logger] [WARN ] {user=alice, requestId=abc-123} almost done

spring-boot-tests/logback/src/test/java/de/cronn/testutils/logback/CapturedLoggingTraitsTest.java

@@ -0,0 +1,114 @@
+package de.cronn.testutils.logback;
+
+import static org.assertj.core.api.Assertions.*;
+
+import org.junit.jupiter.api.Test;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+import org.slf4j.MDC;
+
+import ch.qos.logback.classic.Level;
+
+class CapturedLoggingTraitsTest implements CapturedLoggingTraits {
+
+	private static final Logger log = LoggerFactory.getLogger("sample.logger");
+	private static final Logger classLog = LoggerFactory.getLogger(CapturedLoggingTraitsTest.class);
+
+	@Test
+	void singleMessage() {
+		withCapturedConsoleLogging(() -> log.info("Hello world"));
+	}
+
+	@Test
+	void multipleLevels() {
+		withCapturedConsoleLogging(() -> {
+			log.debug("a debug message");
+			log.info("an info message");
+			log.warn("a warning message");
+			log.error("an error message");
+		});
+	}
+
+	@Test
+	void multilineMessage() {
+		withCapturedConsoleLogging(() -> {
+			log.info("first line\nsecond line");
+			log.info("another message");
+		});
+	}
+
+	@Test
+	void withException() {
+		withCapturedConsoleLogging(() ->
+			log.error("Something went wrong", new IllegalStateException("boom")));
+	}
+
+	@Test
+	void multipleBlocksWithSuffix() {
+		withCapturedConsoleLogging(() -> log.info("first block"), "first");
+		withCapturedConsoleLogging(() -> log.info("second block"), "second");
+	}
+
+	@Test
+	void onlyWarningsAndAbove() {
+		withCapturedConsoleLogging(() -> {
+			log.info("this is filtered out");
+			log.warn("this is captured");
+			log.error("this too");
+		}, EventFilter.atLeastWarning());
+	}
+
+	@Test
+	void capturedFromGivenLevel() {
+		withCapturedConsoleLogging(() -> {
+			log.debug("filtered out debug");
+			log.info("captured info");
+		}, Level.INFO);
+	}
+
+	@Test
+	@SuppressWarnings({"try", "unused"})
+	void withMdc() {
+		withCapturedConsoleLogging(() -> {
+			try (MDC.MDCCloseable requestId = MDC.putCloseable("requestId", "abc-123");
+					MDC.MDCCloseable user = MDC.putCloseable("user", "alice")) {
+				log.info("handling request");
+				log.warn("almost done");
+			}
+		});
+	}
+
+	@Test
+	void onlyFromGivenClass() {
+		withCapturedConsoleLogging(() -> {
+			log.info("from sample.logger, filtered out");
+			classLog.info("from the test class, captured");
+		}, EventFilter.forClass(CapturedLoggingTraitsTest.class));
+	}
+
+	@Test
+	void actionExceptionIsPropagated() {
+		assertThatExceptionOfType(IllegalStateException.class)
+			.isThrownBy(() -> withCapturedConsoleLogging(() -> {
+				throw new IllegalStateException("failing action");
+			}))
+			.withMessage("failing action");
+	}
+
+	@Test
+	@SuppressWarnings({"try", "unused"})
+	void captureLogsAsList() throws Exception {
+		LogbackCaptor captor = getLogbackCaptor();
+		captor.captureLoggingDuring(() -> {
+			log.info("This is informative");
+			try (MDC.MDCCloseable userId = MDC.putCloseable("user.id", "123")) {
+				log.warn("This is a warning for a user");
+			}
+		});
+
+		// Check that the MDC value is present with an assertion
+		assertThat(captor.getCapturedLoggingEvents())
+			.anyMatch(it -> it.getMDCPropertyMap().containsKey("user.id"));
+	}
+
+}

spring-boot-tests/logback/src/test/resources/logback-test.xml

@@ -0,0 +1,20 @@
+<?xml version="1.0" encoding="UTF-8"?>
+<!--
+    An explicit configuration file is required here: spring-boot-starter-test pulls in the
+    spring-boot core jar, which registers RootLogLevelConfigurator via META-INF/services.
+    That configurator pins the root logger to INFO, so without this file the DEBUG events
+    the tests expect to capture are never logged.
+-->
+<configuration>
+
+    <appender name="Console" class="ch.qos.logback.core.ConsoleAppender">
+        <layout class="ch.qos.logback.classic.PatternLayout">
+            <Pattern>%date{HH:mm:ss.SSS} %highlight(%-5level) [%blue(%t)] %yellow(%c{40}:%L) - %msg%n%throwable</Pattern>
+        </layout>
+    </appender>
+
+    <root level="DEBUG">
+        <appender-ref ref="Console"/>
+    </root>
+
+</configuration>