一般に非同期処理を行うと、その実行をログからトレースすることは難しくなります。 Scalaアプリケーションを運用する際もこれが問題となります。コツコツとログにIDを埋めて回ることもできますが、横断的な関心事はAOPで解決したくもなります。ということで、今回はKamonを試してみました。

Kamonは便利なのですがイマイチドキュメントがまとまっておらず、ちょっと苦労したのでここにまとめておくエントリです。

確認環境

Scala 2.12
Play Framework 2.6
SLF4J 1.7.x / Logback 1.2.x
Kamon 1.1.x
SBT 1.1.x

実現したいこと

ログにトレースIDを出力
Futureを使ってもトレースされる
Akka Actorを使ってもトレースされる
Play Frameworkで動作する

依存の追加

Kamonはいくつかのモジュールに分かれています。上記の目的を達成するには、以下のモジュールを追加します*1。

libraryDependencies ++= Seq(
  "io.kamon" %% "kamon-core" % "1.1.2",
  "io.kamon" %% "kamon-akka-2.5" % "1.0.1",
  "io.kamon" %% "kamon-play-2.6" % "1.0.2",
  "io.kamon" %% "kamon-scala-future" % "1.0.0",
  // "janino" % "janino" % "2.5.10",
  "io.kamon" %% "kamon-logback" % "1.0.0"
)

janinoについて

janinoについては必須ではありません。 JaninoEventEvaluatorを使用する場合にのみ必要なものです。ただ、これを含めていない場合はローカルでsbt run した際にXlint:cantFindTypeエラーが表示されてしまいます。 Productionモードで動かす場合は以下のように META-INF/aop.xml を置いておけば抑制することはできるのですが、sbt runの場合はxmlが読まれる前にチェックが走るため抑制することができませんでした。一応は目的通りに動いているのでローカルでのエラーは目を瞑っても良さそうです（？）*2

<!DOCTYPE aspectj PUBLIC "-//AspectJ//DTD//EN" "http://www.eclipse.org/aspectj/dtd/aspectj.dtd">

<aspectj>
    <weaver options="-verbose -warn:none -Xlint:ignore">
    </weaver>
</aspectj>

Scalaz Future(Task)を使っている場合

libraryDependencies += "io.kamon" %% "kamon-scalaz-future" % "1.0.0"

も追加します。他にはTwitter Futureに対応したライブラリもあります。Finagleなどを使う場合はそちらも追加します。

ロガー設定

次にロガーを設定します。ログの出力時にトレースIDをアペンダーに渡すためにCustom Converterが提供されています*3。以下のようにlogback.xmlを設定します。

※2018/4/16現時点ではLogbackしかサポートされていません。他のロガーを使用している場合は、自分でAOPを仕掛けるなどの工夫が必要になります。

<configuration>

  <conversionRule conversionWord="traceId" converterClass="kamon.logback.LogbackTraceIDConverter" />

  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>%date [%traceId] [%thread] %-5level %logger{32} - %message%n%xException</pattern>
    </encoder>
  </appender>

  <root level="INFO">
    <appender-ref ref="STDOUT" />
  </root>
</configuration>

conversionRuleでpatternに指定するWordとコンバーターを紐付けます。あとはいつもどおりのLogbackです。

Playアプリケーションの設定

プロダクションでPlayアプリケーションを動かす場合と、ローカルで動かす場合とで対応方法が異なります。

Kamon: Adding the AspectJ Weaver

プロダクションモード

plugins.sbtにsbt-javaagentを追加します。

addSbtPlugin("com.lightbend.sbt" % "sbt-javaagent" % "0.1.4")

そして、sbtのProject設定に以下のものを追加します。

enablePlugins(JavaAgent)
settings ++= Seq(
  javaAgents += "org.aspectj" % "aspectjweaver" % "1.8.13",
  javaOptions in Universal += "-Dorg.aspectj.tracing.factory=default"
)

ローカル開発モード

sbt runで動かす場合です。plugins.sbtに追加します。

resolvers += Resolver.bintrayIvyRepo("kamon-io", "sbt-plugins")
addSbtPlugin("io.kamon" % "sbt-aspectj-runner-play-2.6" % "1.1.0")

