From 6353aa07abd890340a3472c094f03d783dc9b36f Mon Sep 17 00:00:00 2001
From: Cam Saul <cammsaul@gmail.com>
Date: Tue, 2 Jul 2019 14:12:09 -0700
Subject: [PATCH] More improvements to QP debugging tools (#10288)
clean up add-settings & tests
---
src/metabase/query_processor/debug.clj | 79 +++++++++++++++----
.../middleware/add_settings.clj | 9 ++-
.../middleware/add_settings_test.clj | 53 ++++++++-----
.../query_processor_test/failure_test.clj | 3 +-
4 files changed, 102 insertions(+), 42 deletions(-)
diff --git a/src/metabase/query_processor/debug.clj b/src/metabase/query_processor/debug.clj
index 0bd00692b89..ee55e8782b7 100644
--- a/src/metabase/query_processor/debug.clj
+++ b/src/metabase/query_processor/debug.clj
@@ -1,7 +1,10 @@
(ns metabase.query-processor.debug
"Functions for debugging QP code. Enable QP debugging by binding `qp/*debug*`; the `debug-middleware` function below
wraps each middleware function for debugging purposes."
- (:require [clojure.data :as data]
+ (:require [clojure
+ [data :as data]
+ [pprint :as pprint]
+ [string :as str]]
[metabase.mbql.schema :as mbql.s]
[metabase.query-processor.middleware
[async :as async]
@@ -9,7 +12,10 @@
[metabase.util :as u]
[schema.core :as s]))
-(def ^:private ^:dynamic *timeout* 5000)
+(def ^:private ^:dynamic *timeout*
+ "Timeout (in milliseconds) for async middleware to return a response."
+ 5000)
+
;;; +----------------------------------------------------------------------------------------------------------------+
;;; | Generic Middleware Debugging Utils |
@@ -51,7 +57,8 @@
(deliver before-result <>)))]
(try
(u/prog1 ((middleware wrapped-qp) before-query)
- (when post (post (u/deref-with-timeout before-result *timeout*) <>)))
+ (when (and post (realized? before-result))
+ (post @before-result <>)))
(catch Throwable e
(rethrow "Middleware threw Exception."
{:query {:before before-query, :after after-query}, :result before-result}
@@ -124,15 +131,15 @@
(defn- print-diff [message middleware-var before after]
(when-not (= before after)
(let [[only-in-before only-in-after] (data/diff before after)]
- (println (u/format-color 'yellow (middleware-name middleware-var)) message "\n"
- "before" (u/pprint-to-str 'blue before)
- "after " (u/pprint-to-str 'green after)
- (if only-in-before
- (str "only in before: " (u/pprint-to-str 'cyan only-in-before))
- "")
- (if only-in-after
- (str "only in after: " (u/pprint-to-str 'magenta only-in-after))
- "")))))
+ (println
+ (str
+ (u/format-color 'yellow (middleware-name middleware-var)) " " message "\n"
+ "before:\n" (u/pprint-to-str 'blue before)
+ "after:\n" (u/pprint-to-str 'green after)
+ (when only-in-before
+ (str "only in before:\n" (u/pprint-to-str 'cyan only-in-before)))
+ (when only-in-after
+ (str "only in after:\n" (u/pprint-to-str 'magenta only-in-after))))))))
(defn- validate-query [middleware-var after-query]
;; mbql->native is allowed to have both a `:query` and a `:native` key for whatever reason
@@ -148,10 +155,46 @@
;; TODO - validate results as well
)
-(defn- debug-exception [middleware-var e]
- (println (u/format-color 'red "Exception in %s middleware" (middleware-name middleware-var)))
- (println (u/pprint-to-str 'red e))
- (throw e))
+(defn- exception-causes-seq
+ "Sequence of all causes of `e`. Does not include `e` itself."
+ [e]
+ (rest (take-while some? (iterate #(some-> ^Throwable % .getCause) e))))
+
+(defn- ex-data-excluding-schema-errors [e]
+ (let [data (ex-data e)]
+ (when-not (= (:type data) :schema.core/error)
+ data)))
+
+(defn- format-exception [^Throwable e]
+ {:type (class e)
+ :cause (.getMessage e)
+ :data (ex-data-excluding-schema-errors e)
+ :via (vec (for [^Throwable cause (exception-causes-seq e)]
+ {:type (class cause)
+ :message (.getMessage cause)
+ :data (ex-data-excluding-schema-errors cause)
+ :at (first (seq (.getStackTrace e)))}))
+ :trace (vec
+ (for [frame (seq (.getStackTrace e))
+ :let [frame (str frame)]
+ :when (and (not (str/starts-with? frame "clojure"))
+ (not (str/starts-with? frame "metabase.query_processor.debug")))]
+ frame))})
+
+(def ^:private already-logged-exception
+ "An Exception that we can use to signify that we don't need to do any more logging (because we've already logged the
+ Exception somewhere else.)"
+ (Exception. "[Already logged]"))
+
+(defn- debug-exception [middleware-var, ^Throwable e]
+ ;; only log Exceptions the first time we see them
+ (if (some (partial identical? already-logged-exception)
+ (cons e (exception-causes-seq e)))
+ (throw e)
+ (do
+ (println (u/format-color 'red "Exception in %s middleware" (middleware-name middleware-var)))
+ (pprint/pprint (format-exception e))
+ (throw already-logged-exception))))
(defn debug-middleware
@@ -167,7 +210,9 @@
;; don't try to wrap `async->sync` for debugging because it switches from async to sync right in the middle of
;; things which is much to hairy to try to deal with in the code above. (It also doesn't modify the query or results
;; anyway.)
- (if (= middleware-var #'async/async->sync)
+ ;;
+ ;; `async-setup` also produces weird unhelpful logging so skip that too.
+ (if (#{#'async/async->sync #'async/async-setup} middleware-var)
((var-get middleware-var) qp)
(debug-with-fns
{:pre (partial debug-pre middleware-var)
diff --git a/src/metabase/query_processor/middleware/add_settings.clj b/src/metabase/query_processor/middleware/add_settings.clj
index 3ec06c9bed1..bac20c12b1c 100644
--- a/src/metabase/query_processor/middleware/add_settings.clj
+++ b/src/metabase/query_processor/middleware/add_settings.clj
@@ -1,11 +1,12 @@
(ns metabase.query-processor.middleware.add-settings
"Middleware for adding a `:settings` map to a query before it is processed."
- (:require [medley.core :as m]
+ (:require [metabase.driver :as driver]
[metabase.driver.util :as driver.u]))
-(defn- add-settings* [{:keys [driver] :as query}]
- (let [settings {:report-timezone (driver.u/report-timezone-if-supported driver)}]
- (assoc query :settings (m/filter-vals (complement nil?) settings))))
+(defn- add-settings* [query]
+ (if-let [report-timezone (driver.u/report-timezone-if-supported driver/*driver*)]
+ (assoc-in query [:settings :report-timezone] report-timezone)
+ query))
(defn add-settings
"Adds the `:settings` map to the query which can contain any fixed properties that would be useful at execution time.
diff --git a/test/metabase/query_processor/middleware/add_settings_test.clj b/test/metabase/query_processor/middleware/add_settings_test.clj
index cacd75516ba..ae19fb58059 100644
--- a/test/metabase/query_processor/middleware/add_settings_test.clj
+++ b/test/metabase/query_processor/middleware/add_settings_test.clj
@@ -1,26 +1,41 @@
(ns metabase.query-processor.middleware.add-settings-test
(:require [expectations :refer [expect]]
[metabase.driver :as driver]
- [metabase.models.setting :as setting]
- [metabase.query-processor.middleware.add-settings :as add-settings]))
+ [metabase.query-processor.middleware.add-settings :as add-settings]
+ [metabase.test.util :as tu]))
-(driver/register! ::test-driver, :abstract? true)
+(driver/register! ::timezone-driver, :abstract? true)
-(defmethod driver/supports? [::test-driver :set-timezone] [_ _] true)
+(defmethod driver/supports? [::timezone-driver :set-timezone] [_ _] true)
+(driver/register! ::no-timezone-driver, :abstract? true)
+
+(defmethod driver/supports? [::no-timezone-driver :set-timezone] [_ _] false)
+
+(defn- add-settings [driver query]
+ (driver/with-driver driver
+ ((add-settings/add-settings identity) query)))
+
+;; no `report-timezone` set = query should not be changed
+(expect
+ {}
+ (tu/with-temporary-setting-values [report-timezone nil]
+ (add-settings ::timezone-driver {})))
+
+;; `report-timezone` is an empty string = query should not be changed
+(expect
+ {}
+ (tu/with-temporary-setting-values [report-timezone ""]
+ (add-settings ::timezone-driver {})))
+
+;; if the timezone is something valid it should show up in the query settings
+(expect
+ {:settings {:report-timezone "US/Mountain"}}
+ (tu/with-temporary-setting-values [report-timezone "US/Mountain"]
+ (add-settings ::timezone-driver {})))
+
+;; if the driver doesn't support `:set-timezone`, query should be unchanged, even if `report-timezone` is valid
(expect
- [{:settings {}}
- {:settings {}}
- {:settings {:report-timezone "US/Mountain"}}]
- (let [original-tz (setting/get :report-timezone)
- response1 ((add-settings/add-settings identity) {:driver ::test-driver})]
- ;; make sure that if the timezone is an empty string we skip it in settings
- (setting/set! :report-timezone "")
- (let [response2 ((add-settings/add-settings identity) {:driver ::test-driver})]
- ;; if the timezone is something valid it should show up in the query settings
- (setting/set! :report-timezone "US/Mountain")
- (let [response3 ((add-settings/add-settings identity) {:driver ::test-driver})]
- (setting/set! :report-timezone original-tz)
- [(dissoc response1 :driver)
- (dissoc response2 :driver)
- (dissoc response3 :driver)]))))
+ {}
+ (tu/with-temporary-setting-values [report-timezone "US/Mountain"]
+ (add-settings ::no-timezone-driver {})))
diff --git a/test/metabase/query_processor_test/failure_test.clj b/test/metabase/query_processor_test/failure_test.clj
index d891fedc575..66279e5f213 100644
--- a/test/metabase/query_processor_test/failure_test.clj
+++ b/test/metabase/query_processor_test/failure_test.clj
@@ -21,8 +21,7 @@
:query {:source-table (data/id :venues)
:fields [[:datetime-field [:field-id (data/id :venues :id)] :month]]
:limit qp.i/absolute-max-results}
- :driver :h2
- :settings {}})
+ :driver :h2})
(def ^:private bad-query:native
{:query (str "SELECT parsedatetime(formatdatetime(\"PUBLIC\".\"VENUES\".\"ID\", 'yyyyMM'), 'yyyyMM') AS \"ID\" "
--
GitLab