Introduction to logging in Scala

What are logs?

Logging is a very simple idea of writing to some storage events, data or anything about what happens during your application’s execution. Each log message is made of, at the very least: timestamp, level and the message itself.

Log files are rather boring reading material but they do become indispensable when your application is not doing what you expect it to do. When it crashes or behaves incorrectly logs very often come to the rescue and shed some light on the possible cause of the issue.

Where do logs come from?

For the simplest and most naive solution, you could just call System.out.println or open a file and append to it whenever you need. This would work but there are better solutions.

Simple Logging Facade for Java (SLF4J)

In the JVM world there is a library called SLF4J which stands for Simple Logging Facade for Java. As the name suggests it is just a facade; it doesn't really do any logging. It provides an interface for loggers which you can use in your application and switch between implementations as you like without the need to change much code, if any.

Log levels

Each log message has some level assigned to it. Log level can be thought of as how important the log entry is and how much detail it offers. The highest level would be the most important such as errors, and they will usually contain a stack trace if they were what caused the exception. The lowest level may contain a lot of very detailed information and may be logged very often. Logging every single detail may have a negative impact on your application performance, and for that reason in normal operation the lowest level logs would not be logged.

Log levels supported by SLF4J are (from the highest):

  • Error - something unexpected has happened, it may potentially lead to an application crash.
  • Warning - situation that requires attention as it may be an indication of some bigger problem but can be handled and does not impact normal operations
  • Info - informational messages that are confirmations of normal operation
  • Debug - detailed informational messages useful for debugging issues
  • Trace - even more detailed than debug, potentially may be expensive to generate

In normal operation you will probably want only info and higher logs, enabling debug and trace only if needed for investigations.

Logger implementations

As SLF4J is only a facade we need to get an actual implementation to be able to actually get some logs. Currently the most widely used implementations are:

  • Logback
  • Log4j2 - they actually provide their own API as well but it is compatible with SLF4J

I will not be discussing here which one is better to start - just pick one and thanks to SLF4J you can easily switch if the need arises.

Let's do some logging then

First let’s create a new project
sbt new scala/hello-world.g8

Next we add logback to the build.sbt file:

libraryDependencies += "ch.qos.logback" % "logback-classic" % "1.2.3"  

Thanks to transitive dependencies we don't have to explicitly add dependency on SLF4J.

Now we can edit our Main class to look like this

import org.slf4j.LoggerFactory

object Main extends App {  
  val logger = LoggerFactory.getLogger(getClass.getSimpleName)
  logger.info("I am a log message")
  println("Hello, World!")
}

after running it we can see output such as

23:45:41.112 [run-main-0] INFO Main$ - I am a log message  
Hello, World!  

As you can see, getting an instance of the logger requires only 2 lines: import, and call to LoggerFactory.getLogger. The LoggerFactory.getLogger function takes a single String argument which by convention is name of the class where it will be used. In our example we can see the string Main$ which is the name of our class.

org.slf4j.Logger

You can find api docs for interface provided by SLF4J here. You can see that for each level it has a set of overloaded methods. For example, for info logs they are:

void    info(String msg)  
void    info(String format, Object... arguments)  
void    info(String format, Object arg)  
void    info(String format, Object arg1, Object arg2)  
void    info(String msg, Throwable t)  

There are also equivalent methods with additional marker arguments. They allow for more control over what and where gets logged when the log level alone is not enough.

In its simplest form, which we used before, we just provide a string and it will get printed as is, nothing fancy there.

The 3 versions taking Object arguments allow you to provide values which will be used for the placeholder you put in your string.

Let’s just run the code and see:

import org.slf4j.LoggerFactory

object Main extends App {  
  val logger = LoggerFactory.getLogger(getClass.getSimpleName)
  val someValue = 1 to 4
  logger.info("I am a log message with some extra value: {}", someValue)
  println("Hello, World!")
}

the output we get is:

20:00:51.005 [run-main-1] INFO Main$ - I am a log message with some extra value: Range 1 to 4  
Hello, World!  

The logger will call the toString() method on the provided object and replace the {} placeholders with it. You can provide as many additional arguments as you want thanks to version taking Object...

It is important to use these overloaded methods instead of doing:

  logger.info("I am a log message with some extra value: %s".format(someValue))

or

  logger.info(s"I am a log message with some extra value: $someValue")

They all will have exactly the same output, but the important difference is that if the log level you are logging at is disabled, the toString method will be called on the provided values anyway - which may have negative impact on your application performance as many unnecessary objects will get created.

There are 3 versions taking additional Object arguments, this is just a small optimisation as providing only one or two values is the most common case.

The last version takes the additional argument of type Throwable; this version is there for you in case you catch some exception and want to log it.

import org.slf4j.LoggerFactory

object Main extends App {  
  val logger = LoggerFactory.getLogger(getClass.getSimpleName)
  try {
    throw new Exception("ups!")
  } catch {
    case e: Throwable => logger.info("I am a log message with exception", e)
  }
  println("Hello, World!")
}

we get

