🎉 Add better error reporting.

2025-03-10 14:51:37 -05:00 · 2021-01-24 16:04:23 +01:00 · 2021-01-24 16:04:23 +01:00 · 04b0cf6330
commit 04b0cf6330
parent 1b70283c3a
10 changed files with 333 additions and 77 deletions
--- a/backend/resources/error-report.tmpl
+++ b/backend/resources/error-report.tmpl
@ -0,0 +1,135 @@
+<!DOCTYPE html>
+<html>
+  <head>
+    <meta charset="utf-8" />
+    <meta http-equiv="x-ua-compatible" content="ie=edge" />
+    <title>penpot - error report {{id}}</title>
+    <link rel="stylesheet" href="https://fonts.googleapis.com/css2?family=JetBrains+Mono">
+    <style>
+      body {
+        margin: 0px;
+        padding: 0px;
+      }
+      pre {
+        margin: 0px;
+      }
+      * {
+        font-family: "JetBrains Mono", monospace; 
+        font-size: 12px;
+      }
+      .table {
+        display: flex;
+        flex-direction: column;
+        margin: 10px;
+      }
+
+      .table-row {
+        display: flex;
+        /* width: 100%; */
+        /* border: 1px solid red; */
+      }
+
+      .table-key {
+        font-weight: 600;
+        width: 70px;
+        padding: 4px;
+      }
+
+      .table-val {
+        font-weight: 200;
+        color: #333;
+        padding: 4px;
+      }
+
+      .multiline {
+        margin-top: 15px;
+        flex-direction: column;
+      }
+
+      .multiline .table-key {
+        margin-bottom: 10px;
+        border-bottom: 1px dashed #dddddd;
+        /* padding: 4px; */
+        width: unset;
+      }
+
+    </style>
+  </head>
+  <body>
+    <div class="table">
+      <div class="table-row">
+        <div class="table-key">ERID: </div>
+        <div class="table-val">{{id}}</div>
+      </div>
+      <div class="table-row">
+        <div class="table-key">VERS: </div>
+        <div class="table-val">{{version}}</div>
+      </div>
+      <div class="table-row">
+        <div class="table-key">HOST: </div>
+        <div class="table-val">{{host}}</div>
+      </div>
+      {% if type %}
+      <div class="table-row">
+        <div class="table-key">TYPE: </div>
+        <div class="table-val">{{type}}</div>
+      </div>
+      {% endif %}
+      {% if code %}
+      <div class="table-row">
+        <div class="table-key">CODE: </div>
+        <div class="table-val">{{code}}</div>
+      </div>
+      {% endif %}
+      <div class="table-row">
+        <div class="table-key">CLASS: </div>
+        <div class="table-val">{{class}}</div>
+      </div>
+      <div class="table-row">
+        <div class="table-key">HINT: </div>
+        <div class="table-val">{{hint}}</div>
+      </div>
+
+      <div class="table-row">
+        <div class="table-key">PATH: </div>
+        <div class="table-val">{{method|upper}} {{path}}</div>
+      </div>
+
+      {% if params %}
+      <div class="table-row multiline">
+        <div class="table-key">PARAMS: </div>
+        <div class="table-val">
+          <pre>{{params}}</pre>
+        </div>
+      </div>
+      {% endif %}
+
+      {% if explain %}
+      <div class="table-row multiline">
+        <div class="table-key">EXPLAIN: </div>
+        <div class="table-val">
+          <pre>{{explain}}</pre>
+        </div>
+      </div>
+      {% endif %}
+
+      {% if data %}
+      <div class="table-row multiline">
+        <div class="table-key">EDATA: </div>
+        <div class="table-val">
+          <pre>{{data}}</pre>
+        </div>
+      </div>
+      {% endif %}
+
+
+      <div class="table-row multiline">
+        <div class="table-key">TRACE:</div>
+        <div class="table-val">
+          <pre>{{message}}</pre>
+        </div>
+      </div>
+    </div>
+  </body>
+</html>
+
--- a/backend/src/app/config.clj
+++ b/backend/src/app/config.clj
@ -26,7 +26,7 @@
   :secret-key "default"
   :asserts-enabled true

