LogStage

LogStage is a zero-cost structural logging framework for Scala & Scala.js

Key features:

  1. LogStage extracts structure from ordinary string interpolations in your log messages with zero changes to code.
  2. LogStage uses macros to extract log structure, its faster at runtime than a typical reflective structural logging frameworks,
  3. Log contexts
  4. Console, File and SLF4J sinks included, File sink supports log rotation,
  5. Human-readable output and JSON output included,
  6. Method-level logging granularity. Can configure methods com.example.Service.start and com.example.Service.doSomething independently,
  7. Slf4J adapters: route legacy Slf4J logs into LogStage router

Dependencies

libraryDependencies ++= Seq(
  // LogStage core library
  "io.7mind.izumi" %% "logstage-core" % "1.2.5",
  // Json output
  "io.7mind.izumi" %% "logstage-rendering-circe" % "1.2.5",
  // Router from Slf4j to LogStage
  "io.7mind.izumi" %% "logstage-adapter-slf4j" % "1.2.5",
  // LogStage integration with DIStage
  "io.7mind.izumi" %% "distage-extension-logstage" % "1.2.5",
  // Router from LogStage to Slf4J
  "io.7mind.izumi" %% "logstage-sink-slf4j " % "1.2.5",
)

Overview

The following snippet:

import logstage.IzLogger
import scala.util.Random

val logger = IzLogger()
// logger: IzLogger = izumi.logstage.api.IzLogger@5ad05499

val justAnArg = "example"
// justAnArg: String = example
val justAList = List[Any](10, "green", "bottles")
// justAList: List[Any] = List(10, green, bottles)

logger.trace(s"Argument: $justAnArg, another arg: $justAList")

// custom name, not based on `val` name

logger.info(s"Named expression: ${Random.nextInt() -> "random number"}")

// print result without a name

logger.warn(s"Invisible argument: ${Random.nextInt() -> "random number" -> null}")

// add following fields to all messages printed by a new logger value

val ctxLogger = logger("userId" -> "user@google.com", "company" -> "acme")
// ctxLogger: IzLogger = izumi.logstage.api.IzLogger@4aea51ae
val delta = Random.nextInt(1000)
// delta: Int = 988

ctxLogger.info(s"Processing time: $delta")

Will look like this in string form:

logstage-sample-output-string

And like this in JSON:

logstage-sample-output-string

Note:

  1. JSON formatter is type aware!
  2. Each JSON message contains @class field with holds a unique event class identifier. All events produced by the same source code line will share the same event class.

Syntax Reference

1) Simple variable:

logger.info(s"My message: $argument")

2) Chain:

logger.info(s"My message: ${call.method} ${access.value}")

3) Named expression:

logger.info(s"My message: ${Some.expression -> "argname"}")

4) Invisible named expression:

logger.info(s"My message: ${Some.expression -> "argname" -> null}")

5) De-camelcased name:

logger.info(${camelCaseName -> ' '})

Basic setup

import logstage.{ConsoleSink, IzLogger, Trace}
import logstage.circe.LogstageCirceRenderingPolicy

val textSink = ConsoleSink.text(colored = true)
// textSink: ConsoleSink = izumi.logstage.sink.ConsoleSink$ColoredConsoleSink$@1ae693ce
val jsonSink = ConsoleSink(LogstageCirceRenderingPolicy(prettyPrint = true))
// jsonSink: ConsoleSink = izumi.logstage.sink.ConsoleSink@3bc79f13

val sinks = List(jsonSink, textSink)
// sinks: List[ConsoleSink] = List(izumi.logstage.sink.ConsoleSink@3bc79f13, izumi.logstage.sink.ConsoleSink$ColoredConsoleSink$@1ae693ce)

val logger: IzLogger = IzLogger(Trace, sinks)
// logger: IzLogger = izumi.logstage.api.IzLogger@636b706e
val contextLogger: IzLogger = logger("key" -> "value")
// contextLogger: IzLogger = izumi.logstage.api.IzLogger@7b942a8c

logger.info("Hey")

contextLogger.info("Hey")

Log algebras

LogIO, LogIO2 & LogIO3 algebras provide a purely-functional API for one-, two-, and three-parameter effect types respectively:

import logstage.{IzLogger, LogIO}
import cats.effect.IO

val logger = IzLogger()
// logger: IzLogger = izumi.logstage.api.IzLogger@55c2bed3

