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

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

なお言語はScalaで、[Skinny Micro](http://skinny-framework.org/documentation/micro.html)を使用。

## まとめ
まず結論。
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](https://cloudplatform.googleblog.com/2017/09/Java-8-on-App-Engine-Standard-environment-is-now-generally-available.html)

### GAE SEでlog出力

公式ドキュメントがある。
[Reading and Writing Application Logs](https://cloud.google.com/appengine/docs/standard/java/logs/#writing_application_logs)

これによると`java.util.logging`を使ってログ出力しつつ`logging.properties`でログ設定を記述すればいいらしい。  
slf4jを使っているなら[SLF4J JDK14 Binding](https://mvnrepository.com/artifact/org.slf4j/slf4j-jdk14)を使えば良い。

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

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

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

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

![gae_logging_1.png](https://qiita-image-store.s3.amazonaws.com/0/280/3af84e91-ee8a-f4cd-84ac-05aa60f722ab.png)

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

![gae_logging_2.png](https://qiita-image-store.s3.amazonaws.com/0/280/d524793e-bc0b-c45f-a1c3-9cf4880de228.png)

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

![gae_logging_3.png](https://qiita-image-store.s3.amazonaws.com/0/280/5e2b76c1-0b7d-2709-7b77-cff85d7d0d3e.png)

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

![gae_logging_4.png](https://qiita-image-store.s3.amazonaws.com/0/280/87a9b368-a722-474e-3527-e09721d51391.png)

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

### コード

ログがずれるコードはこんな感じ。
前述の通り言語はScalaで、[Skinny Micro](http://skinny-framework.org/documentation/micro.html)を使用している。

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

```scala
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](https://stackoverflow.com/questions/45638360/servlet-asynchronous-processing-support-in-app-engine-java-8-standard-environmen)

### ログがずれる原因

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

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

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

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

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

ThreadについてJava7のドキュメントはこれ。
[Java 7 Runtime Environment](https://cloud.google.com/appengine/docs/standard/java/runtime#threads)

そして、Java8時代のドキュメントはこれ。
[Java 8 Runtime Environment](https://cloud.google.com/appengine/docs/standard/java/runtime-java8#threads)
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はどうでもいい
  - 好きにスレッド(プール)作ってやりましょう
  - スレッド数とか自由に出来るのでパフォーマンスチューニングはやりやすいはず
  
という結論になる。