Rolling appender is not thread safe

[eerohele]

There's no synchronization around any of the file processing in the taoensso.timbre.appenders.3rd-party.rolling namespace. This can lead to data loss when logging from more than one thread.

In particular, if two threads bypass the .exists check in shift-log-period, they will both arrive at rename-old-create-new-log. As a result, this sequence of events in rename-old-create-new-log becomes possible:

1. Thread 1 renames log to old-log.
2. Thread 1 creates a new, empty log.
3. Thread 2, having bypassed the .exists check, renames the newly created, empty log to old-log, overwriting all data in old-log.

Here's a (probably a somewhat too complicated) REPL session to test the appender:

(import '(java.util.concurrent CountDownLatch))
(import '(java.io File))
(import '(java.nio.file Files))
(import '(java.nio.file.attribute FileTime))
(import '(java.time Instant))
(import '(java.util Date TimeZone))

;; Set default time zone to Europe/London so that we always operate within the same TZ
(TimeZone/setDefault (TimeZone/getTimeZone "Europe/London"))

;; Make log file
(def log-file (File/createTempFile "timbre." ".log"))

;; Get list of log files in log file directory
(defn log-files
  []
  (filter #(.startsWith (.getName %) (.getName log-file))
    (-> (.getParent log-file) io/file .listFiles)))

;; Delete any possible existing log files
(run! #(.delete %) (log-files))

;; Imagine this is the current date
(def current-instant (Instant/parse "2021-11-04T00:00:00.00Z"))

;; Timbre uses java.util.Date instances, so convert Instant to that
(def current-date (Date/from current-instant))

;; Make rolling appender that logs to log-file
(def appender (rolling-appender {:path (.getPath log-file) :pattern :daily}))

;; Grab appender :fn
(def logfn (:fn appender))

; ;; Add previous day's entries into the log file
(spit log-file "AAA\n" :append true)
(spit log-file "BBB\n" :append true)
(spit log-file "CCC\n" :append true)
(slurp log-file)

;; Set the last modified time of the log file to a minute ago
(Files/setLastModifiedTime (.toPath log-file)
  (FileTime/from (.minusSeconds current-instant 60)))

;; Double-check that the last modified time of the log file precedes the cutoff point
(Instant/ofEpochMilli (.lastModified log-file))
(prev-period-end-cal current-date :daily)

;; When this latch opens, log a bunch of stuff using the appender :fn
(def latch (CountDownLatch. 1))

(def futures
  (mapv
    #(future
      (.await latch)
      (logfn {:instant current-date :output_ (str %)}))
    (range 100)))

;; Let slip
(.countDown latch)

;; Wait for futures to finish
(run! deref futures)

;; A silly, convoluted way of formatting the previous day as yyyyMMdd
(def previous-day
  (->
    (.getTime current-date)
    (java.sql.Date.)
    (.toLocalDate)
    (.minusDays 1)
    (.format (java.time.format.DateTimeFormatter/ofPattern "yyyyMMdd"))))

[
 ;; Check the content of the previous day's log file
 (slurp (str log-file "." previous-day))
 ;; Check how many log files there are
 (count (log-files))]

Evaluating the last expression should yield ["AAA\nBBB\nCCC\n" 2], but might not.

The simplest fix might be to lock the body of the try in rolling-appender. Might result in too much lock contention, though?

[eerohele]

The simplest fix might be to lock the body of the try in rolling-appender. Might result in too much lock contention, though?

Looks like that's precisely what the rotor appender does, so maybe we could do the same thing here.

[ptaoussanis]

Your fix will be addressed in forthcoming release, thanks Eero!