Thread safety on println-appender

[sjlnk]

It seems that there are no guarantees that println commands are thread safe (no interleaved lines) on println-appender. Is there some configuration switch that will assure thread safety or do I need to write a custom appender?

[sjlnk]

I created a quick and dirty fix using locking. New appender:

(defn println-appender
  "Returns a simple `println` appender for Clojure/Script.
  Use with ClojureScript requires that `cljs.core/*print-fn*` be set.

  :stream (clj only) - e/o #{:auto :*out* :*err* :std-err :std-out <io-stream>}."

  ;; Unfortunately no easy way to check if *print-fn* is set. Metadata on the
  ;; default throwing fn would be nice...

  [& [{:keys [stream] :or {stream :auto}}]]
  (let [stream (case stream
                 :std-err timbre/default-err
                 :std-out timbre/default-out
                 stream)
        locker (Object.)]
    {:enabled?   true
     :async?     false
     :min-level  nil
     :rate-limit nil
     :output-fn  :inherit
     :fn
     (fn [data]
       (let [{:keys [output_]} data]
         (let [stream (case stream
                        :auto  (if (:error? data) *err* *out*)
                        :*out* *out*
                        :*err* *err*
                        stream)]
           (locking locker (binding [*out* stream] (println (force output_)))))))}))

[ptaoussanis]

Hi there,

Could you be a little more precise about what you mean here by "thread safe"? What kind of interleaving are you seeing? Under what circumstances? Can you provide an example?

Thanks!

[sjlnk]

Writing to stdout from multiple threads is not thread-safe as output often gets interleaved randomly. It's probably not dangerous but it makes the output a mess.

Consider these examples. You might have to run the code a few times or try higher NUM_ITERS or NUM_THREADS to see the effect.

(ns test.core
  (:require
   [taoensso.timbre :as timbre]))

(def NUM-ITERS 5)
(def NUM-THREADS 4)

(defn worker
  []
  (doseq [i (range NUM-ITERS)]
    (timbre/info (.getName (Thread/currentThread)) " " i)))

(defn print-stuff
  [num-threads]
  (doseq [i (range num-threads)]
    (.start (Thread. worker (str "thread-" i)))))

(defn thread-safe-println-appender
  [& [{:keys [stream] :or {stream :auto}}]]
  (let [stream (case stream
                 :std-err timbre/default-err
                 :std-out timbre/default-out
                 stream)
        locker (Object.)]
    {:enabled?   true
     :async?     false
     :min-level  nil
     :rate-limit nil
     :output-fn  :inherit
     :fn
     (fn [data]
       (let [{:keys [output_]} data]
         (let [stream (case stream
                        :auto  (if (:error? data) *err* *out*)
                        :*out* *out*
                        :*err* *err*
                        stream)]
           (locking locker (binding [*out* stream]
                             (println (force output_)))))))}))

(defn set-println-appender [appender]
  (let [config timbre/example-config]
    (timbre/set-config! (assoc config :appenders
                               {:println (appender {:stream :auto})}))))


(defn test-appender
  [appender]
  (set-println-appender appender)
  (println "testing " appender)
  (print-stuff NUM-THREADS)
  (Thread/sleep 1000))

(defn -main
  []
  (test-appender taoensso.timbre.appenders.core/println-appender)
  (test-appender thread-safe-println-appender))

output:

testing  #object[taoensso.timbre.appenders.core$println_appender 0xaf08a49 taoensso.timbre.appenders.core$println_appender@af08a49]
16-08-18 20:00:29 x230 INFO [test.core:11] - thread-0   0
16-08-18 20:00:29 x230 INFO [test.core:11] - thread-2   0
16-08-18 20:00:29 x230 INFO [test.core:11] - thread-0   1
16-08-18 20:00:29 x230 INFO [test.core:11] - thread-0   2
16-08-18 20:00:29 x230 INFO [test.core:11] - thread-0   3
16-08-18 20:00:29 x230 INFO [test.core:11] - thread-0   4
16-08-18 20:00:29 x230 INFO [test.core:11] - thread-1   0
16-08-18 20:00:29 x230 INFO [test.core:11] - thread-2   116-08-18 20:00:29 x230 INFO [test.core:11] - thread-1   1

