Fix DockerHub build & better Pulse render error logging (#12543)

* Change font registration to run on first Pulse PNG render rather than at launch.
    * This will improve startup times slightly . 
    * This was causing DockerHub builds for `metabase-head` to fail 
because the stage 1 "builder" image did not have `ttf-dejavu` and `fontconfig` installed (the builder was running in to #12223).
     * This will resolve issues discussed in #12223 where Metabase fails to launch when running on a "headless" JVM Docker image (i.e., one without AWT libraries) or when we run into the infamous font issues. We still won't be able to render Pulses, but Metabase without Pulses is slightly preferable to no Metabase at all
*  Improved error messages & logging when Pulse rendering fails. Unfortunately, if the AWT classes are unavailable/broken in the JVM there is no way we can render Pulses given our current reliance on it. The best we can do is explain the situation and point people in the right direction. The new error message explains the situation and points people to #7986 for more details and workarounds.  As such, I am going to close #7986 because we cannot fix the underlying issue itself so the best we do is handle it better.
*  Refactor tests in `metabase.api.pulse-test`
*  Add tests for `GET /api/pulse/preview_card/:id`
*  Include entire Exception chain in 500 responses
*  Fix font registration logic not cleaning up `InputStream`s when done with them, wasting memory
*  Minor Dockerfile tweaks

Dockerfile

@@ -16,8 +16,9 @@ ENV LC_CTYPE en_US.UTF-8
 # yarn:  frontend building
 # make:    backend building
 # gettext: translations
+# java-cacerts: installs updated cacerts to /etc/ssl/certs/java/cacerts
 
-RUN apk add --update coreutils bash yarn git wget make gettext
+RUN apk add --update coreutils bash yarn git wget make gettext java-cacerts
 
 # lein:    backend dependencies and building
 ADD https://raw.github.com/technomancy/leiningen/stable/bin/lein /usr/local/bin/lein
@@ -40,9 +41,6 @@ ADD . .
 # build the app
 RUN bin/build
 
-# install updated cacerts to /etc/ssl/certs/java/cacerts
-RUN apk add --update java-cacerts
-
 # import AWS RDS cert into /etc/ssl/certs/java/cacerts
 ADD https://s3.amazonaws.com/rds-downloads/rds-combined-ca-bundle.pem .
 RUN keytool -noprompt -import -trustcacerts -alias aws-rds \

bin/docker/Dockerfile

@@ -4,7 +4,7 @@ ENV FC_LANG en-US
 ENV LC_CTYPE en_US.UTF-8
 
 # dependencies
-RUN apk add --no-cache bash ttf-dejavu fontconfig
+RUN apk add --update --no-cache bash ttf-dejavu fontconfig
 
 # add Metabase jar
 COPY ./metabase.jar /app/

src/metabase/api/pulse.clj

@@ -91,7 +91,6 @@
   (let [pulse-before-update (api/write-check Pulse id)]
     (check-card-read-permissions cards)
     (collection/check-allowed-to-change-collection pulse-before-update pulse-updates)
-
     (db/transaction
       ;; If the collection or position changed with this update, we might need to fixup the old and/or new collection,
       ;; depending on what changed.
@@ -100,7 +99,7 @@
       (pulse/update-pulse!
        (assoc (select-keys pulse-updates [:name :cards :channels :skip_if_empty :collection_id :collection_position
                                           :archived])
-         :id id))))
+              :id id))))
   ;; return updated Pulse
   (pulse/retrieve-pulse id))
 

src/metabase/middleware/exceptions.clj

@@ -4,7 +4,6 @@
             [clojure.string :as str]
             [clojure.tools.logging :as log]
             [metabase.middleware.security :as mw.security]
-            [metabase.util :as u]
             [metabase.util.i18n :as ui18n :refer [trs]])
   (:import java.sql.SQLException
            org.eclipse.jetty.io.EofException))
@@ -56,13 +55,13 @@
                      status-code
                      (str message)
 
-                     ;; Otherwise it's a 500. Return a body that includes exception & filtered
-                     ;; stacktrace for debugging purposes
+                     ;; Otherwise it's a 500. Return the full Exception for debugging purposes
                      :else
-                     (assoc other-info
-                            :message    message
-                            :type       (class e)
-                            :stacktrace (u/filtered-stacktrace e)))]
+                     (merge
+                      other-info
+                      (Throwable->map e)
+                      {:message message
+                       :type    (class e)}))]
 
     {:status  (or status-code 500)
      :headers (mw.security/security-headers)

src/metabase/pulse/render/png.clj

@@ -12,6 +12,7 @@
             [metabase.pulse.render
              [common :as common]
              [style :as style]]
+            [metabase.util.i18n :refer [trs]]
             [schema.core :as s])
   (:import cz.vutbr.web.css.MediaSpec
            java.awt.Dimension
@@ -24,29 +25,33 @@
            org.fit.cssbox.layout.BrowserCanvas
            org.w3c.dom.Document))
 