val log = LogIO.fromLogger[IO](logger)
// log: LogIO[IO] = logstage.LogIO$$anon$1@7e02c7c8

log.info(s"Hey! I'm logging with ${log}stage!").unsafeRunSync()(cats.effect.unsafe.IORuntime.global)

I 2019-03-29T23:21:48.693Z[Europe/Dublin] r.S.App7.res8 ...main-12:5384  (00_logstage.md:92) Hey! I'm logging with log=logstage.LogIO$$anon$1@72736f25stage!

LogIO.log/LogIO2.log/LogIO3.log/IzLogger.log let you refer to an implicit logger’s methods without having to name a logger variable

import logstage.LogIO
import logstage.LogIO.log

def logfun[F[_]: LogIO]: F[Unit] = {
  log.info(s"I'm logging with ${log}stage!")
}

Adding Custom Context to Loggers

LogIO* algebras can be extended with custom context using their .withCustomContext method, same as IzLogger:

import cats.effect.IO
import cats.syntax.all._
import logstage.LogIO
import io.circe.Printer
import io.circe.syntax._

def importEntity(entity: Entity)(implicit log: LogIO[IO]): IO[Unit] = {
  val logWithContext: LogIO[IO] = {
    log.withCustomContext(
      "ID" -> entity.id,
      "entityAsJSON" -> entity.asJson.printWith(Printer.spaces2),
    )
  }

  load(entity).handleErrorWith {
    case error =>
      logWithContext.error(s"Failed to import entity: $error.").void
      // JSON message includes `ID` and `entityAsJSON` fields
  }
}

ZIO environment support

LogZIO.log lets you carry LogZIO capability in environment.

Example:

import logstage.{IzLogger, LogIO3, LogZIO}
import logstage.LogZIO.log
import zio.{URIO, ZEnvironment}

val fn: URIO[LogZIO, Unit] = {
  log.info(s"I'm logging with ${log}stage!")
}
// fn: URIO[LogZIO, Unit] = OnSuccess(logstage.LogZIO.LogZIOImpl.log(LogZIO.scala:35),Sync(logstage.LogZIO.LogZIOImpl.log(LogZIO.scala:35),zio.ZIO$ServiceWithZIOPartiallyApplied$$$Lambda$24035/0x000000080484f448@52fa8c7f),zio.ZIO$$$Lambda$23905/0x0000000802e86970@67ebec1c)

val logger: LogZIO = LogIO3.fromLogger(IzLogger())
// logger: LogZIO = logstage.LogIO$$anon$1@6aaa6e4e

import izumi.functional.bio.UnsafeRun2

val runtime = UnsafeRun2.createZIO()
// runtime: UnsafeRun2.ZIORunner[Any] = izumi.functional.bio.UnsafeRun2$ZIORunner@30b0f9dd

runtime.unsafeRun {
  fn.provideEnvironment(ZEnvironment(logger))
}

Adding FiberId to log messages

LogZIO.withFiberId provides a LogIO instance that logs the current ZIO FiberId in addition to the JVM thread id:

val logger: LogZIO = LogZIO.withFiberId(IzLogger())
// logger: LogZIO = logstage.LogZIO$$anon$1@70c4ed3e

runtime.unsafeRun {
  fn.provideEnvironment(ZEnvironment(logger))
}

I 2019-03-29T23:21:48.760Z[Europe/Dublin] r.S.App9.res10 ...main-12:5384  (00_logstage.md:123) {fiberId=0} Hey! I'm logging with log=logstage.LogZIO$$anon$1@c39104astage!

Adding custom logging context to log messages

LogZIO.withCustomContext allows to append to the custom log context carried in ZIO environment when LogZIO.log is used for logging:

import zio._

def databaseCall(): ZIO[LogZIO, Throwable, String] = ZIO.succeed("stubbed")

def dbLayerFunction(arg: Int): ZIO[LogZIO, Throwable, String] = {
  LogZIO.withCustomContext("arg" -> arg) {
    for {
      result <- databaseCall()
      _      <- log.info(s"Database call $result")
    } yield result
 }
}

def serviceLayerFunction1(): ZIO[LogZIO, Throwable, String] = {
  for {
    _      <- log.info("Going to call dbLayerFunction")
    result <- dbLayerFunction(1)
  } yield result
}

