[#207] Fix: middleware couldn't influence automatic msg_ generation

As of this commit:
The values of :msg_ and :output_ will depend on the actual value of
:vargs *at the time of first evaluation*.

src/taoensso/timbre.cljx

@@ -293,52 +293,41 @@
 
   [context & body] `(binding [*context* ~context] ~@body))
 
-(defn-   next-vargs [v] (if (> (count v) 1) (subvec v 1) []))
+(defn- vrest [v] (if (> (count v) 1) (subvec v 1) []))
-(defn- vargs->margs
+(defn- parse-vargs
-  "Transforms raw vargs -> {:?err _ :?meta _ ...}, extracting:
+  "vargs -> [?err ?meta ?msg-fmt api-vargs]"
-  * Special error or ^:meta {} (experimental, undocumented) v0
-  * Message format string
-  * Message string delay"
   [?err msg-type vargs]
   (let [auto-error? (enc/kw-identical? ?err :auto)
-        msg-fmt?    (enc/kw-identical? msg-type :f)
+        fmt-msg?    (enc/kw-identical? msg-type :f)
         [v0] vargs]
 
     (if (and auto-error? (enc/error? v0))
-      (let [vargs    (next-vargs vargs)
+      (let [?err     v0
-            ?msg-fmt (if msg-fmt? (let [[v0] vargs] v0) nil)
+            ?meta    nil
-            vargs    (if msg-fmt? (next-vargs vargs) vargs)
+            vargs    (vrest vargs)
-            msg_     (delay
+            ?msg-fmt (if fmt-msg? (let [[v0] vargs] v0) nil)
-                      (case msg-type
+            vargs    (if fmt-msg? (vrest vargs) vargs)]
-                        nil ""
-                        :p  (str-join                            vargs)
-                        :f  (enc/format* (have string? ?msg-fmt) vargs)))]
 
-        {:?err v0 :?meta nil :?msg-fmt ?msg-fmt :msg_ msg_ :vargs vargs})
+        [?err ?meta ?msg-fmt vargs])
 
       (let [?meta    (if (and (map? v0) (:meta (meta v0))) v0 nil)
             ?err     (or (:err ?meta) (if auto-error? nil ?err))
             ?meta    (dissoc ?meta :err)
-            vargs    (if ?meta (next-vargs vargs) vargs)
+            vargs    (if ?meta (vrest vargs) vargs)
-            ?msg-fmt (if msg-fmt? (let [[v0] vargs] v0) nil)
+            ?msg-fmt (if fmt-msg? (let [[v0] vargs] v0) nil)
-            vargs    (if msg-fmt? (next-vargs vargs) vargs)
+            vargs    (if fmt-msg? (vrest vargs) vargs)]
-            msg_     (delay
-                      (case msg-type
-                        nil ""
-                        :p  (str-join                            vargs)
-                        :f  (enc/format* (have string? ?msg-fmt) vargs)))]
 
-        {:?err ?err :?meta ?meta :?msg-fmt ?msg-fmt :msg_ msg_ :vargs vargs}))))
+        [?err ?meta ?msg-fmt vargs]))))
 
 (comment
   (let [ex (Exception. "ex")]
     (qb 10000
-      (vargs->margs :auto :f ["fmt" :a :b :c])
+      (parse-vargs :auto :f ["fmt" :a :b :c])
-      (vargs->margs :auto :p [ex    :a :b :c])
+      (parse-vargs :auto :p [ex    :a :b :c])
-      (vargs->margs :auto :p [^:meta {:foo :bar} :a :b :c])
+      (parse-vargs :auto :p [^:meta {:foo :bar} :a :b :c])
-      (vargs->margs :auto :p [       {:foo :bar} :a :b :c])
+      (parse-vargs :auto :p [       {:foo :bar} :a :b :c])
-      (vargs->margs :auto :p [ex])
+      (parse-vargs :auto :p [ex])
-      (vargs->margs :auto :p [^:meta {:err ex}   :a :b :c])))
+      (parse-vargs :auto :p [^:meta {:err ex}   :a :b :c])))
   ;; [2.79 2.51 6.13 1.65 1.94 6.2]
   (infof                                 "Hi %s" "steve")
   (infof ^:meta {:hash :bar}             "Hi %s" "steve")
@@ -359,14 +348,33 @@
   (when (may-log? level ?ns-str config)
     (let [instant (enc/now-dt)
           context *context*
-          vargs   @vargs_
+          vargs1  @vargs_
 
-          ;; {:keys [?err ?meta ?msg-fmt msg_ vargs]}:
+          [?err ?meta ?msg-fmt vargs1] (parse-vargs ?err msg-type vargs1)
-          margs (vargs->margs ?err msg-type vargs)
+
-          data
+          final-vargs_ (atom vargs1) ; Allow middleware to influece msg_
-          (merge
+          msg_
-           ?base-data
+          (case msg-type
-           margs
+            nil ""
+            :p  (delay (str-join @final-vargs_))
+            :f  (do
+                  (have? string? ?msg-fmt)
+                  (delay (enc/format* @final-vargs_))))
+
+          ;; Uniquely identifies a particular logging call for purposes of
+          ;; rate limiting, etc.
+          hash_
+          (delay
+            (hash
+              ;; Nb excl. instant
+              [callsite-id ; Only useful for direct macro calls
+               ?msg-fmt
+               (get ?meta :hash ; Explicit hash provided
+                 @final-vargs_)]))
+
+          data ; Pre-middleware
+          (conj
+            (or ?base-data {})
             {:instant instant
              :level   level
              :context context
@@ -377,28 +385,19 @@
              #+clj :hostname_ #+clj (delay (get-hostname))
              :error-level? (#{:error :fatal} level)
 
-            ;; Uniquely identifies a particular logging call for purposes of
+             :?err_    (delay ?err)          ; Deprecated
-            ;; rate limiting, etc.
+             :vargs_   (delay @final-vargs_) ; ''
-            :hash_ ; TODO Undocumented (experimental)
-            (delay
-             (hash
-              ;; Nb excl. instant
-              [callsite-id ; Only useful for direct macro calls
-               (:?msg-fmt margs)
-               (get-in margs [:?meta :hash] ; Explicit hash provided
-                 (:vargs margs))]))
 
-            ;; :?err     <from-margs>
+             :?err     ?err
-            ;; :?meta    <from-margs> ; TODO Undocumented (experimental)
+             :?meta    ?meta    ; TODO Undocumented (experimental)
-            ;; :?msg-fmt <from-margs> ; TODO Undocumented (experimental)
+             :?msg-fmt ?msg-fmt ; ''
-            ;; :msg_     <from-margs>
+             :hash_    hash_    ; ''
-            ;; :vargs    <from-margs>
+             :vargs    vargs1
+             :msg_     msg_})
 
-            ;;; Deprecated
+          ?middleware (:middleware config)
-            :?err_  (delay (:?err  margs))
-            :vargs_ (delay (:vargs margs))})
 
-          ?data
+          ?data ; Post middleware
           (reduce ; Apply middleware: data->?data
             (fn [acc mf]
               (let [result (mf acc)]
@@ -406,9 +405,10 @@
                   (reduced nil)
                   result)))
             data
-            (:middleware config))]
+            ?middleware)]
 
       (when-let [data ?data] ; Not filtered by middleware
+        (reset! final-vargs_ (:vargs data))
         (let [;; Optimization: try maximize output+timestamp sharing
               ;; between appenders
               output-fn1 (enc/memoize_ (get config :output-fn default-output-fn))