How to force Logger.debug output in Play! framework specs2 tests?

Question

By default all Logger output, visible when an application is running, is mute when the application is tested.

How to force the debugs, infos etc. to be shown in the specs2 reports?

Answer 1

First off, you may like some background why logging is disabled in test mode. This was Guillame Bort's answer to a question in the play forum (see this thread):

The logger is disabled in test mode for now because it was causing an huge PermGen space leak when running tests. But we are working to run tests in a forked JVM so we will enable it again soon.

As a workaround, I created my own logger like this (Scala code):

import play.api.{Play, LoggerLike, Logger}
import org.slf4j.LoggerFactory
import org.slf4j.impl.SimpleLoggerFactory

object MyLogger extends LoggerLike {

  val factory = if (Play.isTest(Play.current)) {
    new SimpleLoggerFactory()
  } else {
    LoggerFactory.getILoggerFactory
  }

  val redirectDebugToInfo = factory.isInstanceOf[SimpleLoggerFactory]

  val logger = factory.getLogger("application")

  def apply(name: String): Logger = new Logger(factory.getLogger(name))

  def apply[T](clazz: Class[T]): Logger = new Logger(factory.getLogger(clazz.getCanonicalName))

  // this method is to make debug statements to show up in test mode
  override def debug(m: => String) = {
    if (redirectDebugToInfo) {
      info(m)
    } else {
      super.debug(m)
    }
  }
}

I don't know how this code behaves regarding the PermGen leak in general, but so far I didn't have that problem. To make it work you need to add this dependency:

"org.slf4j" % "slf4j-simple" % "1.6.4"

Answer 2

If you're using FakeApplication, you can pass some configuration info:

  FakeApplication(additionalConfiguration = Map(
    "logger.application" -> "DEBUG"
  ))

That limits LOGGER output to debug and higher output.

I was surprised to observe that the setting is "sticky". If an early test uses FakeApplication, a later test that does not use FakeApplication will still use the same logging level.

Answer 3

I created a logger.xml file under conf such as this:

<configuration>
    <conversionRule conversionWord="coloredLevel" converterClass="play.api.Logger$ColoredLevel" />

    <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="ERROR" />
    <logger name="application" level="INFO" />

    <root level="ERROR">
        <appender-ref ref="STDOUT" />
    </root>
</configuration>

Then I start my play environment with the following command:

play -Dlogger.file=conf/logger.xml

Voila! Logging data in test. It does lead to memory leaks, but is invaluable during development.

Answer 4

If you're using sbt to run tests (which play does by default), you can set javaOptions in the Test task to control the logging configuration used.

Eg, in project/Build.scala:

javaOptions in Test      += "-Dlogger.file=conf/test-logger.xml"

More about the syntax of the test-logger.xml file here:

http://logback.qos.ch/manual/configuration.html

Answer 5

If you look at Play Logger source, you will see that logging is disabled in Test mode.

If you really want logging, you can create logging configuration file for testing and pass it to Play as system property "logger.file".

Example logging configuration (test-logger.xml file in project root):

<configuration>
  <conversionRule conversionWord="coloredLevel" converterClass="play.api.Logger$ColoredLevel" />
  <logger name="application" level="INFO">
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
      <encoder>
        <pattern>%coloredLevel %logger{15} - %message%n%xException{5}</pattern>
      </encoder>
    </appender>
  </logger>
</configuration>

Running tests:

JAVA_OPTS="-Dlogger.file=test-logger.xml" play test