feat: emit-time enrichers; thread-safe date formatting

src/klog/core.clj

@@ -27,15 +27,19 @@
 ;; (set! *warn-on-reflection* true)
 
 (def fmt
-  (let [tz (TimeZone/getTimeZone "UTC")
-        df (SimpleDateFormat. "yyyy-MM-dd'T'HH:mm:ss.SSS'Z'")]
-    (.setTimeZone df tz)
-    df))
+  ;; SimpleDateFormat is not thread-safe
+  (ThreadLocal/withInitial
+   (reify java.util.function.Supplier
+     (get [_]
+       (let [tz (TimeZone/getTimeZone "UTC")
+             df (SimpleDateFormat. "yyyy-MM-dd'T'HH:mm:ss.SSS'Z'")]
+         (.setTimeZone df tz)
+         df)))))
 
 
 (defn format-date
   [^Date x]
-  (str (.format ^SimpleDateFormat fmt x)))
+  (str (.format ^SimpleDateFormat (.get ^ThreadLocal fmt) x)))
 
 (defonce ^:dynamic *enable* (if (System/getenv "KLOG_DISABLE") false true))
 (def source-line-enabled? (if (System/getenv "KLOG_SOURCE_LINE_ENABLED") true false))
@@ -394,10 +398,40 @@
 
   )
 
+(defonce enrichers (atom {}))
+(defonce ^:private enrichers-warned (atom #{}))
+
+(defn add-enricher!
+  "Applies f to every log map on the emitting thread, before publish.
+   Replaces a previous f under the same id; throw/non-map return = skipped."
+  [id f]
+  (swap! enrichers-warned disj id)
+  (swap! enrichers assoc id f)
+  nil)
+
+(defn rm-enricher!
+  [id]
+  (swap! enrichers dissoc id)
+  nil)
+
+(defn- enrich
+  [l]
+  (reduce-kv (fn [l id f]
+               ;; println, not log: logging from inside enrich re-enters the chain
+               (let [l' (try (f l)
+                             (catch Exception e
+                               (when-not (@enrichers-warned id)
+                                 (swap! enrichers-warned conj id)
+                                 (println :klog/enricher-failed id (.getMessage e)))
+                               nil))]
+                 (if (map? l') l' l)))
+             l
+             @enrichers))
+
 (defn log
   [ev arg]
   (when *enable*
-    (send-off publisher emit (mk-log ev arg))
+    (send-off publisher emit (enrich (mk-log ev arg)))
     nil))
 
 (defn log-ex [e]

test/klog/core_test.clj

@@ -329,3 +329,49 @@
                     :remoteIp "172.10.192.3"
                     :referer "10.70.1.2"
                     :latency "1.5s"}}]))
+
+(deftest format-date-thread-safety-test
+  ;; distinct dates per thread: the corruption needs calendar fields to
+  ;; diverge; identical dates race invisibly
+  (let [dates (mapv #(java.util.Date. (+ 1600000000000 (* ^long % 987654321))) (range 16))
+        expected (mapv sut/format-date dates)
+        bad (atom 0)
+        futs (mapv (fn [i] (future
+                             (dotimes [_ 500]
+                               (try
+                                 (when-not (= (expected i) (sut/format-date (dates i)))
+                                   (swap! bad inc))
+                                 (catch Throwable _ (swap! bad inc))))))
+                   (range 16))]
+    (run! deref futs)
+    (is (zero? @bad) "shared SimpleDateFormat garbles or throws under concurrent format")))
+
+(def ^ThreadLocal call-site-only (ThreadLocal.))
+
+(deftest enrichers-test
+  ;; a raw ThreadLocal is NOT conveyed by send-off (dynamic bindings are),
+  ;; so it only reaches the log map if enrichment runs on the emitting thread
+  (let [seen (atom [])]
+    (sut/add-appender :cap (fn [l] (swap! seen conj l)))
+    (try
+      (testing "enrichers run on the emitting thread — the point of the hook"
+        (sut/add-enricher! ::ids #(assoc % :dd {:trace_id (.get call-site-only)}))
+        (.set call-site-only "t-1")
+        (sut/log :enricher/hit {:a 1})
+        (sut/flush)
+        (is (= {:trace_id "t-1"} (:dd (last @seen)))
+            "nil here means enrichment moved across the send-off"))
+      (testing "a throwing or non-map-returning enricher is skipped; the log still ships"
+        (sut/add-enricher! ::boom (fn [_] (throw (ex-info "boom" {}))))
+        (sut/add-enricher! ::nilly (constantly nil))
+        (.set call-site-only "t-2")
+        (let [warn (with-out-str (sut/log :enricher/survives {:a 2}))]
+          (sut/flush)
+          (is (= :enricher/survives (:ev (last @seen))))
+          (is (= {:trace_id "t-2"} (:dd (last @seen))) "other enrichers still apply")
+          (is (str/includes? warn "enricher-failed") "the failure is not silent")
+          (is (= "" (with-out-str (sut/log :enricher/again {:a 3}))) "warned once per id")))
+      (finally
+        (.remove call-site-only)
+        (doseq [id [::ids ::boom ::nilly]] (sut/rm-enricher! id))
+        (sut/rm-appender :cap)))))