fixing logging WIP - moving play code to lila, configuring logback first

the logger debug on startup is due to the fact that
configuration uses logging before the logger is configured:

play Configuration.scala:
private[Configuration] val logger = Logger(getClass)

app/AppLoader.scala

@@ -2,7 +2,7 @@ package lila.app
 
 import akka.actor.{ ActorSystem, CoordinatedShutdown }
 import com.softwaremill.macwire.*
-import play.api.*
+import play.api.{ ApplicationLoader, Application, BuiltInComponentsFromContext }
 import play.api.http.HttpRequestHandler
 import play.api.libs.crypto.CookieSignerProvider
 import play.api.libs.ws.StandaloneWSClient
@@ -24,10 +24,6 @@ final class LilaComponents(ctx: ApplicationLoader.Context) extends BuiltInCompon
       .invoke(scala.concurrent.ExecutionContext)
       .asInstanceOf[scala.concurrent.ExecutionContext]
 
-  LoggerConfigurator(ctx.environment.classLoader).foreach {
-    _.configure(ctx.environment, ctx.initialConfiguration, Map.empty)
-  }
-
   lila.log("boot").info {
     val java             = System.getProperty("java.version")
     val mem              = Runtime.getRuntime.maxMemory() / 1024 / 1024

app/Env.scala

@@ -102,6 +102,8 @@ final class Env(
   val appVersionCommit  = config.getOptional[String]("app.version.commit")
   val appVersionMessage = config.getOptional[String]("app.version.message")
 
+  lila.log("plan").info("test!")
+  lila.log("plan").warn("test!")
   lazy val apiTimelineSetting = memo.settingStore[Int](
     "apiTimelineEntries",
     default = 10,

app/LoggerConfigurator.scala

@@ -0,0 +1,112 @@
+package lila.app
+
+import java.io.File
+import java.net.URL
+
+import ch.qos.logback.classic._
+import ch.qos.logback.classic.jul.LevelChangePropagator
+import ch.qos.logback.classic.util.ContextInitializer
+import ch.qos.logback.core.util._
+import org.slf4j.ILoggerFactory
+import org.slf4j.LoggerFactory
+import org.slf4j.bridge._
+import play.api._
+
+class LoggerConfigurator {
+  def loggerFactory: ILoggerFactory = {
+    LoggerFactory.getILoggerFactory
+  }
+
+  /** Initialize the Logger when there's no application ClassLoader available.
+    */
+  def init(rootPath: java.io.File, mode: Mode): Unit = {
+    val properties   = Map("application.home" -> rootPath.getAbsolutePath)
+    val resourceName = if (mode == Mode.Dev) "logback-play-dev.xml" else "logback-play-default.xml"
+    val resourceUrl  = Option(this.getClass.getClassLoader.getResource(resourceName))
+    configure(properties, resourceUrl)
+  }
+
+  def configure(): Unit = {
+
+    // Get an explicitly configured file URL
+    def explicitFileUrl = sys.props.get("logger.file").map(new File(_).toURI.toURL)
+
+    // Get an explicitly configured URL
+    def explicitUrl = sys.props.get("logger.url").map(new URL(_))
+
+    val configUrl = explicitFileUrl.orElse(explicitUrl)
+
+    val props = Map("application.home" -> new File(".").getAbsolutePath)
+
+    configure(props, configUrl)
+  }
+
+  def configure(properties: Map[String, String], config: Option[URL]): Unit = {
+    // Touching LoggerContext is not thread-safe, and so if you run several
+    // application tests at the same time (spec2 / scalatest with "new WithApplication()")
+    // then you will see NullPointerException as the array list loggerContextListenerList
+    // is accessed concurrently from several different threads.
+    //
+    // The workaround is to use a synchronized block around a singleton
+    // instance -- in this case, we use the StaticLoggerBinder's loggerFactory.
+    // loggerFactory.synchronized {
+      // Redirect JUL -> SL4FJ
+
+      // Remove existing handlers from JUL
+      SLF4JBridgeHandler.removeHandlersForRootLogger()
+
+      // Configure logback
+      val ctx = loggerFactory.asInstanceOf[LoggerContext]
+
+      ctx.reset()
+
+      // Set a level change propagator to minimize the overhead of JUL
+      //
+      // Please note that translating a java.util.logging event into SLF4J incurs the
+      // cost of constructing LogRecord instance regardless of whether the SLF4J logger
+      // is disabled for the given level. Consequently, j.u.l. to SLF4J translation can
+      // seriously increase the cost of disabled logging statements (60 fold or 6000%
+      // increase) and measurably impact the performance of enabled log statements
+      // (20% overall increase). Please note that as of logback-version 0.9.25,
+      // it is possible to completely eliminate the 60 fold translation overhead for
+      // disabled log statements with the help of LevelChangePropagator.
+      //
+      // https://www.slf4j.org/api/org/slf4j/bridge/SLF4JBridgeHandler.html
+      // https://logback.qos.ch/manual/configuration.html#LevelChangePropagator
+      val levelChangePropagator = new LevelChangePropagator()
+      levelChangePropagator.setContext(ctx)
+      levelChangePropagator.setResetJUL(true)
+      ctx.addListener(levelChangePropagator)
+      SLF4JBridgeHandler.install()
+
+      // Ensure that play.Logger and play.api.Logger are ignored when detecting file name and line number for
+      // logging
+      val frameworkPackages = ctx.getFrameworkPackages
+      frameworkPackages.add(classOf[play.api.Logger].getName)
+
+      properties.foreach { case (k, v) => ctx.putProperty(k, v) }
+
+      config match {
+        case Some(url) =>
+          val initializer = new ContextInitializer(ctx)
+          initializer.configureByResource(url)
+        case None =>
+          System.err.println("Could not detect a logback configuration file, not configuring logback")
+      }
+
+      StatusPrinter.printIfErrorsOccured(ctx)
+    // }
+  }
+
+  /** Shutdown the logger infrastructure.
+    */
+  def shutdown(): Unit = {
+    val ctx = loggerFactory.asInstanceOf[LoggerContext]
+    ctx.stop()
+
+    org.slf4j.bridge.SLF4JBridgeHandler.uninstall()
+
+    // Unset the global application mode for logging
+    play.api.Logger.unsetApplicationMode()
+  }
+}

app/ProdServerStart.scala

@@ -0,0 +1,119 @@
+package lila.app
+
+import java.io._
+import java.nio.file.FileAlreadyExistsException
+import java.nio.file.Files
+import java.nio.file.StandardOpenOption
+
+import scala.concurrent.Future
+
+import akka.Done
+import akka.actor.CoordinatedShutdown
+
+import play.api.{ Application, Environment, ApplicationLoader, Play, Configuration, Mode }
+import play.core.server.{
+  RealServerProcess,
+  ServerProcess,
+  Server,
+  ServerStartException,
+  ServerConfig,
+  ServerProvider
+}
+
+/** Used to start servers in 'prod' mode, the mode that is used in production. The application is loaded and
+  * started immediately.
+  */
+object ProdServerStart {
+
+  /** Start a prod mode server from the command line.
+    */
+  def main(args: Array[String]): Unit = start(new RealServerProcess(args.toIndexedSeq))
+
+  /** Starts a Play server and application for the given process. The settings for the server are based on
+    * values passed on the command line and in various system properties. Crash out by exiting the given
+    * process if there are any problems.
+    *
+    * @param process
+    *   The process (real or abstract) to use for starting the server.
+    */
+  def start(process: ServerProcess): Server = {
+    try {
+      new LoggerConfigurator().configure()
+      // Read settings
+      val config: ServerConfig = readServerConfigSettings(process)
+
+      // Start the application
+      val application: Application = {
+        val environment = Environment(config.rootDir, process.classLoader, config.mode)
+        val context     = ApplicationLoader.Context.create(environment)
+        val loader      = ApplicationLoader(context)
+        loader.load(context)
+      }
+      Play.start(application)
+
+      // Start the server
+      val serverProvider = ServerProvider.fromConfiguration(process.classLoader, config.configuration)
+      val server         = serverProvider.createServer(config, application)
+
+      process.addShutdownHook {
+        // Only run server stop if the shutdown reason is not defined. That means the
+        // process received a SIGTERM (or other acceptable signal) instead of being
+        // stopped because of CoordinatedShutdown, for example when downing a cluster.
+        // The reason for that is we want to avoid calling coordinated shutdown from
+        // inside a JVM shutdown hook if the trigger of the JVM shutdown hook was
+        // coordinated shutdown.
+        if (application.coordinatedShutdown.shutdownReason().isEmpty) {
+          server.stop()
+        }
+      }
+
+      server
+    } catch {
+      case ServerStartException(message, cause) => process.exit(message, cause)
+      case e: Throwable                         => process.exit("Oops, cannot start the server.", Some(e))
+    }
+  }
+
+  /** Read the server config from the current process's command line args and system properties.
+    */
+  def readServerConfigSettings(process: ServerProcess): ServerConfig = {
+    val configuration: Configuration = {
+      val rootDirArg    = process.args.headOption.map(new File(_))
+      val rootDirConfig = rootDirArg.fold(Map.empty[String, String])(ServerConfig.rootDirConfig(_))
+      Configuration.load(process.classLoader, process.properties, rootDirConfig, true)
+    }
+
+    val rootDir: File = {
+      val path = configuration
+        .getOptional[String]("play.server.dir")
+        .getOrElse(throw ServerStartException("No root server path supplied"))
+      val file = new File(path)
+      if (!file.isDirectory)
+        throw ServerStartException(s"Bad root server path: $path")
+      file
+    }
+
+    def parsePort(portType: String): Option[Int] = {
+      configuration.getOptional[String](s"play.server.$portType.port").filter(_ != "disabled").map { str =>
+        try Integer.parseInt(str)
+        catch {
+          case _: NumberFormatException =>
+            throw ServerStartException(s"Invalid ${portType.toUpperCase} port: $str")
+        }
+      }
+    }
+
+    val httpPort  = parsePort("http")
+    val httpsPort = parsePort("https")
+    val address   = configuration.getOptional[String]("play.server.http.address").getOrElse("0.0.0.0")
+
+    if (httpPort.orElse(httpsPort).isEmpty)
+      throw ServerStartException("Must provide either an HTTP or HTTPS port")
+
+    val mode =
+      if (configuration.getOptional[String]("play.mode").contains("prod")) Mode.Prod
+      else Mode.Dev
+
+    ServerConfig(rootDir, httpPort, httpsPort, address, mode, process.properties, configuration)
+  }
+}

build.sbt

@@ -12,6 +12,13 @@ lazy val root = Project("lila", file("."))
   .aggregate(api)
   .settings(buildSettings)
 
+version                                := lilaVersion
+organization                           := "org.lichess"
+Compile / doc / sources                := Seq.empty
+Compile / packageDoc / publishArtifact := false
+Compile / packageSrc / publishArtifact := false
+Compile / run / fork                   := true
+javaOptions ++= Seq("-Xms64m", "-Xmx512m", "-Dlogger.file=conf/logger.prod.xml")
 // shorter prod classpath
 scriptClasspath             := Seq("*")
 Compile / resourceDirectory := baseDirectory.value / "conf"
@@ -22,7 +29,7 @@ playDependencyClasspath := (Runtime / externalDependencyClasspath).value
 // playCommonClassloader   := PlayCommands.playCommonClassloaderTask.value
 // playCompileEverything := PlayCommands.playCompileEverythingTask.value.asInstanceOf[Seq[Analysis]]
 ivyLoggingLevel     := UpdateLogging.DownloadOnly
-Compile / mainClass := Some("play.core.server.ProdServerStart")
+Compile / mainClass := Some("lila.app.ProdServerStart")
 // Adds the Play application directory to the command line args passed to Play
 bashScriptExtraDefines += "addJava \"-Duser.dir=$(realpath \"$(cd \"${app_home}/..\"; pwd -P)\"  $(is_cygwin && echo \"fix\"))\"\n"
 // by default, compile any routes files in the root named "routes" or "*.routes"

project/BuildSettings.scala

@@ -14,19 +14,11 @@ object BuildSettings {
 
   def buildSettings =
     Defaults.coreDefaultSettings ++ Seq(
-      version      := lilaVersion,
-      organization := "org.lichess",
       resolvers ++= Seq(lilaMaven, sonashots),
       scalaVersion := globalScalaVersion,
-      scalacOptions ++= compilerOptions,
+      scalacOptions ++= compilerOptions
       // No bloop project for tests
-      Test / bloopGenerate := None,
-      // disable publishing doc and sources
-      Compile / doc / sources                := Seq.empty,
-      Compile / packageDoc / publishArtifact := false,
-      Compile / packageSrc / publishArtifact := false,
-      Compile / run / fork                   := true,
-      javaOptions ++= Seq("-Xms64m", "-Xmx512m")
+      // Test / bloopGenerate := None,
     )
 
   lazy val defaultLibs: Seq[ModuleID] =

project/Dependencies.scala

@@ -69,7 +69,7 @@ object Dependencies {
   }
 
   object play {
-    val playVersion = "2.8.18-lila_3.4"
+    val playVersion = "2.8.18-lila_3.5"
     val json        = "com.typesafe.play" %% "play-json"         % "2.10.0-RC7"
     val jsonJoda    = "com.typesafe.play" %% "play-json-joda"    % "2.10.0-RC7"
     val api         = "com.typesafe.play" %% "play"              % playVersion