Stackdriver Logging logs are misaligned in GAE SE for Java 8

If you output the log while asynchronously processing with the application on Google AppEngine Standard Environment for Java8, It is a story that fought against the problem that the log is not correctly linked to the request and is output as the log of another request, which is too detailed to be transmitted.

The language is Scala, and Skinny Micro is used.

Summary

First conclusion. GAE should use ThreadManager.createThreadForCurrentRequest instead of its own thread. If you don't mind the log shift in Stackdriver Logging, let's like it.

About prerequisite information

GAE SE for java8?

It became Generally Available in September 2017. Google Cloud Platform Blog: Java 8 on App Engine standard environment is now generally available

Log output on GAE SE

There is official documentation. Reading and Writing Application Logs

According to this, it seems that you should describe the log settings in logging.properties while outputting the log using java.util.logging. If you are using slf4j, you can use SLF4J JDK14 Binding.

Just use java.util.logging to output the log without worrying about it, and it will be displayed nicely in Stackdriver Logging. With GAE SE, this kind of thing is very convenient.

What does it mean that the log output is off?

If you use your own Thread and log output in it, it will be output as a log of another request. Stackdriver Logging has a function that collects logs for each request, and you can see the logs for each request as shown in the image below.

--The request is sent 3 times in the order of / sample / myEc → / sample / threadManagerEc → / sample / myEc.

-↓ Log output by the first request to / sample / myEc

-↓ Log output by the second request to / sample / threadManagerEc

-↓ Log output by the third request to / sample / myEc

In short, the log that should be output in the request to / sample / myEc is treated as that of another request / sample / threadManagerEc.

code

The code that shifts the log looks like this. As mentioned above, the language is Scala, and Skinny Micro is used.

It's a little long, but I put the whole thing on it.

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}

//Case class for parameters received by json
case class Param(text: String) extends AnyVal

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

  //Common processing as a controller
  private def _run(executionContext: ExecutionContext)(implicit ctx: SkinnyContext) = {
    log.info(s"[START]${LocalDateTime.now()} Thread: ${Thread.currentThread().getId}")
    
    // Future.Asynchronous processing with apply
    val resF: Future[String] = Future.apply {
      log.info(s"[Future-START]${LocalDateTime.now()} Thread: ${Thread.currentThread().getId}")
      Thread.sleep(1000)
      //From body to text of request=Get the parameter that is 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)  //Explicitly specify ExecutionContext
    
    //Meet the future
    val result = Await.result(resF, Duration.apply(3000, TimeUnit.MILLISECONDS))     
    log.info(s"[END]${LocalDateTime.now()} Thread: ${Thread.currentThread().getId}")
    result
  }

  //ExecutionContext with its own thread pool
  private val myExecutionContext: ExecutionContext =
    ExecutionContext.fromExecutor(Executors.newFixedThreadPool(3))

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

  //ExecutionContext using ThreadManager
  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 retrieves the value from Future` because async is not supported on GAE SE jetty. Servlet asynchronous processing support in App Engine Java 8 standard environment - Stack Overflow

Cause of log shift

ʻExecutionContext`, that is, the thread used for asynchronous processing is the cause.

The following is a summary of the code described in ↑ around ʻExecutionContext`.

--The path / sample / myEc prepares its own thread pool and uses it to generate ʻExecutionContext. --In the path / sample / threadManagerEc, ThreadManager.createThreadForCurrentRequest is used to create ʻExecutionContext.

It turns out that the log on the thread created without using ThreadManager is off.

Documentation about threads

This is the Java 7 documentation for Thread. Java 7 Runtime Environment

And this is the documentation for the Java 8 era. Java 8 Runtime Environment Click here for the document differences between Java 7 and 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().

So basically, you can freely generate and use Thread like new Thread (). And the continuation

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.

It says that you should use ThreadManager when using the App Engine API. Stackdriver Logging is also a GCP service, so it hits the App Engine API internally, so it probably won't work as expected unless it's a thread managed by ThreadManager.

From this

--I want Stackdriver Logging to log correctly --Use the thread managed by ThreadManager as the thread used for asynchronous processing. --I'm a little worried about performance because I have to make it every time (I haven't benchmarked it) --Stackdriver Logging doesn't matter ――Let's make threads (pools) as you like --Performance tuning should be easy because you can freely adjust the number of threads.

It comes to the conclusion.