diff --git a/README.md b/README.md index bf20b48..7196325 100644 --- a/README.md +++ b/README.md @@ -42,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) @@ -51,6 +52,7 @@ logCapture.assertLoggedInOrder( * [Cucumber example](#cucumber-example) * [Cucumber feature file](#cucumber-feature-file) * [Changes](#changes) + * [4.1.0](#410) * [4.0.1](#401) * [4.0.0](#400) * [3.6.2](#362) @@ -78,7 +80,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 +161,24 @@ log.info("did something"); logCapture.assertLogged(info("did something", logger("com.acme.foo"))); ``` +#### Amount of repetitions + +```java +import static de.dm.infrastructure.logcapture.ExpectedLoggerName.logger; + +... + +log.info("did something"); +log.info("did something"); + +logCapture.assertLogged(atLeast(1), info("did something")); +logCapture.assertLogged(times(2), info("did something")); +logCapture.assertLogged(atMost(3), info("did something")); + +log.info("did nothing"); +logCapture.assertLogged(once(), info("did nothing")); +``` + ### Examples #### Unit Test Example: @@ -326,6 +346,11 @@ And with MDC logging context ## Changes +### 4.1.0 + +* **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 * dependencies updated due to logback vulnerability 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 "/> diff --git a/pom.xml b/pom.xml index 387f01b..e38d76b 100644 --- a/pom.xml +++ b/pom.xml @@ -29,7 +29,7 @@ - 4.0.0-SNAPSHOT + 4.1.0-SNAPSHOT 17 UTF-8 @@ -64,7 +64,7 @@ org.assertj assertj-core - 3.27.2 + 3.27.3 test 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..7b392c3 --- /dev/null +++ b/src/main/java/de/dm/infrastructure/logcapture/ExpectedTimes.java @@ -0,0 +1,97 @@ +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 + * + * @throws IllegalArgumentException if expected occurrences are negative + */ + 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 + * + * @throws IllegalArgumentException if expected occurrences are negative + */ + 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 + * + * @throws IllegalArgumentException if expected occurrences are negative + */ + 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 25c95c7..81391eb 100644 --- a/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java +++ b/src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java @@ -45,12 +45,11 @@ 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", - getDescriptionForUnwantedLogMessage(previousMatch.level, previousMatch.regex, previousMatch.logEventMatchers), - getDescriptionForUnwantedLogMessage(assertion.level, assertion.regex, assertion.logEventMatchers))); + 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))); } matches.put(lastCapturedLogEvent.lastAssertedLogMessageIndex, assertion); } @@ -59,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 * @@ -72,9 +71,46 @@ public NothingElseLoggedAsserter assertLogged(LogExpectation logExpectation) { return new NothingElseLoggedAsserter(1); } + /** + * 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 + * + * @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(ExpectedTimes expectedTimes, LogExpectation logExpectation) { + + var matches = getNumberOfMatches(logExpectation.level, logExpectation.regex, logExpectation.logEventMatchers); + var comparisonStrategy = expectedTimes.getComparisonStrategy(); + var referenceValue = expectedTimes.getReferenceValue(); + + 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 + ? "" + : " (%s without additional matchers)".formatted(matches.matchesWithoutAdditionalMatchers); + throw new AssertionError(""" + Expected log message has not occurred %s %s time(s) + actual occurrences: %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 * @@ -111,7 +147,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); } @@ -180,18 +215,33 @@ 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))); + } + } + + 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 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)) { - throw new AssertionError(format("Found a log message that should not be logged: %s", getDescriptionForUnwantedLogMessage(level, regex, logEventMatchers))); + if (eventMatchesWithoutAdditionalMatchers(event, level, pattern)) { + matchesWithoutAdditionalMatchers++; + if (isMatchedByAll(event, logEventMatchers)) { + completeMatches++; + } } } + return new Matches(completeMatches, matchesWithoutAdditionalMatchers); } private boolean eventMatchesWithoutAdditionalMatchers(LoggedEvent event, Optional level, Pattern pattern) { @@ -203,9 +253,8 @@ private static void throwAssertionForPartiallyMatchingLoggedEvent(Optional level, Optional regex) { - - if (level.isEmpty() && regex.isEmpty()) { - return ""; - } - if (level.isPresent() && regex.isPresent()) { - return "Level: " + level.get() + ", Regex: \"" + regex.get() + "\""; - } - return (level.map(value -> "Level: " + value).orElse("")) + - (regex.map(s -> "Regex: \"" + s + "\"").orElse("")); + return getExpectedLogMessageText(level, regex) + lineSeparator(); } - 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() + " - ")); } + return getExpectedLogMessageText(level, regex) + matchersText + lineSeparator(); + } + + private static String getExpectedLogMessageText(Optional level, Optional regex) { if (level.isEmpty() && regex.isEmpty()) { - return "" + matchersText; + return lineSeparator() + "message: "; } - if (level.isPresent() && regex.isPresent()) { - return "Level: " + level.get() + ", Regex: \"" + regex.get() + "\"" + matchersText; - } - 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/main/java/de/dm/infrastructure/logcapture/LogCapture.java b/src/main/java/de/dm/infrastructure/logcapture/LogCapture.java index 9169fc0..4a8f7a8 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,26 @@ public LogAsserter.NothingElseLoggedAsserter assertLogged(LogExpectation logExpe .assertLogged(logExpectation); } + /** + * assert that a certain expected message has been logged. + * + *

Example: + *

{@code
+     * logCapture.assertLogged(times(3), info("hello world")));
+     * }
+ * + * @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(ExpectedTimes times, LogExpectation logExpectation) { + return new LogAsserter(capturingAppender, new LinkedList<>()) + .assertLogged(times, logExpectation); + } + /** * assert that a certain expected message has not been logged. * diff --git a/src/test/java/com/example/app/AssertedTimesUnitTest.java b/src/test/java/com/example/app/AssertedTimesUnitTest.java new file mode 100644 index 0000000..e77a752 --- /dev/null +++ b/src/test/java/com/example/app/AssertedTimesUnitTest.java @@ -0,0 +1,185 @@ +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.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 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 + LogCapture logCapture = LogCapture.forCurrentPackage(); + + @Test + void assertLoggedWithTimes_succeeds() { + log.info("hello world"); + log.info("hello world"); + log.info("hello world"); + + assertDoesNotThrow(() -> logCapture.assertLogged(times(3), info("hello world"))); + } + + @Test + 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), + info("hello world", + mdc("foo", "bar"), + exception().expectedMessageRegex("noooo!").build()) + )); + + 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_loggedTooFewTimes_assertionFails() { + log.info("hello world"); + log.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_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_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."); + + } + + @Test + void assertLoggedWithTimesOnce_succeeds() { + log.info("hello world"); + + assertDoesNotThrow(() -> logCapture.assertLogged(once(), info("hello world"))); + } + + @Test + void assertLoggedWithTimesOnce_loggedTooOften_assertionFails() { + log.info("hello world"); + log.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_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 + void assertLoggedWithAtLeast_succeeds() { + log.info("hello world"); + log.info("hello world"); + log.info("hello world"); + + assertDoesNotThrow(() -> logCapture.assertLogged(atLeast(3), info("hello world"))); + } + + @Test + void assertLoggedWithAtLeast_loggedTooOften_succeeds() { + log.info("hello world"); + log.info("hello world"); + log.info("hello world"); + + assertDoesNotThrow(() -> logCapture.assertLogged(atLeast(2), info("hello world"))); + } + + @Test + void assertLoggedWithAtLeast_loggedTooLittle_assertionFails() { + log.info("hello world"); + log.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 + void assertLoggedWithAtMost_succeeds() { + log.info("hello world"); + log.info("hello world"); + log.info("hello world"); + + assertDoesNotThrow(() -> logCapture.assertLogged(atMost(3), info("hello world"))); + } + + @Test + void assertLoggedWithAtMost_loggedTooOften_assertionFails() { + log.info("hello world"); + log.info("hello world"); + log.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 + void assertLoggedWithAtMost_loggedLessThanSpecified_succeeds() { + log.info("hello world"); + log.info("hello world"); + + assertDoesNotThrow(() -> logCapture.assertLogged(atMost(3), info("hello world"))); + } +} 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 a4acbfe..0000000 --- a/src/test/java/com/example/app/ReadableApiTest.java +++ /dev/null @@ -1,859 +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 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; - -@Slf4j -@SuppressWarnings("java:S5778") //this rule does not increase the clarity of these tests -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: 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()); - - 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: Level: INFO, Regex: \"without exception\"" + - lineSeparator() + " expected exception: message (regex): \"a message never used\" type: java.lang.RuntimeException" + - lineSeparator() + " actual exception: (null)" + - lineSeparator()); - - } - - @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: "); - - final AssertionError exceptionWithLevel = assertThrows(AssertionError.class, () -> logCapture.assertNotLogged(info())); - assertThat(exceptionWithLevel).hasMessage("Found a log message that should not be logged: Level: 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\""); - - 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\""); - } - - } - - - @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: Level: INFO, Regex: \"hello with marker\"" + - lineSeparator() + " expected marker name: \"expected\"" + - lineSeparator() + " actual marker names: \"[unexpected]\"" + - lineSeparator()); - } - - @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: Level: INFO, Regex: \"hello without marker\"" + - lineSeparator() + " expected marker name: \"expected\"" + - lineSeparator() + " but no marker was found" + - lineSeparator()); - } - - @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: Level: INFO, Regex: \"hello with marker\"" + - lineSeparator() + " expected marker name: \"expected\"" + - lineSeparator() + " actual marker names: \"[unexpected_top [ unexpected_nested ]]\"" + - lineSeparator()); - } - - @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: Level: INFO, Regex: \"hello with markers\"" + - lineSeparator() + " expected marker name: \"expected\"" + - lineSeparator() + " actual marker names: \"[unexpected1, unexpected2]\"" + - lineSeparator()); - } - - @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: Level: INFO, Regex: \"hello with marker\", with matchers:" + - lineSeparator() + " 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: Level: WARN, Regex: \"bye world\"" + - lineSeparator() + " expected logger name (regex): \"WrongLogger$\"" + - lineSeparator() + " actual logger name: \"com.example.app.ReadableApiTest\"" + - lineSeparator()); - } - - @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: Level: INFO, Regex: \"hello on this logger\", with matchers:" + - lineSeparator() + " 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: 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()); - } - - @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: 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()); - } - - @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: 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()); - } - - @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: Level: INFO, Regex: \"hello\"" + - lineSeparator() + " captured message: \"hello\"" + - lineSeparator() + " expected MDC key: key" + - lineSeparator() + " captured MDC values:" + - lineSeparator() + " key: \"value\"" + - lineSeparator()); - } - - @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: Level: INFO, Regex: \"hello world\", with matchers:" + - lineSeparator() + " 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\""); - } - - } - - @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: Level: INFO, Regex: \"hello 2\""); - } - - @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: Level: INFO, Regex: \"hello\" | Second match: Level: INFO, Regex: \"1\""); - } - - @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: Level: INFO, Regex: \"hello 2\""); - } - - @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: 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()); - } - - @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: Level: INFO, Regex: "hello" - 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: Level: INFO, Regex: "hello" - 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: Level: INFO, Regex: "hello" - 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))) - ); - } - } -} diff --git a/src/test/java/de/dm/infrastructure/logcapture/LogCaptureTest.java b/src/test/java/de/dm/infrastructure/logcapture/LogCaptureTest.java index 8493ed4..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,8 +33,11 @@ void fromCurrentPackageWorks() { logCaptureFromOtherPackage.removeAppenderAndResetLogLevel(); 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\""); + var thrown = assertThrows(AssertionError.class, () -> logCaptureFromOtherPackage.assertLogged(info("hello from"))); + assertThat(thrown).hasMessage(""" + Expected log message has not occurred. + message: INFO "hello from" (regex) + """); } @Test @@ -52,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); }