-   :public-uri "http://localhost:3449/"
+   :public-uri "http://localhost:3449"
   :redis-uri "redis://localhost/0"

   :storage-backend :fs
--- a/backend/src/app/error_reporter.clj
+++ b/backend/src/app/error_reporter.clj
@ -12,67 +12,94 @@
  (:require
   [app.common.exceptions :as ex]
   [app.common.spec :as us]
+   [app.common.uuid :as uuid]
   [app.config :as cfg]
   [app.db :as db]
   [app.tasks :as tasks]
   [app.worker :as wrk]
   [app.util.json :as json]
   [app.util.http :as http]
+   [app.util.template :as tmpl]
+   [clojure.pprint :refer [pprint]]
   [clojure.core.async :as a]
   [clojure.spec.alpha :as s]
   [clojure.tools.logging :as log]
+   [clojure.java.io :as io]
   [cuerdas.core :as str]
   [integrant.core :as ig]
-   [promesa.exec :as px]))
+   [promesa.exec :as px])
+  (:import
+   org.apache.logging.log4j.core.LogEvent
+   org.apache.logging.log4j.util.ReadOnlyStringMap))

 ;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;
-;; Error Reporting
+;; Error Listener
 ;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;

-(declare send-notification!)
-(defonce queue-fn identity)
+(declare handle-event)
+
+(defonce queue (a/chan (a/sliding-buffer 64)))
+(defonce queue-fn (fn [event] (a/>!! queue event)))

 (s/def ::uri ::us/string)
