Spying -- or a functional way to log in Scala

All of the logging utilities I've found for Scala suffer from the same problem: they are not written in a functional-programming style. Here's the problem: you want to log the result of a function which, to choose an example more or less at random, looks like this:

  def map2[T, U](to1: Option[T], to2: => Option[T])(f: (T, T) => U): Option[U] = for {t1 <- to1; t2 <- to2} yield f(t1, t2)

Now, we decide that we'd like to log the result of this method (or maybe we just want to print it to the console). To do this the "traditional" way, we would need to write something like this:

  def map2[T, U](to1: Option[T], to2: => Option[T])(f: (T, T) => U): Option[U] = {
    val logger = LoggerFactory.getLogger(getClass)
    val r = for {t1 <- to1; t2 <- to2} yield f(t1, t2)
    logger.debug(s"map2: ${r.toString}")
    r
  }

We have interrupted the flow of the expression, we've had to create a new variable (r), we've had to wrap it all in braces. Not cool!

So, I looked around for something that could do this the functional way. Unfortunately, I couldn't find anything. There is something in Scalaz but it looked complicated and maybe a little too general. So I decided (as I often do) to write my own and call it Spy.

One of the design decisions that I had to make was this: I don't want the Spy to have to be instantiated for every user invocation, or even every class that an invocation appears in. Yet I want each invocation/class to be able to customize the spying behavior somewhat. That's where implicits come (again) to the rescue. But the spy-function (the one that actually does something with a String formed from the expression's value) needs to be found. The natural type of the spy-function is String=>Unit but it turns out that the implicits mechanism couldn't deal with something so ordinary so I changed it to String=>Spy where the Spy class is essentially just a wrapper that has no real significance. Then, the implicit value for the spy-function (if any) could be found and used.

One example of a need to customize the implicit value is to forget about logging and simply write to the console. I tried to make this as easy as possible. See the specification in the repo (linked at the bottom) for an example of this.

Here, using the default slf4j logging mechanism, is the map2 function with logging. Note that, when you use the default mechanism, you must provide an implicit value of a logger in scope. A convenience method has been provided for this as shown below.

  implicit val logger = Spy.getLogger(getClass)
  def map2[T, U](to1: Option[T], to2: => Option[T])(f: (T, T) => U): Option[U] = Spy.spy(s"map2($to1,$to2)",for {t1 <- to1; t2 <- to2} yield f(t1, t2))

We test it using the following specification for map2 (unchanged):

  "map2(Option)" should "succeed" in {
    val one = Some(1)
    val two = Some(2)
    def sum(x: Int, y: Int) = x + y
    map2(one, two)(sum) should matchPattern { case Some(3) => }
    map2(one, None)(sum) should matchPattern { case None => }
  }

And the resulting entries in the log file are:

2016-12-06 22:35:04,123 DEBUG com.phasmid.laScala.fp.FP$  - spy: map2(Some(1),Some(2)): Some(3)
2016-12-06 22:35:04,128 DEBUG com.phasmid.laScala.fp.FP$  - spy: map2(Some(1),None): None

All we had to do, for the default logging behavior, was to ensure there was an implicit value of logger in scope and wrap the expression inside an invocation of Spy.spy. Everything is still purely functional. You can even leave the spy invocation in place if you really want to and either explicitly switch it off by adding false as a third parameter or by turning off debugging in the logger.

If you're interested in using this you can find the Spy class, together with its SpySpec, in my LaScala project.