Merge branch 'master' into structured-logging-prototype

This reverts commit 920353dd3e.

.clj-kondo/config.edn

@@ -247,6 +247,12 @@
     metabase.driver/current-db-time                                              {:namespaces ["metabase.*"]}
     metabase.driver/supports?                                                    {:namespaces ["metabase.*"]}
     metabase.query-processor.middleware.resolve-joins/maybe-resolve-source-table {:namespaces ["metabase.*"]}
+    metabase.util.log/tracef                                                     {:namespaces ["metabase.*"]}
+    metabase.util.log/debugf                                                     {:namespaces ["metabase.*"]}
+    metabase.util.log/infof                                                      {:namespaces ["metabase.*"]}
+    metabase.util.log/warnf                                                      {:namespaces ["metabase.*"]}
+    metabase.util.log/errorf                                                     {:namespaces ["metabase.*"]}
+    metabase.util.log/fatalf                                                     {:namespaces ["metabase.*"]}
     metabase.query-processor.util/normalize-token                                {:namespaces ["metabase.*"]}}}
 
   :discouraged-var
@@ -281,7 +287,14 @@
    medley.core/random-uuid                            {:message "Use clojure.core/random-uuid instead of medley.core/random-uuid"}
    metabase.driver/database-supports?                 {:message "Use metabase.driver.util/supports? instead of metabase.driver/database-supports?"}
    metabase.lib.equality/find-column-indexes-for-refs {:message "Use lib.equality/closest-matches-in-metadata or lib.equality/find-closest-matches-for-refs instead of lib.equality/find-column-indexes-for-refs"}
