From bd3d4b670796cc7611b1344e7db29f1f53c16957 Mon Sep 17 00:00:00 2001
From: Mike Sperber <sperber@deinprogramm.de>
Date: Tue, 10 May 2016 10:30:46 +0200
Subject: [PATCH] [#168] Make rotor appender thread-safe (@mikesperber)

---
 .../timbre/appenders/3rd_party/rotor.clj      |  25 +++--
 .../timbre/appenders/3rd_party/rotor_test.clj | 106 +++++++++++++++---
 2 files changed, 103 insertions(+), 28 deletions(-)

diff --git a/src/taoensso/timbre/appenders/3rd_party/rotor.clj b/src/taoensso/timbre/appenders/3rd_party/rotor.clj
index 8497949..d9fd151 100644
--- a/src/taoensso/timbre/appenders/3rd_party/rotor.clj
+++ b/src/taoensso/timbre/appenders/3rd_party/rotor.clj
@@ -55,17 +55,20 @@
    :rate-limit nil
    :output-fn  :inherit
    :fn
-   (fn [data]
-     (let [{:keys [output-fn]} data
-           output-str (output-fn data)]
-       (when-let [log (io/file path)]
-         (try
-           (when-not (.exists log)
-             (io/make-parents log))
-           (when (> (.length log) max-size)
-             (rotate-logs path backlog))
-           (spit path (str (output-fn data) "\n") :append true)
-           (catch java.io.IOException _)))))})
+   (let [lock (Object.)]
+     (fn [data]
+       (let [{:keys [output-fn]} data
+             output-str (output-fn data)]
+           (let [log (io/file path)]
+             (try
+               ;; all the filesystem manipulations are unsafe in the face of concurrency
+               (locking lock
+                 (when-not (.exists log)
+                   (io/make-parents log))
+                 (when (> (.length log) max-size)
+                   (rotate-logs path backlog)))
+               (spit path (str (output-fn data) "\n") :append true)
+               (catch java.io.IOException _))))))})
 
 ;;;; Deprecated
 
diff --git a/test/taoensso/timbre/appenders/3rd_party/rotor_test.clj b/test/taoensso/timbre/appenders/3rd_party/rotor_test.clj
index beb1ab0..19efd35 100644
--- a/test/taoensso/timbre/appenders/3rd_party/rotor_test.clj
+++ b/test/taoensso/timbre/appenders/3rd_party/rotor_test.clj
@@ -2,28 +2,100 @@
   (:require
     [clojure.test :refer :all]
     [clojure.java.io :as io]
+    [clojure.set :as set]
     [taoensso.timbre :as timbre]
-            [taoensso.timbre.appenders.3rd-party.rotor :as rotor]))
+    [taoensso.timbre.appenders.3rd-party.rotor :as rotor]))
+
+(def logfile "rotor-test.log")
+
+(defn logname
+  [i]
+  (format "%s.%03d" logfile i))
+
+(defn setup
+  [n-logs]
+  (timbre/merge-config!
+   {:appenders {:rotor (rotor/rotor-appender
+                        {:path logfile
+                         :max-size 200
+                         :backlog n-logs})}}))
+
+(defn check-logs-present
+  [n-logs]
+  (let [f (io/file logfile)]
+    (is (.exists f)))
+
+  (doseq [i (range 1 (inc n-logs))]
+    (let [f (io/file (logname i))]
+      (is (.exists f)))))
+
+(defn delete
+  [logfile]
+  (let [f (io/file logfile)]
+    (try
+      (.delete f)
+      (catch java.io.FileNotFoundException e nil))))
+
+(defn teardown
+  [n-logs]
+  (delete logfile)
+
+  (doseq [i (range 1 (inc n-logs))]
+    (delete (logname i))))
 
 (deftest rotor-test
-  []
-  (let [logfile "rotor-test.log"
-        n-logs 5]
-    (timbre/merge-config!
-      {:appenders {:rotor (rotor/rotor-appender
-                            {:path logfile
-                             :max-size 200
-                             :backlog n-logs})}})
+  (let [n-logs 5]
+    (setup n-logs)
     (doseq [i (range 100)]
       (timbre/info "testing..."))
+    (check-logs-present n-logs)
+    (teardown n-logs)))
+
+(defn check-complete
+  [n-logs n-lines]
+  (is (= (set (range n-lines))
+         (apply set/union
+                (for [n (cons logfile (map logname (range 1 (inc n-logs))))]
+                  (try
+                    (with-open [rdr (io/reader n)]
+                      (set (map (fn [line]
+                                  (let [[_ x] (re-matches #".*testing: ([0-9]+)$" line)]
+                                    (Integer/parseInt x)))
+                                (line-seq rdr))))
+                    (catch java.io.FileNotFoundException e (set []))))))))
+
+
+(deftest rotor-complete-test
+  (testing "no log entry gets thrown away"
+    (let [n-logs 100
+          n-lines 100]
+
+      (setup n-logs)
+
+      (doseq [i (range n-lines)]
+        (timbre/info "testing:" i))
+
+      (check-complete n-logs n-lines)
+
+      (teardown n-logs))))
+
+(deftest rotor-concurrency-test
+  (testing "no race rotating log files"
+    (let [n-logs 100
+          n-lines 100]
+
+      (setup n-logs)
+
+      (let [futures
+            (for [i (range n-lines)]
+              (future
+                (timbre/info "testing:" i)))]
+        (doseq [f futures]
+          @f))
+
+      (check-complete n-logs n-lines)
+
+      (teardown n-logs))))
 
-    (let [f (io/file logfile)]
-      (is (.exists f))
-      (.delete f))
-
-    (doseq [i (range 1 (inc n-logs))]
-      (let [f (io/file (str logfile ".00" i))]
-        (is (.exists f))
-        (.delete f)))))