Merge pull request #27701 from akka/wip-occurence0-patriknw

wait for async excess events when occurrences 0

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

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
 

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
 

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)
+        }
+      }
     }
 
   }