petitviolet blog

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

    2017-12-17

    QiitaJavaScalaGAEgcpStackdriverLogging

    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 回リクエストを送っている。

    gae_logging_1.png

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

    gae_logging_2.png

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

    gae_logging_3.png

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

    gae_logging_4.png

    要するに、/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 はどうでもいい

      • 好きにスレッド(プール)作ってやりましょう
      • スレッド数とか自由に出来るのでパフォーマンスチューニングはやりやすいはず

    という結論になる。

    from: https://qiita.com/petitviolet/items/45cca6fe8787ca5d1633