Child actor Termination validation

Question

I have following actor hierarchy parent -> child -> worker where child's life scope is tight to request - when request is completed child actor should be terminated. That I wanted to verify as a part of the test. I created StepParent as a for testing purposes as I want to validate the response for the given request which forwards to msg to testprobe.

class StepParent(child: Props, name: String, probe: ActorRef) extends Actor with ActorLogging {
  context.watch(context.actorOf(props = child, name = name))

  override def receive: Actor.Receive = {
    case msg: PersistImages => context.children.foreach(child => child.tell(msg, sender))
    case msg =>
      log.debug(s"Msg forwarded to probe $msg")
      probe.tell(msg, sender)
  }
}

My test looks as follows:

class ImagesControllerActorTest extends TestKit(ActorSystem("testsystem"))
with WordSpecLike with MustMatchers with StopSystemAfterAll {

  val id = "456"

  "ControllerActor" must {
    "distribute a work to dedicated dedicated workers and combine back results and then terminate" in {

      val p = TestProbe()
      val ica = system.actorOf(Props(classOf[StepParent], createActorWithMockedWorkers(id, p.ref), "ControllerActor", p.ref), "parent")

      p.send(ica, PersistImages(Set(new URL("http://success"), new URL("http://fail"))))

      p.expectMsgPF(2 seconds)(validMsgPersistImageActor)
      p.expectMsgPF(2 seconds)(validMsgPersistImageActor)

      p.expectMsg(2 seconds, ImagesProcessed(id, Set(new URI("file:/"))))

      p.expectMsg(4 seconds, Terminated)
    }
  }

My test is failing because of the last check for expected message:

assertion failed: timeout (4 seconds) during expectMsg while waiting for Terminated
java.lang.AssertionError: assertion failed: timeout (4 seconds) during expectMsg while waiting for Terminated
    at scala.Predef$.assert(Predef.scala:179)
    at akka.testkit.TestKitBase$class.expectMsg_internal(TestKit.scala:338)
...

According to the detailed log Terminated msg is forwarded as well(as per last line)

2015-01-11 17:41:10,386 [WARN ] [testsystem-akka.actor.default-dispatcher-5] akka.tcp://testsystem@127.0.0.1:2555/user/parent/ControllerActor - id: 456 image url: http://fail FAILED
2015-01-11 17:41:10,386 [INFO ] [testsystem-akka.actor.default-dispatcher-5] akka.tcp://testsystem@127.0.0.1:2555/user/parent/ControllerActor - id: 456 Processing completed with 1 downloded and 1 failed
2015-01-11 17:41:10,387 [DEBUG] [testsystem-akka.actor.default-dispatcher-4] akka.tcp://testsystem@127.0.0.1:2555/user/parent - Msg forwarded to probe ImagesProcessed(456,Set(file:/))
2015-01-11 17:41:10,392 [DEBUG] [testsystem-akka.actor.default-dispatcher-2] akka://testsystem/user/parent/ControllerActor/$b - stopped
2015-01-11 17:41:10,394 [DEBUG] [testsystem-akka.actor.default-dispatcher-5] akka://testsystem/user/parent/ControllerActor - stopping
2015-01-11 17:41:10,396 [INFO ] [testsystem-akka.actor.default-dispatcher-4] akka://testsystem/user/parent/ControllerActor/$b - Message [akka.dispatch.sysmsg.Terminate] from Actor[akka://testsystem/user/parent/ImagesControllerActor/$b#-426862126] to Actor[akka://testsystem/user/parent/ControllerActor/$b#-426862126] was not delivered. [1] dead letters encountered. This logging can be turned off or adjusted with configuration settings 'akka.log-dead-letters' and 'akka.log-dead-letters-during-shutdown'.
2015-01-11 17:41:10,396 [INFO ] [testsystem-akka.actor.default-dispatcher-2] akka://testsystem/user/parent/ControllerActor/$a - Message [akka.dispatch.sysmsg.Terminate] from Actor[akka://testsystem/user/parent/ControllerActor/$a#1067345522] to Actor[akka://testsystem/user/parent/ControllerActor/$a#1067345522] was not delivered. [2] dead letters encountered. This logging can be turned off or adjusted with configuration settings 'akka.log-dead-letters' and 'akka.log-dead-letters-during-shutdown'.
2015-01-11 17:41:10,398 [DEBUG] [testsystem-akka.actor.default-dispatcher-2] akka://testsystem/user/parent/ControllerActor - stopped
2015-01-11 17:41:10,399 [DEBUG] [testsystem-akka.actor.default-dispatcher-16] akka://testsystem/user/parent/ControllerActor/$a - stopped
2015-01-11 17:41:10,399 [DEBUG] [testsystem-akka.actor.default-dispatcher-5] akka://testsystem/user/parent - received AutoReceiveMessage Envelope(Terminated(Actor[akka://testsystem/user/parent/ControllerActor#-770422232]),Actor[akka://testsystem/user/parent/ControllerActor#-770422232])
**2015-01-11 17:41:10,400 [DEBUG] [testsystem-akka.actor.default-dispatcher-5] akka.tcp://testsystem@127.0.0.1:2555/user/parent - Msg forwarded to probe Terminated(Actor[akka://testsystem/user/parent/ControllerActor#-770422232])**
...

I do not really understand why last expectedMsg check doesn't work here since the message is forwarded as usual. Is there any special handling for Auto recieved messages?

Can someone pleas bring some shed into this?

Thx

UPDATE: Tried to solve that as suggested - remove wrapper Envelope as follows:

class StepParent(child: Props, name: String, probe: ActorRef) extends Actor with ActorLogging {
  context.watch(context.actorOf(props = child, name = name))

  override def receive: Actor.Receive = {
    case msg: PersistImages => context.children.foreach(child => child.tell(msg, sender))
    case mssg: Envelope =>
      log.debug(s"Envelope msg forwarded to probe $mssg")
      probe.tell(mssg.message, sender)
    case msg =>
      log.debug(s"Msg forwarded to probe $msg")
      probe.tell(msg, sender)
  }
}

2015-01-11 23:52:16,352 [DEBUG] [testsystem-akka.actor.default-dispatcher-4] akka://testsystem/user/parent/ControllerActor - stopping
2015-01-11 23:52:16,354 [DEBUG] [testsystem-akka.actor.default-dispatcher-4] akka://testsystem/user/parent/ControllerActor - stopped
2015-01-11 23:52:16,358 [DEBUG] [testsystem-akka.actor.default-dispatcher-16] akka.tcp://testsystem@127.0.0.1:2555/user/parent - Msg forwarded to probe ImagesProcessed(456,Set(file:/))
2015-01-11 23:52:16,358 [DEBUG] [testsystem-akka.actor.default-dispatcher-16] akka://testsystem/user/parent - received AutoReceiveMessage Envelope(Terminated(Actor[akka://testsystem/user/parent/ControllerActor#-1965336139]),Actor[akka://testsystem/user/parent/ControllerActor#-1965336139])
2015-01-11 23:52:16,360 [DEBUG] [testsystem-akka.actor.default-dispatcher-16] akka.tcp://testsystem@127.0.0.1:2555/user/parent - Msg forwarded to probe Terminated(Actor[akka://testsystem/user/parent/ControllerActor#-1965336139])
2015-01-11 23:52:16,365 [DEBUG] [testsystem-akka.actor.default-dispatcher-16] akka://testsystem/system/testActor2 - received AutoReceiveMessage Envelope(Terminated(Actor[akka://testsystem/user/parent/ControllerActor#-1965336139]),Actor[akka://testsystem/user/parent/ControllerActor#-1965336139])

It is still failing and seems that something suspicious going on here:

2015-01-11 23:52:16,360 [DEBUG] [testsystem-akka.actor.default-dispatcher-16] akka.tcp://testsystem@127.0.0.1:2555/user/parent - Msg forwarded to probe Terminated(Actor[akka://testsystem/user/parent/ImagesControllerActor#-1965336139])

That is not correct message from StepParent but it gets somehow extracted.

I am not sure if `sender` is always in scope at the moment when you are using it in `context.children.foreach(child => child.tell(msg, sender))`. You can try to create a reference for it in the actor, like: `case msg: PersistImages => val current_sender = sender; context.children.foreach(child => child.tell(msg, current_sender))` — Ashalynd, Jan 11 '15 at 17:36
@Ashalynd Good suggestion but that didn't help either. More over previous message is sent exactly by the same path and successfully. — jaksky, Jan 11 '15 at 17:50

Jean Logeart · Answer 1 · 2015-01-11T18:34:48.827

StepParent actually receives an Envelope of the Terminated message.

You can see it from the log:

2015-01-11 17:41:10,399 [DEBUG] [testsystem-akka.actor.default-dispatcher-5] akka://testsystem/user/parent - received AutoReceiveMessage Envelope(Terminated(Actor[akka://testsystem/user/parent/ControllerActor#-770422232]),Actor[akka://testsystem/user/parent/ControllerActor#-770422232])

Yet, the Envelope message is then printed in your logs as if it was a Terminated while it is not.

The message is an Envelope in order to contain the sender metadata from the automatically sent message even though in this case, a Terminated message already contains the sender information.

So for your test to pass, you can do something like:

override def receive: Actor.Receive = {
  case msg: PersistImages => context.children.foreach(child => child.tell(msg, sender))
  case msg: Envelope =>
    log.debug(s"Envelope msg forwarded to probe $msg")
    probe.tell(msg.message, sender)
  case msg =>
    log.debug(s"Msg forwarded to probe $msg")
    probe.tell(msg, sender)
}

Seems that something suspicious going here because removing just wrapping object Envelope didn't help — jaksky, Jan 11 '15 at 23:03

cmbaxter · Answer 2 · 2015-01-12T15:13:49.003

Your assertion for termination is not correct. As it currently is coded:

p.expectMsg(4 seconds, Terminated)

you are basically saying that you are expecting a message that is the Terminated type itself and not an instance of the Terminated case class. You should change the assertion to:

p.expectMsg(4 seconds, Terminated(refToBeTerminated))

or better yet:

p.expectTerminated(refToBeTerminated, 4 seconds)

where refToBeTerminated is the ActorRef that you are expecting to be terminated. I'm not sure if this is your only issue, but it is an issue for sure.

EDIT

Of course, if all you care about is that you got any kind of Terminate then you have multiple options to test that. You could try:

p.expectMsgType[Terminated](4 seconds)

or:

p.expectMsgClass(4 seconds, classOf[Terminated])

or even:

p.expectMsgPF(4 seconds){case t:Terminated => }

I hoped that this way I will avoid a need to spcify ActorRef of child which I do not have and it is not easily externally observable. I am not particularily interested in the comtent of Terminated — jaksky, Jan 12 '15 at 14:44
Unfortunately non of those worked even those I saw they were received via auto recieve logging — jaksky, Jan 14 '15 at 09:47

score 0 · Accepted Answer · answered Jan 14 '15 at 09:53

Unfortunately non of the proposed solution worked even though I was also convinced they could work and from auto receive logging the Terminated message were passed the only way I got this thing working is a kind of "ugly" solution by translated Terminated message to something else:

class StepParent(child: Props, name: String, probe: ActorRef) extends Actor with ActorLogging {
  context.watch(context.actorOf(props = child, name = name))

  override def receive: Actor.Receive = {
    case msg: PersistImages => context.children.foreach(child => child.tell(msg, sender))
    case msg: Terminated =>
      log.debug("Parent: Terminated recieved")
      probe.tell("controller terminated",sender)
    case msg =>
      log.debug(s"Msg forwarded to probe $msg")
      probe.tell(msg, sender)
  }
}

And the assertion logic works fine as:

p.expectMsg(4 seconds,"controller terminated")

Not sure what was going on as it seems that Terminated msg cannot be simply forwarded even though it was obviously received.

Child actor Termination validation

3 Answers3