Skip to content

Commit

Permalink
Merge pull request #23 from Laksuh/master
Browse files Browse the repository at this point in the history
Add assertion for number of times
  • Loading branch information
waschmittel authored Feb 3, 2025
2 parents 3613831 + bf7c5f0 commit f281b75
Show file tree
Hide file tree
Showing 16 changed files with 1,466 additions and 902 deletions.
27 changes: 26 additions & 1 deletion README.md
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand All @@ -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)
Expand Down Expand Up @@ -78,7 +80,7 @@ Add log-capture as a test dependency to your project. If you use Maven, add this
<dependency>
<groupId>de.dm.infrastructure</groupId>
<artifactId>log-capture</artifactId>
<version>4.0.1</version>
<version>4.1.0</version>
<scope>test</scope>
</dependency>
```
Expand Down Expand Up @@ -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:
Expand Down Expand Up @@ -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
Expand Down
2 changes: 1 addition & 1 deletion checkstyle.xml
Original file line number Diff line number Diff line change
Expand Up @@ -128,7 +128,7 @@
<module name="OperatorWrap">
<property name="option" value="EOL"/>
<property name="tokens"
value="BAND, BOR, BSR, BXOR, DIV, EQUAL, GE, GT, LAND, LE, LITERAL_INSTANCEOF, LOR, LT, MINUS, MOD, NOT_EQUAL, PLUS, QUESTION, SL, SR, STAR, METHOD_REF "/>
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 "/>
</module>
<module name="AnnotationLocation">
<property name="id" value="AnnotationLocationMostCases"/>
Expand Down
4 changes: 2 additions & 2 deletions pom.xml
Original file line number Diff line number Diff line change
Expand Up @@ -29,7 +29,7 @@
</developers>

<properties>
<project.version>4.0.0-SNAPSHOT</project.version>
<project.version>4.1.0-SNAPSHOT</project.version>

<java.version>17</java.version>
<encoding>UTF-8</encoding>
Expand Down Expand Up @@ -64,7 +64,7 @@
<dependency>
<groupId>org.assertj</groupId>
<artifactId>assertj-core</artifactId>
<version>3.27.2</version>
<version>3.27.3</version>
<scope>test</scope>
</dependency>
<dependency>
Expand Down
97 changes: 97 additions & 0 deletions src/main/java/de/dm/infrastructure/logcapture/ExpectedTimes.java
Original file line number Diff line number Diff line change
@@ -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.
*
* <p>
* <b>Note:</b> {@link LogCapture#assertNotLogged(LogExpectation...)} can be used
* instead of {@code times(0)} to test that something has not been logged at all
* </p>
*
* @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.
*
* <p>
* <b>Note:</b> {@link LogCapture#assertNotLogged(LogExpectation...)} can be used
* instead of <code>atMost(0)</code> to test that something has not been logged at all
* </p>
*
* @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);
}
}
118 changes: 85 additions & 33 deletions src/main/java/de/dm/infrastructure/logcapture/LogAsserter.java
Original file line number Diff line number Diff line change
Expand Up @@ -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);
}
Expand All @@ -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
*
Expand All @@ -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
*
Expand Down Expand Up @@ -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);
}
Expand Down Expand Up @@ -180,18 +215,33 @@ Integer assertCapturedNext(Optional<Level> level, Optional<String> 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> level, Optional<String> regex, List<LogEventMatcher> 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> level, Optional<String> regex, List<LogEventMatcher> 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> level, Pattern pattern) {
Expand All @@ -203,9 +253,8 @@ private static void throwAssertionForPartiallyMatchingLoggedEvent(Optional<Level

for (LogEventMatcher logEventMatcher : logEventMatchers) {
if (!logEventMatcher.matches(partiallyMatchingLoggedEvent)) {
assertionMessage.append(format("Expected log message has occurred, but never with the expected %s: %s",
assertionMessage.append(format("Expected log message has occurred, but never with the expected %s:%s",
logEventMatcher.getMatcherTypeDescription(), getDescriptionForExpectedMessage(level, regex)));
assertionMessage.append(lineSeparator());
assertionMessage.append(logEventMatcher.getNonMatchingErrorMessage(partiallyMatchingLoggedEvent));
assertionMessage.append(lineSeparator());
}
Expand All @@ -232,31 +281,34 @@ static boolean isMatchedByAll(LoggedEvent loggedEvent, List<? extends LogEventMa

@SuppressWarnings("squid:S1192") // a constant for "Level: " is not helpful
private static String getDescriptionForExpectedMessage(Optional<Level> level, Optional<String> regex) {

if (level.isEmpty() && regex.isEmpty()) {
return "<Any log message>";
}
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> level, Optional<String> regex, List<LogEventMatcher> matchers) {
private static String getDescriptionForExpectedMessageWithAdditionalMatchers(Optional<Level> level, Optional<String> regex, List<LogEventMatcher> 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> level, Optional<String> regex) {
if (level.isEmpty() && regex.isEmpty()) {
return "<Any log message>" + matchersText;
return lineSeparator() + "message: <Any log 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<String> messageRegex) {
return messageRegex
.map("\"%s\" (regex)"::formatted)
.orElse("<any message>");
}

private static String getLevelText(Optional<Level> level) {
return level
.map(Level::toString)
.orElse("<any level>");
}
}
Loading

0 comments on commit f281b75

Please sign in to comment.