diff --git a/akka-actor-testkit-typed/src/main/scala/akka/actor/testkit/typed/internal/LoggingEventFilterImpl.scala b/akka-actor-testkit-typed/src/main/scala/akka/actor/testkit/typed/internal/LoggingEventFilterImpl.scala index 4c2c96b9d2..1a12cf7b8f 100644 --- a/akka-actor-testkit-typed/src/main/scala/akka/actor/testkit/typed/internal/LoggingEventFilterImpl.scala +++ b/akka-actor-testkit-typed/src/main/scala/akka/actor/testkit/typed/internal/LoggingEventFilterImpl.scala @@ -75,17 +75,29 @@ import org.slf4j.event.Level todo == Int.MaxValue || todo == 0 } + private def awaitNoExcess(max: Duration): Boolean = { + if (todo == 0) + !TestKit.awaitCond(todo < 0, max, noThrow = true) + else + todo > 0 + } + override def intercept[T](code: => T)(implicit system: ActorSystem[_]): T = { val effectiveLoggerName = loggerName.getOrElse("") checkLogback(system) TestAppender.setupTestAppender(effectiveLoggerName) TestAppender.addFilter(effectiveLoggerName, this) - val leeway = TestKitSettings(system).FilterLeeway + val settings = TestKitSettings(system) try { val result = code - if (!awaitDone(leeway)) + + // wait some more when occurrences=0 to find asynchronous exceess messages + if (occurrences == 0) + awaitNoExcess(settings.ExpectNoMessageDefaultTimeout) + + if (!awaitDone(settings.FilterLeeway)) if (todo > 0) - throw new AssertionError(s"Timeout ($leeway) waiting for $todo messages on $this.") + throw new AssertionError(s"Timeout (${settings.FilterLeeway}) waiting for $todo messages on $this.") else throw new AssertionError(s"Received ${-todo} excess messages on $this.") result diff --git a/akka-actor-testkit-typed/src/main/scala/akka/actor/testkit/typed/javadsl/LoggingEventFilter.scala b/akka-actor-testkit-typed/src/main/scala/akka/actor/testkit/typed/javadsl/LoggingEventFilter.scala index 462bb1807f..ce16d2869f 100644 --- a/akka-actor-testkit-typed/src/main/scala/akka/actor/testkit/typed/javadsl/LoggingEventFilter.scala +++ b/akka-actor-testkit-typed/src/main/scala/akka/actor/testkit/typed/javadsl/LoggingEventFilter.scala @@ -26,6 +26,13 @@ import org.slf4j.event.Level /** * Number of events the filter is supposed to match. By default 1. + * + * When occurrences > 0 it will not look for excess messages that are logged asynchronously + * outside (after) the `intercept` thunk and it has already found expected number. + * + * When occurrences is 0 it will look for unexpected matching events, and then it will + * also look for excess messages during the configured `akka.actor.testkit.typed.expect-no-message-default` + * duration. */ def withOccurrences(newOccurrences: Int): LoggingEventFilter diff --git a/akka-actor-testkit-typed/src/main/scala/akka/actor/testkit/typed/scaladsl/LoggingEventFilter.scala b/akka-actor-testkit-typed/src/main/scala/akka/actor/testkit/typed/scaladsl/LoggingEventFilter.scala index 7eadc02da8..0bc3e82410 100644 --- a/akka-actor-testkit-typed/src/main/scala/akka/actor/testkit/typed/scaladsl/LoggingEventFilter.scala +++ b/akka-actor-testkit-typed/src/main/scala/akka/actor/testkit/typed/scaladsl/LoggingEventFilter.scala @@ -26,6 +26,13 @@ import org.slf4j.event.Level /** * Number of events the filter is supposed to match. By default 1. + * + * When occurrences > 0 it will not look for excess messages that are logged asynchronously + * outside (after) the `intercept` thunk and it has already found expected number. + * + * When occurrences is 0 it will look for unexpected matching events, and then it will + * also look for excess messages during the configured `akka.actor.testkit.typed.expect-no-message-default` + * duration. */ def withOccurrences(newOccurrences: Int): LoggingEventFilter diff --git a/akka-actor-testkit-typed/src/test/scala/akka/actor/testkit/typed/scaladsl/TestAppenderSpec.scala b/akka-actor-testkit-typed/src/test/scala/akka/actor/testkit/typed/scaladsl/TestAppenderSpec.scala index a0c704a5a3..9ff0818754 100644 --- a/akka-actor-testkit-typed/src/test/scala/akka/actor/testkit/typed/scaladsl/TestAppenderSpec.scala +++ b/akka-actor-testkit-typed/src/test/scala/akka/actor/testkit/typed/scaladsl/TestAppenderSpec.scala @@ -6,11 +6,20 @@ package akka.actor.testkit.typed.scaladsl import java.util.concurrent.atomic.AtomicInteger +import scala.concurrent.Future + import akka.actor.testkit.typed.TestException import org.scalatest.WordSpecLike import org.slf4j.LoggerFactory -class TestAppenderSpec extends ScalaTestWithActorTestKit with WordSpecLike with LogCapturing { +class TestAppenderSpec + extends ScalaTestWithActorTestKit( + """ + # increase to avoid spurious failures in "find unexpected async events withOccurrences(0)" + akka.actor.testkit.typed.expect-no-message-default = 1000 ms + """) + with WordSpecLike + with LogCapturing { class AnotherLoggerClass @@ -39,6 +48,21 @@ class TestAppenderSpec extends ScalaTestWithActorTestKit with WordSpecLike with } } + "find excess messages" in { + intercept[AssertionError] { + LoggingEventFilter.warn("a warning").withOccurrences(2).intercept { + log.error("an error") + log.warn("a warning") + log.warn("a warning") + log.error("an error") + // since this logging is synchronous it will notice 3 occurrences but expecting 2, + // but note that it will not look for asynchronous excess messages when occurrences > 0 and it has + // already found expected number + log.warn("a warning") // 3rd + } + }.getMessage should include("Received 1 excess messages") + } + "only filter events for given logger name" in { val count = new AtomicInteger LoggingEventFilter @@ -57,7 +81,7 @@ class TestAppenderSpec extends ScalaTestWithActorTestKit with WordSpecLike with count.get should ===(2) } - "find unexpected events withOccurences(0)" in { + "find unexpected events withOccurrences(0)" in { LoggingEventFilter.warn("a warning").withOccurrences(0).intercept { log.error("an error") log.warn("another warning") @@ -77,6 +101,20 @@ class TestAppenderSpec extends ScalaTestWithActorTestKit with WordSpecLike with log.warn("a warning") } }.getMessage should include("Received 2 excess messages") + + } + + "find unexpected async events withOccurrences(0)" in { + // expect-no-message-default = 1000 ms + intercept[AssertionError] { + LoggingEventFilter.warn("a warning").withOccurrences(0).intercept { + Future { + Thread.sleep(20) + log.warn("a warning") + log.warn("a warning") + }(system.executionContext) + } + } } }