SLF4J

It’s time to add logging to our app.
We will add logging using SLF4J, and bind the implementation to logback.

SLF4J, Simple Logging Facade for Java, serves as a simple facade or abstraction for various logging frameworks (e.g. java.util.logging, Logback, Log4j) allowing the end user to plug in the desired logging framework at deployment time.

This means that as a library author you can use SLF4J to log messages, and the app that consumes your library (and other libraries that support SLF4J) will choose the implementation. This is how you don’t impose the logging choice on your consumers.

Since we are writing an app, we will choose the implementation.
We will use Logback, which was created by the same developer that created log4j, but is preferred.

We will need to familiarize ourselves with several concepts:

Appenders: a logger can use one or more appenders, which are responsible for writing the logging events, e.g to the console, a file, slack, etc.
Logging Levels: Loggers may be assigned levels (TRACE, DEBUG, INFO, WARN and ERROR).
These levels are ordered: TRACE < DEBUG < INFO < WARN < ERROR.
When the user logs a message, the level of the logging request is determined by the printing method. e.g logger.info("...") is a logging statement of level INFO.
The message will be logged only if the level of the logging request is higher than or equal to the level of the logger.
Logger hierarchy: loggers have a tree like hierarchy, starting from the root logger, where dots are used to separate parents from children.
For example, com.foo is the parent of com.foo.bar. Also, if there is no logger named “com”, then “com.foo” is the child of the root logger.
Levels and appenders are inherited from the nearest ancestor logger.
e.g when defining the logger com.example.some_library, we may set its level to INFO and its appenders to file and console appenders.
The logger com.example.some_library.aaa.bbb.ccc will have the same level and appenders, as long as there is no logger in between these two loggers that changed the level/appenders (or set additivity to false).

Add SLF4J to our build

Let’s add logback-classic and logback-slack-appender as dependencies in build.sbt:

libraryDependencies ++= Seq(
  // more dependencies here
  "ch.qos.logback" % "logback-classic" % "1.2.3",
  "com.github.maricn" % "logback-slack-appender" % "1.4.0",
)

Import Changes in IntelliJ so it will download the dependencies for you and help you with code completion (it will also reload the sbt shell behind the scenes).

Play already uses SLF4J for logging, backed by Logback as its default logging engine, so the logback dependency is not really needed, and is used for clarity here.

Configure Logback

Add a file under conf/logback.xml (or change it if it already exists) with the following content:

<!-- https://www.playframework.com/documentation/latest/SettingsLogger -->
<configuration debug="false">
  <variable name="APP_NAME" value="playground" />
  <contextName>${APP_NAME}</contextName>

  <!-- ********************************* appenders ********************************* -->
  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>%date %contextName %highlight(%-5level) %-10([%thread]) %logger{36} - %message%n</pattern>
    </encoder>
  </appender>

  <appender name="ASYNCSTDOUT" class="ch.qos.logback.classic.AsyncAppender">
    <appender-ref ref="STDOUT"/>
  </appender>

  <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>log/${APP_NAME}/${APP_NAME}.log</file>
    <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
      <!-- daily rollover. keep 14 days worth of history capped at 1GB total size -->
      <fileNamePattern>log/${APP_NAME}/${APP_NAME}.log.%d{yyyy-MM-dd}.%i</fileNamePattern>
      <maxFileSize>100MB</maxFileSize>
      <maxHistory>14</maxHistory>
      <totalSizeCap>1GB</totalSizeCap>
    </rollingPolicy>
    <encoder>
      <pattern>%date %contextName %highlight(%-5level) %-10([%thread]) %logger{36} [%file:%line] %message%n</pattern>
    </encoder>
  </appender>

  <appender name="ASYNCFILE" class="ch.qos.logback.classic.AsyncAppender">
    <appender-ref ref="FILE"/>
  </appender>

  <appender name="SLACK" class="com.github.maricn.logback.SlackAppender">
    <!-- example https://hooks.slack.com/services/T1234ABCD/B1234ABCD/abcdefghijklmnopqrst1234 -->
    <webhookUri>${slack_webhook_url}</webhookUri>
    <!-- Channel that you want to post - default is #general. use #CHANNEL_NAME for channels and @USER_NAME for users -->
    <channel>#${APP_NAME}</channel>
    <!-- Formatting (you can use Slack formatting - URL links, code formatting, etc.) -->
    <layout class="ch.qos.logback.classic.PatternLayout">
      <pattern>%message</pattern>
    </layout>
    <!-- Username of the messages sender -->
    <username>${HOSTNAME}</username>
    <!-- Emoji to be used for messages -->
    <iconEmoji>:ghost:</iconEmoji>
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
      <level>INFO</level>
    </filter>
  </appender>

  <!-- Currently recommended way of using Slack appender -->
  <appender name="ASYNC_SLACK" class="ch.qos.logback.classic.AsyncAppender">
    <appender-ref ref="SLACK" />
  </appender>

  <!-- ********************************* loggers ********************************* -->
  <!-- for our app -->
  <logger name="com.example.${APP_NAME}" level="DEBUG"/>
  <!-- for slack -->
  <logger name="com.example.${APP_NAME}.slack.async" level="INFO">
    <appender-ref ref="ASYNC_SLACK" />
  </logger>
  <!-- for slack, when the program is about to exit and we want the log immediately -->
  <logger name="com.example.${APP_NAME}.slack.synchronous" level="INFO">
    <appender-ref ref="SLACK" />
  </logger>
  <!-- for slack only (without log-file) -->
  <logger name="com.example.${APP_NAME}.slack.only" level="INFO" additivity="false">
    <appender-ref ref="ASYNC_SLACK" />
    <appender-ref ref="STDOUT" />
  </logger>
  <!-- for other jars in your organization -->
  <logger name="com.example" level="INFO"/>
  <!-- for all other components -->
  <root level="WARN">
    <appender-ref ref="ASYNCFILE" />
    <appender-ref ref="ASYNCSTDOUT" />
  </root>
