diff --git a/modules/drivers/druid/src/metabase/driver/druid.clj b/modules/drivers/druid/src/metabase/driver/druid.clj
index 9f4dc39a642623d98394666fe4e7eefd233ecd44..906ed8441ecec55df05574460e06797d81d3aff3 100644
--- a/modules/drivers/druid/src/metabase/driver/druid.clj
+++ b/modules/drivers/druid/src/metabase/driver/druid.clj
@@ -83,7 +83,7 @@
(if-not query-id
(log/warn interrupted-ex "Client closed connection, no queryId found, can't cancel query")
(ssh/with-ssh-tunnel [details-with-tunnel details]
- (log/warnf "Client closed connection, cancelling Druid queryId '%s'" query-id)
+ (log/warnf "Client closed connection, canceling Druid queryId '%s'" query-id)
(try
;; If we can't cancel the query, we don't want to hide the original exception, attempt to cancel, but if
;; we can't, we should rethrow the InterruptedException, not an exception from the cancellation
diff --git a/modules/drivers/presto/src/metabase/driver/presto.clj b/modules/drivers/presto/src/metabase/driver/presto.clj
index 349f0add4cb4a0d8125e579a163a27bf83b24282..74e9dbd426a9c1c8001096646ff94c4212ba46c4 100644
--- a/modules/drivers/presto/src/metabase/driver/presto.clj
+++ b/modules/drivers/presto/src/metabase/driver/presto.clj
@@ -140,7 +140,7 @@
;; If we fail to cancel the query, log it but propogate the interrupted exception, instead of
;; covering it up with a failed cancel
(catch Exception e
- (log/error e (trs "Error cancelling query with ID {0}" id))))
+ (log/error e (trs "Error canceling query with ID {0}" id))))
(log/warn (trs "Client connection closed, no query-id found, can't cancel query")))
;; Propogate the error so that any finalizers can still run
(throw e)))))))))
diff --git a/src/metabase/async/api_response.clj b/src/metabase/async/api_response.clj
index 881d192a9ff3f1b743e203247dd59821a2b34db4..506d63511dfb75063381c59378d30e36d00f4b1c 100644
--- a/src/metabase/async/api_response.clj
+++ b/src/metabase/async/api_response.clj
@@ -51,7 +51,7 @@
(.flush out)
true
(catch EofException e
- (log/debug e (u/format-color 'yellow (trs "connection closed, canceling request")))
+ (log/debug (u/format-color 'yellow (trs "connection closed, canceling request")))
false)
(catch Throwable e
(log/error e (trs "Unexpected error writing keepalive characters"))
diff --git a/src/metabase/async/util.clj b/src/metabase/async/util.clj
index 4a7e671038b344b85cd9a30a3da5e48fce11befd..552e0035543443f90a46ba07c126e40a132375ef 100644
--- a/src/metabase/async/util.clj
+++ b/src/metabase/async/util.clj
@@ -11,8 +11,8 @@
like.
Returns a channel that will send a single message when such early-closing cancelation occurs. You can listen for
- this message to implement special cancelation behavior, such as canceling async jobs. This channel automatically
- closes when either `in-chan` or `out-chan` closes."
+ this message to implement special cancelation/close behavior, such as canceling async jobs. This channel
+ automatically closes when either `in-chan` or `out-chan` closes."
[in-chan :- ManyToManyChannel, out-chan :- ManyToManyChannel]
(let [canceled-chan (a/chan 1)]
;; fire off a block that will wait for either in-chan to produce a result or out-chan to be closed
diff --git a/src/metabase/driver/sql_jdbc/execute.clj b/src/metabase/driver/sql_jdbc/execute.clj
index 4fa65c7861ca14ff57386297d99abb83ae4d82c6..105f52f4516323a16617698f8a1140da83832f46 100644
--- a/src/metabase/driver/sql_jdbc/execute.clj
+++ b/src/metabase/driver/sql_jdbc/execute.clj
@@ -181,8 +181,8 @@
;; we can give up on the query running in the future
@query-future)
(catch InterruptedException e
- (log/warn e (tru "Client closed connection, cancelling query"))
- ;; This is what does the real work of cancelling the query. We aren't checking the result of
+ (log/warn (tru "Client closed connection, canceling query"))
+ ;; This is what does the real work of canceling the query. We aren't checking the result of
;; `query-future` but this will cause an exception to be thrown, saying the query has been cancelled.
(.cancel stmt)
(throw e))))))
diff --git a/src/metabase/middleware/auth.clj b/src/metabase/middleware/auth.clj
index e3bcfe8c2edaf0982fde649dcfb411b410335bba..5f63a95f36983a2edd9de25e24dc81d68de99c37 100644
--- a/src/metabase/middleware/auth.clj
+++ b/src/metabase/middleware/auth.clj
@@ -28,7 +28,7 @@
(defn enforce-api-key
- "Middleware that enforces validation of the client via API Key, cancelling the request processing if the check fails.
+ "Middleware that enforces validation of the client via API Key, canceling the request processing if the check fails.
Validation is handled by first checking for the presence of the `:metabase-api-key` on the request. If the api key
is available then we validate it by checking it against the configured `:mb-api-key` value set in our global config.
diff --git a/src/metabase/middleware/log.clj b/src/metabase/middleware/log.clj
index 3957da0a386f11944466766d8637be9111894ca6..2bcb32d3739e33326a04317f8bb45125c4f99c50 100644
--- a/src/metabase/middleware/log.clj
+++ b/src/metabase/middleware/log.clj
@@ -1,52 +1,149 @@
(ns metabase.middleware.log
"Ring middleware for logging API requests/responses."
- (:require [clojure.tools.logging :as log]
+ (:require [clojure.core.async :as a]
+ [clojure.string :as str]
+ [clojure.tools.logging :as log]
[metabase
[server :as server]
[util :as u]]
+ [metabase.async.util :as async.u]
[metabase.middleware.util :as middleware.u]
[metabase.util
[date :as du]
[i18n :refer [trs]]]
[toucan.db :as db])
- (:import org.eclipse.jetty.util.thread.QueuedThreadPool))
-
-(def ^:private jetty-stats-coll
- (juxt :min-threads :max-threads :busy-threads :idle-threads :queue-size))
-
-(defn- jetty-stats []
- (when-let [jetty-server (server/instance)]
- (let [^QueuedThreadPool pool (.getThreadPool jetty-server)]
- {:min-threads (.getMinThreads pool)
- :max-threads (.getMaxThreads pool)
- :busy-threads (.getBusyThreads pool)
- :idle-threads (.getIdleThreads pool)
- :queue-size (.getQueueSize pool)})))
-
-(defn- log-response [{:keys [uri request-method]} {:keys [status body]} elapsed-time db-call-count]
- (let [log-error #(log/error %) ; these are macros so we can't pass by value :sad:
- log-debug #(log/debug %)
- log-warn #(log/warn %)
- ;; stats? here is to avoid incurring the cost of collecting the Jetty stats and concatenating the extra
- ;; strings when they're just going to be ignored. This is automatically handled by the macro , but is bypassed
- ;; once we wrap it in a function
- [error? color log-fn stats?] (cond
- (>= status 500) [true 'red log-error false]
- (= status 403) [true 'red log-warn false]
- (>= status 400) [true 'red log-debug false]
- :else [false 'green log-debug true])]
- (log-fn (str (apply u/format-color color
- (str "%s %s %d (%s) (%d DB calls)."
- (when stats?
- " Jetty threads: %s/%s (%s busy, %s idle, %s queued) (%d total active threads)"))
- (.toUpperCase (name request-method)) uri status elapsed-time db-call-count
- (when stats?
- (conj (vec (jetty-stats-coll (jetty-stats)))
- (Thread/activeCount))))
- ;; only print body on error so we don't pollute our environment by over-logging
- (when (and error?
- (or (string? body) (coll? body)))
- (str "\n" (u/pprint-to-str body)))))))
+ (:import clojure.core.async.impl.channels.ManyToManyChannel
+ org.eclipse.jetty.util.thread.QueuedThreadPool))
+
+;; To simplify passing large amounts of arguments around most functions in this namespace take an "info" map that
+;; looks like
+;;
+;; {:request ..., :response ..., :start-time ..., :call-count-fn ...}
+;;
+;; This map is created in `log-api-call` at the bottom of this namespace.
+
+;;; +----------------------------------------------------------------------------------------------------------------+
+;;; | Getting & Formatting Request/Response Info |
+;;; +----------------------------------------------------------------------------------------------------------------+
+
+;; These functions take parts of the info map and convert it into formatted strings.
+
+(defn- format-status-info [{:keys [async-status], {:keys [request-method uri]} :request, {:keys [status]} :response}]
+ (str
+ (format "%s %s %d" (str/upper-case (name request-method)) uri status)
+ (when async-status
+ (format " [ASYNC: %s]" async-status))))
+
+(defn- format-performance-info [{:keys [start-time call-count-fn]}]
+ (let [elapsed-time (du/format-nanoseconds (- (System/nanoTime) start-time))
+ db-calls (call-count-fn)]
+ (format "%s (%d DB calls)" elapsed-time db-calls)))
+
+(defn- format-threads-info [{:keys [include-stats?]}]
+ (str
+ (when-let [^QueuedThreadPool pool (some-> (server/instance) .getThreadPool)]
+ (format "Jetty threads: %s/%s (%s busy, %s idle, %s queued) "
+ (.getMinThreads pool)
+ (.getMaxThreads pool)
+ (.getBusyThreads pool)
+ (.getIdleThreads pool)
+ (.getQueueSize pool)))
+ (format "(%d total active threads)" (Thread/activeCount))))
+
+(defn- format-error-info [{{:keys [body]} :response} {:keys [error?]}]
+ (when (and error?
+ (or (string? body) (coll? body)))
+ (str "\n" (u/pprint-to-str body))))
+
+(defn- format-info [info opts]
+ (str/join " " (filter some? [(format-status-info info)
+ (format-performance-info info)
+ (format-threads-info opts)
+ (format-error-info info opts)])))
+
+
+;;; +----------------------------------------------------------------------------------------------------------------+
+;;; | Logging the Info |
+;;; +----------------------------------------------------------------------------------------------------------------+
+
+;; `log-info` below takes an info map and actually writes the log message, using the format functions from the section
+;; above to create the combined message.
+
+;; `log-options` determines som other formating options, such as the color of the message. The first logger out of the
+;; list below whose `:status-pred` is true will be used to log the API request/response.
+;;
+;; `include-stats?` here is to avoid incurring the cost of collecting the Jetty stats and concatenating the extra
+;; strings when they're just going to be ignored. This is automatically handled by the macro, but is bypassed once we
+;; wrap it in a function
+(def ^:private log-options
+ [{:status-pred #(>= % 500)
+ :error? true
+ :color 'red
+ :log-fn #(log/error %)
+ :include-stats? false}
+ {:status-pred #(>= % 403)
+ :error? true
+ :color 'red
+ :log-fn #(log/warn %)
+ :include-stats? false}
+ {:status-pred #(>= % 400)
+ :error? true
+ :color 'red
+ :log-fn #(log/debug %)
+ :include-stats? false}
+ {:status-pred (constantly true)
+ :error? false
+ :color 'green
+ :log-fn #(log/debug %)
+ :include-stats? true}])
+
+(defn- log-info [{{:keys [status]} :response, :as info}]
+ (try
+ (let [{:keys [color log-fn], :as opts} (some #(when ((:status-pred %) status)
+ %)
+ log-options)]
+ (log-fn (u/format-color color (format-info info opts))))
+ (catch Throwable e
+ (log/error e (trs "Error logging API request")))))
+
+
+;;; +----------------------------------------------------------------------------------------------------------------+
+;;; | Async Logging |
+;;; +----------------------------------------------------------------------------------------------------------------+
+
+;; These functions call `log-info` when appropriate -- right away for non-core.async-channel responses, or after the
+;; channel closes for core.async channels.
+
+(defn- log-core-async-response
+ "For async responses that return a `core.async` channel, wait for the channel to return a response before logging the
+ API request info."
+ [{{in-chan :body, :as response} :response, :as info}]
+ ;; create a new out channel, and pipe response from `in-chan` to `out-chan` using the async util single value pipe.
+ ;; The channel returned by that function can be used to listen for either in or out channels to close
+ (let [out-chan (a/chan 1)
+ in-or-out-closed-chan (async.u/single-value-pipe in-chan out-chan)]
+ ;; [async] wait for the pipe to close the canceled/finished channel and log the API response
+ (a/go
+ (log-info (assoc info :async-status (if (a/<! in-or-out-closed-chan) "canceled" "completed"))))
+ ;; [sync] return updated response with our new body
+ (assoc response :body out-chan)))
+
+(defn- logged-response
+ "Log an API response. Returns resonse, possibly modified (i.e., core.async channels will be wrapped); this value
+ should be passed to the normal `respond` function."
+ [{{:keys [body], :as response} :response, :as info}]
+ (if (instance? ManyToManyChannel body)
+ (log-core-async-response info)
+ (do (log-info info)
+ response)))
+
+
+;;; +----------------------------------------------------------------------------------------------------------------+
+;;; | Middleware |
+;;; +----------------------------------------------------------------------------------------------------------------+
+
+;; Actual middleware. Determines whether request should be logged, and, if so, creates the info dictionary and hands
+;; off to functions above.
(defn- should-log-request? [{:keys [uri], :as request}]
;; don't log calls to /health or /util/logs because they clutter up the logs (especially the window in admin) with
@@ -62,12 +159,10 @@
;; non-API call or health or logs call, don't log it
(handler request respond raise)
;; API call, log info about it
- (let [start-time (System/nanoTime)]
- (db/with-call-counting [call-count]
- (let [respond (fn [response]
- (try
- (log-response request response (du/format-nanoseconds (- (System/nanoTime) start-time)) (call-count))
- (catch Throwable e
- (log/error e (trs "Error logging API request"))))
- (respond response))]
- (handler request respond raise)))))))
+ (db/with-call-counting [call-count-fn]
+ (let [info {:request request
+ :start-time (System/nanoTime)
+ :call-count-fn call-count-fn}
+ response->info #(assoc info :response %)
+ respond (comp respond logged-response response->info)]
+ (handler request respond raise))))))
diff --git a/src/metabase/query_processor.clj b/src/metabase/query_processor.clj
index 4794a3fbead20f13003a7fa24845a68537be8ba6..74b1c16afda6978e2430c9082be795aeeb738872 100644
--- a/src/metabase/query_processor.clj
+++ b/src/metabase/query_processor.clj
@@ -300,7 +300,10 @@
(throw (ex-info (str (tru "Invalid response from database driver. No :status provided."))
query-result)))
(when (= :failed (:status query-result))
- (log/warn (u/pprint-to-str 'red query-result))
+ (if (= InterruptedException (:class query-result))
+ (log/info (trs "Query canceled"))
+ (log/warn (trs "Query failure")
+ (u/pprint-to-str 'red query-result)))
(throw (ex-info (str (get query-result :error (tru "General error")))
query-result))))
@@ -341,11 +344,8 @@
(let [result (process-query query)]
(assert-query-status-successful result)
(save-and-return-successful-query! query-execution result))
+ ;; canceled query
(catch Throwable e
- (log/warn (u/format-color 'red (trs "Query failure")
- (.getMessage e)
- "\n"
- (u/pprint-to-str (u/filtered-stacktrace e))))
(save-and-return-failed-query! query-execution e)))))
(s/defn ^:private assoc-query-info [query, options :- mbql.s/Info]