a bit more logging cleanup

project.clj

@@ -80,7 +80,8 @@
                               "-Xmx2048m"                             ; hard limit of 2GB so we stop hitting the 4GB container limit on CircleCI
                               "-XX:+CMSClassUnloadingEnabled"         ; let Clojure's dynamically generated temporary classes be GC'ed from PermGen
                               "-XX:+UseConcMarkSweepGC"]}             ; Concurrent Mark Sweep GC needs to be used for Class Unloading (above)
-             :expectations {:injections [(require 'metabase.test-setup)]
+             :expectations {:global-vars {*warn-on-reflection* false}
+                            :injections [(require 'metabase.test-setup)]
                             :resource-paths ["test_resources"]
                             :env {:mb-test-setting-1 "ABCDEFG"}
                             :jvm-opts ["-Dmb.db.in.memory=true"

src/metabase/db.clj

@@ -95,7 +95,6 @@
   [& {:keys [auto-migrate]
       :or {auto-migrate true}}]
   (reset! setup-db-has-been-called? true)
-  (log/info "Setting up DB specs...")
 
   ;; Test DB connection and throw exception if we have any troubles connecting
   (log/info "Verifying Database Connection ...")

src/metabase/driver.clj

@@ -125,7 +125,7 @@
   (let [-sync-database! (u/runtime-resolved-fn 'metabase.driver.sync 'sync-database!)] ; these need to be resolved at runtime to avoid circular deps
     (fn [database]
       {:pre [(map? database)]}
-      (time (-sync-database! (engine->driver (:engine database)) database)))))
+      (-sync-database! (engine->driver (:engine database)) database))))
 
 (def ^{:arglists '([table])} sync-table!
   "Sync a `Table` and its `Fields`."
@@ -183,10 +183,8 @@
           (when (= :failed (:status query-result))
             (throw (Exception. ^String (get query-result :error "general error"))))
           (query-complete query-execution query-result))
-        (catch Exception ex
-          (log/warn ex)
-          (.printStackTrace ex)
-          (query-fail query-execution (.getMessage ex)))))))
+        (catch Exception e
+          (query-fail query-execution (.getMessage e)))))))
 
 (defn query-fail
   "Save QueryExecution state and construct a failed query response"

src/metabase/driver/query_processor.clj

@@ -41,7 +41,6 @@
   (fn [query]
     (try (qp query)
          (catch Throwable e
-           (.printStackTrace e)
            {:status     :failed
             :error      (.getMessage e)
             :stacktrace (u/filtered-stacktrace e)

src/metabase/driver/sync.clj

@@ -43,39 +43,41 @@
             *sel-disable-logging* true]
     (sync-in-context driver database
       (fn []
-        (log/info (u/format-color 'magenta "Syncing %s database '%s'..." (name (:engine database)) (:name database)))
-
-        (let [active-table-names (active-table-names driver database)
-              table-name->id     (sel :many :field->id [Table :name] :db_id (:id database) :active true)]
-          (assert (set? active-table-names) "active-table-names should return a set.")
-          (assert (every? string? active-table-names) "active-table-names should return the names of Tables as *strings*.")
-
-          ;; First, let's mark any Tables that are no longer active as such.
-          ;; These are ones that exist in table-name->id but not in active-table-names.
-          (doseq [[table-name table-id] table-name->id]
-            (when-not (contains? active-table-names table-name)
-              (upd Table table-id :active false)
-              (log/info (u/format-color 'cyan "Marked table %s.%s as inactive." (:name database) table-name))
-
-              ;; We need to mark driver Table's Fields as inactive so we don't expose them in UI such as FK selector (etc.)
-              (k/update Field
-                        (k/where {:table_id table-id})
-                        (k/set-fields {:active false}))))
-
-          ;; Next, we'll create new Tables (ones that came back in active-table-names but *not* in table-name->id)
-          (let [existing-table-names (set (keys table-name->id))
-                new-table-names      (set/difference active-table-names existing-table-names)]
-            (when (seq new-table-names)
-              (log/debug (u/format-color 'blue "Found new tables: %s" new-table-names))
-              (doseq [new-table-name new-table-names]
-                (ins Table :db_id (:id database), :active true, :name new-table-name)))))
-
-        ;; Now sync the active tables
-        (->> (sel :many Table :db_id (:id database) :active true)
-             (map #(assoc % :db (delay database))) ; replace default delays with ones that reuse database (and don't require a DB call)
-             (sync-database-active-tables! driver))
-
-        (log/info (u/format-color 'magenta "Finished syncing %s database %s." (name (:engine database)) (:name database)))))))
+        (let [start-time (System/currentTimeMillis)]
+          (log/info (u/format-color 'magenta "Syncing %s database '%s'..." (name (:engine database)) (:name database)))
+
+          (let [active-table-names (active-table-names driver database)
+                table-name->id     (sel :many :field->id [Table :name] :db_id (:id database) :active true)]
+            (assert (set? active-table-names) "active-table-names should return a set.")
+            (assert (every? string? active-table-names) "active-table-names should return the names of Tables as *strings*.")
+
+            ;; First, let's mark any Tables that are no longer active as such.
+            ;; These are ones that exist in table-name->id but not in active-table-names.
+            (doseq [[table-name table-id] table-name->id]
+              (when-not (contains? active-table-names table-name)
+                (upd Table table-id :active false)
+                (log/info (u/format-color 'cyan "Marked table %s.%s as inactive." (:name database) table-name))
+
+                ;; We need to mark driver Table's Fields as inactive so we don't expose them in UI such as FK selector (etc.)
+                (k/update Field
+                          (k/where {:table_id table-id})
+                          (k/set-fields {:active false}))))
+
+            ;; Next, we'll create new Tables (ones that came back in active-table-names but *not* in table-name->id)
+            (let [existing-table-names (set (keys table-name->id))
+                  new-table-names      (set/difference active-table-names existing-table-names)]
+              (when (seq new-table-names)
+                (log/debug (u/format-color 'blue "Found new tables: %s" new-table-names))
+                (doseq [new-table-name new-table-names]
+                  (ins Table :db_id (:id database), :active true, :name new-table-name)))))
+
+          ;; Now sync the active tables
+          (->> (sel :many Table :db_id (:id database) :active true)
+               (map #(assoc % :db (delay database))) ; replace default delays with ones that reuse database (and don't require a DB call)
+               (sync-database-active-tables! driver))
+
+          (log/info (u/format-color 'magenta "Finished syncing %s database %s. (%d ms)" (name (:engine database)) (:name database)
+                                    (- (System/currentTimeMillis) start-time))))))))
 
 (defn sync-table!
   "Sync a *single* TABLE by running all the sync steps for it.
@@ -146,7 +148,7 @@
 
         (sync-table-fields-metadata! driver table)
         (swap! finished-tables-count inc)
-        (log/info (u/format-color 'magenta "%s Synced table '%s'." (sync-progress-meter-string @finished-tables-count tables-count) (:name table)))))))
+        (log/debug (u/format-color 'magenta "%s Synced table '%s'." (sync-progress-meter-string @finished-tables-count tables-count) (:name table)))))))
 
 
 ;; ## sync-table steps.

test/metabase/api/common/throttle_test.clj

@@ -99,10 +99,10 @@
     (attempt 1 :d)))
 
 ;; Check that the interal list for the throttler doesn't keep growing after throttling starts
-(expect [0 4]
+(expect [0 3]
   [(do (reset! (:attempts test-throttler) '()) ; reset it to 0
        (count @(:attempts test-throttler)))
-   (do (attempt 1000)
+   (do (attempt 10)
        (count @(:attempts test-throttler)))])
 
 ;; Check that attempts clear after the TTL

test/metabase/driver/generic_sql/native_test.clj

@@ -35,13 +35,12 @@
 ;; Check that we get proper error responses for malformed SQL
 (expect {:status :failed
          :error "Column \"ZID\" not found"}
-  (do (log/info (color/green "NOTE: The following stacktrace is expected <3"))      ; this will print a stacktrace
-      (dissoc (driver/process-query {:native   {:query "SELECT ZID FROM CHECKINS LIMIT 2;"} ; make sure people know it's to be expected
-                                     :type     :native
-                                     :database (db-id)})
-              :stacktrace
-              :query
-              :expanded-query)))
+  (dissoc (driver/process-query {:native   {:query "SELECT ZID FROM CHECKINS LIMIT 2;"} ; make sure people know it's to be expected
+                                 :type     :native
+                                 :database (db-id)})
+          :stacktrace
+          :query
+          :expanded-query))
 
 ;; Check that we're not allowed to run SQL against an H2 database with a non-admin account
 (expect "Running SQL queries against H2 databases using the default (admin) database user is forbidden."

test/metabase/test_setup.clj

@@ -79,22 +79,13 @@
 (defn test-startup
   {:expectations-options :before-run}
   []
-  (log/info "Starting up Metabase unit test runner")
-
   (log/info "Setting up test DB and running migrations...")
   (db/setup-db :auto-migrate true)
 
-  ;; add any global settings defaults
-  (metabase.models.setting/set :site-name "Metabase Test")
-
-  ;; Load the test datasets
-  (load-test-datasets)
-
-  ;; startup test web server
-  (core/start-jetty)
-
-  ;; start the task runner
-  (task/start-task-runner!))
+  (metabase.models.setting/set :site-name "Metabase Test") ; add any global settings defaults
+  (load-test-datasets)                                     ; Load the test datasets
+  (core/start-jetty)                                       ; startup test web server
+  (task/start-task-runner!))                               ; start the task runner
 
 
 (defn test-teardown