Play 2.6 [Scala]: How to access the content of the log during a test?

Question

Lets say I have a route /log that triggers the MyController.iDoLogSometimes controller method:

class MyController extends Controller{
  def iDoLogSometimes = Action{
    request => 
     val hasProperty: Boolean = ??? //A request property check
     if(hasProperty) Logger.info("prop exist")
     else Logger.debug("prop does not exist")   
  }
}

Now, within a test I can send a FakeRequest with whatever properties I need; to cover both cases within my method. However I dont know how I can capture the Logger output and use some kind of must matcher for it.

Note that I do have logback.xml in my conf/ folder; and I do see the log in the console; during the run of the test.

Answer 1

It's not easy to reliably capture log output using most Java/Scala logging libraries since logs are global and access is concurrent. However, you can give it a go if you like. I recently did this in a Play test. I'm using specs2 instead of scalatest, but the idea for capturing the logs is the same:

import ch.qos.logback.classic.Logger
import ch.qos.logback.classic.spi.ILoggingEvent
import ch.qos.logback.core.AppenderBase
import org.slf4j.LoggerFactory
...
"not complain about invalid User-Agent headers" in {

  // This test modifies the global (!) logger to capture log messages.
  // The test will not be reliable when run concurrently. However, since
  // we're checking for the *absence* of log messages the worst thing
  // that will happen is that the test will pass when it should fail. We
  // should not get spurious failures which would cause our CI testing
  // to fail. I think it's still worth including this test because it
  // will still often report correct failures, even if it's not perfect.

  import scala.collection.immutable

  def recordLogEvents[T](block: => T): immutable.Seq[ILoggingEvent] = {

    /** Collects all log events that occur */
    class RecordingAppender extends AppenderBase[ILoggingEvent] {
      private val eventBuffer = ArrayBuffer[ILoggingEvent]()
      override def append(e: ILoggingEvent): Unit = synchronized {
        eventBuffer += e
      }
      def events: immutable.Seq[ILoggingEvent] = synchronized {
        eventBuffer.to[immutable.Seq]
      }
    }

    // Get the Logback root logger and attach a RecordingAppender
    val rootLogger = LoggerFactory.getLogger(org.slf4j.Logger.ROOT_LOGGER_NAME).asInstanceOf[Logger]
    val appender = new RecordingAppender()
    appender.setContext(rootLogger.getLoggerContext)
    appender.start()
    rootLogger.addAppender(appender)
    block
    rootLogger.detachAppender(appender)
    appender.stop()
    appender.events
  }

  withServerAndConfig()((Action, _) => Action { rh =>
    Results.Ok(rh.headers.get("User-Agent").toString)
  }) { port =>
    def testAgent[R: AsResult](agent: String) = {
      val logMessages = recordLogEvents {
        val Seq(response) = BasicHttpClient.makeRequests(port)(
          BasicRequest("GET", "/", "HTTP/1.1", Map(
            "User-Agent" -> agent
          ), "")
        )
        response.body must beLeft(s"Some($agent)")
      }
      logMessages.map(_.getFormattedMessage) must contain(contain(agent))
    }
    // These agent strings come from https://github.com/playframework/playframework/issues/7997
    testAgent("Mozilla/5.0 (iPhone; CPU iPhone OS 11_0_3 like Mac OS X) AppleWebKit/604.1.38 (KHTML, like Gecko) Mobile/15A432 [FBAN/FBIOS;FBAV/147.0.0.46.81;FBBV/76961488;FBDV/iPhone8,1;FBMD/iPhone;FBSN/iOS;FBSV/11.0.3;FBSS/2;FBCR/T-Mobile.pl;FBID/phone;FBLC/pl_PL;FBOP/5;FBRV/0]")
    testAgent("Mozilla/5.0 (Linux; Android 7.0; TRT-LX1 Build/HUAWEITRT-LX1; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/61.0.3163.98 Mobile Safari/537.36 [FB_IAB/FB4A;FBAV/148.0.0.51.62;]")
    testAgent("Mozilla/5.0 (Linux; Android 7.0; SM-G955F Build/NRD90M; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/62.0.3202.84 Mobile Safari/537.36 [FB_IAB/Orca-Android;FBAV/142.0.0.18.63;]")
  }

}