def serviceLayerFunction2(): ZIO[LogZIO, Throwable, String] = {
  log.info("Called serviceLayerFunction2").as("stubbed")
}

def controllerFunction(correlationId: String): ZIO[LogZIO, Throwable, String] = {
  LogZIO.withCustomContext("correlation_id" -> correlationId) {
    for {
      x     <- serviceLayerFunction1()
      y     <- serviceLayerFunction2()
      result = x + y
      _     <- log.info(s"Controller produced $result")
    } yield result
  } <* log.info("Some log after controller function (without correlation_id)")
}

// at the end of the world
runtime.unsafeRun {
  controllerFunction("123").provideEnvironment(ZEnvironment(logger))
}
// res15: String = "stubbedstubbed"

I 2021-08-17T15:07:54.244 (00_logstage.md:220)  …App12.serviceLayerFunction1 [2280:Thread-60           ] correlation_id=123 Going to call dbLayerFunction
I 2021-08-17T15:07:54.342 (00_logstage.md:213)  …n.App12.dbLayerFunction.212 [2280:Thread-60           ] correlation_id=123, arg=1 Database call result=stubbed
I 2021-08-17T15:07:54.358 (00_logstage.md:226)  …App12.serviceLayerFunction2 [2280:Thread-60           ] correlation_id=123 Called serviceLayerFunction2
I 2021-08-17T15:07:54.367 (00_logstage.md:235)  ….controllerFunction.232.233 [2280:Thread-60           ] correlation_id=123 Controller produced result=stubbedstubbed
I 2021-08-17T15:07:54.371 (00_logstage.md:237)  …on.App12.controllerFunction [2280:Thread-60           ] Some log after controller function (without correlation_id)

Custom JSON rendering with LogstageCodec

If you define an instance of LogstageCodec for your type, it will be used when rendering your logs to JSON instead of the default renderer.

You can derive instances of LogstageCodec from Circe codecs with logstage-rendering-circe or write them manually.

Example:

import io.circe.Codec
import io.circe.generic.semiauto
import logstage.LogstageCodec
import logstage.circe.LogstageCirceCodec

final case class KV(key: String, value: Int)

object KV {
  implicit val circeCodec: Codec[KV] = semiauto.deriveCodec[KV]
  implicit val logstageCodec: LogstageCodec[KV] = LogstageCirceCodec.derived[KV]
}

If you want to make sure that all values in your interpolations are rendered using LogstageCodec instead of default renderer, use IzStrictLogger/LogIOStrict types from logstage.strict package:

import logstage.strict.IzStrictLogger
import logstage.ConsoleSink
import logstage.circe.LogstageCirceRenderingPolicy

val logger = IzStrictLogger(sink = ConsoleSink(LogstageCirceRenderingPolicy()))
// logger: IzStrictLogger = izumi.logstage.api.strict.IzStrictLogger@76db0e2d

logger.info(s"Got ${KV("key", 7) -> "KeyValue"}")

SLF4J Router

When not configured, logstage-adapter-slf4j will log messages with level >= Info to stdout.

Due to the global mutable nature of slf4j, to configure slf4j logging you’ll have to mutate a global singleton StaticLogRouter. Replace its LogRouter with the same one you use elsewhere in your application to use the same configuration for Slf4j.

import logstage.IzLogger
import izumi.logstage.api.routing.StaticLogRouter

val myLogger = IzLogger()
// myLogger: IzLogger = izumi.logstage.api.IzLogger@4fbad6a6

// configure SLF4j to use the same router that `myLogger` uses
StaticLogRouter.instance.setup(myLogger.router)

JUL (java.util.logging) support

There are two ways to integrate JUL framework with LogStage.

LogStage implements JUL log handler. Due to the global mutable nature of JUL framework, to configure JUL logging you’ll have to mutate a global singleton holding the root of the JUL logging hierarch java.util.logging.Logger.

This might be done the following way:

val logger = IzLogger()
val router: LogRouter = logger.router
val bridge = new LogstageJulLogger(router)
bridge.installOnly()

LogstageJulLogger#installOnly() method wipes all the logging handlers associated with the root logger and installs LogStage as the only logging handler.

Alternatively, you may use jul-to-slf4j adapter for slf4j.

You might need to do the following in order for the adapter to properly initialize:

SLF4JBridgeHandler.removeHandlersForRootLogger()
SLF4JBridgeHandler.install()
1.2.5