completely rewrite logging: part 1

app/controllers/Analyse.scala

@@ -78,7 +78,7 @@ object Analyse extends LilaController {
  fuccess {
  chess.Replay.plyAtFen(pov.game.pgnMoves, initialFen, pov.game.variant, atFen).fold(
  err => {
- loginfo(s"RedirectAtFen: $err")
+ logger.info(s"RedirectAtFen: $err")
  Redirect(url)
  },
  ply => Redirect(s"$url#$ply"))

app/controllers/Fishnet.scala

@@ -13,7 +13,7 @@ object Fishnet extends LilaController {
 
  private def env = Env.fishnet
  private def api = env.api
- private val logger = play.api.Logger("fishnet")
+ override val logger = lila.log("fishnet")
 
  def acquire = ClientAction[JsonApi.Request.Acquire] { req =>
  client =>

app/controllers/Importer.scala

@@ -31,7 +31,7 @@ object Importer extends LilaController {
  } inject Redirect(routes.Round.watcher(game.id, "white"))
  } recover {
  case e =>
- logwarn(e.getMessage)
+ logger.branch("importer").warn("sendGame", e)
  Redirect(routes.Importer.importGame)
  }
  )

app/controllers/LilaController.scala

@@ -24,6 +24,8 @@ private[controllers] trait LilaController
 
  import Results._
 
+ protected val logger = lila.log("controller")
+
  protected implicit val LilaResultZero = Zero.instance[Result](Results.NotFound)
 
  protected implicit val LilaHtmlMonoid = lila.app.templating.Environment.LilaHtmlMonoid

app/controllers/Main.scala

@@ -89,7 +89,7 @@ object Main extends LilaController {
 
  def jslog(id: String) = Open { ctx =>
  val referer = HTTPRequest.referer(ctx.req)
- loginfo(s"[jslog] ${ctx.req.remoteAddress} ${ctx.userId} $referer")
+ logger.branch("jslog").info(s"${ctx.req.remoteAddress} ${ctx.userId} $referer")
  lila.mon.cheat.cssBot()
  ctx.userId.?? {
  Env.report.api.autoBotReport(_, referer)

app/controllers/Setup.scala

@@ -155,7 +155,10 @@ object Setup extends LilaController with TheftPrevention {
  def filter = OpenBody { implicit ctx =>
  implicit val req = ctx.body
  env.forms.filter(ctx).bindFromRequest.fold[Fu[Result]](
- f => fulogwarn(f.errors.toString) inject BadRequest(()),
+ f => {
+ logger.branch("setup").warn(f.errors.toString)
+ BadRequest(()).fuccess
+ },
  config => JsonOk(env.processor filter config inject config.render)
  )
  }

modules/api/src/main/Cli.scala

@@ -9,9 +9,11 @@ import makeTimeout.short
 
 private[api] final class Cli(bus: lila.common.Bus, renderer: ActorSelection) extends lila.common.Cli {
 
+ private val logger = lila.log("cli")
+
  def apply(args: List[String]): Fu[String] = run(args).map(_ + "\n") ~ {
  _ logFailure ("[cli] " + args.mkString(" ")) foreach { output =>
- loginfo("[cli] %s\n%s".format(args mkString " ", output))
+ logger.info("%s\n%s".format(args mkString " ", output))
  }
  }
 

modules/api/src/main/Env.scala

@@ -56,7 +56,8 @@ final class Env(
  .fold(Net.AssetVersion)(_.toInt max Net.AssetVersion)
  },
  timeToLive = 30.seconds,
- default = Net.AssetVersion)
+ default = Net.AssetVersion,
+ logger = lila.log("assetVersion"))
  def get = cache get true
  }
 

modules/api/src/main/RoundApiBalancer.scala

@@ -30,6 +30,7 @@ private[api] final class RoundApiBalancer(
 
  val router = system.actorOf(
  akka.routing.RoundRobinPool(nbActors).props(Props(new lila.hub.SequentialProvider {
+ val logger = lila.log("round").branch("balancer")
  val futureTimeout = 20.seconds
  def process = {
  case Player(pov, apiVersion, ctx) => {

modules/api/src/main/package.scala

@@ -1,3 +1,3 @@
 package lila
 
-package object api extends PackageObject with WithPlay 
+package object api extends PackageObject with WithPlay

modules/blog/src/main/LastPostCache.scala

@@ -14,7 +14,8 @@ final class LastPostCache(api: BlogApi, ttl: Duration, collection: String) {
  },
  timeToLive = ttl,
  default = Nil,
- awaitTime = 1.millisecond)
+ awaitTime = 1.millisecond,
+ logger = logger)
 
  def apply = cache get true
 

modules/blog/src/main/package.scala

@@ -1,3 +1,6 @@
 package lila
 
-package object blog extends PackageObject with WithPlay
+package object blog extends PackageObject with WithPlay {
+
+ private[blog] def logger = lila.log("blog")
+}

modules/bookmark/src/main/Cached.scala

@@ -1,14 +1,15 @@
 package lila.bookmark
 
-import scala.concurrent.duration._
 import lila.memo.MixedCache
+import scala.concurrent.duration._
 
 private[bookmark] final class Cached {
 
  private[bookmark] val gameIdsCache = MixedCache[String, Set[String]](
  BookmarkRepo.gameIdsByUserId,
  timeToLive = 1 day,
- default = _ => Set.empty)
+ default = _ => Set.empty,
+ logger = lila.log("bookmark"))
 
  def gameIds(userId: String) = gameIdsCache get userId
 

modules/common/src/main/PackageObject.scala

@@ -21,15 +21,6 @@ trait PackageObject extends Steroids with WithFuture {
  def nowTenths: Long = nowMillis / 100
  def nowSeconds: Int = (nowMillis / 1000).toInt
 
- lazy val logger = play.api.Logger("lila")
- def logdebug(s: String) { logger debug s }
- def loginfo(s: String) { logger info s }
- def logwarn(s: String) { logger warn s }
- def logerr(s: String) { logger error s }
- def fuloginfo(s: String) = fuccess { loginfo(s) }
- def fulogwarn(s: String) = fuccess { logwarn(s) }
- def fulogerr(s: String) = fuccess { logerr(s) }
-
  implicit final def runOptionT[F[+_], A](ot: OptionT[F, A]): F[Option[A]] = ot.run
 
  // from scalaz. We don't want to import all OptionTFunctions, because of the clash with `some`
@@ -223,16 +214,9 @@ trait WithPlay { self: PackageObject =>
 
  implicit final class LilaPimpedFutureZero[A: Zero](fua: Fu[A]) {
 
- def nevermind(msg: String): Fu[A] = fua recover {
- case e: lila.common.LilaException => recoverException(e, msg.some)
- case e: java.util.concurrent.TimeoutException => recoverException(e, msg.some)
- }
-
- def nevermind: Fu[A] = nevermind("")
-
- private def recoverException(e: Exception, msg: Option[String]) = {
- logwarn(msg.filter(_.nonEmpty).??(_ + ": ") + e.getMessage)
- zero[A]
+ def nevermind: Fu[A] = fua recover {
+ case e: lila.common.LilaException => zero[A]
+ case e: java.util.concurrent.TimeoutException => zero[A]
  }
  }
 

modules/common/src/main/Scheduler.scala

@@ -38,14 +38,14 @@ final class Scheduler(scheduler: akka.actor.Scheduler, enabled: Boolean, debug:
  enabled ! {
  val f = randomize(freq)
  val doDebug = debug && freq > 5.seconds
- info("schedule %s every %s".format(name, freq))
+ logger.info("schedule %s every %s".format(name, freq))
  scheduler.schedule(f, f) {
  val tagged = "(%s) %s".format(nextString(3), name)
- doDebug ! info(tagged)
+ doDebug ! logger.info(tagged)
  val start = nowMillis
  op effectFold (
- e => err("(%s) %s".format(tagged, e.getMessage)),
- _ => doDebug ! info(tagged + " - %d ms".format(nowMillis - start))
+ e => logger.error("(%s) %s".format(tagged, e.getMessage), e),
+ _ => doDebug ! logger.info(tagged + " - %d ms".format(nowMillis - start))
  )
  }
  }
@@ -58,13 +58,7 @@ final class Scheduler(scheduler: akka.actor.Scheduler, enabled: Boolean, debug:
  def after[A](delay: FiniteDuration)(op: => A) =
  akka.pattern.after(delay, scheduler)(fuccess(op))
 
- private def info(msg: String) {
- loginfo("[cron] " + msg)
- }
-
- private def err(msg: String) {
- logerr("[cron] " + msg)
- }
+ private def logger = lila.log("scheduler")
 
  private def randomize(d: FiniteDuration, ratio: Float = 0.05f): FiniteDuration =
  approximatly(ratio)(d.toMillis) millis

modules/common/src/main/log.scala

@@ -0,0 +1,32 @@
+package lila
+
+object log {
+
+ def apply(name: String): Logger = new Logger(name, identity)
+
+ final class Logger(
+ name: String,
+ transformer: String => String) extends play.api.LoggerLike {
+
+ val logger = org.slf4j.LoggerFactory getLogger name
+
+ def map(trans: String => String) = new Logger(
+ name = name,
+ transformer = msg => trans(transformer(msg)))
+
+ def prefix(p: String) = map(msg => s"$p: $msg")
+
+ def branch(childName: String) = new Logger(
+ name = s"$name.$childName",
+ transformer = transformer)
+
+ override def debug(message: => String) = super.debug(transformer(message))
+ override def debug(message: => String, error: => Throwable) = super.debug(transformer(message), error)
+ override def info(message: => String) = super.info(transformer(message))
+ override def info(message: => String, error: => Throwable) = super.info(transformer(message), error)
+ override def warn(message: => String) = super.warn(transformer(message))
+ override def warn(message: => String, error: => Throwable) = super.warn(transformer(message), error)
+ override def error(message: => String) = super.error(transformer(message))
+ override def error(message: => String, error: => Throwable) = super.error(transformer(message), error)
+ }
+}

modules/db/src/main/Env.scala

@@ -23,7 +23,7 @@ final class Env(
  parsedUri.db.fold[DefaultDB](sys error s"cannot resolve database from URI: $parsedUri") { dbUri =>
  val db = DB(dbUri, connection)
  registerDriverShutdownHook(driver)
- loginfo(s"""ReactiveMongoApi successfully started with DB '$dbUri'! Servers:\n\t\t${parsedUri.hosts.map { s => s"[${s._1}:${s._2}]" }.mkString("\n\t\t")}""")
+ logger.info(s"""ReactiveMongoApi successfully started with DB '$dbUri'! Servers: ${parsedUri.hosts.map { s => s"[${s._1}:${s._2}]" }.mkString("\n\t\t")}""")
  db
  }
  }

modules/db/src/main/Tube.scala

@@ -19,7 +19,7 @@ case class BsTube[Doc](handler: BSONHandler[BSONDocument, Doc]) extends Tube[Doc
  def read(bson: BSONDocument): Option[Doc] = handler readTry bson match {
  case Success(doc) => Some(doc)
  case Failure(err) =>
- logerr(s"[tube] Cannot read ${lila.db.BSON.debug(bson)}\n$err\n${err.printStackTrace}")
+ logger.error(s"[tube] Cannot read ${lila.db.BSON.debug(bson)}\n$err\n", err)
  None
  }
 
@@ -47,7 +47,7 @@ case class JsTube[Doc](
  fromMongo(js) match {
  case JsSuccess(v, _) => Some(v)
  case e =>
- logerr("[tube] Cannot read %s\n%s".format(js, e))
+ logger.error("[tube] Cannot read %s\n%s".format(js, e))
  None
  }
  }
@@ -57,7 +57,7 @@ case class JsTube[Doc](
  def write(doc: Doc): JsResult[JsObject] = writes(doc) match {
  case obj: JsObject => JsSuccess(obj)
  case something =>
- logerr(s"[tube] Cannot write $doc\ngot $something")
+ logger.error(s"[tube] Cannot write $doc\ngot $something")
  JsError()
  }
 

modules/db/src/main/package.scala

@@ -11,4 +11,6 @@ package object db extends PackageObject with WithPlay {
  def recoverDuplicateKey[A](f: WriteResult => A): PartialFunction[Throwable, A] = {
  case e: WriteResult if e.code.contains(11000) => f(e)
  }
+
+ private[db] def logger = lila.log("db")
 }

modules/forumSearch/src/main/ForumSearchApi.scala

@@ -35,7 +35,7 @@ final class ForumSearchApi(
 
  def reset = client match {
  case c: ESClientHttp => c.putMapping >> {
- loginfo(s"Index to ${c.index.name}")
+ lila.log("forumSearch").info(s"Index to ${c.index.name}")
  import lila.db.api._
  import lila.forum.tube.postTube
  $enumerate.bulk[Option[Post]]($query[Post](Json.obj()), 500) { postOptions =>

modules/forumSearch/src/main/package.scala

@@ -1,3 +1,3 @@
 package lila
 
-package object forumSearch extends PackageObject with WithPlay 
+package object forumSearch extends PackageObject with WithPlay

modules/game/src/main/Cli.scala

@@ -17,21 +17,20 @@ private[game] final class Cli(
  (days.headOption flatMap parseIntOption) | 30
  } map (_ mkString " ")
 
- case "game" :: "typecheck" :: Nil => {
- loginfo("Counting games...")
+ case "game" :: "typecheck" :: Nil =>
+ logger.info("Counting games...")
  val size = $count($select.all).await
  var nb = 0
  val bulkSize = 1000
  ($enumerate.bulk[Option[Game]]($query.all, bulkSize) { gameOptions =>
  val nbGames = gameOptions.flatten.size
  if (nbGames != bulkSize)
- logwarn("Built %d of %d games".format(nbGames, bulkSize))
+ logger.warn("Built %d of %d games".format(nbGames, bulkSize))
  nb = nb + nbGames
- loginfo("Typechecked %d of %d games".format(nb, size))
+ logger.info("Typechecked %d of %d games".format(nb, size))
  funit
  }).await(2.hours)
  fuccess("Done")
- }
  }
 
 }

modules/game/src/main/Player.scala

@@ -146,7 +146,7 @@ object Player {
  private def safeRange(range: Range, name: String)(userId: Option[String])(v: Int): Option[Int] =
  if (range contains v) Some(v)
  else {
- logwarn(s"game.Player: $userId $name=$v (range: ${range.min}-${range.max})")
+ logger.warn(s"Player $userId $name=$v (range: ${range.min}-${range.max})")
  None
  }
 

modules/game/src/main/package.scala

@@ -10,4 +10,6 @@ package object game extends PackageObject with WithPlay {
 
  implicit lazy val gameTube = Game.tube inColl Env.current.gameColl
  }
+
+ private[game] def logger = lila.log("game")
 }

modules/gameSearch/src/main/GameSearchApi.scala

@@ -65,7 +65,7 @@ final class GameSearchApi(client: ESClient) extends SearchReadApi[Game, Query] {
  Thread sleep 3000
  client match {
  case c: ESClientHttp =>
- loginfo(s"Drop ${c.index.name}")
+ logger.info(s"Drop ${c.index.name}")
  writeable = false
  Thread sleep 3000
  c.putMapping >> indexSince("2011-01-01")
@@ -77,11 +77,11 @@ final class GameSearchApi(client: ESClient) extends SearchReadApi[Game, Query] {
  parseDate(sinceStr).fold(fufail[Unit](s"Invalid date $sinceStr")) { since =>
  client match {
  case c: ESClientHttp =>
- loginfo(s"Index to ${c.index.name} since $since")
+ logger.info(s"Index to ${c.index.name} since $since")
  writeable = false
  Thread sleep 3000
  doIndex(c, since) >>- {
- loginfo("[game search] Completed indexation.")
+ logger.info("[game search] Completed indexation.")
  Thread sleep 3000
  writeable = true
  }

modules/gameSearch/src/main/package.scala

@@ -1,3 +1,6 @@
 package lila
 
-package object gameSearch extends PackageObject with WithPlay
+package object gameSearch extends PackageObject with WithPlay {
+
+ private[gameSearch] def logger = lila.log("gameSearch")
+}

modules/hub/src/main/FutureSequencer.scala

@@ -32,6 +32,7 @@ object FutureSequencer {
  }
 
  private final class FSequencer(
+ logger: lila.log.Logger,
  receiveTimeout: Option[FiniteDuration],
  executionTimeout: Option[FiniteDuration] = None) extends Actor {
 
@@ -77,7 +78,7 @@ object FutureSequencer {
  f(queue.size)
  self ! Done
  case x =>
- logwarn(s"[FSequencer] Unsupported message $x")
+ logger.warn(s"[FSequencer] Unsupported message $x")
  self ! Done
  }
  }

modules/hub/src/main/Sequencer.scala

@@ -8,7 +8,8 @@ import akka.actor._
 
 final class Sequencer(
  receiveTimeout: Option[FiniteDuration],
- executionTimeout: Option[FiniteDuration] = None) extends Actor {
+ executionTimeout: Option[FiniteDuration] = None,
+ logger: lila.log.Logger) extends Actor {
 
  receiveTimeout.foreach(context.setReceiveTimeout)
 
@@ -49,7 +50,7 @@ final class Sequencer(
  self ! Done
  }
  promiseOption foreach (_ completeWith future)
- case x => logwarn(s"[Sequencer] Unsupported message $x")
+ case x => logger.warn(s"[Sequencer] Unsupported message $x")
  }
  }
 }