September 29, 2014 · akka

Akka Notes - Logging and Testing Actors - 2

In the first two parts (one, two), we briefly talked about Actors and how messaging works. In this part, let's look at fixing up Logging and Testing our TeacherActor.

Recap

This is how our Actor from the previous part looked like :


class TeacherActor extends Actor {

  val quotes = List(
    "Moderation is for cowards",
    "Anything worth doing is worth overdoing",
    "The trouble is you think you have time",
    "You never gonna know if you never even try")

  def receive = {

    case QuoteRequest => {

      import util.Random

      //Get a random Quote from the list and construct a response
      val quoteResponse=QuoteResponse(quotes(Random.nextInt(quotes.size)))

      println (quoteResponse)

    }
  }
}


Logging Akka with SLF4J

You notice that in the code we are printing the quoteResponse to the standard output which you would obviously agree is a bad idea. Let's fix that up by enabling logging via the SLF4J Facade.

1. Fix the Class to use Logging

Akka provides a nice little trait called ActorLogging to achieve it. Let's mix that in :


class TeacherLogActor extends Actor with ActorLogging {

   val quotes = List(
    "Moderation is for cowards",
    "Anything worth doing is worth overdoing",
    "The trouble is you think you have time",
    "You never gonna know if you never even try")

  def receive = {

    case QuoteRequest => {

      import util.Random

      //get a random element (for now)
      val quoteResponse=QuoteResponse(quotes(Random.nextInt(quotes.size)))
      log.info(quoteResponse.toString())
    }
  }
      
  //We'll cover the purpose of this method in the Testing section
  def quoteList=quotes

}



A small detour here :

Internally, when we log a message, the the logging methods in the ActorLogging (eventually) publishes the log message to an EventStream. Yes, I did say publish. So, what actually is an EventStream?

EventStream and Logging

EventStream behaves just like a message broker to which we could publish and receive messages. One subtle distinction from a regular MOM is that the subscribers of the EventStream could only be an Actor.

In case of logging messages, all log messages would be published to the EventStream. By default, the Actor that subscribes to these messages is the DefaultLogger which simply prints the message to the standard output.

class DefaultLogger extends Actor with StdOutLogger {
  override def receive: Receive = {
    ...
    case event: LogEvent ⇒ print(event)
  }
}

So, that's the reason when we try to kick off the StudentSimulatorApp, we see the log message written to the console.

That said, EventStream isn't suited only for logging. It is a general purpose publish-subscribe mechanism available inside the ActorWorld inside a VM (more on that later).


Back to SLF4J setup :

2. Configure Akka to use SLF4J

akka{
    loggers = ["akka.event.slf4j.Slf4jLogger"]
    loglevel = "DEBUG"
    logging-filter = "akka.event.slf4j.Slf4jLoggingFilter"
}

We store this information in a file called application.conf which should be in your classpath. In our sbt folder structure, we would throw this in your main/resources directory.

From the configuration, we could derived that

  1. the loggers property indicates the Actor that is going to subscribe to the log events. What Slf4jLogger does is to simply consume the log messages and delegate that to the SLF4J Logger facade.
  2. the loglevel property simply indicates the minimum level that should be considered for logging.
  3. the logging-filter compares the currently configured loglevel and incoming log message level and chucks out any log message below the configured loglevel before publishing to the EventStream.

But Why didn't we have an application.conf for the previous example?

Simply because Akka provides some sane defaults so that we needn't build a configuration file before we start playing with it. We'll revisit this file too often here on for customizing various things. There are a whole bunch of awesome parameters that you could use inside the application.conf for logging alone. They are explained in detail here.

3. Throw in a logback.xml

We'll be configuring an SLF4J logger backed by logback now.

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
  <appender name="FILE"
    class="ch.qos.logback.core.rolling.RollingFileAppender">
    <encoder>
      <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
    </encoder>

    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
      <fileNamePattern>logs\akka.%d{yyyy-MM-dd}.%i.log</fileNamePattern>
      <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
        <maxFileSize>50MB</maxFileSize>
      </timeBasedFileNamingAndTriggeringPolicy>
    </rollingPolicy>
  </appender>

  <root level="DEBUG">
    <appender-ref ref="FILE" />
  </root>
</configuration>

I threw this inside the main/resources folder too along with application.conf. Please ensure that the main/resources is now in your eclipse or other IDE's classpath. Also include logback and slf4j-api to your build.sbt.

And when we kick off our StudentSimulatorApp and send a message to our new TeacherLogActor, the akkaxxxxx.log file that we configured looks like this.

Akka log file

Testing Akka


Please note that this is by no means an exhaustive coverage of Testing Akka. We would be building our tests on more features of Testing in the following parts under their respective topic headers. These testcases are aimed to cover the Actors we wrote earlier.


While the StudentSimulatorApp does what we need, you would agree that it should be driven out of testcases.

To ease the testing pain, Akka came up with an amazing testing toolkit with which we could do some magical stuff like probing directly into the Actor implementation's internals.

Enough talk, let's see the testcases.

Let's first try to map the StudentSimulatorApp to a Testcase.

