LoginSignup
7
6

More than 5 years have passed since last update.

@akishin(Shin Akiyama)

Finagle でリクエスト毎の ID をログに出力する

Posted at

Finagle を使ったサービスでログにリクエスト毎の ID を出力してリクエスト単位で識別したかったので方法を調べた。

試した環境は以下。

build.sbt
name := "finagle-example"
scalaVersion := "2.11.7"

resolvers += "twitter-repo" at "https://maven.twttr.com"

libraryDependencies ++= Seq(
  "com.twitter" %% "finagle-core" % "6.31.+",
  "com.twitter" %% "finagle-http" % "6.31.+"
)

使ってる com.twitter.logging.Logger に MDC 的な仕組みがあったら楽だと思って調べてみたがどうやら無いらしい。

また、Finagle のような非同期 + マルチスレッドのフレームワークの場合、必ずしも「1 Thread = 1 Request」にはならない。
以下は Finagle の記事ではないが、こういった場合だと単純に MDC は使えないみたいだ。

Logging Contextual Info in an Asynchronous Scala Application – Everything Technical (and more) @ Hootsuite
http://code.hootsuite.com/logging-contextual-info-in-an-asynchronous-scala-application/

ちなみに Finagle ベースの Finatra では LoggingMDCFilter という Filter を提供して Logback の MDC を上手いことサポートしているっぽい。

Logging - Finatra
http://twitter.github.io/finatra/user-guide/logging/#mdc

リクエストヘッダに書き込んで保持する方法

どうしようかと思っていろいろ探していたところ、以下のスライドを発見。

Rewrite in Finagle // Speaker Deck
https://speakerdeck.com/iwag/rewrite-in-finagle?slide=40

Finagle の Filter でリクエストヘッダに ID を付与すればいいらしい。
他にも実装している人がいたので、このアプローチで取り敢えず実現は可能そう。

上記を参考に以下のように実装してみた。
単にログに出したいだけのリクエストID としては若干冗長な気もするけど取り敢えず UUID を使っている。

HTTPServer.scala
import java.util.UUID

import com.twitter.finagle.{Http, Service, SimpleFilter}
import com.twitter.finagle.http
import com.twitter.util.{Await, Future, FuturePool}
import com.twitter.logging.Logger


/**
 * リクエストに ID を追記するフィルタ
 */
class AppendRequestIdFilter extends SimpleFilter[http.Request, http.Response]  {
  private val log = Logger.get(getClass)

  def apply(request: http.Request, service: Service[http.Request, http.Response]) = {
    if (!request.headerMap.contains("X-Request-ID")) {
      val id = UUID.randomUUID().toString
      request.headerMap.put("X-Request-ID", id)
      log.info(s"append request id: $id")
    }
    service(request)
  }
}

/**
 * Service
 */
class HelloService extends Service[http.Request, http.Response] {
  private val log = Logger.get(getClass)

  override def apply(request: http.Request): Future[http.Response] = FuturePool.unboundedPool {
    val id = request.headerMap.getOrElse("X-Request-ID", null)
    log.info(s"found request id: $id")
    val response = http.Response()
    response.setContentString(s"Hello, $id.");
    response
  }
}

/**
 * Server
 */
object HTTPServer {

  private val log = Logger.get(getClass)

  def main(args: Array[String]):Unit = {
    val helloService = new HelloService
    val reqIdFilter  = new AppendRequestIdFilter

    val service = reqIdFilter andThen helloService

    val server = Http.serve(":8080", service)
    Await.ready(server)
  }
}

sbt run してサーバを起動し、別の端末からリクエストを送信。
以下のように生成したリクエスト ID 付きのレスポンスが返ってくる。

% curl http://localhost:8080
Hello, 6ba25bed-9975-4969-9b53-9cb1f0797cc3.
% curl http://localhost:8080
Hello, eae5ba35-e43b-4dd2-bf7f-eb6d9ad3d0a1.

サーバ側のログは以下のように出力されていた。

% sbt run
[info] Set current project to finagle-example (in build file:/home/akishin/src/scala/finagle_ex/)
[info] Running HTTPServer 
3 18, 2016 10:59:35 午後 com.twitter.finagle.Init$$anonfun$1 apply$mcV$sp
情報: Finagle version 6.31.0 (rev=50d3bb0eea5ad3ed332111d707184c80fed6a506) built at 20151203-164135
3 18, 2016 10:59:37 午後 AppendRequestIdFilter apply
INFO: append request id: 6ba25bed-9975-4969-9b53-9cb1f0797cc3
3 18, 2016 10:59:37 午後 HelloService$$anonfun$apply$1 apply
INFO: found request id: 6ba25bed-9975-4969-9b53-9cb1f0797cc3
3 18, 2016 10:59:38 午後 AppendRequestIdFilter apply
INFO: append request id: eae5ba35-e43b-4dd2-bf7f-eb6d9ad3d0a1
3 18, 2016 10:59:38 午後 HelloService$$anonfun$apply$1 apply
INFO: found request id: eae5ba35-e43b-4dd2-bf7f-eb6d9ad3d0a1

リクエスト毎に一意の ID が出力されているようだ。
ここでは com.twitter.logging.Logger のフォーマッタまでは弄らないが、ThreadID も出力するようにしてみると、途中で ThreadID は変わる事もあるが、生成したリクエストID は 1 リクエスト間では一意であることが判る。

