Basic logging in Clojure web service not appearing on console

Question

I am following this tutorial to set up application logging in my Clojure web app, which I am going to be using for some Datomic experimentation. The tutorial suggests that all I have to do is add Clojure's clojure.tools.logging library to my project's dependencies in Leiningen, and output should just show up on my console. However, I am not seeing any logging output, on the console or elsewhere, when starting the app. What am I doing wrong?

Here's how I'm set up. My web stack is Ring/Compojure, running as an embedded Jetty standalone JAR (using ring.adapter.jetty), with a dummy API route that isn't using the database yet.

My project.clj (note: I'm evaluating Datomic's pro version, so there's GPG setup I've done outside of the project to get this protected JAR to be downloaded properly):

(defproject helloworld "0.1.0-SNAPSHOT"
  :description "FIXME: write description"
  :url "http://example.com/FIXME"
  :min-lein-version "2.0.0"
  :repositories {
    "my.datomic.com" {:url "https://my.datomic.com/repo" :creds :gpg}}
  :dependencies [[org.clojure/clojure "1.6.0"]
                 [compojure "1.3.1"]
                 [ring/ring-defaults "0.1.2"]
                 [ring/ring-json "0.3.1"]
                 [ring/ring-defaults "0.1.2"]
                 [ring/ring-jetty-adapter "1.4.0"]
                 [org.clojure/tools.logging "0.3.1"]
                 [com.datomic/datomic-pro "0.9.5198" :exclusions [joda-time]]
                 [joda-time "2.8.1"]]
  :plugins [[lein-ring "0.8.13"]]
  :ring {:handler helloworld.handler/app}
  :main helloworld.core
  :aot [helloworld.core]
  :profiles
  {:dev {:dependencies [[javax.servlet/servlet-api "2.5"]
                        [ring-mock "0.1.5"]]}})

The file src/helloworld/core.clj:

(ns helloworld.core
  (:require [clojure.tools.logging :as log]
            [ring.adapter.jetty :as jetty]
            [helloworld.handler :refer [app]])
  (:gen-class))

(defn -main [& args]
  (println "Hello, world!")
  (log/info "Service is running!")
  (jetty/run-jetty app {:port 8080}))

The Compojure app and API handler, src/helloworld/handler.clj:

(ns helloworld.handler
  (:require [clojure.tools.logging :as log]
            [compojure.core :refer :all]
            [compojure.route :as route]
            [ring.middleware.defaults :refer [wrap-defaults api-defaults]]
            [ring.middleware.json :as json-middleware]
            [ring.util.response :refer [response]]))

(def dummy-entity {:id 1 :name "Hello, world!"})

(defroutes app-routes
  (GET "/" []
    (log/info "Getting all the things!")
    (response [dummy-entity]))
  (route/not-found "Not Found"))

(def app
  (->
    (wrap-defaults app-routes api-defaults)
    (json-middleware/wrap-json-body)
    (json-middleware/wrap-json-response)))

And here's what I see when I try to run it (this is also after hitting the default endpoint a few times):

$ lein run
Hello, world!

So println is definitely working, but logging doesn't seem to be.

Answer 1

It turns out the problem here was including the Datomic library, even if I'm not using it! Here's what happens if I remove datomic-pro and joda-time dependencies and re-run:

$ lein run
2015-07-12 12:50:36.305:INFO::main: Logging initialized @1599ms
Hello, world!
Jul 12, 2015 12:50:38 PM clojure.tools.logging$eval18$fn__22 invoke
INFO: Service is running!
2015-07-12 12:50:38.167:INFO:oejs.Server:main: jetty-9.2.10.v20150310
2015-07-12 12:50:38.225:INFO:oejs.ServerConnector:main: Started ServerConnector@510a6f62{HTTP/1.1}{0.0.0.0:8080}
2015-07-12 12:50:38.226:INFO:oejs.Server:main: Started @3520ms
Jul 12, 2015 12:50:42 PM clojure.tools.logging$eval18$fn__22 invoke
INFO: Getting all the things!

So now I'm getting a bunch of Jetty logging too, as well as my app logs.

I think the issue is this:

• Clojure's logging library picks the logging backend it likes best of the ones that are available.
• The tutorial I was looking at assumed that no logging libraries were included in your project's dependencies (or any of their transitive dependencies!), so the last default (java.util.logging) would be selected. That will log to the console by default.
• However, Datomic pulls in SLF4J, which the Clojure logging library happily prefers.
• SLF4J, in turn, didn't have any logging adapter to use, since I hadn't specified any in my project's dependencies. So it picked a no-op logger. (Thanks, SLF4J.)

I verified this by doing some debugging on the logger that was actually being used. I added this to -main:

(ns ...
  (require ...
           [clojure.tools.logging.impl :as log-impl]
           ...))
...
(let [logger (log-impl/get-logger log/*logger-factory* *ns*)]
    (println logger))

And that showed me some object belonging to SLF4J's NOOP logger class.

I fixed by adding an appropriate SLF4J adapter to my project dependencies. I chose to go with Logback:

[com.datomic/datomic-pro "0.9.5198"
 :exclusions [joda-time org.slf4j/slf4j-nop org.slf4j/slf4j-log4j12]]
[ch.qos.logback/logback-classic "1.1.3"]

To configure, I added the following in resources/logback.xml:

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
  <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
    </encoder>
  </appender>

  <root level="debug">
    <appender-ref ref="CONSOLE" />
  </root>
</configuration>

And that fixed it!