16-08-18 20:00:29 x230 INFO [test.core:11] - thread-3   0
16-08-18 20:00:29 x230 INFO [test.core:11] - thread-2   2
16-08-18 20:00:29 x230 INFO [test.core:11] - thread-1   216-08-18 20:00:29 x230 INFO [test.core:11] - thread-2   3

16-08-18 20:00:29 x230 INFO [test.core:11] - thread-1   3
16-08-18 20:00:29 x230 INFO [test.core:11] - thread-1   4
16-08-18 20:00:29 x230 INFO [test.core:11] - thread-3   1
16-08-18 20:00:29 x230 INFO [test.core:11] - thread-3   216-08-18 20:00:29 x230 INFO [test.core:11] - thread-2   4

16-08-18 20:00:29 x230 INFO [test.core:11] - thread-3   3
16-08-18 20:00:29 x230 INFO [test.core:11] - thread-3   4
testing  #object[test.core$thread_safe_println_appender 0x3c66082a test.core$thread_safe_println_appender@3c66082a]
16-08-18 20:00:30 x230 INFO [test.core:11] - thread-0   0
16-08-18 20:00:30 x230 INFO [test.core:11] - thread-3   0
16-08-18 20:00:30 x230 INFO [test.core:11] - thread-0   1
16-08-18 20:00:30 x230 INFO [test.core:11] - thread-2   0
16-08-18 20:00:30 x230 INFO [test.core:11] - thread-1   0
16-08-18 20:00:30 x230 INFO [test.core:11] - thread-0   2
16-08-18 20:00:30 x230 INFO [test.core:11] - thread-0   3
16-08-18 20:00:30 x230 INFO [test.core:11] - thread-0   4
16-08-18 20:00:30 x230 INFO [test.core:11] - thread-3   1
16-08-18 20:00:30 x230 INFO [test.core:11] - thread-1   1
16-08-18 20:00:30 x230 INFO [test.core:11] - thread-2   1
16-08-18 20:00:30 x230 INFO [test.core:11] - thread-1   2
16-08-18 20:00:30 x230 INFO [test.core:11] - thread-3   2
16-08-18 20:00:30 x230 INFO [test.core:11] - thread-3   3
16-08-18 20:00:30 x230 INFO [test.core:11] - thread-1   3
16-08-18 20:00:30 x230 INFO [test.core:11] - thread-1   4
16-08-18 20:00:30 x230 INFO [test.core:11] - thread-2   2
16-08-18 20:00:30 x230 INFO [test.core:11] - thread-2   3
16-08-18 20:00:30 x230 INFO [test.core:11] - thread-2   4
16-08-18 20:00:30 x230 INFO [test.core:11] - thread-3   4

[ptaoussanis]

Thanks for the example, this was an unintended regression- fixed!

[jaju]

Thanks! I had been observing the same. Is 4.7.4 coming out soon?

[ptaoussanis]

Just cut a release.

[jaju]

Thank you! :)

[chadharrington]

This interleaving occurs on cljs, also. However, the 4.7.4 release only fixes it for clj. Any chance of a fix for cljs? I am seeing interleaving with 4.7.4 running on node.

Thank you for your great work.

[ptaoussanis]

Hi Chad,

It's not immediately obvious to me how interleaving would be happening in a single-threaded Cljs environment - any chance you could provide an example or any more details?

Thanks!

Thank you for your great work.

You're very welcome, cheers! :-)

[chadharrington]

We are using many go blocks. The interleaving happens when we log large messages (stacktraces, mostly). We are seeing this in a large system, so it will take some time to create a minimal test case. I hope to do that this weekend.

[ptaoussanis]

Hi there,

Go blocks don't involve threading though, so the behaviour still surprises me. No need for a minimal test case - but could you possibly provide an example of your faulty (interleaved) output?

Would like to understand better what's actually happening before choosing a solution.

Thanks! Cheers :-)

[ptaoussanis]

Oh, PS- you're welcome to send the example to my email address if you don't want to have to bother sanitising it for GitHub. My address is at www.taoensso.com.