From 7664ce3a5e8b6bc73a4e1d3cb5b9d654e8b1d53d Mon Sep 17 00:00:00 2001 From: Daniel Flassak Date: Fri, 4 Mar 2022 17:53:36 +0100 Subject: [PATCH 1/8] fix typo --- src/test/java/com/example/app/ReadableApiTest.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/test/java/com/example/app/ReadableApiTest.java b/src/test/java/com/example/app/ReadableApiTest.java index a9818a4..4bba76b 100644 --- a/src/test/java/com/example/app/ReadableApiTest.java +++ b/src/test/java/com/example/app/ReadableApiTest.java @@ -332,7 +332,7 @@ void loggerWithAssertNotLogged() { log.info("hello on this logger"); logCapture.assertNotLogged( - info("ello on this logger", + info("hello on this logger", logger("wrongLogger"))); final AssertionError assertionError = assertThrows(AssertionError.class, () -> logCapture.assertNotLogged( From f3a55c42327592b280fe1209721cf8f166f8a9af Mon Sep 17 00:00:00 2001 From: Daniel Flassak Date: Fri, 4 Mar 2022 18:03:30 +0100 Subject: [PATCH 2/8] start implementation of keyValue matcher, bump versions --- pom.xml | 15 +++- .../logcapture/CapturingAppender.java | 1 + .../logcapture/ExpectedKeyValue.java | 55 ++++++++++++++ .../logcapture/LoggedEvent.java | 1 + .../com/example/app/LogstashKeyValueTest.java | 75 +++++++++++++++++++ 5 files changed, 143 insertions(+), 4 deletions(-) create mode 100644 src/main/java/de/dm/infrastructure/logcapture/ExpectedKeyValue.java create mode 100644 src/test/java/com/example/app/LogstashKeyValueTest.java diff --git a/pom.xml b/pom.xml index 60a64f2..c7bfc46 100644 --- a/pom.xml +++ b/pom.xml @@ -32,12 +32,13 @@ 3.4.1-SNAPSHOT 1.8 - 1.18.20 - 1.2.5 - 5.7.2 + 1.18.22 + 1.2.10 + 7.0.1 + 5.8.2 UTF-8 - 3.20.1 + 3.22.1 8.45.1 0.8.7 2.22.2 @@ -62,6 +63,12 @@ logback-classic ${logback.version} + + net.logstash.logback + logstash-logback-encoder + ${logstash-logback-encoder.version} + provided + org.junit.jupiter junit-jupiter-api diff --git a/src/main/java/de/dm/infrastructure/logcapture/CapturingAppender.java b/src/main/java/de/dm/infrastructure/logcapture/CapturingAppender.java index 84daf89..2c99ea4 100644 --- a/src/main/java/de/dm/infrastructure/logcapture/CapturingAppender.java +++ b/src/main/java/de/dm/infrastructure/logcapture/CapturingAppender.java @@ -43,6 +43,7 @@ public synchronized void doAppend(ILoggingEvent loggingEvent) { .mdcData(loggingEvent.getMDCPropertyMap()) .loggedException(getLoggedException(loggingEvent.getThrowableProxy())) .marker(loggingEvent.getMarker()) + .argumentArray(loggingEvent.getArgumentArray()) .build()); } } diff --git a/src/main/java/de/dm/infrastructure/logcapture/ExpectedKeyValue.java b/src/main/java/de/dm/infrastructure/logcapture/ExpectedKeyValue.java new file mode 100644 index 0000000..fedf972 --- /dev/null +++ b/src/main/java/de/dm/infrastructure/logcapture/ExpectedKeyValue.java @@ -0,0 +1,55 @@ +package de.dm.infrastructure.logcapture; + +import lombok.AccessLevel; +import lombok.RequiredArgsConstructor; +import net.logstash.logback.marker.SingleFieldAppendingMarker; + +import java.util.Arrays; +import java.util.stream.Collectors; +import java.util.stream.Stream; + +import static java.lang.String.format; +import static java.lang.System.lineSeparator; + +@RequiredArgsConstructor(access = AccessLevel.PRIVATE) +public class ExpectedKeyValue implements LogEventMatcher { + private final String expectedKey; + private final Object expectedValue; + + // TODO: extract everything referencing net.logstash into a delegate that is only called if that is present in the classpath + // otherwise, fail with an error message describing that keyValue can only be asserted with logstash in the classpath + + @Override + public boolean matches(LoggedEvent loggedEvent) { + return Arrays.stream(loggedEvent.getArgumentArray()) + .flatMap(argument -> argument instanceof SingleFieldAppendingMarker ? Stream.of((SingleFieldAppendingMarker) argument) : Stream.empty()) + .anyMatch(marker -> marker.getFieldValue().equals(expectedValue) && marker.getFieldName().equals(expectedKey)); + } + + @Override + public String getNonMatchingErrorMessage(LoggedEvent loggedEvent) { + String actualKeyValue = Arrays.stream(loggedEvent.getArgumentArray()) + .flatMap(argument -> argument instanceof SingleFieldAppendingMarker ? Stream.of((SingleFieldAppendingMarker) argument) : Stream.empty()) + .map(marker -> format(" key: \"%s\", value: \"%s\"", marker.getFieldName(), marker.getFieldValue())) + .collect(Collectors.joining(lineSeparator())); + + return format(" expected key-value content: key: \"%s\", value: \"%s\"", expectedKey, expectedValue) + + lineSeparator() + + (actualKeyValue.isEmpty() ? " but no key-value content was found" : " actual key-value content:" + lineSeparator() + actualKeyValue); + + } + + @Override + public String getMatcherDescription() { + return "key-value content"; + } + + @Override + public String getMatchingErrorMessage() { + return null; + } + + public static ExpectedKeyValue keyValue(String expectedKey, Object expectedValue) { + return new ExpectedKeyValue(expectedKey, expectedValue); + } +} diff --git a/src/main/java/de/dm/infrastructure/logcapture/LoggedEvent.java b/src/main/java/de/dm/infrastructure/logcapture/LoggedEvent.java index 6510870..662688b 100644 --- a/src/main/java/de/dm/infrastructure/logcapture/LoggedEvent.java +++ b/src/main/java/de/dm/infrastructure/logcapture/LoggedEvent.java @@ -21,6 +21,7 @@ class LoggedEvent { private final Optional loggedException; private final String loggerName; private final Marker marker; + private final Object[] argumentArray; @AllArgsConstructor(access = PRIVATE) @Builder diff --git a/src/test/java/com/example/app/LogstashKeyValueTest.java b/src/test/java/com/example/app/LogstashKeyValueTest.java new file mode 100644 index 0000000..119fcaa --- /dev/null +++ b/src/test/java/com/example/app/LogstashKeyValueTest.java @@ -0,0 +1,75 @@ +package com.example.app; + +import de.dm.infrastructure.logcapture.LogCapture; +import lombok.extern.slf4j.Slf4j; +import net.logstash.logback.argument.StructuredArguments; +import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.extension.RegisterExtension; + +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; + +@SuppressWarnings("java:S5778") //this rule does not increase the clarity of these tests +@Slf4j +class LogstashKeyValueTest { + @RegisterExtension + LogCapture logCapture = LogCapture.forCurrentPackage(); + + @Test + void worksWithObjectEquality() { + log.info("hello", StructuredArguments.keyValue("myKey", "myValue")); + + logCapture.assertLogged(info("hello", keyValue("myKey", "myValue"))); + } + + @Test + void failsWithObjectEquality() { + log.info("hello", StructuredArguments.keyValue("myKey", "actualValue")); + + AssertionError assertionError = assertThrows(AssertionError.class, () -> + logCapture.assertLogged(info("hello", keyValue("myKey", "expectedValue")))); + + assertThat(assertionError).hasMessageFindingMatch( + "Expected log message has occurred, but never with the expected key-value content: Level: INFO, Regex: \"hello\"" + ".*" + + " expected key-value content: key: \"myKey\", value: \"expectedValue\"" + ".*" + + " actual key-value content:" + ".*" + + " key: \"myKey\", value: \"actualValue\""); + } + + @Test + void worksWithStringMatcher() { + //TODO + } + + @Test + void failsWithStringMatcher() { + //TODO + } + + @Test + void worksWithObjectMatcher() { + //TODO + } + + @Test + void failsWithObjectMatcher() { + //TODO + } + + @Test + void objectEqualityFailsWithAssertNotLogged() { + //TODO + } + + @Test + void stringMatchFailsWithAssertNotLogged() { + //TODO + } + + @Test + void objectMatchFailsWithAssertNotLogged() { + //TODO + } +} From 28d4c08a6ede481edc29cde6ea5cb8712193f735 Mon Sep 17 00:00:00 2001 From: Daniel Flassak Date: Fri, 18 Mar 2022 18:10:15 +0100 Subject: [PATCH 3/8] extract ExpectedKeyValueLogstashDelegate --- pom.xml | 40 ++++++++++++------- .../logcapture/ExpectedKeyValue.java | 37 +++++++---------- .../ExpectedKeyValueLogstashDelegate.java | 36 +++++++++++++++++ .../logcapture/ExpectedKeyValueUnitTest.java | 16 ++++++++ .../logcapture/LogCaptureArchTest.java | 19 +++++++++ 5 files changed, 111 insertions(+), 37 deletions(-) create mode 100644 src/main/java/de/dm/infrastructure/logcapture/ExpectedKeyValueLogstashDelegate.java create mode 100644 src/test/java/de/dm/infrastructure/logcapture/ExpectedKeyValueUnitTest.java create mode 100644 src/test/java/de/dm/infrastructure/logcapture/LogCaptureArchTest.java diff --git a/pom.xml b/pom.xml index c7bfc46..2a0f5f5 100644 --- a/pom.xml +++ b/pom.xml @@ -33,12 +33,13 @@ 1.8 1.18.22 - 1.2.10 + 1.2.11 7.0.1 5.8.2 UTF-8 - 3.22.1 + 0.23.1 + 3.22.0 8.45.1 0.8.7 2.22.2 @@ -48,27 +49,16 @@ 3.9.0 2.5.3 3.0.1 + 4.4.0 1.6.8 - - org.projectlombok - lombok - ${lombok.version} - provided - ch.qos.logback logback-classic ${logback.version} - - net.logstash.logback - logstash-logback-encoder - ${logstash-logback-encoder.version} - provided - org.junit.jupiter junit-jupiter-api @@ -79,12 +69,34 @@ junit-jupiter-engine ${junit.version} + + + + org.projectlombok + lombok + ${lombok.version} + provided + + + net.logstash.logback + logstash-logback-encoder + ${logstash-logback-encoder.version} + provided + + + org.assertj assertj-core ${assertj-core.version} test + + com.tngtech.archunit + archunit-junit5 + ${archunit.version} + test + diff --git a/src/main/java/de/dm/infrastructure/logcapture/ExpectedKeyValue.java b/src/main/java/de/dm/infrastructure/logcapture/ExpectedKeyValue.java index fedf972..fca61e1 100644 --- a/src/main/java/de/dm/infrastructure/logcapture/ExpectedKeyValue.java +++ b/src/main/java/de/dm/infrastructure/logcapture/ExpectedKeyValue.java @@ -2,41 +2,23 @@ import lombok.AccessLevel; import lombok.RequiredArgsConstructor; -import net.logstash.logback.marker.SingleFieldAppendingMarker; - -import java.util.Arrays; -import java.util.stream.Collectors; -import java.util.stream.Stream; - -import static java.lang.String.format; -import static java.lang.System.lineSeparator; @RequiredArgsConstructor(access = AccessLevel.PRIVATE) public class ExpectedKeyValue implements LogEventMatcher { + static final String LOGSTASH_MARKER_CLASS = "net.logstash.logback.marker.SingleFieldAppendingMarker"; private final String expectedKey; private final Object expectedValue; - // TODO: extract everything referencing net.logstash into a delegate that is only called if that is present in the classpath - // otherwise, fail with an error message describing that keyValue can only be asserted with logstash in the classpath - @Override public boolean matches(LoggedEvent loggedEvent) { - return Arrays.stream(loggedEvent.getArgumentArray()) - .flatMap(argument -> argument instanceof SingleFieldAppendingMarker ? Stream.of((SingleFieldAppendingMarker) argument) : Stream.empty()) - .anyMatch(marker -> marker.getFieldValue().equals(expectedValue) && marker.getFieldName().equals(expectedKey)); + failIfLogstashIsNotInClasspath(); + return ExpectedKeyValueLogstashDelegate.matches(loggedEvent, expectedKey, expectedValue); } @Override public String getNonMatchingErrorMessage(LoggedEvent loggedEvent) { - String actualKeyValue = Arrays.stream(loggedEvent.getArgumentArray()) - .flatMap(argument -> argument instanceof SingleFieldAppendingMarker ? Stream.of((SingleFieldAppendingMarker) argument) : Stream.empty()) - .map(marker -> format(" key: \"%s\", value: \"%s\"", marker.getFieldName(), marker.getFieldValue())) - .collect(Collectors.joining(lineSeparator())); - - return format(" expected key-value content: key: \"%s\", value: \"%s\"", expectedKey, expectedValue) + - lineSeparator() + - (actualKeyValue.isEmpty() ? " but no key-value content was found" : " actual key-value content:" + lineSeparator() + actualKeyValue); - + failIfLogstashIsNotInClasspath(); + return ExpectedKeyValueLogstashDelegate.getNonMatchingErrorMessage(loggedEvent, expectedKey, expectedValue); } @Override @@ -52,4 +34,13 @@ public String getMatchingErrorMessage() { public static ExpectedKeyValue keyValue(String expectedKey, Object expectedValue) { return new ExpectedKeyValue(expectedKey, expectedValue); } + + private void failIfLogstashIsNotInClasspath() { + try { + Class.forName(LOGSTASH_MARKER_CLASS, false, getClass().getClassLoader()); + } catch (ClassNotFoundException e) { + throw new IllegalArgumentException("keyValue cannot be used for log assertions if " + + "logstash-logback-encoder that provides StructuredArguments.keyValue(...) is not in the classpath."); + } + } } diff --git a/src/main/java/de/dm/infrastructure/logcapture/ExpectedKeyValueLogstashDelegate.java b/src/main/java/de/dm/infrastructure/logcapture/ExpectedKeyValueLogstashDelegate.java new file mode 100644 index 0000000..c99457a --- /dev/null +++ b/src/main/java/de/dm/infrastructure/logcapture/ExpectedKeyValueLogstashDelegate.java @@ -0,0 +1,36 @@ +package de.dm.infrastructure.logcapture; + +import net.logstash.logback.marker.SingleFieldAppendingMarker; + +import java.util.Arrays; +import java.util.stream.Collectors; +import java.util.stream.Stream; + +import static java.lang.String.format; +import static java.lang.System.lineSeparator; + +// this is a delegate accessing net.logstash so that ExpectedKeyValue can fail gracefully +// if logstash is not in the classpath +final class ExpectedKeyValueLogstashDelegate { + private ExpectedKeyValueLogstashDelegate() { + } + + static boolean matches(LoggedEvent loggedEvent, String expectedKey, Object expectedValue) { + return Arrays.stream(loggedEvent.getArgumentArray()) + .flatMap(argument -> argument instanceof SingleFieldAppendingMarker ? Stream.of((SingleFieldAppendingMarker) argument) : Stream.empty()) + .anyMatch(marker -> marker.getFieldValue().equals(expectedValue) && marker.getFieldName().equals(expectedKey)); + } + + static String getNonMatchingErrorMessage(LoggedEvent loggedEvent, String expectedKey, Object expectedValue) { + String actualKeyValue = Arrays.stream(loggedEvent.getArgumentArray()) + .flatMap(argument -> argument instanceof SingleFieldAppendingMarker ? Stream.of((SingleFieldAppendingMarker) argument) : Stream.empty()) + .map(marker -> format(" key: \"%s\", value: \"%s\"", marker.getFieldName(), marker.getFieldValue())) + .collect(Collectors.joining(lineSeparator())); + + return format(" expected key-value content: key: \"%s\", value: \"%s\"", expectedKey, expectedValue) + + lineSeparator() + + (actualKeyValue.isEmpty() ? " but no key-value content was found" : " actual key-value content:" + lineSeparator() + actualKeyValue); + + } + +} diff --git a/src/test/java/de/dm/infrastructure/logcapture/ExpectedKeyValueUnitTest.java b/src/test/java/de/dm/infrastructure/logcapture/ExpectedKeyValueUnitTest.java new file mode 100644 index 0000000..236b9f3 --- /dev/null +++ b/src/test/java/de/dm/infrastructure/logcapture/ExpectedKeyValueUnitTest.java @@ -0,0 +1,16 @@ +package de.dm.infrastructure.logcapture; + +import net.logstash.logback.marker.SingleFieldAppendingMarker; +import org.junit.jupiter.api.Test; + +import static org.assertj.core.api.Assertions.assertThat; + +class ExpectedKeyValueUnitTest { + @Test + @SuppressWarnings("squid:S3415") + // assertion arguments are in the right order, despite Sonar thinking otherwise + void logstashMarkerClassCanonicalNameIsCorrect() { + assertThat(ExpectedKeyValue.LOGSTASH_MARKER_CLASS).isEqualTo(SingleFieldAppendingMarker.class.getCanonicalName()); + } + +} diff --git a/src/test/java/de/dm/infrastructure/logcapture/LogCaptureArchTest.java b/src/test/java/de/dm/infrastructure/logcapture/LogCaptureArchTest.java new file mode 100644 index 0000000..ddfabe4 --- /dev/null +++ b/src/test/java/de/dm/infrastructure/logcapture/LogCaptureArchTest.java @@ -0,0 +1,19 @@ +package de.dm.infrastructure.logcapture; + +import com.tngtech.archunit.core.importer.ImportOption.DoNotIncludeTests; +import com.tngtech.archunit.junit.AnalyzeClasses; +import com.tngtech.archunit.junit.ArchTest; +import com.tngtech.archunit.lang.ArchRule; + +import static com.tngtech.archunit.lang.syntax.ArchRuleDefinition.classes; + +@AnalyzeClasses(packagesOf = LogCapture.class, importOptions = DoNotIncludeTests.class) +public class LogCaptureArchTest { + @ArchTest + static ArchRule logstashIsOnlyUsedInDelegate = classes() + .that() + .doNotHaveFullyQualifiedName(ExpectedKeyValueLogstashDelegate.class.getCanonicalName()) + .should() + .onlyDependOnClassesThat() + .resideOutsideOfPackage("net.logstash.logback.."); +} From 3a6a7b5d36bd800717f0f67af64a0323f121c794 Mon Sep 17 00:00:00 2001 From: Daniel Flassak Date: Fri, 1 Apr 2022 16:24:41 +0200 Subject: [PATCH 4/8] add a test project without logstash dependency to verify that works correctly --- .github/workflows/build.yml | 5 +- project-without-logstash/.gitignore | 9 ++ project-without-logstash/pom.xml | 87 +++++++++++++++++++ .../test/java/com/acme/LogCaptureTest.java | 34 ++++++++ 4 files changed, 134 insertions(+), 1 deletion(-) create mode 100644 project-without-logstash/.gitignore create mode 100644 project-without-logstash/pom.xml create mode 100644 project-without-logstash/src/test/java/com/acme/LogCaptureTest.java diff --git a/.github/workflows/build.yml b/.github/workflows/build.yml index 9f5843e..0b914a4 100644 --- a/.github/workflows/build.yml +++ b/.github/workflows/build.yml @@ -7,4 +7,7 @@ jobs: build: uses: ./.github/workflows/run-with-maven.yml with: - COMMAND: mvn --batch-mode -Dmaven.compiler.showDeprecation=true -Dmaven.compiler.showWarnings=true clean verify + COMMAND: > + mvn --batch-mode -Dmaven.compiler.showDeprecation=true -Dmaven.compiler.showWarnings=true -Dproject.version=0.0.0-SNAPSHOT clean install + && cd project-without-logstash + && mvn --batch-mode -Dlog-capture.version=0.0.0-SNAPSHOT clean verify diff --git a/project-without-logstash/.gitignore b/project-without-logstash/.gitignore new file mode 100644 index 0000000..84d100c --- /dev/null +++ b/project-without-logstash/.gitignore @@ -0,0 +1,9 @@ +/target/ + +### NetBeans ### +/nbproject/private/ +/build/ +/nbbuild/ +/dist/ +/nbdist/ +/.nb-gradle/ diff --git a/project-without-logstash/pom.xml b/project-without-logstash/pom.xml new file mode 100644 index 0000000..4813890 --- /dev/null +++ b/project-without-logstash/pom.xml @@ -0,0 +1,87 @@ + + + 4.0.0 + + de.acme + test-project-without-logstash + 0.0.1-SNAPSHOT + + + + MIT + https://opensource.org/licenses/MIT + repo + + + + + 1.8 + UTF-8 + 3.4.1-SNAPSHOT + + 1.18.22 + 1.2.11 + 5.8.2 + 3.22.0 + + 2.22.2 + 3.9.0 + + + + + org.projectlombok + lombok + ${lombok.version} + provided + + + + + org.junit.jupiter + junit-jupiter-api + ${junit.version} + test + + + org.junit.jupiter + junit-jupiter-engine + ${junit.version} + test + + + de.dm.infrastructure + log-capture + ${log-capture.version} + + + org.assertj + assertj-core + ${assertj-core.version} + test + + + + + + + org.apache.maven.plugins + maven-compiler-plugin + ${maven-compiler-plugin.version} + + ${java.version} + ${java.version} + ${encoding} + true + true + + + + org.apache.maven.plugins + maven-surefire-plugin + ${maven-surefire-plugin.version} + + + + diff --git a/project-without-logstash/src/test/java/com/acme/LogCaptureTest.java b/project-without-logstash/src/test/java/com/acme/LogCaptureTest.java new file mode 100644 index 0000000..3416887 --- /dev/null +++ b/project-without-logstash/src/test/java/com/acme/LogCaptureTest.java @@ -0,0 +1,34 @@ +package com.acme; + +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.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 +public class LogCaptureTest { + @RegisterExtension + LogCapture logCapture = LogCapture.forCurrentPackage(); + + @Test + void assertionWorksDespiteLogstashNotBeingInTheClasspath() { + log.info("hello"); + logCapture.assertLogged(info("hello")); + } + + @Test + void errorMessageForKeyValueAssertion() { + log.info("hello"); + + IllegalArgumentException thrown = assertThrows(IllegalArgumentException.class, () -> + logCapture.assertLogged(info("hello", keyValue("key", "value")))); + + assertThat(thrown).hasMessage("keyValue cannot be used for log assertions if logstash-logback-encoder " + + "that provides StructuredArguments.keyValue(...) is not in the classpath."); + } +} From be1c3eccfd6afbcd6c17c98c854c8a74bb5a2951 Mon Sep 17 00:00:00 2001 From: Daniel Flassak Date: Fri, 1 Apr 2022 16:26:47 +0200 Subject: [PATCH 5/8] make LogEventMatcher more clear, re-formulate messages, draw a clear distinction between the description of wanted and unwanted log messages --- .../logcapture/ExpectedException.java | 6 ++--- .../logcapture/ExpectedLoggerName.java | 6 ++--- .../logcapture/ExpectedMarker.java | 6 ++--- .../logcapture/ExpectedMdcEntry.java | 7 +++--- .../logcapture/LogAsserter.java | 17 +++++++------- .../logcapture/LogEventMatcher.java | 6 ++--- .../java/com/example/app/ReadableApiTest.java | 23 +++++++++++-------- 7 files changed, 37 insertions(+), 34 deletions(-) diff --git a/src/main/java/de/dm/infrastructure/logcapture/ExpectedException.java b/src/main/java/de/dm/infrastructure/logcapture/ExpectedException.java index 8ab23dc..03f1f69 100644 --- a/src/main/java/de/dm/infrastructure/logcapture/ExpectedException.java +++ b/src/main/java/de/dm/infrastructure/logcapture/ExpectedException.java @@ -51,8 +51,8 @@ public String getNonMatchingErrorMessage(LoggedEvent loggedEvent) { } @Override - public String getMatchingErrorMessage() { - return format("not expected exception was found: %s", this); + public String getMatcherDetailDescription() { + return format("Exception: %s", this); } private static String loggedExceptionToString(Optional optionalException) { @@ -70,7 +70,7 @@ private static String loggedExceptionToString(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", getLevelAndRegexExpectation(level, regex, logEventMatchers))); + throw new AssertionError(format("Expected log message has not occurred: %s", getDescriptionForExpectedMessage(level, regex))); } void assertNotCaptured(Optional level, Optional regex, List logEventMatchers) { @@ -189,7 +189,7 @@ void assertNotCaptured(Optional level, Optional regex, List level, Optional regex) { + private static String getDescriptionForExpectedMessage(Optional level, Optional regex) { if (!level.isPresent() && !regex.isPresent()) { return ""; @@ -241,10 +241,11 @@ private static String getLevelAndRegexExpectation(Optional level, Optiona (regex.map(s -> "Regex: \"" + s + "\"").orElse("")); } - private static String getLevelAndRegexExpectation(Optional level, Optional regex, List matchers) { + private static String getDescriptionForUnwantedLogMessage(Optional level, Optional regex, List matchers) { String matchersText = ""; if (!matchers.isEmpty()) { - matchersText = ", with matchers: " + matchers.stream().map(LogEventMatcher::getMatchingErrorMessage).collect(Collectors.joining(", ")); + matchersText = ", with matchers:" + lineSeparator() + " " + matchers.stream().map(LogEventMatcher::getMatcherDetailDescription) + .collect(Collectors.joining(lineSeparator() + " ")); } if (!level.isPresent() && !regex.isPresent()) { return "" + matchersText; diff --git a/src/main/java/de/dm/infrastructure/logcapture/LogEventMatcher.java b/src/main/java/de/dm/infrastructure/logcapture/LogEventMatcher.java index fb17635..8e842f8 100644 --- a/src/main/java/de/dm/infrastructure/logcapture/LogEventMatcher.java +++ b/src/main/java/de/dm/infrastructure/logcapture/LogEventMatcher.java @@ -27,14 +27,14 @@ public interface LogEventMatcher { * * @return matched aspect */ - String getMatcherDescription(); + String getMatcherTypeDescription(); /** - * returns an error message describing why a logged event does match, even of it shouldn't. + * returns an error message describing the concrete matcher, including as much of its expectations as possible * * @return matched aspect */ - String getMatchingErrorMessage(); + String getMatcherDetailDescription(); } diff --git a/src/test/java/com/example/app/ReadableApiTest.java b/src/test/java/com/example/app/ReadableApiTest.java index 4bba76b..ea52e63 100644 --- a/src/test/java/com/example/app/ReadableApiTest.java +++ b/src/test/java/com/example/app/ReadableApiTest.java @@ -179,16 +179,16 @@ void assertNotLoggedFails() { log.info("testlogmessage"); final AssertionError exceptionAny = assertThrows(AssertionError.class, () -> logCapture.assertNotLogged(any())); - assertThat(exceptionAny).hasMessage("Expected log message should not occur: "); + assertThat(exceptionAny).hasMessage("Found a log message that should not be logged: "); final AssertionError exceptionWithLevel = assertThrows(AssertionError.class, () -> logCapture.assertNotLogged(info())); - assertThat(exceptionWithLevel).hasMessage("Expected log message should not occur: Level: 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("Expected log message should not occur: Regex: \"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("Expected log message should not occur: Level: INFO, Regex: \"testlogmessage\""); + assertThat(exceptionWithRegexAndLevel).hasMessage("Found a log message that should not be logged: Level: INFO, Regex: \"testlogmessage\""); } } @@ -277,7 +277,8 @@ void markerWithAssertNotLogged() { final AssertionError assertionError = assertThrows(AssertionError.class, () -> logCapture.assertNotLogged( info("hello with marker", marker("expected")))); - assertThat(assertionError).hasMessage("Expected log message should not occur: Level: INFO, Regex: \"hello with marker\", with matchers: not expected marker name: \"expected\" was found"); + assertThat(assertionError).hasMessage("Found a log message that should not be logged: Level: INFO, Regex: \"hello with marker\", with matchers:" + + lineSeparator() + " marker name: \"expected\""); } } @@ -339,7 +340,8 @@ void loggerWithAssertNotLogged() { info("hello on this logger", logger("ReadableApiTest$")))); assertThat(assertionError) - .hasMessage("Expected log message should not occur: Level: INFO, Regex: \"hello on this logger\", with matchers: not expected logger name (regex) was found: \"ReadableApiTest$\""); + .hasMessage("Found a log message that should not be logged: Level: INFO, Regex: \"hello on this logger\", with matchers:" + + lineSeparator() + " logger name (regex): \"ReadableApiTest$\""); } } @@ -516,12 +518,13 @@ void notLoggedWithMdc() { logCapture.assertNotLogged(info("helloWorld", mdc("thirdKey", "value"))); final AssertionError oneKeyMatches = assertThrows(AssertionError.class, () -> logCapture.assertNotLogged(info("hello world", mdc("key", "value")))); - assertThat(oneKeyMatches).hasMessage("Expected log message should not occur: Level: INFO, Regex: \"hello world\", with matchers: not expected MDCValue with key was found: \"key\""); + 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("Expected log message should not occur: Level: INFO, Regex: \"hello world\", with matchers: not expected MDCValue with key was found: \"key\", not expected MDCValue with key was found: \"another_key\""); - - + 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\""); } } From 33ef6ef9f31a98953b01d71b2120ec910257a519 Mon Sep 17 00:00:00 2001 From: Daniel Flassak Date: Fri, 1 Apr 2022 16:28:17 +0200 Subject: [PATCH 6/8] finish implementation of ExpectedKeyValue --- .../logcapture/ExpectedKeyValue.java | 47 ++++++++-- .../ExpectedKeyValueLogstashDelegate.java | 6 +- .../com/example/app/LogstashKeyValueTest.java | 87 +++++++++++++++---- 3 files changed, 116 insertions(+), 24 deletions(-) diff --git a/src/main/java/de/dm/infrastructure/logcapture/ExpectedKeyValue.java b/src/main/java/de/dm/infrastructure/logcapture/ExpectedKeyValue.java index fca61e1..7ce60dd 100644 --- a/src/main/java/de/dm/infrastructure/logcapture/ExpectedKeyValue.java +++ b/src/main/java/de/dm/infrastructure/logcapture/ExpectedKeyValue.java @@ -3,11 +3,16 @@ import lombok.AccessLevel; import lombok.RequiredArgsConstructor; +import static java.lang.String.format; + +/** + * define expected StructuredArgument.keyValue(...) from logstash with this matcher + */ @RequiredArgsConstructor(access = AccessLevel.PRIVATE) public class ExpectedKeyValue implements LogEventMatcher { static final String LOGSTASH_MARKER_CLASS = "net.logstash.logback.marker.SingleFieldAppendingMarker"; private final String expectedKey; - private final Object expectedValue; + private final String expectedValue; @Override public boolean matches(LoggedEvent loggedEvent) { @@ -22,19 +27,51 @@ public String getNonMatchingErrorMessage(LoggedEvent loggedEvent) { } @Override - public String getMatcherDescription() { + public String getMatcherTypeDescription() { return "key-value content"; } @Override - public String getMatchingErrorMessage() { - return null; + public String getMatcherDetailDescription() { + return format("keyValue content with key: \"%s\" and value: \"%s\"", expectedKey, expectedValue); } - public static ExpectedKeyValue keyValue(String expectedKey, Object expectedValue) { + /** + * use this in a log expectation to verify that something has been logged with a keyValue argument from logstashg's StructuredArgument + * + * @param expectedKey expected key + * @param expectedValue expected value + * + * @return expected keyValue to use in log expectation + */ + public static ExpectedKeyValue keyValue(String expectedKey, String expectedValue) { return new ExpectedKeyValue(expectedKey, expectedValue); } + /** + * use this in a log expectation to verify that something has been logged with a keyValue argument from logstashg's StructuredArgument + * + * @param expectedKey expected key + * @param expectedValue expected value + * + * @return expected keyValue to use in log expectation + */ + public static ExpectedKeyValue keyValue(String expectedKey, int expectedValue) { + return new ExpectedKeyValue(expectedKey, String.valueOf(expectedValue)); + } + + /** + * use this in a log expectation to verify that something has been logged with a keyValue argument from logstashg's StructuredArgument + * + * @param expectedKey expected key + * @param expectedValue expected value + * + * @return expected keyValue to use in log expectation + */ + public static ExpectedKeyValue keyValue(String expectedKey, long expectedValue) { + return new ExpectedKeyValue(expectedKey, String.valueOf(expectedValue)); + } + private void failIfLogstashIsNotInClasspath() { try { Class.forName(LOGSTASH_MARKER_CLASS, false, getClass().getClassLoader()); diff --git a/src/main/java/de/dm/infrastructure/logcapture/ExpectedKeyValueLogstashDelegate.java b/src/main/java/de/dm/infrastructure/logcapture/ExpectedKeyValueLogstashDelegate.java index c99457a..fb39f26 100644 --- a/src/main/java/de/dm/infrastructure/logcapture/ExpectedKeyValueLogstashDelegate.java +++ b/src/main/java/de/dm/infrastructure/logcapture/ExpectedKeyValueLogstashDelegate.java @@ -15,13 +15,13 @@ final class ExpectedKeyValueLogstashDelegate { private ExpectedKeyValueLogstashDelegate() { } - static boolean matches(LoggedEvent loggedEvent, String expectedKey, Object expectedValue) { + static boolean matches(LoggedEvent loggedEvent, String expectedKey, String expectedValue) { return Arrays.stream(loggedEvent.getArgumentArray()) .flatMap(argument -> argument instanceof SingleFieldAppendingMarker ? Stream.of((SingleFieldAppendingMarker) argument) : Stream.empty()) - .anyMatch(marker -> marker.getFieldValue().equals(expectedValue) && marker.getFieldName().equals(expectedKey)); + .anyMatch(marker -> expectedValue.equals(marker.getFieldValue()) && marker.getFieldName().equals(expectedKey)); } - static String getNonMatchingErrorMessage(LoggedEvent loggedEvent, String expectedKey, Object expectedValue) { + static String getNonMatchingErrorMessage(LoggedEvent loggedEvent, String expectedKey, String expectedValue) { String actualKeyValue = Arrays.stream(loggedEvent.getArgumentArray()) .flatMap(argument -> argument instanceof SingleFieldAppendingMarker ? Stream.of((SingleFieldAppendingMarker) argument) : Stream.empty()) .map(marker -> format(" key: \"%s\", value: \"%s\"", marker.getFieldName(), marker.getFieldValue())) diff --git a/src/test/java/com/example/app/LogstashKeyValueTest.java b/src/test/java/com/example/app/LogstashKeyValueTest.java index 119fcaa..d48a480 100644 --- a/src/test/java/com/example/app/LogstashKeyValueTest.java +++ b/src/test/java/com/example/app/LogstashKeyValueTest.java @@ -8,6 +8,7 @@ import static de.dm.infrastructure.logcapture.ExpectedKeyValue.keyValue; import static de.dm.infrastructure.logcapture.LogExpectation.info; +import static java.lang.System.lineSeparator; import static org.assertj.core.api.Assertions.assertThat; import static org.junit.jupiter.api.Assertions.assertThrows; @@ -18,14 +19,14 @@ class LogstashKeyValueTest { LogCapture logCapture = LogCapture.forCurrentPackage(); @Test - void worksWithObjectEquality() { + void worksWithString() { log.info("hello", StructuredArguments.keyValue("myKey", "myValue")); logCapture.assertLogged(info("hello", keyValue("myKey", "myValue"))); } @Test - void failsWithObjectEquality() { + void failsWithString() { log.info("hello", StructuredArguments.keyValue("myKey", "actualValue")); AssertionError assertionError = assertThrows(AssertionError.class, () -> @@ -39,37 +40,91 @@ void failsWithObjectEquality() { } @Test - void worksWithStringMatcher() { - //TODO + void worksWithInteger() { + log.info("hello", StructuredArguments.keyValue("myKey", 100000)); + + logCapture.assertLogged(info("hello", keyValue("myKey", 100000))); } @Test - void failsWithStringMatcher() { - //TODO + void failsWithInteger() { + log.info("hello", StructuredArguments.keyValue("myKey", 100001)); + + AssertionError assertionError = assertThrows(AssertionError.class, () -> + logCapture.assertLogged(info("hello", keyValue("myKey", 100000)))); + + assertThat(assertionError).hasMessageFindingMatch( + "Expected log message has occurred, but never with the expected key-value content: Level: INFO, Regex: \"hello\"" + ".*" + + " expected key-value content: key: \"myKey\", value: \"100000\"" + ".*" + + " actual key-value content:" + ".*" + + " key: \"myKey\", value: \"100001\""); } @Test - void worksWithObjectMatcher() { - //TODO + void failsWithIntegerThatIsNoInteger() { + log.info("hello", StructuredArguments.keyValue("myKey", "not an int")); + + AssertionError assertionError = assertThrows(AssertionError.class, () -> + logCapture.assertLogged(info("hello", keyValue("myKey", 100000)))); + + assertThat(assertionError).hasMessageFindingMatch( + "Expected log message has occurred, but never with the expected key-value content: Level: INFO, Regex: \"hello\"" + ".*" + + " expected key-value content: key: \"myKey\", value: \"100000\"" + ".*" + + " actual key-value content:" + ".*" + + " key: \"myKey\", value: \"not an int\""); } + @Test - void failsWithObjectMatcher() { - //TODO + void worksWithLong() { + log.info("hello", StructuredArguments.keyValue("myKey", 1000000000000L)); + + logCapture.assertLogged(info("hello", keyValue("myKey", 1000000000000L))); } @Test - void objectEqualityFailsWithAssertNotLogged() { - //TODO + void failsWithLong() { + log.info("hello", StructuredArguments.keyValue("myKey", 1000000000001L)); + + AssertionError assertionError = assertThrows(AssertionError.class, () -> + logCapture.assertLogged(info("hello", keyValue("myKey", 1000000000000L)))); + + assertThat(assertionError).hasMessageFindingMatch( + "Expected log message has occurred, but never with the expected key-value content: Level: INFO, Regex: \"hello\"" + ".*" + + " expected key-value content: key: \"myKey\", value: \"1000000000000\"" + ".*" + + " actual key-value content:" + ".*" + + " key: \"myKey\", value: \"1000000000001\""); + } + + @Test + void failsWithLongThatIsNoLong() { + log.info("hello", StructuredArguments.keyValue("myKey", "not a long")); + + AssertionError assertionError = assertThrows(AssertionError.class, () -> + logCapture.assertLogged(info("hello", keyValue("myKey", 1000000000000L)))); + + assertThat(assertionError).hasMessageFindingMatch( + "Expected log message has occurred, but never with the expected key-value content: Level: INFO, Regex: \"hello\"" + ".*" + + " expected key-value content: key: \"myKey\", value: \"1000000000000\"" + ".*" + + " actual key-value content:" + ".*" + + " key: \"myKey\", value: \"not a long\""); } @Test - void stringMatchFailsWithAssertNotLogged() { - //TODO + void assertNotLoggedSucceeds() { + log.info("info", StructuredArguments.keyValue("key", "actualValue")); + + logCapture.assertNotLogged(info("info", keyValue("key", "forbiddenValue"))); } @Test - void objectMatchFailsWithAssertNotLogged() { - //TODO + void assertNotLoggedFailsWithProperMessage() { + log.info("info", StructuredArguments.keyValue("key", "forbiddenValue")); + + AssertionError actual = assertThrows(AssertionError.class, () -> + logCapture.assertNotLogged(info("info", keyValue("key", "forbiddenValue")))); + + assertThat(actual).hasMessage("Found a log message that should not be logged: Level: INFO, Regex: \"info\", with matchers:" + + lineSeparator() + " keyValue content with key: \"key\" and value: \"forbiddenValue\""); } } From 9743ce3918005b3dc7a0115e70bef986eab4e3ba Mon Sep 17 00:00:00 2001 From: Daniel Flassak Date: Mon, 4 Apr 2022 12:16:37 +0200 Subject: [PATCH 7/8] update readme --- README.md | 26 ++++++++++++++++++++++++++ 1 file changed, 26 insertions(+) diff --git a/README.md b/README.md index a6b6314..d66f95f 100644 --- a/README.md +++ b/README.md @@ -139,6 +139,26 @@ log.info("did something"); logCapture.info("did something", logger("com.acme.foo")); ``` +#### Key-Value (from Logstash) + +**Note that** this will only work if logstash-logback-encoder is in your classpath - log-capture does not depend on it, so you need to add it manually if you intend to use it. + +```java +import static de.dm.infrastructure.logcapture.ExpectedKeyValue.keyValue; + +... + +log.info("hello", + StructuredArguments.keyValue("myString", "hello"), + StructuredArguments.keyValue("myNumber", 42) +); + +logCapture.assertLogged(info("hello", + keyValue("myString", "hello"), + keyValue("myNumber", 42)) +); +``` + ### Examples #### Unit Test Example: @@ -306,6 +326,12 @@ And with MDC logging context ## Changes +### 3.5.0 + +* Added new Log Event Matcher: `ExpectedKeyValue.keyValue(...)` to assert `StructuredArguments.keyValue(...)` from Logstash +* Improved readability for assertion errors when using `assertNotLogged(...)` +* Updated dependencies + ### 3.4.1 * Improved Javadoc for deprecated methods From 2e2daa7336ab78cc72cf80131f4257075d9bf14f Mon Sep 17 00:00:00 2001 From: Daniel Flassak Date: Mon, 4 Apr 2022 12:17:23 +0200 Subject: [PATCH 8/8] update version in POM --- pom.xml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/pom.xml b/pom.xml index 2a0f5f5..8dabf98 100644 --- a/pom.xml +++ b/pom.xml @@ -29,7 +29,7 @@ - 3.4.1-SNAPSHOT + 3.5.0-SNAPSHOT 1.8 1.18.22