20:14:42.235 [main] INFO Main$ - I am a log message with exception  
java.lang.Exception: ups!  
    at Main$.delayedEndpoint$Main$1(Main.scala:6)
    at Main$delayedInit$body.apply(Main.scala:3)
    at scala.Function0.apply$mcV$sp(Function0.scala:34)
    at scala.Function0.apply$mcV$sp$(Function0.scala:34)
    at scala.runtime.AbstractFunction0.apply$mcV$sp(AbstractFunction0.scala:12)
    at scala.App.$anonfun$main$1$adapted(App.scala:76)
    at scala.collection.immutable.List.foreach(List.scala:388)
    at scala.App.main(App.scala:76)
    at scala.App.main$(App.scala:74)
    at Main$.main(Main.scala:3)
    at Main.main(Main.scala)
Hello, World!  

as you can see this time together with our message we also have the message from the exception, as well as a stacktrace.

Configuration

Let’s run this now:

import org.slf4j.LoggerFactory

object Main extends App {  
  val logger = LoggerFactory.getLogger(getClass.getSimpleName)
  logger.trace("Trace log message")
  logger.debug("Debug log message")
  logger.info("Info log message")
  logger.warn("Warning log message")
  logger.error("Error log message")
}

we get

20:17:40.918 [main] DEBUG Main$ - Debug log message  
20:17:40.921 [main] INFO Main$ - Info log message  
20:17:40.921 [main] WARN Main$ - Warning log message  
20:17:40.921 [main] ERROR Main$ - Error log message  

The trace log is missing :o
That obviously means that it is disabled and we have to enable it somehow.
As we are using logback we need to provide a config file for it. This is explained in detail in their documentation
You don't have to read it all - just create a file: src/main/resources/logback.xml
with content:

<configuration>

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <!-- encoders are assigned the type
             ch.qos.logback.classic.encoder.PatternLayoutEncoder by default -->
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
        </encoder>
    </appender>

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

This is the default configuration so running the application now will not differ from our previous run

But if we change line 11 to:

    <root level="trace">

and run it:

20:29:59.411 [main] TRACE Main$ - Trace log message  
20:29:59.413 [main] DEBUG Main$ - Debug log message  
20:29:59.413 [main] INFO  Main$ - Info log message  
20:29:59.413 [main] WARN  Main$ - Warning log message  
20:29:59.413 [main] ERROR Main$ - Error log message  

our trace log will be there. In a similar fashion we can disable some levels. Let’s change config to:

    <root level="warn">

And now we only get

20:31:34.352 [main] WARN  Main$ - Warning log message  
20:31:34.354 [main] ERROR Main$ - Error log message  

The value we set for level is the lowest log level we want to see.

Of course there is a little more to that config file than just what level you want. If you read it carefully you will see it mentions appender and encoder.

Appenders

Appender is the class that will actually write your logs somewhere. All this time we were using the default appender - ConsoleAppender. It simply writes the logs to the console as the name says.

Logback comes with a few more appenders which are listed and explained in detail here.

We will cover only one more which is FileAppender. I am sure you already guessed it correctly - this appender will write logs to the file.

If you change your logback.xml file to:

<configuration>

    <appender name="STDOUT" class="ch.qos.logback.core.FileAppender">
        <file>main.log</file>
        <append>true</append>
        <!-- encoders are assigned the type
             ch.qos.logback.classic.encoder.PatternLayoutEncoder by default -->
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
        </encoder>
    </appender>

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

and run the application, you will see that there are no more logs printed in the output of the program, but instead a main.log file got created in the root of the project which contains our logs.

Encoders

Part of the appender configuration is encoder. Encoders convert whatever you passed to the logger into OutputStream, which is what actually gets written by the appender.
The most relevant property of the encoder is a pattern.
Default pattern is:

%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n

which is what makes our log look like this:

20:46:29.252 [main] WARN  Main$ - Warning log message  

If for example we change it a little to

%d{HH:mm:ss.SSS} %-5level [%thread] %logger{36} - %msg%n

Then, as expected, we can see level and thread values switched this time.

20:54:48.266 WARN  [main] Main$ - Warning log message  

Logback also provides additional values that you may want to include in your logs, or you can configure it to have different output. All is explained in the docs

For example we may want to use ISO format for a timestamp

%date{ISO8601} [%thread] %-5level %logger{36} - %msg%n

Which results in

2019-01-30 20:57:37,991 [main] WARN  Main$ - Warning log message  

Scala World

All the above is true for all JVM languages, but there is a little extra we can get for Scala. There is a small library available for Scala called Grizzled-SLF4J.
If you add it to your build.sbt

libraryDependencies += "org.clapper" %% "grizzled-slf4j" % "1.3.3"  

Then you can change your Main class to look like this:

package com.example

import grizzled.slf4j.Logging

object Main extends App with Logging {  
  trace("Trace log message")
  trace("sdfg")
  debug("Debug log message")
  info("Info log message")
  warn("Warning log message")
  error("Error log message")
}

The benefits of this library are:
1. No need to create a logger instance yourself, just mix in the Logging trait and the logger and its method will be lazily initialised for you
2. It uses by-name parameters for messages, which allow us to use string interpolation instead of string formatting. As mentioned before, string interpolation should not be used with vanilla slf4j, but by-name parameters are evaluated only when used inside the called function. If log level is disabled the interpolation won’t happen and no unnecessary objects will get created.

At Football Radar

At Football Radar we use Finagle for many of our projects. Finagle provides its own Logging trait which is similar to the one provided by grizzled-slf4j but there is more.

Finagle comes with a built-in admin interface which offers many useful tools and insights about the current state of your service. One of these tools is a logging page where you can change the logging level per logger at runtime.

It is a very convenient way to enable debug or trace logging per class/logger without the need to restart the service with a new configuration.