logging rewrite: part 2

app/Env.scala

@@ -53,7 +53,7 @@ final class Env(
  domain = Env.api.Net.Domain
  )), name = RouterName)
 
- play.api.Logger("boot").info("Preloading modules")
+ lila.log.boot.info("Preloading modules")
  List(Env.socket,
  Env.site,
  Env.tournament,

app/controllers/LilaSocket.scala

@@ -14,7 +14,7 @@ object LilaSocket extends RequestGetter {
 
  private type AcceptType[A] = RequestHeader => Fu[Either[Result, (Iteratee[A, _], Enumerator[A])]]
 
- private val logger = play.api.Logger("ratelimit")
+ private val logger = lila.log("ratelimit")
 
  def rateLimited[A: FrameFormatter](consumer: TokenBucket.Consumer, name: String)(f: AcceptType[A]): WebSocket[A, A] =
  WebSocket[A, A] { req =>

app/controllers/Opening.scala

@@ -98,18 +98,4 @@ object Opening extends LilaController {
  )
  }
  }
-
- def importOne = Action.async(parse.json) { implicit req =>
- env.api.opening.importOne(req.body, ~get("token", req)) map { id =>
- Ok("kthxbye " + {
- val url = s"http:https://lichess.org/training/opening/$id"
- play.api.Logger("opening import").info(s"${req.remoteAddress} $url")
- url
- })
- } recover {
- case e =>
- play.api.Logger("opening import").warn(e.getMessage)
- BadRequest(e.getMessage)
- }
- }
 }

app/controllers/Prismic.scala