但し、この方法では Logger に対して生成したリクエストIDを渡す方法がないため、全ログにリクエストID を出力したい場合、Logger のラッパーを書いて毎回取り出したリクエストIDをメッセージに連結、とかやらなければならない。

一旦出来る事が判ったのはいいがそれはちょっと面倒臭いので別の方法を探してみる。

Local を使って保持する方法

twitter/util に含まれる com.twitter.util.Local を使うと ThreadLocal と同じような感じで値を保持できるらしい。
Effective Scala でも以下のように紹介されている。

Util ライブラリの Local は、特定の Future のディスパッチツリーに対するローカルな参照セルを提供する。
Local に値をセットすると、同じスレッド内の Future によって遅延されるあらゆる計算がこの値を利用できるようになる。
これらはスレッドローカルに似ているが、そのスコープが Java スレッドでなく”Future スレッド”のツリーである点が異なる。

これを使えば Request オブジェクトに頼らなくても同様の仕組みを実現できそう。

しかし中々 com.twitter.util.Local を使ったサンプルコードが見つからない・・・。
Google は諦めて GitHub を検索していたら以下のコードを見つけた。

なるほど。こう使うのか。

という訳で com.twitter.util.Local を使うように書きなおしてみる。

HTTPServer.scala
import java.util.UUID

import com.twitter.finagle.{Http, Service, SimpleFilter}
import com.twitter.finagle.http
import com.twitter.util.{Await, Future, FuturePool, Local}
import com.twitter.logging.Logger

/**
  * リクエスト毎の値を保持するためのコンテキストオブジェクト
  */
object RequestContext {
  private[this] val local = new Local[String]

  def requestId = local() match {
    case Some(id) => id
    case None =>
      val id = UUID.randomUUID().toString
      local.update(id)
      id
  }

  def setRequestId(id:String) = local.update(id)

  def clear() = local.clear()
}

/**
 * ログ出力フィルタ
 */
class LoggingFilter extends SimpleFilter[http.Request, http.Response]  {
  private val log = Logger.get(getClass)

  def apply(request: http.Request, service: Service[http.Request, http.Response]) = {
    log.info(s"request start: ${RequestContext.requestId}")
    val future = service(request)
    log.info(s"request end: ${RequestContext.requestId}")
    future
  }
}

/**
 * Service
 */
class HelloService extends Service[http.Request, http.Response] {
  private val log = Logger.get(getClass)

  override def apply(request: http.Request): Future[http.Response] = FuturePool.unboundedPool {
    val id = RequestContext.requestId
    log.info(s"found request id: ${id}")
    val response = http.Response()
    response.setContentString(s"Hello, $id.");
    response
  }
}

/**
 * Server
 */
object HTTPServer {

  private val log = Logger.get(getClass)

  def main(args: Array[String]):Unit = {
    val helloService = new HelloService
    val loggingFilter  = new LoggingFilter

    val service = loggingFilter andThen helloService

    val server = Http.serve(":8080", service)
    Await.ready(server)
  }
}

先ほどと同様、 sbt run してサーバを起動し、別の端末からリクエストを送信してみる。
同じ様に生成したリクエスト ID 付きのレスポンスが返ってくる。

% curl http://localhost:8080
Hello, 19fc5a09-1140-4393-b5cd-55e1538a5965.
 % curl http://localhost:8080
Hello, f32814a5-b2d0-4dc5-9ecc-ed81fd5f3e91.

サーバ側のログは以下。

% sbt run
[info] Set current project to finagle-example (in build file:/home/akishin/src/scala/finagle_ex/)
[info] Compiling 1 Scala source to /home/akishin/src/scala/finagle_ex/target/scala-2.11/classes...
[info] Running HTTPServer 
3 18, 2016 11:16:32 午後 com.twitter.finagle.Init$$anonfun$1 apply$mcV$sp
情報: Finagle version 6.31.0 (rev=50d3bb0eea5ad3ed332111d707184c80fed6a506) built at 20151203-164135
3 18, 2016 11:16:40 午後 LoggingFilter apply
INFO: request start: 19fc5a09-1140-4393-b5cd-55e1538a5965
3 18, 2016 11:16:40 午後 LoggingFilter apply
INFO: request end: 19fc5a09-1140-4393-b5cd-55e1538a5965
3 18, 2016 11:16:40 午後 HelloService$$anonfun$apply$1 apply
INFO: found request id: 19fc5a09-1140-4393-b5cd-55e1538a5965
3 18, 2016 11:16:42 午後 LoggingFilter apply
INFO: request start: f32814a5-b2d0-4dc5-9ecc-ed81fd5f3e91
3 18, 2016 11:16:42 午後 LoggingFilter apply
INFO: request end: f32814a5-b2d0-4dc5-9ecc-ed81fd5f3e91
3 18, 2016 11:16:42 午後 HelloService$$anonfun$apply$1 apply
INFO: found request id: f32814a5-b2d0-4dc5-9ecc-ed81fd5f3e91

こちらもリクエスト毎に一意のリクエストIDが出力できているようだ。

com.twitter.util.Local を使った方法であれば Request オブジェクトに依存しないため、 com.twitter.logging.Logger の Formatter を作成してその中でリクエストID を自動的にログに追加する、といったことも簡単にできそう。

7
6
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
7
6