ActorSystemSpec failed
ActorSystemSpec failed at http://scalable1:8080/job/akka-nightly/209/
[info] ActorSystemSpec:
[info] An ActorSystem
[info] - must reject invalid names (3 milliseconds)
[info] - must allow valid names (5 milliseconds)
[info] - must support extensions (0 milliseconds)
[info] - must run termination callbacks in order (74 milliseconds)
[info] - must awaitTermination after termination callbacks (362 milliseconds)
[info] - must return isTerminated status correctly (7 milliseconds)
[info] - must throw RejectedExecutionException when shutdown (8 milliseconds)
[info] - must reliably create waves of actors (1 second, 991 milliseconds)
[info] - must reliable deny creation of actors while shutting down (711 milliseconds)
[info] - shut down when /user fails *** FAILED *** (3 seconds, 43 milliseconds)
[info] java.lang.AssertionError: assertion failed: timeout 3 seconds expired
[info] at scala.Predef$.assert(Predef.scala:173)
[info] at akka.testkit.TestKitBase$class.poll$1(TestKit.scala:213)
[info] at akka.testkit.TestKitBase$class.awaitCond(TestKit.scala:219)
[info] at akka.testkit.TestKit.awaitCond(TestKit.scala:630)
[info] at akka.actor.ActorSystemSpec$$anonfun$1$$anonfun$apply$mcV$sp$16$$anonfun$apply$mcV$sp$17.apply$mcV$sp(ActorSystemSpec.scala:199)
[info] at akka.actor.ActorSystemSpec$$anonfun$1$$anonfun$apply$mcV$sp$16$$anonfun$apply$mcV$sp$17.apply(ActorSystemSpec.scala:197)
[info] at akka.actor.ActorSystemSpec$$anonfun$1$$anonfun$apply$mcV$sp$16$$anonfun$apply$mcV$sp$17.apply(ActorSystemSpec.scala:197)
[info] at akka.testkit.EventFilter.intercept(TestEventListener.scala:100)
[info] at akka.actor.ActorSystemSpec$$anonfun$1$$anonfun$apply$mcV$sp$16.apply$mcV$sp(ActorSystemSpec.scala:197)
[info] at akka.actor.ActorSystemSpec$$anonfun$1$$anonfun$apply$mcV$sp$16.apply(ActorSystemSpec.scala:195)
[info] at akka.actor.ActorSystemSpec$$anonfun$1$$anonfun$apply$mcV$sp$16.apply(ActorSystemSpec.scala:195)
[info] at org.scalatest.WordSpec$$anon$2.apply(WordSpec.scala:2179)
[info] at org.scalatest.Suite$class.withFixture(Suite.scala:1974)
[info] at akka.testkit.AkkaSpec.withFixture(AkkaSpec.scala:58)
[info] at org.scalatest.WordSpec$class.invokeWithFixture$1(WordSpec.scala:2176)
[info] at org.scalatest.WordSpec$$anonfun$runTest$1.apply(WordSpec.scala:2185)
[info] at org.scalatest.WordSpec$$anonfun$runTest$1.apply(WordSpec.scala:2185)
[info] at org.scalatest.SuperEngine.runTestImpl(Engine.scala:198)
[info] at org.scalatest.WordSpec$class.runTest(WordSpec.scala:2185)
[info] at akka.testkit.AkkaSpec.runTest(AkkaSpec.scala:58)
[info] at org.scalatest.WordSpec$$anonfun$runTests$1.apply(WordSpec.scala:2250)
[info] at org.scalatest.WordSpec$$anonfun$runTests$1.apply(WordSpec.scala:2250)
[info] at org.scalatest.SuperEngine$$anonfun$org$scalatest$SuperEngine$$runTestsInBranch$1.apply(Engine.scala:260)
[info] at org.scalatest.SuperEngine$$anonfun$org$scalatest$SuperEngine$$runTestsInBranch$1.apply(Engine.scala:249)
[info] at scala.collection.immutable.List.foreach(List.scala:309)
[info] at org.scalatest.SuperEngine.org$scalatest$SuperEngine$$runTestsInBranch(Engine.scala:249)
[info] at org.scalatest.SuperEngine$$anonfun$org$scalatest$SuperEngine$$runTestsInBranch$1.apply(Engine.scala:265)
[info] at org.scalatest.SuperEngine$$anonfun$org$scalatest$SuperEngine$$runTestsInBranch$1.apply(Engine.scala:249)
[info] at scala.collection.immutable.List.foreach(List.scala:309)
[info] at org.scalatest.SuperEngine.org$scalatest$SuperEngine$$runTestsInBranch(Engine.scala:249)
[info] at org.scalatest.SuperEngine.runTestsImpl(Engine.scala:326)
[info] at org.scalatest.WordSpec$class.runTests(WordSpec.scala:2250)
[info] at akka.testkit.AkkaSpec.runTests(AkkaSpec.scala:58)
[info] at org.scalatest.Suite$class.run(Suite.scala:2303)
[info] at akka.testkit.AkkaSpec.org$scalatest$WordSpec$$super$run(AkkaSpec.scala:58)
[info] at org.scalatest.WordSpec$$anonfun$run$1.apply(WordSpec.scala:2297)
[info] at org.scalatest.WordSpec$$anonfun$run$1.apply(WordSpec.scala:2297)
[info] at org.scalatest.SuperEngine.runImpl(Engine.scala:362)
[info] at org.scalatest.WordSpec$class.run(WordSpec.scala:2297)
[info] at akka.testkit.AkkaSpec.org$scalatest$BeforeAndAfterAll$$super$run(AkkaSpec.scala:58)
[info] at org.scalatest.BeforeAndAfterAll$class.run(BeforeAndAfterAll.scala:213)
[info] at akka.testkit.AkkaSpec.run(AkkaSpec.scala:58)
[info] at org.scalatest.tools.ScalaTestFramework$ScalaTestRunner.run(ScalaTestFramework.scala:180)
[info] at org.scalatools.testing.Runner2.run(Runner2.java:16)
[info] at sbt.TestRunner.delegateRun(TestFramework.scala:57)
[info] at sbt.TestRunner.run(TestFramework.scala:51)
[info] at sbt.TestRunner.runTest$1(TestFramework.scala:71)
[info] at sbt.TestRunner.run(TestFramework.scala:80)
[info] at sbt.TestFramework$$anonfun$6$$anonfun$apply$8$$anonfun$7$$anonfun$apply$9.apply(TestFramework.scala:178)
[info] at sbt.TestFramework$$anonfun$6$$anonfun$apply$8$$anonfun$7$$anonfun$apply$9.apply(TestFramework.scala:178)
[info] at sbt.TestFramework$.sbt$TestFramework$$withContextLoader(TestFramework.scala:190)
[info] at sbt.TestFramework$$anonfun$6$$anonfun$apply$8$$anonfun$7.apply(TestFramework.scala:178)
[info] at sbt.TestFramework$$anonfun$6$$anonfun$apply$8$$anonfun$7.apply(TestFramework.scala:178)
[info] at sbt.Tests$$anonfun$makeSerial$1$$anonfun$apply$8.apply(Tests.scala:121)
[info] at sbt.Tests$$anonfun$makeSerial$1$$anonfun$apply$8.apply(Tests.scala:121)
[info] at scala.collection.TraversableLike$$anonfun$map$1.apply(TraversableLike.scala:233)
[info] at scala.collection.TraversableLike$$anonfun$map$1.apply(TraversableLike.scala:233)
[info] at scala.collection.LinearSeqOptimized$class.foreach(LinearSeqOptimized.scala:59)
[info] at scala.collection.immutable.List.foreach(List.scala:76)
[info] at scala.collection.TraversableLike$class.map(TraversableLike.scala:233)
[info] at scala.collection.immutable.List.map(List.scala:76)
[info] at sbt.Tests$$anonfun$makeSerial$1.apply(Tests.scala:121)
[info] at sbt.Tests$$anonfun$makeSerial$1.apply(Tests.scala:121)
[info] at sbt.std.Transform$$anon$3$$anonfun$apply$2.apply(System.scala:47)
[info] at sbt.std.Transform$$anon$3$$anonfun$apply$2.apply(System.scala:47)
[info] at sbt.std.Transform$$anon$5.work(System.scala:71)
[info] at sbt.Execute$$anonfun$submit$1$$anonfun$apply$1.apply(Execute.scala:232)
[info] at sbt.Execute$$anonfun$submit$1$$anonfun$apply$1.apply(Execute.scala:232)
[info] at sbt.ErrorHandling$.wideConvert(ErrorHandling.scala:18)
[info] at sbt.Execute.work(Execute.scala:238)
[info] at sbt.Execute$$anonfun$submit$1.apply(Execute.scala:232)
[info] at sbt.Execute$$anonfun$submit$1.apply(Execute.scala:232)
[info] at sbt.ConcurrentRestrictions$$anon$4$$anonfun$1.apply(ConcurrentRestrictions.scala:159)
[info] at sbt.CompletionService$$anon$2.call(CompletionService.scala:30)
[info] at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
[info] at java.util.concurrent.FutureTask.run(FutureTask.java:166)
[info] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
[info] at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
[info] at java.util.concurrent.FutureTask.run(FutureTask.java:166)
[info] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
[info] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
[info] at java.lang.Thread.run(Thread.java:679)
[info] - must allow configuration of guardian supervisor strategy (176 milliseconds)
[info] - must shut down when /user escalates (110 milliseconds)
Leave a comment
on 2012-09-04 07:16 *
By bjorn.antonsson@typesafe.com
Assigned to set to bjorn.antonsson@typesafe.com
on 2012-09-04 10:54 *
By bjorn.antonsson@typesafe.com
(Comment removed)
on 2012-09-04 11:11 *
By bjorn.antonsson@typesafe.com
Damn you Assembla! Why you swallow my comment?
So the failing test only creates an actor system and then kills "/user". This should happen in a couple of 100 millis, and timing out after 3 seconds seems fishy.
Maybe there is some race between the Watch messages sent to the system guardian and root guardian and the Kill message sent to the "/user" during initialization of the actors and switching to real actor cells.
So the failing test only creates an actor system and then kills "/user". This should happen in a couple of 100 millis, and timing out after 3 seconds seems fishy.
Maybe there is some race between the Watch messages sent to the system guardian and root guardian and the Kill message sent to the "/user" during initialization of the actors and switching to real actor cells.
on 2012-09-04 12:13 *
By bjorn.antonsson@typesafe.com
Current findings.
If I turn down the parallelism-min and parallelism-max to 2, then the test fails 1 out of 5 times on my laptop. No matter if I turn up the timeout to 6 seconds.
The ActorSystem tree looks like this.
And a thread dump during the test says that nobody is waiting for somebody else (except for the SBT shell thread that's waiting for the test to finish).
This leads me to think that we somehow miss handling a message.
If I turn down the parallelism-min and parallelism-max to 2, then the test fails 1 out of 5 times on my laptop. No matter if I turn up the timeout to 6 seconds.
The ActorSystem tree looks like this.
-> / LocalActorRefProvider$$anon$1 class akka.actor.LocalActorRefProvider$Guardian status=0 2 children
⌊-> system LocalActorRef class akka.actor.LocalActorRefProvider$Guardian status=0 1 children
| ⌊-> log1-TestEventListener RepointableActorRef class akka.testkit.TestEventListener status=0 no children
⌊-> user LocalActorRef class akka.actor.LocalActorRefProvider$Guardian status=4 no children
And a thread dump during the test says that nobody is waiting for somebody else (except for the SBT shell thread that's waiting for the test to finish).
This leads me to think that we somehow miss handling a message.
on 2012-09-05 10:02 *
By bjorn.antonsson@typesafe.com
So right now the failure is that the ChildRestartStats the are returned for the "/user" actor have the uid set to 0 even though the parent has seen and processed the Supervise message for "/user".
sys are the messages in the system mailbox which happily is empty
mupp are all the Supervise messages that we have received and processed
sys are the messages in the system mailbox which happily is empty
mupp are all the Supervise messages that we have received and processed
DEBUG] [09/05/2012 11:53:35.558] [Stop-akka.actor.default-dispatcher-2] [akka://Stop/] dropping Failed(d52a41b5-a067-4e0c-8c23-47568e910475akka.actor.ActorKilledException: Kill) from old child Actor[akka://Stop/user] (uid=0 != 918989510)
[DEBUG] [09/05/2012 11:53:35.559] [Stop-akka.actor.default-dispatcher-2] [About to dump sys! ]
[DEBUG] [09/05/2012 11:53:35.559] [Stop-akka.actor.default-dispatcher-2] [About to dump mupp! ]
[DEBUG] [09/05/2012 11:53:35.559] [Stop-akka.actor.default-dispatcher-2] [>>> ] Supervise(Actor[akka://Stop/user],918989510)
[DEBUG] [09/05/2012 11:53:35.560] [Stop-akka.actor.default-dispatcher-2] [>>> ] Supervise(Actor[akka://Stop/system],-1736641869)
on 2012-09-05 10:32 *
By bjorn.antonsson@typesafe.com
The ChildRestartStats that we pull out of the ChildrenContainer is not the same instance that we write the uid to during supervise processing.
Shouldn't they be the same?
Shouldn't they be the same?
on 2012-09-05 10:35 *
By bjorn.antonsson@typesafe.com
There is a race in initChild, we read the childrenRefs container twice before we CAS...