Monadic Logging and You

Martin Snyder / @MartinSnyder / Wingspan Technology, Inc.

Logging can be a mess

Immediacy implies synchronization
Interleaved log entries
Clustered Servers
Cross-tier correlation

Mess #1 - Immediacy implies synchronization

A system has a transient problem. Logging is added to diagnose the problem which then becomes non-reproducible.

Mess #2 - Interleaved log entries

A user in a multi-user system performs an action known to produce an unexpected behavior. Tracing their execution through the log file is difficult because their log statements are interleaved with log statements from other users.

Mess #3 - Clustered Servers

A user performs an action known to produce an unexpected behavior. Because the production system involves a cluster of servers, multiple log files must be downloaded and analyzed to find the activity of interest.

Mess #4 - Multi-tier correlation

A user performs an action known to produce an unexpected behavior. The path of execution involves multiple server processes. Tracing the user's execution through the multiple systems is difficult because there is no reliable way to correlate the log statements across systems.

Writer Monad Tutorial

case class SimpleWriter[T](log: List[String], value: T) {
    def map[B](f: T => B): SimpleWriter[B] =
        SimpleWriter(log, f(value))

    def flatMap[B](f: T => SimpleWriter[B]) = {
        val nextWriter = f(value)
        SimpleWriter(log ::: nextWriter.log, nextWriter.value)
    }
}

Writer Monad Usage

def loggedAdder(a: Int, b: Int): SimpleWriter[Int] =
    SimpleWriter(List(s"Added $a to $b"), a + b)

def loggedToString(o: Any): SimpleWriter[String] =
    SimpleWriter(List(s"Converted $o to string"), o.toString)

def main(args: Array[String]) = {
    val resultWithLog = for (
        sum <- loggedAdder(5, 7);
        converted <- loggedToString(sum)
    ) yield s"--> $converted <--"

    resultWithLog.log.foreach(l => println(s"LOG: $l"))
    println(s"Output is ${resultWithLog.value}")
}

LOG: Added 5 to 7
LOG: Converted 12 to string
Output is --> 12 <--

Expanded Logging Monad

object SimpleLogger {
    case class Entry(msg: String, timestamp: Long)
}

case class SimpleLogger[T](log: List[Entry], value: T) {
    def map[B](f: T => B): SimpleLogger[B] =
        SimpleLogger(log, f(value))

    def flatMap[B](f: T => SimpleLogger[B]) = {
        val nextWriter = f(value)
        SimpleLogger(log ::: nextWriter.log, nextWriter.value)
    }
}

Solved - Immediacy implies synchronization

A system has a transient problem. Turning logging on or off no longer affects program execution so the issue can be more easily analyzed.

Solved - Interleaved log entries

A user in a multi-user system performs an action known to produce an unexpected behavior. It is easy to review their log entries because they are organized together along with context information for the operation.

Console Output

INFO [127.0.0.1 - Anonymous] http://localhost:8080/api/board/8de53901-48b6-49b9-8a65-818b4a47d06e
[  8 mSecs] select x2."id", x2."name", x2."terrain_set_id", x2."width", x2."height" from "board" x2 where x2."id" = ? -- Loaded 1 records
[  5 mSecs] select x2."parent_id", x2."row", x2."column", x2."name", x2."capitol" from "board_city" x2 where x2."parent_id" = ? -- Loaded 3 records
[  5 mSecs] select x2."parent_id", x2."row", x2."column", x2."terrain_type_index" from "board_terrain" x2 where x2."parent_id" = ? -- Loaded 24 records

Solved - Clustered Servers

A user performs an action known to produce an unexpected behavior. Because the application can deliver the server-side log entries back to the client, support staff has immediate access to the relevant information.

HTTP Response Headers

HTTP/1.1 200 OK
Date: Sat, 27 Feb 2016 19:54:14 GMT
Content-Type: application/json
Content-Length: 685
Service-Trace: select x2."id", x2."name", x2."terrain_set_id", x2."width", x2."height" from "board" x2 where x2."id" = ?; eventTime=0; duration=8; result=Loaded 1 records}
Service-Trace: select x2."parent_id", x2."row", x2."column", x2."name", x2."capitol" from "board_city" x2 where x2."parent_id" = ?; eventTime=14; duration=5; result=Loaded 3 records}
Service-Trace: select x2."parent_id", x2."row", x2."column", x2."terrain_type_index" from "board_terrain" x2 where x2."parent_id" = ?; eventTime=23; duration=5; result=Loaded 24 records}

Solved - Cross-tier correlation

A user performs an action known to produce an unexpected behavior. If we're really lucky and our whole world works this way, any server involved in the communication can aggregate all of the log entries for all involved servers.

TODOs

This is where you come in!

TODO: Log Less

Target I/O Boundaries like network calls
Target Timing of lengthy operations

TODO: Combine Logging Monad with Result Type

Avoids nested monads and monad transformers
Log interface is union of the writer and the result

TODO: Use caution with deferred string construction

Closures may cause data to escape its intended scope
Motivations are different between imperative logging and functional logging

TODO: Conditional Logging

Consider discarding "log levels"
Pass log settings as parameters to functions

TODO: Ignore deadlock issues

Exposure due to loss of immediacy
Better to use non-logging techniques
Better still to not have problems like this :)

TODO: Never throw exceptions

Narrow scope of exceptions using Try
Pass failures out to preserve associated log entries

Thank You!