-   next.jdbc/active-tx?                               {:message "Use metabase.app-db.core/in-transaction? to see if we are in a transaction"}}
+   ;; TODO [bryan] Pull the metabase.util.log/*f entries out when we've migrated off of logf et al.
+   metabase.util.log/tracef                           {:message "Use log/trace with a context map instead" :level :info}
+   metabase.util.log/debugf                           {:message "Use log/debug with a context map instead" :level :info}
+   metabase.util.log/infof                            {:message "Use log/info with a context map instead" :level :info}
+   metabase.util.log/warnf                            {:message "Use log/warn with a context map instead" :level :info}
+   metabase.util.log/errorf                           {:message "Use log/error with a context map instead" :level :info}
+   metabase.util.log/fatalf                           {:message "Use log/fatal with a context map instead" :level :info}}
+   next.jdbc/active-tx?                               {:message "Use metabase.db/in-transaction? to see if we are in a transaction"}}
 
   :discouraged-namespace
   {camel-snake-kebab.core {:message "CSK is not Turkish-safe, use the versions in metabase.util instead."}

bin/kondo.sh

@@ -60,4 +60,4 @@ fi
 
 set -x
 
-$command
+$command | grep -v ' info: '

src/metabase/notification/send.clj

@@ -386,7 +386,7 @@
                             (.awaitTermination ^ThreadPoolExecutor executor 30 java.util.concurrent.TimeUnit/SECONDS)
                             (catch InterruptedException _
                               (log/warn "Interrupted while waiting for notification executor to terminate"))))))
-    (log/infof "Starting notification thread pool with %d threads" pool-size)
+    (log/info "Starting notification thread pool." {:pool-size pool-size})
     (dotimes [_ pool-size]
       (start-worker!))
     (fn [notification]

src/metabase/request/session.clj

@@ -7,6 +7,7 @@
    [metabase.settings.core :as setting]
    [metabase.users.models.user :as user]
    [metabase.util.i18n :as i18n]
+   [metabase.util.log :as log]
    [toucan2.core :as t2]))
 
 (def ^:private current-user-fields

src/metabase/server/middleware/log.clj

@@ -46,12 +46,17 @@
    (when async-status
      (format " [ASYNC: %s]" async-status))))
 
-(defn- format-performance-info
+(defn- performance-info
   [{:keys [start-time call-count-fn _diag-info-fn]
     :or {start-time    (u/start-timer)
          call-count-fn (constantly -1)}}]
   (let [elapsed-time (u/since-ms start-time)
         db-calls     (call-count-fn)]
+    {:elapsed-time elapsed-time
+     :db-calls db-calls}))
+
+(defn- format-performance-info [info]
+  (let [{:keys [db-calls elapsed-time]} (performance-info info)]
     (format "%.0fms (%s DB calls)" elapsed-time db-calls)))
 
 (defn- stats [diag-info-fn]

src/metabase/server/middleware/session.clj

@@ -79,9 +79,9 @@
   for `X-METABASE-SESSION`. If neither is found then no keyword is bound to the request."
   [handler]
   (fn [request respond raise]
-    (let [request (or (wrap-session-key-with-strategy :best request)
-                      request)]
-      (handler request respond raise))))
+    (let [request (or (wrap-session-key-with-strategy :best request) request)]
+      (log/with-context {:mb-session-key (:metabase-session-key request)}
+        (handler request respond raise)))))
 
 ;;; +----------------------------------------------------------------------------------------------------------------+
 ;;; |                                             wrap-current-user-info                                             |

src/metabase/task/impl.clj

@@ -74,7 +74,7 @@
     (try
       ;; don't bother logging namespace for now, maybe in the future if there's tasks of the same name in multiple
       ;; namespaces we can log it
-      (log/info "Initializing task" (u/format-color 'green (name k)) (u/emoji "📆"))
+      (log/info "Initializing" (u/emoji "📆") {:mb/task-name (name k)})
       (f k)
       (catch Throwable e
         (log/errorf e "Error initializing task %s" k)))))

src/metabase/util/log.clj

@@ -49,17 +49,61 @@
          (lambdaisland.glogi/log logger# level# nil s#)
          a#))))
 
+(defmacro with-context
+  "Executes body with the given context map and message prefix in ThreadContext.
+   The context map's keys and values are added to the ThreadContext individually.
+   Preserves any existing context values and restores them after execution.
+
+   The keys in context-map should be keywords.
+
+   Example usage:
+   (with-context {:notification_id 1}
+     (log/infof \"Hello\"))
+
+   ThreadContext will contain: {\"notification_id\" \"1\"} and stack \"Notification 1\""
+  [context-map & body]
+  (macros/case
+    :clj `(let [ctx-map# ~context-map
+                ctx-keys# (keys ctx-map#)
+                ;; Store original values before modifying
+                original-values# (into {}
+                                       (keep (fn [k#]
+                                               (when-let [v# (ThreadContext/get (str (symbol k#)))]
+                                                 [(str (symbol k#)) v#])))
+                                       ctx-keys#)]
+            (try
+              (doseq [k# ctx-keys#]
+                (ThreadContext/put (str (symbol k#)) (str (get ctx-map# k#))))
+              ~@body
+              (finally
+                (doseq [k# ctx-keys#]
+                  (if-let [original# (find original-values# (str (symbol k#)))]
+                    (ThreadContext/put (str (symbol k#)) (val original#))
+                    (ThreadContext/remove (str (symbol k#))))))))
+    "cljs" ~@body))
+
+(defn parse-args
+  "Parses args for [[trace]], [[debug]], [[info]], [[warn]], [[error]], [[fatal]]
+  into a map with message, context and exception keys."
+  [& args]
+  (let [first-arg (first args)
+        has-exception? (instance? Exception first-arg)
+
+        rest-args (if has-exception? (rest args) args)
+        has-context? (map? (last rest-args))
+        message-args (cond-> rest-args has-context? drop-last)]
+    {:msg (str/join \space (or message-args []))
+     :ctx (when has-context? (last rest-args))
+     :e (when has-exception? first-arg)}))
+
 (defn- tools-logp
   "Macro helper for [[logp]] in CLJ."
   [logger-ns level x more]
   `(let [logger# (clojure.tools.logging.impl/get-logger clojure.tools.logging/*logger-factory* ~logger-ns)]
      (when (clojure.tools.logging.impl/enabled? logger# ~level)
-       (let [x# ~x]
-         (if (instance? Throwable x#)
-           (clojure.tools.logging/log* logger# ~level x#  ~(if (nil? more)
-                                                             ""
-                                                             `(print-str ~@more)))
-           (clojure.tools.logging/log* logger# ~level nil (print-str x# ~@more)))))))
+       (let [args# (parse-args ~@(cons x more))]
+         (with-context (:ctx args#)
+           (clojure.tools.logging/log* logger# ~level (:e args#) (:msg args#)))))))
 
 (defn- tools-logf
   "Macro helper for [[logf]] in CLJ."
@@ -81,7 +125,8 @@
 (defmacro logp
   "Implementation for prn-style `logp`.
   You shouldn't have to use this directly; prefer the level-specific macros like [[info]]."
-  {:arglists '([level message & more] [level throwable message & more])}
+  {:arglists '([level message & more]
+               [level throwable message & more])}
   [level x & more]
   `(do
      ~(config/build-type-case
@@ -104,75 +149,130 @@
         :clj  (tools-logf *ns*       level x args))))
 
 ;;; --------------------------------------------------- Public API ---------------------------------------------------
+
 (defmacro trace
-  "Log one or more args at the `:trace` level."
-  {:arglists '([& args] [e & args])}
+  "Log one or more args at the `:trace` level.
+
+   Takes an optional context map as the last argument."
+  {:arglists '(;; as many msgs as you want -- must include at least 1 string
+               ;; These can optionally take an exception as the first arg
+               [msg] [msg1 msg2] [msg1 msg2 msg3] [msg1 msg2 msg3 msg4] [msg1 msg2 msg3 msg4 msg5]
+               [msg ctx] [msg1 msg2 ctx] [msg1 msg2 msg3 ctx] [msg1 msg2 msg3 msg4 ctx] [msg1 msg2 msg3 msg4 msg5 ctx]
+               [e msg] [e msg1 msg2] [e msg1 msg2 msg3] [e msg1 msg2 msg3 msg4] [e msg1 msg2 msg3 msg4 msg5]
+               [e msg ctx] [e msg1 msg2 ctx] [e msg1 msg2 msg3 ctx] [e msg1 msg2 msg3 msg4 ctx] [e msg1 msg2 msg3 msg4 msg5 ctx])}
   [& args]
   `(logp :trace ~@args))
 
-(defmacro tracef
-  "Log a message at the `:trace` level by applying `format` to a format string and args."
+(defmacro debug
+  "Log one or more args at the `:debug` level.
+
+   Takes an optional context map as the last argument."
+  {:arglists '(;; as many msgs as you want -- must include at least 1 string
+               ;; These can optionally take an exception as the first arg
+               [msg] [msg1 msg2] [msg1 msg2 msg3] [msg1 msg2 msg3 msg4] [msg1 msg2 msg3 msg4 msg5]
+               [msg ctx] [msg1 msg2 ctx] [msg1 msg2 msg3 ctx] [msg1 msg2 msg3 msg4 ctx] [msg1 msg2 msg3 msg4 msg5 ctx]
+               [e msg] [e msg1 msg2] [e msg1 msg2 msg3] [e msg1 msg2 msg3 msg4] [e msg1 msg2 msg3 msg4 msg5]
+               [e msg ctx] [e msg1 msg2 ctx] [e msg1 msg2 msg3 ctx] [e msg1 msg2 msg3 msg4 ctx] [e msg1 msg2 msg3 msg4 msg5 ctx])}
+  [& args]
+  `(logp :debug ~@args))
+
+(defmacro info
+  "Log one or more args at the `:info` level.
+
+   Takes an optional context map as the last argument."
+  {:arglists '(;; as many msgs as you want -- must include at least 1 string
+               ;; These can optionally take an exception as the first arg
+               [msg] [msg1 msg2] [msg1 msg2 msg3] [msg1 msg2 msg3 msg4] [msg1 msg2 msg3 msg4 msg5]
+               [msg ctx] [msg1 msg2 ctx] [msg1 msg2 msg3 ctx] [msg1 msg2 msg3 msg4 ctx] [msg1 msg2 msg3 msg4 msg5 ctx]
+               [e msg] [e msg1 msg2] [e msg1 msg2 msg3] [e msg1 msg2 msg3 msg4] [e msg1 msg2 msg3 msg4 msg5]
+               [e msg ctx] [e msg1 msg2 ctx] [e msg1 msg2 msg3 ctx] [e msg1 msg2 msg3 msg4 ctx] [e msg1 msg2 msg3 msg4 msg5 ctx])}
+  [& args]
+  `(logp :info ~@args))
+
+(defmacro warn
+  "Log one or more args at the `:warn` level.
+
+   Takes an optional context map as the last argument."
+  {:arglists '(;; as many msgs as you want -- must include at least 1 string
+               ;; These can optionally take an exception as the first arg
+               [msg] [msg1 msg2] [msg1 msg2 msg3] [msg1 msg2 msg3 msg4] [msg1 msg2 msg3 msg4 msg5]
+               [msg ctx] [msg1 msg2 ctx] [msg1 msg2 msg3 ctx] [msg1 msg2 msg3 msg4 ctx] [msg1 msg2 msg3 msg4 msg5 ctx]
+               [e msg] [e msg1 msg2] [e msg1 msg2 msg3] [e msg1 msg2 msg3 msg4] [e msg1 msg2 msg3 msg4 msg5]
+               [e msg ctx] [e msg1 msg2 ctx] [e msg1 msg2 msg3 ctx] [e msg1 msg2 msg3 msg4 ctx] [e msg1 msg2 msg3 msg4 msg5 ctx])}
+  [& args]
+  `(logp :warn ~@args))
+
+(defmacro error
+  "Log one or more args at the `:error` level.
+
+   Takes an optional context map as the last argument."
+  {:arglists '(;; as many msgs as you want -- must include at least 1 string
+               ;; These can optionally take an exception as the first arg
+               [msg] [msg1 msg2] [msg1 msg2 msg3] [msg1 msg2 msg3 msg4] [msg1 msg2 msg3 msg4 msg5]
+               [msg ctx] [msg1 msg2 ctx] [msg1 msg2 msg3 ctx] [msg1 msg2 msg3 msg4 ctx] [msg1 msg2 msg3 msg4 msg5 ctx]
+               [e msg] [e msg1 msg2] [e msg1 msg2 msg3] [e msg1 msg2 msg3 msg4] [e msg1 msg2 msg3 msg4 msg5]
+               [e msg ctx] [e msg1 msg2 ctx] [e msg1 msg2 msg3 ctx] [e msg1 msg2 msg3 msg4 ctx] [e msg1 msg2 msg3 msg4 msg5 ctx])}
+  [& args]
+  `(logp :error ~@args))
+
+#_{:clj-kondo/ignore [:clojure-lsp/unused-public-var]}
+(defmacro fatal
+  "Log one or more args at the `:fatal` level.
+
+   Takes an optional context map as the last argument."
+  {:arglists '(;; as many msgs as you want -- must include at least 1 string
+               ;; These can optionally take an exception as the first arg
+               [msg] [msg1 msg2] [msg1 msg2 msg3] [msg1 msg2 msg3 msg4] [msg1 msg2 msg3 msg4 msg5]
+               [msg ctx] [msg1 msg2 ctx] [msg1 msg2 msg3 ctx] [msg1 msg2 msg3 msg4 ctx] [msg1 msg2 msg3 msg4 msg5 ctx]
+               [e msg] [e msg1 msg2] [e msg1 msg2 msg3] [e msg1 msg2 msg3 msg4] [e msg1 msg2 msg3 msg4 msg5]
+               [e msg ctx] [e msg1 msg2 ctx] [e msg1 msg2 msg3 ctx] [e msg1 msg2 msg3 msg4 ctx] [e msg1 msg2 msg3 msg4 msg5 ctx])}
+  [& args]
+  `(logp :fatal ~@args))
+
+(defmacro ^:deprecated tracef
+  "Log a message at the `:trace` level by applying `format` to a format string and args.
+
+  DEPRECATION WARNING: Instead of using formatted string logging, use trace, with a map as the last arg."
   {:arglists '([format-string & args] [e format-string & args])}
   [& args]
   `(logf :trace ~@args))
 
-(defmacro debug
-  "Log one or more args at the `:debug` level."
-  {:arglists '([& args] [e & args])}
-  [& args]
-  `(logp :debug ~@args))
+(defmacro ^:deprecated debugf
+  "Log a message at the `:debug` level by applying `format` to a format string and args.
 
-(defmacro debugf
-  "Log a message at the `:debug` level by applying `format` to a format string and args."
+  DEPRECATION WARNING: Instead of using formatted string logging, use debug, with a map as the last arg."
   {:arglists '([format-string & args] [e format-string & args])}
   [& args]
   `(logf :debug ~@args))
 
-(defmacro info
-  "Log one or more args at the `:info` level."
-  {:arglists '([& args] [e & args])}
-  [& args]
-  `(logp :info ~@args))
+(defmacro ^:deprecated infof
+  "Log a message at the `:info` level by applying `format` to a format string and args.
 
-(defmacro infof
-  "Log a message at the `:info` level by applying `format` to a format string and args."
+  DEPRECATION WARNING: Instead of using formatted string logging, use info, with a map as the last arg."
   {:arglists '([format-string & args] [e format-string & args])}
   [& args]
   `(logf :info ~@args))
 
-(defmacro warn
-  "Log one or more args at the `:warn` level."
-  {:arglists '([& args] [e & args])}
-  [& args]
-  `(logp :warn ~@args))
+(defmacro ^:deprecated warnf
+  "Log a message at the `:warn` level by applying `format` to a format string and args.
 
-(defmacro warnf
-  "Log a message at the `:warn` level by applying `format` to a format string and args."
+  DEPRECATION WARNING: Instead of using formatted string logging, use warn, with a map as the last arg."
   {:arglists '([format-string & args] [e format-string & args])}
   [& args]
   `(logf :warn ~@args))
 
-(defmacro error
-  "Log one or more args at the `:error` level."
-  {:arglists '([& args] [e & args])}
-  [& args]
-  `(logp :error ~@args))
+(defmacro ^:deprecated errorf
+  "Log a message at the `:error` level by applying `format` to a format string and args.
 
-(defmacro errorf
-  "Log a message at the `:error` level by applying `format` to a format string and args."
+  DEPRECATION WARNING: Instead of using formatted string logging, use error, with a map as the last arg."
   {:arglists '([format-string & args] [e format-string & args])}
   [& args]
   `(logf :error ~@args))
 
-#_{:clj-kondo/ignore [:clojure-lsp/unused-public-var]}
-(defmacro fatal
-  "Log one or more args at the `:fatal` level."
-  {:arglists '([& args] [e & args])}
-  [& args]
-  `(logp :fatal ~@args))
+(defmacro ^:deprecated fatalf
+  "Log a message at the `:fatal` level by applying `format` to a format string and args.
 
-(defmacro fatalf
-  "Log a message at the `:fatal` level by applying `format` to a format string and args."
+  DEPRECATION WARNING: Instead of using formatted string logging, use fatal, with a map as the last arg."
   {:arglists '([format-string & args] [e format-string & args])}
   [& args]
   `(logf :fatal ~@args))
@@ -210,34 +310,3 @@
   [& body]
   `(binding [clojure.tools.logging/*logger-factory* clojure.tools.logging.impl/disabled-logger-factory]
      ~@body))
-
-(defmacro with-context
-  "Executes body with the given context map and message prefix in ThreadContext.
-   The context map's keys and values are added to the ThreadContext individually.
-   Preserves any existing context values and restores them after execution.
-
-   Example usage:
-   (with-context {:notification_id 1}
-     (log/infof \"Hello\"))
-
-   ThreadContext will contain: {\"notification_id\" \"1\"} and stack \"Notification 1\""
-  [context-map & body]
-  (macros/case
-    :clj `(let [ctx-map# ~(update-keys context-map #(str "mb-" (u.format/qualified-name %)))
-                ctx-keys# (keys ctx-map#)
-                ;; Store original values before modifying
-                original-values# (into {}
-                                       (keep (fn [k#]
-                                               (when-let [v# (ThreadContext/get (name k#))]
-                                                 [(name k#) v#])))
-                                       ctx-keys#)]
-            (try
-              (doseq [k# ctx-keys#]
-                (ThreadContext/put (name k#) (str (get ctx-map# k#))))
-              ~@body
-              (finally
-                (doseq [k# ctx-keys#]
-                  (if-let [original# (find original-values# (name k#))]
-                    (ThreadContext/put (name k#) (val original#))
-                    (ThreadContext/remove (name k#)))))))
-    :cljs ~@body))

src/metabase/util/log/capture.cljc

@@ -20,13 +20,16 @@
        [[goog.string :as gstring]])
    [clojure.set :as set]
    [clojure.spec.alpha :as s]
-   [clojure.string :as str]))
+   [clojure.string :as str])
+  #?(:clj
+     (:import
+      (org.apache.logging.log4j ThreadContext))))
 
 (def ^:dynamic ^{:arglists '([namespace-str level-int])} *capture-logs-fn*
   "Function with the signature that given a namespace string and log level (as an int), returns a function that should
   be used to capture a log message, if messages at that level should be captured. Its signature is
 
-    (f namespace-str level-int) => (f e message)"
+    (f namespace-str level-int) => (f e message & [ctx])"
   (constantly nil))
 
 ;;; Code below converts log levels to integers right away, because a simple int comparison like `(<= 5 4)` is super
@@ -50,16 +53,18 @@
   ;; the prefix stuff is calculated outside of the function so we can be SUPER OPTIMIZED and not do anything
   ;; allocation in cases where we're not going to capture anything.
   (let [captured-namespace-prefix (str captured-namespace \.)]
-    (fn [message-namespace message-level-int]
+    (fn capture-logs-return-fn
+      [message-namespace message-level-int]
       ;; similarly, the level comparison is done first, because it's faster and will hopefully filter out a lot of
       ;; things we weren't going to capture anyway before we do the more expensive namespace check
       (when (and (<= message-level-int captured-level-int)
                  (or (= message-namespace captured-namespace)
                      (str/starts-with? message-namespace captured-namespace-prefix)))
         ;; VERY IMPORTANT! Only return the capturing function if we actually want to capture a log message.
-        (fn capture-fn [e message]
+        (fn capture-fn [e message & [ctx]]
           (swap! logs conj {:namespace (symbol message-namespace)
                             :level     (int->level message-level-int)
+                            :ctx       (update-keys ctx keyword)
                             :e         e
                             :message   message}))))))
 
@@ -73,9 +78,11 @@
                                   (let [f1 (old-capture-fn a-message message-level-int)
                                         f2 (capture-fn a-message message-level-int)]
                                     (cond
-                                      (and f1 f2) (fn [e message]
-                                                    (f1 e message)
-                                                    (f2 e message))
+                                      (and f1 f2) (fn [e message ctx]
+                                                    ;; If this stacks multiple times, then f1 will call everything in
+                                                    ;; the log-capture stack.
+                                                    (f1 e message ctx)
+                                                    (f2 e message ctx))
                                       f1          f1
                                       f2          f2)))]
       (f (fn [] @logs)))))
@@ -180,8 +187,18 @@
 (defn capture-logp!
   "Impl for log message capturing for [[metabase.util.log/logp]]."
   [f & args]
-  (let [{:keys [e args]} (parse-args args)]
-    (f e (str/join \space (map print-str args)))))
+  (let [{:keys [e args]}  (parse-args args)
+        has-inline-ctx?   (map? (last args))
+        msgs              (if has-inline-ctx? (butlast args) args)
+        inline-ctx        (when has-inline-ctx?
+                            (update-keys (last args) #(str (symbol %))))
+        ctx-map           #?(:clj (ThreadContext/getImmutableContext)
+                             ;; not implemented in cljs
+                             :cljs {})
+        has-with-context? (not-empty ctx-map)]
+    (f e (str/join \space (map print-str msgs))
+       (when (or has-inline-ctx? has-with-context?)
+         (merge (into {} ctx-map) inline-ctx)))))
 
 (defn capture-logf!
   "Impl for log message capturing for [[metabase.util.log/logf]]."

test/metabase/settings/api_test.clj

@@ -1,6 +1,5 @@
 (ns metabase.settings.api-test
   (:require
-   [clojure.string :as str]
    [clojure.test :refer :all]
    [metabase.api.common.validation :as validation]
    [metabase.driver.h2 :as h2]
@@ -388,7 +387,12 @@
   :encryption :no)
 
 (deftest deprecation-warning-for-deprecated-setting-test
-  (log.capture/with-log-messages-for-level [warnings :warn]
+  (log.capture/with-log-messages-for-level [warnings :info]
     (test-deprecated-setting! "hello")
-    (is (re-find #"Setting test-deprecated-setting is deprecated as of Metabase 0.51.0"
-                 (str/join " " (map :message (warnings)))))))
+    (is (= [{:namespace 'metabase.models.setting,
+             :level :warn,
+             :ctx nil,
+             :e nil,
+             :message
+             "Setting test-deprecated-setting is deprecated as of Metabase 0.51.0 and may be removed in a future version."}]
+           (warnings)))))

test/metabase/util/formatting/date_test.cljc

@@ -339,7 +339,12 @@
                 (date/format-datetime-with-unit "2022-04-07T19:08:45.123" {:unit         :asdf
                                                                            :date-style   "asdf"
                                                                            :time-enabled false}))
-        (is (=? [{:level :warn, :message "Unrecognized date style {:date-style asdf, :unit :asdf}"}]
+
+        (is (=? [{:namespace 'metabase.util.formatting.internal.date-formatters,
+                  :level :warn,
+                  :ctx {:date-style "asdf", :unit :asdf},
+                  :e nil,
+                  :message "Unrecognized date style"}]
                 (messages))))
       (is (= "2022-04-07T19:08:45" @result)))))
 

test/metabase/util/log/capture_test.cljc

@@ -11,22 +11,69 @@
      metabase.test-runner.assert-exprs.approximately-equal/keep-me))
 
 (deftest ^:parallel basic-logp-test
-  (is (= [{:namespace 'metabase.util.log.capture-test, :level :warn, :e nil, :message "a message"}]
+  (is (= [{:namespace 'metabase.util.log.capture-test, :level :warn, :e nil, :message "a message", :ctx nil}]
          (log.capture/with-log-messages-for-level [messages :warn]
            (log/info "not this one")
            (log/warn "a message")
            (messages))))
-  (is (= [{:namespace 'metabase.util.log.capture-test, :level :info, :e nil, :message "here's one"}
-          {:namespace 'metabase.util.log.capture-test, :level :warn, :e nil, :message "a message"}]
+  (is (= [{:namespace 'metabase.util.log.capture-test, :level :info, :e nil, :message "here's one", :ctx nil}
+          {:namespace 'metabase.util.log.capture-test, :level :warn, :e nil, :message "a message", :ctx nil}]
          (log.capture/with-log-messages-for-level [messages :info]
            (log/info "here's one")
            (log/warn "a message")
            (messages))))
-  (is (= [{:namespace 'metabase.util.log.capture-test, :level :info, :e nil, :message ":keyword 78"}]
+  (is (= [{:namespace 'metabase.util.log.capture-test, :level :info, :e nil, :message ":keyword 78", :ctx nil}]
          (log.capture/with-log-messages-for-level [messages :info]
            (log/info :keyword 78)
            (messages)))))
 
+#?(:clj
+   (deftest ^:parallel logp-context-test
+     (is (= [{:namespace 'metabase.util.log.capture-test, :level :warn, :e nil, :message "a message one", :ctx {:a/b 1}}]
+            (log.capture/with-log-messages-for-level [messages :warn]
+              (log/info "info are not captured, so don't expect to see this one.")
+              (log/warn "a message one" {:a/b 1})
+              (messages))))
+     (is (= [{:namespace 'metabase.util.log.capture-test, :level :info, :e nil, :message "here's one"}
+             {:namespace 'metabase.util.log.capture-test, :level :warn, :e nil, :message "a message two", :ctx {:a/b 1}}]
+            (log.capture/with-log-messages-for-level [messages :info]
+              (log/info "here's one")
+              (log/warn "a message two" {:a/b 1})
+              (messages))))
+     (is (= [{:namespace 'metabase.util.log.capture-test, :level :info, :e nil, :message ":keyword 78", :ctx {:a/b 1}}]
+            (log.capture/with-log-messages-for-level [messages :info]
+              (log/info :keyword 78 {:a/b 1})
+              (messages))))))
+
+#?(:clj
+   (deftest ^:parallel logp-super-context-test
+     (is (=
+          [{:message "empty context", :ctx nil}
+           {:message "a",             :ctx {"a/a" "A"}}
+           {:message "a b",           :ctx {"a/a" "A", "b/b" "B"}}
+           {:message "a b c",         :ctx {"a/a" "A", "b/b" "B", "c/c" "C"}}
+           {:message "a b c d",       :ctx {"a/a" "A", "b/b" "B", "c/c" "C", "d/d" "D"}}
+           {:message "a b c",         :ctx {"a/a" "A", "b/b" "B", "c/c" "C"}}
+           {:message "a b",           :ctx {"a/a" "A", "b/b" "B"}}
+           {:message "a",             :ctx {"a/a" "A"}}
+           {:message "empty context", :ctx nil}]
+          (log.capture/with-log-messages-for-level [messages :info]
+            (log/info "empty context")
+            (log/with-context {:a/a "A"}
+              (log/info "a")
+              (log/with-context {:b/b "B"}
+                (log/info "a b")
+                (log/with-context {:c/c "C"}
+                  (log/info "a b c")
+                  (log/info "a b c d" {:d/d "D"})
+                  (log/info "a b c"))
+                (log/info "a b"))
+              (log/info "a"))
+            (log/info "empty context")
+            (mapv
+             #(select-keys % [:message :ctx])
+             (messages)))))))
+
 (deftest ^:parallel logp-levels-test
   (let [important-message #{"fatal" "error" "warn" "info" "debug" "trace"}
         spam (fn []
@@ -36,12 +83,12 @@
                (log/info  "info")
                (log/debug "debug")
                (log/trace "trace"))
-        logs [{:namespace 'metabase.util.log.capture-test, :level :fatal, :e nil, :message "fatal"}
-              {:namespace 'metabase.util.log.capture-test, :level :error, :e nil, :message "error"}
-              {:namespace 'metabase.util.log.capture-test, :level :warn, :e  nil, :message "warn"}
-              {:namespace 'metabase.util.log.capture-test, :level :info, :e  nil, :message "info"}
-              {:namespace 'metabase.util.log.capture-test, :level :debug, :e nil, :message "debug"}
-              {:namespace 'metabase.util.log.capture-test, :level :trace, :e nil, :message "trace"}]]
+        logs [{:namespace 'metabase.util.log.capture-test, :level :fatal, :e nil, :ctx nil, :message "fatal"}
+              {:namespace 'metabase.util.log.capture-test, :level :error, :e nil, :ctx nil, :message "error"}
+              {:namespace 'metabase.util.log.capture-test, :level :warn, :e  nil, :ctx nil, :message "warn"}
+              {:namespace 'metabase.util.log.capture-test, :level :info, :e  nil, :ctx nil, :message "info"}
+              {:namespace 'metabase.util.log.capture-test, :level :debug, :e nil, :ctx nil, :message "debug"}
+              {:namespace 'metabase.util.log.capture-test, :level :trace, :e nil, :ctx nil, :message "trace"}]]
     (are [prefix level] (= (->> logs
                                 (filter #(contains? important-message (:message %)))
                                 (take prefix))
@@ -57,7 +104,7 @@
       6 :trace)))
 
 (deftest ^:parallel logf-formatting-test
-  (is (= [{:namespace 'metabase.util.log.capture-test, :level :info, :e nil, :message "input: 8, 3; output: ignored"}]
+  (is (= [{:namespace 'metabase.util.log.capture-test, :level :info, :e nil, :message "input: 8, 3; output: ignored", :ctx nil}]
          (log.capture/with-log-messages-for-level [messages :info]
            (log/infof "input: %d, %d; %s: ignored" 8 3 "output")
            (messages)))))
@@ -84,6 +131,7 @@
       (log/trace "a" "picture")
       (is (= [{:namespace 'metabase.util.log.capture-test
                :level     :trace
+               :ctx       nil
                :e         nil
                :message   "a picture"}]
              (messages))))))
@@ -96,6 +144,7 @@
       (log/debug "a picture")
       (is (= [{:namespace 'metabase.util.log.capture-test
                :level     :debug
+               :ctx       nil
                :e         nil
                :message   "a picture"}]
              (messages))))))
@@ -108,6 +157,7 @@
       (log/trace "a picture")
       (is (= [{:namespace 'metabase.util.log.capture-test
                :level     :trace
+               :ctx       nil
                :e         nil
                :message   "a picture"}]
              (messages))))))
@@ -120,6 +170,7 @@
       (log/trace "a picture")
       (is (= [{:namespace 'metabase.util.log.capture-test
                :level     :trace
+               :ctx       nil
                :e         nil
                :message   "a picture"}]
              (messages))))))
@@ -137,15 +188,14 @@
   (testing "Should be able to use `with-log-messages-for-level` multiple times"
     (log.capture/with-log-messages-for-level [util-trace-messages ["metabase.util" :trace]]
       (log.capture/with-log-messages-for-level [test-debug-messages [metabase.util.log.capture-test :debug]]
-        (is (= []
-               (util-trace-messages)))
-        (is (= []
-               (test-debug-messages)))
+        (is (= [] (util-trace-messages)))
+        (is (= [] (test-debug-messages)))
         (testing "trace message should only show up in :trace"
           (log/trace "a picture")
           (is (= [{:namespace 'metabase.util.log.capture-test
                    :level     :trace
                    :e         nil
+                   :ctx       nil
                    :message   "a picture"}]
                  (util-trace-messages)))
           (is (= []
@@ -155,14 +205,53 @@
           (is (= [{:namespace 'metabase.util.log.capture-test
                    :level     :trace
                    :e         nil
+                   :ctx       nil
                    :message   "a picture"}
                   {:namespace 'metabase.util.log.capture-test
                    :level     :debug
                    :e         nil
+                   :ctx       nil
+                   :message   "a bug"}]
+                 (util-trace-messages)))
+          (is (= [{:namespace 'metabase.util.log.capture-test
+                   :level     :debug
+                   :e         nil
+                   :ctx       nil
+                   :message   "a bug"}]
+                 (test-debug-messages))))))))
+
+(deftest ^:parallel multiple-captures-ctx-test
+  (testing "Should be able to use `with-log-messages-for-level` multiple times"
+    (log.capture/with-log-messages-for-level [util-trace-messages ["metabase.util" :trace]]
+      (log.capture/with-log-messages-for-level [test-debug-messages [metabase.util.log.capture-test :debug]]
+        (is (= [] (util-trace-messages)))
+        (is (= [] (test-debug-messages)))
+        (testing "trace message should only show up in :trace"
+          (log/trace "me like we were" {:on-the "titanic"})
+          (is (= [{:namespace 'metabase.util.log.capture-test
+                   :level :trace
+                   :ctx {:on-the "titanic"}
+                   :e nil
+                   :message "me like we were"}]
+                 (util-trace-messages)))
+          (is (= []
+                 (test-debug-messages))))
+        (testing "debug message should show up in :trace and :debug"
+          (log/debug "a bug" {:we/will "fix"})
+          (is (= [{:namespace 'metabase.util.log.capture-test
+                   :level :trace
+                   :ctx {:on-the "titanic"}
+                   :e nil
+                   :message "me like we were"}
+                  {:namespace 'metabase.util.log.capture-test
+                   :level     :debug
+                   :ctx       {:we/will "fix"}
+                   :e         nil
                    :message   "a bug"}]
                  (util-trace-messages)))
           (is (= [{:namespace 'metabase.util.log.capture-test
                    :level     :debug
+                   :ctx       {:we/will "fix"}
                    :e         nil
                    :message   "a bug"}]
                  (test-debug-messages))))))))
@@ -180,6 +269,7 @@
              (util-debug-messages)))
       (is (= [{:namespace 'metabase.util.log.capture-test
                :level     :trace
+               :ctx       nil
                :e         nil
                :message   "a picture"}]
              (test-trace-messages))))
@@ -187,15 +277,18 @@
       (log/debugf "a %s" "bug")
       (is (= [{:namespace 'metabase.util.log.capture-test
                :level     :debug
+               :ctx       nil
                :e         nil
                :message   "a bug"}]
              (util-debug-messages)))
       (is (= [{:namespace 'metabase.util.log.capture-test
                :level     :trace
+               :ctx       nil
                :e         nil
                :message   "a picture"}
               {:namespace 'metabase.util.log.capture-test
                :level     :debug
+               :ctx       nil
                :e         nil
                :message   "a bug"}]
              (test-trace-messages))))))

test/metabase/util/log_test.clj

@@ -1,12 +1,69 @@
 (ns metabase.util.log-test
   (:require
-   [clojure.test :refer :all]
-   [metabase.util.log :as log])
+   [clojure.test :refer [deftest is testing]]
+   [clojure.test.check.clojure-test :refer [defspec]]
+   [clojure.test.check.properties :as prop]
+   [malli.generator :as mg]
+   [metabase.util.log :as log]
+   [metabase.util.malli.schema :as ms])
   (:import
    (org.apache.logging.log4j ThreadContext)))
 
 (set! *warn-on-reflection* true)
 
+(deftest log-parse-args-test
+  (is (= ["Must have at least one string in arguments" nil]
+         (try (#'log/parse-args) (catch Exception e [(ex-message e) (ex-data e)]))))
+  (is (= {:msg "a", :ctx nil, :e nil}
+         (#'log/parse-args "a")))
+  (is (= {:msg "a b", :ctx nil, :e nil}
+         (#'log/parse-args "a" "b")))
+  (is (= {:msg "a b", :ctx {:a 1}, :e nil}
+         (#'log/parse-args "a" "b" {:a 1})))
+  (is (= {:msg "a b 2", :ctx {:a 1}, :e {:ex-message "message", :ex-data {}}}
+         (-> (#'log/parse-args (ex-info "message" {}) "a" "b" 2 {:a 1})
+             (update :e (fn [e]
+                          {:ex-message (ex-message e)
+                           :ex-data (ex-data e)}))))))
+
+(def oddity
+  [:and
+   {:gen/elements [(ex-info "woops" {:problem true})
+                   (ex-info "uh o" {:problem :yea})
+                   (ex-info "oops" {:problem :nope})]}
+   (ms/InstanceOfClass Throwable)])
+
+(def ^:private valid-args [:cat
+                           [:? oddity]
+                           ;; anything printable with at least 1 string.
+                           [:* :any] :string [:* :any]
+                           [:? :map]])
+
+(defspec can-valid-log-args
+  (prop/for-all [log-args (mg/generator valid-args)]
+    (= #{:msg :ctx :e} (set (keys (apply #'log/parse-args log-args))))))
+
+(defspec can-pick-out-ctx-maps
+  (prop/for-all [log-args (mg/generator valid-args)]
+    (if (map? (last log-args))
+      (= (last log-args)
+         (:ctx (apply #'log/parse-args log-args)))
+      true)))
+
+(defspec enforces-at-least-one-string
+  (prop/for-all [log-args (mg/generator [:cat [:? oddity] [:* :string] [:? :map]])]
+    (if (seq (filter string? log-args))
+      true
+      (try (apply #'log/parse-args log-args)
+           (catch Exception e (= "Must have at least one string in arguments" (ex-message e)))))))
+
+(defspec enforces-at-least-one-string-with-any
+  (prop/for-all [log-args (mg/generator [:cat [:? oddity] [:* :any] [:? :map]])]
+    (if (seq (filter string? log-args))
+      true
+      (try (apply #'log/parse-args log-args)
+           (catch Exception e (= "Must have at least one string in arguments" (ex-message e)))))))
+
 (defn- get-context
   []
   (ThreadContext/getImmutableContext))