Merge pull request #2743 from metabase/fix-sql-comment-prepending

Fix prepending SQL query info comment 

resources/log4j.properties

@@ -17,6 +17,7 @@ log4j.appender.file.layout.ConversionPattern=%d [%t] %-5p%c - %m%n
 log4j.appender.metabase=metabase.logger.Appender
 
 # customizations to logging by package
+log4j.logger.com.mchange.v2.resourcepool=ERROR # c3p0 connection pools tend to log useless warnings way too often; only log actual errors
 log4j.logger.metabase=INFO
 log4j.logger.metabase.db=DEBUG
 log4j.logger.metabase.driver=DEBUG

src/metabase/driver.clj

@@ -61,9 +61,9 @@
   (date-interval [this, ^Keyword unit, ^Number amount]
     "*OPTIONAL* Return an driver-appropriate representation of a moment relative to the current moment in time. By default, this returns an `Timestamp` by calling
      `metabase.util/relative-date`; but when possible drivers should return a native form so we can be sure the correct timezone is applied. For example, SQL drivers should
-     return a Korma form to call the appropriate SQL fns:
+     return a HoneySQL form to call the appropriate SQL fns:
 
-       (date-interval (PostgresDriver.) :month 1) -> (k/raw* \"(NOW() + INTERVAL '1 month')\")")
+       (date-interval (PostgresDriver.) :month 1) -> (hsql/call :+ :%now (hsql/raw \"INTERVAL '1 month'\"))")
 
   (describe-database ^java.util.Map [this, ^DatabaseInstance database]
     "Return a map containing information that describes all of the schema settings in DATABASE, most notably a set of tables.

src/metabase/driver/bigquery.clj

@@ -341,12 +341,13 @@
   (binding [sqlqp/*query* outer-query]
     (let [honeysql-form (honeysql-form outer-query)
           sql           (honeysql-form->sql honeysql-form)]
-      {:query      (str "-- " (qp/query->remark outer-query) "\n" sql)
+      {:query      sql
        :table-name table-name
        :mbql?      true})))
 
-(defn- execute-query [{{{:keys [dataset-id]} :details, :as database} :database, {sql :query, :keys [table-name mbql?]} :native}]
-  (let [results (process-native* database sql)
+(defn- execute-query [{{{:keys [dataset-id]} :details, :as database} :database, {sql :query, :keys [table-name mbql?]} :native, :as outer-query}]
+  (let [sql     (str "-- " (qp/query->remark outer-query) "\n" sql)
+        results (process-native* database sql)
         results (if mbql?
                   (post-process-mbql dataset-id table-name results)
                   (update results :columns (partial map keyword)))]

src/metabase/driver/generic_sql/query_processor.clj

@@ -279,7 +279,7 @@
   (binding [*query* outer-query]
     (let [honeysql-form (build-honeysql-form driver outer-query)
           [sql & args]  (sql/honeysql-form->sql+args driver honeysql-form)]
-      {:query  (str "-- " (qp/query->remark outer-query) "\n" sql)
+      {:query  sql
        :params args})))
 
 
@@ -294,8 +294,8 @@
 
 (defn- run-query
   "Run the query itself."
-  [{sql :query, params :params} connection]
-  (let [sql              (hx/unescape-dots sql)
+  [{sql :query, params :params, remark :remark} connection]
+  (let [sql              (str "-- " remark "\n" (hx/unescape-dots sql))
         statement        (into [sql] params)
         [columns & rows] (jdbc/query connection statement, :identifiers identity, :as-arrays? true)]
     {:rows    (or rows [])
@@ -323,12 +323,13 @@
 
 (defn execute-query
   "Process and run a native (raw SQL) QUERY."
-  [driver {:keys [database settings], query :native}]
-  (do-with-try-catch
-    (fn []
-      (let [db-connection (sql/db->jdbc-connection-spec database)]
-        (jdbc/with-db-transaction [transaction-connection db-connection]
-          (do-with-auto-commit-disabled transaction-connection
-            (fn []
-              (maybe-set-timezone! driver settings transaction-connection)
-              (run-query query transaction-connection))))))))
+  [driver {:keys [database settings], query :native, :as outer-query}]
+  (let [query (assoc query :remark (qp/query->remark outer-query))]
+    (do-with-try-catch
+      (fn []
+        (let [db-connection (sql/db->jdbc-connection-spec database)]
+          (jdbc/with-db-transaction [transaction-connection db-connection]
+            (do-with-auto-commit-disabled transaction-connection
+              (fn []
+                (maybe-set-timezone! driver settings transaction-connection)
+                (run-query query transaction-connection)))))))))

src/metabase/query_processor.clj

@@ -451,8 +451,7 @@
 (defn query->remark
   "Genarate an approparite REMARK to be prepended to a query to give DBAs additional information about the query being executed.
    See documentation for `mbql->native` and [issue #2386](https://github.com/metabase/metabase/issues/2386) for more information."
-  ^String [{{:keys [executed-by uuid query-hash query-type]} :info, :as info}]
-  {:pre [(map? info)]}
+  ^String [{{:keys [executed-by uuid query-hash query-type], :as info} :info}]
   (format "Metabase:: userID: %s executionID: %s queryType: %s queryHash: %s" executed-by uuid query-type query-hash))
 
 (defn- run-query
@@ -590,13 +589,13 @@
         query           (assoc query :info {:executed-by executed_by
                                             :uuid        query-uuid
                                             :query-hash  (hash query)
-                                            :query-type (if (mbql-query? query) "MBQL" "native")})]
+                                            :query-type  (if (mbql-query? query) "MBQL" "native")})]
     (try
       (let [result (process-query query)]
         (assert-valid-query-result result)
         (query-complete query-execution result))
       (catch Throwable e
-        (log/error (u/format-color 'red "Query failure: %s" (.getMessage e)))
+        (log/error (u/format-color 'red "Query failure: %s\n%s" (.getMessage e) (u/pprint-to-str (u/filtered-stacktrace e))))
         (query-fail query-execution (.getMessage e))))))
 
 (defn query-fail

src/metabase/sync_database/analyze.clj

@@ -40,7 +40,7 @@
   (try
     (queries/table-row-count table)
     (catch Throwable e
-      (log/error (u/format-color 'red "Unable to determine row_count for '%s': %s" (:name table) (.getMessage e))))))
+      (log/error (u/format-color 'red "Unable to determine row count for '%s': %s\n%s" (:name table) (.getMessage e) (u/pprint-to-str (u/filtered-stacktrace e)))))))
 
 (defn test-for-cardinality?
   "Should FIELD should be tested for cardinality?"

src/metabase/sync_database/interface.clj

@@ -34,7 +34,7 @@
 
 (def DescribeTableFKs
   "Schema for the expected output of `describe-table-fks`."
-  #{{:fk-column-name   schema/Str
-     :dest-table       {:name   schema/Str
-                        :schema (schema/maybe schema/Str)}
-     :dest-column-name schema/Str}})
+  (schema/maybe #{{:fk-column-name   schema/Str
+                   :dest-table       {:name   schema/Str
+                                      :schema (schema/maybe schema/Str)}
+                   :dest-column-name schema/Str}}))

test/metabase/api/dataset_test.clj

 (ns metabase.api.dataset-test
   "Unit tests for /api/dataset endpoints."
-  (:require [expectations :refer :all]
+  (:require [clojure.string :as s]
+            [expectations :refer :all]
             [metabase.api.dataset :refer [dataset-query-api-constraints]]
             [metabase.db :as db]
             (metabase.models [card :refer [Card]]
@@ -13,14 +14,14 @@
 
 (defn user-details [user]
   (tu/match-$ user
-              {:email $
-               :date_joined $
-               :first_name $
-               :last_name $
-               :last_login $
-               :is_superuser $
-               :is_qbnewb $
-               :common_name $}))
+    {:email        $
+     :date_joined  $
+     :first_name   $
+     :last_name    $
+     :last_login   $
+     :is_superuser $
+     :is_qbnewb    $
+     :common_name  $}))
 
 (defn remove-ids-and-boolean-timestamps [m]
   (let [f (fn [v]
@@ -91,6 +92,7 @@
     [(format-response result)
      (format-response (QueryExecution :uuid (:uuid result)))]))
 
+
 ;; Even if a query fails we still expect a 200 response from the api
 (expect
   ;; the first result is directly from the api call
@@ -100,7 +102,7 @@
                                :cols    []}
                 :row_count    0
                 :status       "failed"
-                :error        "Syntax error in SQL statement \"FOOBAR[*] \"; expected \"FROM, {\""
+                :error        true
                 :id           true
                 :uuid         true
                 :json_query   {:database    (id)
@@ -117,11 +119,15 @@
                 :version     0
                 :raw_query   ""
                 :result_rows 0))])
-  (let [result ((user->client :rasta) :post 200 "dataset" {:database (id)
-                                                           :type     "native"
-                                                           :native   {:query "foobar"}})]
-    [(format-response result)
-     (format-response (QueryExecution :uuid (:uuid result)))]))
+  ;; Error message's format can differ a bit depending on DB version and the comment we prepend to it, so check that it exists and contains the substring "Syntax error in SQL statement"
+  (let [check-error-message (fn [output]
+                              (update output :error (fn [error-message]
+                                                      (boolean (re-find #"Syntax error in SQL statement" error-message)))))
+        result              ((user->client :rasta) :post 200 "dataset" {:database (id)
+                                                                        :type     "native"
+                                                                        :native   {:query "foobar"}})]
+    [(check-error-message (format-response result))
+     (check-error-message (format-response (QueryExecution :uuid (:uuid result))))]))
 
 
 ;; GET /api/dataset/card/:id