The caveats of the log4cats interfaces

[Baccata]

Hello everyone

I've been meaning to write this down for a while, and it's not an easy topic to tackle, but I think it's one that deserves some more formalised discussion than an occasional quick rant in discord.

The point of this discussion

The thesis of this post is essentially that the interfaces offered by log4cats are not ideal for a number of reasons, and that using them as a defacto standard logging interfaces in the TL ecosystem is also not ideal, as it accidentally promotes an approach to logging that is vastly imperfect in Scala applications, both from a developer point of view, but also from an operator point of view. In effect, the current log4cats interfaces facilitate the leak of anti-patterns (in the context of FP) that are coming from Java-land.

My team at $work maintains Scala/Java tooling for numerous engineering teams of our organisation. We try to contribute to the open-source ecosystem in some ways, but a lot of what we work on is internal to the company. In particular, in the context of Scala, we maintain observability tooling for our users. This tooling that has tight integration with smithy4s and http4s, and essentially this takes the form of a "bootstrapping" construct that lowers the barrier of entry for having traced http-calls and logs correlated with the tracing information. For tracing, we've elected to expose the Natchez interface to our users (and are planning to explore the otel4s interface once it stabilises a bit). For logging however, even though the TL ecosystem provides a logging library in the form of log4cats, we've decided to ditch it in favour of a homegrown interface, which has surprised some of our users.

As the ecosystem expands, it pains me to see that the logging interface that the TL community has adopted as defacto standard suffers from the caveats that has led my team to create a homegrown thing, and motivates me to write a bit about it.

The POC

Instead of braindumping in the discussion, I've taken the time to describe the problems we see in the log4cats interface in this repo, and to expose a POC inspired from what we've done at $work but stripped out the coupling we've enforced :

https://github.com/Baccata/logger-poc/

In particular, the core of the POC is the LoggerKernel interface. What distinguishes from the log4cats interfaces are the following point :

1. It's a Single Abstract Method interface, which makes it extremely middleware friendly (compared to log4cats' StructuredLogger which has 20 abstract methods)
2. It uses an inversion-of-control pattern, where instead of providing a Log datatype directly, the single method takes a function of type Log.Builder => Log.Builder that allows to enrich such log data with bits of information. Because the user is not responsible for creating the log instance, it means that the LoggerKernel implementations are free to decide upon how the data is stored in memory. The repo showcases a Log implementation backed by a mutable data structures, thus having better control on the amount of allocations
3. The Log.Builder exposes a context capture method that leverages the visitor-pattern to capture (much) richer information than what a Map[String, String] allows for, while still giving the control to implementors over if and how the data should be stored in intermediate data structures.

Additionally to this LoggerKernel interface, the following POC elements are provided in this repo :

1. Integration with the existing log4cats interfaces to showcase that, if the TL community was agreeing with the point I'm trying to make, the transition from the current interface to something better could happen gradually
2. A higher-level logging interface that can be used on top of LoggerKernel, allowing for the capture of source-code information by means of the implicit macros provided by the sourcecode library, enriched with varargs-based methods that allow for capturing many bits of information without exponentially increasing the size of the interface.
3. A fs2-powered, POC implementation of LoggerKernel, that uses a Channel as a multiple-producer/single-consumer queue, and a more specialised one that prints logs to stdout in the background. Although the POC compiles against Scala 3.3.x on JVM, the code can be cross-compiled to all versions and all platforms supported by fs2.
4. An example application that showcases stuff

The goals

In my mind, the goal of this exercise would be the reaching of an acknowledgment that the current log4cats Logger and StructuredLogger interfaces, as a central pillar to the TL ecosystem, are far from ideal, and that we could work towards improving the situation by providing better interfaces for application-developers and library-developers alike.

[ybasket]

I really like the proposal and the POC!

At $WORK, we ran into some problems similar to what you describe and also ended up writing our own interfaces on top. In our case, this also (but not exclusively) stems from the fact that we mostly use https://github.com/valskalla/odin for logging, but as TL libraries like http4s rely on log4cats, we can't avoid interacting with it. This leads to us bridging log4cats->slf4j->Odin. I would happily ditch this setup for a log4cats that has richer context structure, source code location and less coupling to slf4j.

The design goals of the POC read sound, I agree with them. The code looks good at first glance (besides irrelevant nitpicks) and I like the fact there's a fs2 backend, that's something I've missed with log4cats so far.

[djspiewak]