+(defn- register-font! [filename]
+  (with-open [is (io/input-stream (io/resource filename))]
+    (.registerFont (java.awt.GraphicsEnvironment/getLocalGraphicsEnvironment)
+                   (java.awt.Font/createFont java.awt.Font/TRUETYPE_FONT is))))
 
-(defonce
-  ^{:doc     "Makes custom fonts available to Java so that CSSBox can render them"
-    :private true}
-  register-fonts
-  (delay (doseq [weight ["regular" "700" "900"]]
-           (.registerFont (java.awt.GraphicsEnvironment/getLocalGraphicsEnvironment)
-                          (java.awt.Font/createFont
-                           java.awt.Font/TRUETYPE_FONT
-                           (-> (format "frontend_client/app/fonts/lato-v16-latin/lato-v16-latin-%s.ttf" weight)
-                               io/resource
-                               io/input-stream))))))
+(defn- register-fonts! []
+  (try
+    (doseq [weight ["regular" "700" "900"]]
+      (register-font! (format "frontend_client/app/fonts/lato-v16-latin/lato-v16-latin-%s.ttf" weight)))
+    (catch Throwable e
+      (let [message (str (trs "Error registering fonts: Metabase will not be able to send Pulses.")
+                         " "
+                         (trs "This is a known issue with certain JVMs. See {0} and for more details."
+                              "https://github.com/metabase/metabase/issues/7986"))]
+        (log/error e message)
+        (throw (ex-info message {} e))))))
 