Mapping App to Testcase

Let's look at the declaration alone now.

class TeacherPreTest extends TestKit(ActorSystem("UniversityMessageSystem"))
  with WordSpecLike
  with MustMatchers
  with BeforeAndAfterAll {

So, from the definition of the TestCase class we see that :

  1. The TestKit trait accepts an ActorSystem through which we would be creating Actors. Internally, the TestKit decorates the ActorSystem and replaces the default dispatcher too.
  2. We use WordSpec which is one of the many fun ways to write testcases with ScalaTest.
  3. The MustMatchers provide convenient methods to make the testcase look like natural language
  4. We mixin the BeforeAndAfterAll to shutdown the ActorSystem after the testcases are complete. The afterAll method that the trait provides is more like our tearDown in JUnit

1, 2 - Sending message to Actors

  1. The first testcase just sends a message to the PrintActor. It doesn't assert anything :-(

  2. The second case sends message to the Log actor which uses the log field of the ActorLogging to publish the message to the EventStream. This doesn't assert anything too :-(


  //1. Sends message to the Print Actor. Not even a testcase actually
  "A teacher" must {

    "print a quote when a QuoteRequest message is sent" in {

      val teacherRef = TestActorRef[TeacherActor]
      teacherRef ! QuoteRequest
    }
  }

  //2. Sends message to the Log Actor. Again, not a testcase per se
  "A teacher with ActorLogging" must {

    "log a quote when a QuoteRequest message is sent" in {

    val teacherRef = TestActorRef[TeacherLogActor]
      teacherRef ! QuoteRequest
    }

3 - Asserting internal state of Actors

The third case uses the underlyingActor method of the TestActorRef and calls upon the quoteList method of the TeacherActor. The quoteList method returns the list of quotes back. We use this list to assert its size.

If reference to quoteList throws you back, refer to the TeacherLogActor code listed above and look for

//From TeacherLogActor
//We'll cover the purpose of this method in the Testing section
  def quoteList=quotes
    //3. Asserts the internal State of the Log Actor. 
    "have a quote list of size 4" in {

      val teacherRef = TestActorRef[TeacherLogActor]
      teacherRef.underlyingActor.quoteList must have size (4)
      teacherRef.underlyingActor.quoteList must have size (4)
    }

4 - Asserting log messages

As we discussed earlier in the EventStream and Logging section (above), all log messages go to the EventStream and the SLF4JLogger subscribes to it and uses its appenders to write to the log file/console etc. Wouldn't it be nice to subscribe to the EventStream directly in our testcase and assert the presence of the log message itself? Looks like we can do that too.

This involves two steps :

  1. You need to add an extra configuration to your TestKit like so :

class TeacherTest extends TestKit(ActorSystem("UniversityMessageSystem", ConfigFactory.parseString("""akka.loggers = ["akka.testkit.TestEventListener"]""")))
  with WordSpecLike
  with MustMatchers
  with BeforeAndAfterAll {

  1. Now that we have a subscription to the EventStream, we could assert it from our testcase as :

 //4. Verifying log messages from eventStream
    "be verifiable via EventFilter in response to a QuoteRequest that is sent" in {

      val teacherRef = TestActorRef[TeacherLogActor]
      EventFilter.info(pattern = "QuoteResponse*", occurrences = 1) intercept {
        teacherRef ! QuoteRequest
      }
    }
    

The EventFilter.info block just intercepts for 1 log message which starts with QuoteResponse (pattern='QuoteResponse*). (You could also achieve it by using a start='QuoteResponse'. If there is no log message as a result of sending a message to the TeacherLogActor, the testcase would fail.

5 - Testing Actors with constructor parameters

Please note that the way we create Actors in the testcase is via the TestActorRef[TeacherLogActor] and not via system.actorOf. This is just so that we could get access to the Actor's internals through the underlyingActor method in the TeacherActorRef. We wouldn't be able to achieve this via the ActorRef that we have access during the regular runtime. (That doesn't give us any excuse to use TestActorRef in production. You'll be hunted down).

If the Actor accepts parameters, then the way we create TestActorRef would be like :


val teacherRef = TestActorRef(new TeacherLogParameterActor(quotes))

The entire testcase would then look something like :

//5. have a quote list of the same size as the input parameter
    " have a quote list of the same size as the input parameter" in {

      val quotes = List(
        "Moderation is for cowards",
        "Anything worth doing is worth overdoing",
        "The trouble is you think you have time",
        "You never gonna know if you never even try")

      val teacherRef = TestActorRef(new TeacherLogParameterActor(quotes))
      //val teacherRef = TestActorRef(Props(new TeacherLogParameterActor(quotes)))
      
      teacherRef.underlyingActor.quoteList must have size (4)
      EventFilter.info(pattern = "QuoteResponse*", occurrences = 1) intercept {
        teacherRef ! QuoteRequest
      }
    }

Shutting down ActorSystem

And finally, the afterAll lifecycle method

override def afterAll() {
    super.afterAll()
    system.shutdown()
  }

CODE

As always, the entire project could be downloaded from github here.