From e39c0c16f43c6f12df89c0c17e580dd53176db3c Mon Sep 17 00:00:00 2001 From: Thibault Duplessis Date: Thu, 8 Dec 2022 15:31:52 +0100 Subject: [PATCH] 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 | 6 +- app/Env.scala | 2 + app/LoggerConfigurator.scala | 112 ++++++++++++++++++++ app/ProdServerStart.scala | 119 ++++++++++++++++++++++ build.sbt | 9 +- conf/{logback.xml => logger.dev.xml} | 0 conf/{prod-logger.xml => logger.prod.xml} | 0 project/BuildSettings.scala | 12 +-- project/Dependencies.scala | 2 +- 9 files changed, 245 insertions(+), 17 deletions(-) create mode 100644 app/LoggerConfigurator.scala create mode 100644 app/ProdServerStart.scala rename conf/{logback.xml => logger.dev.xml} (100%) rename conf/{prod-logger.xml => logger.prod.xml} (100%) diff --git a/app/AppLoader.scala b/app/AppLoader.scala index fef7afd82456d..3c0e76d4fd3d0 100644 --- a/app/AppLoader.scala +++ b/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 diff --git a/app/Env.scala b/app/Env.scala index 373bd3bcfddcf..154a967787860 100644 --- a/app/Env.scala +++ b/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, diff --git a/app/LoggerConfigurator.scala b/app/LoggerConfigurator.scala new file mode 100644 index 0000000000000..71c9d3572b1e6 --- /dev/null +++ b/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() + } +} diff --git a/app/ProdServerStart.scala b/app/ProdServerStart.scala new file mode 100644 index 0000000000000..0a7bf4372bc45 --- /dev/null +++ b/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) + } +} diff --git a/build.sbt b/build.sbt index cde080437f1f4..91eacb8ec9074 100644 --- a/build.sbt +++ b/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" diff --git a/conf/logback.xml b/conf/logger.dev.xml similarity index 100% rename from conf/logback.xml rename to conf/logger.dev.xml diff --git a/conf/prod-logger.xml b/conf/logger.prod.xml similarity index 100% rename from conf/prod-logger.xml rename to conf/logger.prod.xml diff --git a/project/BuildSettings.scala b/project/BuildSettings.scala index d8e1c77f46203..0dc458669a536 100644 --- a/project/BuildSettings.scala +++ b/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] = diff --git a/project/Dependencies.scala b/project/Dependencies.scala index 961123e664158..0fae151d8cbdb 100644 --- a/project/Dependencies.scala +++ b/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