#2368
  • Created on
    2012-08-10 11:49
  • Reported by
    bjorn.antonsson@typesafe.com
  • Status
    Fixed
  • Priority
    Highest (1)
  • Assigned to
    bjorn.antonsson@typesafe.com
  • Milestone
    2.1-RC1
  • Plan Level
    -
  • Due Date
    -

Related Tickets

Add new subtask or bug

SuperVisorHierarchySpec failure on scalable1

The SuperVisorHierarchySpec has started failing on scalable1.

See http://217.142.157.108:8080/job/akka-local/207

Stack trace here:

[info] - survive being stressed *** FAILED *** (26 seconds, 346 milliseconds)
[info] java.lang.AssertionError: assertion failed: expected stressTestSuccessful, found timeout in Stopping
[info] at scala.Predef$.assert(Predef.scala:170)
[info] at akka.testkit.TestKitBase$class.expectMsg_internal(TestKit.scala:283)
[info] at akka.testkit.TestKitBase$class.expectMsg(TestKit.scala:278)
[info] at akka.testkit.TestKit.expectMsg(TestKit.scala:630)
[info] at akka.actor.SupervisorHierarchySpec$$anonfun$9$$anonfun$apply$mcV$sp$10.apply$mcV$sp(SupervisorHierarchySpec.scala:795)
[info] at akka.actor.SupervisorHierarchySpec$$anonfun$9$$anonfun$apply$mcV$sp$10.apply(SupervisorHierarchySpec.scala:776)
[info] at akka.actor.SupervisorHierarchySpec$$anonfun$9$$anonfun$apply$mcV$sp$10.apply(SupervisorHierarchySpec.scala:776)
[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.LinearSeqOptimized$class.foreach(LinearSeqOptimized.scala:59)
[info] at scala.collection.immutable.List.foreach(List.scala:78)
[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.LinearSeqOptimized$class.foreach(LinearSeqOptimized.scala:59)
[info] at scala.collection.immutable.List.foreach(List.scala:78)
[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:62)
[info] at sbt.TestRunner.run(TestFramework.scala:56)
[info] at sbt.TestRunner.runTest$1(TestFramework.scala:76)
[info] at sbt.TestRunner.run(TestFramework.scala:85)
[info] at sbt.TestFramework$$anonfun$6$$anonfun$apply$8$$anonfun$7$$anonfun$apply$9.apply(TestFramework.scala:184)
[info] at sbt.TestFramework$$anonfun$6$$anonfun$apply$8$$anonfun$7$$anonfun$apply$9.apply(TestFramework.scala:184)
[info] at sbt.TestFramework$.sbt$TestFramework$$withContextLoader(TestFramework.scala:196)
[info] at sbt.TestFramework$$anonfun$6$$anonfun$apply$8$$anonfun$7.apply(TestFramework.scala:184)
[info] at sbt.TestFramework$$anonfun$6$$anonfun$apply$8$$anonfun$7.apply(TestFramework.scala:184)
[info] at sbt.Tests$$anonfun$makeSerial$1$$anonfun$apply$8.apply(Tests.scala:115)
[info] at sbt.Tests$$anonfun$makeSerial$1$$anonfun$apply$8.apply(Tests.scala:115)
[info] at scala.collection.TraversableLike$$anonfun$map$1.apply(TraversableLike.scala:194)
[info] at scala.collection.TraversableLike$$anonfun$map$1.apply(TraversableLike.scala:194)
[info] at scala.collection.LinearSeqOptimized$class.foreach(LinearSeqOptimized.scala:59)
[info] at scala.collection.immutable.List.foreach(List.scala:45)
[info] at scala.collection.TraversableLike$class.map(TraversableLike.scala:194)
[info] at scala.collection.immutable.List.map(List.scala:45)
[info] at sbt.Tests$$anonfun$makeSerial$1.apply(Tests.scala:115)
[info] at sbt.Tests$$anonfun$makeSerial$1.apply(Tests.scala:115)
[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:67)
[info] at sbt.Execute$$anonfun$submit$1$$anonfun$apply$1.apply(Execute.scala:221)
[info] at sbt.Execute$$anonfun$submit$1$$anonfun$apply$1.apply(Execute.scala:221)
[info] at sbt.ErrorHandling$.wideConvert(ErrorHandling.scala:18)
[info] at sbt.Execute.work(Execute.scala:227)
[info] at sbt.Execute$$anonfun$submit$1.apply(Execute.scala:221)
[info] at sbt.Execute$$anonfun$submit$1.apply(Execute.scala:221)
[info] at sbt.CompletionService$$anon$1$$anon$2.call(CompletionService.scala:26)
[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)
User picture
  on 2012-08-13 19:26 *
By viktorklang
Priority changed from High (2) to Highest (1)
User picture
  on 2012-08-13 19:26 *
By viktorklang
Priority changed from Highest (1) to High (2)
User picture
  on 2012-08-18 13:22 *
By rkuhn
I added some more debug tracing for the case exhibited here, and until that says something different I'm going to assume that it is just a timeout problem.
User picture
  on 2012-08-30 16:58 *
By viktorklang
Priority changed from High (2) to Highest (1)
User picture
  on 2012-09-07 10:03 *
By bjorn.antonsson@typesafe.com
Attachment SHS_Failure_akka-local-jdk7_66.txt added
file:b8PMEK-mir4yXhacwqjQXA
Failure on scalable1 with complete log
User picture
  on 2012-09-07 12:16 *
By bjorn.antonsson@typesafe.com
Status changed from New to Accepted
User picture
  on 2012-09-07 12:52 *
By bjorn.antonsson@typesafe.com
Assigned to set to bjorn.antonsson@typesafe.com
Both failure logs show patterns where it seems like a child has survived its parent (not so nice).

The only way that a log can survive a child is if we somehow miss calling preStart for an actor, but call postRestart which pulls out the old log from the stateCache.

Both failures also happen when there is a failure during instance creation involved.
User picture
  on 2012-09-07 14:28 *
By bjorn.antonsson@typesafe.com
So in both cases the supervisor strategy is returning Resume for a child that just has failed during instance creation as part of a parent restart.

What are the semantics of that?
User picture
  on 2012-09-08 13:20 *
By viktorklang
Is this fixed yet? We need this done asap, we have plenty of other things to also complete prior to RC1.
User picture
  on 2012-09-09 07:06 *
By bjorn.antonsson@typesafe.com
No, this isn't fixed yet. And yes it's what I'm spending my time on.

Will attach two more logs with more debug information (the number after the actor path is the identity hashcode, as close to an address you'll get). They show the pattern of calling postRestart on a new instance after we failed to create another instance, which will pull out the old logs and let it survive.

Why we do that I'll dig into on monday.

Now back to wekeend.
User picture
  on 2012-09-09 07:08 *
By bjorn.antonsson@typesafe.com
Attachment SHS_Failureban_4.txt.zip added
file:bNptn8-JWr4Bf5acwqjQYw
User picture
  on 2012-09-09 07:08 *
By bjorn.antonsson@typesafe.com
Attachment SHS_Failureban_5.txt added
file:bNCI1C-JWr4Bf5acwqjQYw
User picture
  on 2012-09-09 07:09 *
By bjorn.antonsson@typesafe.com
Attachment SHS_Failureban_5.txt deleted
User picture
  on 2012-09-09 07:09 *
By bjorn.antonsson@typesafe.com
Attachment SHS_Failureban_5.txt.zip added
file:ccBH0a-JWr4A1TacwqjQXA
User picture
  on 2012-09-10 09:30 *
By bjorn.antonsson@typesafe.com
So the problem is that the child is about to be recreated and fails in the constructor. The supervisor strategy says Resume, and the code converts this into a Restart. This isn't ok if it's during creation.

Now to dive into ActorCell and FaultHandling.
User picture
  on 2012-09-10 10:36 *
By viktorklang
Milestone changed from Mingus to 2.1-RC1
Updating tickets (#2349, #2368, #2378, #2383, #2387, #2401, #2402, #2426, #2428, #2431, #2462, #2472, #2483, #2484)
User picture
  on 2012-09-11 11:53 *
By rkuhn
after some fixes by Björn I was lucky enough to observe this:
(1347356150073064000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/2/2/1/1],1747003858,re-applying Failure(Resume,false,0,0,0,1,0) to Actor[akka://SupervisorHierarchySpec/user/stressTest/head/2/2/1/1/1])
(1347356150073133000,Actor[akka://SupervisorHierarchySpec/user/stressTest],0,Ready(Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/1/1]))
(1347356150073143000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/2/2/1/1/1],1795705297,started)
(1347356150073158000,Actor[akka://SupervisorHierarchySpec/user/stressTest],0,Ready(Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/1/2]))
(1347356150073181000,Actor[akka://SupervisorHierarchySpec/user/stressTest],0,Ready(Actor[akka://SupervisorHierarchySpec/user/stressTest/head/2/1/1/5/3]))
(1347356150073203000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/2/2/1/1/1/1],620813560,started)
(1347356150073210000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/2/2/1/1/1],1795705297,resumed 0)
(1347356150073221000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/2/2/1/1/1/1],620813560,suspended 0)

After this “head/2/2/1/1/1/1” remains at suspend count +1, which ultimately fails the test because it does not answer its “ping”. So the question is: the parent is resumed after having failed in the constructor one, why is the child then suspended as a response and not subsequently resumed?
User picture
  on 2012-09-11 14:15 *
By bjorn.antonsson@typesafe.com
Some more log snippets:

(1347361134085634000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1],208268452,Failed in constructor)
(1347361134085805000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head],1867246260,re-applying Failure(Restart,false,0,2,0,2,1) to Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1])
(1347361134086157000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1],1108275911,Failed in constructor)
(1347361134086272000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head],1867246260,re-applying Failure(Restart,false,0,2,0,1,1) to Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1])
(1347361134086412000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1],1667565746,restarted 0 b3d26621-c85f-47f1-b1f0-f1004f978493akka.actor.PostRestartException: exception post restart (class akka.actor.PostRestartException))
(1347361134086745000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/2/1/4/1/1],881318729,applying Failure(Resume,false,0,0,1,0,0) to Actor[akka://SupervisorHierarchySpec/user/stressTest/head/2/1/4/1/1/1])
(1347361134086761000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1],2115899672,started)
(1347361134086881000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/1],1744076631,started)
(1347361134087104000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/2],1691639314,started)
(1347361134087396000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/3],845947765,started)
(1347361134087925000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/3/2],1917176726,started)
(1347361134090084000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/1/4],947619468,started)
(1347361134090273000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/3/2/1],1765497636,started)
(1347361134091430000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/1/5],364052518,started)
(1347361134091760000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/1/6],875666299,started)
(1347361134092425000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/2/1],261933875,started)
(1347361134092696000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/3/2/2],1196725181,Failed in constructor)
(1347361134092928000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/3/2/3],695720868,started)
(1347361134095204000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/2/3],1702621936,started)
(1347361134096024000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/3/2/3/4],1365384137,started)
(1347361134096217000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/2/1/4/1],1915372237,ping)
(1347361134096256000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/2/1/2/4/1/1],1895856229,ping)
(1347361134097395000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/3/2/1/2],637387237,started)
(1347361134098624000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/1/4/1],526042303,started)
(1347361134098920000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/3/2/1/2/1],13652120,started)
(1347361134106471000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/1/4/1/1],186516361,started)
(1347361134108325000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/1/4/1/1/1],1017872708,started)
(1347361134109185000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/2/3/3],1939305942,started)
(1347361134110843000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/2/1/5/1/5/2],2033600008,ping)
(1347361134114438000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/1/5/3],233245754,started)
(1347361134114723000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/2/3/3/1],1809650967,started)
(1347361134114900000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/1/5/3/1],1610500148,started)
(1347361134115293000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/2/1/5/1/5],462909977,ping)
(1347361134115379000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/1/6/2],291482190,started)
(1347361134115423000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/2/3/3/1/1],530968523,started)
(1347361134115508000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/2],1058252165,ping)
(1347361134115577000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/1/6/4],1925940452,started)
(1347361134116256000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/1/6/2/1],69545182,started)
(1347361134116346000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/1/6/4/1],893984425,started)
(1347361134116779000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/3/2],1917176726,ping)
(1347361134116810000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/2/1/4],595622725,ping)
(1347361134116828000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/1/6],875666299,ping)
(1347361134116955000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/3/2],1917176726,re-applying Failure(Resume,false,0,0,0,1,0) to Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/3/2/2])
(1347361134116982000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/2/1/5],1748707460,ping)
(1347361134117191000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/2/1/4/1/1],881318729,ping)
(1347361134117240000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/3/2/2],1667328593,started)
(1347361134117321000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/3/2/2],1667328593,resumed 0)
(1347361134117348000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/3/2/2/2],496235052,started)
(1347361134117385000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/3/2/2/2],496235052,suspended 0)
(1347361134117406000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/3/2/2/3],1543517663,started)
(1347361134117437000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/3/2/2/3],1543517663,suspended 0)
(1347361134117507000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/3/2/2/2/1],753614434,started)
(1347361134117548000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/3/2/2/2/1],753614434,suspended 0)
(1347361134117885000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/3/2/2/3/1],1634501641,started)
(1347361134117935000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/3/2/2/3/1],1634501641,suspended 0)
(1347361134118038000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/3/2/2/2/1/1],458267863,started)
(1347361134118088000,Actor[akka://SupervisorHierarchySpec/user/stressTest/head/1/1/3/2/2/2/1/1],458267863,suspended 0)


and these are the pingchildren
pingChildren:
akka://SupervisorHierarchySpec/user/stressTest/head/1/1/3/2/2/2
akka://SupervisorHierarchySpec/user/stressTest/head/1/1/3/2/2/2/1
akka://SupervisorHierarchySpec/user/stressTest/head/1/1/3/2/2/2/1/1
akka://SupervisorHierarchySpec/user/stressTest/head/1/1/3/2/2/3
akka://SupervisorHierarchySpec/user/stressTest/head/1/1/3/2/2/3/1
User picture
  on 2012-09-12 11:07 *
By bjorn.antonsson@typesafe.com
Status changed from Accepted to Fixed