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` 引数引き回し

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

```scala: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` を使う
こちらが本記事でご紹介する方法。
どこのコードからでもリクエスト開始時点の時刻を得られます。

```scala:ThriftServerのクラスで`SetRequestLocalTimeFilter`フィルタを差し込みつつ...
class VerboseServiceServer extends ThriftServer
{
  // ...

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

```scala: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](https://twitter.github.io/finagle/guide/Contexts.html) を、リクエストごとに固有の領域として利用しています。

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

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

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

### `RequestLocalTime` の実装
```scala: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を使いこなして次世代オンライン証券を構築するエンジニアを募集中です。