So I really like the PoC, and the Fs2 backend is great. One caveat I will add though is that it's important to think through how to reduce allocations when certain log levels are disabled. It's kind of crappy that this is a problem worth thinking about, but it genuinely is (at least with TRACE and DEBUG levels, both of which are frequently disabled in production and are correspondingly often very chatty). So that in turn means that LoggerKernel probably needs to be macro-ified to some extent, with all the annoyance that entails.

[Baccata]

I don't think macro-ification at that level is absolutely necessary. Here's why :

At the time of writing this, the LoggerKernel interface looks like this :

trait LoggerKernel[F[_]] {
  def log(record: Log.Builder => Log.Builder) : F[Unit] 
}

The reason for record to take a function is that it already gives some control to the implementors of the interface over what is stored and how. The interface for Log.Builder is this :

trait Builder {
    def withTimestamp(value: FiniteDuration): Builder
    def withLevel(level: LogLevel): Builder
    def withLevelValue(levelValue: Double): Builder
    def withMessage(message: => String): Builder
    def withThrowable(throwable: Throwable): Builder
    def withContext(name: String)(f: Context): Builder
    // ... 
    def build(): Log
  }

which implies that allocations of String in particular (which are a big offender) can be eluded. Now, it certainly doesn't prevent all allocations. In particular, I think the Log.Builder => Log.Builder lambda would have to be allocated, even if it ends up being backed by something that applies a no-op in specific log levels.

First of all, it's likely that facilitating the no-op by promoting the Level to a bonafide method parameter would probably make it easier for implementors :

trait LoggerKernel[F[_]] {
  def log(level: LogLevel, record: Log.Builder => Log.Builder) : F[Unit] 
}

From there, I think turning the record parameter into a byName, it'd suffice to allow for circumventing allocations without macro-ification :

trait LoggerKernel[F[_]] {
  def log(level: LogLevel, record: => Log.Builder => Log.Builder) : F[Unit] 
}

which at this point maybe eliminates the value of inverting the control over if/how the data is stored, which may mean that the interface could be :

trait LoggerKernel[F[_]] {
  def log(level: LogLevel, data: => Log)
} 

The implication being that the only parameter implementors to control the instantiation would be the level. But it's probably more intuitive to most people.

[djspiewak]

