diff --git a/.gitignore b/.gitignore new file mode 100644 index 0000000..82eca33 --- /dev/null +++ b/.gitignore @@ -0,0 +1,25 @@ +/target/ +!.mvn/wrapper/maven-wrapper.jar + +### STS ### +.apt_generated +.classpath +.factorypath +.project +.settings +.springBeans +.sts4-cache + +### IntelliJ IDEA ### +.idea +*.iws +*.iml +*.ipr + +### NetBeans ### +/nbproject/private/ +/build/ +/nbbuild/ +/dist/ +/nbdist/ +/.nb-gradle/ \ No newline at end of file diff --git a/.travis.yml b/.travis.yml new file mode 100644 index 0000000..fc15864 --- /dev/null +++ b/.travis.yml @@ -0,0 +1,19 @@ +language: java +env: + global: + # OSSRH_JIRA_USERNAME + - secure: TPbdHAtQGq73vosBm57yROH+uNIJawNQxPmznne+Djq9NMo+q/iWx2l0Yj9VxJqhVlW4UTzRdqXyzY+kgsECAF1XSICDRvkkzIViBVwoIzz0k9DdwM2Ues5FPNz93cH+Tb1zFM6/+irSa5DzGh9abgVgFC3AW01oJ18CzIWytW+M+lHOfWsuqvlg17ttW0SUX9na2cirk0NPOQTQmkGLxUFwWL56J0tymPSc6+Brg7X3wzGqpvE8wIKm+Wt4deimCfQomWUuyfpi6gnwgPktRgcZE9OWZttPYuKMgfuFOwk5UfkVigorpvWnBQtKCvISJc9wmgiH66xBgH2dzfoFwwk6JTQUhNNqIP5L2AJmjyWEHRY93Pu9L7MKBVSzBjQ5kGhJbF6cDUW2HjSDJkGCQrqFYC4IpWPOhO6HLuFjqqejRuR0rNTp76+KU2L+2ThOF7YQoKazgj1KdQJnQGMKBapYgDq0TOpp3MlFwkJbKhkV7oo9DQmo5hL+V5MvH+u/pEpk9+xCNzxnaOJCBZVIwx7hbhjrK6mnSc2jsq2bnAjDXhgKD01l8JGhzn8LfJ56ay/4EKC5jGp4D20rshm3omscMH/dDyJjRsn7mCtHiVmnz6dC/EByIGcUB5gNjN3exYS5PUDoI7Na/UHuaDX4CFDtCBJatQKuh4g6AbRYzoU= + # OSSRH_JIRA_PASSWORD + - secure: rKnHA4ozbQD8M/mpkKOrzwp6QiDazorI0NxvaedsZel52HGpIURUlJjgErUOzW5b55cAbZrgEYwdBgtprXR4wO9W/K8H6qjEiGbR35HMrn2DTWkSeqwEewB6U2XhxlxBOeBTmLSFLQiVnj06SC0+G12AHdlCECpJoAipEqJ1d8FvHh1Pq9CFbNvPLetl05i/UIZQ10KBfx1y8aznajjkjWhWM7IS636Dj0LJyDKWXFOoAhYtntn6BKo2lPUG1j5f4c/p0ietXIlTkLR+FVVpU7/1KD9GWWWHbu9S4bqT9yQdw5BHUVjxjagWNk9NgspCuDP4Sf1RBCzyVEcavuGQW7isUBi7zMzOGyHzvoyDFGe4uAqtX+EBZaEg4HgrLDPx9GS2FfI6wLThDNf0e7vkniYUhI7hHeYQ0MxMbU+2t38ghBkw5KrCu16PmB+McJzCgoFpk/GquweDUp2XTPu0dQagWB2V15bu9uxrjO4A6h3pWZstjwPjG+825YZX7XjJ5p7v3UkZQNOuZeDVcssGzJSV0L535kUski6xpKd4oi+HXymBCFb3P4vCEViieJKdWHOhgT4n/lKW2sYIP/WOqlC/F/cJ0VOrJ1cApaoEkss/IHADh9DxlAx/7eX15ECNwPEoSwGyjO81ypo+6/aWC9UqJ0jjdoVMmEej7WzZdYA= + # GPG_KEY_NAME + - secure: ZZpaJVSGWZ4fsqSFlBv/UpRkNBBQv098yLtSBdYz2lCuv3sQtCvxBMG11Yj3cU+bHBpAg+Su6qxHD6yurlrqVanWqHRNRJVxw7/9mFRh5oSACyRwy66d8u1n+grosjxSJNQqHFeFAzhHkXTBULd5tGLhpZrmSd3fYN3MJtBSr9qgLjbKgZKymsqMy+syuoL/ZmjcTEIKZ5t/tYsT9DdAHxhGfr8bYsfEJUpi5ZmYtm/5JsY06pZZNyRkjKtswB8FjcRkn4k75qilSVU4wbwHwCeBvZ0QqkF0h3DIiW7dOEYbSO6Zn2vZbOl6SiAFbV95qSHp7V+gyQCZelwBcUeg4fU5CmVa2R9dyyWYVX/f40xs14vYx1O2nJCfh71dsCw0dCv1lIJeGlLdQ90CW/C22Ioh3C47VAvov5J4T6F28Zb13lTZOxwvzSDRYpXDEF1su9jHZTGrqXCwtczPEY1h6d/DReb5l82MiMkL0Li0uLAHOKYYXNl+9W5d3aQSOOB6kWNB1pxo8veUGz0fii+gBtWff1CIhh8X2/Eii694bwFArFVnPWm5bQJzomOgEbjc5YMki9eUaYmwx2+Y96amzpcmju573LxRqqlWT4GPMxNvmwxGH9pxMu2i0PT36wBg66h+TKdOEcdBEiAn2usrVCoCv7MCKqt2FSDc8t83tos= + # GPG_KEY_PASSPHRASE + - secure: TtYwboYkbGyeYWDF5+HiBg0N/vFdD/7fHMXGi8Q95S8NrlL7IcB2jqqWLKOvbxTPBC2+FsQwfURctu891c3D/NuI2TR4BWnWCPprdlaCpK4x1gOLZiOGHXlf4pGRzp7X5NmNCqCt9W+Z4SUchXVpudAmKbJSvLhU5UFHBG4IY3VtYPu7lip858oYkRm/Iq8EeTFGs2nJ1002CoVq3DvTNNjIm0Y8JFPpFBF4Y06ivr2B0aVhfDsMtqCfFPe/6eVlE2w2CgS7cQjAKtpZPBNOAdRwS4soAEWbiAZw0JI5PfhAoVLhxaC4IX6aaMHfRnyWYsnSCu8R6i6TccN/MKW+QM3a8ajtdJeEMZcrHAcJOo7ktwFvu/O25YuaENB6ZdR/SV+vmB6MlHkzPuhR6oxtmH5WgwqXknWYBglfiI6tnsoOfwxTxJ4A5M320+7DINDt5dLKCsaElFSe+nhi4IKBzV3ARFFimpdTqGfO0y2X6uqYwVbfi0VgCjFx402blb/ZSTDHoNfBrB8p7iWrqqQZKz/mr9Vhl5nuMdqqJW447AhjVFjjvV9U3jBHfxCoBdXzywCn4lsaIomc+kjaMtCbAGd4+a6gsY3TEsguaVM48neA/w3oTDnT7FGy0NCzYDkJI3tfdnD+KCKQQPTmzn1PT/vNVpIR90OULvptaJ2FXeA= +jdk: openjdk11 +install: mvn install -P !build-extras -DskipTests=true -Dmaven.javadoc.skip=true -B + -V +script: mvn verify -P !build-extras -B +cache: + directories: + - "~/.m2/repository" +after_success: ".travis/deploy_to_maven_central.sh" diff --git a/.travis/codesigning.asc.enc b/.travis/codesigning.asc.enc new file mode 100644 index 0000000..5f43932 Binary files /dev/null and b/.travis/codesigning.asc.enc differ diff --git a/.travis/deploy_to_maven_central.sh b/.travis/deploy_to_maven_central.sh new file mode 100755 index 0000000..6d460af --- /dev/null +++ b/.travis/deploy_to_maven_central.sh @@ -0,0 +1,15 @@ +#!/usr/bin/env bash +if [ "$TRAVIS_BRANCH" = 'master' ] && [ "$TRAVIS_PULL_REQUEST" == 'false' ] || [ ! -z "$TRAVIS_TAG" ]; then + openssl aes-256-cbc -K $encrypted_419f3502ba64_key -iv $encrypted_419f3502ba64_iv -in .travis/codesigning.asc.enc -out .travis/codesigning.asc -d + gpg --fast-import .travis/codesigning.asc + + if [ ! -z "$TRAVIS_TAG" ] + then + echo "on a tag -> set pom.xml to $TRAVIS_TAG" + mvn --settings .travis/mvnsettings.xml org.codehaus.mojo:versions-maven-plugin:2.1:set -DnewVersion=$TRAVIS_TAG 1>/dev/null 2>/dev/null + else + echo "not on a tag -> keep snapshot version in pom.xml" + fi + + mvn deploy -P sign,build-extras --settings .travis/mvnsettings.xml -DskipTests=true -B -U +fi diff --git a/.travis/mvnsettings.xml b/.travis/mvnsettings.xml new file mode 100644 index 0000000..eb63c75 --- /dev/null +++ b/.travis/mvnsettings.xml @@ -0,0 +1,28 @@ + + + + + + ossrh + ${env.OSSRH_JIRA_USERNAME} + ${env.OSSRH_JIRA_PASSWORD} + + + + + + ossrh + + true + + + gpg + ${env.GPG_KEY_NAME} + ${env.GPG_PASSPHRASE} + + + + + diff --git a/LICENSE b/LICENSE new file mode 100644 index 0000000..55ef6fd --- /dev/null +++ b/LICENSE @@ -0,0 +1,19 @@ +Copyright (c) 2019 dmTECH GmbH, https://www.dmtech.de + +Permission is hereby granted, free of charge, to any person obtaining a copy +of this software and associated documentation files (the "Software"), to deal +in the Software without restriction, including without limitation the rights +to use, copy, modify, merge, publish, distribute, sublicense, and/or sell +copies of the Software, and to permit persons to whom the Software is +furnished to do so, subject to the following conditions: + +The above copyright notice and this permission notice shall be included in all +copies or substantial portions of the Software. + +THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR +IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, +FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE +AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER +LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, +OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE +SOFTWARE. diff --git a/MAINTAINERS.md b/MAINTAINERS.md new file mode 100644 index 0000000..9236c10 --- /dev/null +++ b/MAINTAINERS.md @@ -0,0 +1,2 @@ +Daniel Flassak (https://github.com/waschmittel) + diff --git a/README.md b/README.md new file mode 100644 index 0000000..2005a72 --- /dev/null +++ b/README.md @@ -0,0 +1,224 @@ +# log-capture + +[](https://dmtech.de/) +[![Build Status](https://travis-ci.org/dm-drogeriemarkt/log-capture.svg?branch=master)](https://travis-ci.org/dm-drogeriemarkt/log-capture) + +Helper for Unit/Integration tests with JUnit 4 to test if something has been logged. + +Because this is a library, Checkstyle is used to make sure all public classes/methods have appropriate Javadoc. + +## Table of Contents + +* [Usage:](#Usage) + * [Examples:](#Examples) + * [Unit Test Example:](#Unit-Test-Example) + * [Integration Test Example:](#Integration-Test-Example) + * [Example with MDC](#Example-with-MDC) +* [Usage with non-JUnit Runner](#Usage-with-non-JUnit-Runner) + * [Cucumber example](#Cucumber-example) + * [Cucumber feature file](#Cucumber-feature-file) + * [Cucumber stepdefs](#Cucumber-stepdefs) + * [Cucumber DTOs](#Cucumber-DTOs) + +## Usage: + +### Examples: + +#### Unit Test Example: + +```java +package my.company.application; + +... + +public class MyUnitTest { + + Logger logger = LoggerFactory.getLogger(MyUnitTest.class); + + // captures logs from any packages, but only if the log event's call stack + // indicates that it has been caused by the test + @Rule + public LogCapture logCapture = LogCapture.forUnitTest(); + + @Test + public void twoLogMessagesInOrder() { + log.info("something interesting"); + log.error("something terrible"); + + logCapture + .assertLogged(Level.INFO, "^something interesting$") //second parameter is a regular expression + .thenLogged(Level.ERROR, "terrible"); + } +} +``` + +#### Integration Test Example: + +```Java +package my.company.application; + +import utility.that.logs.Tool; +import irrelevant.utility.Irrelevant; +... + +public class MyIntegrationTest { + + Logger logger = LoggerFactory.getLogger(MyIntegrationTest.class); + + // captures only logs from my.company and utility.that.logs and sub-packages + @Rule + public LogCapture logCapture = LogCapture.forIntegrationTest("my.company", "utility.that.logs"); + + @Test + public void twoLogMessagesInOrder() { + Irrelevant.doSomething(); + Tool.doSomething(); + + log.info("something interesting"); + log.error("something terrible"); + + logCapture + .assertLogged(Level.INFO, "^something interesting") + .assertLogged(Level.INFO, "^info from utility.that.logs") + .thenLogged(Level.ERROR, "terrible"); + } +} +``` + +#### Example with MDC + +```Java +package my.company.application; + +... + +import static de.dm.prom.logcapture.ExpectedMdcEntry.withMdc; + +... + +public class MyUnitTest { + Logger logger = LoggerFactory.getLogger(MyUnitTest.class); + + @Rule + public LogCapture logCapture = LogCapture.forUnitTest(); + + @Test + public void logMessageWithMdcInformation() { + MDC.put("my_mdc_key", "this is the MDC value"); + MDC.put("other_mdc_key", "this is the other MDC value"); + log.info("this message has some MDC information attached"); + + logCapture + .assertLogged(Level.INFO, "information attached", + withMdc("my_mdc_key", "^this is the MDC value$"), + withMdc("other_mdc_key", "^this is the other MDC value$") + ); + } +} +``` + +If assertLogged fails because the message is correct, but the MDC value is wrong, the assertion error will contain the actual MDC values of the last captured log event where the log message and level matched. + +This can be useful for debugging purposes. For example, this test code: + +```java + MDC.put("my_mdc_key", "this is the wrong MDC value"); + MDC.put("other_mdc_key", "this is the other MDC value"); + log.info("this message has some MDC information attached"); + + logCapture + .assertLogged(Level.INFO, "information attached", + withMdc("my_mdc_key", "^something expected that never occurs$"), + withMdc("other_mdc_key", "^this is the other MDC value$") + ); +``` + +will output: + +```text +java.lang.AssertionError: Expected log message has occurred, but never with the expected MDC value: Level: INFO, Regex: "information attached" + Captured message: "this message has some MDC information attached" + Captured MDC values: + my_mdc_key: "this is the wrong MDC value" + other_mdc_key: "this is the other MDC value" +``` + + +## Usage with non-JUnit Runner + +If you intend to use LogCapture outside of a JUnit test, you cannot rely on JUnit's `@Rule` annotation and must call LocCapture's `addAppender()` and `removeAppender()` methods manually. + +Be aware that this will still cause JUnit to be a dependency. + +### Cucumber example + +Here's an Example that shows how to use LogCapture with Cucumber 4: + +#### Cucumber feature file + +```cucumber +And with MDC logging context + | contextId | contentRegex | + | verkaufsbon_vo | ^MDC_JSON_VALUE:.*2401219817317 | +* the following messages where logged + | level | messageRegex | + | INFO | ^Received bon$ | +``` + +#### Cucumber stepdefs + +You can create these stepdefs in your project to use log-capture in feature files. + +```java +public class LoggingStepdefs { + private ExpectedMdcEntry[] expectedMdcEntries; + + public LogCapture logCapture = LogCapture.forIntegrationTest("my.company.app"); + + @Before + public void setupLogCapture() { + logCapture.addAppender(); + } + + @And("with MDC logging context") + public void withMdcLoggingContext(List logContexts) { + List expectedMdcEntries = new LinkedList<>(); + logContexts.forEach(logContext -> expectedMdcEntries.add(ExpectedMdcEntry.withMdc(logContext.getContextId(), logContext.getContentRegex()))); + this.expectedMdcEntries = expectedMdcEntries.toArray(new ExpectedMdcEntry[0]); + } + + @And("the following messages where logged") + public void followingMessagedLogged(List logEntries) { + LogEntry firstEntry = logEntries.get(0); + logEntries.remove(0); + LogCapture.LastCapturedLogEvent lastCapturedLogEvent = logCapture.assertLogged(Level.toLevel(firstEntry.getLevel()), firstEntry.getMessageRegex(), expectedMdcEntries); + for (LogEntry logEntry : logEntries) { + lastCapturedLogEvent = lastCapturedLogEvent.thenLogged(Level.toLevel(logEntry.getLevel()), logEntry.getMessageRegex(), expectedMdcEntries); + } + } +} +``` + +#### Cucumber DTOs + +You need to register these DTOs with Cucumber's [TypeRegistryConfigurer](https://cucumber.io/docs/cucumber/configuration/#type-registry): + +```java +import lombok.Data; + +@Data +public class LogContext { + private String contextId; + private String contentRegex; +} +``` + +```java +import lombok.Data; + +@Data +public class LogEntry { + private String level; + private String messageRegex; +} +``` diff --git a/checkstyle.xml b/checkstyle.xml new file mode 100644 index 0000000..22df762 --- /dev/null +++ b/checkstyle.xml @@ -0,0 +1,237 @@ + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + diff --git a/pom.xml b/pom.xml new file mode 100644 index 0000000..1b476ae --- /dev/null +++ b/pom.xml @@ -0,0 +1,266 @@ + + + 4.0.0 + + de.dm.infrastructure + log-capture + 1.0.0-SNAPSHOT + + structured-logging + Makes it possible to capture logs and assert if things have been logged + https://github.com/dm-drogeriemarkt/log-capture + + + + MIT + https://opensource.org/licenses/MIT + repo + + + + + + dmTECH GmbH + https://www.dmtech.de + Daniel Flassak + daniel.flassak@dm.de + + + + + 1.8 + 1.18.4 + 1.2.3 + 4.12 + UTF-8 + + 8.22 + 0.8.4 + 2.22.2 + 3.1.0 + 3.1.0 + 3.1.1 + 3.8.1 + 2.5.3 + 1.6 + ${maven-gpg-plugin.version}.8 + + + + + org.projectlombok + lombok + ${lombok.version} + provided + + + ch.qos.logback + logback-classic + ${logback.version} + + + junit + junit + ${junit.version} + + + + + + + org.apache.maven.plugins + maven-compiler-plugin + ${maven-compiler-plugin.version} + + ${java.version} + ${java.version} + ${encoding} + true + true + + + + org.apache.maven.plugins + maven-release-plugin + ${maven-release-plugin.version} + + v@{project.version}-${project.artifactId} + + + + org.sonatype.plugins + nexus-staging-maven-plugin + ${nexus-staging-maven-plugin.version} + true + + ossrh + https://oss.sonatype.org/ + true + + + + org.jacoco + jacoco-maven-plugin + ${jacoco.version} + + + org.apache.maven.plugins + maven-checkstyle-plugin + ${maven-checkstyle-plugin.version} + + checkstyle.xml + UTF-8 + true + true + false + + + + com.puppycrawl.tools + checkstyle + ${checkstyle.version} + + + + + verify + verify + + check + + + + + + org.apache.maven.plugins + maven-surefire-plugin + ${maven-surefire-plugin.version} + + + + + + + build-extras + + true + + + + + org.apache.maven.plugins + maven-source-plugin + ${maven-source-plugin.version} + + + attach-sources + + jar-no-fork + + + + + + org.apache.maven.plugins + maven-javadoc-plugin + ${maven-javadoc-plugin.version} + + ${java.version} + ${encoding} + + + + attach-javadocs + + jar + + + + + + + + + sign + + + + org.apache.maven.plugins + maven-gpg-plugin + ${maven-gpg-plugin.version} + + + sign-artifacts + verify + + sign + + + + + + + + + instrumentation + + + + org.jacoco + jacoco-maven-plugin + + + **/*Config*.class + + + + + default-prepare-agent + + prepare-agent + + + + default-prepare-agent-integration + + prepare-agent-integration + + + + default-report + + report + + + + default-report-integration + + report-integration + + + + + + + + + + + + ossrh + https://oss.sonatype.org/content/repositories/snapshots + + + ossrh + https://oss.sonatype.org/service/local/staging/deploy/maven2 + + + + + scm:git:git://github.com/dm-drogeriemarkt/log-capture.git + scm:git:ssh://git@github.com/dm-drogeriemarkt/log-capture.git + + http://github.com/dm-drogeriemarkt/log-capture/tree/master + + diff --git a/src/main/java/de/dm/infrastructure/logcapture/CapturingAppender.java b/src/main/java/de/dm/infrastructure/logcapture/CapturingAppender.java new file mode 100644 index 0000000..e2769b0 --- /dev/null +++ b/src/main/java/de/dm/infrastructure/logcapture/CapturingAppender.java @@ -0,0 +1,166 @@ +package de.dm.infrastructure.logcapture; + +import ch.qos.logback.classic.Level; +import ch.qos.logback.classic.LoggerContext; +import ch.qos.logback.classic.spi.ILoggingEvent; +import ch.qos.logback.core.Appender; +import ch.qos.logback.core.filter.Filter; +import ch.qos.logback.core.spi.ContextAwareBase; +import ch.qos.logback.core.spi.FilterReply; +import lombok.Getter; +import lombok.Setter; + +import java.util.ArrayList; +import java.util.Arrays; +import java.util.LinkedList; +import java.util.List; +import java.util.Map; +import java.util.Set; +import java.util.regex.Pattern; +import java.util.stream.Collectors; + +@Getter +@Setter +class CapturingAppender extends ContextAwareBase implements Appender { + + List loggedEvents = new ArrayList<>(); + final List capturedPackages; + + private String name; + private boolean started; + private final boolean captureStackTrace; + + CapturingAppender(LoggerContext loggerContext, boolean captureStackTrace, List capturedPackages) { + this.capturedPackages = capturedPackages; + setName("CAPTURE-" + Thread.currentThread().getId()); + setContext(loggerContext); + this.captureStackTrace = captureStackTrace; + } + + @Override + public synchronized void doAppend(ILoggingEvent loggingEvent) { + if (eventIsRelevant(loggingEvent)) { + loggedEvents.add( + new LoggedEvent( + loggingEvent.getLevel(), + loggingEvent.getFormattedMessage(), + captureStackTrace ? getMethodsInCallStack(loggingEvent) : null, + loggingEvent.getMDCPropertyMap() + )); + } + } + + private boolean eventIsRelevant(ILoggingEvent loggingEvent) { + if (capturedPackages.size() == 0) { + return true; + } + for (String packageName : capturedPackages) { + if (loggingEvent.getLoggerName().startsWith(packageName)) { + return true; + } + } + return false; + } + + private static Set getMethodsInCallStack(ILoggingEvent loggingEvent) { + return Arrays.stream(loggingEvent.getCallerData()) + .map(CapturingAppender::toMethodName) + .collect(Collectors.toSet()); + } + + private static String toMethodName(StackTraceElement callerData) { + return String.format("%s.%s", callerData.getClassName(), callerData.getMethodName()); + } + + Integer whenCapturedNext(Level level, String regex, int startIndex, StackTraceElement caller, ExpectedMdcEntry... expectedMdcEntries) { + Pattern pattern = Pattern.compile(".*" + regex + ".*"); + LoggedEvent eventWithWrongMdcContents = null; + for (int i = startIndex; i < loggedEvents.size(); i++) { + LoggedEvent event = loggedEvents.get(i); + if (eventMatchesWithoutMdc(event, level, pattern, caller)) { + if (containsMdcEntries(event.getMdcData(), expectedMdcEntries)) { + return i; + } + eventWithWrongMdcContents = event; + } + } + if (eventWithWrongMdcContents != null) { + throwAssertionForFoundMessageWithWrongMdcContents(level, regex, eventWithWrongMdcContents); + } + throw new AssertionError(String.format("Expected log message has not occurred: Level: %s, Regex: \"%s\"", level, regex)); + } + + private boolean eventMatchesWithoutMdc(LoggedEvent event, Level level, Pattern pattern, StackTraceElement caller) { + return eventHasLevel(event, level) + && eventMatchesPattern(event, pattern) + && eventIsRelevantToTest(event, caller); + } + + private void throwAssertionForFoundMessageWithWrongMdcContents(Level level, String regex, LoggedEvent eventWithWrongMdcContents) { + StringBuilder assertionMessage = new StringBuilder(String.format("Expected log message has occurred, but never with the expected MDC value: Level: %s, Regex: \"%s\"", level, regex)); + assertionMessage.append(System.lineSeparator()); + assertionMessage.append(String.format(" Captured message: \"%s\"", eventWithWrongMdcContents.getFormattedMessage())); + assertionMessage.append(System.lineSeparator()); + assertionMessage.append(" Captured MDC values:"); + for (Map.Entry entry : eventWithWrongMdcContents.getMdcData().entrySet()) { + assertionMessage.append(System.lineSeparator()); + assertionMessage.append(String.format(" %s: \"%s\"", entry.getKey(), entry.getValue())); + } + throw new AssertionError(assertionMessage.toString()); + } + + // if the call stack is null, it's an integration test where filtering is done via logger name instead of the call stack + private boolean eventIsRelevantToTest(LoggedEvent event, StackTraceElement caller) { + return event.getMethodsInCallStack() == null || event.getMethodsInCallStack().contains(toMethodName(caller)); + } + + private boolean eventMatchesPattern(LoggedEvent event, Pattern pattern) { + return pattern.matcher(event.getFormattedMessage()).matches(); + } + + private boolean eventHasLevel(LoggedEvent event, Level level) { + return event.getLevel().equals(level); + } + + static boolean containsMdcEntries(Map mdcData, ExpectedMdcEntry[] expectedMdcEntries) { + if (expectedMdcEntries == null) { + return true; + } + for (ExpectedMdcEntry expectedMdcEntry : expectedMdcEntries) { + if (!expectedMdcEntry.isContainedIn(mdcData)) { + return false; + } + } + return true; + } + + @Override + public void addFilter(Filter newFilter) { + //do nothing + } + + @Override + public void clearAllFilters() { + // do nothing + } + + @Override + public List> getCopyOfAttachedFiltersList() { + return new LinkedList<>(); + } + + @Override + public FilterReply getFilterChainDecision(ILoggingEvent event) { + return FilterReply.ACCEPT; //never filter + } + + @Override + public void start() { + started = true; + } + + @Override + public void stop() { + started = false; + } +} diff --git a/src/main/java/de/dm/infrastructure/logcapture/ExpectedMdcEntry.java b/src/main/java/de/dm/infrastructure/logcapture/ExpectedMdcEntry.java new file mode 100644 index 0000000..964d5fe --- /dev/null +++ b/src/main/java/de/dm/infrastructure/logcapture/ExpectedMdcEntry.java @@ -0,0 +1,62 @@ +package de.dm.infrastructure.logcapture; + +import lombok.RequiredArgsConstructor; + +import java.util.Map; +import java.util.regex.Pattern; + +/** + * define expected MDC entries with this + */ +@RequiredArgsConstructor +public final class ExpectedMdcEntry { + + private final String key; + private final MdcMatcher matcher; + + boolean isContainedIn(Map mdcContents) { + if (!mdcContents.containsKey(key)) { + return false; + } + return matcher.matches(mdcContents.get(key)); + } + + /** + * use this in LogCapture.assertLogged(...) to verify that something has been logged with an MDC value + * + * @param key MDC key + * @param valueRegex regex that must match the expected value. Will be wrapped with .* + * + * @return expected entry + */ + public static ExpectedMdcEntry withMdc(String key, String valueRegex) { + return new ExpectedMdcEntry(key, new PatternMatcher(valueRegex)); + } + + /** + * use this in LogCapture.assertLogged(...) to verify that something has been logged with an MDC value + * + * @param key MDC key + * @param matcher implementation of {@link MdcMatcher} that checks if the actual MDC content matches the expectations + * + * @return expected entry + */ + public static ExpectedMdcEntry withMdc(String key, MdcMatcher matcher) { + return new ExpectedMdcEntry(key, matcher); + } + + private static class PatternMatcher implements MdcMatcher { + + private final Pattern pattern; + + PatternMatcher(String valueRegex) { + pattern = Pattern.compile(".*" + valueRegex + ".*"); + } + + @Override + public boolean matches(String mdcValue) { + return pattern.matcher(mdcValue).matches(); + } + } + +} diff --git a/src/main/java/de/dm/infrastructure/logcapture/LogCapture.java b/src/main/java/de/dm/infrastructure/logcapture/LogCapture.java new file mode 100644 index 0000000..8148d69 --- /dev/null +++ b/src/main/java/de/dm/infrastructure/logcapture/LogCapture.java @@ -0,0 +1,142 @@ +package de.dm.infrastructure.logcapture; + +import ch.qos.logback.classic.Level; +import ch.qos.logback.classic.Logger; +import lombok.RequiredArgsConstructor; +import org.junit.rules.TestRule; +import org.junit.runner.Description; +import org.junit.runners.model.Statement; +import org.slf4j.LoggerFactory; + +import java.util.Arrays; +import java.util.Collections; +import java.util.List; + +/** + * a JUnit 4 @Rule that can be used to capture log output. Use the appropriate constructor for unit/integration tests. + */ +public final class LogCapture implements TestRule { //should implement AfterEachCallback, BeforeEachCallback in JUnit 5 + + private final boolean forUnitTest; + private final List capturedPackages; + private CapturingAppender capturingAppender; + private Logger rootLogger = (Logger) LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME); + + /** + * LogCapture for unit test - will filter out any log messages that are not caused by the test using the + * message's call stack + * + * @return LogCapture for unit test + */ + public static LogCapture forUnitTest() { + return new LogCapture(true, Collections.emptyList()); + } + + /** + * LocCapture for integration test - needs some packages (for example "de.dm") to define which logs should + * be captured at DEBUG level. Other package's messages may also be captured depending on the log level + * defined in the application + * + * @param capturedPackages packages whose logs should be captured at DEBUG level + * + * @return LogCapture for integration test + */ + public static LogCapture forIntegrationTest(String... capturedPackages) { + if (capturedPackages.length == 0) { + throw new IllegalArgumentException("LogCapture must capture at least one package."); + } + return new LogCapture(false, Arrays.asList(capturedPackages)); + } + + private LogCapture(boolean forUnitTest, List capturedPackages) { + this.forUnitTest = forUnitTest; + this.capturedPackages = capturedPackages; + } + + @Override + public Statement apply(Statement base, Description description) { + return new Statement() { + @Override + public void evaluate() throws Throwable { + addAppender(); + try { + base.evaluate(); + } finally { + removeAppender(); + } + } + }; + } + + /** + * Use this if you are not using LogCapture via JUnit's @Rule + *

