Documentation

You are viewing the documentation for the 2.7.3 release in the 2.7.x series of releases. The latest stable release series is 3.0.x.

§The Logging API

Using logging in your application can be useful for monitoring, debugging, error tracking, and business intelligence. Play provides an API for logging which is accessed through the Logger object and uses Logback as the default logging engine.

§Logging architecture

The logging API uses a set of components that help you to implement an effective logging strategy.

§Logger

Your application can define Logger instances to send log message requests. Each Logger has a name which will appear in log messages and is used for configuration. The Logger API is based on SLF4J, and so Logger is based on the org.slf4j.Logger interface.

Loggers follow a hierarchical inheritance structure based on their naming. A logger is said to be an ancestor of another logger if its name followed by a dot is the prefix of descendant logger name. For example, a logger named “com.foo” is the ancestor of a logger named “com.foo.bar.Baz.” All loggers inherit from a root logger. Logger inheritance allows you to configure a set of loggers by configuring a common ancestor.

We recommend creating separately-named loggers for each class. Following this convention, the Play libraries use loggers namespaced under “play”, and many third party libraries will have loggers based on their class names.

§Log levels

Log levels are used to classify the severity of log messages. When you write a log request statement you will specify the severity and this will appear in generated log messages.

This is the set of available log levels, in decreasing order of severity.

In addition to classifying messages, log levels are used to configure severity thresholds on loggers and appenders. For example, a logger set to level INFO will log any request of level INFO or higher (INFO, WARN, ERROR) but will ignore requests of lower severities (DEBUG, TRACE). Using OFF will ignore all log requests.

§Appenders

The logging API allows logging requests to print to one or many output destinations called “appenders.” Appenders are specified in configuration and options exist for the console, files, databases, and other outputs.

Appenders combined with loggers can help you route and filter log messages. For example, you could use one appender for a logger that logs useful data for analytics and another appender for errors that is monitored by an operations team.

Note: For further information on architecture, see the Logback documentation.

§Using Loggers

First import the Logger class and companion object:

import play.api.Logger

§Creating loggers

You can create a new logger using the Logger.apply factory method with a name argument:

val accessLogger: Logger = Logger("access")

A common strategy for logging application events is to use a distinct logger per class using the class name. The logging API supports this with a factory method that takes a class argument:

val logger: Logger = Logger(this.getClass())

There is also a Logging trait that does this for you automatically and exposes a protected val logger:

import play.api.Logging

class MyClassWithLogging extends Logging {
  logger.info("Using the trait")
}

Once you have a Logger set up, you can use it to write log statements:

// Log some debug info
logger.debug("Attempting risky calculation.")

try {
  val result = riskyCalculation

  // Log result if successful
  logger.debug(s"Result=$result")
} catch {
  case t: Throwable => {
    // Log error with message and Throwable.
    logger.error("Exception with riskyCalculation", t)
  }
}

Using Play’s default logging configuration, these statements will produce console output similar to this:

[debug] c.e.s.MyClass - Attempting risky calculation.
[error] c.e.s.MyClass - Exception with riskyCalculation
java.lang.ArithmeticException: / by zero
    at controllers.Application.riskyCalculation(Application.java:20) ~[classes/:na]
    at controllers.Application.index(Application.java:11) ~[classes/:na]
    at Routes$$anonfun$routes$1$$anonfun$applyOrElse$1$$anonfun$apply$1.apply(routes_routing.scala:69) [classes/:na]
    at Routes$$anonfun$routes$1$$anonfun$applyOrElse$1$$anonfun$apply$1.apply(routes_routing.scala:69) [classes/:na]
    at play.core.Router$HandlerInvoker$$anon$8$$anon$2.invocation(Router.scala:203) [play_2.10-2.3-M1.jar:2.3-M1]

Note that the messages have the log level, logger name (in this case the class name, displayed in abbreviated form), message, and stack trace if a Throwable was used in the log request.

There is also a play.api.Logger singleton object that allows you to access a logger named application, but its use is deprecated in Play 2.7.0 and above. You should declare your own logger instances using one of the strategies defined above.

§Using Markers and Marker Contexts

The SLF4J API has a concept of markers, which act to enrich logging messages and mark out messages as being of special interest. Markers are especially useful for triggering and filtering – for example, OnMarkerEvaluator can send an email when a marker is seen, or particular flows can be marked out to their own appenders.

The Logger API provides access to markers through the play.api.MarkerContext trait.

You can create a MarkerContext with the Logger by using the MarkerContext.apply method:

val marker: org.slf4j.Marker = MarkerFactory.getMarker("SOMEMARKER")
val mc: MarkerContext        = MarkerContext(marker)

You can also provide a typed MarkerContext by extending from DefaultMarkerContext:

val someMarker: org.slf4j.Marker = MarkerFactory.getMarker("SOMEMARKER")
case object SomeMarkerContext extends play.api.DefaultMarkerContext(someMarker)

Once a MarkerContext has been created, it can be used with a logging statement, either explicitly:

// use a typed marker as input
logger.info("log message with explicit marker context with case object")(SomeMarkerContext)

// Use a specified marker.
val otherMarker: Marker               = MarkerFactory.getMarker("OTHER")
val otherMarkerContext: MarkerContext = MarkerContext(otherMarker)
logger.info("log message with explicit marker context")(otherMarkerContext)

Or implicitly:

