该系列译自 Rerun.me, 并在原作者的基础上有所改动。本篇为该系列的第三篇——Actor 的日志和测试。

前文 Akka Notes 1 - Introducing ActorsAkka Notes 2 - Actor Messaging 对 Akka Actor 设计模式和消息机制做了简单的介绍。今天我们来探讨 Actor 的日志和测试功能,而今天测试的对象则主要是 TeacherActor.

前文2 中 TeacherActor 的长相如下:

package me.yuanbin.akkanotes.actormsg

import akka.actor.Actor
import me.yuanbin.akkanotes.protocols.StudentProtocol._
import me.yuanbin.akkanotes.protocols.TeacherProtocol._
import scala.util.Random

/**
 * Your Teacher Actor class.
 *
 * The class could use refinement by way of
 * using ActorLogging which uses the EventBus of the Actor framework
 * instead of the plain old System out
 *
 */

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 => {
      //Get a random Quote from the list and construct a response
      val quoteResponse = QuoteResponse(quotes(Random.nextInt(quotes.size)))
      println()
      println(quoteResponse)
    }
  }
}

使用 SLF4J 作为 Akka 的日志组件

SLF4J 并没有去实现日志记录,而是作为后端日志库如 Log4j, Logback 的抽象层,这种好处在于你的代码可以独立于其他日志记录的 API。P.S. SLF4J 和 Log4J 的作者是同一个人。

在以上代码中你可能发现我们将quoteResponse 直接打印到标准输出,这对于大型调试来说通常不是什么好的想法,我们使用 SLF4J 这个库来作为 Akka 的日志记录组件。

1. 为 TeacherActor 类添加 Logging

Akka 提供了一个叫 ActorLogging 的 trait, 我们可以用这个 trait 来达成目标。类 TeacherActor 经过修改之后它大概长成下面这个样子:


这里有个小小的点需要注意,在内部,当我们记录一条消息时,最终 ActorLogging 的 logging 方法将这条日志消息 publish 到一条 EventStream 中,那么到底什么是 EventStream 呢?

EventStream 和 Logging

EventStream 的行为就像一个消息的代理人,我们可以通过它 publish 和 receive 消息。 它和通常的 MOM 有一个细微的区别——EventStream 的订阅者必须是一个 Actor. 为了记录消息,所有的日志记录消息都必须被 pushlish 到 EventStream 中。默认情况下,订阅这些消息的 Actor 是 DefaultLogger,它会将这些消息简单地打印到标准输出。 DefaultLogger 的部分源码如下:

  class DefaultLogger extends Actor with StdOutLogger with RequiresMessageQueue[LoggerMessageQueueSemantics] {
    override def receive: Receive = {
      case InitializeLogger(_)  sender() ! LoggerInitialized
      case event: LogEvent      print(event)
    }
  }

所以这就是我们尝试启动 StudentSimulatorApp 的原因,我们能看到日志消息被写入到控制台中。这也就是说 EventStream 不仅适合用作日志记录,同时也是 VM 中 Actor 世界的一个通用的 publish-subscribe 机制。

接下来继续配置 SLF4J

配置 Akka 支持使用 SLF4J

我们在src/main/resources/application.conf中写入如下内容:

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

从以上配置文件可知:

  1. loggers 属性表示将由 Actor 订阅日志事件,Slf4jLogger 所做的就是获取日志消息并代理给 SLF4J Logger facade.
  2. loglevel 属性表明记录时的最低等级,如 debug, warn, info 等不同等级。
  3. logging-filter 会比较当前配置的 loglevel 和输入的日志消息等级,并在 publish 到 EventStream 之前丢弃掉任何低于配置中 loglevel 的日志消息。

那么问题来了,为何在前一篇文章里没有这个文件呢?——Akka 默认给你配置了很多选项,所以没有特殊需求时可不自定义。关于 Logging 的更多细节可参考 Akka 的文档

将日志记录配置写入 logback.xml

我们使用 Logback 作为 SLF4J 的后端日志库,和之前的 application.conf 一样,存放在src/main/resources/目录下,具体配置文件如下:

<?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>

当我们启动StudentSimulatorApp后,Student 将向 TeacherLogActor 发送一个请求,相应的akkaxxx.log 文件内容大致如下所示。

17:56:08.659 [UniversityMessageSystem-akka.actor.default-dispatcher-4] INFO  akka.event.slf4j.Slf4jLogger - Slf4jLogger started
17:56:08.676 [UniversityMessageSystem-akka.actor.default-dispatcher-4] DEBUG akka.event.EventStream - logger log1-Slf4jLogger started
17:56:08.682 [UniversityMessageSystem-akka.actor.default-dispatcher-4] DEBUG akka.event.EventStream - Default Loggers started
17:56:08.696 [UniversityMessageSystem-akka.actor.default-dispatcher-4] INFO  m.y.a.actorlog.TeacherLogActor - QuoteResponse(The trouble is you think you have time)
17:56:10.714 [UniversityMessageSystem-akka.actor.default-dispatcher-4] DEBUG akka.event.EventStream - shutting down: StandardOutLogger started

