Testing Timbre log outputs with Midje

Question

I am using Timbre as a logging library but I am having issues testing it with Midje. I've got the following method and all I'm trying to do is asserting that Will be printed is printed.

(defn init [level]
    (timbre/merge-config! {:output-fn my-output-fn})
    (timbre/set-level! level)
    (timbre/info "Will be printed")
    (timbre/debug "Won't be printed"))

By wrapping (timbre/default-output-fn) around a function of my own my-output-fn, I am able to assert that only 1 out of 2 logs are printed, which is true:

(fact "print info but not debug"
    (core/init :info) => nil
    (provided
        (core/my-output-fn anything) => irrelevant :times 1))

However I would like to make sure that the message being printed is Will be printed. I can't find any way of doing this, what would you do?

I am doing experiments in the following project https://github.com/stephanebruckert/timbre-midje

While I am not familiar with midge, have you looked at this question: http://stackoverflow.com/questions/32310619/clojure-configure-timbre-logging/32340732#32340732 — Alan Thompson, Oct 14 '16 at 06:09
Yes, and we can see that the answer got around the problem by using a comment: `(trace "Hello, Timbre! trace") ; will not be logged, below current log-level`. That's what I want to automate — Stéphane Bruckert, Oct 14 '16 at 10:49

user2609980 · Answer 1 · 2016-10-14T18:16:45.110

It is possible to validate the input of a function using Midje's as-checker prerequisite.

When you print the data that come into timbre/default-output-fn (I discovered this via your output-fn) you see it has the following structure:

{:hash_ #delay[{:status :pending, :val nil} 0x5ed805b1], :instant #inst "2016-10-14T17:07:16.779-00:00", :config {:level :info, ....

So the log-level is available in data. With as-checker the log level can be validated as follows:

(fact "print info but not debug"
      (core/init :info) => nil
      (provided
       (timbre/default-output-fn anything ; opts is first argument
                                 (as-checker (fn [data]
                                               (= (-> data :config :level) ; get log level
                                                  :info))))     ; validate that it is info
       => anything :times 1)
      (provided
       (timbre/default-output-fn anything
                                 (as-checker (fn [data]
                                               (= (-> data :config :level)
                                                  :debug))))
       => anything :times 0))

Now, you wanted to check the content of the message. Not only the log level.

The actual message is not available in the opts or data passed toward default-output-fn. Looking around in the the Timbre code I saw it is available in a private function vargs->margs that takes an ?err, a msg-type and vargs. The vargs contain the message (in your case what comes in is for example :auto :p ["The message"]).

Via the as-checker approach the messages can be validated follows:

(fact "print Will be printed, not Won't be printed"
      (core/init :info) => nil
      (provided
       (#'timbre/vargs->margs anything anything ["Will be printed"]) => {} :times 1)
      (provided
       (#'timbre/vargs->margs anything anything ["Won't be printed"]) => {} :times 0) )

Note that vargs->margs has to return a map, otherwise Timbre throws an exception in a later function.

This way it is validated that "Will be printed" is printed once, and "Won't be printed" is never printed.

Thanks! There might be a simpler way though. Code is here: https://github.com/erooijak/timbre-midje. — user2609980, Oct 14 '16 at 18:26
I see. Note that the log level checking did not work at first, but does after the edit. Thanks for the problem. — user2609980, Oct 14 '16 at 18:34

Stéphane Bruckert · Accepted Answer · 2016-10-18T20:43:59.853

@ErwinRooijakkers' idea worked but @ptaoussanis on Github has a good reason not to do it.

Please note that timbre/vargs->margs is private, and an implementation detail. Its behaviour can change at any time without notice, would strongly recommend not depending on it in any way.

It'd be possible to use a custom appender that sends output somewhere that are handy for your tests to analyse. You could setup these appenders as part of your test setup, and/or use something like timbre/with-config for the appropriate test calls.

So we can add an appender that passes the parameters to check (level message) to a stub.

core.clj

(defn init
  ([level]
    (init level {}))
  ([level config]
    (timbre/merge-config! config)
    (timbre/set-level! level)
    (timbre/info "will be printed")
    (timbre/debug "won't be printed")))

core_test.clj

(:require [timbre-midje.core :as core]
          [midje.sweet :refer :all]))

(defn log-stub [level message])

(def log-stub-appender
  {:appenders
    {:test-appender
      {:enabled? true
       :fn (fn [data] (log-stub (:level data) (:vargs data)))}}})

(fact "print info but not debug"
  (core/init :info log-stub-appender) => nil
  (provided
    (log-stub :info ["will be printed"]) => irrelevant :times 1
    (log-stub :debug ["won't be printed"]) => irrelevant :times 0))

Testing Timbre log outputs with Midje

2 Answers2