</configuration>

This file defines the following loggers:

<root> logger: with level=WARN and file and console appenders. This will be applied to all third party components, such as com.third.party
com.example logger that inherits the appenders from the root logger (thus it also logs to a file and the console), and sets the level to INFO, since it may be interesting to get info messages from other components in your organiztion (com.example) like com.example.library
com.example.playgroud that also inherits the console and file appenders, and sets the level to DEBUG (you may want to change this in production).
Three slack loggers: synchronous, asynchronous and one that only logs to slack and to the console without logging to a file (using additivity="false"). These loggers write messages to the channel #playground, which you should create in advance. You can change the channel to @your_user to send a message to yourself instead. Also, make sure to provide a slack webhook url (via slack_webhook_url). See Slack API for further details.

The file appender writes to log/playground/playground.log, and there’s a daily rotation of the log file, keeping the last 14 days of logs up to 1GB (so the log won’t take all the disk space in the server).
It may sufficient to only log to STDOUT in case you have log shipment that ships the content of the standard outputs to a log system.

We don’t need the logs in the git repository, so we will add it to .gitignore:

log/
# the rest of `.gitignore` content

Set the logger in the ApplicationLoader

Since we are using a custom class loader, we also need to configure logging with the LoggerConfigurator.
In AppLoader.scala, add the configureLogging method and invoke it from the load method:

class AppLoader extends ApplicationLoader {
  def load(context: Context): Application = {
    configureLogging(context)
    // rest of "load" body
  }

  private def configureLogging(context: Context): Unit =
    LoggerConfigurator(context.environment.classLoader).foreach {
      _.configure(context.environment, context.initialConfiguration, Map.empty)
    }
}

Use the logger

Let’s write something to the log.
For example, in AppComponents.scala:

import org.slf4j.LoggerFactory

// inside the body of AppComponents:
private val logger = LoggerFactory.getLogger(getClass)
logger.debug(s"running in ${environment.mode} mode")

LoggerFactory.getLogger() expects either a string with the logger name (e.g “com.example.playground.something”) or Class[T].
It is convenient to simply call getClass, as it will return the runtime class of the current object, e.g in this case it will return com.example.playground.configuration.components.DevComponents.
This logger, along with other loggers in “com.example.playground” package, inherits its level and appenders from the “com.example.playground” logger.

Send slack messages

If we want to log a message to slack we can use for example
val slackLoggerAsync = LoggerFactory.getLogger("com.example.playground.slack.async")
to create a logger.
Alternatively, you can create a simple class like:

package com.example.playground.configuration

import org.slf4j.{Logger, LoggerFactory}

class SlackLogger {
  val async: Logger = LoggerFactory.getLogger("com.example.playground.slack.async")
  val sync: Logger  = LoggerFactory.getLogger("com.example.playground.slack.synchronous")
  val only: Logger  = LoggerFactory.getLogger("com.example.playground.slack.only")
}

Then inject it to your services, e.g by adding slackLogger: SlackLogger to the constructor of the services and wire SlackLogger.

Once we have a slack logger, sending a message is as easy as using the logger, e.g

slackLogger.async.info("hello world")

SLF4J and specific bindings (Logback, Log4j)

Notice that our code always refers to classes in org.slf4j package, specifically Logger and LoggerFactory, and not to classes in ch.qos.logback package.
The binding to logback is simply done by adding the logback dependency to the classpath, which we did in build.sbt.