finatra-thriftでリクエスト受付時点の時刻を一貫して取得

TL;DR

• リクエスト-レスポンスの間で、一貫した時刻を取得できると便利
• コントローラ関数の1行目で val now = OffsetDateTime.now して doSomething(now, ...) で引数引き回しは嫌だ
• RequestLocalTime.current.requestedAt で、どこでもリクエスト開始時点の時刻を取得できる仕組みを作った

動機: リクエスト-レスポンスの間で一貫した時刻がほしい

多数のリクエストを受け付けるアプリケーションの場合、複数リクエストから吐かれるログがごちゃ混ぜな順番になってしまうことがあります。

コントローラコード

@Singleton
class VerboseServiceController @Inject() ()
  extends Controller
    with idl.VerboseService.BaseServiceIface
    with Logging
{
  override val echo = handle(Echo) { args =>
    info(s"[PointA] Current time: ${OffsetDateTime.now}")

    debug("sleeping...")
    Thread.sleep(1000)

    info(s"[PointB] Current time: ${OffsetDateTime.now}")

    Future(s"You said: ${args.message}")
  }
}

ログ出力例（nowを毎回呼び出す）

[PointA] Current time: 2017-02-10T14:10:56.100Z　← リクエスト1のログ
[PointA] Current time: 2017-02-10T14:10:56.101Z　← リクエスト2のログ
[PointB] Current time: 2017-02-10T14:10:57.100Z　← リクエスト1のログ？実はリクエスト2のログ
[PointB] Current time: 2017-02-10T14:10:57.102Z　← リクエスト1のログ

これを、次のようにリクエスト時点のログを一貫して出せるようにしたいと思います。

ログ出力例（リクエスト時点の時刻）

[PointA] Request time: 2017-02-10T14:10:56.100Z　← リクエスト1のログ
[PointA] Request time: 2017-02-10T14:10:56.101Z　← リクエスト2のログ
[PointB] Request time: 2017-02-10T14:10:56.101Z　← リクエスト2のログ。時刻が同上なので分かりやすい
[PointB] Request time: 2017-02-10T14:10:56.100Z　← リクエスト1のログ

イメージしやすいようにログを例に挙げましたが、DBへの時刻記録や、時刻を使った条件分岐もリクエスト時点の時刻を一貫して使いたかったりする場合があります。

ナイーブな策: now 引数引き回し

やりたいことは実現できていますが、いちいち引数を渡すのが面倒です。

`now`引数引き回し

  override val echo = handle(Echo) { args =>
    val now = OffsetDateTime.now

    info(s"[PointA] Current time: $now")

    debug("sleeping...")
    Thread.sleep(1000)

    doSomething(now)

    info(s"[PointB] Current time: $now")

    Future(s"You said: ${args.message}")
  }

  def doSomething(now: OffsetDateTime): Unit = {
    ... // DBに `now` の値を書き込む

    doAnother(now)
  }

  def doAnother(now: OffsetDateTime): Unit =
    if (now > importantDateTime) ...  // リクエスト時点が `importantDateTime` 以降だったら何かをする

RequestLocalTime.current.requestedAt を使う

こちらが本記事でご紹介する方法。
どこのコードからでもリクエスト開始時点の時刻を得られます。

ThriftServerのクラスで`SetRequestLocalTimeFilter`フィルタを差し込みつつ...

class VerboseServiceServer extends ThriftServer
{
  // ...

  override def configureThrift(router: ThriftRouter) {
    router
      // other filters ...
      .filter[SetRequestLocalTimeFilter]
      .add[VerboseServiceController]
  }
}

`RequestLocalTime.current.requestedAt`を好きな箇所で呼び出す

  override val echo = handle(Echo) { args =>
    info(s"[PointA] Current time: ${RequestLocalTime.current.requestedAt}")

    debug("sleeping...")
    Thread.sleep(1000)

    doSomething

    info(s"[PointB] Current time: ${RequestLocalTime.current.requestedAt}")

    Future(s"You said: ${args.message}")
  }

  def doSomething: Unit = {
    ... // DBに `RequestLocalTime.current.requestedAt` の値を書き込む

    doAnother
  }

  def doAnother: Unit =
    if (RequestLocalTime.current.requestedAt > importantDateTime) ...  // リクエスト時点が `importantDateTime` 以降だったら何かをする

now 引数引き回しから解放されました。

RequestLocalTime の仕組み

com.twitter.finagle.context.Contexts を、リクエストごとに固有の領域として利用しています。

リクエスト開始時点において、この領域に OffsetDateTime.now を書き込んでやり、それを RequestLocalTime.current.requestedAt でどこからでも参照できるようにしています。

リクエスト開始時点において、この領域に OffsetDateTime.now を書き込んでやり

これを実現するために、 SetRequestLocalTimeFilter フィルタを差し込んでいます。

RequestLocalTime の実装

RequestLocalTime

package com.github.laysakura.requestlocaltime.filters

import java.time.OffsetDateTime

import com.twitter.finagle.Service
import com.twitter.finagle.context.Contexts
import com.twitter.finatra.thrift.{ThriftFilter, ThriftRequest}
import com.twitter.util.Future

case class RequestLocalTime(requestedAt: OffsetDateTime) {
  /**
    * f を実行している間は、 RequestLocalTime.current.requestedAt で、常に同一の時刻（リクエスト時点のもの）が見える。
    */
  def asCurrent[T](f: => T): T = RequestLocalTime.let(this)(f)
}

object RequestLocalTime {
  private val ctx = new Contexts.local.Key[RequestLocalTime]

  def current: RequestLocalTime = Contexts.local.get(ctx).get

  private def let[R](requestedAt: RequestLocalTime)(f: => R): R =
    Contexts.local.let(ctx, requestedAt)(f)
}

SetRequestLocalTimeFilter の実装

SetRequestLocalTimeFilter

class SetRequestLocalTimeFilter extends ThriftFilter {
  override def apply[T, U](request: ThriftRequest[T], service: Service[ThriftRequest[T], U]): Future[U] =
    RequestLocalTime(OffsetDateTime.now).asCurrent {
      service(request)  // Controllerの初めから終わりまでのコードがこれで実行されるので、その区間で RequestLocalTime.current.requestedAt を参照すると OffsetDateTime.now の結果が見える
    }
}

フル実装

https://github.com/laysakura/finatra-request-local-time に、 RequestLocalTime と SetRequestLocalTimeFilter のフル実装を含んだサンプルプロジェクトを作成しました。

$ sbt test

で挙動を確認できます。

発展的な話題

• com.twitter.finagle.context.Contexts は便利
  • ClientId や TraceId も Contexts を使って実現されている
• リクエスト開始時刻以外にも、リクエスト-レスポンスの間で一貫した値を何でも持たせられる
  • リクエストを投げたユーザのIDなどもこの仕組みで取れると便利そう

広告

株式会社FOLIOでは、finatra, finagle, thriftを使いこなして次世代オンライン証券を構築するエンジニアを募集中です。