Spit appender is not thread-safe?

[schmee]

During development I noticed a case where the logging was not working correctly when using the spit appender and multiple threads. I've tried to find a minimal repro for the issue:

(ns repro
  (:require [taoensso.timbre :as timbre]
            [taoensso.timbre.appenders.core :as appenders])
  (:import [java.util.concurrent Executors]))

(timbre/set-config!
  (merge
    timbre/example-config
    {:appenders {:spit (appenders/spit-appender {:fname "log/repro.log"})}}))

(defn logger [n running lock]
  (loop []
    (if @running
      (do
        (Thread/sleep 100)
        (recur))
      ;; This drops output
      (timbre/info (str "Hello from thread " n)))))
      ;; This doesn't
      ; (locking lock
      ;   (timbre/info (str "Hello from thread " n))))))

(defn repro []
  (let [n-threads 8
        running (atom true)
        lock (Object.)
        pool (Executors/newFixedThreadPool n-threads)]
    (dotimes [n n-threads]
      (.submit pool ^Runnable #(logger n running lock)))
    (Thread/sleep 1000)
    (reset! running false)
    (.shutdown pool)))

When you run repro in a REPL it should print 8 lines of output to the file, but often it drops lines somewhere and prints less then this. When locking all the 8 lines are always printed. Is this a bug or intended behavior of spit appender?

[ptaoussanis]

Hi John,

Thanks for the clear issue+repro. This isn't intended behaviour, exactly- though a function of just using Clojure's spit underneath.

Switching the appender's default :async? to true might be the cheapest solution? Otherwise open to see a PR that looks at other options (flushing, locking, etc.) if those offer better performance.

Thanks!

[ptaoussanis]

Fixing shortly, thanks again for the report + repro!