Fix logging

.gitignore

@@ -1,4 +1,5 @@
 target/
+logs/
 repository/
 dist/
 *.lock

framework/play/src/main/java/play/data/DynamicForm.java

@@ -21,8 +21,8 @@ public String get(String key) {
         return (String)get().getData().get(key);
     }
 
-    public DynamicForm bind() {
-        Form<Dynamic> form = super.bind();
+    public DynamicForm bindFromRequest() {
+        Form<Dynamic> form = super.bindFromRequest();
         return new DynamicForm(form.data, form.errors, form.value);
     }
 

framework/play/src/main/java/play/data/Form.java

@@ -42,10 +42,6 @@ public Form(Class<T> clazz) {
         this(clazz, new HashMap<String,String>(), new HashMap<String,List<ValidationError>>(), None());
     }
 
-    public Form(T t) {
-        this((Class<T>)t.getClass(), new HashMap<String,String>(), new HashMap<String,List<ValidationError>>(), Some(t));
-    }
-
     public Form(Class<T> clazz, Map<String,String> data, Map<String,List<ValidationError>> errors, Option<T> value) {
         this.backedType = clazz;
         this.data = data;
@@ -58,7 +54,7 @@ public Form(Class<T> clazz, Map<String,String> data, Map<String,List<ValidationE
         }
     }
 
-    public Form<T> bind() {
+    public Form<T> bindFromRequest() {
         Map<String,String> data = new HashMap<String,String>();
         Map<String,String[]> urlFormEncoded = play.mvc.Controller.request().urlFormEncoded();
         for(String key: urlFormEncoded.keySet()) {

framework/play/src/main/java/play/db/ebean/EbeanPlugin.java

@@ -83,6 +83,10 @@ public void onStart() {
 
     }
 
+    public void onStop() {
+        //com.avaje.ebeaninternal.server.lib.ShutdownManager.shutdown();
+    }
+
     public static String generateEvolutionScript(EbeanServer server, ServerConfig config) {
         DdlGenerator ddl = new DdlGenerator((SpiEbeanServer)server, config.getDatabasePlatform(), config);
         String ups = ddl.generateCreateDdl();

framework/play/src/main/java/play/mvc/Controller.java

@@ -58,10 +58,6 @@ public static <T> Form<T> form(Class<T> clazz) {
         return new Form(clazz);
     }
 
-    public static <T> Form<T> form(T t) {
-        return new Form(t);
-    }
-
     // -- Results
 
     public static Result TODO = new Todo();

framework/play/src/main/resources/conf/logger.xml

@@ -0,0 +1,31 @@
+<configuration>
+
+  <conversionRule conversionWord="coloredLevel" converterClass="play.api.ColoredLevel" />
+
+  <appender name="FILE" class="ch.qos.logback.core.FileAppender">
+     <file>${application.home}/logs/application.log</file>
+     <encoder>
+       <pattern>%date - [%level] - from %logger in %thread %n%message%n%xException%n</pattern>
+     </encoder>
+   </appender>
+
+  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
+    <encoder>
+      <pattern>%coloredLevel %logger{15} - %message%n%xException{5}</pattern>
+    </encoder>
+  </appender>
+
+  <logger name="play" level="INFO" />
+  <logger name="application" level="INFO" />
+
+  <!-- Off these ones as they are annoying, and anyway we manage configuration ourself -->
+  <logger name="com.avaje.ebean.config.PropertyMapLoader" level="OFF" />
+  <logger name="com.avaje.ebeaninternal.server.core.XmlConfigLoader" level="OFF" />
+  <logger name="com.avaje.ebeaninternal.server.lib.BackgroundThread" level="OFF" />
+
+  <root level="ERROR">
+    <appender-ref ref="STDOUT" />
+    <appender-ref ref="FILE" />
+  </root>
+
+</configuration>

framework/play/src/main/scala/play/api/Application.scala

@@ -27,6 +27,13 @@ import scala.collection.JavaConverters._
  */
 case class Application(path: File, classloader: ApplicationClassLoader, sources: Option[SourceMapper], mode: Play.Mode.Mode) {
 
+  // Reconfigure logger
+  Logger.configure(
+    getExistingFile("conf/logger.xml").map(_.toURI.toURL).getOrElse {
+      resource("conf/logger.xml").getOrElse(null)
+    },
+    Map("application.home" -> path.getAbsolutePath))
+
   /**
    * The global settings used by this application.
    * @see play.api.GlobalSettings
@@ -174,4 +181,18 @@ case class Application(path: File, classloader: ApplicationClassLoader, sources:
         .setScanners(new scanners.TypeAnnotationsScanner())).getStore.getTypesAnnotatedWith(annotation.getName).asScala.toSet
   }
 
+  def resource(name: String): Option[java.net.URL] = {
+    Option(classloader.getResource(Option(name).map {
+      case s if s.startsWith("/") => s.drop(1)
+      case s => s
+    }.get))
+  }
+
+  def resourceAsStream(name: String): Option[InputStream] = {
+    Option(classloader.getResourceAsStream(Option(name).map {
+      case s if s.startsWith("/") => s.drop(1)
+      case s => s
+    }.get))
+  }
+
 }

framework/play/src/main/scala/play/api/Exceptions.scala

@@ -2,7 +2,7 @@ package play.api
 
 import java.io.File
 
-case class PlayException(title: String, description: String, cause: Option[Throwable] = None) extends RuntimeException("%s -> %s".format(title, description), cause.orNull) {
+case class PlayException(title: String, description: String, cause: Option[Throwable] = None) extends RuntimeException("%s [%s]".format(title, description), cause.orNull) {
   val id = "x"
 }
 

framework/play/src/main/scala/play/api/Global.scala

@@ -19,7 +19,12 @@ trait GlobalSettings {
     router.actionFor(request)
   }
 
-  def onError(ex: Throwable): Result = {
+  def onError(request: RequestHeader, ex: Throwable): Result = {
+    Logger.error(
+      """
+      |
+      |! Internal server error, for request [%s] ->
+      |""".stripMargin.format(request), ex)
     InternalServerError(Option(Play._currentApp).map {
       case app if app.mode == Play.Mode.Dev => views.html.defaultpages.devError.f
       case app => views.html.defaultpages.error.f

framework/play/src/main/scala/play/api/Logger.scala

@@ -0,0 +1,100 @@
+package play.api
+
+import org.slf4j.{ LoggerFactory, Logger => Slf4jLogger }
+
+trait LoggerLike {
+
+  val logger: Slf4jLogger
+
+  lazy val isTraceEnabled = logger.isTraceEnabled
+  lazy val isDebugEnabled = logger.isDebugEnabled
+  lazy val isInfoEnabled = logger.isInfoEnabled
+  lazy val isWarnEnabled = logger.isWarnEnabled
+  lazy val isErrorEnabled = logger.isWarnEnabled
+
+  def trace(message: String) { logger.trace(message) }
+  def trace(message: String, error: Throwable) { logger.trace(message, error) }
+
+  def debug(message: String) { logger.debug(message) }
+  def debug(message: String, error: Throwable) { logger.debug(message, error) }
+
+  def info(message: String) { logger.info(message) }
+  def info(message: String, error: Throwable) { logger.info(message, error) }
+
+  def warn(message: String) { logger.warn(message) }
+  def warn(message: String, error: Throwable) { logger.warn(message, error) }
+
+  def error(message: String) { logger.error(message) }
+  def error(message: String, error: Throwable) { logger.error(message, error) }
+
+}
+
+class Logger(val logger: Slf4jLogger) extends LoggerLike
+
+object Logger extends LoggerLike {
+
+  val logger = LoggerFactory.getLogger("application")
+
+  def apply(name: String) = new Logger(LoggerFactory.getLogger(name))
+  def apply[T](clazz: Class[T]) = new Logger(LoggerFactory.getLogger(clazz))
+
+  def configure(configFile: java.net.URL, properties: Map[String, String] = Map.empty) = {
+
+    // Redirect JUL -> SL4J
+    {
+      import org.slf4j.bridge._
+      import java.util.logging._
+
+      Option(java.util.logging.Logger.getLogger("")).map { root =>
+        root.setLevel(Level.FINEST)
+        root.getHandlers.foreach(root.removeHandler(_))
+      }
+
+      SLF4JBridgeHandler.install()
+    }
+
+    // Configure logback
+    {
+      import org.slf4j._
+
+      import ch.qos.logback.classic.joran._
+      import ch.qos.logback.core.util._
+      import ch.qos.logback.classic._
+
+      val ctx = LoggerFactory.getILoggerFactory.asInstanceOf[LoggerContext]
+      try {
+        val configurator = new JoranConfigurator
+        configurator.setContext(ctx)
+        ctx.reset
+        properties.map {
+          case (name, value) => ctx.putProperty(name, value)
+        }
+        configurator.doConfigure(configFile)
+      } catch {
+        case _ =>
+      }
+
+      StatusPrinter.printInCaseOfErrorsOrWarnings(ctx)
+    }
+
+  }
+
+}
+
+import ch.qos.logback.classic._
+import ch.qos.logback.classic.spi._
+import ch.qos.logback.classic.pattern._
+
+class ColoredLevel extends ClassicConverter {
+
+  def convert(event: ILoggingEvent) = {
+    event.getLevel match {
+      case Level.TRACE => "[\u001b[0;35mtrace\u001b[m]"
+      case Level.DEBUG => "[\u001b[0;36mdebug\u001b[m]"
+      case Level.INFO => "[\u001b[0;37minfo\u001b[m]"
+      case Level.WARN => "[\u001b[0;33mwarn\u001b[m]"
+      case Level.ERROR => "[\u001b[0;31merror\u001b[m]"
+    }
+  }
+
+}

framework/play/src/main/scala/play/api/Play.scala

@@ -24,25 +24,32 @@ object Play {
   def start(app: Application) {
 
     // First stop previous app if exists
-    Option(_currentApp).map {
-      _.plugins.values.foreach { p =>
-        try { p.onStop } catch { case _ => }
-      }
-    }
+    stop()
 
     _currentApp = app
 
-    println("Application has restarted")
+    if (app.mode == Mode.Dev) {
+      println()
+      println(new jline.ANSIBuffer().magenta("--- (RELOAD) ---"))
+      println()
+    }
 
     app.plugins.values.foreach(_.onStart)
 
+    Logger("play").info("Application is started")
+
+  }
+
+  def stop() {
+    Option(_currentApp).map {
+      _.plugins.values.foreach { p =>
+        try { p.onStop } catch { case _ => }
+      }
+    }
   }
 
   def resourceAsStream(name: String)(implicit app: Application): Option[InputStream] = {
-    Option(app.classloader.getResourceAsStream(Option(name).map {
-      case s if s.startsWith("/") => s.drop(1)
-      case s => s
-    }.get))
+    app.resourceAsStream(name)
   }
 
   def getFile(subPath: String)(implicit app: Application) = app.getFile(subPath)

framework/play/src/main/scala/play/api/db/DB.scala

@@ -120,7 +120,7 @@ class DBPlugin(app: Application) extends Plugin {
       case (name, (ds, config)) => {
         try {
           ds.getConnection.close()
-          println("database:" + name + " connected at " + ds.getJdbcUrl)
+          Logger("play").info("database [" + name + "] connected at " + ds.getJdbcUrl)
         } catch {
           case e => {
             throw app.configuration.reportError(config, "Cannot connect to database at [" + ds.getJdbcUrl + "]", Some(e.getCause))

framework/play/src/main/scala/play/api/db/evolutions/Evolutions.scala

@@ -321,7 +321,7 @@ object OfflineEvolutions {
         Configuration.fromFile(new File(applicationPath, "conf/application.conf")).sub("db." + dbName), classloader)))
     val script = Evolutions.evolutionScript(api, applicationPath, dbName)
 
-    println("Applying evolution script for database '" + dbName + "':\n\n" + Evolutions.toHumanReadableScript(script))
+    Logger("play").warn("Applying evolution script for database '" + dbName + "':\n\n" + Evolutions.toHumanReadableScript(script))
 
     Evolutions.applyScript(api, dbName, script)
 

framework/play/src/main/scala/play/core/ApplicationProvider.scala

@@ -53,7 +53,8 @@ class StaticApplication(applicationPath: File) extends ApplicationProvider {
 
 abstract class ReloadableApplication(applicationPath: File) extends ApplicationProvider {
 
-  Logger.log("Running the application from SBT, auto-reloading is enabled")
+  println()
+  println("Running the application from SBT, auto-reloading is enabled")
 
   var lastState: Either[PlayException, Application] = Left(PlayException("Not initialized", "?"))
 

framework/play/src/main/scala/play/core/Invoker.scala

@@ -50,10 +50,9 @@ class Invoker extends Actor {
         }
       } catch {
         case e => try {
-          e.printStackTrace()
-          app.global.onError(e)
+          app.global.onError(request, e)
         } catch {
-          case e => DefaultGlobal.onError(e)
+          case e => DefaultGlobal.onError(request, e)
         }
       }
 

framework/play/src/main/scala/play/core/server/NettyServer.scala

@@ -405,10 +405,11 @@ class NettyServer(appProvider: ApplicationProvider) extends Server {
 
   allChannels.add(bootstrap.bind(new java.net.InetSocketAddress(9000)))
 
-  Logger.log("Listening for HTTP on port 9000...")
+  Logger("play").info("Listening for HTTP on port 9000...")
 
   def stop() {
-    Logger.log("Stopping Play server...")
+    Play.stop()
+    Logger("play").warn("Stopping server...")
     allChannels.close().awaitUninterruptibly()
     bootstrap.releaseExternalResources()
   }
@@ -429,11 +430,11 @@ object NettyServer {
           val pidFile = new File(applicationPath, "RUNNING_PID")
 
           if (pidFile.exists) {
-            Logger.log("This application is already running (Or delete the RUNNING_PID file).")
+            println("This application is already running (Or delete the RUNNING_PID file).")
             System.exit(-1)
           }
 
-          Logger.log("Process ID is " + pid)
+          println("Process ID is " + pid)
 
           new FileOutputStream(pidFile).write(pid.getBytes)
           Runtime.getRuntime.addShutdownHook(new Thread {
@@ -448,7 +449,8 @@ object NettyServer {
             new StaticApplication(applicationPath))
         } catch {
           case e => {
-            Logger.log("Oops, cannot start the server -> " + e.getMessage)
+            println("Oops, cannot start the server.")
+            e.printStackTrace()
             System.exit(-1)
           }
         }