ただ、有効化するとそれなりにメモリを使う点と、微妙に安定しない（？）ので使わないという選択肢もあります。プロダクションモードでは上述の設定で動作するので、必要に応じて有効化すれば良いでしょう。なお、AspectJ Weaverが見つからない場合に派手な警告メッセージが表示されますが、application.confに以下を追加しておくと非表示にできます。

kamon.show-aspectj-missing-warning = no

以上で設定は終わりです。

どうやって実現されているのか？

Kamon > Documentation > Basics > Context

に大まかな説明があります。 KamonではContextというオブジェクトを引き回すことで、非同期に実行されていても同じトレースIDを参照できるようになっています。また、Spanという概念があり、Contextに紐付けることで処理のまとまりを表現できるようになっています。

今回のケースの場合はkamon-playを依存に追加すると、AOPによってRequestHandlerの処理開始時にこのContextとSpanが作成されます。 kamon-scala-futureやkamon-akkaを依存に含めているとFutureやAkka Actorを使用する際に、このContextオブジェクトを渡してくれるようAOPで書き換えられます。

具体的には実行部分のAroundとして、

Kamon.withContext(runnable.context) {
  pjp.proceed()
}

のように現在スレッド（ThreadLocal）のContextを保存して、ブロックの中は引数で受け取ったContextで処理されるように制御されます。このため、kamon-scala-futureなどを依存に含めない場合はAOP以外の方法で引き継がない限り、Contextは失われてしまいます。その場合はログに undefined として出力されます*4。

おまけ）JVMのメトリクスを取得する

Kamonではメトリクスも取得できます（これが本来の使い方）。他の有名所としてはMicrometer、Dropwizard metricsなどがあげられます。しかし、Scala（特にPlay Framework）へのサポート状況を踏まえると現状Kamonは有力かなぁと思います。

先に追加した依存ライブラリによってある程度のメトリクスは取得できていますが、さらにJVMやホストのメトリクスを取得する場合は以下のように追加します。 Reporter（取得したメトリクスをExportする口）にはPrometheusを使用しています。

libraryDependencies ++= Seq(
  "io.kamon" %% "kamon-system-metrics" % "1.0.0",
  "io.kamon" %% "kamon-prometheus" % "1.0.0"
)

application.confにReporter指定を追記します。

kamon.reporters += "kamon.prometheus.PrometheusReporter"

あとは、アプリケーションの起動時にSystemMetricsを取得するよう開始メソッドを呼ぶだけです。ここではGuice DIを使った例を示します。

import kamon.system.SystemMetrics
import play.api.inject.ApplicationLifecycle
import com.google.inject.AbstractModule

class StartUp @Inject() (lifecycle: ApplicationLifecycle)(implicit ec: ExecutionContext) {
  SystemMetrics.startCollecting()

  lifecycle.addStopHook(() => Future {
    SystemMetrics.stopCollecting()
  })
}

class MainModule extends AbstractModule {
  bind(classOf[StartUp]).asEagerSingleton()
}

微妙に不安定

ただ、ローカルで動かしていると、たまにPrometheusのエンドポイントがすでにアドレスが使われているとBindExceptionが発生することがあります。アドレスにアクセスするとエンドポイントが動いていたりするので、どこかで処理が二重に呼ばれるのかもしれません（？）要調査です。

またMetaspaceが足りなくなるエラーも度々発生します。これは単純にメモリを積めば解決しそうですが、SBTサーバーを立ち上げたままであるからなのか、AOPだと致し方ないのかまだ判然としませんので様子見中です。

余談

Javaエージェントによる新しいInstrumentationの実装が行われています。

github.com

AOPによる書き換えが嫌だなぁという場合は、こちらも将来的には有力な選択肢になるかもしれませんね。

*1:Kamonはモジュールごとバラバラにバージョンを付けているのがちょっと面倒

*2:情報お待ちしております

*3:これがKamonのドキュメントには記載が見つからない。コード読んでLogbackの使い方を知らないとたどり着けないの厳しい

*4:なぜここの処理からundefinedに？とちょっとハマりました

yoskhdia’s diary

DDDとかプログラミングとかアーキテクチャとか雑多に

Kamonを使ってログにトレースIDを出力する（＋Play Framework）