val marker: Marker             = MarkerFactory.getMarker("SOMEMARKER")
implicit val mc: MarkerContext = MarkerContext(marker)

// Use the implicit MarkerContext in logger.info...
logger.info("log message with implicit marker context")

For convenience, there is an implicit conversion available from a Marker to a MarkerContext:

val mc: MarkerContext = MarkerFactory.getMarker("SOMEMARKER")

// Use the marker that has been implicitly converted to MarkerContext
logger.info("log message with implicit marker context")(mc)

Markers can be extremely useful, because they can carry contextual information across threads where MDC may not be available, by using a MarkerContext as an implicit parameter to methods to provide a logging context. For example, using Logstash Logback Encoder and an implicit conversion chain, request information can be encoded into logging statements automatically:

trait RequestMarkerContext {

  // Adding 'implicit request' enables implicit conversion chaining
  // See http://docs.scala-lang.org/tutorials/FAQ/chaining-implicits.html
  implicit def requestHeaderToMarkerContext(implicit request: RequestHeader): MarkerContext = {
    import net.logstash.logback.marker.LogstashMarker
    import net.logstash.logback.marker.Markers._

    val requestMarkers: LogstashMarker = append("host", request.host)
      .and(append("path", request.path))

    MarkerContext(requestMarkers)
  }

}

And then used in a controller and carried through Future that may use different execution contexts:

def asyncIndex = Action.async { implicit request =>
  Future {
    methodInOtherExecutionContext() // implicit conversion here
  }(otherExecutionContext)
}

def methodInOtherExecutionContext()(implicit mc: MarkerContext): Result = {
  logger.debug("index: ") // same as above
  Ok("testing")
}

Note that marker contexts are also very useful for “tracer bullet” style logging, where you want to log on a specific request without explicitly changing log levels. For example, you can add a marker only when certain conditions are met:

trait TracerMarker {
  import TracerMarker._

  implicit def requestHeaderToMarkerContext(implicit request: RequestHeader): MarkerContext = {
    val marker = org.slf4j.MarkerFactory.getDetachedMarker("dynamic") // base do-nothing marker...
    if (request.getQueryString("trace").nonEmpty) {
      marker.add(tracerMarker)
    }
    marker
  }
}

object TracerMarker {
  private val tracerMarker = org.slf4j.MarkerFactory.getMarker("TRACER")
}

class TracerBulletController @Inject()(cc: ControllerComponents) extends AbstractController(cc) with TracerMarker {
  private val logger = play.api.Logger("application")

  def index = Action { implicit request: Request[AnyContent] =>
    logger.trace("Only logged if queryString contains trace=true")

    Ok("hello world")
  }
}

And then trigger logging with the following TurboFilter in logback.xml: 

<turboFilter class="ch.qos.logback.classic.turbo.MarkerFilter">
  <Name>TRACER_FILTER</Name>
  <Marker>TRACER</Marker>
  <OnMatch>ACCEPT</OnMatch>
</turboFilter>

At which point you can dynamically set debug statements in response to input.

For more information about using Markers in logging, see TurboFilters and marker based triggering sections in the Logback manual.

§Logging patterns

Effective use of loggers can help you achieve many goals with the same tool:

import scala.concurrent.Future
import play.api.Logger
import play.api.mvc._
import javax.inject.Inject

class AccessLoggingAction @Inject()(parser: BodyParsers.Default)(implicit ec: ExecutionContext)
    extends ActionBuilderImpl(parser) {
  val accessLogger = Logger("access")
  override def invokeBlock[A](request: Request[A], block: (Request[A]) => Future[Result]) = {
    accessLogger.info(s"method=${request.method} uri=${request.uri} remote-address=${request.remoteAddress}")
    block(request)
  }
}

class Application @Inject()(val accessLoggingAction: AccessLoggingAction, cc: ControllerComponents)
    extends AbstractController(cc) {

  val logger = Logger(this.getClass())

  def index = accessLoggingAction {
    try {
      val result = riskyCalculation
      Ok(s"Result=$result")
    } catch {
      case t: Throwable => {
        logger.error("Exception with riskyCalculation", t)
        InternalServerError("Error in calculation: " + t.getMessage())
      }
    }
  }
}

This example uses action composition to define an AccessLoggingAction that will log request data to a logger named “access.” The Application controller uses this action and it also uses its own logger (named after its class) for application events. In configuration you could then route these loggers to different appenders, such as an access log and an application log.

The above design works well if you want to log request data for only specific actions. To log all requests, it’s better to use a filter:

import javax.inject.Inject
import akka.stream.Materializer
import scala.concurrent.ExecutionContext.Implicits.global
import scala.concurrent.Future
import play.api.Logger
import play.api.mvc._
import play.api._

class AccessLoggingFilter @Inject()(implicit val mat: Materializer) extends Filter {

  val accessLogger = Logger("access")

  def apply(next: (RequestHeader) => Future[Result])(request: RequestHeader): Future[Result] = {
    val resultFuture = next(request)

    resultFuture.foreach(result => {
      val msg = s"method=${request.method} uri=${request.uri} remote-address=${request.remoteAddress}" +
        s" status=${result.header.status}";
      accessLogger.info(msg)
    })

    resultFuture
  }
}

In the filter version we’ve added the response status to the log request by logging when the Future[Result] completes.

§Configuration

See configuring logging for details on configuration.

Next: Advanced topics