It's been a minute. After releasing the Scala API for Echopraxia and writing it up, I've been working my way up the chain and trying to exploit/break the API with progressively more demanding use cases.
Akka has been a personal favorite testing ground of mine. Akka is deeply concurrent, and as such using a debugger is nearly pointless – even if you add breakpoints, you'll trip over timeouts if you take too long to return a message. As such there's really only two reliable ways to debug and observe Akka code. Unit tests… and logging.
So. The task I set myself was to add structured logging to Akka. I already had an advantage in that I'm familiar with Akka internals, and in the end it was fairly straightforward with only a couple of surprises.
The first obstacle to adding structured logging is that the
MarkerLoggingAdapter serializes arguments into a String before publishing it to the event bus, using formatN to convert arguments.
MarkerLoggingAdapter converts arguments to String eagerly, any arguments that pass through Akka's logging will be flattened and can't be retrieved later – there is no
Error(msg, arg1) passed through to the event bus and then to
It is still possible to pass through structured data though! Because the MarkerLoggingAdapter passes through
LogMarker then using
SLF4JLogMarker will pass along an
org.slf4j.Marker through to Logback, and we can piggyback information on the way.
This led me to think about using Echopraxia directly against SLF4J.
Echopraxia does allow you to log using an
org.slf4j.Logger directly for simple cases. For example, arguments work fine:
Although as exceptions in SLF4J get "eaten" if they have a template placeholder, if you want to keep the exception, you need to pass it in twice:
I added some direct API features to Echopraxia. Using the direct API, context fields can be represented by
FieldMarker, and conditions by
ConditionMarker. This passes information through to the backend appropriately.
This is only half the story though – the condition still needs to be evaluated, and because that doesn't go through an Echopraxia logger, that means adding a
And then also when rendering JSON, we need to swap out the
FieldMarker with actual event specific custom fields that
logstash-logback-encoder will recognize, using
This… is a hack, and I don't love it. The problem here is that there is no central pipeline for creating and manipulating Logback's
LoggingEvent. The turbo filter API will only let you return
FilterReply and the actual creation of a
LoggingEvent happens internally. So… if you want to tweak the logging event, you have to have an appender transform it, then pass it through to the appender's children. This is the approach used in composite appenders.
This is complicated by Logback not officially supporting
appender-ref for appenders themselves. You can add
appender-ref from the root:
but even though it's perfectly legal to have appender children, to add
appender-ref on appenders, you need to explicitly loosen the
AppenderRefAction to match (which can cause complaints):
On a tangent, because Logback runs through appenders in sequence in the same thread, it's possible for synchronous appenders to block asynchronous appenders:
As such, either you have multiple async appenders, or you wrap all the IO appenders inside a disruptor so you only have the overhead of one thread. This means that appenders can really serve three different roles: managing concurrency, event transformation, and IO sinks with encoders.
Adding the direct API means that there is a fallback position, but I found that it was still very fiddly. Filters and other features that depend on composing loggers are not available in SLF4J. Aggregating multiple markers is awkward, even leveraging implicit conversion.
The second option was to sidestep the
LoggingAdapter altogether and extend Akka's models with a structured logging API. There are two models in Akka: actors and streams, and they each have their own approach.
The first goal was to provide values for Akka components. The plan was to create structured output that would correspond to the
toString debug output. But Akka components such as
ActorPath make heavy use of internal APIs that are only accessible under the
akka package. Solution: define the package as
akka.echopraxia to open up the API.
First, a pure trait so you can provide your mapping:
and then some default implementations:
So far, so good.
There are two Scala APIs for Akka actors, typed actors and "classic" untyped actors. The logging in Akka Typed, and the logging in Akka Classic are a little different, but they both provide additional context in the form of MDC.
Next: create an echopraxia equivalent to
ActorLogging. This is a bit complicated, because an echopraxia logger needs a field builder, and that means that an actor has to be able to provide it. That's okay – we can define the field builder requirement by adding
and then use a self type to create a logger using the given field builder:
And that opens the door to actors with an Echopraxia logger:
This is pretty straightforward and almost transparent.
Next, we need an implicit
EchopraxiaLoggingAdapter for our version of
And we're good to go.
LoggingReceive will take an
Any because it's untyped, so that gets rendered with a standard
For Akka Typed, it's pretty much the same thing. We'll need to render
AkkaTypedFieldBuilder similar to the
AkkaFieldBuilder, but working with typed
Behavior[T] means that we can require that the message passed through has a
fieldBuilder.ToValue defined on it, which is easiest to do on the logger itself through implicits rather than
Okay, but how does that work?
Well, there's a
Behaviors.intercept method that does what we want. This isn't in the documentation, but it is is part of the public API so we can use it and pass it to the
If it doesn't have a
fieldBuilder.ToValue, it doesn't compile, and all output uses the given field builder instead of a global unstructured
toString. Finally, at long last.
Integrating Echopraxia with Akka Streams is a bit different, as it involves type enrichment on the
FlowOps methods (and their
Context equivalents). This follows from the custom operator suggestions given in the docs:
SourceLoggingStage is not a
FlowOps itself, it does require an
elog.info("name") to close the loop. This takes out the implicit
LoggingOptions (which I really don't like) and allows for
elog.withFields similar to the
Each logging stage class breaks down into a call to
EchopraxiaLog, which has structured logging for the graph stage and exposes the graph stage operation as
extract method means that you can decide how you want to render the field, using
One of my hopes was that I could represent a
Flow as a tree through structured logging. This doesn't seem possible from what I can tell, because streams are "traversable" and a traversal builder doesn't have a complete picture of the flow before it's built – I can render the inlets and outlets, but it's not the same. It's the same problem with functions – referential transparency means that you have to use something like treelog to describe a computation.
It's really nice to see how the early bets have paid off. One unexpected win was being able to resolve
ByteString as a structured
utf8 string instead of an array of bytes. The default implementation contains both bytes length and utf8:
Being able to render ByteString as either binary focused or text focused depending on what field builder is passed in is great.
Another win is the automatic type class derivation – since messages are typically case classes, it's trivial to add mappings in field builders for them.