-(when-not *compile-files*
-  @register-fonts)
+(defonce ^{:doc      "Makes custom fonts available to Java so that CSSBox can render them."
+           :private  true
+           :arglists '([])} register-fonts-if-needed!
+  (let [register!* (delay (register-fonts!))]
+    (fn []
+      @register!*)))
 
 (defn- write-image!
   [^BufferedImage image, ^String format-name, ^ByteArrayOutputStream output-stream]
-  (try
-    (ImageIO/write image format-name output-stream)
-    (catch javax.imageio.IIOException iioex
-      (log/error iioex "Error writing image to output stream")
-      (throw iioex))))
+  (ImageIO/write image format-name output-stream))
 
 (defn- dom-analyzer
   ^DOMAnalyzer [^Document doc, ^StreamDocumentSource doc-source, ^Dimension window-size]
@@ -76,6 +81,7 @@
 
 (defn- render-to-png!
   [^String html, ^ByteArrayOutputStream os, width]
+  (register-fonts-if-needed!)
   (with-open [is (ByteArrayInputStream. (.getBytes html StandardCharsets/UTF_8))]
     (let [doc-source     (StreamDocumentSource. is nil "text/html; charset=utf-8")
           doc            (.parse (DefaultDOMSource. doc-source))
@@ -86,11 +92,15 @@
   "Render the Hiccup HTML `content` of a Pulse to a PNG image, returning a byte array."
   [{:keys [content]} :- common/RenderedPulseCard
    width]
-  (let [html (html [:html [:body {:style (style/style
-                                          {:margin           0
-                                           :padding          0
-                                           :background-color :white})}
-                           content]])]
-    (with-open [os (ByteArrayOutputStream.)]
-      (render-to-png! html os width)
-      (.toByteArray os))))
+  (try
+    (let [html (html [:html [:body {:style (style/style
+                                            {:margin           0
+                                             :padding          0
+                                             :background-color :white})}
+                             content]])]
+      (with-open [os (ByteArrayOutputStream.)]
+        (render-to-png! html os width)
+        (.toByteArray os)))
+    (catch Throwable e
+      (log/error e (trs "Error rendering Pulse"))
+      (throw e))))

test/metabase/async/api_response_test.clj

 (ns metabase.async.api-response-test
   (:require [cheshire.core :as json]
             [clojure.core.async :as a]
+            [clojure.test :refer :all]
             [expectations :refer [expect]]
             [metabase.async.api-response :as async-response]
             [metabase.test.util.async :as tu.async]
-            [ring.core.protocols :as ring.protocols])
+            [ring.core.protocols :as ring.protocols]
+            [schema.core :as s])
   (:import [java.io ByteArrayOutputStream Closeable]))
 
 (def ^:private long-timeout-ms
@@ -48,13 +50,7 @@
   true)
 
 (defn- os->response [^ByteArrayOutputStream os]
-  (some->
-   os
-   .toString
-   (json/parse-string keyword)
-   ((fn [response]
-      (cond-> response
-        (:stacktrace response) (update :stacktrace (partial every? string?)))))))
+  (some-> os .toString (json/parse-string keyword)))
 
 
 ;;; ------------------------------ Normal responses: message sent to the input channel -------------------------------
@@ -98,43 +94,37 @@
 
 ;;; ----------------------------------------- Input-chan closed unexpectedly -----------------------------------------
 
-;; if we close input-channel prematurely, output-channel should get closed
-(expect
-  (tu.async/with-chans [input-chan]
-    (with-response [{:keys [output-chan]} input-chan]
-      ;; output-chan may or may not get the InterruptedException written to it -- it's a race condition -- we're just
-      ;; want to make sure it closes
-      (a/close! input-chan)
-      (not= ::tu.async/timed-out (tu.async/wait-for-result output-chan)))))
-
-;; ...as should the output stream
-(expect
-  (tu.async/with-chans [input-chan]
-    (with-response [{:keys [os-closed-chan]} input-chan]
-      (a/close! input-chan)
-      (wait-for-close os-closed-chan))))
-
-;; An error should be written to the output stream
-(expect
-  {:message     "Input channel unexpectedly closed."
-   :type        "class java.lang.InterruptedException"
-   :_status 500
-   :stacktrace  true}
-  (tu.async/with-chans [input-chan]
-    (with-response [{:keys [os os-closed-chan]} input-chan]
-      (a/close! input-chan)
-      (wait-for-close os-closed-chan)
-      (os->response os))))
+(deftest input-chan-closed-unexpectedly-test
+  (testing "When input-channel is closed prematurely"
+    (tu.async/with-chans [input-chan]
+      (with-response [{:keys [os output-chan os-closed-chan]} input-chan]
+        (a/close! input-chan)
+        (testing "output-channel should get closed"
+          ;; output-chan may or may not get the InterruptedException written to it -- it's a race condition -- we're just
+          ;; want to make sure it closes
+          (not= ::tu.async/timed-out (tu.async/wait-for-result output-chan))
+
+          (testing "...as should the output stream"
+            (is (= true
+                   (wait-for-close os-closed-chan)))))
+
+        (testing "An error should be written to the output stream"
+          (is (schema= {:message (s/eq "Input channel unexpectedly closed.")
+                        :type    (s/eq "class java.lang.InterruptedException")
+                        :_status (s/eq 500)
+                        :trace   s/Any
+                        s/Any    s/Any}
+                       (os->response os))))))))
 
 
 ;;; ------------------------------ Output-chan closed early (i.e. API request canceled) ------------------------------
 
 ;; If output-channel gets closed (presumably because the API request is canceled), input-chan should also get closed
 (expect
-  (tu.async/with-chans [input-chan]
-    (with-response [{:keys [output-chan]} input-chan]
-      (a/close! output-chan)
-      (wait-for-close input-chan))))
+ (tu.async/with-chans [input-chan]
+   (with-response [{:keys [output-chan]} input-chan]
+     (a/close! output-chan)
+     (wait-for-close input-chan))))
 
 ;; if output chan gets closed, output-stream should also get closed
 (expect
@@ -156,43 +146,42 @@
 
 ;;; --------------------------------------- input chan message is an Exception ---------------------------------------
 
-;; If the message sent to input-chan is an Exception an appropriate response should be generated
-(expect
-  {:message "Broken", :type "class java.lang.Exception", :stacktrace true, :_status 500}
-  (tu.async/with-chans [input-chan]
-    (with-response [{:keys [os os-closed-chan]} input-chan]
-      (a/>!! input-chan (Exception. "Broken"))
-      (wait-for-close os-closed-chan)
-      (os->response os))))
-
-
-;;; ------------------------------------------ input-chan never written to -------------------------------------------
-
-;; If we write a bad API endpoint and return a channel but never write to it, the request should be canceled after
-;; `absolute-max-keepalive-ms`
-(expect
-  {:message     "No response after waiting 500.0 ms. Canceling request."
-   :type        "class java.util.concurrent.TimeoutException"
-   :_status 500
-   :stacktrace  true}
-  (with-redefs [async-response/absolute-max-keepalive-ms 500]
+(deftest input-change-message-is-exception-test
+  (testing "If the message sent to input-chan is an Exception an appropriate response should be generated"
     (tu.async/with-chans [input-chan]
       (with-response [{:keys [os os-closed-chan]} input-chan]
+        (a/>!! input-chan (Exception. "Broken"))
         (wait-for-close os-closed-chan)
-        (os->response os)))))
+        (is (schema= {:message  (s/eq "Broken")
+                      :type     (s/eq "class java.lang.Exception")
+                      :trace    s/Any
+                      :_status  (s/eq 500)
+                      s/Keyword s/Any}
+                     (os->response os)))))))
 
