Clear and concise logging in Scala
As I was working on a new Pricing Service for the Depop backend the other day, I realised that it needed more logging. A lot more to be honest.
The Pricing Service will serve to supply prices for all of the products on Depop’s market to our internal services and it is vital that we can see the logs of how it is working.
Logging is one of those things — along with unit testing and monitoring — that ought to be woven into the writing of the code, but often gets relegated until after the core functionality is written.
Admonishing myself, I set about examining the program for places where logging would most illuminate the progress of the price calculation and in particular, the places where things might go awry.
As I did this I noticed a couple of things…
The code got uglier
In Scala, the last value calculated in a function is the return value.
This leads to concise code like:
val calculatePrice = (price: Price) =>
(maybeShippingPrice: Option[Price]) =>
maybeShippingPrice.map(p => p + price)However, with logging, it gets a lot bulkier:
val calculatePrice = (price: Price) =>
(maybeShippingPrice: Option[Price]) => {
val maybeTotal = maybeShippingPrice.map(p => p + price)
if (maybeTotal.isEmpty) {
logger.info("No shipping price available")
}
maybeTotal
}There was a pattern to the logging
I kept coming across the same pattern in logging as we see above — in general:
def exampleFunction[T](arg: T): String = {
val result = calculateStringFromT(arg)
if (someTestOn(result)) {
logger.error(s"The test on result was true - arg was [$arg]")
}
result
}This was screaming out for generalisation.
Also, it would be great if we could make it look less ugly¹.
The types involved
Breaking down our exampleFunction, we have:
- A result
- A condition for logging based on the result
- A means of logging a string
- A string to log
The result could be anything, so let’s denote this by the type variable T.
The condition is a predicate:
type LoggingPredicate[T] = T => Boolean
The means of logging is a procedure² that takes a String:
type Logger = String => Unit
The String that is logged is calculated from the result and may use the variables available at the time. If this function is defined within the function to be logged, it will have access to the local variables, so all we need is:
type MessageGen[T] = T => String
A first stab at a logging function
Given these types, we can start to build a logging function:
def log[T]( t : T,
shouldLog : LoggingPredicate[T],
logger : Logger,
msgGen : MessageGen[T] ): T = {
if (shouldLog(t)) logger(msgGen(t))
t
}Improving things with Partial Functions
We can combine the functionality of the logging predicate and the message generator by making the message generator a partial function:
type MessageGen[T] = PartialFunction[T, String]A partial function is only defined for a subset of its possible inputs. We use this to log the String it returns when it is defined and skip logging when it’s not:
def log[T]( t : T,
msgGen: MessageGen[T],
logger: Logger ): T = {
msgGen.lift(t).foreach(msg => logger(msg))
t
}We don’t want to get an exception if the partial function is not defined, so we call lift(t) on it. This converts the partial function to a plain function that returns None if the parameter passed is not in the domain of the partial function and Some(msg)if it is. Only in the case of the latter is the logger called.
Using the logging function
Let’s see how this looks from the client’s point of view by revisiting the earlier example.
First, let’s set up some Loggers³
val info : Logger = s => logger.info(s)
val warning : Logger = s => logger.warn(s)
val error : Logger = s => logger.error(s)Now we can update the example function to use our new log function:
def exampleFunction[T](arg: T): String = {
val result = calculateStringFromT(arg)
val msgGen: MessageGen[String] = {
case "" => s"The result was empty - arg was [$arg]"
}
log(result, msgGen, info)
}Notice how MessageGen now being a partial function enables elegant implementation using pattern matching syntax.
If we also move it outside the function, we can clarify things even more:
private def msgGen[T](t: T): MessageGen[String] = {
case "" => s"The result was empty - arg was [$t]"
}
def exampleFunction[T](arg: T): String = {
val result = calculateStringFromT(arg)
log(result, msgGen(arg), logger.info)
}Now it’s starting to look better! However the log function does not communicate its intent well to a human reader. What we are trying to say, in English, is:
Log this item using this message generator at level info, then return it.Let’s see if we can craft a more fluent interface to express this clearly.
Some syntactic sugar to improve readability
To improve the readability of this code, we are going to use two tools — currying and implicit classes.
First, let’s curry the log function:
def log[T](t: T): MessageGen[T] => Logger => T = {
msgGen => logger =>
msgGen.lift(t).foreach(msg => logger(msg))
t
}Currying the log function has changed it from a function that takes three parameters and returns a value T, to a function that takes one parameter and returns another function of MessageGen[T] => Logger => T
So now instead of calling:
log(result, msgGen(arg), logger.info)We call:
log(result)and defer the supplying of the rest of the parameters for later.
This takes advantage of the fact that in functional programming languages, functions are values. Given that, we can now use an implicit class to add functions to this type:
implicit class MessageGenOps[T](f: MessageGen[T] => Logger => T) {
def using(msgGen: MessageGen[T]): Logger => T = f(msgGen)
}Note the implicit class takes a single parameter of the type returned by our curried log function. This lets us call the defined function — using — on the return value of log, making a chain of calls typical for a fluent interface:
log(item).using(msgGen)
Having supplied the MessageGen parameter of the log method’s return type, we’re now left with Logger => T.
So we make another implicit class:
implicit class LoggerOps[T](f: Logger => T) {
def atLevel(logger: Logger): T = f(logger)
}Now we can write log(item).using(msgGen).atLevel(info) which is almost there, we just need one more implicit class:
implicit class SelfHelper[T](t: T) {
def andReturnIt: T = t
}This may seem like an odd class — it has no functionality! It does, however, let us complete our fluent chain of calls gracefully:
log(item).using(msgGen).atLevel(info).andReturnItCompare this with our English sentence:
Log this item using this message generator at level info, then return it.Pretty close, eh?
Logging parameterised types
Going back to our original motivating example, let’s add logging to it using our new functionality:
val msgGen: MessageGen[Option[Price]] = {
case Some(price) if price> 50 => "Expensive shipping"
}val calculatePrice = (price: Price) =>
(maybeShippingPrice: Option[Price]) => {
val maybeTotal = maybeShippingPrice.map(p => p + price)
log(maybeTotal).using(msgGen).atLevel(info).andReturnIt
}
Here, we are logging a value of type Option[T]. This is a parameterised type, often referred to as generic⁴.
Note the predicate price > 50 is really on the inner Price value, but since log is typed:
def log[T](t: T): MessageGen[T] => Logger => Tthis binds T to Option[Price], so we need to define our message generator as MessageGen[Option[Price]].
It is simple enough to unwrap the Option, in this case, but it would get more annoying for List and other collections.
There is an important type where this approach won’t work at all, though.
Future
A Future represents a value that is still in the process of being calculated. We cannot create a MessageGen[Future[T]] because it will block until the future value is populated.
Fortunately, it turns out that Future has a function that will accept a procedure as a parameter and execute it once the value is generated:
def foreach[U](f: (T) => U)
(implicit executor: ExecutionContext): UnitThis suggests we should be able to create a logging function for Future using foreach:
def logF[T](ft: Future[T])(implicit ec: ExecutionContext):
MessageGen[T] => Logger => Future[T] = {
msgGen => logger => {
ft.foreach(t => msgGen.lift(t).foreach(msg => logger(msg)))
ft
}
}Once the Future resolves, it will call the function passed to foreach and log if the future value is in the domain of msgGen.
A logger for parameterised types
We can try to generalise this future logger to all single parameter types :
def logEachBad[T, F[_]](ft: F[T])
: MessageGen[T] => Logger => F[T] = {
msgGen => logger =>
ft.foreach(t => log(t)(msgGen)(logger))
ft
}but this won’t compile because there is no evidence that F[T] has a foreach function.
Generalising ForEach using Type Classes
This is interesting because Option, List etc. do have foreach functions. The problem is that there is no trait that these types have in common with Future that we can use as a type bound to F[_] to prove that.
But we can make one:
trait ForEach[T, F[_]] {
def forEach(ft: F[T]): (T => Unit) => Unit
}ForEach⁵ is a type class that we will use to provide F[_] with forEach⁶ functionality for List, Future, Option etc.
The implementations are trivial and make use of SAM conversion⁷, allowing us to implement the single abstract method of the ForEach trait with a lambda:
implicit def optionForEach[T]: ForEach[T, Option] =
(t: Option[T]) => t.foreachThe implementation for List, Set, Option et al. would, in fact, all be identical, because they share a common trait — IterableOnce — which contains their foreach method. So we can replace the above with:
implicit def itrForEach[T, F[A] <: IterableOnce[A]]: ForEach[T, F] =
(ft: F[T]) => ft.iterator.foreachWhich lets us cover List, Set, Option and all other IterableOnce subclasses.
This, combined with the implementation for Future:
implicit def futureForEach[T](implicit ec: ExecutionContext)
: ForEach[T, Future] =
(ft: Future[T]) => ft.foreachshould cover most cases.
Each implementation is tagged as implicit. We can see why when we look at the updated definition for logEach:
def logEach[T, F[_]](ft: F[T])
(implicit fe: ForEach[T, F])
: MessageGen[T] => Logger => F[T] =
msgGen => logFn => {
fe.forEach(ft)(t => log(t)(msgGen)(logFn))
ft
}When a client wants to log a Future, the implicitForEach value must be available in implicit scope. The compiler will then provide it as the ForEach[T, F] parameter.
This is ad-hoc polymorphism and it’s awesome!
We can ensure all instances are in implicit scope by putting them in ForEach’s companion object⁸:
object ForEach {
implicit def futureForEach ...
}Then, simply importing ForEach itself brings all of the implicit instances into scope:
import util.ForEach
val intF: Future[Int] = calculateFancyInt()
val msgGenInt: MessageGen[Int] = { case 0 => "Zero returned!" }
logEach(intF).using(msgGenInt).atLevel(info).andReturnObserve that in logEach, the type of the MessageGenerator — T and the return type of logEach — F[T] are different, unlike log in which they are the same.
This means we have to make a small change to one of our earlier implicit classes to accommodate that:
implicit class MessageGenOps2[T, R]
(f: MessageGen[T] => Logger => R) {
def using(msgGen: MessageGen[T]): Logger => R = f(msgGen)
}One more thing - Either
As its name suggests, the value of an Either[A, B]can be either Left(a: A) or Right(b: B).
It has a foreach method that is a bit like Option’s in that if the Either is a Right(b), it will provide that value to the supplied procedure, but if it’s a Left, it will not call the procedure at all.
The problem is that its type constructor takes two type parameters, so it doesn’t fit the patternForEach[T, F[_]]which expects just one.
We can solve that by fixing the A parameter⁹ to, for example, Error:
type ErrorOrT[T] = Either[Error, T]
Then:
implicit def errorOrTForEach[T]: ForEach[T, ErrorOrT] =
(ft: ErrorOrT[T]) => ft.foreachWe can use a similar trick to let us log a nested type¹⁰ using the inner value, for example:
type FutureOption[T] = Future[Option[T]]
implicit def futureOptionForEach[T](implicit ec: ExecutionContext)
: ForEach[T, FutureOption] =
(ft: FutureOption[T]) =>
(proc: T => Unit) => ft.foreach(opt => opt.foreach(proc))This will let us log a Future[Option[T]] using a MessageGen[T]¹¹
Conclusions
Logging is important. Your on-call support team will thank you for it if it’s done well (and curse you if it’s not).
The small DSL presented here is designed to make it easy to log messages in a way that is clear for the reader of the code and all without adding unsightly postscripts to your functions.
So, no excuses!
¹ The aesthetics of code are, of course, purely subjective.
² We define a procedure as any function that returns Unit.
³ We are using play.api.Logger here, which uses slf4j under the covers.
⁴ This is parametric polymorphism.
⁵ ForEach is slightly more constrained than the foreach methods of Future, Option etc. They expect a function of T => U where we require T => Unit. In practice, the reason that the type variable is called U is that it will be discarded even if it is not Unit, so you could pass a function of, say, T => String to foreach, but you’ll never know what the String value was.
⁶ I’ve never understood why foreach is all one case in Scala libraries.
⁷ The T parameter in ForEach could have been brought down to the function level, but SAM Conversion would not then be possible as the single abstract function would be polymorphic.
⁸ The alternative would be to put them either in the same or separate objects and import them individually as needed. In cases where the implicits might be ambiguous, this would be required.
⁹ Or we could have used a kind projector.
¹⁰ Future[Option[T]] is not a higher kinded type since Future is defined as Future[T]not Future[F[_]], it just happens that T is being bound to a generic type in this case.
¹¹ We could have used a monad transformer like Cats’ OptionT here to simplify this implementation, but since I got all the way through this article without mentioning the M word, I didn’t want to spoil it.