@@ -9,14 +9,16 @@ import lila.memo.AsyncCache
 
 object Prismic {
 
- private val logger = (level: Symbol, message: String) => level match {
- case 'DEBUG => play.api.Logger("prismic") debug message
- case 'ERROR => play.api.Logger("prismic") error message
- case _ => play.api.Logger("prismic") info message
+ private val logger = lila.log("prismic")
+
+ val prismicLogger = (level: Symbol, message: String) => level match {
+ case 'DEBUG => logger debug message
+ case 'ERROR => logger error message
+ case _ => logger info message
  }
 
  private val fetchPrismicApi = AsyncCache.single[PrismicApi](
- f = PrismicApi.get(Env.api.PrismicApiUrl, logger = logger),
+ f = PrismicApi.get(Env.api.PrismicApiUrl, logger = prismicLogger),
  timeToLive = 1 minute)
 
  def prismicApi = fetchPrismicApi(true)
@@ -42,7 +44,7 @@ object Prismic {
  }
  } recover {
  case e: Exception =>
- play.api.Logger("prismic").error(s"bookmark:$name $e")
+ logger.error(s"bookmark:$name $e")
  none
  }
 

conf/routes

@@ -369,7 +369,6 @@ GET /api/user controllers.Api.users
 GET /api/user/:name controllers.Api.user(name: String)
 GET /api/user/:name/games controllers.Api.userGames(name: String)
 GET /api/game/:id controllers.Api.game(id: String)
-POST /api/opening controllers.Opening.importOne
 GET /api/status controllers.Api.status
 
 # Misc

modules/api/src/main/Cli.scala

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

modules/api/src/main/RatingFest.scala

@@ -34,9 +34,7 @@ object RatingFest {
  def unrate(game: Game) =
  (game.whitePlayer.ratingDiff.isDefined || game.blackPlayer.ratingDiff.isDefined) ?? GameRepo.unrate(game.id).void
 
- def log(x: Any) {
- play.api.Logger.info(x.toString)
- }
+ def log(x: Any) = lila.log("ratingFest") info x.toString
 
  var nb = 0
  for {

modules/api/src/main/RoundApiBalancer.scala

@@ -15,6 +15,8 @@ private[api] final class RoundApiBalancer(
  api: RoundApi,
  nbActors: Int) {
 
+ private val logger = lila.log("round").branch("balancer")
+
  private object implementation {
 
  implicit val timeout = makeTimeout seconds 20
@@ -30,14 +32,14 @@ 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
+ val logger = RoundApiBalancer.this.logger
  def process = {
  case Player(pov, apiVersion, ctx) => {
  api.player(pov, apiVersion)(ctx) addFailureEffect { e =>
- play.api.Logger("RoundApiBalancer").error(s"$pov $e")
+ logger.error(pov.toString, e)
  }
- }.chronometer.logIfSlow(500, "RoundApiBalancer") { _ => s"inner player $pov" }.result
+ }.chronometer.logIfSlow(500, logger) { _ => s"inner player $pov" }.result
  case Watcher(pov, apiVersion, tv, analysis, initialFenO, withMoveTimes, withOpening, ctx) =>
  api.watcher(pov, apiVersion, tv, analysis, initialFenO, withMoveTimes, withOpening)(ctx)
  case UserAnalysis(pov, pref, initialFen, orientation, owner) =>
@@ -50,11 +52,11 @@ private[api] final class RoundApiBalancer(
 
  def player(pov: Pov, apiVersion: Int)(implicit ctx: Context): Fu[JsObject] = {
  router ? Player(pov, apiVersion, ctx) mapTo manifest[JsObject] addFailureEffect { e =>
- play.api.Logger("RoundApiBalancer").error(s"$pov $e")
+ logger.error(pov.toString, e)
  }
  }.chronometer
  .mon(_.round.api.player)
- .logIfSlow(500, "RoundApiBalancer") { _ => s"outer player $pov" }
+ .logIfSlow(500, logger) { _ => s"outer player $pov" }
  .result
 
  def watcher(pov: Pov, apiVersion: Int, tv: Option[lila.round.OnTv],

modules/blog/src/main/BlogApi.scala

@@ -27,14 +27,14 @@ final class BlogApi(prismicUrl: String, collection: String) {
  }
 
  private val cache = BuiltInCache(200)
- private val logger = (level: Symbol, message: String) => level match {
- case 'DEBUG => play.api.Logger("prismic") debug message
- case 'ERROR => play.api.Logger("prismic") error message
- case _ => play.api.Logger("prismic") info message
+ private val prismicLogger = (level: Symbol, message: String) => level match {
+ case 'DEBUG => logger debug message
+ case 'ERROR => logger error message
+ case _ => logger info message
  }
 
  private val fetchPrismicApi = AsyncCache.single[Api](
- f = Api.get(prismicUrl, cache = cache, logger = logger),
+ f = Api.get(prismicUrl, cache = cache, logger = prismicLogger),
  timeToLive = 10 seconds)
 
  def prismicApi = fetchPrismicApi(true)

modules/common/src/main/Chronometer.scala

@@ -6,15 +6,15 @@ object Chronometer {
 
  def millis = (nanos / 1000000).toInt
 
- def logIfSlow(threshold: Int, logger: String)(msg: A => String) = {
- if (millis >= threshold) play.api.Logger(logger).debug(s"<${millis}ms> ${msg(result)}")
+ def logIfSlow(threshold: Int, logger: lila.log.Logger)(msg: A => String) = {
+ if (millis >= threshold) logger.debug(s"<${millis}ms> ${msg(result)}")
  this
  }
  }
 
  case class FuLap[A](lap: Fu[Lap[A]]) {
 
- def logIfSlow(threshold: Int, logger: String)(msg: A => String) = {
+ def logIfSlow(threshold: Int, logger: lila.log.Logger)(msg: A => String) = {
  lap.foreach(_.logIfSlow(threshold, logger)(msg))
  this
  }

modules/common/src/main/DetectLanguage.scala

@@ -25,15 +25,15 @@ final class DetectLanguage(url: String, key: String) {
  )) map { response =>
  (response.json \ "data" \ "detections").asOpt[List[Detection]] match {
  case None =>
- play.api.Logger("DetectLanguage").warn("Invalide service response")
+ lila.log("DetectLanguage").warn(s"Invalide service response ${response.json}")
  None
  case Some(res) => res.filter(_.isReliable)
  .sortBy(-_.confidence)
  .headOption map (_.language) flatMap Lang.get
  }
  } recover {
  case e: Exception =>
- play.api.Logger("detect language").warn(e.getMessage)
+ lila.log("DetectLanguage").warn(e.getMessage, e)
  Lang("en").some
  }
 }

modules/common/src/main/PackageObject.scala

@@ -30,7 +30,7 @@ trait PackageObject extends Steroids with WithFuture {
 
  implicit final class LilaPimpedString(s: String) {
 
- def boot[A](v: => A): A = { play.api.Logger("boot").info(s); v }
+ def boot[A](v: => A): A = { lila.log.boot.info(s); v }
  }
 
  implicit final class LilaPimpedValid[A](v: Valid[A]) {
@@ -157,10 +157,9 @@ trait WithPlay { self: PackageObject =>
  def flatFold[B](fail: Exception => Fu[B], succ: A => Fu[B]): Fu[B] =
  fua flatMap succ recoverWith { case e: Exception => fail(e) }
 
- def logFailure(logger: => String, msg: Exception => String): Fu[A] = fua ~ (_ onFailure {
- case e: Exception => play.api.Logger(logger).warn(msg(e))
- })
- def logFailure(logger: => String): Fu[A] = logFailure(logger, _.toString)
+ def logFailure(logger: => lila.log.Logger, msg: Exception => String): Fu[A] =
+ addFailureEffect { e => logger.warn(msg(e), e) }
+ def logFailure(logger: => lila.log.Logger): Fu[A] = logFailure(logger, _.toString)
 
  def addEffect(effect: A => Unit) = fua ~ (_ foreach effect)
 

modules/common/src/main/log.scala

@@ -2,31 +2,14 @@ package lila
 
 object log {
 
- def apply(name: String): Logger = new Logger(name, identity)
+ def apply(name: String): Logger = new Logger(name)
 
- final class Logger(
- name: String,
- transformer: String => String) extends play.api.LoggerLike {
+ val boot = apply("boot")
 
- val logger = org.slf4j.LoggerFactory getLogger name
-
- def map(trans: String => String) = new Logger(
- name = name,
- transformer = msg => trans(transformer(msg)))
+ final class Logger(name: String) extends play.api.LoggerLike {
 
- def prefix(p: String) = map(msg => s"$p: $msg")
-
- def branch(childName: String) = new Logger(
- name = s"$name.$childName",
- transformer = transformer)
+ val logger = org.slf4j.LoggerFactory getLogger name
 
- 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)
+ def branch(childName: String) = new Logger(name = s"$name.$childName")
  }
 }

modules/common/src/main/mon.scala

@@ -320,5 +320,5 @@ object mon {
 
  private def nodots(s: String) = s.replace(".", "_")
 
- private val logger = play.api.Logger("monitor")
+ private val logger = lila.log("monitor")
 }

modules/explorer/src/main/ExplorerIndexer.scala

@@ -170,5 +170,5 @@ private final class ExplorerIndexer(
  }
  })
 
- private val logger = play.api.Logger("explorer")
+ private val logger = lila.log("explorer")
 }

modules/fishnet/src/main/AnalysisBuilder.scala

@@ -28,7 +28,7 @@ private object AnalysisBuilder {
  fufail(_),
  replay => UciToPgn(replay, uciAnalysis) match {
  case (analysis, errors) =>
- errors foreach { e => log.warn(s"[UciToPgn] $debug $e") }
+ errors foreach { e => logger.warn(s"[UciToPgn] $debug $e") }
  if (analysis.valid) {
  if (analysis.emptyRatio >= 1d / 10)
  fufail(s"Analysis $debug has ${analysis.nbEmptyInfos} empty infos out of ${analysis.infos.size}")

modules/fishnet/src/main/Cleaner.scala

@@ -27,7 +27,7 @@ private final class Cleaner(
  moveDb.find(_ acquiredBefore since).map { move =>
  moveDb updateOrGiveUp move.timeout
  clientTimeout(move)
- log.warn(s"Timeout move ${move.game.id}")
+ logger.warn(s"Timeout move ${move.game.id}")
  }
  scheduleMoves
  }
@@ -40,15 +40,15 @@ private final class Cleaner(
  }.map { ana =>
  repo.updateOrGiveUpAnalysis(ana.timeout) >>- {
  clientTimeout(ana)
- log.warn(s"Timeout analysis ${ana.game.id}")
+ logger.warn(s"Timeout analysis ${ana.game.id}")
  }
  }.sequenceFu.void
  } andThenAnyway scheduleAnalysis
 
  private def clientTimeout(work: Work) = work.acquiredByKey ?? repo.getClient foreach {
  _ foreach { client =>
  monitor.timeout(work, client)
- log.warn(s"Timeout client ${client.fullId}")
+ logger.warn(s"Timeout client ${client.fullId}")
  }
  }
 

modules/fishnet/src/main/FishnetApi.scala

@@ -38,15 +38,15 @@ final class FishnetApi(
  case Skill.All => acquireMove(client) orElse acquireAnalysis(client)
  }).chronometer
  .mon(_.fishnet.acquire time client.skill.key)
- .logIfSlow(100, "fishnet")(_ => s"acquire ${client.skill}")
+ .logIfSlow(100, logger)(_ => s"acquire ${client.skill}")
  .result
  .withTimeout(1 second, AcquireTimeout)
  .recover {
  case e: FutureSequencer.Timeout =>
- log.warn(s"[${client.skill}] Fishnet.acquire ${e.getMessage}")
+ logger.warn(s"[${client.skill}] Fishnet.acquire ${e.getMessage}")
  none
  case AcquireTimeout =>
- log.warn(s"[${client.skill}] Fishnet.acquire timed out")
+ logger.warn(s"[${client.skill}] Fishnet.acquire timed out")
  none
  } >>- monitor.acquire(client)
 
@@ -77,43 +77,43 @@ final class FishnetApi(
  moveDb.transaction { implicit txn =>
  moveDb.get(workId).filter(_ isAcquiredBy client) match {
  case None =>
- log.warn(s"Received unknown or unacquired move $workId by ${client.fullId}")
+ logger.warn(s"Received unknown or unacquired move $workId by ${client.fullId}")
  case Some(work) => data.move.uci match {
  case Some(uci) =>
  monitor.move(work, client)
  hub.actor.roundMap ! hubApi.map.Tell(work.game.id, hubApi.round.FishnetPlay(uci, work.currentFen))
  moveDb.delete(work)
  case _ =>
  monitor.failure(work, client)
- log.warn(s"Received invalid move ${data.move} by ${client.fullId}")
+ logger.warn(s"Received invalid move ${data.move} by ${client.fullId}")
  moveDb.updateOrGiveUp(work.invalid)
  }
  }
  }
  }.chronometer.mon(_.fishnet.move.post)
- .logIfSlow(100, "fishnet")(_ => "post move").result
+ .logIfSlow(100, logger)(_ => "post move").result
 
  def postAnalysis(workId: Work.Id, client: Client, data: JsonApi.Request.PostAnalysis): Funit = sequencer {
  repo.getAnalysis(workId).map(_.filter(_ isAcquiredBy client)) flatMap {
  case None =>
- log.warn(s"Received unknown or unacquired analysis $workId by ${client.fullId}")
+ logger.warn(s"Received unknown or unacquired analysis $workId by ${client.fullId}")
  fuccess(none)
  case Some(work) => AnalysisBuilder(client, work, data) flatMap { analysis =>
  monitor.analysis(work, client, data)
  repo.deleteAnalysis(work) inject analysis.some
  } recoverWith {
  case e: AnalysisBuilder.GameIsGone =>
- log.warn(s"Game ${work.game.id} was deleted by ${work.sender} before analysis completes")
+ logger.warn(s"Game ${work.game.id} was deleted by ${work.sender} before analysis completes")
  monitor.analysis(work, client, data)
  repo.deleteAnalysis(work) inject none
  case e: Exception =>
  monitor.failure(work, client)
- log.warn(s"Received invalid analysis $workId by ${client.fullId}: ${e.getMessage}")
+ logger.warn(s"Received invalid analysis $workId by ${client.fullId}: ${e.getMessage}")
  repo.updateOrGiveUpAnalysis(work.invalid) inject none
  }
  }
  }.chronometer.mon(_.fishnet.analysis.post)
- .logIfSlow(200, "fishnet") { res =>
+ .logIfSlow(200, logger) { res =>
  s"post analysis for ${res.??(_.id)}"
  }.result
  .flatMap { _ ?? saveAnalysis }

modules/fishnet/src/main/FishnetRepo.scala

@@ -43,7 +43,7 @@ private final class FishnetRepo(
  def getAnalysis(id: Work.Id) = analysisColl.find(selectWork(id)).one[Work.Analysis]
  def updateAnalysis(ana: Work.Analysis) = analysisColl.update(selectWork(ana.id), ana).void
  def deleteAnalysis(ana: Work.Analysis) = analysisColl.remove(selectWork(ana.id)).void
- def giveUpAnalysis(ana: Work.Analysis) = deleteAnalysis(ana) >>- log.warn(s"Give up on analysis $ana")
+ def giveUpAnalysis(ana: Work.Analysis) = deleteAnalysis(ana) >>- logger.warn(s"Give up on analysis $ana")
  def updateOrGiveUpAnalysis(ana: Work.Analysis) = if (ana.isOutOfTries) giveUpAnalysis(ana) else updateAnalysis(ana)
  def countAnalysis(acquired: Boolean) = analysisColl.count(BSONDocument(
  "acquired" -> BSONDocument("$exists" -> acquired)

modules/fishnet/src/main/MoveDB.scala

@@ -39,7 +39,7 @@ private final class MoveDB {
 
  def updateOrGiveUp(move: Move) = transaction { implicit txn =>
  if (move.isOutOfTries) {
- log.warn(s"Give up on move $move")
+ logger.warn(s"Give up on move $move")
  delete(move)
  }
  else update(move)

modules/fishnet/src/main/package.scala

@@ -2,5 +2,5 @@ package lila
 
 package object fishnet extends PackageObject with WithPlay {
 
- val log = play.api.Logger("fishnet")
+ private[fishnet] def logger = lila.log("fishnet")
 }