String allocation is only the biggest offender in logging because we tend to log strings. In more structured logging systems (e.g. systems that log protos and don't allow you to log strings) then your allocation pressure shifts to those objects. In this case, the allocation pressure would be on two things: the lambda and the Log.Builder instance.

To make matters worse, making the lambda by-name doesn't really solve the problem, it just shifts the allocation to a Function0 which wraps around a lambda, so now your allocation pressure is Function0 instances. This is actually a step backward from String instances since String has magical GC semantics which compress the memory footprint and make allocations cheaper over time, whereas other objects do not benefit from this.

I don't see a way around some form of macroing. Obviously with Scala 3 you can use inline instead, which is effectively a form of macro but a more restricted one. You might not necessarily need to shift the level into the signature as a first-class thing, since you can have a special Log.Builder singleton which is just "don't log", though you wouldn't be able to do that without playing fast and loose with configured log level checking.

[Baccata]

Okay, I'm certainly happy to defer to your knowledge about allocations. I'm however concerned about the implications of having the central interface expose a single-abstract macroified method, in particular with relation to middleware.

It may work okay in scala 3 thanks to the inline keyword (without polluting the interface with an actual macro) but it'd probably not work at all in scala 2. Moreover, I'm not certain whether the central interface should come with an implication that the configured log level threshold should be inspectable, which would be required for the implementation of the macros

Is a "0 allocations on disabled log levels" goal even worth pursuing, as opposed to trying to not go crazy with allocations ? It doesn't seem to be a goal of the current interfaces.

[djspiewak]

Is a "0 allocations on disabled log levels" goal even worth pursuing, as opposed to trying to not go crazy with allocations ? It doesn't seem to be a goal of the current interfaces.

I suppose this is fair. For posterity, the current Logger interface in log4cats unconditionally allocates a thunk => String, as well as the effect itself. Thinking it through, we can at least do a bit better than this if we allow inspection of log level as an uncontrolled side-effect in the builder, which would allow us to short-circuit both the Log.Builder allocation (returning a singleton non-builder) as well as the effect allocation (returning F.unit). At minimum, this wouldn't regress the current log4cats behavior.

I share your concerns about the macroified function. What if we compromise and only do it for Scala 3? I'm kind of okay with saying "alright, we didn't regress Scala 2, and we made Scala 3 what it always should have been".

[Baccata]

if we allow inspection of log level as an uncontrolled side-effect in the builder, which would allow us to short-circuit both the Log.Builder allocation

Mmm not exactly sure if when you say "log level" here, you mean log threshold, or the level of the log indicated by the caller ? I wouldn't want to assume that the log threshold could be retrieved via an uncontrolled effect, this would force too much assumption onto the interface.

As for the log level I'm more and more weighing towards promoting it to bonafide method parameter, it's much less contortion to operate on.

"alright, we didn't regress Scala 2, and we made Scala 3 what it always should have been".

right so my understanding of inlines was way off, and we can't use it in the kernel interface, as the compiler will not let callers invoke abstract inlined methods.

So I think the problems needs to be approached from two angles

1. what can implementors of back-ends do to minimise allocations ?
2. what can callers of front-ends do to minimise allocations ?

From the point of view of the implementors of logging back-ends

The idea of inverting control by exposing Log.Builder => Log.Builder so that the implementor has control over the memory layout of a log caters to point 1 : this allows to leverage mutable builders (avoiding allocation of "Log" case-classes), prevents the creation of intermediate Json ADTs, and prevents the allocation of un-necessary Options. This, I think, reduces GC pressure when logs are actually dispatched .

Additionally, promoting the LogLevel to a bonafide method parameter allows the implementors to make the decision to short circuit the execution of the Log.Builder => Log.Builder lambda altogether when the value is below a certain threshold. It doesn't prevent the allocation of the lambda in question, but at least its execution.

From the point of view of the callers of logging front-ends

This is where Scala 3 inlines (and potentially Scala 2 macros) can be of interest. Once again, the promotion of LogLevel to method parameter is appealing :

trait LoggerKernel[F[_]] {
  // no inline keyword at this level
  def log(level: LogLevel, record: Log.Builder => Log.Builder) : F[Unit] 
}

This allows for threshold-aware frontends that can circumvent most allocations :

  class ThresholdAwareLogger[F[_]: Monad](logThreshold: F[Double], kernel: LoggerKernel[F]) extends LoggerKernel[F] {
    // inline here, because it's not an abstract methods, callers can it provided they're using the `ThresholdAwareLogger`
    inline def log(level: LogLevel, record: Builder => Builder): F[Unit] = logThreshold.flatMap { t =>
      if (level.value < t) Monad[F].unit
      else kernel.log(level, record) // the lambda would only be allocated on this branch 
    }
    
    // add whatever other `inline` methods to get decent UX 
  }

Here the only allocation added by the log call would be the reified FlatMap instance. If applications where logThreshold can be statically determined for the lifecycle of the logger, you could even have another version without flatMap.

threshold in front-end vs threshold in kernel interface?

We can play with how those things should live :

So essentially the question is : is the notion of logThreshold something that is fundamental enough to be part of a kernel interface ?

// not SAM anymore, but 2 methods is still somewhat middleware-friendly 
trait LoggerKernel[F[_]] {
   def logThreshold: F[Double] // can always be implemented with `F.pure(Double.MaxValue)`
   def log(level: LogLevel, record: Log.Builder => Log.Builder) : F[Unit] 
} 

Should a kernel interface offer more front-end-ish methods OOTB, getting rid of a LoggerKernel abstraction in favour of a more blessed Logger that would retain a SAM nature but expose inline/macro methods ?

abstract class Logger[F[_] : Monad] { 
   def logThreshold: F[Double] 
   def dispatch(level: LogLevel, record: Log.Builder => Log.Builder) : F[Unit] 
   
   inline def log(level: LogLevel, record: Log.Builder => Log.Builder): F[Unit] = logThreshold.flatMap { t =>
      if (level.value < t) Monad[F].unit
      else dispatch(level, record)
    }
    
    // add whatever other `inline` methods to get decent UX 
} 

Honestly I' don't know. Having a more prescriptive core-interface may force prevent ill-usage in applications and libraries alike, but I'd rather the stakeholders (ie library maintainers) weighed in.

[kubukoz]

I dig this. You had me at SAMs and a JSON abstraction.

[CJSmith-0141]

Thank you for putting this forward, I really like the proposal and the code.

How would you do something like this with your proposed interface?

def runEffectAndLogDuration[F[_]: Monad, A](
      effect: F[A],
      description: String
  )(using clock: Clock[F], logger: SelfAwareStructuredLogger[F]): F[A] =
    clock.timed(effect).flatMap { case (dur, res) =>
      logger.info(s"effect $description took ${dur.toMillis}ms") >> res.pure[F]
    }

If I'm reading the code correctly it looks like Logger would be a drop-in replacement for SelfAwareStructuredLogger?

[Baccata]

@CJSmith-0141 I wouldn't say "drop-in" because it's a different interface/UX, but it'd certainly meant to be an alternative/replacement.

One of the point is that application-writers and library-writers should be able to use different front-end constructs if they want to, but libraries should declare logger: LoggerKernel as a user-facing parameter when they need a logger.

[lorandszakacs]

As one of the (absentee) maintainers of log4cats this proposal echoes very many things I have found lacking in log4cats but unable to muster the effort to bring them about. First, we must acknowledge that the interfaces we see log4cats were designed to make the fewest source code changes in order to stop doing side-effecty logs in .map(_ => logger.info(...)) calls and the like. The need for this concern is (partially) gone.

Now, since I do not like the past to haunt me too much, could we embark on a road to make the interfaces in this proposal a log4cats 2.7.0 and then a 3.0.0? I could imagine something like this:

1. log4cats ships with all new interfaces in a minor version 2.7.0, deprecates the old ones (or doesn't, maybe even later). The shims from the new ones to the old ones get shipped as well.
2. 2.7.0 would release with new interfaces. Definitely does not break all of the downstream ecosystem. Compromising on some symbol naming could possibly be necessary.
   a) could it be possible to unite the two new approaches under the existing LoggerFactory[F[_]] so that even downstream libraries can still ask for the interface as they did previously, while internally shifting to methods that provide new loggers?
   b) scalafix to just migrate (some?) existing usages of old interfaces to the new thing?
