GAE SE for Java8でStackdriver Loggingのログがずれる問題

Google AppEngine Standard Environment for Java8に乗せたアプリケーションで非同期処理しつつログ出力すると、
ログがリクエストに正しく紐付かずに別のリクエストのログとして出力されてしまう、という細かすぎて伝わらない問題と戦った話です。

なお言語はScalaで、Skinny Microを使用。

まとめ

まず結論。
GAEでは独自のスレッドではなくThreadManager.createThreadForCurrentRequestを使いましょう。
Stackdriver Loggingでログがずれても問題なければ好きにしましょう。

前提情報について

GAE SE for java8?

2017年9月にGenerally Availableになった。
Google Cloud Platform Blog: Java 8 on App Engine standard environment is now generally available

GAE SEでlog出力

公式ドキュメントがある。
Reading and Writing Application Logs

これによるとjava.util.loggingを使ってログ出力しつつlogging.propertiesでログ設定を記述すればいいらしい。

slf4jを使っているならSLF4J JDK14 Bindingを使えば良い。

特に気にせずjava.util.loggingを使ってログ出力するだけでStackdriver Loggingにいい感じに表示される。
GAE SEだとこういうあたりが非常に便利。

ログ出力がずれるってどういうこと？

独自のThreadを使用してその中でログ出力すると、別のリクエストのログとして出力されてしまう。
Stackdriver Loggingはリクエストごとにログをまとめてくれる機能があり、以下の画像のようにリクエスト単位でログを見れる。

• /sample/myEc→/sample/threadManagerEc→/sample/myEcという順に3回リクエストを送っている。

• ↓1回目の/sample/myEcへのリクエストで出力されたログ

• ↓2回目の/sample/threadManagerEcへのリクエストで出力されたログ

• ↓3回目の/sample/myEcへのリクエストで出力されたログ

要するに、/sample/myEcへのリクエストで出力されるべきログが別のリクエストである/sample/threadManagerEcのものとして扱われてしまっている。

コード

ログがずれるコードはこんな感じ。
前述の通り言語はScalaで、Skinny Microを使用している。

やや長いが全体を載せる。

import java.time.LocalDateTime
import java.util.concurrent.{Executors, TimeUnit}

import com.google.appengine.api.ThreadManager
import skinny.micro.AsyncWebApp
import skinny.micro.context.SkinnyContext
import skinny.micro.contrib.json4s.JSONSupport

import scala.concurrent.duration.Duration
import scala.concurrent.{Await, ExecutionContext, Future}

// jsonで受け取るパラメータ用のcase class
case class Param(text: String) extends AnyVal

class SampleController extends AsyncWebApp with JSONSupport {
  private lazy val log = org.slf4j.LoggerFactory.getLogger(getClass)

  // controllerとしての処理を共通化
  private def _run(executionContext: ExecutionContext)(implicit ctx: SkinnyContext) = {
    log.info(s"[START]${LocalDateTime.now()} Thread: ${Thread.currentThread().getId}")

    // Future.applyで非同期処理
    val resF: Future[String] = Future.apply {
      log.info(s"[Future-START]${LocalDateTime.now()} Thread: ${Thread.currentThread().getId}")
      Thread.sleep(1000)
      // リクエストのbodyからtext=xxxとなっているパラメータを取得
      val param = fromJSONString[Param](request.body).get
      log.info(s"$requestPath param: $param")
      log.info(s"[Future-END]${LocalDateTime.now()} Thread: ${Thread.currentThread().getId}")
      param.toString
    }(executionContext)  // 明示的にExecutionContextを指定

    // Futureを待ち合わせる
    val result = Await.result(resF, Duration.apply(3000, TimeUnit.MILLISECONDS))     
    log.info(s"[END]${LocalDateTime.now()} Thread: ${Thread.currentThread().getId}")
    result
  }

  // 独自のスレッドプールを用いたExecutionContext
  private val myExecutionContext: ExecutionContext =
    ExecutionContext.fromExecutor(Executors.newFixedThreadPool(3))

  post("/sample/myEc") { implicit ctx =>
    _run(myExecutionContext)
  }

  // ThreadManagerを使ったExecutionContext
  private val threadManagerExecutionContext: ExecutionContext = new ExecutionContext {
    override def execute(runnable: Runnable): Unit =
      ThreadManager.createThreadForCurrentRequest(runnable).run()
    override def reportFailure(cause: Throwable): Unit =
      ExecutionContext.defaultReporter
  }

  post("/sample/threadManagerEc") { implicit ctx =>
    _run(threadManagerExecutionContext)
  }
}

Await.resultでFutureから値を取り出しているのは、GAE SEのjettyではasyncがサポートされていないため。
Servlet asynchronous processing support in App Engine Java 8 standard environment - Stack Overflow

ログがずれる原因

ExecutionContext、つまり非同期処理に用いたスレッドが原因。

↑に記載したコードについてExecutionContextあたりをまとめると以下。

• /sample/myEcというパスでは独自にスレッドプールを用意して、それを用いてExecutionContextを生成している
• /sample/threadManagerEcというパスではThreadManager.createThreadForCurrentRequestを使ってExecutionContextを生成している

ThreadManagerを使用せずに作成したスレッド上でのログはずれてしまうことがわかった。

スレッドについてのドキュメント

ThreadについてJava7のドキュメントはこれ。
Java 7 Runtime Environment

そして、Java8時代のドキュメントはこれ。
Java 8 Runtime Environment
Java7と8でのドキュメントの差分はこちら。

With the Java 8 runtime, you can still create threads that way, but you can also use Java's built-in APIs, for example new Thread().

ということなので、基本的にはnew Thread()みたいに自由にThreadを生成して使うことが出来る。
そしてその続きは、

Currently, if you want to call App Engine APIs (com.google.appengine.api.*), you must call those APIs from a request thread or from a thread created using the ThreadManager API.

となっていて、AppEngineのAPIを使う時はThreadManagerを使えと書いてある。
Stackdriver LoggingもGCPサービスなので内部的にはAppEngineのAPIを叩いているのでThreadManagerが管理しているスレッドでないと期待するようには動作してくれないということだろう。

このことから

• Stackdriver Loggingでログが正しく出て欲しい
  • 非同期処理に用いるスレッドにはThreadManagerが管理するスレッドを使用する
  • 毎回作る必要があるのでパフォーマンスちょっと気になる(ベンチマークはしていない)
• Stackdriver Loggingはどうでもいい
  • 好きにスレッド(プール)作ってやりましょう
  • スレッド数とか自由に出来るのでパフォーマンスチューニングはやりやすいはず

という結論になる。