-(defmethod ig/pre-init-spec ::instance [_]
-  (s/keys :req-un [::wrk/executor]
+
+(defmethod ig/pre-init-spec ::reporter [_]
+  (s/keys :req-un [::wrk/executor ::db/pool]
          :opt-un [::uri]))

-(defmethod ig/init-key ::instance
+(defmethod ig/init-key ::reporter
  [_ {:keys [executor uri] :as cfg}]
-  (let [out (a/chan (a/sliding-buffer 64))]
-    (log/info "Intializing error reporter.")
-    (if uri
-      (do
-        (alter-var-root #'queue-fn (constantly (fn [x] (a/>!! out (str x)))))
-        (a/go-loop []
-          (let [val (a/<! out)]
-            (if (nil? val)
-              (log/info "Closing error reporting loop.")
-              (do
-                (px/run! executor #(send-notification! cfg val))
-                (recur))))))
-      (log/info "No webhook uri is provided (error reporting becomes noop)."))
-    out))
+  (log/info "Intializing error reporter.")
+  (let [close-ch (a/chan 1)]
+    (a/go-loop []
+      (let [[val port] (a/alts! [close-ch queue])]
+        (cond
+          (= port close-ch)
+          (log/info "Stoping error reporting loop.")

-(defmethod ig/halt-key! ::instance
-  [_ out]
-  (alter-var-root #'queue-fn (constantly identity))
-  (a/close! out))
+          (nil? val)
+          (log/info "Stoping error reporting loop.")

-(defn send-notification!
-  [cfg report]
+          :else
+          (do
+            (px/run! executor #(handle-event cfg val))
+            (recur)))))
+    close-ch))
+
+(defmethod ig/halt-key! ::reporter
+  [_ close-ch]
+  (a/close! close-ch))
+
+(defn- get-context-data
+  [event]
+  (let [^LogEvent levent (deref event)
+        ^ReadOnlyStringMap rosm (.getContextData levent)]
+    (into {:message (str event)}
+          (comp
+           (map (fn [[key val]]
+                  (cond
+                    (= "id" key)         [:id (uuid/uuid val)]
+                    (= "profile-id" key) [:profile-id (uuid/uuid val)]
+                    (str/blank? val)     nil
+                    (string? key)        [(keyword key) val]
+                    :else                [key val])))
+           (filter some?))
+
+          (.toMap rosm))))
+
+(defn- send-mattermost-notification!
+  [cfg {:keys [message host version id] :as cdata}]
  (try
    (let [uri    (:uri cfg)
          prefix (str/<< "Unhandled exception (@channel):\n"
-                         "- host: `~(:host cfg/config)`\n"
-                         "- version: `~(:full cfg/version)`")
-          text   (str prefix "\n```\n" report "\n```")
-
+                         "- detail: ~(:public-uri cfg/config)/dbg/error-by-id/~{id}\n"
+                         "- host: `~{host}`\n"
+                         "- version: `~{version}`\n")
+          text   (str prefix "```\n" message "\n```")
          rsp    (http/send! {:uri uri
                              :method :post
                              :headers {"content-type" "application/json"}
                              :body (json/encode-str {:text text})})]
-
      (when (not= (:status rsp) 200)
        (log/warnf "Error reporting webhook replying with unexpected status: %s\n%s"
                   (:status rsp)
@ -80,3 +107,54 @@

    (catch Exception e
      (log/warnf e "Unexpected exception on error reporter."))))
+
+(defn- persist-on-database!
+  [{:keys [pool] :as cfg} {:keys [id] :as cdata}]
+  (db/with-atomic [conn pool]
+    (db/insert! conn :server-error-report
+                {:id id :content (db/tjson cdata)})))
+
+(defn handle-event
+  [cfg event]
+  (try
+    (let [cdata (get-context-data event)]
+      (when (:uri cfg)
+        (send-mattermost-notification! cfg cdata))
+      (persist-on-database! cfg cdata))
+    (catch Exception e
+      (log/warnf e "Unexpected exception on error reporter."))))
+
+;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;
+;; Http Handler
+;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;
+
+(defmethod ig/pre-init-spec ::handler [_]
+  (s/keys :req-un [::db/pool]))
+
+(defmethod ig/init-key ::handler
+  [_ {:keys [pool] :as cfg}]
+  (letfn [(parse-id [request]
+            (let [id (get-in request [:path-params :id])
+                  id (us/uuid-conformer id)]
+              (when (uuid? id)
+                id)))
+          (retrieve-report [id]
+            (ex/ignoring
+             (when-let [{:keys [content] :as row} (db/get-by-id pool :server-error-report id)]
+               (assoc row :content (db/decode-transit-pgobject content)))))
+
+          (render-template [{:keys [content] :as report}]
+            (some-> (io/resource "error-report.tmpl")
+                    (tmpl/render content)))]
+
+
+    (fn [request]
+      (let [result (some-> (parse-id request)
+                           (retrieve-report)
+                           (render-template))]
+        (if result
+          {:status 200
+           :headers {"content-type" "text/html; charset=utf-8"}
+           :body result}
+          {:status 404
+           :body "not found"})))))
--- a/backend/src/app/http.clj
+++ b/backend/src/app/http.clj
@ -9,17 +9,18 @@

 (ns app.http
  (:require
-   [app.common.spec :as us]
   [app.common.data :as d]
+   [app.common.spec :as us]
+   [app.common.uuid :as uuid]
   [app.config :as cfg]
+   [app.http.assets :as assets]
   [app.http.auth :as auth]
   [app.http.errors :as errors]
   [app.http.middleware :as middleware]
-   [app.http.assets :as assets]
   [app.metrics :as mtx]
+   [clojure.spec.alpha :as s]
   [clojure.tools.logging :as log]
   [integrant.core :as ig]
-   [clojure.spec.alpha :as s]
   [reitit.ring :as rr]
   [ring.adapter.jetty9 :as jetty])
  (:import
@ -101,12 +102,11 @@
      (try
        (handler request)
        (catch Exception e
-          (log/errorf e
-                      (str "Unhandled exception: " (ex-message e) "\n"
-                           "=| uri:    " (pr-str (:uri request)) "\n"
-                           "=| method: " (pr-str (:request-method request)) "\n"))
-          {:status 500
-           :body "internal server error"})))))
+          (let [cdata (errors/get-error-context request e)]
+            (errors/update-thread-context! cdata)
+            (log/errorf e "Unhandled exception: %s (id: %s)" (ex-message e) (str (:id cdata)))
+            {:status 500
+             :body "internal server error"}))))))

 (defn- create-router
  [{:keys [session rpc google-auth gitlab-auth github-auth metrics ldap-auth storage svgparse] :as cfg}]
@ -119,12 +119,15 @@
     ["/by-file-media-id/:id" {:get #(assets/file-objects-handler storage %)}]
     ["/by-file-media-id/:id/thumbnail" {:get #(assets/file-thumbnails-handler storage %)}]]

+    ["/dbg"
+     ["/error-by-id/:id" {:get (:error-reporter-handler cfg)}]]
+
    ["/api" {:middleware [[middleware/format-response-body]
                          [middleware/parse-request-body]
-                          [middleware/errors errors/handle]
                          [middleware/params]
                          [middleware/multipart-params]
                          [middleware/keyword-params]
+                          [middleware/errors errors/handle]
                          [middleware/cookies]]}

     ["/svg" {:post svgparse}]
--- a/backend/src/app/http/errors.clj
+++ b/backend/src/app/http/errors.clj
@ -10,27 +10,50 @@
 (ns app.http.errors
  "A errors handling for the http server."
  (:require
-   [clojure.pprint :refer [pprint]]
   [app.common.exceptions :as ex]
+   [app.common.uuid :as uuid]
+   [app.config :as cfg]
+   [clojure.pprint :refer [pprint]]
   [clojure.tools.logging :as log]
   [cuerdas.core :as str]
-   [expound.alpha :as expound]))
+   [expound.alpha :as expound])
+  (:import
+   org.apache.logging.log4j.ThreadContext))

-(defn get-context-string
-  [request edata]
-  (str "=| uri:    " (pr-str (:uri request)) "\n"
-       "=| method: " (pr-str (:request-method request)) "\n"
-       "=| params: \n"
-       (with-out-str
-         (pprint (:params request)))
-       "\n"
+(defn update-thread-context!
+  [data]
+  (run! (fn [[key val]]
+          (ThreadContext/put
+           (name key)
+           (cond
+             (coll? val) (with-out-str (pprint val))
+             (instance? clojure.lang.Named val) (name val)
+             :else (str val))))
+        data))

-       (when (map? edata)
-         (str "=| ex-data: \n"
-              (with-out-str
-                (pprint edata))))
+(defn- explain-error
+  [error]
+  (with-out-str
+    (expound/printer (:data error))))

-       "\n"))
+(defn get-error-context
+  [request error]
+  (let [edata (ex-data error)]
+    (merge
+     {:id      (uuid/next)
+      :path    (:uri request)
+      :method  (:request-method request)
+      :params  (:params request)
+      :version (:full cfg/version)
+      :host    (:host cfg/config)
+      :class   (.getCanonicalName ^java.lang.Class (class error))
+      :hint    (ex-message error)}
+
+     (when (map? edata)
+       edata)
+
+     (when (and (map? edata) (:data edata))
+       {:explain (explain-error edata)}))))

 (defmulti handle-exception
  (fn [err & _rest]
@ -42,11 +65,6 @@
  [err _]
  {:status 401 :body (ex-data err)})

-(defn- explain-error
-  [error]
-  (with-out-str
-    (expound/printer (:data error))))
-
 (defmethod handle-exception :validation
  [err req]
  (let [header (get-in req [:headers "accept"])
@ -66,11 +84,10 @@

 (defmethod handle-exception :assertion
  [error request]
-  (let [edata (ex-data error)]
-    (log/error error
-                (str "Internal error: assertion\n"
-                     (get-context-string request edata)
-                     (explain-error edata)))
+  (let [edata (ex-data error)
+        cdata (get-error-context request error)]
+    (update-thread-context! cdata)
+    (log/errorf error "Internal error: assertion (id: %s)" (str (:id cdata)))
    {:status 500
     :body {:type :server-error
            :data (-> edata
@ -83,15 +100,15 @@

 (defmethod handle-exception :default
  [error request]
-  (let [edata (ex-data error)]
-    (log/error error
-                (str "Internal Error: "
-                     (ex-message error)
-                     (get-context-string request edata)))
+  (let [cdata (get-error-context request error)]
+    (update-thread-context! cdata)
+    (log/errorf error "Internal error: %s (id: %s)"
+                (ex-message error)
+                (str (:id cdata)))
    {:status 500
     :body {:type :server-error
            :hint (ex-message error)
-            :data edata}}))
+            :data (ex-data error)}}))

 (defn handle
  [error req]
--- a/backend/src/app/http/middleware.clj
+++ b/backend/src/app/http/middleware.clj
@ -14,7 +14,6 @@
   [app.metrics :as mtx]
   [app.util.transit :as t]
   [app.util.json :as json]
-   ;; [clojure.data.json :as json]
   [clojure.java.io :as io]
   [ring.middleware.cookies :refer [wrap-cookies]]
   [ring.middleware.keyword-params :refer [wrap-keyword-params]]
--- a/backend/src/app/main.clj
+++ b/backend/src/app/main.clj
@ -84,6 +84,9 @@
     :github-auth (ig/ref :app.http.auth/github)
     :ldap-auth   (ig/ref :app.http.auth/ldap)
     :svgparse    (ig/ref :app.svgparse/handler)
+
+     :error-reporter-handler   (ig/ref :app.error-reporter/handler)
+
     :storage     (ig/ref :app.storage/storage)}

    :app.svgparse/svgc
@ -240,10 +243,14 @@
    :app.srepl/server
    {:port 6062}

-    :app.error-reporter/instance
-    {:uri (:error-report-webhook cfg/config)
+    :app.error-reporter/reporter
+    {:uri      (:error-report-webhook cfg/config)
+     :pool     (ig/ref :app.db/pool)
     :executor (ig/ref :app.worker/executor)}

+    :app.error-reporter/handler
+    {:pool (ig/ref :app.db/pool)}
+
    :app.storage/storage
    {:pool     (ig/ref :app.db/pool)
     :executor (ig/ref :app.worker/executor)
--- a/backend/src/app/migrations.clj
+++ b/backend/src/app/migrations.clj
@ -131,6 +131,9 @@

   {:name "0039-fix-some-on-delete-triggers"
    :fn (mg/resource "app/migrations/sql/0039-fix-some-on-delete-triggers.sql")}
+
+   {:name "0040-add-error-report-tables"
+    :fn (mg/resource "app/migrations/sql/0040-add-error-report-tables.sql")}
   ])


--- a/backend/src/app/migrations/sql/0040-add-error-report-tables.sql
+++ b/backend/src/app/migrations/sql/0040-add-error-report-tables.sql
@ -0,0 +1,10 @@
+CREATE TABLE server_error_report (
+  id uuid NOT NULL,
+  created_at timestamptz NOT NULL DEFAULT clock_timestamp(),
+  content jsonb,
+
+  PRIMARY KEY (id, created_at)
+);
+
+ALTER TABLE server_error_report
+  ALTER COLUMN content SET STORAGE external;
--- a/docker/devenv/files/nginx.conf
+++ b/docker/devenv/files/nginx.conf
@ -99,6 +99,10 @@ http {
            proxy_pass http://127.0.0.1:6060/api;
        }

+        location /dbg {
+            proxy_pass http://127.0.0.1:6060/dbg;
+        }
+
        location /export {
            proxy_pass http://127.0.0.1:6061;
        }