diff --git a/akka-actor-tests/src/test/scala/akka/actor/actor/FSMActorSpec.scala b/akka-actor-tests/src/test/scala/akka/actor/actor/FSMActorSpec.scala index d0610d16e9..2eda6ade56 100644 --- a/akka-actor-tests/src/test/scala/akka/actor/actor/FSMActorSpec.scala +++ b/akka-actor-tests/src/test/scala/akka/actor/actor/FSMActorSpec.scala @@ -4,7 +4,7 @@ package akka.actor -import org.scalatest.WordSpec +import org.scalatest.{ WordSpec, BeforeAndAfterAll, BeforeAndAfterEach } import org.scalatest.matchers.MustMatchers import akka.testkit._ @@ -97,9 +97,27 @@ object FSMActorSpec { case class CodeState(soFar: String, code: String) } -class FSMActorSpec extends WordSpec with MustMatchers with TestKit { +class FSMActorSpec extends WordSpec with MustMatchers with TestKit with BeforeAndAfterAll with BeforeAndAfterEach { import FSMActorSpec._ + val eh_level = EventHandler.level + + override def afterEach { + EventHandler.level = eh_level + } + + override def beforeAll { + val f = FSM.getClass.getDeclaredField("debugEvent") + f.setAccessible(true) + f.setBoolean(FSM, true) + } + + override def afterAll { + val f = FSM.getClass.getDeclaredField("debugEvent") + f.setAccessible(true) + f.setBoolean(FSM, false) + } + "An FSM Actor" must { "unlock the lock" in { @@ -162,7 +180,7 @@ class FSMActorSpec extends WordSpec with MustMatchers with TestKit { }) EventHandler.addListener(logger) fsm ! "go" - expectMsgPF() { + expectMsgPF(1 second) { case EventHandler.Error(_: EventHandler.EventHandlerException, `fsm`, "Next state 2 does not exist") ⇒ true } EventHandler.removeListener(logger) @@ -178,7 +196,42 @@ class FSMActorSpec extends WordSpec with MustMatchers with TestKit { } val ref = Actor.actorOf(fsm).start() ref.stop() - expectMsg(fsm.StopEvent(Shutdown, 1, null)) + expectMsg(1 second, fsm.StopEvent(Shutdown, 1, null)) + } + + "log events and transitions if asked to do so" in { + val fsm = Actor.actorOf(new Actor with FSM[Int, Null] { + debug + startWith(1, null) + when(1) { + case Ev("go") ⇒ + setTimer("t", Shutdown, 1.5 seconds, false) + goto(2) + } + when(2) { + case Ev("stop") ⇒ + cancelTimer("t") + stop + } + onTermination { + case StopEvent(r, _, _) ⇒ testActor ! r + } + }).start() + val logger = Actor.actorOf(new Actor { + def receive = { + case x ⇒ testActor forward x + } + }) + EventHandler.addListener(logger) + EventHandler.level = EventHandler.DebugLevel + fsm ! "go" + expectMsg(1 second, EventHandler.Debug(fsm, "processing event go")) + expectMsg(1 second, EventHandler.Debug(fsm, "setting timer 't'/1500 milliseconds: Shutdown")) + expectMsg(1 second, EventHandler.Debug(fsm, "transition 1 -> 2")) + fsm ! "stop" + expectMsg(1 second, EventHandler.Debug(fsm, "processing event stop")) + expectMsg(1 second, EventHandler.Debug(fsm, "canceling timer 't'")) + expectMsg(1 second, Normal) } } diff --git a/akka-actor/src/main/scala/akka/actor/FSM.scala b/akka-actor/src/main/scala/akka/actor/FSM.scala index 1d157c659e..44bd36dedb 100644 --- a/akka-actor/src/main/scala/akka/actor/FSM.scala +++ b/akka-actor/src/main/scala/akka/actor/FSM.scala @@ -5,6 +5,7 @@ package akka.actor import akka.util._ import akka.event.EventHandler +import akka.config.Config.config import scala.collection.mutable import java.util.concurrent.ScheduledFuture @@ -62,6 +63,8 @@ object FSM { * for derived classes. */ implicit def d2od(d: Duration): Option[Duration] = Some(d) + + val debugEvent = config.getBool("akka.actor.debug.fsm", false) } /** @@ -241,6 +244,7 @@ trait FSM[S, D] extends ListenerManagement { timers(name).cancel } val timer = Timer(name, msg, repeat, timerGen.next) + if (doDebug) EventHandler.debug(self, "setting " + (if (repeat) "repeating " else "") + "timer '" + name + "'/" + timeout + ": " + msg) timer.schedule(self, timeout) timers(name) = timer stay @@ -252,6 +256,7 @@ trait FSM[S, D] extends ListenerManagement { */ protected final def cancelTimer(name: String) = { if (timers contains name) { + if (doDebug) EventHandler.debug(self, "canceling timer '" + name + "'") timers(name).cancel timers -= name } @@ -343,6 +348,14 @@ trait FSM[S, D] extends ListenerManagement { */ def stateData: D = currentState.stateData + /** + * Set the debug flag (if enabled in akka.conf "akka.actor.debug.fsm"), which + * means that received events as well as state transitions are logged at + * DEBUG level. Do NOT enable this on actors which take part in event logging + * (i.e. which directly or indirectly receive messages from the EventHandler) + */ + def debug { doDebug = debugEvent } + /* * **************************************************************** * PRIVATE IMPLEMENTATION DETAILS @@ -404,6 +417,9 @@ trait FSM[S, D] extends ListenerManagement { // ListenerManagement shall not start() or stop() listener actors override protected val manageLifeCycleOfListeners = false + // debug messages enabled? + private var doDebug = false + /** * ******************************************* * Main actor receive() method @@ -412,10 +428,12 @@ trait FSM[S, D] extends ListenerManagement { override final protected def receive: Receive = { case TimeoutMarker(gen) ⇒ if (generation == gen) { + if (doDebug) EventHandler.debug(self, "processing StateTimeout") processEvent(StateTimeout) } case t@Timer(name, msg, repeat, generation) ⇒ if ((timers contains name) && (timers(name).generation == generation)) { + if (doDebug) EventHandler.debug(self, "processing timer '" + name + "' sending event " + msg) processEvent(msg) if (!repeat) { timers -= name @@ -438,6 +456,7 @@ trait FSM[S, D] extends ListenerManagement { timeoutFuture = None } generation += 1 + if (doDebug) EventHandler.debug(self, "processing event " + value) processEvent(value) } } @@ -462,6 +481,7 @@ trait FSM[S, D] extends ListenerManagement { terminate(Failure("Next state %s does not exist".format(nextState.stateName))) } else { if (currentState.stateName != nextState.stateName) { + if (doDebug) EventHandler.debug(self, "transition " + currentState.stateName + " -> " + nextState.stateName) handleTransition(currentState.stateName, nextState.stateName) notifyListeners(Transition(self, currentState.stateName, nextState.stateName)) } diff --git a/akka-docs/scala/fsm.rst b/akka-docs/scala/fsm.rst index bdd7499c8a..ceef1b75e1 100644 --- a/akka-docs/scala/fsm.rst +++ b/akka-docs/scala/fsm.rst @@ -283,11 +283,11 @@ Initiating Transitions ---------------------- The result of any :obj:`stateFunction` must be a definition of the next state -unless terminating the FSM, which is described in `Termination`_. The state -definition can either be the current state, as described by the :func:`stay` -directive, or it is a different state as given by :func:`goto(state)`. The -resulting object allows further qualification by way of the modifiers described -in the following: +unless terminating the FSM, which is described in `Termination from Inside`_. +The state definition can either be the current state, as described by the +:func:`stay` directive, or it is a different state as given by +:func:`goto(state)`. The resulting object allows further qualification by way +of the modifiers described in the following: :meth:`forMax(duration)` This modifier sets a state timeout on the next state. This means that a timer @@ -486,6 +486,27 @@ implementation by the :class:`FSM` trait is to execute the :meth:`onTermination` handler called, do not forget to call ``super.postStop``. +Logging +------- + +The setting ``akka.actor.debug.fsm`` in ``akka.conf`` enables logging of an +event trace by :class:`FSM` instances which turn this feature on:: + + class MyFSM extends Actor with FSM[X, Z] { + debug + ... + } + +This FSM will log at DEBUG level: + + * all processed events, including :obj:`StateTimeout` and scheduled timer + messages + * every setting and cancellation of named timers + * all state transitions + +Life cycle changes and special messages can be logged as described for +:ref:`Actors `. + Examples ======== diff --git a/akka-docs/scala/testing.rst b/akka-docs/scala/testing.rst index d21e1f4c5d..dedde18378 100644 --- a/akka-docs/scala/testing.rst +++ b/akka-docs/scala/testing.rst @@ -624,6 +624,8 @@ has to offer: exception stack traces - Exclusion of certain classes of dead-lock scenarios +.. _actor.logging: + Tracing Actor Invocations =========================