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}")
}
}
[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 の実装
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は便利 - リクエスト開始時刻以外にも、リクエスト-レスポンスの間で一貫した値を何でも持たせられる
- リクエストを投げたユーザのIDなどもこの仕組みで取れると便利そう
広告
株式会社FOLIOでは、finatra, finagle, thriftを使いこなして次世代オンライン証券を構築するエンジニアを募集中です。