-;; input chan should get closed
-(expect
-  (with-redefs [async-response/absolute-max-keepalive-ms 500]
-    (tu.async/with-chans [input-chan]
-      (with-response [{:keys [os-closed-chan]} input-chan]
-        (wait-for-close os-closed-chan)
-        (wait-for-close input-chan)))))
 
-;; output chan should get closed
-(expect
-  (with-redefs [async-response/absolute-max-keepalive-ms 500]
-    (tu.async/with-chans [input-chan]
-      (with-response [{:keys [output-chan os-closed-chan]} input-chan]
-        (wait-for-close os-closed-chan)
-        (wait-for-close output-chan)))))
+;;; ------------------------------------------ input-chan never written to -------------------------------------------
+
+(deftest input-chan-never-written-to-test
+  (testing (str "If we write a bad API endpoint and return a channel but never write to it, the request should be "
+                "canceled after `absolute-max-keepalive-ms`")
+    (with-redefs [async-response/absolute-max-keepalive-ms 50]
+      (tu.async/with-chans [input-chan]
+        (with-response [{:keys [os os-closed-chan output-chan]} input-chan]
+          (is (= true
+                 (wait-for-close os-closed-chan)))
+          (testing "error should be written to output stream"
+            (is (schema= {:message  (s/eq "No response after waiting 50.0 ms. Canceling request.")
+                          :type     (s/eq "class java.util.concurrent.TimeoutException")
+                          :_status  (s/eq 500)
+                          :trace    s/Any
+                          s/Keyword s/Any}
+                         (os->response os))))
+
+          (testing "input chan should get closed"
+            (is (= true
+                   (wait-for-close input-chan))))
+
+          (testing "output chan should get closed"
+            (is (= true
+                   (wait-for-close output-chan)))))))))

test/metabase/pulse/render/png_test.clj

+(ns metabase.pulse.render.png-test
+  (:require [clojure.test :refer :all]
+            [metabase.pulse.render.png :as png]
+            [metabase.test :as mt]
+            [schema.core :as s]))
+
+(deftest register-fonts-test
+  (testing "Under normal circumstances, font registration should work as expected"
+    (is (= nil
+           (#'png/register-fonts-if-needed!))))
+
+  (testing "If font regsitration fails, we should an Exception with a useful error message"
+    (with-redefs [png/register-font! (fn [& _]
+                                       (throw (ex-info "Oops!" {})))]
+      (let [messages (mt/with-log-messages
+                       (is (thrown-with-msg?
+                            clojure.lang.ExceptionInfo
+                            #"Error registering fonts: Metabase will not be able to send Pulses"
+                            (#'png/register-fonts!))))]
+        (testing "Should log the Exception"
+          (is (schema= [(s/one (s/eq :error) "log type")
+                        (s/one Throwable "exception")
+                        (s/one #"^Error registering fonts" "message")]
+                       (first messages))))))))

test/metabase/test.clj

@@ -8,6 +8,7 @@
             [medley.core :as m]
             [metabase
              [driver :as driver]
+             [email-test :as et]
              [query-processor :as qp]
              [query-processor-test :as qp.test]]
             [metabase.driver.sql-jdbc.test-util :as sql-jdbc.tu]
@@ -37,12 +38,13 @@
   data/keep-me
   datasets/keep-me
   driver/keep-me
+  et/keep-me
   initialize/keep-me
   qp/keep-me
   qp.test-util/keep-me
   qp.test/keep-me
   sql-jdbc.tu/keep-me
-  [test-users/keep-me]
+  test-users/keep-me
   tt/keep-me
   tu/keep-me
   tu.async/keep-me
@@ -76,6 +78,16 @@
   *driver*
   with-driver]
 
+ [et
+  email-to
+  fake-inbox-email-fn
+  inbox
+  regex-email-bodies
+  reset-inbox!
+  summarize-multipart-email
+  with-expected-messages
+  with-fake-inbox]
+
  [initialize
   initialize-if-needed!]
 
@@ -107,6 +119,7 @@
   sql-jdbc-drivers]
 
  [test-users
+  fetch-user
   user->id
   user->client
   user->credentials

test/metabase/test/util.clj

@@ -361,7 +361,7 @@
     @messages))
 
 (defmacro with-log-messages
-  "Execute BODY, and return a vector of all messages logged using the `log/` family of functions. Messages are of the
+  "Execute `body`, and return a vector of all messages logged using the `log/` family of functions. Messages are of the
   format `[:level throwable message]`, and are returned in chronological order from oldest to newest.
 
      (with-log-messages (log/warn \"WOW\")) ; -> [[:warn nil \"WOW\"]]"