测试 Akka

需要注意的是这里提供的方法并不是要测试 Akka 的所有方面,我们将在后续章节中根据相应的主题提供更多的测试特性,这里的测试用例用于测试我们之前写的 Actor.

既然StudentSimulatorApp 已经完成了我们的基本功能,现在我们可以对它进行测试了。为了减轻测试的痛苦,Akka 提供了一套非常棒的测试工具集。有了它,我们就可以做一些非常酷的事情,比如直接查看 Akka 的内部实现。废话少说,下面让我们来看看测试集。

首先将我们的StudentSimulatorApp 映射为一个 Testcase.

Mapping.001

我们先来看看上面的声明部分:

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

从以上测试类的定义我们可以知道:

  1. TestKit 这个 trait 接收一个可以用来创建 Actor 的ActorSystem. 在内部实现中,TestKit 修饰了 ActorSystem 并替换了其默认的 dispatcher.
  2. 我们用 ScalaTest 中的 WordSpec 来编写测试类,这在 ScalaTest 中是非常有意思的一种方式。
  3. MustMatchers 则提供了一些非常方便的方法以使得测试用例看起来就像是自然语言一样。
  4. 我们将 BeforeAndAfterAll 包含了进来,这样可以在测试用例结束后关闭 ActorSystem. trait 提供的 afterAll 方法和 JUnit 中的tearDown 方法有些类似。

向 Actor 发送消息

  1. 第一个测试用例仅仅只是发送一条消息给PrintActor, 它并不做任何断言 :-(
  2. 第二个测试用例发送一条消息给Log Actor, 这个 Log Actor 使用 ActorLogging 的 log 域并且将消息推送到 EventStream 中,这个同样不进行任何断言 :-(
  //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
    }

对 Actors 的内部状态进行断言

第三种情形将使用 TestActorRefunderlyingActor 方法并且调用TeacherActorquoteList 方法。这个 quoteList 方法将返回一个 quotes 列表,我们使用这个列表断言其大小。 如果对quoteList 的引用失败了,参考TeacherLogActor中的代码并找到如下几行:

//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)
    }

对 Log 消息进行断言

正如我们在 EventStream 和 Logging 章节中所讨论过的,所有的日志消息都将流向 EventStream,SLF4J Logger 订阅这条消息并且使用它的 appenders 来写入到 日志文件/控制台等。在测试用例中直接订阅 EventStream 并对日志消息出现的地方进行断言不好吗?看起来我们是可以这么做的。

要实现以上这两点需要进行两个步骤:

  1. 你需要在你的TestKit中增加一额外的配置如:
class TeacherTest extends TestKit(ActorSystem("UniversityMessageSystem",
  ConfigFactory.parseString("""akka.loggers = ["akka.testkit.TestEventListener"]""")))
  with WordSpecLike
  with MustMatchers
  with BeforeAndAfterAll {
  1. 既然我们已经订阅了 EventStream, 那么接下来就可以从我们的测试用例中进行断言了:
 //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
      }
    }

EventFilter.info 语句块捕获以QuoteResponse 开头的日志消息(pattern='QuoteResponse*),你也可以写成start='QuoteResponse'. 如果向 TeacherLogActor 发送消息,却没有日志消息产生,那么测试就会失效。

对带构造参数的 Actor 进行测试

需要注意的是我们在测试用例中构建 Actors 的方式是通过 TestActorRef[TeacherLogActor] 而不是通过 system.actorOf. 之所以这么做是因为我们能通过TeacherActorRefunderlyingActor方法访问 Actor 的内部。而通常在程序的运行时通过 ActorRef 是无法访问 Actor 的内部情况的。但这并不是我们在生产环境中使用 TestActorRef 的借口,否则你会被揍扁的…

如果 Actor 接收了参数,那么我们创建 TestActorRef 的方式就和下面的方式类似:

val teacherRef = TestActorRef(new TeacherLogParameterActor(quotes))

于是整个测试类看起来就像如下这个样子:

//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
      }
    }

关闭 ActorSystem

最终afterAll方法如下:

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

源码

Akka Logging

源码可以从 akka_notes/akka_logging 找到。运行方式,确保系统安装好 sbt 0.13.8.

cd akka_notes/akka_logging
sbt run

在 logs 文件夹下即可找到相应的 log 文件。

Akka Testing

源码可以从 akka_notes/akka_testing 找到。运行方式,确保系统安装好 sbt 0.13.8.

cd akka_notes/akka_testing
sbt test