apache / pekko

Build highly concurrent, distributed, and resilient message-driven applications using Java/Scala
https://pekko.apache.org/
Apache License 2.0
1.2k stars 148 forks source link

EventSourcedBehaviorLoggingSpec test fails regularly #1521

Closed pjfanning closed 3 weeks ago

pjfanning commented 3 weeks ago

Scala 3.3 testing in nightly build but may just be an issue everywhere.

https://github.com/apache/pekko/actions/runs/11226174902/job/31219178672

[10-08 08:24:16.856] [info] - must always log user message in context.log *** FAILED *** (6 seconds, 14 milliseconds)
[10-08 08:24:16.857] [info]   java.lang.AssertionError: Timeout (6 seconds) waiting for 1 messages on LoggingTestKitImpl(1,Some(INFO),Some(org.apache.pekko.persistence.typed.EventSourcedBehaviorLoggingSpec$ChattyEventSourcingBehavior$),None,Some(received message 'Mary'),None,None,Map(),true,None).
[10-08 08:24:16.857] [info]   at org.apache.pekko.actor.testkit.typed.internal.LoggingTestKitImpl.expect(LoggingTestKitImpl.scala:113)
[10-08 08:24:16.857] [info]   at org.apache.pekko.persistence.typed.EventSourcedBehaviorLoggingSpec.f$proxy1$1(EventSourcedBehaviorLoggingSpec.scala:86)
[10-08 08:24:16.857] [info]   at org.apache.pekko.persistence.typed.EventSourcedBehaviorLoggingSpec.$init$$$anonfun$1$$anonfun$1(EventSourcedBehaviorLoggingSpec.scala:87)
[10-08 08:24:16.857] [info]   at org.scalatest.Transformer.apply$$anonfun$1(Transformer.scala:22)
[10-08 08:24:16.857] [info]   at org.scalatest.OutcomeOf.outcomeOf(OutcomeOf.scala:85)
[10-08 08:24:16.857] [info]   at org.scalatest.OutcomeOf.outcomeOf$(OutcomeOf.scala:31)
[10-08 08:24:16.858] [info]   at org.scalatest.OutcomeOf$.outcomeOf(OutcomeOf.scala:104)
[10-08 08:24:16.858] [info]   at org.scalatest.Transformer.apply(Transformer.scala:22)
[10-08 08:24:16.858] [info]   at org.scalatest.Transformer.apply(Transformer.scala:21)
[10-08 08:24:16.858] [info]   at org.scalatest.wordspec.AnyWordSpecLike$$anon$3.apply(AnyWordSpecLike.scala:1118)
[10-08 08:24:16.858] [info]   at org.apache.pekko.actor.testkit.typed.scaladsl.LogCapturing.withFixture(LogCapturing.scala:79)
[10-08 08:24:16.858] [info]   at org.apache.pekko.actor.testkit.typed.scaladsl.LogCapturing.withFixture$(LogCapturing.scala:42)
[10-08 08:24:16.858] [info]   at org.apache.pekko.persistence.typed.EventSourcedBehaviorLoggingSpec.withFixture(EventSourcedBehaviorLoggingSpec.scala:64)
[10-08 08:24:16.858] [info]   at org.scalatest.wordspec.AnyWordSpecLike.invokeWithFixture$1(AnyWordSpecLike.scala:1124)
[10-08 08:24:16.858] [info]   at org.scalatest.wordspec.AnyWordSpecLike.runTest$$anonfun$1(AnyWordSpecLike.scala:1128)
[10-08 08:24:16.859] [info]   at org.scalatest.SuperEngine.runTestImpl(Engine.scala:306)
[10-08 08:24:16.859] [info]   at org.scalatest.wordspec.AnyWordSpecLike.runTest(AnyWordSpecLike.scala:1128)
[10-08 08:24:16.859] [info]   at org.scalatest.wordspec.AnyWordSpecLike.runTest$(AnyWordSpecLike.scala:44)
[10-08 08:24:16.859] [info]   at org.apache.pekko.persistence.typed.EventSourcedBehaviorLoggingSpec.runTest(EventSourcedBehaviorLoggingSpec.scala:64)
[10-08 08:24:16.859] [info]   at org.scalatest.wordspec.AnyWordSpecLike.runTests$$anonfun$1(AnyWordSpecLike.scala:1187)
[10-08 08:24:16.859] [info]   at org.scalatest.SuperEngine.traverseSubNodes$1$$anonfun$1(Engine.scala:413)
[10-08 08:24:16.859] [info]   at scala.runtime.function.JProcedure1.apply(JProcedure1.java:15)
[10-08 08:24:16.859] [info]   at scala.runtime.function.JProcedure1.apply(JProcedure1.java:10)
[10-08 08:24:16.859] [info]   at scala.collection.immutable.List.foreach(List.scala:334)
[10-08 08:24:16.859] [info]   at org.scalatest.SuperEngine.traverseSubNodes$1(Engine.scala:429)
[10-08 08:24:16.860] [info]   at org.scalatest.SuperEngine.runTestsInBranch(Engine.scala:390)
[10-08 08:24:16.860] [info]   at org.scalatest.SuperEngine.traverseSubNodes$1$$anonfun$1(Engine.scala:427)
[10-08 08:24:16.860] [info]   at scala.runtime.function.JProcedure1.apply(JProcedure1.java:15)
[10-08 08:24:16.860] [info]   at scala.runtime.function.JProcedure1.apply(JProcedure1.java:10)
[10-08 08:24:16.860] [info]   at scala.collection.immutable.List.foreach(List.scala:334)
[10-08 08:24:16.860] [info]   at org.scalatest.SuperEngine.traverseSubNodes$1(Engine.scala:429)
[10-08 08:24:16.860] [info]   at org.scalatest.SuperEngine.runTestsInBranch(Engine.scala:396)
[10-08 08:24:16.860] [info]   at org.scalatest.SuperEngine.runTestsImpl(Engine.scala:475)
[10-08 08:24:16.860] [info]   at org.scalatest.wordspec.AnyWordSpecLike.runTests(AnyWordSpecLike.scala:1187)
[10-08 08:24:16.860] [info]   at org.scalatest.wordspec.AnyWordSpecLike.runTests$(AnyWordSpecLike.scala:44)
[10-08 08:24:16.860] [info]   at org.apache.pekko.persistence.typed.EventSourcedBehaviorLoggingSpec.runTests(EventSourcedBehaviorLoggingSpec.scala:64)
[10-08 08:24:16.860] [info]   at org.scalatest.Suite.run(Suite.scala:1114)
[10-08 08:24:16.861] [info]   at org.scalatest.Suite.run$(Suite.scala:564)
[10-08 08:24:16.861] [info]   at org.apache.pekko.actor.testkit.typed.scaladsl.ScalaTestWithActorTestKit.org$scalatest$BeforeAndAfterAll$$super$run(ScalaTestWithActorTestKit.scala:41)
[10-08 08:24:16.861] [info]   at org.scalatest.BeforeAndAfterAll.liftedTree1$1(BeforeAndAfterAll.scala:213)
[10-08 08:24:16.861] [info]   at org.scalatest.BeforeAndAfterAll.run(BeforeAndAfterAll.scala:217)
[10-08 08:24:16.861] [info]   at org.scalatest.BeforeAndAfterAll.run$(BeforeAndAfterAll.scala:135)
[10-08 08:24:16.861] [info]   at org.apache.pekko.persistence.typed.EventSourcedBehaviorLoggingSpec.org$scalatest$wordspec$AnyWordSpecLike$$super$run(EventSourcedBehaviorLoggingSpec.scala:64)
[10-08 08:24:16.861] [info]   at org.scalatest.wordspec.AnyWordSpecLike.run$$anonfun$1(AnyWordSpecLike.scala:1232)
[10-08 08:24:16.861] [info]   at org.scalatest.SuperEngine.runImpl(Engine.scala:535)
[10-08 08:24:16.861] [info]   at org.scalatest.wordspec.AnyWordSpecLike.run(AnyWordSpecLike.scala:1232)
[10-08 08:24:16.861] [info]   at org.scalatest.wordspec.AnyWordSpecLike.run$(AnyWordSpecLike.scala:44)
[10-08 08:24:16.861] [info]   at org.apache.pekko.persistence.typed.EventSourcedBehaviorLoggingSpec.run(EventSourcedBehaviorLoggingSpec.scala:64)
[10-08 08:24:16.861] [info]   at org.scalatest.tools.Framework.org$scalatest$tools$Framework$$runSuite(Framework.scala:321)
[10-08 08:24:16.861] [info]   at org.scalatest.tools.Framework$ScalaTestTask.execute(Framework.scala:517)
[10-08 08:24:16.861] [info]   at sbt.ForkMain$Run.lambda$runTest$1(ForkMain.java:414)
[10-08 08:24:16.861] [info]   at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:317)
[10-08 08:24:16.862] [info]   at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
[10-08 08:24:16.862] [info]   at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
[10-08 08:24:16.862] [info]   at java.base/java.lang.Thread.run(Thread.java:1583)
raboof commented 3 weeks ago

likely caused by #1506, having a look.

This is about EventSourcedBehaviorLoggingInternalLoggerSpec and EventSourcedBehaviorLoggingContextLoggerSpec on JDK21.