+ * For example, this may be used in a Method that is annotated with Cucumber's @Before annotation to start capturing. + * In this case, make sure you also call {@link LogCapture#removeAppender()} in an @After method + */ + public void addAppender() { + capturingAppender = new CapturingAppender(rootLogger.getLoggerContext(), forUnitTest, capturedPackages); + if (capturedPackages.size() == 0) { + rootLogger.getLoggerContext().getLogger(org.slf4j.Logger.ROOT_LOGGER_NAME).setLevel(Level.DEBUG); + } else { + capturedPackages.forEach(packageName -> + rootLogger.getLoggerContext().getLogger(packageName).setLevel(Level.DEBUG) + ); + } + rootLogger.addAppender(capturingAppender); + } + + /** + * Use this if you are not using LogCapture via JUnit's @Rule + *

+ * For example, this may be used in a Method that is annotated with Cucumber's @After annotation to start capturing. + */ + public void removeAppender() { + rootLogger.detachAppender(capturingAppender); + } + + /** + * assert that some message has been logged + * + * @param level expected log level + * @param regex regex to match formatted log message + * @param expectedMdcEntries expected MDC entries, see @{@link ExpectedMdcEntry} + * + * @return a LastCapturedLogEvent from which .thenLogged(...) can be called to assert if things have been logged in a specific order + */ + public LastCapturedLogEvent assertLogged(Level level, String regex, ExpectedMdcEntry... expectedMdcEntries) { + StackTraceElement caller = Thread.currentThread().getStackTrace()[2]; + return assertLogged(level, regex, 0, caller, expectedMdcEntries); + } + + private LastCapturedLogEvent assertLogged(Level level, String regex, int index, StackTraceElement caller, ExpectedMdcEntry... expectedMdcEntries) { + if (capturingAppender == null) { + throw new IllegalStateException("capuringAppender is null. Please make sure that either LogCapture is used with a @Rule annotation or that addAppender is called manually."); + } + Integer foundAtIndex = capturingAppender.whenCapturedNext(level, regex, index, caller, expectedMdcEntries); + return new LastCapturedLogEvent(foundAtIndex, caller); + } + + /** + * Helper to allow for comfortable assertions to check the order in which things are logged + */ + @RequiredArgsConstructor + public class LastCapturedLogEvent { + private final int index; + private final StackTraceElement caller; + + /** + * assert that something has been logged after this event + * + * @param level expected log level + * @param regex regex to match formatted log message + * @param expectedMdcEntries expected MDC entries, see @{@link ExpectedMdcEntry} + * + * @return another LastCapturedLogEvent - for obvious reasons + */ + public LastCapturedLogEvent thenLogged(Level level, String regex, ExpectedMdcEntry... expectedMdcEntries) { + return assertLogged(level, regex, index + 1, caller, expectedMdcEntries); + } + } + +} diff --git a/src/main/java/de/dm/infrastructure/logcapture/LoggedEvent.java b/src/main/java/de/dm/infrastructure/logcapture/LoggedEvent.java new file mode 100644 index 0000000..d69efe0 --- /dev/null +++ b/src/main/java/de/dm/infrastructure/logcapture/LoggedEvent.java @@ -0,0 +1,18 @@ +package de.dm.infrastructure.logcapture; + +import ch.qos.logback.classic.Level; +import lombok.Getter; +import lombok.RequiredArgsConstructor; + +import java.util.Map; +import java.util.Set; + +@RequiredArgsConstructor +@Getter +class LoggedEvent { + + private final Level level; + private final String formattedMessage; + private final Set methodsInCallStack; + private final Map mdcData; +} diff --git a/src/main/java/de/dm/infrastructure/logcapture/MdcMatcher.java b/src/main/java/de/dm/infrastructure/logcapture/MdcMatcher.java new file mode 100644 index 0000000..d19abe4 --- /dev/null +++ b/src/main/java/de/dm/infrastructure/logcapture/MdcMatcher.java @@ -0,0 +1,16 @@ +package de.dm.infrastructure.logcapture; + +/** + * implement this if you have custom requirements when matching MDC contents + */ +public interface MdcMatcher { + + /** + * check if an actual MDC value matches the expectations + * + * @param mdcValue actual MDC value + * + * @return if the expectations are matched + */ + boolean matches(String mdcValue); +} diff --git a/src/main/java/de/dm/infrastructure/logcapture/package-info.java b/src/main/java/de/dm/infrastructure/logcapture/package-info.java new file mode 100644 index 0000000..5a5d006 --- /dev/null +++ b/src/main/java/de/dm/infrastructure/logcapture/package-info.java @@ -0,0 +1 @@ +package de.dm.infrastructure.logcapture; diff --git a/src/test/java/de/dm/infrastructure/logcapture/CapturingAppenderIntegrationTest.java b/src/test/java/de/dm/infrastructure/logcapture/CapturingAppenderIntegrationTest.java new file mode 100644 index 0000000..14a4955 --- /dev/null +++ b/src/test/java/de/dm/infrastructure/logcapture/CapturingAppenderIntegrationTest.java @@ -0,0 +1,32 @@ +package de.dm.infrastructure.logcapture; + +import org.junit.Assert; +import org.junit.Test; + +import java.util.HashMap; +import java.util.Map; + +public class CapturingAppenderIntegrationTest { + + private final String TEST_KEY = "test_key"; + private final String OTHER_KEY = "test_key_2"; + + @Test + public void containsMdcEntries() { + ExpectedMdcEntry expectedMdcEntry1 = ExpectedMdcEntry.withMdc(TEST_KEY, "test value"); + ExpectedMdcEntry expectedMdcEntry2 = ExpectedMdcEntry.withMdc(OTHER_KEY, "good value"); + ExpectedMdcEntry[] expectedMdcEntries = new ExpectedMdcEntry[]{expectedMdcEntry1, expectedMdcEntry2}; + + Map mdcContents = new HashMap<>(); + mdcContents.put(TEST_KEY, "this is a test value, cool!"); + mdcContents.put(OTHER_KEY, "this is a good value, cool!"); + + Assert.assertTrue(CapturingAppender.containsMdcEntries(mdcContents, expectedMdcEntries)); + } + + @Test + public void nullEntriesShouldNotThrowNullPointerException() { + Map mdcContents = new HashMap<>(); + Assert.assertTrue(CapturingAppender.containsMdcEntries(mdcContents, null)); + } +} diff --git a/src/test/java/de/dm/infrastructure/logcapture/ExpectedMdcEntryUnitTest.java b/src/test/java/de/dm/infrastructure/logcapture/ExpectedMdcEntryUnitTest.java new file mode 100644 index 0000000..90812f5 --- /dev/null +++ b/src/test/java/de/dm/infrastructure/logcapture/ExpectedMdcEntryUnitTest.java @@ -0,0 +1,30 @@ +package de.dm.infrastructure.logcapture; + +import org.junit.Assert; +import org.junit.Test; + +import java.util.HashMap; +import java.util.Map; + +public class ExpectedMdcEntryUnitTest { + + private static final String TEST_KEY = "test_key"; + + @Test + public void isContainedIn() { + ExpectedMdcEntry expectedMdcEntry = ExpectedMdcEntry.withMdc(TEST_KEY, "test value"); + Map mdcContents = new HashMap<>(); + mdcContents.put(TEST_KEY, "this is a test value, cool!"); + Assert.assertTrue(expectedMdcEntry.isContainedIn(mdcContents)); + } + + @Test + public void isNotContainedIn() { + ExpectedMdcEntry expectedMdcEntry = ExpectedMdcEntry.withMdc(TEST_KEY, "test value"); + Map mdcContents = new HashMap<>(); + mdcContents.put(TEST_KEY, "this is a value, cool!"); + mdcContents.put("some_other_key", "this is a test value, cool!"); + Assert.assertFalse(expectedMdcEntry.isContainedIn(mdcContents)); + } + +} diff --git a/src/test/java/de/dm/infrastructure/logcapture/LogCaptureInIntegrationTest.java b/src/test/java/de/dm/infrastructure/logcapture/LogCaptureInIntegrationTest.java new file mode 100644 index 0000000..adbe755 --- /dev/null +++ b/src/test/java/de/dm/infrastructure/logcapture/LogCaptureInIntegrationTest.java @@ -0,0 +1,45 @@ +package de.dm.infrastructure.logcapture; + +import ch.qos.logback.classic.Level; +import lombok.extern.slf4j.Slf4j; +import org.junit.Rule; +import org.junit.Test; +import org.junit.rules.ExpectedException; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; + +@Slf4j +public class LogCaptureInIntegrationTest { + + @Rule + public LogCapture logCapture = LogCapture.forIntegrationTest("de.dm"); + + @Rule //to be replaced with Assertions.assertThrows() in JUnit 5 + public final ExpectedException exception = ExpectedException.none(); + + @Test + public void twoLogMessagesInOrder() { + log.info("something interesting"); + log.error("something terrible"); + + logCapture + .assertLogged(Level.INFO, "^something interesting") + .thenLogged(Level.ERROR, "terrible"); + } + + @Test + public void catchMissingLogMessage() { + exception.expect(AssertionError.class); + logCapture.assertLogged(Level.INFO, "something that has not been logged"); + } + + @Test + public void filterOutIrrelevantLogMessagesInIntegrationTest() { + ch.qos.logback.classic.Logger rootLogger = (ch.qos.logback.classic.Logger) LoggerFactory.getLogger(ch.qos.logback.classic.Logger.ROOT_LOGGER_NAME); + rootLogger.getLoggerContext().getLogger(org.slf4j.Logger.ROOT_LOGGER_NAME).setLevel(Level.DEBUG); + Logger logger = LoggerFactory.getLogger("com.acme.whatever"); + logger.info("something from another package"); + exception.expect(AssertionError.class); + logCapture.assertLogged(Level.INFO, "something from another package"); + } +} diff --git a/src/test/java/de/dm/infrastructure/logcapture/LogCaptureInUnitTest.java b/src/test/java/de/dm/infrastructure/logcapture/LogCaptureInUnitTest.java new file mode 100644 index 0000000..33f6c48 --- /dev/null +++ b/src/test/java/de/dm/infrastructure/logcapture/LogCaptureInUnitTest.java @@ -0,0 +1,89 @@ +package de.dm.infrastructure.logcapture; + +import ch.qos.logback.classic.Level; +import lombok.extern.slf4j.Slf4j; +import org.junit.Assert; +import org.junit.Rule; +import org.junit.Test; +import org.junit.rules.ExpectedException; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; +import org.slf4j.MDC; + +import static de.dm.infrastructure.logcapture.ExpectedMdcEntry.withMdc; + +@Slf4j +public class LogCaptureInUnitTest { + + private static final String MDC_KEY = "mdc_key"; + @Rule + public LogCapture logCapture = LogCapture.forUnitTest(); + + @Rule //to be replaced with Assertions.assertThrows() in JUnit 5 + public final ExpectedException exception = ExpectedException.none(); + + @Test + public void twoLogMessagesInOrder() { + log.info("something interesting"); + log.error("something terrible"); + + logCapture + .assertLogged(Level.INFO, "^something interesting") + .thenLogged(Level.ERROR, "terrible"); + } + + @Test + public void catchMissingLogMessage() { + boolean assertionErrorThrown = false; + try { + logCapture.assertLogged(Level.INFO, "something that has not been logged"); + } catch (AssertionError e) { + String expectedMessage = "Expected log message has not occurred: Level: INFO, Regex: \"something that has not been logged\""; + Assert.assertEquals(expectedMessage, e.getMessage()); + assertionErrorThrown = true; + } + if (!assertionErrorThrown) { + throw new AssertionError("Assertion Error has not been thrown for missing log message."); + } + } + + @Test + public void dontFilterOutMessagesFromOtherPackagesInUnitTests() { + Logger logger = LoggerFactory.getLogger("com.acme.whatever"); + logger.info("something from another package"); + logCapture.assertLogged(Level.INFO, "something from another package"); + } + + @Test + public void logMessagesWithMdc() { + MDC.put(MDC_KEY, "an mdc value here"); + log.info("this should have an mdc value"); + + logCapture + .assertLogged(Level.INFO, "mdc value", withMdc(MDC_KEY, "mdc value")); + } + + @Test + public void correctLogMessagesWithMissingMdc() { + String actualMdcValue = "a wrong value here"; + MDC.put(MDC_KEY, actualMdcValue); + log.info("some message"); + + boolean assertionErrorThrown = false; + try { + logCapture + .assertLogged(Level.INFO, "some message", withMdc(MDC_KEY, "mdc value")); + } catch (AssertionError e) { + String expectedMessage = "Expected log message has occurred, but never with the expected MDC value: Level: INFO, Regex: \"some message\"" + + System.lineSeparator() + " Captured message: \"some message\"" + + System.lineSeparator() + " Captured MDC values:" + + System.lineSeparator() + " " + MDC_KEY + ": \"" + actualMdcValue + "\""; + + Assert.assertEquals(expectedMessage, e.getMessage()); + assertionErrorThrown = true; + } + if (!assertionErrorThrown) { + throw new AssertionError("Assertion Error has not been thrown for missing log message."); + } + } +} diff --git a/src/test/resources/logback.xml b/src/test/resources/logback.xml new file mode 100644 index 0000000..c0c13f8 --- /dev/null +++ b/src/test/resources/logback.xml @@ -0,0 +1,11 @@ + + + + %d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n + + + + + + +