From 79783ba6eea40218c6fc0267886cdbd4c5cf3e59 Mon Sep 17 00:00:00 2001 From: MuSTa1nE Date: Wed, 23 Aug 2017 23:36:59 +0100 Subject: [PATCH] Capture Async logs. Add assertions to assert on result. --- build.gradle | 1 + src/main/java/com/logcapture/Await.java | 11 +++ src/main/java/com/logcapture/CaptureLogs.java | 65 ++++++++++++++++- src/main/java/com/logcapture/LogCapture.java | 30 ++++++-- .../assertion/ExpectedLoggingMessage.java | 2 +- .../com/logcapture/CaptureLogsShould.java | 16 ----- .../java/com/logcapture/LogCaptureShould.java | 69 +++++++++++++++++-- .../ExpectedLoggingMessageShould.java | 27 ++++---- 8 files changed, 179 insertions(+), 42 deletions(-) create mode 100644 src/main/java/com/logcapture/Await.java diff --git a/build.gradle b/build.gradle index ab3843f..5d50a5f 100644 --- a/build.gradle +++ b/build.gradle @@ -32,6 +32,7 @@ dependencies { compile "org.slf4j:slf4j-api:1.7.22" compile "ch.qos.logback:logback-classic:1.1.8" compile "org.hamcrest:hamcrest-library:1.3" + compile "com.jayway.awaitility:awaitility:1.7.0" testCompile "junit:junit:4.12" testCompile "org.assertj:assertj-core:3.6.1" diff --git a/src/main/java/com/logcapture/Await.java b/src/main/java/com/logcapture/Await.java new file mode 100644 index 0000000..1364dbe --- /dev/null +++ b/src/main/java/com/logcapture/Await.java @@ -0,0 +1,11 @@ +package com.logcapture; + +import com.logcapture.assertion.ExpectedLoggingMessage; + +import java.time.Duration; + +@FunctionalInterface +public interface Await { + + LogCapture waitAtMost(Duration duration, ExpectedLoggingMessage condition); +} diff --git a/src/main/java/com/logcapture/CaptureLogs.java b/src/main/java/com/logcapture/CaptureLogs.java index 0ff96bf..c734dce 100644 --- a/src/main/java/com/logcapture/CaptureLogs.java +++ b/src/main/java/com/logcapture/CaptureLogs.java @@ -2,26 +2,87 @@ import ch.qos.logback.classic.Logger; import ch.qos.logback.classic.spi.ILoggingEvent; +import com.logcapture.assertion.ExpectedLoggingMessage; import com.logcapture.infrastructure.logback.StubAppender; import org.slf4j.LoggerFactory; +import java.time.Duration; import java.util.List; +import java.util.concurrent.Callable; +import java.util.function.Supplier; +import static com.jayway.awaitility.Awaitility.await; +import static java.util.concurrent.TimeUnit.SECONDS; import static org.slf4j.Logger.ROOT_LOGGER_NAME; public class CaptureLogs { - public static List captureLogEvents(Runnable codeBlock) { + public static LogCapture captureLogEvents(Runnable codeBlock) { StubAppender logAppender = new StubAppender(); Logger root = (Logger) LoggerFactory.getLogger(ROOT_LOGGER_NAME); root.addAppender(logAppender); try { codeBlock.run(); + return new LogCapture<>(logAppender.events(), null); } finally { root.detachAppender(logAppender); } + } + + public static LogCapture captureLogEvents(Supplier codeBlock) { + StubAppender logAppender = new StubAppender(); + Logger root = (Logger) LoggerFactory.getLogger(ROOT_LOGGER_NAME); + + root.addAppender(logAppender); + try { + T result = codeBlock.get(); + return new LogCapture<>(logAppender.events(), result); + } finally { + root.detachAppender(logAppender); + } + } + + public static LogCapture captureLogEventsAsync(Runnable codeBlock, Duration duration, ExpectedLoggingMessage expectedLoggingMessage) { + StubAppender logAppender = new StubAppender(); + Logger root = (Logger) LoggerFactory.getLogger(ROOT_LOGGER_NAME); + + root.addAppender(logAppender); + try { + codeBlock.run(); + awaitForLogMessage(duration, hasLoggedMessage(logAppender.events(), expectedLoggingMessage)); + return new LogCapture<>(logAppender.events(), null); + } finally { + root.detachAppender(logAppender); + } + } + + public static LogCapture captureLogEventsAsync(Supplier codeBlock, Duration duration, ExpectedLoggingMessage expectedLoggingMessage) { + StubAppender logAppender = new StubAppender(); + Logger root = (Logger) LoggerFactory.getLogger(ROOT_LOGGER_NAME); + + root.addAppender(logAppender); + try { + T result = codeBlock.get(); + awaitForLogMessage(duration, hasLoggedMessage(logAppender.events(), expectedLoggingMessage)); + return new LogCapture<>(logAppender.events(), result); + } finally { + root.detachAppender(logAppender); + } + } + + private static Callable hasLoggedMessage(List events, ExpectedLoggingMessage expectedLoggingMessage) { + return () -> { + try { + new LogCapture<>(events, null).logged(expectedLoggingMessage); + return true; + } catch (Exception e) { + return false; + } + }; + } - return logAppender.events(); + private static void awaitForLogMessage(Duration duration, Callable condition) { + await().atMost(duration.getSeconds(), SECONDS).until(condition); } } diff --git a/src/main/java/com/logcapture/LogCapture.java b/src/main/java/com/logcapture/LogCapture.java index 5c00dd7..52428ef 100644 --- a/src/main/java/com/logcapture/LogCapture.java +++ b/src/main/java/com/logcapture/LogCapture.java @@ -4,16 +4,20 @@ import com.logcapture.assertion.ExpectedLoggingMessage; import java.util.List; +import java.util.function.Consumer; +import java.util.function.Supplier; -public class LogCapture { +public class LogCapture { private final List events; + private final T result; - private LogCapture(List events) { + public LogCapture(List events, T result) { this.events = events; + this.result = result; } - public LogCapture containMessage(ExpectedLoggingMessage expectedLoggingMessage) { + public LogCapture logged(ExpectedLoggingMessage expectedLoggingMessage) { for (ILoggingEvent event : events) { if (expectedLoggingMessage.matches(event)) { return this; @@ -23,7 +27,23 @@ public LogCapture containMessage(ExpectedLoggingMessage expectedLoggingMessage) throw new RuntimeException("No Log Found for [" + expectedLoggingMessage + "]"); } - public static LogCapture captureLogEvents(Runnable codeBlock) { - return new LogCapture(CaptureLogs.captureLogEvents(codeBlock)); + public LogCapture assertions(Consumer assertions) { + assertions.accept(result); + return this; + } + + public static LogCapture captureLogEvents(Runnable codeBlock) { + return CaptureLogs.captureLogEvents(codeBlock); + } + + public static LogCapture captureLogEvents(Supplier codeBlock) { + return CaptureLogs.captureLogEvents(codeBlock); + } + + public static Await captureLogEventsAsync(Runnable codeBlock) { + return (duration, condition) -> CaptureLogs.captureLogEventsAsync(codeBlock, duration, condition); + } + public static Await captureLogEventsAsync(Supplier codeBlock) { + return (duration, condition) -> CaptureLogs.captureLogEventsAsync(codeBlock, duration, condition); } } diff --git a/src/main/java/com/logcapture/assertion/ExpectedLoggingMessage.java b/src/main/java/com/logcapture/assertion/ExpectedLoggingMessage.java index 2359f8d..10ce599 100644 --- a/src/main/java/com/logcapture/assertion/ExpectedLoggingMessage.java +++ b/src/main/java/com/logcapture/assertion/ExpectedLoggingMessage.java @@ -23,7 +23,7 @@ public class ExpectedLoggingMessage { private ExpectedLoggingMessage() { } - public static ExpectedLoggingMessage logMessage() { + public static ExpectedLoggingMessage aMessage() { return new ExpectedLoggingMessage(); } diff --git a/src/test/java/com/logcapture/CaptureLogsShould.java b/src/test/java/com/logcapture/CaptureLogsShould.java index 0796448..f047f57 100644 --- a/src/test/java/com/logcapture/CaptureLogsShould.java +++ b/src/test/java/com/logcapture/CaptureLogsShould.java @@ -1,35 +1,19 @@ package com.logcapture; -import ch.qos.logback.classic.spi.ILoggingEvent; import org.junit.Test; import org.slf4j.Logger; import org.slf4j.LoggerFactory; -import org.slf4j.event.Level; - -import java.util.List; import static com.logcapture.CaptureLogs.captureLogEvents; import static com.logcapture.infrastructure.logback.StubAppender.STUB_APPENDER_NAME; import static org.assertj.core.api.Assertions.assertThat; import static org.assertj.core.api.Assertions.assertThatThrownBy; import static org.slf4j.Logger.ROOT_LOGGER_NAME; -import static org.slf4j.event.Level.INFO; public class CaptureLogsShould { private final Logger log = LoggerFactory.getLogger(this.getClass()); - @Test - public void capture_events() { - List logEvents = captureLogEvents(() -> log.info("a message")); - - boolean anyMatch = logEvents.stream().anyMatch(e -> - Level.valueOf(e.getLevel().levelStr) == INFO && e.getMessage().equals("a message")); - - assertThat(logEvents).hasSize(1); - assertThat(anyMatch).isTrue(); - } - @Test public void detach_appender_when_events_are_captured() { captureLogEvents(() -> log.info("a message")); diff --git a/src/test/java/com/logcapture/LogCaptureShould.java b/src/test/java/com/logcapture/LogCaptureShould.java index 32788b0..3da591d 100644 --- a/src/test/java/com/logcapture/LogCaptureShould.java +++ b/src/test/java/com/logcapture/LogCaptureShould.java @@ -1,13 +1,18 @@ package com.logcapture; -import org.assertj.core.api.Assertions; import org.junit.Test; import org.slf4j.Logger; import org.slf4j.LoggerFactory; +import java.util.concurrent.CompletableFuture; + import static ch.qos.logback.classic.Level.INFO; import static com.logcapture.LogCapture.captureLogEvents; -import static com.logcapture.assertion.ExpectedLoggingMessage.logMessage; +import static com.logcapture.LogCapture.captureLogEventsAsync; +import static com.logcapture.assertion.ExpectedLoggingMessage.aMessage; +import static java.time.Duration.ofSeconds; +import static org.assertj.core.api.Assertions.assertThat; +import static org.assertj.core.api.Assertions.assertThatThrownBy; import static org.hamcrest.Matchers.equalTo; public class LogCaptureShould { @@ -16,15 +21,69 @@ public class LogCaptureShould { @Test public void verify_captured_events() { captureLogEvents(() -> log.info("a message")) - .containMessage(logMessage() + .logged(aMessage() + .withLevel(equalTo(INFO)) + .withMessage(equalTo("a message"))); + } + + @Test + public void verify_captured_events_without_result_assertion_null() { + captureLogEvents(() -> log.info("a message")) + .logged(aMessage() + .withLevel(equalTo(INFO)) + .withMessage(equalTo("a message"))) + .assertions(result -> assertThat(result).isNull()); + } + + @Test + public void verify_captured_events_having_assertions_as_result() { + captureLogEvents(() -> { + log.info("a message"); + return "aResult"; + }) + .assertions((result) -> assertThat(result).isEqualTo("aResult")) + .logged(aMessage() .withLevel(equalTo(INFO)) .withMessage(equalTo("a message"))); } + @Test + public void verify_captured_events_without_assertions() { + captureLogEvents(() -> { + log.info("a message"); + return "aResult"; + }) + .logged(aMessage() + .withLevel(equalTo(INFO)) + .withMessage(equalTo("a message"))) + .assertions((result) -> assertThat(result).isEqualTo("aResult")); + } + + @Test + public void verify_captured_async_logs_of_runnable() { + captureLogEventsAsync(() -> new Thread(() -> log.info("a message")).start()) + .waitAtMost(ofSeconds(1), aMessage() + .withLevel(equalTo(INFO)) + .withMessage(equalTo("a message"))) + .assertions(result -> assertThat(result).isNull()); + } + + @Test + public void verify_captured_events_async_with_assertions() { + captureLogEventsAsync(() -> CompletableFuture.supplyAsync(() -> { + log.info("a message"); + return "aResult"; + })) + .waitAtMost(ofSeconds(1), aMessage() + .withLevel(equalTo(INFO)) + .withMessage(equalTo("a message"))) + .assertions(result -> assertThat(result).isCompletedWithValue("aResult")); + } + @Test public void fail_when_verify_captured_events_not_found() { - Assertions.assertThatThrownBy(() -> captureLogEvents(() -> log.info("a message")) - .containMessage(logMessage() + assertThatThrownBy(() -> captureLogEvents(() -> log.info("a message")) + .logged(aMessage() .withLevel(equalTo(INFO)) .withMessage(equalTo("a different message")))) .isInstanceOf(RuntimeException.class) diff --git a/src/test/java/com/logcapture/assertion/ExpectedLoggingMessageShould.java b/src/test/java/com/logcapture/assertion/ExpectedLoggingMessageShould.java index 2000527..faaa369 100644 --- a/src/test/java/com/logcapture/assertion/ExpectedLoggingMessageShould.java +++ b/src/test/java/com/logcapture/assertion/ExpectedLoggingMessageShould.java @@ -9,6 +9,7 @@ import static ch.qos.logback.classic.Level.ERROR; import static ch.qos.logback.classic.Level.INFO; +import static com.logcapture.assertion.ExpectedLoggingMessage.aMessage; import static org.assertj.core.api.Assertions.assertThat; import static org.hamcrest.Matchers.equalTo; import static org.hamcrest.Matchers.instanceOf; @@ -18,7 +19,7 @@ public class ExpectedLoggingMessageShould { @Test public void match_when_log_level_match() { LoggingEvent logEvent = aLoggingEventWith(INFO, "message"); - ExpectedLoggingMessage expectedLoggingMessage = ExpectedLoggingMessage.logMessage().withLevel(equalTo(INFO)); + ExpectedLoggingMessage expectedLoggingMessage = aMessage().withLevel(equalTo(INFO)); boolean matches = expectedLoggingMessage.matches(logEvent); @@ -28,7 +29,7 @@ public void match_when_log_level_match() { @Test public void match_when_message_match() { LoggingEvent logEvent = aLoggingEventWith(INFO, "message"); - ExpectedLoggingMessage expectedLoggingMessage = ExpectedLoggingMessage.logMessage().withMessage(equalTo("message")); + ExpectedLoggingMessage expectedLoggingMessage = aMessage().withMessage(equalTo("message")); boolean matches = expectedLoggingMessage.matches(logEvent); @@ -38,7 +39,7 @@ public void match_when_message_match() { @Test public void match_when_length_message_match() { LoggingEvent logEvent = aLoggingEventWith(INFO, "message"); - ExpectedLoggingMessage expectedLoggingMessage = ExpectedLoggingMessage.logMessage() + ExpectedLoggingMessage expectedLoggingMessage = aMessage() .length(equalTo(7)); boolean matches = expectedLoggingMessage.matches(logEvent); @@ -50,7 +51,7 @@ public void match_when_length_message_match() { public void match_when_mdc_keys_match() { MDC.put("aKey", "someValue"); LoggingEvent logEvent = aLoggingEventWith(INFO, "message"); - ExpectedLoggingMessage expectedLoggingMessage = ExpectedLoggingMessage.logMessage() + ExpectedLoggingMessage expectedLoggingMessage = aMessage() .withMdc("aKey", equalTo("someValue")); boolean matches = expectedLoggingMessage.matches(logEvent); @@ -61,7 +62,7 @@ public void match_when_mdc_keys_match() { @Test public void match_when_logger_class_match() { LoggingEvent logEvent = aLoggingEventWith(INFO, "message"); - ExpectedLoggingMessage expectedLoggingMessage = ExpectedLoggingMessage.logMessage() + ExpectedLoggingMessage expectedLoggingMessage = aMessage() .withLoggerName(equalTo(ExpectedLoggingMessageShould.class.getName())); boolean matches = expectedLoggingMessage.matches(logEvent); @@ -72,7 +73,7 @@ public void match_when_logger_class_match() { @Test public void match_when_exception_class_match() { LoggingEvent logEvent = aLoggingEventWith(INFO, "message", new RuntimeException()); - ExpectedLoggingMessage expectedLoggingMessage = ExpectedLoggingMessage.logMessage() + ExpectedLoggingMessage expectedLoggingMessage = aMessage() .havingException(ExpectedLoggedException.logException() .withException(instanceOf(RuntimeException.class))); @@ -84,7 +85,7 @@ public void match_when_exception_class_match() { @Test public void match_when_message_and_log_level_match() { LoggingEvent logEvent = aLoggingEventWith(INFO, "message"); - ExpectedLoggingMessage expectedLoggingMessage = ExpectedLoggingMessage.logMessage() + ExpectedLoggingMessage expectedLoggingMessage = aMessage() .withLevel(equalTo(INFO)) .withMessage(equalTo("message")); @@ -96,7 +97,7 @@ public void match_when_message_and_log_level_match() { @Test public void not_match_when_log_level_different() { LoggingEvent logEvent = aLoggingEventWith(INFO, "message"); - ExpectedLoggingMessage expectedLoggingMessage = ExpectedLoggingMessage.logMessage() + ExpectedLoggingMessage expectedLoggingMessage = aMessage() .withMessage(equalTo("differentMessage")); boolean matches = expectedLoggingMessage.matches(logEvent); @@ -107,7 +108,7 @@ public void not_match_when_log_level_different() { @Test public void not_match_when_message_different() { LoggingEvent logEvent = aLoggingEventWith(INFO, "message"); - ExpectedLoggingMessage expectedLoggingMessage = ExpectedLoggingMessage.logMessage() + ExpectedLoggingMessage expectedLoggingMessage = aMessage() .withMessage(equalTo("anotherMessage")); boolean matches = expectedLoggingMessage.matches(logEvent); @@ -118,7 +119,7 @@ public void not_match_when_message_different() { @Test public void not_match_when_message_length_different() { LoggingEvent logEvent = aLoggingEventWith(INFO, "message"); - ExpectedLoggingMessage expectedLoggingMessage = ExpectedLoggingMessage.logMessage() + ExpectedLoggingMessage expectedLoggingMessage = aMessage() .length(equalTo(8)); boolean matches = expectedLoggingMessage.matches(logEvent); @@ -130,7 +131,7 @@ public void not_match_when_message_length_different() { public void not_match_when_mdc_keys_different() { MDC.put("aKey", "differentValue"); LoggingEvent logEvent = aLoggingEventWith(INFO, "message"); - ExpectedLoggingMessage expectedLoggingMessage = ExpectedLoggingMessage.logMessage() + ExpectedLoggingMessage expectedLoggingMessage = aMessage() .withMdc("aKey", equalTo("someValue")); boolean matches = expectedLoggingMessage.matches(logEvent); @@ -141,7 +142,7 @@ public void not_match_when_mdc_keys_different() { @Test public void not_match_when_logger_class_different() { LoggingEvent logEvent = aLoggingEventWith(INFO, "message"); - ExpectedLoggingMessage expectedLoggingMessage = ExpectedLoggingMessage.logMessage() + ExpectedLoggingMessage expectedLoggingMessage = aMessage() .withLoggerName(equalTo("anotherClassName")); boolean matches = expectedLoggingMessage.matches(logEvent); @@ -151,7 +152,7 @@ public void not_match_when_logger_class_different() { @Test public void describe_failure_using_to_string() { - ExpectedLoggingMessage expectedLoggingMessage = ExpectedLoggingMessage.logMessage() + ExpectedLoggingMessage expectedLoggingMessage = aMessage() .withLevel(equalTo(ERROR)) .withMessage(equalTo("message")) .length(equalTo(8))