From b2e37fb91e245c5f1052c9db8d19534f1fa84d74 Mon Sep 17 00:00:00 2001 From: "Krause-Barmann, Camillo" Date: Wed, 29 Jan 2025 12:16:48 +0100 Subject: [PATCH 01/23] Add assertion for number of times *times() *atLeast() *atMost() --- .../logcapture/LogAsserter.java | 43 +++++++++ .../infrastructure/logcapture/LogCapture.java | 7 +- .../dm/infrastructure/logcapture/Times.java | 62 ++++++++++++ .../logcapture/AssertedTimesUnitTest.java | 96 +++++++++++++++++++ 4 files changed, 207 insertions(+), 1 deletion(-) create mode 100644 src/main/java/de/dm/infrastructure/logcapture/Times.java create mode 100644 src/test/java/de/dm/infrastructure/logcapture/AssertedTimesUnitTest.java diff --git a/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java b/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java index 25c95c7..b0145d9 100644 --- a/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java +++ b/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java @@ -2,6 +2,7 @@ import ch.qos.logback.classic.Level; import lombok.RequiredArgsConstructor; +import lombok.extern.slf4j.Slf4j; import java.util.HashMap; import java.util.LinkedList; @@ -18,6 +19,7 @@ /** * class doing the actual assertions of log messages */ +@Slf4j @RequiredArgsConstructor(access = PACKAGE) public class LogAsserter { private final CapturingAppender capturingAppender; @@ -72,6 +74,34 @@ public NothingElseLoggedAsserter assertLogged(LogExpectation logExpectation) { return new NothingElseLoggedAsserter(1); } + /** + * assert a message has been logged the given times + * + * @param logExpectation descriptions of expected log message + * + * @return asserter that can be used to check if anything else has been logged + * + * @throws AssertionError if the expected log message has not been logged + */ + public NothingElseLoggedAsserter assertLogged(LogExpectation logExpectation, Times times) { + + int matches = assertCapturedMultipleTimes(logExpectation.level, logExpectation.regex, logExpectation.logEventMatchers); + + boolean failAssertion = switch (times.getOperator()) { + case EQUAL -> matches != times.getTimes(); + case AT_LEAST -> matches < times.getTimes(); + case AT_MOST -> matches > times.getTimes(); + }; + if (failAssertion) { + throw new AssertionError(""" + Log message has not occurred as expected: + Message: %s + Expected: %s + Actual: %s + """.formatted(logExpectation.regex, times, matches)); + } + return new NothingElseLoggedAsserter(1); + } /** * assert that multiple log messages have been logged in an expected order @@ -194,6 +224,19 @@ void assertNotCaptured(Optional level, Optional regex, List level, Optional regex, List logEventMatchers) { + Pattern pattern = Pattern.compile(".*" + regex.orElse("") + ".*", Pattern.DOTALL + Pattern.MULTILINE); + + int matches = 0; + for (int i = 0; i < capturingAppender.loggedEvents.size(); i++) { + LoggedEvent event = capturingAppender.loggedEvents.get(i); + if (eventMatchesWithoutAdditionalMatchers(event, level, pattern) && isMatchedByAll(event, logEventMatchers)) { + matches++; + } + } + return matches; + } + private boolean eventMatchesWithoutAdditionalMatchers(LoggedEvent event, Optional level, Pattern pattern) { return eventMatchesLevel(event, level) && eventMatchesPattern(event, pattern); } diff --git a/src/main/java/de/dm/infrastructure/logcapture/LogCapture.java b/src/main/java/de/dm/infrastructure/logcapture/LogCapture.java index 9169fc0..92c225a 100644 --- a/src/main/java/de/dm/infrastructure/logcapture/LogCapture.java +++ b/src/main/java/de/dm/infrastructure/logcapture/LogCapture.java @@ -114,7 +114,7 @@ public void removeAppenderAndResetLogLevel() { rootLogger.detachAppender(capturingAppender); resetLogLevel(); } - + /** * assert that a certain expected message has been logged. * @@ -134,6 +134,11 @@ public LogAsserter.NothingElseLoggedAsserter assertLogged(LogExpectation logExpe .assertLogged(logExpectation); } + public LogAsserter.NothingElseLoggedAsserter assertLogged(LogExpectation logExpectation, Times times) { + return new LogAsserter(capturingAppender, new LinkedList<>()) + .assertLogged(logExpectation, times); + } + /** * assert that a certain expected message has not been logged. * diff --git a/src/main/java/de/dm/infrastructure/logcapture/Times.java b/src/main/java/de/dm/infrastructure/logcapture/Times.java new file mode 100644 index 0000000..895f99a --- /dev/null +++ b/src/main/java/de/dm/infrastructure/logcapture/Times.java @@ -0,0 +1,62 @@ +package de.dm.infrastructure.logcapture; + +import lombok.Getter; +import lombok.RequiredArgsConstructor; + +import static de.dm.infrastructure.logcapture.Times.Operator.AT_LEAST; +import static de.dm.infrastructure.logcapture.Times.Operator.AT_MOST; +import static de.dm.infrastructure.logcapture.Times.Operator.EQUAL; +import static lombok.AccessLevel.PRIVATE; + +@Getter +@RequiredArgsConstructor(access = PRIVATE) +public class Times { + + private final int times; + private final Operator operator; + + public enum Operator { + /** + * check for equal number of occurrences (==) + */ + EQUAL, + /** + * check for minimal number of occurrences (>=) + */ + AT_LEAST, + /** + * check for maximum number of occurrences (<=) + */ + AT_MOST + } + + /** + * Asserts that the log entry is logged exactly the given times. + * @param times number of times to be asserted + */ + public static Times times(int times) { + + if (times < 2) { + throw new IllegalArgumentException("Times must be greater than 1. If you want to test a single log entry, remove times as argument."); + } + return new Times(times, EQUAL); + } + + /** + * Asserts that the log entry is logged at least as often as the given times. + * @param times number of times to be asserted at least + */ + public static Times atLeast(int times) { + + return new Times(times, AT_LEAST); + } + + /** + * Asserts that the log entry is logged at most as often as the given times. + * @param times number of times to be asserted at most + */ + public static Times atMost(int times) { + + return new Times(times, AT_MOST); + } +} diff --git a/src/test/java/de/dm/infrastructure/logcapture/AssertedTimesUnitTest.java b/src/test/java/de/dm/infrastructure/logcapture/AssertedTimesUnitTest.java new file mode 100644 index 0000000..bad8a6a --- /dev/null +++ b/src/test/java/de/dm/infrastructure/logcapture/AssertedTimesUnitTest.java @@ -0,0 +1,96 @@ +package de.dm.infrastructure.logcapture; + +import lombok.extern.slf4j.Slf4j; +import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.extension.RegisterExtension; + +import static de.dm.infrastructure.logcapture.LogExpectation.info; +import static de.dm.infrastructure.logcapture.Times.atLeast; +import static de.dm.infrastructure.logcapture.Times.atMost; +import static de.dm.infrastructure.logcapture.Times.times; +import static org.junit.jupiter.api.Assertions.assertDoesNotThrow; +import static org.junit.jupiter.api.Assertions.assertThrows; + +@Slf4j +class AssertedTimesUnitTest { + @RegisterExtension + LogCapture logCapture = LogCapture.forCurrentPackage(); + + @Test + void assertLoggedWithTimes_succeeds() { + log.info("hello world"); + log.info("hello world"); + log.info("hello world"); + + assertDoesNotThrow(() -> logCapture.assertLogged(info("hello world"), times(3))); + } + + @Test + void assertLoggedWithTimes_loggedTooOften_assertionFails() { + log.info("hello world"); + log.info("hello world"); + log.info("hello world"); + + assertThrows(AssertionError.class, () -> logCapture.assertLogged(info("hello world"), times(2))); + } + + @Test + void assertLoggedWithTimes_loggedTooLess_assertionFails() { + log.info("hello world"); + log.info("hello world"); + + assertThrows(AssertionError.class, () -> logCapture.assertLogged(info("hello world"), times(3))); + } + + @Test + void assertLoggedWithAtLeast_succeeds() { + log.info("hello world"); + log.info("hello world"); + log.info("hello world"); + + assertDoesNotThrow(() -> logCapture.assertLogged(info("hello world"), atLeast(3))); + } + + @Test + void assertLoggedWithAtLeast_loggedTooOften_succeeds() { + log.info("hello world"); + log.info("hello world"); + log.info("hello world"); + + assertDoesNotThrow(() -> logCapture.assertLogged(info("hello world"), atLeast(2))); + } + + @Test + void assertLoggedWithAtLeast_loggedTooLess_assertionFails() { + log.info("hello world"); + log.info("hello world"); + + assertThrows(AssertionError.class, () -> logCapture.assertLogged(info("hello world"), atLeast(3))); + } + + @Test + void assertLoggedWithAtMost_succeeds() { + log.info("hello world"); + log.info("hello world"); + log.info("hello world"); + + assertDoesNotThrow(() -> logCapture.assertLogged(info("hello world"), atMost(3))); + } + + @Test + void assertLoggedWithAtMost_loggedTooOften_assertionFails() { + log.info("hello world"); + log.info("hello world"); + log.info("hello world"); + + assertThrows(AssertionError.class, () -> logCapture.assertLogged(info("hello world"), atMost(2))); + } + + @Test + void assertLoggedWithAtMost_loggedLessThanSpecified_succeeds() { + log.info("hello world"); + log.info("hello world"); + + assertDoesNotThrow(() -> logCapture.assertLogged(info("hello world"), atMost(3))); + } +} From f75ab6b958930eafc7919a4de642694b6b6daca0 Mon Sep 17 00:00:00 2001 From: "Krause-Barmann, Camillo" Date: Wed, 29 Jan 2025 12:18:21 +0100 Subject: [PATCH 02/23] remove unnecessary slf4j annotation --- src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java | 2 -- 1 file changed, 2 deletions(-) diff --git a/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java b/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java index b0145d9..82ae9d2 100644 --- a/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java +++ b/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java @@ -2,7 +2,6 @@ import ch.qos.logback.classic.Level; import lombok.RequiredArgsConstructor; -import lombok.extern.slf4j.Slf4j; import java.util.HashMap; import java.util.LinkedList; @@ -19,7 +18,6 @@ /** * class doing the actual assertions of log messages */ -@Slf4j @RequiredArgsConstructor(access = PACKAGE) public class LogAsserter { private final CapturingAppender capturingAppender; From 928d886b31dde23a7ca436b590acc5d4a1555fac Mon Sep 17 00:00:00 2001 From: "Krause-Barmann, Camillo" Date: Wed, 29 Jan 2025 12:52:58 +0100 Subject: [PATCH 03/23] fix logout put when assertion of times did fail --- .../java/de/dm/infrastructure/logcapture/LogAsserter.java | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java b/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java index 82ae9d2..28efaa9 100644 --- a/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java +++ b/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java @@ -92,11 +92,11 @@ public NothingElseLoggedAsserter assertLogged(LogExpectation logExpectation, Tim }; if (failAssertion) { throw new AssertionError(""" - Log message has not occurred as expected: + Log message has not occurred as often as expected: Message: %s Expected: %s Actual: %s - """.formatted(logExpectation.regex, times, matches)); + """.formatted(logExpectation.regex.get(), times, matches)); } return new NothingElseLoggedAsserter(1); } From d5bb2e8dd381cc891fdab2239b5cf19df1b1840d Mon Sep 17 00:00:00 2001 From: "Krause-Barmann, Camillo" Date: Wed, 29 Jan 2025 13:55:29 +0100 Subject: [PATCH 04/23] fix java doc for new method --- src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java b/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java index 28efaa9..5ccc4e8 100644 --- a/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java +++ b/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java @@ -79,7 +79,7 @@ public NothingElseLoggedAsserter assertLogged(LogExpectation logExpectation) { * * @return asserter that can be used to check if anything else has been logged * - * @throws AssertionError if the expected log message has not been logged + * @throws AssertionError if the expected log message has not been logged as often as expected */ public NothingElseLoggedAsserter assertLogged(LogExpectation logExpectation, Times times) { From 8f3f4d499f07389b3f3fe85f21ed042902ffa0b8 Mon Sep 17 00:00:00 2001 From: "Krause-Barmann, Camillo" Date: Wed, 29 Jan 2025 14:41:25 +0100 Subject: [PATCH 05/23] polish java doc --- pom.xml | 2 +- .../infrastructure/logcapture/LogAsserter.java | 1 + .../infrastructure/logcapture/LogCapture.java | 15 +++++++++++++++ .../de/dm/infrastructure/logcapture/Times.java | 17 ++++++++++++++--- 4 files changed, 31 insertions(+), 4 deletions(-) diff --git a/pom.xml b/pom.xml index 387f01b..19b1198 100644 --- a/pom.xml +++ b/pom.xml @@ -29,7 +29,7 @@ - 4.0.0-SNAPSHOT + 4.1.0-SNAPSHOT 17 UTF-8 diff --git a/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java b/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java index 5ccc4e8..ee8a367 100644 --- a/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java +++ b/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java @@ -76,6 +76,7 @@ public NothingElseLoggedAsserter assertLogged(LogExpectation logExpectation) { * assert a message has been logged the given times * * @param logExpectation descriptions of expected log message + * @param times number of times the message should have been logged * * @return asserter that can be used to check if anything else has been logged * diff --git a/src/main/java/de/dm/infrastructure/logcapture/LogCapture.java b/src/main/java/de/dm/infrastructure/logcapture/LogCapture.java index 92c225a..e1bb99a 100644 --- a/src/main/java/de/dm/infrastructure/logcapture/LogCapture.java +++ b/src/main/java/de/dm/infrastructure/logcapture/LogCapture.java @@ -134,6 +134,21 @@ public LogAsserter.NothingElseLoggedAsserter assertLogged(LogExpectation logExpe .assertLogged(logExpectation); } + /** + * assert that a certain expected message has been logged. + * + *

Example: + * 

{@code
+     * logCapture.assertLogged(info("hello world"), times(3)));
+     * }
+ * + * @param logExpectation description of the expected log message + * @param times the number of times the message should have been logged + * + * @return asserter that can be used to check if anything else has been logged + * + * @throws AssertionError if the expected log message has not been logged + */ public LogAsserter.NothingElseLoggedAsserter assertLogged(LogExpectation logExpectation, Times times) { return new LogAsserter(capturingAppender, new LinkedList<>()) .assertLogged(logExpectation, times); diff --git a/src/main/java/de/dm/infrastructure/logcapture/Times.java b/src/main/java/de/dm/infrastructure/logcapture/Times.java index 895f99a..f36dd2f 100644 --- a/src/main/java/de/dm/infrastructure/logcapture/Times.java +++ b/src/main/java/de/dm/infrastructure/logcapture/Times.java @@ -17,22 +17,27 @@ public class Times { public enum Operator { /** - * check for equal number of occurrences (==) + * check for equal number of occurrences */ EQUAL, /** - * check for minimal number of occurrences (>=) + * check for minimal number of occurrences */ AT_LEAST, /** - * check for maximum number of occurrences (<=) + * check for maximum number of occurrences */ AT_MOST } /** * Asserts that the log entry is logged exactly the given times. + * * @param times number of times to be asserted + * + * @return Times object which asserts with exactly the given times + * + * @throws IllegalArgumentException if times is less than 2 (use atLeast, atMost or remove times as argument) */ public static Times times(int times) { @@ -44,7 +49,10 @@ public static Times times(int times) { /** * Asserts that the log entry is logged at least as often as the given times. + * * @param times number of times to be asserted at least + * + * @return Times object which asserts at least the given times */ public static Times atLeast(int times) { @@ -53,7 +61,10 @@ public static Times atLeast(int times) { /** * Asserts that the log entry is logged at most as often as the given times. + * * @param times number of times to be asserted at most + * + * @return Times object which asserts at most the given times */ public static Times atMost(int times) { From 9c63289fa89d09329a4ce8649df7ecb82e2cf80f Mon Sep 17 00:00:00 2001 From: "Krause-Barmann, Camillo" Date: Wed, 29 Jan 2025 14:52:50 +0100 Subject: [PATCH 06/23] add more Times constructors --- .../dm/infrastructure/logcapture/Times.java | 17 +++++++-- .../logcapture/AssertedTimesUnitTest.java | 35 +++++++++++++++++++ 2 files changed, 49 insertions(+), 3 deletions(-) diff --git a/src/main/java/de/dm/infrastructure/logcapture/Times.java b/src/main/java/de/dm/infrastructure/logcapture/Times.java index f36dd2f..83ff833 100644 --- a/src/main/java/de/dm/infrastructure/logcapture/Times.java +++ b/src/main/java/de/dm/infrastructure/logcapture/Times.java @@ -36,17 +36,25 @@ public enum Operator { * @param times number of times to be asserted * * @return Times object which asserts with exactly the given times - * - * @throws IllegalArgumentException if times is less than 2 (use atLeast, atMost or remove times as argument) */ public static Times times(int times) { if (times < 2) { - throw new IllegalArgumentException("Times must be greater than 1. If you want to test a single log entry, remove times as argument."); + throw new IllegalArgumentException("Times must be greater than 1.\nIf you want to test a single log entry use once() instead.\nIf you want to test no entry at all, use assertNotLogged() instead."); } return new Times(times, EQUAL); } + /** + * Asserts that the log entry is logged exactly once. + * + * @return Times object which asserts with exactly once + */ + public static Times once() { + + return new Times(1, EQUAL); + } + /** * Asserts that the log entry is logged at least as often as the given times. * @@ -68,6 +76,9 @@ public static Times atLeast(int times) { */ public static Times atMost(int times) { + if (times < 1) { + throw new IllegalArgumentException("Times must be greater than 0.\nIf you want to test no entry at all, use assertNotLogged() instead."); + } return new Times(times, AT_MOST); } } diff --git a/src/test/java/de/dm/infrastructure/logcapture/AssertedTimesUnitTest.java b/src/test/java/de/dm/infrastructure/logcapture/AssertedTimesUnitTest.java index bad8a6a..84ba6e3 100644 --- a/src/test/java/de/dm/infrastructure/logcapture/AssertedTimesUnitTest.java +++ b/src/test/java/de/dm/infrastructure/logcapture/AssertedTimesUnitTest.java @@ -7,6 +7,7 @@ import static de.dm.infrastructure.logcapture.LogExpectation.info; import static de.dm.infrastructure.logcapture.Times.atLeast; import static de.dm.infrastructure.logcapture.Times.atMost; +import static de.dm.infrastructure.logcapture.Times.once; import static de.dm.infrastructure.logcapture.Times.times; import static org.junit.jupiter.api.Assertions.assertDoesNotThrow; import static org.junit.jupiter.api.Assertions.assertThrows; @@ -42,6 +43,40 @@ void assertLoggedWithTimes_loggedTooLess_assertionFails() { assertThrows(AssertionError.class, () -> logCapture.assertLogged(info("hello world"), times(3))); } + @Test + void times_lowerThan2_throwsIllegalArgumentException() { + + assertThrows(IllegalArgumentException.class, () -> times(1)); + assertThrows(IllegalArgumentException.class, () -> times(0)); + } + + @Test + void atMost_lowerThan1_throwsIllegalArgumentException() { + + assertThrows(IllegalArgumentException.class, () -> atMost(0)); + } + + @Test + void assertLoggedWithTimesOnce_succeeds() { + log.info("hello world"); + + assertDoesNotThrow(() -> logCapture.assertLogged(info("hello world"), once())); + } + + @Test + void assertLoggedWithTimesOnce_loggedTooOften_assertionFails() { + log.info("hello world"); + log.info("hello world"); + + assertThrows(AssertionError.class, () -> logCapture.assertLogged(info("hello world"), once())); + } + + @Test + void assertLoggedWithTimesOnce_loggedTooLess_assertionFails() { + + assertThrows(AssertionError.class, () -> logCapture.assertLogged(info("hello world"), once())); + } + @Test void assertLoggedWithAtLeast_succeeds() { log.info("hello world"); From 65eb3779c3d606cd7b09e6253df20122b10b2203 Mon Sep 17 00:00:00 2001 From: "Krause-Barmann, Camillo" Date: Wed, 29 Jan 2025 15:21:41 +0100 Subject: [PATCH 07/23] add documentation to readme --- README.md | 33 +++++++++++++++++-- .../logcapture/LogAsserter.java | 1 - 2 files changed, 31 insertions(+), 3 deletions(-) diff --git a/README.md b/README.md index bf20b48..aca5cf5 100644 --- a/README.md +++ b/README.md @@ -50,7 +50,8 @@ logCapture.assertLoggedInOrder( * [Usage outside of JUnit 5 (Cucumber example)](#usage-outside-of-junit-5-cucumber-example) * [Cucumber example](#cucumber-example) * [Cucumber feature file](#cucumber-feature-file) -* [Changes](#changes) +* [Changes](#changes) + * [4.1.0](#410) * [4.0.1](#401) * [4.0.0](#400) * [3.6.2](#362) @@ -78,7 +79,7 @@ Add log-capture as a test dependency to your project. If you use Maven, add this de.dm.infrastructure log-capture - 4.0.1 + 4.1.0 test ``` @@ -159,6 +160,30 @@ log.info("did something"); logCapture.assertLogged(info("did something", logger("com.acme.foo"))); ``` +### Expect a specifiq ammount of times + +It is possible to match a LogExpectation multiple times. This can be done by using the `Times` class. + +```java +import static de.dm.infrastructure.logcapture.ExpectedLoggerName.logger; + +... + +log.info("did something"); +log.info("did something"); + +logCapture.assertLogged(info("did something"), times(2)); +``` + +There are also more options for checking the amount of times a log message is logged a little more or less specific. + +```java +logCapture.assertLogged(info("did something"), atLeast(1)); // not important if more than once, but at least once +logCapture.assertLogged(info("did something"), atMost(2)); // not important if less than e.g. twice, but at most twice +logCapture.assertLogged(info("did something"), once()); // exactly once +``` + + ### Examples #### Unit Test Example: @@ -326,6 +351,10 @@ And with MDC logging context ## Changes +### 4.1.0 + +* added Times class which allows matching a LogExpectation multiple times + ### 4.0.1 * dependencies updated due to logback vulnerability diff --git a/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java b/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java index ee8a367..0f78647 100644 --- a/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java +++ b/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java @@ -140,7 +140,6 @@ public void assertNotLogged(LogExpectation... logExpectations) { throw new IllegalArgumentException("at least one LogExpectation is required for assertNotLogged(). Found none"); } - for (LogExpectation assertion : logExpectations) { assertNotCaptured(assertion.level, assertion.regex, assertion.logEventMatchers); } From 02f4084d084d0812c1f6879203b27a57c45e2923 Mon Sep 17 00:00:00 2001 From: "Krause-Barmann, Camillo" Date: Wed, 29 Jan 2025 15:22:28 +0100 Subject: [PATCH 08/23] fix typo --- README.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/README.md b/README.md index aca5cf5..ae8d53f 100644 --- a/README.md +++ b/README.md @@ -160,7 +160,7 @@ log.info("did something"); logCapture.assertLogged(info("did something", logger("com.acme.foo"))); ``` -### Expect a specifiq ammount of times +### Expect a specific amount of times It is possible to match a LogExpectation multiple times. This can be done by using the `Times` class. From f3c0c5b6656e9dc91f9345c33de9eff62289d412 Mon Sep 17 00:00:00 2001 From: Daniel Flassak Date: Fri, 31 Jan 2025 16:39:34 +0100 Subject: [PATCH 09/23] WIP refactor to integrate well into the current style in code and API doc and to show helpful error messages --- .../logcapture/ExpectedTimes.java | 91 +++++++++++++++++++ .../logcapture/LogAsserter.java | 77 +++++++++------- .../infrastructure/logcapture/LogCapture.java | 8 +- .../dm/infrastructure/logcapture/Times.java | 84 ----------------- .../logcapture/AssertedTimesUnitTest.java | 40 ++++---- 5 files changed, 162 insertions(+), 138 deletions(-) create mode 100644 src/main/java/de/dm/infrastructure/logcapture/ExpectedTimes.java delete mode 100644 src/main/java/de/dm/infrastructure/logcapture/Times.java diff --git a/src/main/java/de/dm/infrastructure/logcapture/ExpectedTimes.java b/src/main/java/de/dm/infrastructure/logcapture/ExpectedTimes.java new file mode 100644 index 0000000..5969436 --- /dev/null +++ b/src/main/java/de/dm/infrastructure/logcapture/ExpectedTimes.java @@ -0,0 +1,91 @@ +package de.dm.infrastructure.logcapture; + +import lombok.Getter; +import lombok.RequiredArgsConstructor; + +import static de.dm.infrastructure.logcapture.ExpectedTimes.ComparisonStrategy.AT_LEAST; +import static de.dm.infrastructure.logcapture.ExpectedTimes.ComparisonStrategy.AT_MOST; +import static de.dm.infrastructure.logcapture.ExpectedTimes.ComparisonStrategy.EQUAL; +import static lombok.AccessLevel.PRIVATE; + +/** + * define expected repetitions of log messages + */ +@Getter +@RequiredArgsConstructor(access = PRIVATE) +public class ExpectedTimes { + + private final int referenceValue; + private final ComparisonStrategy comparisonStrategy; + + @RequiredArgsConstructor + enum ComparisonStrategy { + EQUAL("exactly"), + AT_LEAST("at least"), + AT_MOST("at most"); + + final String strategyName; + } + + /** + * Asserts that the log entry is logged exactly as often as the given times. + * + *

+ * Note: {@link LogCapture#assertNotLogged(LogExpectation...)} can be used + * instead of {@code times(0)} to test that something has not been logged at all + *

+ * + * @param times exact number of expected log messages + * + * @return Times object which asserts with exactly the given times + */ + public static ExpectedTimes times(int times) { + + if (times < 0) { + throw new IllegalArgumentException("Number of log message occurrences that are expected must be positive."); + } + return new ExpectedTimes(times, EQUAL); + } + + /** + * Asserts that the log entry is logged exactly once. + * + * @return Times object which asserts with exactly once + */ + public static ExpectedTimes once() { + return new ExpectedTimes(1, EQUAL); + } + + /** + * Asserts that the log entry is logged at least as often as the given times. + * + * @param min minimum number of log message occurrences, must be at least 1 + * + * @return Times object which asserts at least the given times + */ + public static ExpectedTimes atLeast(int min) { + if (min < 1) { + throw new IllegalArgumentException("Minimum number of log message occurrences that are expected must be greater than 0."); + } + return new ExpectedTimes(min, AT_LEAST); + } + + /** + * Asserts that the log entry is logged at most as often as the given maximum. + * + *

+ * Note: {@link LogCapture#assertNotLogged(LogExpectation...)} can be used + * instead of atMost(0) to test that something has not been logged at all + *

+ * + * @param max maximum number of log message occurrences, must be positive + * + * @return Times object which asserts at most the given times + */ + public static ExpectedTimes atMost(int max) { + if (max < 0) { + throw new IllegalArgumentException("Maximum number of log message occurrences that are expected must be greater than 0."); + } + return new ExpectedTimes(max, AT_MOST); + } +} diff --git a/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java b/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java index 0f78647..693c68e 100644 --- a/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java +++ b/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java @@ -49,8 +49,8 @@ public NothingElseLoggedAsserter assertLoggedInAnyOrder(LogExpectation... logExp "Imprecise matching: Two log expectations have matched the same message. " + "Use more precise matching or in-order matching. " + "(First match: %s | Second match: %s", - getDescriptionForUnwantedLogMessage(previousMatch.level, previousMatch.regex, previousMatch.logEventMatchers), - getDescriptionForUnwantedLogMessage(assertion.level, assertion.regex, assertion.logEventMatchers))); + getDescriptionForExpectedMessageWithAdditionalMatchers(previousMatch.level, previousMatch.regex, previousMatch.logEventMatchers), + getDescriptionForExpectedMessageWithAdditionalMatchers(assertion.level, assertion.regex, assertion.logEventMatchers))); } matches.put(lastCapturedLogEvent.lastAssertedLogMessageIndex, assertion); } @@ -73,37 +73,45 @@ public NothingElseLoggedAsserter assertLogged(LogExpectation logExpectation) { } /** - * assert a message has been logged the given times + * assert a message has been logged as often as expected * + * @param expectedTimes definition of number of times the message should have been logged * @param logExpectation descriptions of expected log message - * @param times number of times the message should have been logged * * @return asserter that can be used to check if anything else has been logged * * @throws AssertionError if the expected log message has not been logged as often as expected */ - public NothingElseLoggedAsserter assertLogged(LogExpectation logExpectation, Times times) { + public NothingElseLoggedAsserter assertLogged(ExpectedTimes expectedTimes, LogExpectation logExpectation) { - int matches = assertCapturedMultipleTimes(logExpectation.level, logExpectation.regex, logExpectation.logEventMatchers); + var matches = getNumberOfMatches(logExpectation.level, logExpectation.regex, logExpectation.logEventMatchers); + var comparisonStrategy = expectedTimes.getComparisonStrategy(); + var referenceValue = expectedTimes.getReferenceValue(); - boolean failAssertion = switch (times.getOperator()) { - case EQUAL -> matches != times.getTimes(); - case AT_LEAST -> matches < times.getTimes(); - case AT_MOST -> matches > times.getTimes(); + boolean failAssertion = switch (comparisonStrategy) { + case EQUAL -> matches.completeMatches != referenceValue; + case AT_LEAST -> matches.completeMatches < referenceValue; + case AT_MOST -> matches.completeMatches > referenceValue; }; + if (failAssertion) { + var additionalMatchersHint = matches.matchesWithoutAdditionalMatchers == matches.completeMatches + ? "" + : "Occurrences without additional matchers: " + matches.matchesWithoutAdditionalMatchers + lineSeparator(); throw new AssertionError(""" - Log message has not occurred as often as expected: - Message: %s - Expected: %s - Actual: %s - """.formatted(logExpectation.regex.get(), times, matches)); + Expected log message has not occurred %s %s time(s), but %s time(s) + %s%s""".formatted( + comparisonStrategy.strategyName, + referenceValue, + matches.completeMatches, + additionalMatchersHint, + getDescriptionForExpectedMessageWithAdditionalMatchers(logExpectation.level, logExpectation.regex, logExpectation.logEventMatchers))); } return new NothingElseLoggedAsserter(1); } /** - * assert that multiple log messages have been logged in an expected order + * assert that multiple log messages have been logged in the expected order * * @param logExpectations descriptions of expected log messages, in order * @@ -212,27 +220,29 @@ Integer assertCapturedNext(Optional level, Optional regex, int st } void assertNotCaptured(Optional level, Optional regex, List logEventMatchers) { - Pattern pattern = Pattern.compile(".*" + regex.orElse("") + ".*", Pattern.DOTALL + Pattern.MULTILINE); - - for (int i = 0; i < capturingAppender.loggedEvents.size(); i++) { - LoggedEvent event = capturingAppender.loggedEvents.get(i); - if (eventMatchesWithoutAdditionalMatchers(event, level, pattern) && isMatchedByAll(event, logEventMatchers)) { - throw new AssertionError(format("Found a log message that should not be logged: %s", getDescriptionForUnwantedLogMessage(level, regex, logEventMatchers))); - } + if (getNumberOfMatches(level, regex, logEventMatchers).completeMatches > 0) { + throw new AssertionError(format("Found a log message that should not be logged: %s", getDescriptionForExpectedMessageWithAdditionalMatchers(level, regex, logEventMatchers))); } } - private int assertCapturedMultipleTimes(Optional level, Optional regex, List logEventMatchers) { + private record Matches(int completeMatches, int matchesWithoutAdditionalMatchers) {} + + private Matches getNumberOfMatches(Optional level, Optional regex, List logEventMatchers) { Pattern pattern = Pattern.compile(".*" + regex.orElse("") + ".*", Pattern.DOTALL + Pattern.MULTILINE); - int matches = 0; + int completeMatches = 0; + int matchesWithoutAdditionalMatchers = 0; + for (int i = 0; i < capturingAppender.loggedEvents.size(); i++) { LoggedEvent event = capturingAppender.loggedEvents.get(i); - if (eventMatchesWithoutAdditionalMatchers(event, level, pattern) && isMatchedByAll(event, logEventMatchers)) { - matches++; + if (eventMatchesWithoutAdditionalMatchers(event, level, pattern)) { + matchesWithoutAdditionalMatchers++; + if (isMatchedByAll(event, logEventMatchers)) { + completeMatches++; + } } } - return matches; + return new Matches(completeMatches, matchesWithoutAdditionalMatchers); } private boolean eventMatchesWithoutAdditionalMatchers(LoggedEvent event, Optional level, Pattern pattern) { @@ -278,26 +288,25 @@ private static String getDescriptionForExpectedMessage(Optional level, Op return ""; } if (level.isPresent() && regex.isPresent()) { - return "Level: " + level.get() + ", Regex: \"" + regex.get() + "\""; + return "Expectation: " + lineSeparator() + " " + level.get() + " - \"" + regex.get() + "\""; } return (level.map(value -> "Level: " + value).orElse("")) + (regex.map(s -> "Regex: \"" + s + "\"").orElse("")); } - private static String getDescriptionForUnwantedLogMessage(Optional level, Optional regex, List matchers) { + private static String getDescriptionForExpectedMessageWithAdditionalMatchers(Optional level, Optional regex, List matchers) { String matchersText = ""; if (matchers != null && !matchers.isEmpty()) { - matchersText = ", with matchers:" + lineSeparator() + " " + matchers.stream().map(LogEventMatcher::getMatcherDetailDescription) - .collect(Collectors.joining(lineSeparator() + " ")); + matchersText = lineSeparator() + " with additional matchers:" + lineSeparator() + " - " + matchers.stream().map(LogEventMatcher::getMatcherDetailDescription) + .collect(Collectors.joining(lineSeparator() + " - ")); } if (level.isEmpty() && regex.isEmpty()) { return "" + matchersText; } if (level.isPresent() && regex.isPresent()) { - return "Level: " + level.get() + ", Regex: \"" + regex.get() + "\"" + matchersText; + return "Expectation: " + lineSeparator() + " " + level.get() + " - \"" + regex.get() + "\"" + matchersText; } return (level.map(value -> "Level: " + value).orElse("")) + (regex.map(s -> "Regex: \"" + s + "\"").orElse("")) + matchersText; } } - diff --git a/src/main/java/de/dm/infrastructure/logcapture/LogCapture.java b/src/main/java/de/dm/infrastructure/logcapture/LogCapture.java index e1bb99a..4a8f7a8 100644 --- a/src/main/java/de/dm/infrastructure/logcapture/LogCapture.java +++ b/src/main/java/de/dm/infrastructure/logcapture/LogCapture.java @@ -139,19 +139,19 @@ public LogAsserter.NothingElseLoggedAsserter assertLogged(LogExpectation logExpe * *

Example: * 

{@code
-     * logCapture.assertLogged(info("hello world"), times(3)));
+     * logCapture.assertLogged(times(3), info("hello world")));
      * }
* - * @param logExpectation description of the expected log message * @param times the number of times the message should have been logged + * @param logExpectation description of the expected log message * * @return asserter that can be used to check if anything else has been logged * * @throws AssertionError if the expected log message has not been logged */ - public LogAsserter.NothingElseLoggedAsserter assertLogged(LogExpectation logExpectation, Times times) { + public LogAsserter.NothingElseLoggedAsserter assertLogged(ExpectedTimes times, LogExpectation logExpectation) { return new LogAsserter(capturingAppender, new LinkedList<>()) - .assertLogged(logExpectation, times); + .assertLogged(times, logExpectation); } /** diff --git a/src/main/java/de/dm/infrastructure/logcapture/Times.java b/src/main/java/de/dm/infrastructure/logcapture/Times.java deleted file mode 100644 index 83ff833..0000000 --- a/src/main/java/de/dm/infrastructure/logcapture/Times.java +++ /dev/null @@ -1,84 +0,0 @@ -package de.dm.infrastructure.logcapture; - -import lombok.Getter; -import lombok.RequiredArgsConstructor; - -import static de.dm.infrastructure.logcapture.Times.Operator.AT_LEAST; -import static de.dm.infrastructure.logcapture.Times.Operator.AT_MOST; -import static de.dm.infrastructure.logcapture.Times.Operator.EQUAL; -import static lombok.AccessLevel.PRIVATE; - -@Getter -@RequiredArgsConstructor(access = PRIVATE) -public class Times { - - private final int times; - private final Operator operator; - - public enum Operator { - /** - * check for equal number of occurrences - */ - EQUAL, - /** - * check for minimal number of occurrences - */ - AT_LEAST, - /** - * check for maximum number of occurrences - */ - AT_MOST - } - - /** - * Asserts that the log entry is logged exactly the given times. - * - * @param times number of times to be asserted - * - * @return Times object which asserts with exactly the given times - */ - public static Times times(int times) { - - if (times < 2) { - throw new IllegalArgumentException("Times must be greater than 1.\nIf you want to test a single log entry use once() instead.\nIf you want to test no entry at all, use assertNotLogged() instead."); - } - return new Times(times, EQUAL); - } - - /** - * Asserts that the log entry is logged exactly once. - * - * @return Times object which asserts with exactly once - */ - public static Times once() { - - return new Times(1, EQUAL); - } - - /** - * Asserts that the log entry is logged at least as often as the given times. - * - * @param times number of times to be asserted at least - * - * @return Times object which asserts at least the given times - */ - public static Times atLeast(int times) { - - return new Times(times, AT_LEAST); - } - - /** - * Asserts that the log entry is logged at most as often as the given times. - * - * @param times number of times to be asserted at most - * - * @return Times object which asserts at most the given times - */ - public static Times atMost(int times) { - - if (times < 1) { - throw new IllegalArgumentException("Times must be greater than 0.\nIf you want to test no entry at all, use assertNotLogged() instead."); - } - return new Times(times, AT_MOST); - } -} diff --git a/src/test/java/de/dm/infrastructure/logcapture/AssertedTimesUnitTest.java b/src/test/java/de/dm/infrastructure/logcapture/AssertedTimesUnitTest.java index 84ba6e3..4d91475 100644 --- a/src/test/java/de/dm/infrastructure/logcapture/AssertedTimesUnitTest.java +++ b/src/test/java/de/dm/infrastructure/logcapture/AssertedTimesUnitTest.java @@ -4,11 +4,14 @@ import org.junit.jupiter.api.Test; import org.junit.jupiter.api.extension.RegisterExtension; +import static de.dm.infrastructure.logcapture.ExpectedMdcEntry.mdc; +import static de.dm.infrastructure.logcapture.ExpectedTimes.atLeast; +import static de.dm.infrastructure.logcapture.ExpectedTimes.atMost; +import static de.dm.infrastructure.logcapture.ExpectedTimes.once; +import static de.dm.infrastructure.logcapture.ExpectedTimes.times; import static de.dm.infrastructure.logcapture.LogExpectation.info; -import static de.dm.infrastructure.logcapture.Times.atLeast; -import static de.dm.infrastructure.logcapture.Times.atMost; -import static de.dm.infrastructure.logcapture.Times.once; -import static de.dm.infrastructure.logcapture.Times.times; +import static java.lang.System.lineSeparator; +import static org.assertj.core.api.Assertions.assertThat; import static org.junit.jupiter.api.Assertions.assertDoesNotThrow; import static org.junit.jupiter.api.Assertions.assertThrows; @@ -23,7 +26,7 @@ void assertLoggedWithTimes_succeeds() { log.info("hello world"); log.info("hello world"); - assertDoesNotThrow(() -> logCapture.assertLogged(info("hello world"), times(3))); + assertDoesNotThrow(() -> logCapture.assertLogged(times(3), info("hello world"))); } @Test @@ -32,7 +35,12 @@ void assertLoggedWithTimes_loggedTooOften_assertionFails() { log.info("hello world"); log.info("hello world"); - assertThrows(AssertionError.class, () -> logCapture.assertLogged(info("hello world"), times(2))); + var assertionError = assertThrows(AssertionError.class, () -> logCapture.assertLogged(times(2), info("hello world", mdc("foo", "bar"), ExpectedException.exception().expectedMessageRegex("noooo!").build()))); + + assertThat(assertionError).hasMessage("Expected log message has occurred, but never with the expected marker name: Level: INFO, Regex: \"hello without marker\"" + + lineSeparator() + " expected marker name: \"expected\"" + + lineSeparator() + " but no marker was found" + + lineSeparator()); } @Test @@ -40,7 +48,7 @@ void assertLoggedWithTimes_loggedTooLess_assertionFails() { log.info("hello world"); log.info("hello world"); - assertThrows(AssertionError.class, () -> logCapture.assertLogged(info("hello world"), times(3))); + assertThrows(AssertionError.class, () -> logCapture.assertLogged(times(3), info("hello world"))); } @Test @@ -60,7 +68,7 @@ void atMost_lowerThan1_throwsIllegalArgumentException() { void assertLoggedWithTimesOnce_succeeds() { log.info("hello world"); - assertDoesNotThrow(() -> logCapture.assertLogged(info("hello world"), once())); + assertDoesNotThrow(() -> logCapture.assertLogged(once(), info("hello world"))); } @Test @@ -68,13 +76,13 @@ void assertLoggedWithTimesOnce_loggedTooOften_assertionFails() { log.info("hello world"); log.info("hello world"); - assertThrows(AssertionError.class, () -> logCapture.assertLogged(info("hello world"), once())); + assertThrows(AssertionError.class, () -> logCapture.assertLogged(once(), info("hello world"))); } @Test void assertLoggedWithTimesOnce_loggedTooLess_assertionFails() { - assertThrows(AssertionError.class, () -> logCapture.assertLogged(info("hello world"), once())); + assertThrows(AssertionError.class, () -> logCapture.assertLogged(once(), info("hello world"))); } @Test @@ -83,7 +91,7 @@ void assertLoggedWithAtLeast_succeeds() { log.info("hello world"); log.info("hello world"); - assertDoesNotThrow(() -> logCapture.assertLogged(info("hello world"), atLeast(3))); + assertDoesNotThrow(() -> logCapture.assertLogged(atLeast(3), info("hello world"))); } @Test @@ -92,7 +100,7 @@ void assertLoggedWithAtLeast_loggedTooOften_succeeds() { log.info("hello world"); log.info("hello world"); - assertDoesNotThrow(() -> logCapture.assertLogged(info("hello world"), atLeast(2))); + assertDoesNotThrow(() -> logCapture.assertLogged(atLeast(2), info("hello world"))); } @Test @@ -100,7 +108,7 @@ void assertLoggedWithAtLeast_loggedTooLess_assertionFails() { log.info("hello world"); log.info("hello world"); - assertThrows(AssertionError.class, () -> logCapture.assertLogged(info("hello world"), atLeast(3))); + assertThrows(AssertionError.class, () -> logCapture.assertLogged(atLeast(3), info("hello world"))); } @Test @@ -109,7 +117,7 @@ void assertLoggedWithAtMost_succeeds() { log.info("hello world"); log.info("hello world"); - assertDoesNotThrow(() -> logCapture.assertLogged(info("hello world"), atMost(3))); + assertDoesNotThrow(() -> logCapture.assertLogged(atMost(3), info("hello world"))); } @Test @@ -118,7 +126,7 @@ void assertLoggedWithAtMost_loggedTooOften_assertionFails() { log.info("hello world"); log.info("hello world"); - assertThrows(AssertionError.class, () -> logCapture.assertLogged(info("hello world"), atMost(2))); + assertThrows(AssertionError.class, () -> logCapture.assertLogged(atMost(2), info("hello world"))); } @Test @@ -126,6 +134,6 @@ void assertLoggedWithAtMost_loggedLessThanSpecified_succeeds() { log.info("hello world"); log.info("hello world"); - assertDoesNotThrow(() -> logCapture.assertLogged(info("hello world"), atMost(3))); + assertDoesNotThrow(() -> logCapture.assertLogged(atMost(3), info("hello world"))); } } From 4fa5fb16ea34a9cb9e92b53872566676e4fefe55 Mon Sep 17 00:00:00 2001 From: Daniel Flassak Date: Fri, 31 Jan 2025 16:40:16 +0100 Subject: [PATCH 10/23] add TODO --- .../de/dm/infrastructure/logcapture/AssertedTimesUnitTest.java | 1 + 1 file changed, 1 insertion(+) diff --git a/src/test/java/de/dm/infrastructure/logcapture/AssertedTimesUnitTest.java b/src/test/java/de/dm/infrastructure/logcapture/AssertedTimesUnitTest.java index 4d91475..ec02ada 100644 --- a/src/test/java/de/dm/infrastructure/logcapture/AssertedTimesUnitTest.java +++ b/src/test/java/de/dm/infrastructure/logcapture/AssertedTimesUnitTest.java @@ -37,6 +37,7 @@ void assertLoggedWithTimes_loggedTooOften_assertionFails() { var assertionError = assertThrows(AssertionError.class, () -> logCapture.assertLogged(times(2), info("hello world", mdc("foo", "bar"), ExpectedException.exception().expectedMessageRegex("noooo!").build()))); + // TODO: assert all assertion messages in this test files assertThat(assertionError).hasMessage("Expected log message has occurred, but never with the expected marker name: Level: INFO, Regex: \"hello without marker\"" + lineSeparator() + " expected marker name: \"expected\"" + lineSeparator() + " but no marker was found" + From e80bd89ce5640589a9689d034108aed5dba4a5be Mon Sep 17 00:00:00 2001 From: Daniel Flassak Date: Fri, 31 Jan 2025 16:40:31 +0100 Subject: [PATCH 11/23] add TODO --- .../de/dm/infrastructure/logcapture/AssertedTimesUnitTest.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/test/java/de/dm/infrastructure/logcapture/AssertedTimesUnitTest.java b/src/test/java/de/dm/infrastructure/logcapture/AssertedTimesUnitTest.java index ec02ada..72b9565 100644 --- a/src/test/java/de/dm/infrastructure/logcapture/AssertedTimesUnitTest.java +++ b/src/test/java/de/dm/infrastructure/logcapture/AssertedTimesUnitTest.java @@ -37,7 +37,7 @@ void assertLoggedWithTimes_loggedTooOften_assertionFails() { var assertionError = assertThrows(AssertionError.class, () -> logCapture.assertLogged(times(2), info("hello world", mdc("foo", "bar"), ExpectedException.exception().expectedMessageRegex("noooo!").build()))); - // TODO: assert all assertion messages in this test files + // TODO: assert all assertion messages in this test files and check tests for completeness assertThat(assertionError).hasMessage("Expected log message has occurred, but never with the expected marker name: Level: INFO, Regex: \"hello without marker\"" + lineSeparator() + " expected marker name: \"expected\"" + lineSeparator() + " but no marker was found" + From 8fedd20e592bdb8fdfa34ea5ebb7ef49add96ab1 Mon Sep 17 00:00:00 2001 From: Daniel Flassak Date: Mon, 3 Feb 2025 10:55:00 +0100 Subject: [PATCH 12/23] update tests for better message readability and fix some small formatting issues --- .../logcapture/LogAsserter.java | 41 ++-- .../java/com/example/app/ReadableApiTest.java | 221 +++++++++++------- .../logcapture/LogCaptureTest.java | 5 +- 3 files changed, 168 insertions(+), 99 deletions(-) diff --git a/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java b/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java index 693c68e..adcd25e 100644 --- a/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java +++ b/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java @@ -216,12 +216,12 @@ Integer assertCapturedNext(Optional level, Optional regex, int st if (eventMatchingWithoutAdditionalMatchers != null) { throwAssertionForPartiallyMatchingLoggedEvent(level, regex, eventMatchingWithoutAdditionalMatchers, logEventMatchers); } - throw new AssertionError(format("Expected log message has not occurred: %s", getDescriptionForExpectedMessage(level, regex))); + throw new AssertionError(format("Expected log message has not occurred.%s", getDescriptionForExpectedMessage(level, regex))); } void assertNotCaptured(Optional level, Optional regex, List logEventMatchers) { if (getNumberOfMatches(level, regex, logEventMatchers).completeMatches > 0) { - throw new AssertionError(format("Found a log message that should not be logged: %s", getDescriptionForExpectedMessageWithAdditionalMatchers(level, regex, logEventMatchers))); + throw new AssertionError(format("Found a log message that should not be logged.%s", getDescriptionForExpectedMessageWithAdditionalMatchers(level, regex, logEventMatchers))); } } @@ -254,9 +254,8 @@ private static void throwAssertionForPartiallyMatchingLoggedEvent(Optional level, Optional regex) { - - if (level.isEmpty() && regex.isEmpty()) { - return ""; - } - if (level.isPresent() && regex.isPresent()) { - return "Expectation: " + lineSeparator() + " " + level.get() + " - \"" + regex.get() + "\""; - } - return (level.map(value -> "Level: " + value).orElse("")) + - (regex.map(s -> "Regex: \"" + s + "\"").orElse("")); + return getExpectedLogMessageText(level, regex) + lineSeparator(); } private static String getDescriptionForExpectedMessageWithAdditionalMatchers(Optional level, Optional regex, List matchers) { @@ -300,13 +291,25 @@ private static String getDescriptionForExpectedMessageWithAdditionalMatchers(Opt matchersText = lineSeparator() + " with additional matchers:" + lineSeparator() + " - " + matchers.stream().map(LogEventMatcher::getMatcherDetailDescription) .collect(Collectors.joining(lineSeparator() + " - ")); } + return getExpectedLogMessageText(level, regex) + matchersText + lineSeparator(); + } + + private static String getExpectedLogMessageText(Optional level, Optional regex) { if (level.isEmpty() && regex.isEmpty()) { - return "" + matchersText; - } - if (level.isPresent() && regex.isPresent()) { - return "Expectation: " + lineSeparator() + " " + level.get() + " - \"" + regex.get() + "\"" + matchersText; + return lineSeparator() + "message: "; } - return (level.map(value -> "Level: " + value).orElse("")) + - (regex.map(s -> "Regex: \"" + s + "\"").orElse("")) + matchersText; + return lineSeparator() + "message: " + getLevelText(level) + " " + getRegexText(regex); + } + + private static String getRegexText(Optional messageRegex) { + return messageRegex + .map("\"%s\" (regex)"::formatted) + .orElse(""); + } + + private static String getLevelText(Optional level) { + return level + .map(Level::toString) + .orElse(""); } } diff --git a/src/test/java/com/example/app/ReadableApiTest.java b/src/test/java/com/example/app/ReadableApiTest.java index a4acbfe..655e39c 100644 --- a/src/test/java/com/example/app/ReadableApiTest.java +++ b/src/test/java/com/example/app/ReadableApiTest.java @@ -23,7 +23,6 @@ import static de.dm.infrastructure.logcapture.LogExpectation.info; import static de.dm.infrastructure.logcapture.LogExpectation.trace; import static de.dm.infrastructure.logcapture.LogExpectation.warn; -import static java.lang.System.lineSeparator; import static org.assertj.core.api.Assertions.assertThat; import static org.junit.jupiter.api.Assertions.assertDoesNotThrow; import static org.junit.jupiter.api.Assertions.assertThrows; @@ -158,10 +157,12 @@ void expectedExceptionFails() { .build() ))); - assertThat(assertionError).hasMessage("Expected log message has occurred, but never with the expected Exception: Level: WARN, Regex: \"oh no!\"" + - lineSeparator() + " expected exception: message (regex): \"a message never used\" type: java.lang.RuntimeException" + - lineSeparator() + " actual exception: message: \"this is illegal\", type: java.lang.IllegalArgumentException, cause: (message: \"never be null!\", type: java.lang.NullPointerException)" + - lineSeparator()); + assertThat(assertionError).hasMessage(""" + Expected log message has occurred, but never with the expected Exception: + message: WARN "oh no!" (regex) + expected exception: message (regex): "a message never used" type: java.lang.RuntimeException + actual exception: message: "this is illegal", type: java.lang.IllegalArgumentException, cause: (message: "never be null!", type: java.lang.NullPointerException) + """); AssertionError withoutExceptionAssertionError = assertThrows(AssertionError.class, () -> logCapture.assertLogged( @@ -172,10 +173,12 @@ void expectedExceptionFails() { .build() ))); - assertThat(withoutExceptionAssertionError).hasMessage("Expected log message has occurred, but never with the expected Exception: Level: INFO, Regex: \"without exception\"" + - lineSeparator() + " expected exception: message (regex): \"a message never used\" type: java.lang.RuntimeException" + - lineSeparator() + " actual exception: (null)" + - lineSeparator()); + assertThat(withoutExceptionAssertionError).hasMessage(""" + Expected log message has occurred, but never with the expected Exception: + message: INFO "without exception" (regex) + expected exception: message (regex): "a message never used" type: java.lang.RuntimeException + actual exception: (null) + """); } @@ -184,16 +187,28 @@ void assertNotLoggedFails() { log.info("testlogmessage"); final AssertionError exceptionAny = assertThrows(AssertionError.class, () -> logCapture.assertNotLogged(any())); - assertThat(exceptionAny).hasMessage("Found a log message that should not be logged: "); + assertThat(exceptionAny).hasMessage(""" + Found a log message that should not be logged. + message: + """); final AssertionError exceptionWithLevel = assertThrows(AssertionError.class, () -> logCapture.assertNotLogged(info())); - assertThat(exceptionWithLevel).hasMessage("Found a log message that should not be logged: Level: INFO"); + assertThat(exceptionWithLevel).hasMessage(""" + Found a log message that should not be logged. + message: INFO + """); final AssertionError exceptionWithRegex = assertThrows(AssertionError.class, () -> logCapture.assertNotLogged(any("testlogmessage"))); - assertThat(exceptionWithRegex).hasMessage("Found a log message that should not be logged: Regex: \"testlogmessage\""); + assertThat(exceptionWithRegex).hasMessage(""" + Found a log message that should not be logged. + message: "testlogmessage" (regex) + """); final AssertionError exceptionWithRegexAndLevel = assertThrows(AssertionError.class, () -> logCapture.assertNotLogged(info("testlogmessage"))); - assertThat(exceptionWithRegexAndLevel).hasMessage("Found a log message that should not be logged: Level: INFO, Regex: \"testlogmessage\""); + assertThat(exceptionWithRegexAndLevel).hasMessage(""" + Found a log message that should not be logged. + message: INFO "testlogmessage" (regex) + """); } } @@ -211,10 +226,12 @@ void markerFailsBecauseOtherMarkerIsPresent() { marker("expected")) )); - assertThat(assertionError).hasMessage("Expected log message has occurred, but never with the expected marker name: Level: INFO, Regex: \"hello with marker\"" + - lineSeparator() + " expected marker name: \"expected\"" + - lineSeparator() + " actual marker names: \"[unexpected]\"" + - lineSeparator()); + assertThat(assertionError).hasMessage(""" + Expected log message has occurred, but never with the expected marker name: + message: INFO "hello with marker" (regex) + expected marker name: "expected" + actual marker names: "[unexpected]" + """); } @Test @@ -227,10 +244,12 @@ void markerFailsBecauseNoMarkerIsPresent() { marker("expected")) )); - assertThat(assertionError).hasMessage("Expected log message has occurred, but never with the expected marker name: Level: INFO, Regex: \"hello without marker\"" + - lineSeparator() + " expected marker name: \"expected\"" + - lineSeparator() + " but no marker was found" + - lineSeparator()); + assertThat(assertionError).hasMessage(""" + Expected log message has occurred, but never with the expected marker name: + message: INFO "hello without marker" (regex) + expected marker name: "expected" + but no marker was found + """); } @Test @@ -245,10 +264,12 @@ void markerFailsWhileNestedMarkersArePresent() { marker("expected")) )); - assertThat(assertionError).hasMessage("Expected log message has occurred, but never with the expected marker name: Level: INFO, Regex: \"hello with marker\"" + - lineSeparator() + " expected marker name: \"expected\"" + - lineSeparator() + " actual marker names: \"[unexpected_top [ unexpected_nested ]]\"" + - lineSeparator()); + assertThat(assertionError).hasMessage(""" + Expected log message has occurred, but never with the expected marker name: + message: INFO "hello with marker" (regex) + expected marker name: "expected" + actual marker names: "[unexpected_top [ unexpected_nested ]]" + """); } @Test @@ -265,10 +286,12 @@ void markerFailsWhileMultipleMarkersArePresent() { marker("expected")) )); - assertThat(assertionError).hasMessage("Expected log message has occurred, but never with the expected marker name: Level: INFO, Regex: \"hello with markers\"" + - lineSeparator() + " expected marker name: \"expected\"" + - lineSeparator() + " actual marker names: \"[unexpected1, unexpected2]\"" + - lineSeparator()); + assertThat(assertionError).hasMessage(""" + Expected log message has occurred, but never with the expected marker name: + message: INFO "hello with markers" (regex) + expected marker name: "expected" + actual marker names: "[unexpected1, unexpected2]" + """); } @Test @@ -302,8 +325,12 @@ void markerWithAssertNotLogged() { final AssertionError assertionError = assertThrows(AssertionError.class, () -> logCapture.assertNotLogged( info("hello with marker", marker("expected")))); - assertThat(assertionError).hasMessage("Found a log message that should not be logged: Level: INFO, Regex: \"hello with marker\", with matchers:" + - lineSeparator() + " marker name: \"expected\""); + assertThat(assertionError).hasMessage(""" + Found a log message that should not be logged. + message: INFO "hello with marker" (regex) + with additional matchers: + - marker name: "expected" + """); } } @@ -347,10 +374,12 @@ void expectedLoggerFails() { logger("WrongLogger$")) )); - assertThat(assertionError).hasMessage("Expected log message has occurred, but never with the expected logger name: Level: WARN, Regex: \"bye world\"" + - lineSeparator() + " expected logger name (regex): \"WrongLogger$\"" + - lineSeparator() + " actual logger name: \"com.example.app.ReadableApiTest\"" + - lineSeparator()); + assertThat(assertionError).hasMessage(""" + Expected log message has occurred, but never with the expected logger name: + message: WARN "bye world" (regex) + expected logger name (regex): "WrongLogger$" + actual logger name: "com.example.app.ReadableApiTest" + """); } @Test @@ -365,8 +394,12 @@ void loggerWithAssertNotLogged() { info("hello on this logger", logger("ReadableApiTest$")))); assertThat(assertionError) - .hasMessage("Found a log message that should not be logged: Level: INFO, Regex: \"hello on this logger\", with matchers:" + - lineSeparator() + " logger name (regex): \"ReadableApiTest$\""); + .hasMessage(""" + Found a log message that should not be logged. + message: INFO "hello on this logger" (regex) + with additional matchers: + - logger name (regex): "ReadableApiTest$" + """); } } @@ -400,12 +433,14 @@ void singleMdcFails() { mdc("key", "value")) )); - assertThat(assertionError).hasMessage("Expected log message has occurred, but never with the expected MDC value: Level: WARN, Regex: \"bye world\"" + - lineSeparator() + " captured message: \"bye world\"" + - lineSeparator() + " expected MDC key: key" + - lineSeparator() + " expected MDC value: \".*value.*\"" + - lineSeparator() + " captured MDC values:" + - lineSeparator()); + assertThat(assertionError).hasMessage(""" + Expected log message has occurred, but never with the expected MDC value: + message: WARN "bye world" (regex) + captured message: "bye world" + expected MDC key: key + expected MDC value: ".*value.*" + captured MDC values: + """); } @Test @@ -424,12 +459,14 @@ void mdcForAllFails() { warn("bye world") )); - assertThat(assertionError).hasMessage("Expected log message has occurred, but never with the expected MDC value: Level: WARN, Regex: \"bye world\"" + - lineSeparator() + " captured message: \"bye world\"" + - lineSeparator() + " expected MDC key: key" + - lineSeparator() + " expected MDC value: \".*value.*\"" + - lineSeparator() + " captured MDC values:" + - lineSeparator()); + assertThat(assertionError).hasMessage(""" + Expected log message has occurred, but never with the expected MDC value: + message: WARN "bye world" (regex) + captured message: "bye world" + expected MDC key: key + expected MDC value: ".*value.*" + captured MDC values: + """); } @Test @@ -466,13 +503,15 @@ void mdcForAllAndSingleMdcFails() { mdc("another_key", "another_value")) )); - assertThat(assertionError).hasMessage("Expected log message has occurred, but never with the expected MDC value: Level: WARN, Regex: \"bye world\"" + - lineSeparator() + " captured message: \"bye world\"" + - lineSeparator() + " expected MDC key: another_key" + - lineSeparator() + " expected MDC value: \".*another_value.*\"" + - lineSeparator() + " captured MDC values:" + - lineSeparator() + " key: \"value\"" + - lineSeparator()); + assertThat(assertionError).hasMessage(""" + Expected log message has occurred, but never with the expected MDC value: + message: WARN "bye world" (regex) + captured message: "bye world" + expected MDC key: another_key + expected MDC value: ".*another_value.*" + captured MDC values: + key: "value" + """); } @Test @@ -508,12 +547,14 @@ void customMdcMatcherFails() { mdc("key", mdcValue -> !mdcValue.equals("value")) ))); - assertThat(assertionError).hasMessage("Expected log message has occurred, but never with the expected MDC value: Level: INFO, Regex: \"hello\"" + - lineSeparator() + " captured message: \"hello\"" + - lineSeparator() + " expected MDC key: key" + - lineSeparator() + " captured MDC values:" + - lineSeparator() + " key: \"value\"" + - lineSeparator()); + assertThat(assertionError).hasMessage(""" + Expected log message has occurred, but never with the expected MDC value: + message: INFO "hello" (regex) + captured message: "hello" + expected MDC key: key + captured MDC values: + key: "value" + """); } @Test @@ -537,13 +578,21 @@ void notLoggedWithMdc() { logCapture.assertNotLogged(info("helloWorld", mdc("thirdKey", "value"))); final AssertionError oneKeyMatches = assertThrows(AssertionError.class, () -> logCapture.assertNotLogged(info("hello world", mdc("key", "value")))); - assertThat(oneKeyMatches).hasMessage("Found a log message that should not be logged: Level: INFO, Regex: \"hello world\", with matchers:" + - lineSeparator() + " MDCValue with key: \"key\""); + assertThat(oneKeyMatches).hasMessage(""" + Found a log message that should not be logged. + message: INFO "hello world" (regex) + with additional matchers: + - MDCValue with key: "key" + """); final AssertionError bothKeysMatches = assertThrows(AssertionError.class, () -> logCapture.assertNotLogged(info("hello world", mdc("key", "value"), mdc("another_key", "another_value")))); - assertThat(bothKeysMatches).hasMessage("Found a log message that should not be logged: Level: INFO, Regex: \"hello world\", with matchers:" + - lineSeparator() + " MDCValue with key: \"key\"" + - lineSeparator() + " MDCValue with key: \"another_key\""); + assertThat(bothKeysMatches).hasMessage(""" + Found a log message that should not be logged. + message: INFO "hello world" (regex) + with additional matchers: + - MDCValue with key: "key" + - MDCValue with key: "another_key" + """); } } @@ -575,7 +624,10 @@ void assertionWithoutOrderFails() { info("hello 2") )); - assertThat(assertionError).hasMessage("Expected log message has not occurred: Level: INFO, Regex: \"hello 2\""); + assertThat(assertionError).hasMessage(""" + Expected log message has not occurred. + message: INFO "hello 2" (regex) + """); } @Test @@ -592,9 +644,12 @@ void assertionWithoutOrderMatchingSameMessageFails() { info("1") )); - assertThat(assertionError).hasMessage("Imprecise matching: Two log expectations have matched the same message. " + - "Use more precise matching or in-order matching. " + - "(First match: Level: INFO, Regex: \"hello\" | Second match: Level: INFO, Regex: \"1\""); + assertThat(assertionError).hasMessage(""" + Imprecise matching: Two log expectations have matched the same message. Use more precise matching or in-order matching. (First match:\s + message: INFO "hello" (regex) + | Second match:\s + message: INFO "1" (regex) + """); // TODO: fix this } @Test @@ -623,7 +678,10 @@ void assertionWithOrderFails() { info("hello 2") )); - assertThat(assertionError).hasMessage("Expected log message has not occurred: Level: INFO, Regex: \"hello 2\""); + assertThat(assertionError).hasMessage(""" + Expected log message has not occurred. + message: INFO "hello 2" (regex) + """); } @Test @@ -718,10 +776,12 @@ void combinedLogExpectationsOnlyOutputMismatch() { exception().expectedMessageRegex("an exception that was not logged").build()) )); - assertThat(assertionError).hasMessage("Expected log message has occurred, but never with the expected Exception: Level: ERROR, Regex: \"some error\"" + - lineSeparator() + " expected exception: message (regex): \"an exception that was not logged\"" + - lineSeparator() + " actual exception: message: \"an exception that was logged\", type: java.lang.RuntimeException" + - lineSeparator()); + assertThat(assertionError).hasMessage(""" + Expected log message has occurred, but never with the expected Exception: + message: ERROR "some error" (regex) + expected exception: message (regex): "an exception that was not logged" + actual exception: message: "an exception that was logged", type: java.lang.RuntimeException + """); } @Nested @@ -737,7 +797,8 @@ void failsWithDetailsNotMatchingExistingKeyValues() { logCapture.assertLogged(info("hello", keyValue("key", "a value"))) ); assertThat(assertionError).hasMessage(""" - Expected log message has occurred, but never with the expected key-value pair: Level: INFO, Regex: "hello" + Expected log message has occurred, but never with the expected key-value pair: + message: INFO "hello" (regex) expected key-value pair (key, a value) actual pairs: [(key1, 1), (key2, value2)] """); @@ -752,7 +813,8 @@ void failsWithDetailsWithNoExistingKeyValues() { logCapture.assertLogged(info("hello", keyValue("key", "a value"))) ); assertThat(assertionError).hasMessage(""" - Expected log message has occurred, but never with the expected key-value pair: Level: INFO, Regex: "hello" + Expected log message has occurred, but never with the expected key-value pair: + message: INFO "hello" (regex) expected key-value pair (key, a value) actual pairs: [] """); @@ -839,7 +901,8 @@ void failsWithBigDecimalAndPrecisionAndInt() { logCapture.assertLogged(info("hello", keyValue("meaning", 42))) ); assertThat(assertionError).hasMessage(""" - Expected log message has occurred, but never with the expected key-value pair: Level: INFO, Regex: "hello" + Expected log message has occurred, but never with the expected key-value pair: + message: INFO "hello" (regex) expected key-value pair (meaning, 42) actual pairs: [(meaning, 42.00)] """); diff --git a/src/test/java/de/dm/infrastructure/logcapture/LogCaptureTest.java b/src/test/java/de/dm/infrastructure/logcapture/LogCaptureTest.java index 8493ed4..e8989da 100644 --- a/src/test/java/de/dm/infrastructure/logcapture/LogCaptureTest.java +++ b/src/test/java/de/dm/infrastructure/logcapture/LogCaptureTest.java @@ -33,7 +33,10 @@ void fromCurrentPackageWorks() { assertThat(logCaptureFromOtherPackage.capturedPackages).containsExactly(LogCaptureCreatorInOtherPackage.class.getPackage().getName()); var thrown = assertThrows(AssertionError.class, () -> logCaptureFromOtherPackage.assertLogged(LogExpectation.info("hello from"))); - assertThat(thrown).hasMessage("Expected log message has not occurred: Level: INFO, Regex: \"hello from\""); + assertThat(thrown).hasMessage(""" + Expected log message has not occurred. + message: INFO "hello from" (regex) + """); } @Test From 338d371af149f76e52459fdf49a5603f6c493e38 Mon Sep 17 00:00:00 2001 From: Daniel Flassak Date: Mon, 3 Feb 2025 10:58:21 +0100 Subject: [PATCH 13/23] add suppression --- src/test/java/com/example/app/ReadableApiTest.java | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/src/test/java/com/example/app/ReadableApiTest.java b/src/test/java/com/example/app/ReadableApiTest.java index 655e39c..aa7fb60 100644 --- a/src/test/java/com/example/app/ReadableApiTest.java +++ b/src/test/java/com/example/app/ReadableApiTest.java @@ -28,7 +28,10 @@ import static org.junit.jupiter.api.Assertions.assertThrows; @Slf4j -@SuppressWarnings("java:S5778") //this rule does not increase the clarity of these tests +@SuppressWarnings({ + "java:S5778", //this rule does not increase the clarity of these tests + "LoggingSimilarMessage" // not a sensible rule for a logging test +}) class ReadableApiTest { @RegisterExtension LogCapture logCapture = LogCapture.forCurrentPackage(); From 9e2e4e387790bfc4aa418d5dbe84d7e1c1e39866 Mon Sep 17 00:00:00 2001 From: Daniel Flassak Date: Mon, 3 Feb 2025 13:27:49 +0100 Subject: [PATCH 14/23] improve readability of imprecise matching message --- .../java/de/dm/infrastructure/logcapture/LogAsserter.java | 7 +++---- src/test/java/com/example/app/ReadableApiTest.java | 7 ++++--- 2 files changed, 7 insertions(+), 7 deletions(-) diff --git a/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java b/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java index adcd25e..c8678ba 100644 --- a/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java +++ b/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java @@ -45,10 +45,9 @@ public NothingElseLoggedAsserter assertLoggedInAnyOrder(LogExpectation... logExp LastCapturedLogEvent lastCapturedLogEvent = assertCapturedNext(assertion.level, assertion.regex, Optional.empty(), assertion.logEventMatchers); if (matches.containsKey(lastCapturedLogEvent.lastAssertedLogMessageIndex)) { LogExpectation previousMatch = matches.get(lastCapturedLogEvent.lastAssertedLogMessageIndex); - throw new AssertionError(String.format( - "Imprecise matching: Two log expectations have matched the same message. " + - "Use more precise matching or in-order matching. " + - "(First match: %s | Second match: %s", + throw new AssertionError(format(""" + Imprecise matching: Two log expectations have matched the same message. Use more precise matching or in-order matching. + -- First match:%s-- Second match:%s""", getDescriptionForExpectedMessageWithAdditionalMatchers(previousMatch.level, previousMatch.regex, previousMatch.logEventMatchers), getDescriptionForExpectedMessageWithAdditionalMatchers(assertion.level, assertion.regex, assertion.logEventMatchers))); } diff --git a/src/test/java/com/example/app/ReadableApiTest.java b/src/test/java/com/example/app/ReadableApiTest.java index aa7fb60..a9e50be 100644 --- a/src/test/java/com/example/app/ReadableApiTest.java +++ b/src/test/java/com/example/app/ReadableApiTest.java @@ -648,11 +648,12 @@ void assertionWithoutOrderMatchingSameMessageFails() { )); assertThat(assertionError).hasMessage(""" - Imprecise matching: Two log expectations have matched the same message. Use more precise matching or in-order matching. (First match:\s + Imprecise matching: Two log expectations have matched the same message. Use more precise matching or in-order matching. + -- First match: message: INFO "hello" (regex) - | Second match:\s + -- Second match: message: INFO "1" (regex) - """); // TODO: fix this + """); } @Test From 06ec7fb49207d9107281a88e0aa21eda382aa849 Mon Sep 17 00:00:00 2001 From: Daniel Flassak Date: Mon, 3 Feb 2025 13:57:27 +0100 Subject: [PATCH 15/23] update AssertedTimesUnitTest and finalize assertion error message --- .../logcapture/LogAsserter.java | 6 +- .../logcapture/AssertedTimesUnitTest.java | 76 ++++++++++++++----- 2 files changed, 58 insertions(+), 24 deletions(-) diff --git a/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java b/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java index c8678ba..88196a5 100644 --- a/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java +++ b/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java @@ -96,10 +96,10 @@ public NothingElseLoggedAsserter assertLogged(ExpectedTimes expectedTimes, LogEx if (failAssertion) { var additionalMatchersHint = matches.matchesWithoutAdditionalMatchers == matches.completeMatches ? "" - : "Occurrences without additional matchers: " + matches.matchesWithoutAdditionalMatchers + lineSeparator(); + : " (%s without additional matchers)".formatted(matches.matchesWithoutAdditionalMatchers); throw new AssertionError(""" - Expected log message has not occurred %s %s time(s), but %s time(s) - %s%s""".formatted( + Expected log message has not occurred %s %s time(s) + actual occurrences: %s%s%s""".formatted( comparisonStrategy.strategyName, referenceValue, matches.completeMatches, diff --git a/src/test/java/de/dm/infrastructure/logcapture/AssertedTimesUnitTest.java b/src/test/java/de/dm/infrastructure/logcapture/AssertedTimesUnitTest.java index 72b9565..1ddda6e 100644 --- a/src/test/java/de/dm/infrastructure/logcapture/AssertedTimesUnitTest.java +++ b/src/test/java/de/dm/infrastructure/logcapture/AssertedTimesUnitTest.java @@ -10,11 +10,14 @@ import static de.dm.infrastructure.logcapture.ExpectedTimes.once; import static de.dm.infrastructure.logcapture.ExpectedTimes.times; import static de.dm.infrastructure.logcapture.LogExpectation.info; -import static java.lang.System.lineSeparator; import static org.assertj.core.api.Assertions.assertThat; import static org.junit.jupiter.api.Assertions.assertDoesNotThrow; import static org.junit.jupiter.api.Assertions.assertThrows; +@SuppressWarnings({ + "java:S5778", //this rule does not increase the clarity of these tests + "LoggingSimilarMessage" // not a sensible rule for a logging test +}) @Slf4j class AssertedTimesUnitTest { @RegisterExtension @@ -37,32 +40,41 @@ void assertLoggedWithTimes_loggedTooOften_assertionFails() { var assertionError = assertThrows(AssertionError.class, () -> logCapture.assertLogged(times(2), info("hello world", mdc("foo", "bar"), ExpectedException.exception().expectedMessageRegex("noooo!").build()))); - // TODO: assert all assertion messages in this test files and check tests for completeness - assertThat(assertionError).hasMessage("Expected log message has occurred, but never with the expected marker name: Level: INFO, Regex: \"hello without marker\"" + - lineSeparator() + " expected marker name: \"expected\"" + - lineSeparator() + " but no marker was found" + - lineSeparator()); + assertThat(assertionError).hasMessage(""" + Expected log message has not occurred exactly 2 time(s) + actual occurrences: 0 (3 without additional matchers) + message: INFO "hello world" (regex) + with additional matchers: + - MDCValue with key: "foo" + - Exception: message (regex): "noooo!" + """); } @Test - void assertLoggedWithTimes_loggedTooLess_assertionFails() { + void assertLoggedWithTimes_loggedTooFewTimes_assertionFails() { log.info("hello world"); log.info("hello world"); - assertThrows(AssertionError.class, () -> logCapture.assertLogged(times(3), info("hello world"))); + var assertionError = assertThrows(AssertionError.class, () -> logCapture.assertLogged(times(3), info("hello world"))); + + assertThat(assertionError).hasMessage(""" + Expected log message has not occurred exactly 3 time(s) + actual occurrences: 2 + message: INFO "hello world" (regex) + """); } @Test - void times_lowerThan2_throwsIllegalArgumentException() { - - assertThrows(IllegalArgumentException.class, () -> times(1)); - assertThrows(IllegalArgumentException.class, () -> times(0)); + void times_lowerThanZero_throwsIllegalArgumentException() { + var assertionError = assertThrows(IllegalArgumentException.class, () -> times(-1)); + assertThat(assertionError).hasMessage("Number of log message occurrences that are expected must be positive."); } @Test - void atMost_lowerThan1_throwsIllegalArgumentException() { + void atMost_lowerThanZero_throwsIllegalArgumentException() { + var assertionError = assertThrows(IllegalArgumentException.class, () -> atMost(-1)); + assertThat(assertionError).hasMessage("Maximum number of log message occurrences that are expected must be greater than 0."); - assertThrows(IllegalArgumentException.class, () -> atMost(0)); } @Test @@ -77,13 +89,24 @@ void assertLoggedWithTimesOnce_loggedTooOften_assertionFails() { log.info("hello world"); log.info("hello world"); - assertThrows(AssertionError.class, () -> logCapture.assertLogged(once(), info("hello world"))); + var assertionError = assertThrows(AssertionError.class, () -> logCapture.assertLogged(once(), info("hello world"))); + assertThat(assertionError).hasMessage(""" + Expected log message has not occurred exactly 1 time(s) + actual occurrences: 2 + message: INFO "hello world" (regex) + """); + } @Test - void assertLoggedWithTimesOnce_loggedTooLess_assertionFails() { - - assertThrows(AssertionError.class, () -> logCapture.assertLogged(once(), info("hello world"))); + void assertLoggedWithTimesOnce_loggedTooLittle_assertionFails() { + + var assertionError = assertThrows(AssertionError.class, () -> logCapture.assertLogged(once(), info("hello world"))); + assertThat(assertionError).hasMessage(""" + Expected log message has not occurred exactly 1 time(s) + actual occurrences: 0 + message: INFO "hello world" (regex) + """); } @Test @@ -105,11 +128,17 @@ void assertLoggedWithAtLeast_loggedTooOften_succeeds() { } @Test - void assertLoggedWithAtLeast_loggedTooLess_assertionFails() { + void assertLoggedWithAtLeast_loggedTooLittle_assertionFails() { log.info("hello world"); log.info("hello world"); - assertThrows(AssertionError.class, () -> logCapture.assertLogged(atLeast(3), info("hello world"))); + var assertionError = assertThrows(AssertionError.class, () -> logCapture.assertLogged(atLeast(3), info("hello world"))); + assertThat(assertionError).hasMessage(""" + Expected log message has not occurred at least 3 time(s) + actual occurrences: 2 + message: INFO "hello world" (regex) + """); + } @Test @@ -127,7 +156,12 @@ void assertLoggedWithAtMost_loggedTooOften_assertionFails() { log.info("hello world"); log.info("hello world"); - assertThrows(AssertionError.class, () -> logCapture.assertLogged(atMost(2), info("hello world"))); + var assertionError = assertThrows(AssertionError.class, () -> logCapture.assertLogged(atMost(2), info("hello world"))); + assertThat(assertionError).hasMessage(""" + Expected log message has not occurred at most 2 time(s) + actual occurrences: 3 + message: INFO "hello world" (regex) + """); } @Test From 19cd593f8b407c188fcbf37d71af74d9a63d8d6b Mon Sep 17 00:00:00 2001 From: Daniel Flassak Date: Mon, 3 Feb 2025 14:09:12 +0100 Subject: [PATCH 16/23] move tests into individual files instead of using @Nested --- .../example/app}/AssertedTimesUnitTest.java | 7 +- .../com/example/app/BasicReadableApiTest.java | 134 +++ .../example/app/ExpectedExceptionTest.java | 120 +++ .../com/example/app/ExpectedKeyValueTest.java | 159 +++ .../com/example/app/ExpectedLoggerTest.java | 87 ++ .../com/example/app/ExpectedMarkerTest.java | 141 +++ .../java/com/example/app/ExpectedMdcTest.java | 215 ++++ .../java/com/example/app/InOrderTest.java | 184 ++++ .../java/com/example/app/ReadableApiTest.java | 926 ------------------ 9 files changed, 1045 insertions(+), 928 deletions(-) rename src/test/java/{de/dm/infrastructure/logcapture => com/example/app}/AssertedTimesUnitTest.java (94%) create mode 100644 src/test/java/com/example/app/BasicReadableApiTest.java create mode 100644 src/test/java/com/example/app/ExpectedExceptionTest.java create mode 100644 src/test/java/com/example/app/ExpectedKeyValueTest.java create mode 100644 src/test/java/com/example/app/ExpectedLoggerTest.java create mode 100644 src/test/java/com/example/app/ExpectedMarkerTest.java create mode 100644 src/test/java/com/example/app/ExpectedMdcTest.java create mode 100644 src/test/java/com/example/app/InOrderTest.java delete mode 100644 src/test/java/com/example/app/ReadableApiTest.java diff --git a/src/test/java/de/dm/infrastructure/logcapture/AssertedTimesUnitTest.java b/src/test/java/com/example/app/AssertedTimesUnitTest.java similarity index 94% rename from src/test/java/de/dm/infrastructure/logcapture/AssertedTimesUnitTest.java rename to src/test/java/com/example/app/AssertedTimesUnitTest.java index 1ddda6e..572d043 100644 --- a/src/test/java/de/dm/infrastructure/logcapture/AssertedTimesUnitTest.java +++ b/src/test/java/com/example/app/AssertedTimesUnitTest.java @@ -1,5 +1,8 @@ -package de.dm.infrastructure.logcapture; +package com.example.app; +import de.dm.infrastructure.logcapture.ExpectedException; +import de.dm.infrastructure.logcapture.LogCapture; +import de.dm.infrastructure.logcapture.LogExpectation; import lombok.extern.slf4j.Slf4j; import org.junit.jupiter.api.Test; import org.junit.jupiter.api.extension.RegisterExtension; @@ -38,7 +41,7 @@ void assertLoggedWithTimes_loggedTooOften_assertionFails() { log.info("hello world"); log.info("hello world"); - var assertionError = assertThrows(AssertionError.class, () -> logCapture.assertLogged(times(2), info("hello world", mdc("foo", "bar"), ExpectedException.exception().expectedMessageRegex("noooo!").build()))); + var assertionError = assertThrows(AssertionError.class, () -> logCapture.assertLogged(times(2), LogExpectation.info("hello world", mdc("foo", "bar"), ExpectedException.exception().expectedMessageRegex("noooo!").build()))); assertThat(assertionError).hasMessage(""" Expected log message has not occurred exactly 2 time(s) diff --git a/src/test/java/com/example/app/BasicReadableApiTest.java b/src/test/java/com/example/app/BasicReadableApiTest.java new file mode 100644 index 0000000..257f001 --- /dev/null +++ b/src/test/java/com/example/app/BasicReadableApiTest.java @@ -0,0 +1,134 @@ +package com.example.app; + +import de.dm.infrastructure.logcapture.LogCapture; +import lombok.extern.slf4j.Slf4j; +import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.extension.RegisterExtension; +import org.slf4j.MDC; + +import static de.dm.infrastructure.logcapture.ExpectedException.exception; +import static de.dm.infrastructure.logcapture.ExpectedMdcEntry.mdc; +import static de.dm.infrastructure.logcapture.LogExpectation.any; +import static de.dm.infrastructure.logcapture.LogExpectation.debug; +import static de.dm.infrastructure.logcapture.LogExpectation.error; +import static de.dm.infrastructure.logcapture.LogExpectation.info; +import static de.dm.infrastructure.logcapture.LogExpectation.trace; +import static de.dm.infrastructure.logcapture.LogExpectation.warn; +import static org.assertj.core.api.Assertions.assertThat; +import static org.junit.jupiter.api.Assertions.assertThrows; + +@Slf4j +@SuppressWarnings({ + "java:S5778", //this rule does not increase the clarity of these tests + "LoggingSimilarMessage" // not a sensible rule for a logging test +}) +class BasicReadableApiTest { + @RegisterExtension + LogCapture logCapture = LogCapture.forCurrentPackage(); + + @Test + void basicReadableApiSucceeds() { + log.info("hello world", new IllegalArgumentException("shame on you", new NullPointerException("bah!"))); + + logCapture.assertLogged(info("hello world")); + } + + @Test + void varargsAssertionsRequireLogExpectations() { + assertThat( + assertThrows(IllegalArgumentException.class, () -> + logCapture.assertLoggedInAnyOrder() + )) + .hasMessage("at least 2 LogExpectations are required for assertLoggedInAnyOrder(). Found none"); + + assertThat( + assertThrows(IllegalArgumentException.class, () -> + logCapture.assertLoggedInAnyOrder(info("Hello world")) + )) + .hasMessageMatching("at least 2 LogExpectations are required for assertLoggedInAnyOrder\\(\\)\\. Found .*Hello world.*"); + + assertThat( + assertThrows(IllegalArgumentException.class, () -> + logCapture.assertLoggedInOrder() + )) + .hasMessage("at least 2 LogExpectations are required for assertLoggedInOrder(). Found none"); + + assertThat( + assertThrows(IllegalArgumentException.class, () -> + logCapture.assertLoggedInOrder(info("Hello world")) + )) + .hasMessageMatching("at least 2 LogExpectations are required for assertLoggedInOrder\\(\\)\\. Found .*Hello world.*"); + + assertThat( + assertThrows(IllegalArgumentException.class, () -> + logCapture.assertNotLogged() + )) + .hasMessageMatching("at least one LogExpectation is required for assertNotLogged\\(\\)\\. Found none"); + } + + @Test + void withRequiresAtLeastOneMatcher() { + assertThat( + assertThrows(IllegalArgumentException.class, () -> + logCapture + .with() + .assertLogged(info("Hello world")) + )) + .hasMessage("with() needs at least one LogEventMatcher"); + } + + @Test + void allLevelsWork() { + log.error("first error"); + log.error("second error"); + log.warn("first warn"); + log.warn("second warn"); + log.info("first info"); + log.info("second info"); + log.debug("first debug"); + log.debug("second debug"); + log.trace("first trace"); + log.trace("second trace"); + + logCapture.assertLoggedInOrder( + error("first error"), + error("second error")); + logCapture.assertLoggedInOrder( + warn("first warn"), + warn("second warn")); + logCapture.assertLoggedInOrder( + info("first info"), + info("second info")); + logCapture.assertLoggedInOrder( + debug("first debug"), + debug("second debug")); + logCapture.assertLoggedInOrder( + trace("first trace"), + trace("second trace")); + logCapture.assertNotLogged(warn("first error")); + logCapture.assertNotLogged(any("notlogged error")); + } + + + @Test + void combinedLogExpectationsOnlyOutputMismatch() { + MDC.put("key", "a value"); + log.error("some error", new RuntimeException("an exception that was logged")); + MDC.clear(); + + AssertionError assertionError = assertThrows(AssertionError.class, () -> + logCapture.assertLogged( + error("some error", + mdc("key", "a value"), + exception().expectedMessageRegex("an exception that was not logged").build()) + )); + + assertThat(assertionError).hasMessage(""" + Expected log message has occurred, but never with the expected Exception: + message: ERROR "some error" (regex) + expected exception: message (regex): "an exception that was not logged" + actual exception: message: "an exception that was logged", type: java.lang.RuntimeException + """); + } + +} diff --git a/src/test/java/com/example/app/ExpectedExceptionTest.java b/src/test/java/com/example/app/ExpectedExceptionTest.java new file mode 100644 index 0000000..6305ea7 --- /dev/null +++ b/src/test/java/com/example/app/ExpectedExceptionTest.java @@ -0,0 +1,120 @@ +package com.example.app; + +import de.dm.infrastructure.logcapture.LogCapture; +import lombok.extern.slf4j.Slf4j; +import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.extension.RegisterExtension; + +import static de.dm.infrastructure.logcapture.ExpectedException.exception; +import static de.dm.infrastructure.logcapture.LogExpectation.any; +import static de.dm.infrastructure.logcapture.LogExpectation.debug; +import static de.dm.infrastructure.logcapture.LogExpectation.error; +import static de.dm.infrastructure.logcapture.LogExpectation.info; +import static de.dm.infrastructure.logcapture.LogExpectation.trace; +import static de.dm.infrastructure.logcapture.LogExpectation.warn; +import static org.assertj.core.api.Assertions.assertThat; +import static org.junit.jupiter.api.Assertions.assertThrows; + +@Slf4j +@SuppressWarnings({ + "java:S5778", //this rule does not increase the clarity of these tests + "LoggingSimilarMessage" // not a sensible rule for a logging test +}) +class ExpectedExceptionTest { + @RegisterExtension + LogCapture logCapture = LogCapture.forCurrentPackage(); + + @Test + void expectedExceptionSucceeds() { + log.warn("oh no!", new IllegalArgumentException("shame on you!", new NullPointerException("never use null"))); + + logCapture.assertLogged( + warn("oh no!", + exception() + .expectedMessageRegex("shame on you!") + .expectedType(RuntimeException.class) + .build() + )); + logCapture.assertLogged( + warn("oh no!", + exception() + .expectedType(IllegalArgumentException.class) + .expectedCause(exception() + .expectedType(NullPointerException.class) + .expectedMessageRegex("never use null") + .build()) + .build() + )); + logCapture.assertNotLogged(debug(), info(), trace(), error()); + logCapture.assertLogged(warn()); + } + + @Test + void expectedExceptionFails() { + log.info("without exception"); + log.warn("oh no!", new IllegalArgumentException("this is illegal", new NullPointerException("never be null!"))); + + AssertionError assertionError = assertThrows(AssertionError.class, + () -> logCapture.assertLogged( + warn("oh no!", + exception() + .expectedMessageRegex("a message never used") + .expectedType(RuntimeException.class) + .build() + ))); + + assertThat(assertionError).hasMessage(""" + Expected log message has occurred, but never with the expected Exception: + message: WARN "oh no!" (regex) + expected exception: message (regex): "a message never used" type: java.lang.RuntimeException + actual exception: message: "this is illegal", type: java.lang.IllegalArgumentException, cause: (message: "never be null!", type: java.lang.NullPointerException) + """); + + AssertionError withoutExceptionAssertionError = assertThrows(AssertionError.class, + () -> logCapture.assertLogged( + info("without exception", + exception() + .expectedMessageRegex("a message never used") + .expectedType(RuntimeException.class) + .build() + ))); + + assertThat(withoutExceptionAssertionError).hasMessage(""" + Expected log message has occurred, but never with the expected Exception: + message: INFO "without exception" (regex) + expected exception: message (regex): "a message never used" type: java.lang.RuntimeException + actual exception: (null) + """); + + } + + @Test + void assertNotLoggedFails() { + log.info("testlogmessage"); + + final AssertionError exceptionAny = assertThrows(AssertionError.class, () -> logCapture.assertNotLogged(any())); + assertThat(exceptionAny).hasMessage(""" + Found a log message that should not be logged. + message: + """); + + final AssertionError exceptionWithLevel = assertThrows(AssertionError.class, () -> logCapture.assertNotLogged(info())); + assertThat(exceptionWithLevel).hasMessage(""" + Found a log message that should not be logged. + message: INFO + """); + + final AssertionError exceptionWithRegex = assertThrows(AssertionError.class, () -> logCapture.assertNotLogged(any("testlogmessage"))); + assertThat(exceptionWithRegex).hasMessage(""" + Found a log message that should not be logged. + message: "testlogmessage" (regex) + """); + + final AssertionError exceptionWithRegexAndLevel = assertThrows(AssertionError.class, () -> logCapture.assertNotLogged(info("testlogmessage"))); + assertThat(exceptionWithRegexAndLevel).hasMessage(""" + Found a log message that should not be logged. + message: INFO "testlogmessage" (regex) + """); + } + +} diff --git a/src/test/java/com/example/app/ExpectedKeyValueTest.java b/src/test/java/com/example/app/ExpectedKeyValueTest.java new file mode 100644 index 0000000..4ee2173 --- /dev/null +++ b/src/test/java/com/example/app/ExpectedKeyValueTest.java @@ -0,0 +1,159 @@ +package com.example.app; + +import de.dm.infrastructure.logcapture.LogCapture; +import lombok.extern.slf4j.Slf4j; +import org.junit.jupiter.api.Assertions; +import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.extension.RegisterExtension; + +import java.math.BigDecimal; +import java.util.concurrent.atomic.AtomicInteger; + +import static de.dm.infrastructure.logcapture.ExpectedKeyValue.keyValue; +import static de.dm.infrastructure.logcapture.LogExpectation.info; +import static org.assertj.core.api.Assertions.assertThat; +import static org.junit.jupiter.api.Assertions.assertThrows; + +@Slf4j +@SuppressWarnings({ + "java:S5778", //this rule does not increase the clarity of these tests + "LoggingSimilarMessage" // not a sensible rule for a logging test +}) +class ExpectedKeyValueTest { + @RegisterExtension + LogCapture logCapture = LogCapture.forCurrentPackage(); + + + @Test + void failsWithDetailsNotMatchingExistingKeyValues() { + log.atInfo().setMessage("hello") + .addKeyValue("key1", 1) + .addKeyValue("key2", "value2") + .log(); + + var assertionError = assertThrows(AssertionError.class, () -> + logCapture.assertLogged(info("hello", keyValue("key", "a value"))) + ); + assertThat(assertionError).hasMessage(""" + Expected log message has occurred, but never with the expected key-value pair: + message: INFO "hello" (regex) + expected key-value pair (key, a value) + actual pairs: [(key1, 1), (key2, value2)] + """); + } + + @Test + void failsWithDetailsWithNoExistingKeyValues() { + log.atInfo().setMessage("hello") + .log(); + + var assertionError = assertThrows(AssertionError.class, () -> + logCapture.assertLogged(info("hello", keyValue("key", "a value"))) + ); + assertThat(assertionError).hasMessage(""" + Expected log message has occurred, but never with the expected key-value pair: + message: INFO "hello" (regex) + expected key-value pair (key, a value) + actual pairs: [] + """); + } + + @Test + void requiresKey() { + var assertionError = assertThrows(IllegalArgumentException.class, () -> + logCapture.assertLogged(info("hello", keyValue(null, "a value"))) + ); + assertThat(assertionError).hasMessage("key and value are required for key-value log assertion"); + } + + @Test + void requiresValue() { + var assertionError = assertThrows(IllegalArgumentException.class, () -> + logCapture.assertLogged(info("hello", keyValue("a_key", null))) + ); + assertThat(assertionError).hasMessage("key and value are required for key-value log assertion"); + } + + @Test + void succeedsWithString() { + log.atInfo().setMessage("hello") + .addKeyValue("name", "Frederick") + .log(); + + Assertions.assertDoesNotThrow(() -> + logCapture.assertLogged(info("hello", keyValue("name", "Frederick"))) + ); + } + + @Test + void succeedsWithLong() { + log.atInfo().setMessage("hello") + .addKeyValue("meaning", 42L) + .log(); + + Assertions.assertDoesNotThrow(() -> + logCapture.assertLogged(info("hello", keyValue("meaning", 42L))) + ); + } + + @Test + void succeedsWithLongAndInt() { + log.atInfo().setMessage("hello") + .addKeyValue("meaning", 42) + .log(); + + Assertions.assertDoesNotThrow(() -> + logCapture.assertLogged(info("hello", keyValue("meaning", 42L))) + ); + } + + @Test + void succeedsWithIntAndLong() { + log.atInfo().setMessage("hello") + .addKeyValue("meaning", 42L) + .log(); + + Assertions.assertDoesNotThrow(() -> + logCapture.assertLogged(info("hello", keyValue("meaning", 42))) + ); + } + + @Test + void succeedsWithIntAndAtomicInt() { + log.atInfo().setMessage("hello") + .addKeyValue("meaning", new AtomicInteger(42)) + .log(); + + Assertions.assertDoesNotThrow(() -> + logCapture.assertLogged(info("hello", keyValue("meaning", 42))) + ); + } + + @Test + void failsWithBigDecimalAndPrecisionAndInt() { + log.atInfo().setMessage("hello") + .addKeyValue("meaning", new BigDecimal("42.00")) + .log(); + + var assertionError = assertThrows(AssertionError.class, () -> + logCapture.assertLogged(info("hello", keyValue("meaning", 42))) + ); + assertThat(assertionError).hasMessage(""" + Expected log message has occurred, but never with the expected key-value pair: + message: INFO "hello" (regex) + expected key-value pair (meaning, 42) + actual pairs: [(meaning, 42.00)] + """); + } + + @Test + void succeedsWithBigDecimalAndInt() { + log.atInfo().setMessage("hello") + .addKeyValue("meaning", new BigDecimal("42")) + .log(); + + Assertions.assertDoesNotThrow(() -> + logCapture.assertLogged(info("hello", keyValue("meaning", 42))) + ); + } +} diff --git a/src/test/java/com/example/app/ExpectedLoggerTest.java b/src/test/java/com/example/app/ExpectedLoggerTest.java new file mode 100644 index 0000000..51875f0 --- /dev/null +++ b/src/test/java/com/example/app/ExpectedLoggerTest.java @@ -0,0 +1,87 @@ +package com.example.app; + +import de.dm.infrastructure.logcapture.LogCapture; +import lombok.extern.slf4j.Slf4j; +import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.extension.RegisterExtension; + +import static de.dm.infrastructure.logcapture.ExpectedLoggerName.logger; +import static de.dm.infrastructure.logcapture.LogExpectation.info; +import static de.dm.infrastructure.logcapture.LogExpectation.warn; +import static org.assertj.core.api.Assertions.assertThat; +import static org.junit.jupiter.api.Assertions.assertThrows; + +@Slf4j +@SuppressWarnings({ + "java:S5778", //this rule does not increase the clarity of these tests + "LoggingSimilarMessage" // not a sensible rule for a logging test +}) +class ExpectedLoggerTest { + @RegisterExtension + LogCapture logCapture = LogCapture.forCurrentPackage(); + + @Test + void expectedLoggerSucceeds() { + log.info("hello world"); + log.warn("bye world"); + + logCapture.assertLogged( + warn("bye world", + logger("ExpectedLoggerTest")) + ); + + logCapture.with( + logger("ExpectedLoggerTest") + ).assertLoggedInAnyOrder( + warn("bye world"), + info("hello world") + ); + + logCapture.with( + logger("^com.example.app.ExpectedLoggerTest") + ).assertLoggedInAnyOrder( + info("hello world"), + warn("bye world") + ); + } + + @Test + void expectedLoggerFails() { + log.info("hello world"); + log.warn("bye world"); + + AssertionError assertionError = assertThrows(AssertionError.class, + () -> logCapture.assertLoggedInOrder( + info("hello world"), + warn("bye world", + logger("WrongLogger$")) + )); + + assertThat(assertionError).hasMessage(""" + Expected log message has occurred, but never with the expected logger name: + message: WARN "bye world" (regex) + expected logger name (regex): "WrongLogger$" + actual logger name: "com.example.app.ExpectedLoggerTest" + """); + } + + @Test + void loggerWithAssertNotLogged() { + log.info("hello on this logger"); + + logCapture.assertNotLogged( + info("hello on this logger", + logger("wrongLogger"))); + + final AssertionError assertionError = assertThrows(AssertionError.class, () -> logCapture.assertNotLogged( + info("hello on this logger", + logger("ExpectedLoggerTest$")))); + assertThat(assertionError) + .hasMessage(""" + Found a log message that should not be logged. + message: INFO "hello on this logger" (regex) + with additional matchers: + - logger name (regex): "ExpectedLoggerTest$" + """); + } +} diff --git a/src/test/java/com/example/app/ExpectedMarkerTest.java b/src/test/java/com/example/app/ExpectedMarkerTest.java new file mode 100644 index 0000000..1ea05a3 --- /dev/null +++ b/src/test/java/com/example/app/ExpectedMarkerTest.java @@ -0,0 +1,141 @@ +package com.example.app; + +import de.dm.infrastructure.logcapture.LogCapture; +import lombok.extern.slf4j.Slf4j; +import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.extension.RegisterExtension; +import org.slf4j.Marker; +import org.slf4j.MarkerFactory; + +import static de.dm.infrastructure.logcapture.ExpectedMarker.marker; +import static de.dm.infrastructure.logcapture.LogExpectation.info; +import static org.assertj.core.api.Assertions.assertThat; +import static org.junit.jupiter.api.Assertions.assertThrows; + +@Slf4j +@SuppressWarnings({ + "java:S5778", //this rule does not increase the clarity of these tests + "LoggingSimilarMessage" // not a sensible rule for a logging test +}) +class ExpectedMarkerTest { + @RegisterExtension + LogCapture logCapture = LogCapture.forCurrentPackage(); + + @Test + void markerFailsBecauseOtherMarkerIsPresent() { + log.info(MarkerFactory.getMarker("unexpected"), "hello with marker"); + + AssertionError assertionError = assertThrows(AssertionError.class, + () -> logCapture.assertLogged( + info("hello with marker", + marker("expected")) + )); + + assertThat(assertionError).hasMessage(""" + Expected log message has occurred, but never with the expected marker name: + message: INFO "hello with marker" (regex) + expected marker name: "expected" + actual marker names: "[unexpected]" + """); + } + + @Test + void markerFailsBecauseNoMarkerIsPresent() { + log.info("hello without marker"); + + AssertionError assertionError = assertThrows(AssertionError.class, + () -> logCapture.assertLogged( + info("hello without marker", + marker("expected")) + )); + + assertThat(assertionError).hasMessage(""" + Expected log message has occurred, but never with the expected marker name: + message: INFO "hello without marker" (regex) + expected marker name: "expected" + but no marker was found + """); + } + + @Test + void markerFailsWhileNestedMarkersArePresent() { + Marker marker = MarkerFactory.getMarker("unexpected_top"); + marker.add(MarkerFactory.getMarker("unexpected_nested")); + log.info(marker, "hello with marker"); + + AssertionError assertionError = assertThrows(AssertionError.class, + () -> logCapture.assertLogged( + info("hello with marker", + marker("expected")) + )); + + assertThat(assertionError).hasMessage(""" + Expected log message has occurred, but never with the expected marker name: + message: INFO "hello with marker" (regex) + expected marker name: "expected" + actual marker names: "[unexpected_top [ unexpected_nested ]]" + """); + } + + @Test + void markerFailsWhileMultipleMarkersArePresent() { + log.atInfo() + .setMessage("hello with markers") + .addMarker(MarkerFactory.getMarker("unexpected1")) + .addMarker(MarkerFactory.getMarker("unexpected2")) + .log(); + + AssertionError assertionError = assertThrows(AssertionError.class, + () -> logCapture.assertLogged( + info("hello with markers", + marker("expected")) + )); + + assertThat(assertionError).hasMessage(""" + Expected log message has occurred, but never with the expected marker name: + message: INFO "hello with markers" (regex) + expected marker name: "expected" + actual marker names: "[unexpected1, unexpected2]" + """); + } + + @Test + void markerSucceedsForNestedMarker() { + Marker marker = MarkerFactory.getMarker("expected_top"); + marker.add(MarkerFactory.getMarker("expected_nested")); + log.info(marker, "hello with marker"); + + logCapture.assertLogged( + info("hello with marker", + marker("expected_nested"))); + } + + @Test + void markerSucceeds() { + log.info(MarkerFactory.getMarker("expected"), "hello with marker"); + + logCapture.assertLogged( + info("hello with marker", + marker("expected"))); + } + + @Test + void markerWithAssertNotLogged() { + log.info(MarkerFactory.getMarker("expected"), "hello with marker"); + + logCapture.assertNotLogged( + info("hello with marker", + marker("not expected"))); + + final AssertionError assertionError = assertThrows(AssertionError.class, () -> logCapture.assertNotLogged( + info("hello with marker", + marker("expected")))); + assertThat(assertionError).hasMessage(""" + Found a log message that should not be logged. + message: INFO "hello with marker" (regex) + with additional matchers: + - marker name: "expected" + """); + } + +} diff --git a/src/test/java/com/example/app/ExpectedMdcTest.java b/src/test/java/com/example/app/ExpectedMdcTest.java new file mode 100644 index 0000000..e13b47f --- /dev/null +++ b/src/test/java/com/example/app/ExpectedMdcTest.java @@ -0,0 +1,215 @@ +package com.example.app; + +import de.dm.infrastructure.logcapture.LogCapture; +import lombok.extern.slf4j.Slf4j; +import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.extension.RegisterExtension; +import org.slf4j.MDC; + +import static de.dm.infrastructure.logcapture.ExpectedMdcEntry.mdc; +import static de.dm.infrastructure.logcapture.LogExpectation.error; +import static de.dm.infrastructure.logcapture.LogExpectation.info; +import static de.dm.infrastructure.logcapture.LogExpectation.warn; +import static org.assertj.core.api.Assertions.assertThat; +import static org.junit.jupiter.api.Assertions.assertThrows; + +@Slf4j +@SuppressWarnings({ + "java:S5778", //this rule does not increase the clarity of these tests + "LoggingSimilarMessage" // not a sensible rule for a logging test +}) +class ExpectedMdcTest { + @RegisterExtension + LogCapture logCapture = LogCapture.forCurrentPackage(); + + @Test + void singleMdcSucceeds() { + log.info("hello world"); + MDC.put("key", "value"); + log.warn("bye world"); + MDC.clear(); + + logCapture.assertLoggedInOrder( + info("hello world"), + warn("bye world", + mdc("key", "value")) + ); + } + + @Test + void singleMdcFails() { + MDC.put("key", "value"); + log.info("hello world"); + MDC.clear(); + log.warn("bye world"); + + AssertionError assertionError = assertThrows(AssertionError.class, () -> + logCapture.assertLoggedInOrder( + info("hello world"), + warn("bye world", + mdc("key", "value")) + )); + + assertThat(assertionError).hasMessage(""" + Expected log message has occurred, but never with the expected MDC value: + message: WARN "bye world" (regex) + captured message: "bye world" + expected MDC key: key + expected MDC value: ".*value.*" + captured MDC values: + """); + } + + @Test + void mdcForAllFails() { + MDC.put("key", "value"); + log.info("hello world"); + MDC.clear(); + log.warn("bye world"); + + AssertionError assertionError = assertThrows(AssertionError.class, () -> + logCapture + .with( + mdc("key", "value")) + .assertLoggedInAnyOrder( + info("hello world"), + warn("bye world") + )); + + assertThat(assertionError).hasMessage(""" + Expected log message has occurred, but never with the expected MDC value: + message: WARN "bye world" (regex) + captured message: "bye world" + expected MDC key: key + expected MDC value: ".*value.*" + captured MDC values: + """); + } + + @Test + void mdcForAllSucceeds() { + MDC.put("key", "value"); + log.info("hello world"); + log.warn("bye world"); + MDC.clear(); + + logCapture + .with( + mdc("key", "value")) + .assertLoggedInAnyOrder( + info("hello world"), + warn("bye world")); + } + + @Test + void mdcForAllAndSingleMdcFails() { + MDC.put("key", "value"); + MDC.put("another_key", "another_value"); + log.info("hello world"); + MDC.remove("another_key"); + log.warn("bye world"); + MDC.clear(); + + AssertionError assertionError = assertThrows(AssertionError.class, () -> + logCapture + .with( + mdc("key", "value")) + .assertLoggedInAnyOrder( + info("hello world"), + warn("bye world", + mdc("another_key", "another_value")) + )); + + assertThat(assertionError).hasMessage(""" + Expected log message has occurred, but never with the expected MDC value: + message: WARN "bye world" (regex) + captured message: "bye world" + expected MDC key: another_key + expected MDC value: ".*another_value.*" + captured MDC values: + key: "value" + """); + } + + @Test + void mdcForAllAndSingleMdcSucceeds() { + MDC.put("key", "value"); + log.info("hello world"); + MDC.put("another_key", "another_value"); + log.warn("bye world"); + MDC.remove("another_key"); + log.error("hello again"); + MDC.clear(); + + logCapture + .with( + mdc("key", "value") + ) + .assertLoggedInOrder( + info("hello world"), + warn("bye world", + mdc("another_key", "another_value")), + error("hello again")); + } + + @Test + void customMdcMatcherFails() { + MDC.put("key", "value"); + log.info("hello"); + MDC.clear(); + + AssertionError assertionError = assertThrows(AssertionError.class, + () -> logCapture.assertLogged( + info("hello", + mdc("key", mdcValue -> !mdcValue.equals("value")) + ))); + + assertThat(assertionError).hasMessage(""" + Expected log message has occurred, but never with the expected MDC value: + message: INFO "hello" (regex) + captured message: "hello" + expected MDC key: key + captured MDC values: + key: "value" + """); + } + + @Test + void customMdcMatcherSucceeds() { + MDC.put("key", "value"); + log.info("hello"); + MDC.clear(); + + logCapture.assertLogged( + info("hello", + mdc("key", mdcValue -> mdcValue.equals("value")))); + } + + @Test + void notLoggedWithMdc() { + MDC.put("key", "value"); + MDC.put("another_key", "another_value"); + log.info("hello world"); + MDC.clear(); + + logCapture.assertNotLogged(info("helloWorld", mdc("thirdKey", "value"))); + + final AssertionError oneKeyMatches = assertThrows(AssertionError.class, () -> logCapture.assertNotLogged(info("hello world", mdc("key", "value")))); + assertThat(oneKeyMatches).hasMessage(""" + Found a log message that should not be logged. + message: INFO "hello world" (regex) + with additional matchers: + - MDCValue with key: "key" + """); + + final AssertionError bothKeysMatches = assertThrows(AssertionError.class, () -> logCapture.assertNotLogged(info("hello world", mdc("key", "value"), mdc("another_key", "another_value")))); + assertThat(bothKeysMatches).hasMessage(""" + Found a log message that should not be logged. + message: INFO "hello world" (regex) + with additional matchers: + - MDCValue with key: "key" + - MDCValue with key: "another_key" + """); + } + +} diff --git a/src/test/java/com/example/app/InOrderTest.java b/src/test/java/com/example/app/InOrderTest.java new file mode 100644 index 0000000..65c8af3 --- /dev/null +++ b/src/test/java/com/example/app/InOrderTest.java @@ -0,0 +1,184 @@ +package com.example.app; + +import de.dm.infrastructure.logcapture.LogCapture; +import lombok.extern.slf4j.Slf4j; +import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.extension.RegisterExtension; + +import static de.dm.infrastructure.logcapture.LogExpectation.info; +import static org.assertj.core.api.Assertions.assertThat; +import static org.junit.jupiter.api.Assertions.assertThrows; + +@Slf4j +@SuppressWarnings({ + "java:S5778", //this rule does not increase the clarity of these tests + "LoggingSimilarMessage" // not a sensible rule for a logging test +}) +class InOrderTest { + @RegisterExtension + LogCapture logCapture = LogCapture.forCurrentPackage(); + + @Test + void assertionWithoutOrderSucceeds() { + log.info("hello 1"); + log.info("hello 2"); + log.info("hello 3"); + + logCapture.assertLoggedInAnyOrder( + info("hello 3"), + info("hello 1"), + info("hello 2") + ); + } + + @Test + void assertionWithoutOrderFails() { + log.info("hello 1"); + log.info("hello 3"); + + AssertionError assertionError = assertThrows(AssertionError.class, () -> + logCapture.assertLoggedInAnyOrder( + info("hello 3"), + info("hello 1"), + info("hello 2") + )); + + assertThat(assertionError).hasMessage(""" + Expected log message has not occurred. + message: INFO "hello 2" (regex) + """); + } + + @Test + // this behavior is necessary because + // 1. otherwise nothingElseLogged() would be a lot more complicated + // 2. is is reasonable to assume that is it not the user's intention to verify the same message twice + void assertionWithoutOrderMatchingSameMessageFails() { + log.info("hello 1"); + log.info("hello 3"); + + AssertionError assertionError = assertThrows(AssertionError.class, () -> + logCapture.assertLoggedInAnyOrder( + info("hello"), + info("1") + )); + + assertThat(assertionError).hasMessage(""" + Imprecise matching: Two log expectations have matched the same message. Use more precise matching or in-order matching. + -- First match: + message: INFO "hello" (regex) + -- Second match: + message: INFO "1" (regex) + """); + } + + @Test + void assertionWithOrderSucceeds() { + log.info("hello 1"); + log.info("hello 2"); + log.info("hello 3"); + + logCapture.assertLoggedInOrder( + info("hello 1"), + info("hello 2"), + info("hello 3") + ); + } + + @Test + void assertionWithOrderFails() { + log.info("hello 1"); + log.info("hello 2"); + log.info("hello 3"); + + AssertionError assertionError = assertThrows(AssertionError.class, () -> + logCapture.assertLoggedInOrder( + info("hello 1"), + info("hello 3"), + info("hello 2") + )); + + assertThat(assertionError).hasMessage(""" + Expected log message has not occurred. + message: INFO "hello 2" (regex) + """); + } + + @Test + void nothingElseLoggedInOrderSucceeds() { + log.info("hello world"); + log.info("hello universe"); + + logCapture + .assertLoggedInOrder( + info("hello world"), + info("hello universe")) + .assertNothingElseLogged(); + } + + @Test + void nothingElseLoggedInOrderFails() { + log.info("hello world"); + log.info("hello universe"); + log.info("hello multiverse"); + + AssertionError assertionError = assertThrows(AssertionError.class, () -> + logCapture + .assertLoggedInOrder( + info("hello world"), + info("hello universe")) + .assertNothingElseLogged()); + + assertThat(assertionError).hasMessage("There have been other log messages than the asserted ones."); + } + + @Test + void nothingElseLoggedOutOfOrderSucceeds() { + log.info("hello world"); + log.info("hello universe"); + + logCapture + .assertLoggedInAnyOrder( + info("hello universe"), + info("hello world")) + .assertNothingElseLogged(); + } + + @Test + void nothingElseLoggedOutOfOrderFails() { + log.info("hello world"); + log.info("hello multiverse"); + log.info("hello universe"); + + AssertionError assertionError = assertThrows(AssertionError.class, () -> + logCapture + .assertLoggedInAnyOrder( + info("hello universe"), + info("hello world")) + .assertNothingElseLogged()); + + assertThat(assertionError).hasMessage("There have been other log messages than the asserted ones."); + } + + @Test + void nothingElseLoggedSingleLogMessageSucceeds() { + log.info("hello world"); + + logCapture + .assertLogged(info("hello world")) + .assertNothingElseLogged(); + } + + @Test + void nothingElseLoggedSingleLogMessageFails() { + log.info("hello world"); + log.info("hello universe"); + + AssertionError assertionError = assertThrows(AssertionError.class, () -> + logCapture + .assertLogged(info("hello world")) + .assertNothingElseLogged()); + + assertThat(assertionError).hasMessage("There have been other log messages than the asserted ones."); + } +} diff --git a/src/test/java/com/example/app/ReadableApiTest.java b/src/test/java/com/example/app/ReadableApiTest.java deleted file mode 100644 index a9e50be..0000000 --- a/src/test/java/com/example/app/ReadableApiTest.java +++ /dev/null @@ -1,926 +0,0 @@ -package com.example.app; - -import de.dm.infrastructure.logcapture.LogCapture; -import lombok.extern.slf4j.Slf4j; -import org.junit.jupiter.api.Nested; -import org.junit.jupiter.api.Test; -import org.junit.jupiter.api.extension.RegisterExtension; -import org.slf4j.MDC; -import org.slf4j.Marker; -import org.slf4j.MarkerFactory; - -import java.math.BigDecimal; -import java.util.concurrent.atomic.AtomicInteger; - -import static de.dm.infrastructure.logcapture.ExpectedException.exception; -import static de.dm.infrastructure.logcapture.ExpectedKeyValue.keyValue; -import static de.dm.infrastructure.logcapture.ExpectedLoggerName.logger; -import static de.dm.infrastructure.logcapture.ExpectedMarker.marker; -import static de.dm.infrastructure.logcapture.ExpectedMdcEntry.mdc; -import static de.dm.infrastructure.logcapture.LogExpectation.any; -import static de.dm.infrastructure.logcapture.LogExpectation.debug; -import static de.dm.infrastructure.logcapture.LogExpectation.error; -import static de.dm.infrastructure.logcapture.LogExpectation.info; -import static de.dm.infrastructure.logcapture.LogExpectation.trace; -import static de.dm.infrastructure.logcapture.LogExpectation.warn; -import static org.assertj.core.api.Assertions.assertThat; -import static org.junit.jupiter.api.Assertions.assertDoesNotThrow; -import static org.junit.jupiter.api.Assertions.assertThrows; - -@Slf4j -@SuppressWarnings({ - "java:S5778", //this rule does not increase the clarity of these tests - "LoggingSimilarMessage" // not a sensible rule for a logging test -}) -class ReadableApiTest { - @RegisterExtension - LogCapture logCapture = LogCapture.forCurrentPackage(); - - @Test - void basicReadableApiSucceeds() { - log.info("hello world", new IllegalArgumentException("shame on you", new NullPointerException("bah!"))); - - logCapture.assertLogged(info("hello world")); - } - - @Test - void varargsAssertionsRequireLogExpectations() { - assertThat( - assertThrows(IllegalArgumentException.class, () -> - logCapture.assertLoggedInAnyOrder() - )) - .hasMessage("at least 2 LogExpectations are required for assertLoggedInAnyOrder(). Found none"); - - assertThat( - assertThrows(IllegalArgumentException.class, () -> - logCapture.assertLoggedInAnyOrder(info("Hello world")) - )) - .hasMessageMatching("at least 2 LogExpectations are required for assertLoggedInAnyOrder\\(\\)\\. Found .*Hello world.*"); - - assertThat( - assertThrows(IllegalArgumentException.class, () -> - logCapture.assertLoggedInOrder() - )) - .hasMessage("at least 2 LogExpectations are required for assertLoggedInOrder(). Found none"); - - assertThat( - assertThrows(IllegalArgumentException.class, () -> - logCapture.assertLoggedInOrder(info("Hello world")) - )) - .hasMessageMatching("at least 2 LogExpectations are required for assertLoggedInOrder\\(\\)\\. Found .*Hello world.*"); - - assertThat( - assertThrows(IllegalArgumentException.class, () -> - logCapture.assertNotLogged() - )) - .hasMessageMatching("at least one LogExpectation is required for assertNotLogged\\(\\)\\. Found none"); - } - - @Test - void withRequiresAtLeastOneMatcher() { - assertThat( - assertThrows(IllegalArgumentException.class, () -> - logCapture - .with() - .assertLogged(info("Hello world")) - )) - .hasMessage("with() needs at least one LogEventMatcher"); - } - - @Test - void allLevelsWork() { - log.error("first error"); - log.error("second error"); - log.warn("first warn"); - log.warn("second warn"); - log.info("first info"); - log.info("second info"); - log.debug("first debug"); - log.debug("second debug"); - log.trace("first trace"); - log.trace("second trace"); - - logCapture.assertLoggedInOrder( - error("first error"), - error("second error")); - logCapture.assertLoggedInOrder( - warn("first warn"), - warn("second warn")); - logCapture.assertLoggedInOrder( - info("first info"), - info("second info")); - logCapture.assertLoggedInOrder( - debug("first debug"), - debug("second debug")); - logCapture.assertLoggedInOrder( - trace("first trace"), - trace("second trace")); - logCapture.assertNotLogged(warn("first error")); - logCapture.assertNotLogged(any("notlogged error")); - } - - @Nested - class ExpectedExceptionWorks { - @Test - void expectedExceptionSucceeds() { - log.warn("oh no!", new IllegalArgumentException("shame on you!", new NullPointerException("never use null"))); - - logCapture.assertLogged( - warn("oh no!", - exception() - .expectedMessageRegex("shame on you!") - .expectedType(RuntimeException.class) - .build() - )); - logCapture.assertLogged( - warn("oh no!", - exception() - .expectedType(IllegalArgumentException.class) - .expectedCause(exception() - .expectedType(NullPointerException.class) - .expectedMessageRegex("never use null") - .build()) - .build() - )); - logCapture.assertNotLogged(debug(), info(), trace(), error()); - logCapture.assertLogged(warn()); - } - - @Test - void expectedExceptionFails() { - log.info("without exception"); - log.warn("oh no!", new IllegalArgumentException("this is illegal", new NullPointerException("never be null!"))); - - AssertionError assertionError = assertThrows(AssertionError.class, - () -> logCapture.assertLogged( - warn("oh no!", - exception() - .expectedMessageRegex("a message never used") - .expectedType(RuntimeException.class) - .build() - ))); - - assertThat(assertionError).hasMessage(""" - Expected log message has occurred, but never with the expected Exception: - message: WARN "oh no!" (regex) - expected exception: message (regex): "a message never used" type: java.lang.RuntimeException - actual exception: message: "this is illegal", type: java.lang.IllegalArgumentException, cause: (message: "never be null!", type: java.lang.NullPointerException) - """); - - AssertionError withoutExceptionAssertionError = assertThrows(AssertionError.class, - () -> logCapture.assertLogged( - info("without exception", - exception() - .expectedMessageRegex("a message never used") - .expectedType(RuntimeException.class) - .build() - ))); - - assertThat(withoutExceptionAssertionError).hasMessage(""" - Expected log message has occurred, but never with the expected Exception: - message: INFO "without exception" (regex) - expected exception: message (regex): "a message never used" type: java.lang.RuntimeException - actual exception: (null) - """); - - } - - @Test - void assertNotLoggedFails() { - log.info("testlogmessage"); - - final AssertionError exceptionAny = assertThrows(AssertionError.class, () -> logCapture.assertNotLogged(any())); - assertThat(exceptionAny).hasMessage(""" - Found a log message that should not be logged. - message: - """); - - final AssertionError exceptionWithLevel = assertThrows(AssertionError.class, () -> logCapture.assertNotLogged(info())); - assertThat(exceptionWithLevel).hasMessage(""" - Found a log message that should not be logged. - message: INFO - """); - - final AssertionError exceptionWithRegex = assertThrows(AssertionError.class, () -> logCapture.assertNotLogged(any("testlogmessage"))); - assertThat(exceptionWithRegex).hasMessage(""" - Found a log message that should not be logged. - message: "testlogmessage" (regex) - """); - - final AssertionError exceptionWithRegexAndLevel = assertThrows(AssertionError.class, () -> logCapture.assertNotLogged(info("testlogmessage"))); - assertThat(exceptionWithRegexAndLevel).hasMessage(""" - Found a log message that should not be logged. - message: INFO "testlogmessage" (regex) - """); - } - - } - - - @Nested - class ExpectedMarker { - @Test - void markerFailsBecauseOtherMarkerIsPresent() { - log.info(MarkerFactory.getMarker("unexpected"), "hello with marker"); - - AssertionError assertionError = assertThrows(AssertionError.class, - () -> logCapture.assertLogged( - info("hello with marker", - marker("expected")) - )); - - assertThat(assertionError).hasMessage(""" - Expected log message has occurred, but never with the expected marker name: - message: INFO "hello with marker" (regex) - expected marker name: "expected" - actual marker names: "[unexpected]" - """); - } - - @Test - void markerFailsBecauseNoMarkerIsPresent() { - log.info("hello without marker"); - - AssertionError assertionError = assertThrows(AssertionError.class, - () -> logCapture.assertLogged( - info("hello without marker", - marker("expected")) - )); - - assertThat(assertionError).hasMessage(""" - Expected log message has occurred, but never with the expected marker name: - message: INFO "hello without marker" (regex) - expected marker name: "expected" - but no marker was found - """); - } - - @Test - void markerFailsWhileNestedMarkersArePresent() { - Marker marker = MarkerFactory.getMarker("unexpected_top"); - marker.add(MarkerFactory.getMarker("unexpected_nested")); - log.info(marker, "hello with marker"); - - AssertionError assertionError = assertThrows(AssertionError.class, - () -> logCapture.assertLogged( - info("hello with marker", - marker("expected")) - )); - - assertThat(assertionError).hasMessage(""" - Expected log message has occurred, but never with the expected marker name: - message: INFO "hello with marker" (regex) - expected marker name: "expected" - actual marker names: "[unexpected_top [ unexpected_nested ]]" - """); - } - - @Test - void markerFailsWhileMultipleMarkersArePresent() { - log.atInfo() - .setMessage("hello with markers") - .addMarker(MarkerFactory.getMarker("unexpected1")) - .addMarker(MarkerFactory.getMarker("unexpected2")) - .log(); - - AssertionError assertionError = assertThrows(AssertionError.class, - () -> logCapture.assertLogged( - info("hello with markers", - marker("expected")) - )); - - assertThat(assertionError).hasMessage(""" - Expected log message has occurred, but never with the expected marker name: - message: INFO "hello with markers" (regex) - expected marker name: "expected" - actual marker names: "[unexpected1, unexpected2]" - """); - } - - @Test - void markerSucceedsForNestedMarker() { - Marker marker = MarkerFactory.getMarker("expected_top"); - marker.add(MarkerFactory.getMarker("expected_nested")); - log.info(marker, "hello with marker"); - - logCapture.assertLogged( - info("hello with marker", - marker("expected_nested"))); - } - - @Test - void markerSucceeds() { - log.info(MarkerFactory.getMarker("expected"), "hello with marker"); - - logCapture.assertLogged( - info("hello with marker", - marker("expected"))); - } - - @Test - void markerWithAssertNotLogged() { - log.info(MarkerFactory.getMarker("expected"), "hello with marker"); - - logCapture.assertNotLogged( - info("hello with marker", - marker("not expected"))); - - final AssertionError assertionError = assertThrows(AssertionError.class, () -> logCapture.assertNotLogged( - info("hello with marker", - marker("expected")))); - assertThat(assertionError).hasMessage(""" - Found a log message that should not be logged. - message: INFO "hello with marker" (regex) - with additional matchers: - - marker name: "expected" - """); - } - - } - - @Nested - class ExpectedLogger { - @Test - void expectedLoggerSucceeds() { - log.info("hello world"); - log.warn("bye world"); - - logCapture.assertLogged( - warn("bye world", - logger("ReadableApiTest$")) - ); - - logCapture.with( - logger("ReadableApiTest$") - ).assertLoggedInAnyOrder( - warn("bye world"), - info("hello world") - ); - - logCapture.with( - logger("^com.example.app.ReadableApiTest$") - ).assertLoggedInAnyOrder( - info("hello world"), - warn("bye world") - ); - } - - @Test - void expectedLoggerFails() { - log.info("hello world"); - log.warn("bye world"); - - AssertionError assertionError = assertThrows(AssertionError.class, - () -> logCapture.assertLoggedInOrder( - info("hello world"), - warn("bye world", - logger("WrongLogger$")) - )); - - assertThat(assertionError).hasMessage(""" - Expected log message has occurred, but never with the expected logger name: - message: WARN "bye world" (regex) - expected logger name (regex): "WrongLogger$" - actual logger name: "com.example.app.ReadableApiTest" - """); - } - - @Test - void loggerWithAssertNotLogged() { - log.info("hello on this logger"); - - logCapture.assertNotLogged( - info("hello on this logger", - logger("wrongLogger"))); - - final AssertionError assertionError = assertThrows(AssertionError.class, () -> logCapture.assertNotLogged( - info("hello on this logger", - logger("ReadableApiTest$")))); - assertThat(assertionError) - .hasMessage(""" - Found a log message that should not be logged. - message: INFO "hello on this logger" (regex) - with additional matchers: - - logger name (regex): "ReadableApiTest$" - """); - } - } - - @Nested - class ExpectedMdc { - @Test - void singleMdcSucceeds() { - log.info("hello world"); - MDC.put("key", "value"); - log.warn("bye world"); - MDC.clear(); - - logCapture.assertLoggedInOrder( - info("hello world"), - warn("bye world", - mdc("key", "value")) - ); - } - - @Test - void singleMdcFails() { - MDC.put("key", "value"); - log.info("hello world"); - MDC.clear(); - log.warn("bye world"); - - AssertionError assertionError = assertThrows(AssertionError.class, () -> - logCapture.assertLoggedInOrder( - info("hello world"), - warn("bye world", - mdc("key", "value")) - )); - - assertThat(assertionError).hasMessage(""" - Expected log message has occurred, but never with the expected MDC value: - message: WARN "bye world" (regex) - captured message: "bye world" - expected MDC key: key - expected MDC value: ".*value.*" - captured MDC values: - """); - } - - @Test - void mdcForAllFails() { - MDC.put("key", "value"); - log.info("hello world"); - MDC.clear(); - log.warn("bye world"); - - AssertionError assertionError = assertThrows(AssertionError.class, () -> - logCapture - .with( - mdc("key", "value")) - .assertLoggedInAnyOrder( - info("hello world"), - warn("bye world") - )); - - assertThat(assertionError).hasMessage(""" - Expected log message has occurred, but never with the expected MDC value: - message: WARN "bye world" (regex) - captured message: "bye world" - expected MDC key: key - expected MDC value: ".*value.*" - captured MDC values: - """); - } - - @Test - void mdcForAllSucceeds() { - MDC.put("key", "value"); - log.info("hello world"); - log.warn("bye world"); - MDC.clear(); - - logCapture - .with( - mdc("key", "value")) - .assertLoggedInAnyOrder( - info("hello world"), - warn("bye world")); - } - - @Test - void mdcForAllAndSingleMdcFails() { - MDC.put("key", "value"); - MDC.put("another_key", "another_value"); - log.info("hello world"); - MDC.remove("another_key"); - log.warn("bye world"); - MDC.clear(); - - AssertionError assertionError = assertThrows(AssertionError.class, () -> - logCapture - .with( - mdc("key", "value")) - .assertLoggedInAnyOrder( - info("hello world"), - warn("bye world", - mdc("another_key", "another_value")) - )); - - assertThat(assertionError).hasMessage(""" - Expected log message has occurred, but never with the expected MDC value: - message: WARN "bye world" (regex) - captured message: "bye world" - expected MDC key: another_key - expected MDC value: ".*another_value.*" - captured MDC values: - key: "value" - """); - } - - @Test - void mdcForAllAndSingleMdcSucceeds() { - MDC.put("key", "value"); - log.info("hello world"); - MDC.put("another_key", "another_value"); - log.warn("bye world"); - MDC.remove("another_key"); - log.error("hello again"); - MDC.clear(); - - logCapture - .with( - mdc("key", "value") - ) - .assertLoggedInOrder( - info("hello world"), - warn("bye world", - mdc("another_key", "another_value")), - error("hello again")); - } - - @Test - void customMdcMatcherFails() { - MDC.put("key", "value"); - log.info("hello"); - MDC.clear(); - - AssertionError assertionError = assertThrows(AssertionError.class, - () -> logCapture.assertLogged( - info("hello", - mdc("key", mdcValue -> !mdcValue.equals("value")) - ))); - - assertThat(assertionError).hasMessage(""" - Expected log message has occurred, but never with the expected MDC value: - message: INFO "hello" (regex) - captured message: "hello" - expected MDC key: key - captured MDC values: - key: "value" - """); - } - - @Test - void customMdcMatcherSucceeds() { - MDC.put("key", "value"); - log.info("hello"); - MDC.clear(); - - logCapture.assertLogged( - info("hello", - mdc("key", mdcValue -> mdcValue.equals("value")))); - } - - @Test - void notLoggedWithMdc() { - MDC.put("key", "value"); - MDC.put("another_key", "another_value"); - log.info("hello world"); - MDC.clear(); - - logCapture.assertNotLogged(info("helloWorld", mdc("thirdKey", "value"))); - - final AssertionError oneKeyMatches = assertThrows(AssertionError.class, () -> logCapture.assertNotLogged(info("hello world", mdc("key", "value")))); - assertThat(oneKeyMatches).hasMessage(""" - Found a log message that should not be logged. - message: INFO "hello world" (regex) - with additional matchers: - - MDCValue with key: "key" - """); - - final AssertionError bothKeysMatches = assertThrows(AssertionError.class, () -> logCapture.assertNotLogged(info("hello world", mdc("key", "value"), mdc("another_key", "another_value")))); - assertThat(bothKeysMatches).hasMessage(""" - Found a log message that should not be logged. - message: INFO "hello world" (regex) - with additional matchers: - - MDCValue with key: "key" - - MDCValue with key: "another_key" - """); - } - - } - - @Nested - class InOrder { - @Test - void assertionWithoutOrderSucceeds() { - log.info("hello 1"); - log.info("hello 2"); - log.info("hello 3"); - - logCapture.assertLoggedInAnyOrder( - info("hello 3"), - info("hello 1"), - info("hello 2") - ); - } - - @Test - void assertionWithoutOrderFails() { - log.info("hello 1"); - log.info("hello 3"); - - AssertionError assertionError = assertThrows(AssertionError.class, () -> - logCapture.assertLoggedInAnyOrder( - info("hello 3"), - info("hello 1"), - info("hello 2") - )); - - assertThat(assertionError).hasMessage(""" - Expected log message has not occurred. - message: INFO "hello 2" (regex) - """); - } - - @Test - // this behavior is necessary because - // 1. otherwise nothingElseLogged() would be a lot more complicated - // 2. is is reasonable to assume that is it not the user's intention to verify the same message twice - void assertionWithoutOrderMatchingSameMessageFails() { - log.info("hello 1"); - log.info("hello 3"); - - AssertionError assertionError = assertThrows(AssertionError.class, () -> - logCapture.assertLoggedInAnyOrder( - info("hello"), - info("1") - )); - - assertThat(assertionError).hasMessage(""" - Imprecise matching: Two log expectations have matched the same message. Use more precise matching or in-order matching. - -- First match: - message: INFO "hello" (regex) - -- Second match: - message: INFO "1" (regex) - """); - } - - @Test - void assertionWithOrderSucceeds() { - log.info("hello 1"); - log.info("hello 2"); - log.info("hello 3"); - - logCapture.assertLoggedInOrder( - info("hello 1"), - info("hello 2"), - info("hello 3") - ); - } - - @Test - void assertionWithOrderFails() { - log.info("hello 1"); - log.info("hello 2"); - log.info("hello 3"); - - AssertionError assertionError = assertThrows(AssertionError.class, () -> - logCapture.assertLoggedInOrder( - info("hello 1"), - info("hello 3"), - info("hello 2") - )); - - assertThat(assertionError).hasMessage(""" - Expected log message has not occurred. - message: INFO "hello 2" (regex) - """); - } - - @Test - void nothingElseLoggedInOrderSucceeds() { - log.info("hello world"); - log.info("hello universe"); - - logCapture - .assertLoggedInOrder( - info("hello world"), - info("hello universe")) - .assertNothingElseLogged(); - } - - @Test - void nothingElseLoggedInOrderFails() { - log.info("hello world"); - log.info("hello universe"); - log.info("hello multiverse"); - - AssertionError assertionError = assertThrows(AssertionError.class, () -> - logCapture - .assertLoggedInOrder( - info("hello world"), - info("hello universe")) - .assertNothingElseLogged()); - - assertThat(assertionError).hasMessage("There have been other log messages than the asserted ones."); - } - - @Test - void nothingElseLoggedOutOfOrderSucceeds() { - log.info("hello world"); - log.info("hello universe"); - - logCapture - .assertLoggedInAnyOrder( - info("hello universe"), - info("hello world")) - .assertNothingElseLogged(); - } - - @Test - void nothingElseLoggedOutOfOrderFails() { - log.info("hello world"); - log.info("hello multiverse"); - log.info("hello universe"); - - AssertionError assertionError = assertThrows(AssertionError.class, () -> - logCapture - .assertLoggedInAnyOrder( - info("hello universe"), - info("hello world")) - .assertNothingElseLogged()); - - assertThat(assertionError).hasMessage("There have been other log messages than the asserted ones."); - } - - @Test - void nothingElseLoggedSingleLogMessageSucceeds() { - log.info("hello world"); - - logCapture - .assertLogged(info("hello world")) - .assertNothingElseLogged(); - } - - @Test - void nothingElseLoggedSingleLogMessageFails() { - log.info("hello world"); - log.info("hello universe"); - - AssertionError assertionError = assertThrows(AssertionError.class, () -> - logCapture - .assertLogged(info("hello world")) - .assertNothingElseLogged()); - - assertThat(assertionError).hasMessage("There have been other log messages than the asserted ones."); - } - } - - @Test - void combinedLogExpectationsOnlyOutputMismatch() { - MDC.put("key", "a value"); - log.error("some error", new RuntimeException("an exception that was logged")); - MDC.clear(); - - AssertionError assertionError = assertThrows(AssertionError.class, () -> - logCapture.assertLogged( - error("some error", - mdc("key", "a value"), - exception().expectedMessageRegex("an exception that was not logged").build()) - )); - - assertThat(assertionError).hasMessage(""" - Expected log message has occurred, but never with the expected Exception: - message: ERROR "some error" (regex) - expected exception: message (regex): "an exception that was not logged" - actual exception: message: "an exception that was logged", type: java.lang.RuntimeException - """); - } - - @Nested - class ExpectedKeyValues { - @Test - void failsWithDetailsNotMatchingExistingKeyValues() { - log.atInfo().setMessage("hello") - .addKeyValue("key1", 1) - .addKeyValue("key2", "value2") - .log(); - - var assertionError = assertThrows(AssertionError.class, () -> - logCapture.assertLogged(info("hello", keyValue("key", "a value"))) - ); - assertThat(assertionError).hasMessage(""" - Expected log message has occurred, but never with the expected key-value pair: - message: INFO "hello" (regex) - expected key-value pair (key, a value) - actual pairs: [(key1, 1), (key2, value2)] - """); - } - - @Test - void failsWithDetailsWithNoExistingKeyValues() { - log.atInfo().setMessage("hello") - .log(); - - var assertionError = assertThrows(AssertionError.class, () -> - logCapture.assertLogged(info("hello", keyValue("key", "a value"))) - ); - assertThat(assertionError).hasMessage(""" - Expected log message has occurred, but never with the expected key-value pair: - message: INFO "hello" (regex) - expected key-value pair (key, a value) - actual pairs: [] - """); - } - - @Test - void requiresKey() { - var assertionError = assertThrows(IllegalArgumentException.class, () -> - logCapture.assertLogged(info("hello", keyValue(null, "a value"))) - ); - assertThat(assertionError).hasMessage("key and value are required for key-value log assertion"); - } - - @Test - void requiresValue() { - var assertionError = assertThrows(IllegalArgumentException.class, () -> - logCapture.assertLogged(info("hello", keyValue("a_key", null))) - ); - assertThat(assertionError).hasMessage("key and value are required for key-value log assertion"); - } - - @Test - void succeedsWithString() { - log.atInfo().setMessage("hello") - .addKeyValue("name", "Frederick") - .log(); - - assertDoesNotThrow(() -> - logCapture.assertLogged(info("hello", keyValue("name", "Frederick"))) - ); - } - - @Test - void succeedsWithLong() { - log.atInfo().setMessage("hello") - .addKeyValue("meaning", 42L) - .log(); - - assertDoesNotThrow(() -> - logCapture.assertLogged(info("hello", keyValue("meaning", 42L))) - ); - } - - @Test - void succeedsWithLongAndInt() { - log.atInfo().setMessage("hello") - .addKeyValue("meaning", 42) - .log(); - - assertDoesNotThrow(() -> - logCapture.assertLogged(info("hello", keyValue("meaning", 42L))) - ); - } - - @Test - void succeedsWithIntAndLong() { - log.atInfo().setMessage("hello") - .addKeyValue("meaning", 42L) - .log(); - - assertDoesNotThrow(() -> - logCapture.assertLogged(info("hello", keyValue("meaning", 42))) - ); - } - - @Test - void succeedsWithIntAndAtomicInt() { - log.atInfo().setMessage("hello") - .addKeyValue("meaning", new AtomicInteger(42)) - .log(); - - assertDoesNotThrow(() -> - logCapture.assertLogged(info("hello", keyValue("meaning", 42))) - ); - } - - @Test - void failsWithBigDecimalAndPrecisionAndInt() { - log.atInfo().setMessage("hello") - .addKeyValue("meaning", new BigDecimal("42.00")) - .log(); - - var assertionError = assertThrows(AssertionError.class, () -> - logCapture.assertLogged(info("hello", keyValue("meaning", 42))) - ); - assertThat(assertionError).hasMessage(""" - Expected log message has occurred, but never with the expected key-value pair: - message: INFO "hello" (regex) - expected key-value pair (meaning, 42) - actual pairs: [(meaning, 42.00)] - """); - } - - @Test - void succeedsWithBigDecimalAndInt() { - log.atInfo().setMessage("hello") - .addKeyValue("meaning", new BigDecimal("42")) - .log(); - - assertDoesNotThrow(() -> - logCapture.assertLogged(info("hello", keyValue("meaning", 42))) - ); - } - } -} From fcfac75903743c3b75cca469bb6805131c21f46c Mon Sep 17 00:00:00 2001 From: Daniel Flassak Date: Mon, 3 Feb 2025 14:13:25 +0100 Subject: [PATCH 17/23] don't force ternary "?" into the same line --- checkstyle.xml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/checkstyle.xml b/checkstyle.xml index bf77e46..da9489e 100644 --- a/checkstyle.xml +++ b/checkstyle.xml @@ -128,7 +128,7 @@ + value="BAND, BOR, BSR, BXOR, DIV, EQUAL, GE, GT, LAND, LE, LITERAL_INSTANCEOF, LOR, LT, MINUS, MOD, NOT_EQUAL, PLUS, SL, SR, STAR, METHOD_REF "/> From 06fb9c416204f1a51157576bc6e122e4d01fa702 Mon Sep 17 00:00:00 2001 From: Daniel Flassak Date: Mon, 3 Feb 2025 14:15:25 +0100 Subject: [PATCH 18/23] complete Javadoc --- .../java/de/dm/infrastructure/logcapture/ExpectedTimes.java | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/src/main/java/de/dm/infrastructure/logcapture/ExpectedTimes.java b/src/main/java/de/dm/infrastructure/logcapture/ExpectedTimes.java index 5969436..7b392c3 100644 --- a/src/main/java/de/dm/infrastructure/logcapture/ExpectedTimes.java +++ b/src/main/java/de/dm/infrastructure/logcapture/ExpectedTimes.java @@ -38,6 +38,8 @@ enum ComparisonStrategy { * @param times exact number of expected log messages * * @return Times object which asserts with exactly the given times + * + * @throws IllegalArgumentException if expected occurrences are negative */ public static ExpectedTimes times(int times) { @@ -62,6 +64,8 @@ public static ExpectedTimes once() { * @param min minimum number of log message occurrences, must be at least 1 * * @return Times object which asserts at least the given times + * + * @throws IllegalArgumentException if expected occurrences are negative */ public static ExpectedTimes atLeast(int min) { if (min < 1) { @@ -81,6 +85,8 @@ public static ExpectedTimes atLeast(int min) { * @param max maximum number of log message occurrences, must be positive * * @return Times object which asserts at most the given times + * + * @throws IllegalArgumentException if expected occurrences are negative */ public static ExpectedTimes atMost(int max) { if (max < 0) { From a4fb2f9f0d80326df3b452eff1d3e6d8fca92b48 Mon Sep 17 00:00:00 2001 From: Daniel Flassak Date: Mon, 3 Feb 2025 14:21:24 +0100 Subject: [PATCH 19/23] test readability nitpicking --- .../com/example/app/AssertedTimesUnitTest.java | 18 +++++++++++++----- .../logcapture/LogCaptureTest.java | 9 +++++---- 2 files changed, 18 insertions(+), 9 deletions(-) diff --git a/src/test/java/com/example/app/AssertedTimesUnitTest.java b/src/test/java/com/example/app/AssertedTimesUnitTest.java index 572d043..e77a752 100644 --- a/src/test/java/com/example/app/AssertedTimesUnitTest.java +++ b/src/test/java/com/example/app/AssertedTimesUnitTest.java @@ -1,12 +1,11 @@ package com.example.app; -import de.dm.infrastructure.logcapture.ExpectedException; import de.dm.infrastructure.logcapture.LogCapture; -import de.dm.infrastructure.logcapture.LogExpectation; import lombok.extern.slf4j.Slf4j; import org.junit.jupiter.api.Test; import org.junit.jupiter.api.extension.RegisterExtension; +import static de.dm.infrastructure.logcapture.ExpectedException.exception; import static de.dm.infrastructure.logcapture.ExpectedMdcEntry.mdc; import static de.dm.infrastructure.logcapture.ExpectedTimes.atLeast; import static de.dm.infrastructure.logcapture.ExpectedTimes.atMost; @@ -36,12 +35,18 @@ void assertLoggedWithTimes_succeeds() { } @Test - void assertLoggedWithTimes_loggedTooOften_assertionFails() { + void assertLoggedWithTimes_loggedTooOftenWithAdditionalMatchers_assertionFails() { log.info("hello world"); log.info("hello world"); log.info("hello world"); - var assertionError = assertThrows(AssertionError.class, () -> logCapture.assertLogged(times(2), LogExpectation.info("hello world", mdc("foo", "bar"), ExpectedException.exception().expectedMessageRegex("noooo!").build()))); + var assertionError = assertThrows(AssertionError.class, () -> + logCapture.assertLogged( + times(2), + info("hello world", + mdc("foo", "bar"), + exception().expectedMessageRegex("noooo!").build()) + )); assertThat(assertionError).hasMessage(""" Expected log message has not occurred exactly 2 time(s) @@ -58,7 +63,10 @@ void assertLoggedWithTimes_loggedTooFewTimes_assertionFails() { log.info("hello world"); log.info("hello world"); - var assertionError = assertThrows(AssertionError.class, () -> logCapture.assertLogged(times(3), info("hello world"))); + var assertionError = assertThrows(AssertionError.class, () -> + logCapture.assertLogged( + times(3), + info("hello world"))); assertThat(assertionError).hasMessage(""" Expected log message has not occurred exactly 3 time(s) diff --git a/src/test/java/de/dm/infrastructure/logcapture/LogCaptureTest.java b/src/test/java/de/dm/infrastructure/logcapture/LogCaptureTest.java index e8989da..029c9a2 100644 --- a/src/test/java/de/dm/infrastructure/logcapture/LogCaptureTest.java +++ b/src/test/java/de/dm/infrastructure/logcapture/LogCaptureTest.java @@ -9,6 +9,7 @@ import static ch.qos.logback.classic.Level.INFO; import static ch.qos.logback.classic.Level.TRACE; +import static de.dm.infrastructure.logcapture.LogExpectation.info; import static org.assertj.core.api.Assertions.assertThat; import static org.junit.jupiter.api.Assertions.assertThrows; @@ -32,7 +33,7 @@ void fromCurrentPackageWorks() { logCaptureFromOtherPackage.removeAppenderAndResetLogLevel(); assertThat(logCaptureFromOtherPackage.capturedPackages).containsExactly(LogCaptureCreatorInOtherPackage.class.getPackage().getName()); - var thrown = assertThrows(AssertionError.class, () -> logCaptureFromOtherPackage.assertLogged(LogExpectation.info("hello from"))); + var thrown = assertThrows(AssertionError.class, () -> logCaptureFromOtherPackage.assertLogged(info("hello from"))); assertThat(thrown).hasMessage(""" Expected log message has not occurred. message: INFO "hello from" (regex) @@ -55,12 +56,12 @@ private void logLevelIsResetTo(Level originalLevel) { comExampleLogger.setLevel(originalLevel); - LogCapture logCapture = LogCapture.forPackages("com.example"); - logCapture.addAppenderAndSetLogLevelToTrace(); + LogCapture logCaptureComExample = LogCapture.forPackages("com.example"); + logCaptureComExample.addAppenderAndSetLogLevelToTrace(); assertThat(comExampleLogger.getLevel()).isEqualTo(TRACE); - logCapture.removeAppenderAndResetLogLevel(); + logCaptureComExample.removeAppenderAndResetLogLevel(); assertThat(comExampleLogger.getLevel()).isEqualTo(originalLevel); } From 0138688628d199291b0e0626839895919ba3fbef Mon Sep 17 00:00:00 2001 From: Daniel Flassak Date: Mon, 3 Feb 2025 14:25:45 +0100 Subject: [PATCH 20/23] update dependency --- pom.xml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/pom.xml b/pom.xml index 19b1198..e38d76b 100644 --- a/pom.xml +++ b/pom.xml @@ -64,7 +64,7 @@ org.assertj assertj-core - 3.27.2 + 3.27.3 test From d3585d14081c06956739665b983c4a1a7d41d0df Mon Sep 17 00:00:00 2001 From: Daniel Flassak Date: Mon, 3 Feb 2025 14:32:56 +0100 Subject: [PATCH 21/23] fix javadoc --- src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java b/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java index 88196a5..81391eb 100644 --- a/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java +++ b/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java @@ -58,7 +58,7 @@ public NothingElseLoggedAsserter assertLoggedInAnyOrder(LogExpectation... logExp } /** - * assert a single multiple message has been logged + * assert a single message has been logged at least once * * @param logExpectation descriptions of expected log message * From 06eebcd84a407741418dfa1e37d2cb0960df6a19 Mon Sep 17 00:00:00 2001 From: Daniel Flassak Date: Mon, 3 Feb 2025 14:33:47 +0100 Subject: [PATCH 22/23] update README --- README.md | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) diff --git a/README.md b/README.md index ae8d53f..04acad9 100644 --- a/README.md +++ b/README.md @@ -19,6 +19,11 @@ logCapture.assertLoggedInOrder( info("hello world"), warn("bye world") ); + +log.info("I did something", name); +log.info("I did something", name); + +logCapture.assertLogged(atLeast(2), info("I did something")); ``` It's even simple when there's more than just the message and level to assert: @@ -353,7 +358,8 @@ And with MDC logging context ### 4.1.0 -* added Times class which allows matching a LogExpectation multiple times +* **Feature**: Added method to test number of log message repetitions via `times(...)`, `once()`, `atMost(...)` and `atLeast(...)` +* **Improvement**: Better readability of assertion messages ### 4.0.1 From bf7c5f09dc1d38db1d574a26ee4fa4166713ed1d Mon Sep 17 00:00:00 2001 From: Daniel Flassak Date: Mon, 3 Feb 2025 14:57:54 +0100 Subject: [PATCH 23/23] update README --- README.md | 26 ++++++++------------------ 1 file changed, 8 insertions(+), 18 deletions(-) diff --git a/README.md b/README.md index 04acad9..7196325 100644 --- a/README.md +++ b/README.md @@ -19,11 +19,6 @@ logCapture.assertLoggedInOrder( info("hello world"), warn("bye world") ); - -log.info("I did something", name); -log.info("I did something", name); - -logCapture.assertLogged(atLeast(2), info("I did something")); ``` It's even simple when there's more than just the message and level to assert: @@ -47,6 +42,7 @@ logCapture.assertLoggedInOrder( * [Markers](#markers) * [Key-Value](#key-value) * [Logger name](#logger-name) + * [Amount of repetitions](#amount-of-repetitions) * [Examples](#examples) * [Unit Test Example:](#unit-test-example) * [Integration Test Example:](#integration-test-example) @@ -55,7 +51,7 @@ logCapture.assertLoggedInOrder( * [Usage outside of JUnit 5 (Cucumber example)](#usage-outside-of-junit-5-cucumber-example) * [Cucumber example](#cucumber-example) * [Cucumber feature file](#cucumber-feature-file) -* [Changes](#changes) +* [Changes](#changes) * [4.1.0](#410) * [4.0.1](#401) * [4.0.0](#400) @@ -165,9 +161,7 @@ log.info("did something"); logCapture.assertLogged(info("did something", logger("com.acme.foo"))); ``` -### Expect a specific amount of times - -It is possible to match a LogExpectation multiple times. This can be done by using the `Times` class. +#### Amount of repetitions ```java import static de.dm.infrastructure.logcapture.ExpectedLoggerName.logger; @@ -177,17 +171,13 @@ import static de.dm.infrastructure.logcapture.ExpectedLoggerName.logger; log.info("did something"); log.info("did something"); -logCapture.assertLogged(info("did something"), times(2)); -``` - -There are also more options for checking the amount of times a log message is logged a little more or less specific. +logCapture.assertLogged(atLeast(1), info("did something")); +logCapture.assertLogged(times(2), info("did something")); +logCapture.assertLogged(atMost(3), info("did something")); -```java -logCapture.assertLogged(info("did something"), atLeast(1)); // not important if more than once, but at least once -logCapture.assertLogged(info("did something"), atMost(2)); // not important if less than e.g. twice, but at most twice -logCapture.assertLogged(info("did something"), once()); // exactly once +log.info("did nothing"); +logCapture.assertLogged(once(), info("did nothing")); ``` - ### Examples