What Scala adds to a Logging API
I released echopraxia-plusscala last week – it's a Scala API for structured logging that co-exists peacefully with Logback or Log4J 2, for applications that want a richer logging experience.
Using the Scala API is a different experience from using the Java API, because Scala opens up a number of options. I also wrote this briefly on Reddit.
Tuples and Functions
The first enhancement is richer support for tuples and functions. For Scala, it comes out of the box:
logger.info("hi {}", _.string("name" -> "will"))
Requiring a function as a second argument is relatively low impact, because of the placeholder _ variable. I tried working with various infix DSLs and found them to be more clunky than useful.
Type Classes in Field Builders
Where it really starts getting fun is in the field builder.
Most type classes frameworks, including Blindsight, have a pattern that places the type class instance in a companion object:
trait ToValue[-T] {
def toValue(t: T): Value[_]
}
case class Foo(name: String, quantity: Int)
object Foo {
implicit val fooToValue: ToValue[Foo] = ...
}
This is convenient, but results in a "globally available" type class instance. Once your code depends on companion objects throughout the codebase, it can be very hard to limit and scope that behavior.
This behavior can be very counterproductive for JSON serialization – consider a situation where you may have a public API representation of an object, and a private representation. Rather than having two different JSON serializations of the same object, you'll sometimes see two almost identical case class representations of the same data, just so that the JSON will match up.
The default field builder API has the type class defined as dependent types, with the primitives defined inline:
trait ValueTypeClasses {
@implicitNotFound("Could not find an implicit ToValue[${T}]")
trait ToValue[-T] {
def toValue(t: T): Value[_]
}
object ToValue {
def apply[T: ToValue](t: T): Value[_] = implicitly[ToValue[T]].toValue(t)
implicit val valueToValue: ToValue[Value[_]] =
identity(_)
implicit val intToValue: ToValue[Int] =
(int: Int) => Value.number(int: java.lang.Integer)
// ...
implicit val stringToStringValue: ToValue[String] =
(s: String) => Value.string(s)
implicit val throwableToValue: ToValue[Throwable] =
e => Value.exception(e)
}
}
And the FieldBuilder takes the type class:
trait FieldBuilder extends ValueTypeClasses {
// ...
def keyValue[V: ToValue](key: String, value: V): Field =
Field.keyValue(key, ToValue(value))
}
Defining your own type class instance is likewise done inside the trait:
trait SomeFieldBuilder extends FieldBuilder {
implicit val fooToValue: ToValue[Foo] = ...
}
object SomeFieldBuilder extends SomeFieldBuilder
And finally:
val logger = LoggerFactory.getLogger.withFieldBuilder(SomeFieldBuilder)
val myFoo: Foo = ...
logger.info("Some message {}", fb => fb.keyValue("foo", myFoo))
Inside the field builder function, there's no import tax applied. This is because the type inference is to Logger[SomeFieldBuilder.type], meaning that the SomeFieldBuilder singleton object is within the implicit resolution scope of the function – by contrast, Logger[SomeFieldBuilder] will not work, as implicit resolution won't follow the trait alone.
There's no possibility of ambiguous or conflicting type class instances, and you can control what's being logged by swapping out the field builder. The field builder is operating as an object capability for logging arbitrary objects, instead of the capability being provided by the companion object or the logger itself.
This means that if convenience methods or functions are defined, it's easiest to create another singleton object for it:
trait OneOffFieldBuilder extends SomeObjectBuilder {
val function: (Foo, Bar) => FieldBuilderResult = { case (foo, bar) =>
list(
obj("foo", foo),
obj("bar", bar)
)
}
def method(foo: Foo, bar: Bar): FieldBuilderResult = {
list(
obj("foo", foo),
obj("bar", bar)
)
}
}
object OneOffFieldBuilder extends OneOffFieldBuilder
And then the method is available for use in that context.
val oneOffLogger = LoggerFactory.getLogger.withFieldBuilder(OneOffFieldBuilder)
oneOffLogger.info("{}", _.method(foo, bar))
This is a bit different from the usual idioms, but it's very handy.
Type Class Derivation
The second thing possible in Scala is using automatic type class derivation with Magnolia. Magnolia is a "shortcut" for defining type class behavior for case classes and sealed traits, and what makes Magnolia really cool is that it does this using Scala macros, meaning that the Scala compiler is literally filling in the implementation for ToValue[Foo].
Magnolia comes with both fully automatic derivation, and semi-automatic derivation, which requires a gen[T] marker for the macro:
trait AutoFieldBuilder extends FieldBuilder with AutoDerivation
object AutoFieldBuilder extends AutoFieldBuilder
trait SemiAutoFieldBuilder extends FieldBuilder with SemiAutoDerivation
object SemiAutoFieldBuilder extends SemiAutoFieldBuilder {
implicit lazy val iceCreamToValue: ToValue[IceCream] = gen[IceCream]
implicit lazy val entityIdToValue: ToValue[EntityId] = gen[EntityId]
implicit lazy val barToValue: ToValue[Bar] = gen[Bar]
implicit lazy val fooToValue: ToValue[Foo] = gen[Foo]
}
It is possible to abuse auto-derivation, particularly with logging – dumping an fully automatic case class AST can result in very large logs, but again, the field builder is providing the capability, so you can limit or truncate your output at a single point.
Miscellanous Scala Support
There's a number of small tweaks throughout the code that only show up on direct use. For example, Scala has a number of built-in classes like Option and Either. These are treated as normal case classes, but there can be cases where users would rather log the contained value directly:
trait ShortFieldBuilder extends FieldBuilder with EitherValueTypes with OptionValueTypes
autoLogger.info("{}", _.keyValue("some", Option(1)))
autoLogger.info("{}", _.keyValue("none", None))
autoLogger.info("{}", _.keyValue("right", Right(true)))
autoLogger.info("{}", _.keyValue("left", Left(false)))
yields:
12:35:13.566 [main] INFO com.example.GenericMain$ - some=1
12:35:13.567 [main] INFO com.example.GenericMain$ - none=null
12:35:13.570 [main] INFO com.example.GenericMain$ - right=true
12:35:13.571 [main] INFO com.example.GenericMain$ - left=false
In addition, the Condition and LoggingContext interfaces used in Echopraxia all return Scala collections, so findList returns a Seq and Map[String, Any] for applicable objects:
val isWill = Condition { (context: LoggingContext) =>
val list = context.findList("$.person[?(@.name == 'will')]")
val map = list.head.asInstanceOf[Map[String, Any]]
map("name") == "will"
}
Trace and Flow Loggers
Finally, there are two additional loggers available for Scala.
The trace logger leverages sourcecode to extract as much information as possible from the method to provide trace information on entry and exit:
object TraceMain {
private val logger = TraceLoggerFactory.getLogger.withFieldBuilder(AutoTraceFieldBuilder)
private def createFoo(barValue: String): Foo = logger.trace {
Foo(Bar(barValue))
}
def main(args: Array[String]): Unit = {
val foo = createFoo("bar")
}
}
entry: com.example.TraceMain.createFoo(barValue: String) - (bar)
exit: com.example.TraceMain.createFoo(barValue: String) - (bar) => {@type=com.example.Foo, bar=bar}
The flow logger renders entry and exit information, but doesn't leverage sourcecode data. Otherwise, the API is the same.
This was probably the part that I had the hardest time with.
The reason? Adding source code information has a runtime overhead, even if the logger is disabled. It's minor, but it's there – and in a situation involving tracing, you could reasonably expect every single method inside a hot loop to be called repeatedly.
I've benchmarked and optimized the code repeatedly to minimize object allocation and ensure everything runs as close to native speed as possible, as I know the first question of any logging framework is going to be "is it slow?" But the really important question is "what does my logging framework do when it's turned off?"
SLF4J sets the bar at 2 nanoseconds for an isEnabled check. Echopraxia takes 7.7ns for an isEnabled check (or 0.5ns if you have Condition.never set). But adding sourcecode implicit parameters adds 20 nanoseconds to a logging statement before it even gets tot he isEnabled check.
Adding two versions of the same logger that differ only in their implicit parameters was the best compromise; if the app is slow or seems under GC pressure, then switch to a flow logger and/or use Condition.never to do a direct passthrough.
The other thing I'm happy about in the flow logging API is that again, all control goes through the field builder API. For example, the TraceLogger takes a field builder with TraceFieldBuilder:
class TraceLogger[FB <: TraceFieldBuilder](core: CoreLogger, fieldBuilder: FB) {
// ...
}
where the TraceFieldBuilder determines how the source info is represented and how the enter and exit statements will look:
trait TraceFieldBuilder extends ValueTypeClasses with ListToFieldBuilderResultMethods {
def sourceFields(implicit line: Line, file: File, enc: Enclosing, args: Args): SourceFields
def enteringTemplate: String
def exitingTemplate: String
def throwingTemplate: String
def entering(sourceFields: SourceFields): FieldBuilderResult
def exiting(sourceFields: SourceFields, value: Value[_]): FieldBuilderResult
def throwing(sourceFields: SourceFields, ex: Throwable): FieldBuilderResult
}
and the default can be swapped out:
trait DefaultTraceFieldBuilder extends FieldBuilder with TraceFieldBuilder {
import DefaultTraceFieldBuilder._
override val enteringTemplate: String = "{}: {} - ({})"
override val exitingTemplate: String = "{}: {} - ({}) => {}"
override val throwingTemplate: String = "{}: {} - ({}) ! {}"
override def entering(sourceFields: SourceFields): FieldBuilderResult = {
list(Seq(entryTag) ++ sourceFields.argumentFields)
}
override def exiting(sourceFields: SourceFields, retValue: Value[_]): FieldBuilderResult = {
list(Seq(exitTag) ++ sourceFields.argumentFields :+ value(TraceResult, retValue))
}
override def throwing(sourceFields: SourceFields, ex: Throwable): FieldBuilderResult = {
list(Seq(throwingTag) ++ sourceFields.argumentFields :+ exception(ex))
}
override def sourceFields(implicit line: Line, file: File, enc: Enclosing, args: Args): SourceFields =
new DefaultSourceFields(line, file, enc, args)
}
The logger itself barely knows what's going on. It's stupidly simple:
trait DefaultTraceLoggerMethods[FB <: TraceFieldBuilder] extends DefaultMethodsSupport[FB] with TraceLoggerMethods[FB] {
def trace[B: ToValue](attempt: => B)(implicit line: Line, file: File, enc: Enclosing, args: Args): B = {
handle(JLevel.TRACE, attempt)
}
@inline
private def handle[B: ToValue](
level: JLevel,
attempt: => B
)(implicit line: Line, file: File, enc: Enclosing, args: Args): B = {
val sourceFields = fb.sourceFields
val extraFields = (() => fb.list(sourceFields.loggerFields).fields()).asJava
if (core.isEnabled(level, extraFields)) {
execute(core, level, sourceFields, attempt)
} else {
attempt
}
}
@inline
private def execute[B: ToValue](core: CoreLogger, level: JLevel, sourceFields: SourceFields, attempt: => B): B = {
val handle = core.logHandle(level, fb)
handle.log(fb.enteringTemplate, entering(sourceFields))
val result = Try(attempt)
result match {
case Success(ret) =>
handle.log(fb.exitingTemplate, exiting(sourceFields, ret))
case Failure(ex) =>
handle.log(fb.throwingTemplate, throwing(sourceFields, ex))
}
result.get // rethrow the exception
}
}
One of the things that did matter to me was that source code information should be available as a condition, so I did have to make some tweaks to the Java API to ensure that the core logger could take in some extra fields:
if (core.isEnabled(level, extraFields)) {
// ...
}
This means that you have the option of turning on logging at a TRACE level, and can add a condition that only actually traces for the methods you select. Using the condition API may be around 80 to 500 nanoseconds per call depending on your choice of methods – well worth the cost for throttling your logging output to only what you need.