10. Logging

In this chapter we discuss how to log statement execution and timing.

Setting Up

Once again we will set up our REPL with a transactor.

import doobie.imports._
import cats._, cats.data._, cats.implicits._
import fs2.interop.cats._

val xa = DriverManagerTransactor[IOLite](
  "org.postgresql.Driver", "jdbc:postgresql:world", "postgres", ""
)

We’re still playing with the country table, shown here for reference.

CREATE TABLE country (
  code       character(3)  NOT NULL,
  name       text          NOT NULL,
  population integer       NOT NULL,
  gnp        numeric(10,2)
  -- more columns, but we won't use them here
)

Basic Statement Logging

When we construct a Query0 or Update0 we can provide an optional LogHandler that will be given a LogEvent on completion and can perform an arbitrary side-effect to report the event as desired.

doobie provides an example LogHandler that writes a summary to a JDK logger, so let’s try that one. Instead of calling .query let’s call .queryWithLogHandler.

def byName(pat: String) = {
  sql"select name, code from country where name like $pat"
    .queryWithLogHandler[(String, String)](LogHandler.jdkLogHandler)
    .list
    .transact(xa)
}

When we run our program we get our result as expected.

scala> byName("U%").unsafePerformIO
res1: List[(String, String)] = List((United Arab Emirates,ARE), (United Kingdom,GBR), (Uganda,UGA), (Ukraine,UKR), (Uruguay,URY), (Uzbekistan,UZB), (United States,USA), (United States Minor Outlying Islands,UMI))

But now on standard out we see:

Jan 07, 2017 7:07:43 AM doobie.util.log$LogHandler$ $anonfun$jdkLogHandler$1
INFO: Successful Statement Execution:

  select name, code from country where name like ?

 arguments = [U%]
   elapsed = 9 ms exec + 6 ms processing (15 ms total)

Let’s break down what we’re seeing:

Implicit Logging

If you wish to turn on logging generally, you can introduce an implicit LogHandler that will get picked up and used by the .query/.update operations.

implicit val han = LogHandler.jdkLogHandler

def byName(pat: String) = {
  sql"select name, code from country where name like $pat"
    .query[(String, String)] // handler will be picked up here
    .list
    .transact(xa)
}

Writing Your LogHandler

If you use the jdkLogHandler you will be warned that it’s just an example, write your own! So let’s do that. LogHandler is a very simple data type:

case class LogHandler(unsafeRun: LogEvent => Unit)

LogEvent has three constructors, all of which provide the SQL string and argument list.

See the Scaladoc for details on this data type.

The simplest possible LogHandler does nothing at all, and this is what you get by default.

val nop = LogHandler(_ => ())

But that’s not interesting. Let’s at least print the event out.

scala> val trivial = LogHandler(e => Console.println("*** " + e))
trivial: doobie.util.log.LogHandler = LogHandler(<function1>)

scala> sql"select 42".queryWithLogHandler[Int](trivial).unique.transact(xa).unsafePerformIO
*** Success(select 42,List(),558192 nanoseconds,189663 nanoseconds)
res3: Int = 42

The jdkLogHandler implementation is straightforward. You might use it as a template to write a logger to suit your particular logging back-end.

import java.util.logging.Logger
import doobie.util.log._

val jdkLogHandler: LogHandler = {
  val jdkLogger = Logger.getLogger(getClass.getName)
  LogHandler {

    case Success(s, a, e1, e2) =>
      jdkLogger.info(s"""Successful Statement Execution:
        |
        |  ${s.lines.dropWhile(_.trim.isEmpty).mkString("\n  ")}
        |
        | arguments = [${a.mkString(", ")}]
        |   elapsed = ${e1.toMillis} ms exec + ${e2.toMillis} ms processing (${(e1 + e2).toMillis} ms total)
      """.stripMargin)

    case ProcessingFailure(s, a, e1, e2, t) =>
      jdkLogger.severe(s"""Failed Resultset Processing:
        |
        |  ${s.lines.dropWhile(_.trim.isEmpty).mkString("\n  ")}
        |
        | arguments = [${a.mkString(", ")}]
        |   elapsed = ${e1.toMillis} ms exec + ${e2.toMillis} ms processing (failed) (${(e1 + e2).toMillis} ms total)
        |   failure = ${t.getMessage}
      """.stripMargin)

    case ExecFailure(s, a, e1, t) =>
      jdkLogger.severe(s"""Failed Statement Execution:
        |
        |  ${s.lines.dropWhile(_.trim.isEmpty).mkString("\n  ")}
        |
        | arguments = [${a.mkString(", ")}]
        |   elapsed = ${e1.toMillis} ms exec (failed)
        |   failure = ${t.getMessage}
      """.stripMargin)

  }
}

Caveats

Logging is not yet supported for streaming (.process or YOLO mode’s .quick).

Note that the LogHandler invocation is part of your ConnectionIO program, and it is called synchronously. Most back-end loggers are asynchronous so this is unlikely to be an issue, but do take care not to spend too much time in your handler.

Further note that the handler is not transactional; anything your logger does stays done, even if the transaction is rolled back. This is only for diagnostics, not for business logic.