Akka server logging with Slf4j/Logback in Google Cloud Platform

Wooden Log Sculptures By Jae-Hyo Lee

After deployment of service to Google Cloud Platform, we would like to bring in proper logging & monitoring.

As a Akka Http (Scala) server, using sbt as dependency management, adding Slf4j logger is just one extra line in build.sbt:

#build.sbt
"com.typesafe.akka" %% "akka-slf4j" % "2.5.17"

Basic Configuration.

Slf4j by itself works out of box.

All we need to do, is create a file called application.conf, specify log level like below.

#application.conf
akka{
loggers = [“akka.event.slf4j.Slf4jLogger”]
# Options: OFF, ERROR, WARNING, INFO, DEBUG
loglevel = DEBUG
}

Among 5 levels, DEBUG is the most verbose. We probably don’t want that for production, but for experiment/testing purpose, it’s a good start point.

For Actor, Akka Actor comes with nice trait ActorLogging:

#com.my.akka.server.awesomeActor.scala
import akka.actor.{ Actor, ActorLogging }
class SomeActor extends Actor with ActorLogging { 
...
log.info("some info")
...
}

For none actor, we need to include the lib and define the logger:

#com.my.akka.server.myAwesomeClass
package com.my.akka.server
import org.slf4j.{ Logger, LoggerFactory }
class myAwesomeClass {
  val logger: Logger =   LoggerFactory.getLogger(classOf[myAwesomeClass])
  logger.info("...")
}

Remember the log level is set to DEBUG in application.conf ?

DEBUG means any log level ≥ DEBUG will be send to stdout, like log.debug, log.info … are all going out.


A side note, if you are using slick for db connection like us, once we set everything up like above, any request to server that leads to a db hit will output a lot, I mean, really, a lot, information.

How many white ducks are there ?
Too much output is worse than no output

This is because the logger come with slick has logging level set to DEBUG by default.

We could add slick to the list of loggers, and set log level to INFO or something higher should shut it up.

But we gonna use logback anyway, configurations on each single logger can be done over there.


Configuration via Logback.

Logback is a logging backend for slf4j.

Adding dependency via sbt is, again, simple like a breeze (sorry maven, bye)

#build.sbt
“ch.qos.logback” % “logback-classic” % “1.2.3”

Recall that in application.conf, we specify logging level of a list of loggers all together ?

Logback give us a granular way of configuration, down to each single logger (slick, Slf4jLogger, etc …), in logback.xml file like below.

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <appender name="CONSOLE"   class="ch.qos.logback.core.ConsoleAppender">
<target>System.out</target>
<encoder>
<pattern>%date{MM/dd HH:mm:ss} [%thread] %-5level %logger{36} %X{akkaSource} - %msg%n</pattern>
</encoder>
</appender>
    <logger name="slick" level="INFO" >
<appender-ref ref="CONSOLE"/>
</logger>
    <logger name="akka.event.slf4j.Slf4jLogger" level="WARN"
additivity="false">
<appender-ref ref="CONSOLE" />
</logger>
    <root level="ERROR">
<appender-ref ref="CONSOLE"/>
</root>
</configuration>

The rules in xml are like follow:

  • Appender controls where (like stdout) and how (string pattern) to log. We need to name it, like the one above: CONSOLE.
  • Logger itself controls level of logging — DEBUG, INFO, WARN(not WARNING), …
  • Logger references appender. In the example above, logger slick reference appender CONSOLE.
  • There is a logger called root, it’s the parent of all loggers.
  • If a logger has additivity set to true, its logging message will bubble up to its parent. If you see some logging message being print out twice, this might be why.

Logging in Google Cloud Platform

Everything above works very well locally, but did I mention our server is deployed to GCP ?

Turn out that GCP has a logging appender, let’s add it to the logback.xml, just like any other appenders (enhancer is defined by us, will explain later).

#logback.xml
<appender name=”CLOUD” class=”com.google.cloud.logging.logback.LoggingAppender”>
<log>my-service.log</log>
<enhancer>com.my.akka.server.GCPLoggingEnhancer</enhancer>
</appender>

Then reference it in logger:

#logback.xml
<logger name=”slick” level=”INFO” >
<appender-ref ref=”CLOUD”/>
</logger>

Oh and don’t forget to add GCP dependencies:

#build.sbt
“com.google.cloud” % “google-cloud-logging-logback” % “0.73.0-alpha”,
“com.google.cloud” % “google-cloud-logging” % “1.55.0”

Enhancer

Instead of encoder, we are going to define enhancer GCPLoggingEnhancer like below.

# com.my.akka.server.LoggingEnhancer
package com.my.akka.server;
import com.google.cloud.logging.LogEntry;
import com.google.cloud.logging.LoggingEnhancer;
public class GCPLoggingEnhancer implements LoggingEnhancer {
@Override
public void enhanceLogEntry(LogEntry.Builder logEntry) {

logEntry.addLabel(“myLoggingKey”, “myLoggingValue”);
 }
}

GCP doc on logging with java lib (works for scala too) is here.

labels

The whole logEntry.addLabel is there because, later in GCP’s monitoring tool (Stackdriver), we can search by label name and value like below:

logName

Just fyi the logName is whatever you put between <log>…</log> in the appender. so in our example above, you will see my-service.log


More on loggers

As mentioned earlier in this post, logback allows you to config logging in a very granular way. It could be great, or annoying, depends on how you look at it.

For example, remember we extend a trait called ActorLogging so we can log inside our actor?

Well, logger for all actors : akka.actor.ActorSystemImpl

#logback.xml
<logger name=”akka.actor.ActorSystemImpl” level=”WARN”>
...
</logger>

Same idea apply to the logger we created in none-actor classes, notice the name.

#logback.xml
<logger name=”com.my.akka.server” level=”WARN”>
...
</logger>

Well it’s easy if I’m the one created the logger, but how do i know what’s the name of the logger in the trait ActorLogging ?

On trick is to print it out by %logger:

<appender name=”CONSOLE” class=”ch.qos.logback.core.ConsoleAppender”>
<target>System.out</target>
<encoder>
<pattern>%date{MM/dd HH:mm:ss} [%thread] %-5level %logger{36} %X{akkaSource} — %msg%n</pattern>
</encoder>
</appender>

When we start the server, the logger name is split out on the console like this

12/30 23:25:10 [WebServer-akka.actor.default-dispatcher-4] INFO akka.actor.ActorSystemImpl akka.actor.ActorSystemImpl(WebServer) — Server online at http://0:0:0:0:0:0:0:0:9090/
Press RETURN to stop…

That’s it, we are all learning as we go.