External Database, Phase 2

Let’s get the rest of the functions in the clojure-game-geek.db namespace working again and add tests for them. We’ll do a little refactoring as well, to make both the production code and the tests clearer and simpler.

Logging

It’s always a good idea to know exactly what SQL queries are executing in your application; you’ll never figure out what’s slowing down your application if you don’t know what queries are even executing.

src/clojure_game_geek/db.clj
(ns clojure-game-geek.db
  (:require
    [com.stuartsierra.component :as component]
    [io.pedestal.log :as log]
    [clojure.java.jdbc :as jdbc]
    [clojure.string :as str])
  (:import (com.mchange.v2.c3p0 ComboPooledDataSource)))

(defn ^:private pooled-data-source
  [host dbname user password port]
  {:datasource
   (doto (ComboPooledDataSource.)
     (.setDriverClass "org.postgresql.Driver")
     (.setJdbcUrl (str "jdbc:postgresql://" host ":" port "/" dbname))
     (.setUser user)
     (.setPassword password))})

(defrecord ClojureGameGeekDb [ds]

  component/Lifecycle

  (start [this]
    (assoc this
           :ds (pooled-data-source "localhost" "cggdb" "cgg_role" "lacinia" 25432)))

  (stop [this]
    (-> ds :datasource .close)
    (assoc this :ds nil)))

(defn new-db
  []
  {:db (map->ClojureGameGeekDb {})})


(defn ^:private query
  [component statement]
  (let [[sql & params] statement]
    (log/debug :sql (str/replace sql #"\s+" " ")
               :params params))
  (jdbc/query (:ds component) statement))

We’ve introduced our own version of clojure.java.jdbc/query with two differences:

  • It logs the SQL and parameters it will execute
  • It accepts a component, and extracts the database specification from the component

Because of how we format the SQL in our code, it is useful to convert the embedded newlines and indentation into single spaces.

A bit about logging: In a typical Java, or even Clojure, application the focus on logging is on a textural message for the user to read. Different developers approach this in different ways … everything from the inscrutably cryptic to the overly verbose. Yes, across that spectrum, there always an assumption that some user is reading the log.

The io.pedestal/pedestal.log library introduces a different idea: logs as a stream of data … a sequence of maps. That’s what we see in the call to log/debug: just keys and values that are interesting.

When logged, it may look like:

DEBUG clojure-game-geek.db - {:sql "select game_id, name, summary, min_players, max_players, created_at, updated_at from board_game where game_id = $1",
  :params (1234), :line 38}

That’s the debug level and namespace, and the map of keys and values (io.pedestal.log adds the :line key).

The useful and interesting details are present and unambiguously formatted, since it is not formatted specifically for a user to read.

This can be a very powerful concept; these logs can even be read back into memory, converted back into data, and operated on with all the map, reduce, and filter power that Clojure provides. [1]

After years of sweating the details on formatting (and capitalizing, and quoting, and punctuating) human-readible error messages, it is a joy to just throw whatever data is useful into the log, and not care about all those human oriented formatting details.

This is, of course, all possible because all data in Clojure can be printed out nicely and even read back in again. By comparison, data values or other objects in Java only have useful debugging output if their class provides an override of the toString() method.

When it comes time to execute a query, not much has changed except that it isn’t necessary to extract the databased spec from the component:

src/clojure_game_geek/db.clj
(defn find-game-by-id
  [component game-id]
  (first
    (query component
           ["select game_id, name, summary, min_players, max_players, created_at, updated_at
             from board_game where game_id = ?" game-id])))

logback-test.xml

We can enable logging, just for testing purposes, in our logback-test.xml:

dev-resources/logback-test.xml
<configuration scan="true" scanPeriod="1 seconds">

  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>%-5level %logger - %msg%n</pattern>
    </encoder>
  </appender>

  <root level="warn">
    <appender-ref ref="STDOUT"/>
  </root>

  <logger name="clojure-game-geek.db" level="DEBUG"/>

</configuration>

Nicely, Logback will pick up this change to the configuration file without a restart.

Re-running tests

If we switch back to the clojure-game-geek.system-tests namespace and re-run the tests, the debug output will be mixed into the test tool output:

Loading src/clojure_game_geek/db.clj... done
Loading test/clojure_game_geek/system_tests.clj... done
Running tests in clojure-game-geek.system-tests
DEBUG clojure-game-geek.db - {:sql "select game_id, name, summary, min_players, max_players, created_at, updated_at from board_game where game_id = $1", :params (1234), :line 42}
Ran 1 test containing 1 assertion.
No failures.

More code updates

The remaining functions in clojure-game-geek.db can be rewritten to make use of query and operate on the real database:

src/clojure_game_geek/db.clj
(defn find-member-by-id
  [component member-id]
  (first
    (query component
           ["select member_id, name, created_at, updated_at
             from member
             where member_id = $1" member-id])))

(defn list-designers-for-game
  [component game-id]
  (query component
         ["select d.designer_id, d.name, d.uri, d.created_at, d.updated_at
           from designer d
           inner join designer_to_game j on (d.designer_id = j.designer_id)
           where j.game_id = $1
           order by d.name" game-id]))

(defn list-games-for-designer
  [component designer-id]
  (query component
         ["select g.game_id, g.name, g.summary, g.min_players, g.max_players, g.created_at, g.updated_at
           from board_game g
           inner join designer_to_game j on (g.game_id = j.game_id)
           where j.designer_id = $1
           order by g.name" designer-id]))

(defn list-ratings-for-game
  [component game-id]
  (query component
         ["select game_id, member_id, rating, created_at, updated_at
           from game_rating
           where game_id = $1" game-id]))

(defn list-ratings-for-member
  [component member-id]
  (query component
         ["select game_id, member_id, rating, created_at, updated_at
           from game_rating
           where member_id = $1" member-id]))

(defn upsert-game-rating
  "Adds a new game rating, or changes the value of an existing game rating.

  Returns nil"
  [component game-id member-id rating]
  (query component
         ["insert into game_rating (game_id, member_id, rating)
           values ($1, $2, $3)
           on conflict (game_id, member_id) do update set rating = $3"
          game-id member-id rating])

  nil)

The majority of this is quite straight-forward, except for upsert-game-rating, which makes use of PostgreSQL language extensions to handle a conflict (where a rating already exists for a particular game and member) - the insert is converted to an update.

In the next chapter, we’ll focus on testing the code we’ve just added.

[1]I’ve used this on another project where a bug manifested only at a large scale of operations; by hooking into Logback and capturing the logged maps, it was possible to quickly filter through megabytes of output to the find the clues that revealed how the bug occured.