Logging is a really important feature every application must have. Without it, it’s nearly impossible to know what your application is doing, how long does it take it, if it is failing, and if it is, why.
With this in mind, play added logging support to it’s framework, using logback as logging implementation, and giving access to it through the Logger class.
The logging API provides easy to use and very efficient tools to implement an effective logging strategy, which will make it easier to debug and monitor your application.
1. The Concept
Most logging frameworks, including play’s logging support, provide components which receive a logging request and send them to an appender, which will finally output the log (in most cases via UDP, the file system or even the console).
For severity classification, logback provides log levels:
- OFF: Turn off logging
- ERROR: Application’s errors, unexpected situations, stuff that should not happen
- WARNING: Almost errors, unexpected stuff that is not necessarily an error, things which should be noticed but with “this could be right” in mind
- INFO: Interesting runtime events
- DEBUG: Detailed information which could be useful when tracking an error or debugging the application
- TRACE: Most detailed information that could be useful in some situations but you don’t want to see all the time
Loggers can be configured to show only messages which have an “above the threshold” severity. This means you can define a threshold of “DEBUG” and you’ll only see messages which are above this threshold (DEBUG, INFO, WARNING, ERROR). You can even define a threshold of “ERROR” and only see ERROR messages. Then, if you are tracking a bug in a production environment, just change this threshold to debug or trace and see every teeny tiny detail of the process you are debugging.
An application can define any number of loggers with unique names, which have hierarchy, and everyone inherits from a root logger. Let’s say we have a logger called application, and a logger called application.controllers. Logback will automatically assume application is an ancestor of application.controllers, and then apply to application.controllers every configuration of application which is not overwritten by it. And the same goes to application and the root logger.
This means we can configure application with a threshold of WARNING, and every logger which inherits from it will have the same threshold unless it’s explicitly overwritten.
Now we got the concept, let’s write some code. Have a look at this example of how to write rest services in a play application, and then come back to add some useful logging to it.
2. The Code
You’ll see there is a directory called conf in project’s root directory, and a file called logback.xml in it. That is logback’s configuration file, which play will load automatically. Let’s have a look:
logback.xml
<configuration>
<conversionRule conversionWord="coloredLevel" converterClass="play.api.Logger$ColoredLevel" />
<!--Appenders-->
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%coloredLevel - %logger - %message%n%xException</pattern>
</encoder>
</appender>
<!--
The logger name is typically the Java/Scala package name.
This configures the log level to log at for a package and its children packages.
-->
<!--Loggers-->
<logger name="play" level="INFO" />
<logger name="application" level="DEBUG" />
<!--Root logger-->
<root level="ERROR">
<appender-ref ref="STDOUT" />
</root>
</configuration>
So, what’s going on here? This is a very basic logback configuration. It defines an appender called STDOUT, which uses logback’s ConsoleApender. If you refer to logback’s documentation, you will find every available appender, how to configure them and what do they do.
It also defines three loggers: play, application, root.
The root logger is mandatory, is the ancestor of every other logger. The play logger will be the one play uses for it’s internal logging. The application logger is the ancestor of every logger located in a package named application and all its subpackages.
Let’s see how do we implement logging in our application:
PersonController.scala
package controllers
import model.Person
import play.api.Logger
import play.api.libs.functional.syntax._
import play.api.libs.json._
import play.api.mvc._
import scala.collection.mutable
class PersonController extends Controller {
val repository: mutable.MutableList[Person] = new mutable.MutableList[Person]()
val logger: Logger = Logger(this.getClass())
implicit val personWrites: Writes[Person] = (
(JsPath \ "name").write[String] and
(JsPath \ "age").write[Int]
)(unlift(Person.unapply))
implicit val personReads: Reads[Person] = (
(JsPath \ "name").read[String] and
(JsPath \ "age").read[Int]
)(Person.apply _)
def all = Action {
logger.info("requested to retrieve all people")
logger.info(s"returning ${repository.size} people")
Ok(Json.toJson(repository)).as(JSON)
}
def insert = Action(BodyParsers.parse.json) { request =>
logger.info("requested to insert person")
logger.trace(s"received json: ${request.body.toString()}")
request.body.validate[Person].fold(
errors => {
logger.error(s"${errors.toString()} while trying to insert person")
BadRequest("invalid json person")
},
person => {
logger.debug(s"person to insert: ${person.toString}")
repository.+=(person)
logger.info("successfully inserter person")
Ok
}
)
}
}
PersonController.java
package controllers;
import com.fasterxml.jackson.databind.JsonNode;
import com.fasterxml.jackson.databind.node.ArrayNode;
import com.fasterxml.jackson.databind.node.ObjectNode;
import com.google.common.base.Preconditions;
import org.apache.commons.lang3.StringUtils;
import org.apache.commons.lang3.builder.ToStringBuilder;
import play.*;
import play.libs.Json;
import play.mvc.*;
import model.Person;
import java.util.LinkedList;
import java.util.List;
public class PersonController extends Controller {
private static final Logger.ALogger logger = Logger.of(PersonController.class);
private final List repository = new LinkedList();
public Result all() {
logger.info("retrieving all people");
ArrayNode result = Json.newArray();
repository.forEach(p -> {
logger.trace("person to retrieve: {}", ToStringBuilder.reflectionToString(p));
ObjectNode node = Json.newObject();
node.put("name", p.getName());
node.put("age", p.getAge());
logger.trace("json: {}", node.toString());
result.add(node);
});
logger.info("retrieving {} people", result.size());
return ok(result);
}
@BodyParser.Of(BodyParser.Json.class)
public Result insert() {
logger.info("requested to insert person");
JsonNode json = request().body().asJson();
logger.trace("received json: {}", json.toString());
try {
logger.trace("interpreting json");
String name = json.findPath("name").textValue();
Preconditions.checkArgument(StringUtils.isNotBlank(name));
int age = json.findPath("age").intValue();
final Person p = new Person(name, age);
logger.debug("person to insert: {}", ToStringBuilder.reflectionToString(p));
repository.add(p);
logger.info("successfully inserted person");
return ok();
} catch (Exception e) {
logger.error("there was an error while trying to insert person", e);
return internalServerError();
}
}
}
If we run our application and execute our insert action, like this:
curl -v --request POST --header "Content-Type: application/json" --data '{ "name": "Michael", "age": 21 }' http://localhost:9000/people
We’ll see something like:
[info] - play.api.Play - Application started (Dev)
Yeah, well, nothing. That’s because the root logger has an ERROR threshold configured. Let’s write a logger for our controllers package to be able to see what’s going on there:
logback.xml
<configuration>
<conversionRule conversionWord="coloredLevel" converterClass="play.api.Logger$ColoredLevel" />
<!--Appenders-->
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%coloredLevel - %logger - %message%n%xException</pattern>
</encoder>
</appender>
<!--
The logger name is typically the Java/Scala package name.
This configures the log level to log at for a package and its children packages.
-->
<!--Loggers-->
<logger name="play" level="INFO" />
<logger name="controllers" level="TRACE" />
<!--Root logger-->
<root level="ERROR">
<appender-ref ref="STDOUT" />
</root>
</configuration>
Now, if we repeat the exercise we’ll see something like:
[info] - play.api.Play - Application started (Dev)
[info] - controllers.PersonController - requested to insert person
[trace] - controllers.PersonController - received json: {"name":"Michael","age":21}
[trace] - controllers.PersonController - interpreting json
[debug] - controllers.PersonController - person to insert: model.Person@545dd470[name=Michael,age=21]
[info] - controllers.PersonController - successfully inserted person
That’s actually useful. In our application we defined a Logger for our class, and log some actually useful information. Our application is now telling us what was it requested to do, the parameters sent to it, the object that came out of it and the status of the whole process.
Now, this is nice. But in real life we need more information to know what’s really happening, and we need it automatically added to that log.
For example, I’d like to see the exact moment when a line was written to my log file, and I don’t want to manually instantiate a Date and add it to my log, it’s not very scalable. Well, logback has a solution for that problem, and that’s the pattern of our appender:
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%coloredLevel - %logger - %message%n%xException</pattern>
</encoder>
</appender>
This pattern is saying: my message might have the level dash the logger dash my message and an exception. And we can add almost anything to it. So what happens if we change it to:
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%d - %coloredLevel - %logger - %message%n%xException</pattern>
</encoder>
</appender>
That %d is telling logback to add the date to my log line:
2015-11-23 22:55:32,307 - [info] - play.api.Play - Application started (Dev)
2015-11-23 22:55:32,318 - [info] - controllers.PersonController - requested to insert person
2015-11-23 22:55:32,319 - [trace] - controllers.PersonController - received json: {"name":"Michael","age":21}
2015-11-23 22:55:32,319 - [trace] - controllers.PersonController - interpreting json
2015-11-23 22:55:32,319 - [debug] - controllers.PersonController - person to insert: model.Person@65cffe9b[name=Michael,age=21]
2015-11-23 22:55:32,319 - [info] - controllers.PersonController - successfully inserted person
That log is really useful now, it tells me the exact time everything happens. But there is one thing missing, what if two concurrent calls are made? Let’s see how does it look now:
2015-11-23 23:00:35,656 - [info] - controllers.PersonController - requested to insert person
2015-11-23 23:00:35,657 - [trace] - controllers.PersonController - received json: {"name":"Michael","age":21}
2015-11-23 23:00:35,666 - [info] - controllers.PersonController - requested to insert person
2015-11-23 23:00:35,669 - [trace] - controllers.PersonController - received json: {"name":"Sarah","age":32}
2015-11-23 23:00:35,657 - [trace] - controllers.PersonController - interpreting json
2015-11-23 23:00:35,658 - [debug] - controllers.PersonController - person to insert: model.Person@baac0bc[name=Michael,age=21]
2015-11-23 23:00:35,670 - [trace] - controllers.PersonController - interpreting json
2015-11-23 23:00:35,671 - [debug] - controllers.PersonController - person to insert: model.Person@58fb0b0c[name=Sarah,age=32]
2015-11-23 23:00:35,671 - [info] - controllers.PersonController - successfully inserted person
2015-11-23 23:00:35,658 - [info] - controllers.PersonController - successfully inserted person
Which lines belongs to whom? Well, with that pattern is nearly impossible to know, so let’s pimp it up a bit, and add our thread name to it:
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%d - %coloredLevel - [%thread] - %logger - %message%n%xException</pattern>
</encoder>
</appender>
2015-11-23 23:04:21,552 - [info] - [ForkJoinPool-1-worker-1] - play.api.Play - Application started (Dev)
2015-11-23 23:04:21,762 - [info] - [application-akka.actor.default-dispatcher-4] - controllers.PersonController - requested to insert person
2015-11-23 23:04:21,762 - [info] - [application-akka.actor.default-dispatcher-2] - controllers.PersonController - requested to insert person
2015-11-23 23:04:21,851 - [trace] - [application-akka.actor.default-dispatcher-2] - controllers.PersonController - received json: {"name":"Sarah","age":32}
2015-11-23 23:04:21,851 - [trace] - [application-akka.actor.default-dispatcher-4] - controllers.PersonController - received json: {"name":"Michael","age":21}
2015-11-23 23:04:21,853 - [trace] - [application-akka.actor.default-dispatcher-2] - controllers.PersonController - interpreting json
2015-11-23 23:04:21,853 - [trace] - [application-akka.actor.default-dispatcher-4] - controllers.PersonController - interpreting json
2015-11-23 23:04:21,872 - [debug] - [application-akka.actor.default-dispatcher-2] - controllers.PersonController - person to insert: model.Person@2e58db1f[name=Sarah,age=32]
2015-11-23 23:04:21,872 - [info] - [application-akka.actor.default-dispatcher-2] - controllers.PersonController - successfully inserted person
2015-11-23 23:04:21,875 - [debug] - [application-akka.actor.default-dispatcher-4] - controllers.PersonController - person to insert: model.Person@3d169b6a[name=Michael,age=21]
2015-11-23 23:04:21,876 - [info] - [application-akka.actor.default-dispatcher-4] - controllers.PersonController - successfully inserted person
Now, if an exception is raised from any request, we’ll know exactly which person caused it, and that information is awesome when you have a large application with lots of concurrent users in a server far away from home.
Another useful feature that most logging frameworks provide, are thread locals which contain custom parameters to our logging pattern. What if I want to inform what method am I in, without explicitly writing it? Well, MDC (Mapped Diagnostic Context) is a thread local where you can put data to append to your pattern, let’s see an example:
PersonController.scala
package controllers
import model.Person
import org.slf4j.MDC
import play.api.Logger
import play.api.libs.functional.syntax._
import play.api.libs.json._
import play.api.mvc._
import scala.collection.mutable
class PersonController extends Controller {
val repository: mutable.MutableList[Person] = new mutable.MutableList[Person]()
val logger: Logger = Logger(this.getClass())
implicit val personWrites: Writes[Person] = (
(JsPath \ "name").write[String] and
(JsPath \ "age").write[Int]
)(unlift(Person.unapply))
implicit val personReads: Reads[Person] = (
(JsPath \ "name").read[String] and
(JsPath \ "age").read[Int]
)(Person.apply _)
def all = Action {
MDC.put("method", "all")
logger.info(s"returning ${repository.size} people")
Ok(Json.toJson(repository)).as(JSON)
}
def insert = Action(BodyParsers.parse.json) { request =>
MDC.put("method", "insert")
logger.trace(s"received json: ${request.body.toString()}")
request.body.validate[Person].fold(
errors => {
logger.error(s"invalid json: ${errors.toString()}")
BadRequest("invalid json person")
},
person => {
logger.debug(s"person to insert: ${person.toString}")
repository.+=(person)
logger.info("success")
Ok
}
)
}
}
PersonController.java
package controllers;
import com.fasterxml.jackson.databind.JsonNode;
import com.fasterxml.jackson.databind.node.ArrayNode;
import com.fasterxml.jackson.databind.node.ObjectNode;
import com.google.common.base.Preconditions;
import org.apache.commons.lang3.StringUtils;
import org.apache.commons.lang3.builder.ToStringBuilder;
import org.slf4j.MDC;
import play.*;
import play.libs.Json;
import play.mvc.*;
import model.Person;
import java.util.LinkedList;
import java.util.List;
public class PersonController extends Controller {
private static final Logger.ALogger logger = Logger.of(PersonController.class);
private final List repository = new LinkedList();
public Result all() {
MDC.put("method", "all");
ArrayNode result = Json.newArray();
repository.forEach(p -> {
logger.trace("person to retrieve: {}", ToStringBuilder.reflectionToString(p));
ObjectNode node = Json.newObject();
node.put("name", p.getName());
node.put("age", p.getAge());
logger.trace("json: {}", node.toString());
result.add(node);
});
logger.info("retrieving {} people", result.size());
return ok(result);
}
@BodyParser.Of(BodyParser.Json.class)
public Result insert() {
MDC.put("method", "insert");
JsonNode json = request().body().asJson();
logger.trace("received json: {}", json.toString());
try {
logger.trace("interpreting json");
String name = json.findPath("name").textValue();
Preconditions.checkArgument(StringUtils.isNotBlank(name));
int age = json.findPath("age").intValue();
final Person p = new Person(name, age);
logger.debug("person to insert: {}", ToStringBuilder.reflectionToString(p));
repository.add(p);
logger.info("success");
return ok();
} catch (Exception e) {
logger.error("an exception raised" ,e);
return internalServerError();
}
}
}
As you can see, we are putting an entry with key method and the method name as value as the first line of our methods in slf4j’s MDC. Then in our logback.xml we refer to it as:
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%d - %coloredLevel - [%thread] - %logger %X{method} - %message%n%xException</pattern>
</encoder>
</appender>
And then, if we call again our insert method, we’ll se:
2015-11-23 23:32:09,759 - [info] - [ForkJoinPool-1-worker-1] - play.api.Play - Application started (Dev)
2015-11-23 23:32:10,063 - [trace] - [application-akka.actor.default-dispatcher-6] - controllers.PersonController insert - received json: {"name":"Michael","age":21}
2015-11-23 23:32:10,066 - [trace] - [application-akka.actor.default-dispatcher-6] - controllers.PersonController insert - interpreting json
2015-11-23 23:32:10,090 - [debug] - [application-akka.actor.default-dispatcher-6] - controllers.PersonController insert - person to insert: model.Person@44e55d5c[name=Michael,age=21]
2015-11-23 23:32:10,090 - [info] - [application-akka.actor.default-dispatcher-6] - controllers.PersonController insert - success
As you can see, logback is now appending our method names to every message, so we don’t need to explicitly refer to it in every log line.
3. Download the project
This was an example of ligging on play framework with both scala an java.
You can download the full source code of this example here: play-scala-example, play-java-example
