やりたいこと

PlayFrameworkのアプリケーションログに、ユーザーエージェントや、リクエストをトレースするIDを、常に出力する。

request


$ curl -v -H "X-Person-Id: 100" -X GET http://127.0.0.1:9000/
* Hostname was NOT found in DNS cache
*   Trying 127.0.0.1...
* Connected to 127.0.0.1 (127.0.0.1) port 9000 (#0)
> GET / HTTP/1.1
> User-Agent: curl/7.37.1
> Host: 127.0.0.1:9000
> Accept: */*
> X-Person-Id: 100
>
< HTTP/1.1 200 OK
< Content-Type: text/plain; charset=utf-8
< X-Trace-Id: dbfe163c-c74d-4f08-86fe-890e8244ee50
< Content-Length: 2
<
* Connection #0 to host 127.0.0.1 left intact

# ヘッダのX-Person-Idと、UserAgent、トレース用のIDがログに出力されている
$ tail -n1 target/universal/stage/logs/application.log
2015-02-01T06:37:39+0000 [INFO] application "info log" 100 "dbfe163c-c74d-4f08-86fe-890e8244ee50" "curl/7.37.1"

やりかた

logbackにはMapped Diagnostic Contexts (MDC)を使っても可能ですが、Playframeworkのように異なるスレッドで非同期に実行されているとコンテキストの受け渡し処理を追加する必要でした(たぶん)。

そこでKammon-ioを使うことで、少しだけ簡単に導入することができます。

Kammon-io自体は他にも便利が機能があるので、他の機能との兼ね合いで導入の検討をされてみると良いかもしれません。

設定してみる

ライブラリの追加

Kammon-ioの他に、後述するAspectJweaverとJaninoのライブラリを追加します。

build.sbt

val kamonVersion = "0.3.5"

val aspectjweaverVersion = "1.8.4"

libraryDependencies ++= Seq(
  "io.kamon"    %% "kamon-core"   % kamonVersion,
  "io.kamon"    %% "kamon-play"   % kamonVersion,
  "org.aspectj" % "aspectjweaver" % aspectjweaverVersion,
  "janino"      % "janino"        % "2.4.3"
)

ロガーの設定

Kammon-ioも内部ではMDCを使っているため、logger.xmlの設定はMDCと同じ記述方法となります。

ポイント1
今回はFILE_APPLICATIONとFILEの2つの設定をしています。
リクエスト情報は、ライブラリなどが出力される情報にはふくまれていないため、常に空文字列が出力されます。
そこで、EvaluatorFilterを使ってアプリケーションのロガーの場合と、そうでない場合(ライブラリやフレームワーク)で出力するフォーマットを変更しています。

ポイント2
EvaluatorFilterを使うにはjaninoライブラリの追加が必要です。

他にもファイル自体を分ける方法も良いかもしれません。

logger.xml

    <appender name="FILE_APPLICATION" class="ch.qos.logback.core.FileAppender">
        <file>${application.home}/logs/application.log</file>
        <encoder>
            <pattern>%date{yyyy-MM-dd'T'HH:mm:ssZ,GMT} [%level] %logger "%replace(%message){'\n', '\\n'}" %X{userId:--} "%X{traceId:--}" "%X{userAgent:--}"%n</pattern>
        </encoder>
        <filter class="ch.qos.logback.core.filter.EvaluatorFilter">
            <evaluator>
                <expression>return mdc != null &amp;&amp; mdc.get("traceId") != null;</expression>
            </evaluator>
            <OnMatch>ACCEPT</OnMatch>
            <OnMismatch>DENY</OnMismatch>
        </filter>
    </appender>

    <appender name="FILE" class="ch.qos.logback.core.FileAppender">
        <file>${application.home}/logs/application.log</file>
        <encoder>
            <pattern>%date{yyyy-MM-dd'T'HH:mm:ssZ,GMT} [%level] %logger "%replace(%message){'\n', '\\n'}"%n</pattern>
        </encoder>
        <filter class="ch.qos.logback.core.filter.EvaluatorFilter">
            <evaluator>
                <expression>return mdc != null &amp;&amp; mdc.get("traceId") != null;</expression>
            </evaluator>
            <OnMatch>DENY</OnMatch>
            <OnMismatch>ACCEPT</OnMismatch>
        </filter>
    </appender>

    <root level="ERROR">
        …
        <appender-ref ref="FILE_APPLICATION" />
        <appender-ref ref="FILE" />
        …
    </root>

アプリケーション設定(任意)

任意の設定ですが、ログレベルをDEBUGで実行している場合、org.aspectjだけでもINFOレベルしないと、えらいログの量になります。

applicaiton.conf

logger {
  root=DEBUG

  # Logger used by the framework:
  play=DEBUG

  # Logger provided to your application:
  application=DEBUG

  # Aspectj logging
  org.aspectj=INFO
}

フィルターの作成

Global.scalaで設定するフィルタークラスの定義です。
このソースはKammon-ioリポジトリにあるサンプルを加工しています。
TraceLocalFilter.scala

TraceLocalContainerクラスに定義されているフィールド名が、MDCで使用するログのフィールドの名前にマッピングされます。

ポイント
onResultでレスポンスヘッダにトレースIDを設定することで、NginxなどのアクセスログにもトレースIDを出力することができます。
この設定により、トレースIDでアクセスログとアプリケーションログのマッピングが可能になります。

TraceLocalFilter.scala

package filters

import kamon.trace.TraceLocal
import play.api.Logger
import play.api.libs.concurrent.Execution.Implicits.defaultContext
import play.api.mvc.{ Filter, RequestHeader, Result }

import scala.concurrent.Future

case class TraceLocalContainer(
  userId: Long,
  traceId: String,
  userAgent: String)

object TraceLocalKey extends TraceLocal.TraceLocalKey {
  type ValueType = TraceLocalContainer
}

object TraceLocalFilter extends Filter {
  val logger = Logger(this.getClass)
  val PersonIdKey = "X-Person-Id"
  val UserAgentKey = "User-Agent"

  // @see NginxのCustomLogFormatに以下設定を追加することで、AccessLogにトレースIDが記録される。
  // trace_id["$sent_http_x_trace_id"]
  val ResponseIdKey = "X-Trace-Id"

  override def apply(next: (RequestHeader) => Future[Result])(header: RequestHeader): Future[Result] = {

    def onResult(result: Result) = {
      val traceLocalContainer = TraceLocal.retrieve(TraceLocalKey).getOrElse(TraceLocalContainer(0L, "unknown", "unknown"))
      result.withHeaders(ResponseIdKey -> traceLocalContainer.traceId)
    }

    val traceId: String = java.util.UUID.randomUUID.toString
    val personId: Long = header.headers.get(PersonIdKey).getOrElse("0").toLong
    val userAgent: String = header.headers.get(UserAgentKey).getOrElse("unknown")

    val traceLocalContainer: TraceLocalContainer = TraceLocalContainer(personId, traceId, userAgent)

    //update the TraceLocalStorage
    TraceLocal.store(TraceLocalKey)(traceLocalContainer)

    //call the action
    next(header).map(onResult)
  }
}

フィルターの登録

Globalセッティングが他にない場合(シンプル)

Global.scala

import filters.TraceLocalFilter
import play.api.mvc.WithFilters

object Global extends WithFilters(TraceLocalFilter)

他にもGlobalセッティングを使っている場合

Global.scala

import filters.TraceLocalFilter
import play.api._
import play.api.mvc.{ RequestHeader, _ }

object Global extends GlobalSettings {
  override def onError(request: RequestHeader, ex: Throwable) = {
  …
  }

  override def doFilter(a: EssentialAction): EssentialAction = {
    Filters(super.doFilter(a), TraceLocalFilter)
  }
}

アプリケーションログの出力

サンプルとしてコントローラーから直接アプリケーションログを出力する。

Application.scala

  def index = Action {
    Logger.info("info log")
    Ok("OK")
  }

起動用シェルスクリプトの設定(Prod-mode)

最後にとっても重要な設定と説明を！！

Kammon-ioのドキュメントにも記載されていますが、Kammon-ioを使用するにはjavaagentにAspectJweaverを指定する必要があります。
通常はsbt-aspectjを使って、load-timeの設定を行うことでrunコマンドでもKammon-ioが動作します。

ただしPlayframeworkのDev-mode(runコマンド)では、残念ながらload-timeの設定を入れても、AspectJweaverが読み込まれずKammon-ioの一部の機能が動作しません。今回の機能も動作しません。

つまり、 PlayframeworkのDev-modeでは、Kammon-ioがほとんど機能しません！！
Kammon-ioのサンプルでも明示されている制限事項ですが、ハマりました。

In order to run the example we need set the -javaagent option to the JVM, but Play have some limitations when trying to set an

java agent in Play dev mode (ie, play run) -> https://github.com/playframework/playframework/issues/1372, so we have others options:

ショックでした…
※何か代替方法があったら、ご連絡ください！

とりあえず気を取り直して、Prod-modeで動作させる方法を追加します。
classpathオプションではなく、javaagentオプションでの指定が必要なため、起動スクリプトに設定を追加します。

build.sbt

val aspectjweaverVersion = "1.8.4"

NativePackagerKeys.bashScriptExtraDefines ++= Seq(
  s"""addJava "-javaagent:$${lib_dir}/org.aspectj.aspectjweaver-$aspectjweaverVersion.jar""""
)

動かしてみる

開発時用の起動シェルを追加

stage.sh

# !/bin/bash

base_dir=$(cd $(dirname $0); pwd)"/target/universal/stage"
mem=512

bash ${base_dir}/bin/qiita-playframework-trace-log -mem $mem

Prod-modeで実行！！

$ bash stage.sh
…
[INFO] [02/01/2015 16:37:40.435] [New I/O worker #1] [PlayExtension(akka://application)] Starting the Kamon(Play) extension
…

最後に

GitHubに動作するサンプルをPushしてあります。
[https://github.com/watawuwu/qiita-playframework-trace-log]

Kammon-ioは他にも、メトリクス収集の機能があったり、これからの動向が気になるライブラリです。

自分はNewRelicとの連携も使いたいのですが、現在はAspectJweaverのライブラリと競合してるのか、エラーになってしまっているので解決したら、投稿したいと思います！！

あとAspectJweaverって凄いですね。
起動時にソースを差し込んでる？感じなんでしょうか。

kamon.play.instrumentation.LoggerLikeInstrumentation.scala

@Aspect
class LoggerLikeInstrumentation {

  import kamon.play.instrumentation.LoggerLikeInstrumentation._

  @DeclareMixin("play.api.LoggerLike+")
  def mixinContextAwareToLoggerLike: TraceContextAware = TraceContextAware.default

  @Pointcut("execution(* play.api.LoggerLike+.info(..))")
  def infoPointcut(): Unit = {}

  @Pointcut("execution(* play.api.LoggerLike+.warn(..))")
  def warnPointcut(): Unit = {}

  @Pointcut("execution(* play.api.LoggerLike+.error(..))")
  def errorPointcut(): Unit = {}

  @Pointcut("execution(* play.api.LoggerLike+.trace(..))")
  def tracePointcut(): Unit = {}

  @Around("(infoPointcut() || warnPointcut() || errorPointcut() || tracePointcut()) && this(logger)")
  def aroundLog(pjp: ProceedingJoinPoint, logger: LoggerLike): Any = {
    withMDC {
      pjp.proceed()
    }
  }
}

ちなみに
debugレベルのログはLoggerLikeInstrumentationで定義されていないためか、動作しません。

本記事は理解できてないこと多いので、記事への指摘ありましたらよろしくお願いします。
もちろん質問も！！