3. eventually release a log4cats 3.0.0 when the entire ecosystem is changing due to a cats 3.0.0 😸

I am writing this up in a hurry, but I am definitely willing to put some effort into seeing this done somehow. And I started an enumeration because I expected the process to be much more difficult than this 😅

[kubukoz]

I started an enumeration because I expected the process to be much more difficult than this

Don't worry, things always get more difficult than planned :)

[Baccata]

I agree with the overall plan as you formulate it. The symbol naming is the thing that concerns me a bit as in even if 3.0.0 was binary breaking, I don't think the org.typelevel.log4cats.Logger symbol should be replaced by something entirely different, and there's a legitimate user expectations that looking for Logger in their IDE should give the right thing.

I don't want to open for bike shedding on symbols in this discussion, but it'll be worth putting some thoughts into it.

[Baccata]

@rossabaker, @iRevive, @ChristopherDavenport : hey folks, apologies for the ping, but I'd like your take on this, if you can spare the time. I think it's relevant to http4s / otel4s / the davenverse.

[rossabaker]

I haven't followed the conversation closely, but as long as

the transition from the current interface to something better could happen gradually

is true, I have no particular objection. But I don't immediately see a way to request the new interface in library code without breaking changes, and even if log4cats can stay 2.x, I am concerned about it triggering another ripple of incompatible major versions in the stack between log4cats and apps.

[Baccata]

Yup, that's a fair concern. I guess the next step of this discussion is for me to explore the options in http4s to ensure that a non-breaking path can be prescribed.

[rossabaker]

If it's impossible in http4s-0.23 (and then presumably also others), that shouldn't be a dealbreaker. Apps might get to enjoy the advantages now. But given that I spent a part of my day dealing with Cats-Effect 3.5 breakage many months after the fact, I just want to remind all library authors of the cost of breaking changes.

If we can manage that, I like the proposal.

[iRevive]

I like the proposal. At $work we primarily use https://github.com/valskalla/odin for logging, because the functionality can be extended in a matter of a few lines. With log4cats, in the current state, the situation may be different (e.g. #800).

The POC looks good. I like the SAMs and Builder and how easy a middleware can be implemented.

[Baccata]

I've taken a little time to wire my POC into http4s, see whether it could be done in a non-breaking way. Here it is, for the curious : Baccata/http4s#2

[lorandszakacs]

I've taken a little time to wire my POC into http4s, see whether it could be done in a non-breaking way. Here it is, for the curious : Baccata/http4s#2

This is looking great! A similar pattern can be applied to libraries that request org.typelevel.log4cats.LoggerFactory[F], and I think we have a genuine path forward.

[iRevive]

A little late.

The poc looks good. I like the composable API and straightforward design.

The API feels a bit low level. But I agree that each library can build whatever abstraction they want on top of the low-level code.