♻️ Refactor error reporting and logging context formatting

The prev approach uses clojure.pprint without any limit extensivelly
for format error context data and all this is done on the calling
thread. The clojure.pprint seems very inneficient in cpu and memory
usage on pprinting large data structures.

This is improved in the following way:

- All formatting and pretty printing is moved to logging thread,
  reducing unnecesary blocking and load on jetty http threads.
- Replace the clojure.pprint with fipp.edn that looks considerably
  faster than the first one.
- Add some safe limits on pretty printer for strip printing some
  data when the data structure is very large, very deep or both.

backend/src/app/cli/manage.clj

@@ -140,7 +140,6 @@
   indicating the action the program should take and the options provided."
   [args]
   (let [{:keys [options arguments errors summary] :as opts} (parse-opts args cli-options)]
-    ;; (pp/pprint opts)
     (cond
       (:help options) ; help => exit OK with usage summary
       {:exit-message (usage summary) :ok? true}

backend/src/app/http.clj

@@ -76,11 +76,11 @@
       (try
         (handler request)
         (catch Throwable e
-          (l/with-context (errors/get-error-context request e)
           (l/error :hint "unexpected error processing request"
+                   ::l/context (errors/get-error-context request e)
                    :query-string (:query-string request)
                    :cause e)
-            {:status 500 :body "internal server error"}))))))
+          {:status 500 :body "internal server error"})))))
 
 ;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;
 ;; Http Router

backend/src/app/http/debug.clj

@@ -18,7 +18,7 @@
    [app.util.template :as tmpl]
    [app.util.time :as dt]
    [clojure.java.io :as io]
-   [clojure.pprint :as ppr]
+   [fipp.edn :as fpp]
    [cuerdas.core :as str]
    [datoteka.core :as fs]
    [integrant.core :as ig]))
@@ -147,11 +147,10 @@
              (some-> (db/get-by-id pool :server-error-report id) :content db/decode-transit-pgobject)))
 
           (render-template [report]
-            (binding [ppr/*print-right-margin* 300]
             (let [context (dissoc report
                                   :trace :cause :params :data :spec-problems
                                   :spec-explain :spec-value :error :explain :hint)
-                    params  {:context (with-out-str (ppr/pprint context))
+                  params  {:context (with-out-str (fpp/pprint context {:width 300}))
                            :hint    (:hint report)
                            :spec-explain  (:spec-explain report)
                            :spec-problems (:spec-problems report)
@@ -161,7 +160,7 @@
                                               (some-> report :error :trace))
                            :params        (:params report)}]
               (-> (io/resource "templates/error-report.tmpl")
-                    (tmpl/render params)))))
+                  (tmpl/render params))))
           ]
 
     (when-not (authorized? pool request)

backend/src/app/http/errors.clj

@@ -9,11 +9,10 @@
   (:require
    [app.common.exceptions :as ex]
    [app.common.logging :as l]
+   [app.common.spec :as us]
    [app.common.uuid :as uuid]
-   [clojure.pprint]
    [clojure.spec.alpha :as s]
-   [cuerdas.core :as str]
+   [cuerdas.core :as str]))
-   [expound.alpha :as expound]))
 
 (defn- parse-client-ip
   [{:keys [headers] :as request}]
@@ -36,14 +35,13 @@
       :data          (some-> data (dissoc ::s/problems ::s/value ::s/spec))
       :ip-addr       (parse-client-ip request)
       :profile-id    (:profile-id request)}
+
      (let [headers (:headers request)]
        {:user-agent (get headers "user-agent")
         :frontend-version (get headers "x-frontend-version" "unknown")})
 
      (when (and data (::s/problems data))
-       {:spec-explain (binding [s/*explain-out* expound/printer]
+       {:spec-explain (us/pretty-explain data)}))))
-                        (with-out-str
-                          (s/explain-out (update data ::s/problems #(take 10 %)))))}))))
 
 (defmulti handle-exception
   (fn [err & _rest]
@@ -59,20 +57,10 @@
   [err _]
   {:status 400 :body (ex-data err)})
 
-(defn- explain-spec-error-data
-  [data]
-  (when (and (::s/problems data)
-             (::s/value data)
-             (::s/spec data))
-    (binding [s/*explain-out* expound/printer]
-      (with-out-str
-        (s/explain-out (update data ::s/problems #(take 10 %)))))))
-
-
 (defmethod handle-exception :validation
   [err _]
   (let [data    (ex-data err)
-        explain (explain-spec-error-data data)]
+        explain (us/pretty-explain data)]
     {:status 400
      :body (-> data
                (dissoc ::s/problems)
@@ -82,8 +70,10 @@
 (defmethod handle-exception :assertion
   [error request]
   (let [edata (ex-data error)]
-    (l/with-context (get-error-context request error)
+    (l/error ::l/raw (ex-message error)
-      (l/error ::l/raw (ex-message error) :cause error))
+             ::l/context (get-error-context request error)
+             :cause error)
+
     {:status 500
      :body {:type :server-error
             :code :assertion
@@ -105,9 +95,9 @@
              (ex/exception? (:handling edata)))
       (handle-exception (:handling edata) request)
       (do
-        (l/with-context (get-error-context request error)
+        (l/error ::l/raw (ex-message error)
-          (l/error ::l/raw (ex-message error) :cause error))
+                 ::l/context (get-error-context request error)
-
+                 :cause error)
         {:status 500
          :body {:type :server-error
                 :code :unexpected
@@ -117,10 +107,9 @@
 (defmethod handle-exception org.postgresql.util.PSQLException
   [error request]
   (let [state (.getSQLState ^java.sql.SQLException error)]
-
+    (l/error ::l/raw (ex-message error)
-    (l/with-context (get-error-context request error)
+             ::l/context (get-error-context request error)
-      (l/error ::l/raw (ex-message error) :cause error))
+             :cause error)
-
     (cond
       (= state "57014")
       {:status 504

backend/src/app/loggers/sentry.clj

@@ -120,8 +120,6 @@
               (.captureMessage ^IHub shub msg)
               ))
           ]
-    ;; (clojure.pprint/pprint event)
-
     (when @enabled
       (.withScope ^IHub shub (reify ScopeCallback
                                (run [_ scope]

backend/src/app/srepl/main.clj

@@ -17,7 +17,7 @@
    [app.srepl.dev :as dev]
    [app.util.blob :as blob]
    [app.util.time :as dt]
-   [clojure.pprint :refer [pprint]]
+   [fipp.edn :refer [pprint]]
    [clojure.spec.alpha :as s]
    [cuerdas.core :as str]
    [expound.alpha :as expound]))

backend/src/app/util/time.clj

@@ -8,7 +8,8 @@
   (:require
    [app.common.exceptions :as ex]
    [clojure.spec.alpha :as s]
-   [cuerdas.core :as str])
+   [cuerdas.core :as str]
+   [fipp.ednize :as fez])
   (:import
    java.time.Duration
    java.time.Instant
@@ -111,6 +112,11 @@
 (defmethod print-dup Duration [o w]
   (print-method o w))
 
+(extend-protocol fez/IEdn
+  Duration
+  (-edn [o] (pr-str o)))
+
+
 ;; --- INSTANT
 
 (defn instant
@@ -175,6 +181,10 @@
 (defmethod print-dup Instant [o w]
   (print-method o w))
 
+(extend-protocol fez/IEdn
+  Instant
+  (-edn [o] (pr-str o)))
+
 ;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;
 ;; Cron Expression
 ;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;

backend/src/app/worker.clj

@@ -249,10 +249,16 @@
 
 (defn get-error-context
   [error item]
-  (let [edata (ex-data error)]
+  (let [data (ex-data error)]
+    (merge
      {:id            (uuid/next)
-     :data    edata
+      :hint          (ex-message error)
-     :params  item}))
+      :spec-problems (some->> data ::s/problems (take 10) seq vec)
+      :spec-value    (some->> data ::s/value)
+      :data          (some-> data (dissoc ::s/problems ::s/value ::s/spec))
+      :params        item}
+     (when (and data (::s/problems data))
+       {:spec-explain (us/pretty-explain data)}))))
 
 (defn- handle-exception
   [error item]
@@ -266,8 +272,10 @@
 
         (= ::noop (:strategy edata))
         (assoc :inc-by 0))
-      (l/with-context (get-error-context error item)
+      (do
-        (l/error :cause error :hint "unhandled exception on task")
+        (l/error :hint "unhandled exception on task"
+                 ::l/context (get-error-context error item)
+                 :cause error)
         (if (>= (:retry-num item) (:max-retries item))
           {:status :failed :task item :error error}
           {:status :retry :task item :error error})))))

common/src/app/common/logging.cljc

@@ -9,6 +9,7 @@
    [app.common.exceptions :as ex]
    [clojure.pprint :refer [pprint]]
    [cuerdas.core :as str]
+   [fipp.edn :as fpp]
    #?(:clj [io.aviso.exception :as ie])
    #?(:cljs [goog.log :as glog]))
   #?(:cljs (:require-macros [app.common.logging])
@@ -52,22 +53,16 @@
    (defn stringify-data
      [val]
      (cond
-       (instance? clojure.lang.Named val)
-       (name val)
-
-       (instance? Throwable val)
-       (binding [ie/*app-frame-names* [#"app.*"]
-                 ie/*fonts* nil
-                 ie/*traditional* true]
-         (ie/format-exception val nil))
-
        (string? val)
        val
 
+       (instance? clojure.lang.Named val)
+       (name val)
+
        (coll? val)
-       (binding [clojure.pprint/*print-right-margin* 200]
+       (binding [*print-level* 5
-         (-> (with-out-str (pprint val))
+                 *print-length* 20]
-             (simple-prune (* 1024 1024 3))))
+         (with-out-str (fpp/pprint val {:width 200})))
 
        :else
        (str val))))
@@ -163,13 +158,13 @@
      (.isEnabled ^Logger logger ^Level level)))
 
 (defmacro log
-  [& {:keys [level cause ::logger ::async ::raw] :or {async true} :as props}]
+  [& {:keys [level cause ::logger ::async ::raw ::context] :or {async true} :as props}]
   (if (:ns &env) ; CLJS
     `(write-log! ~(or logger (str *ns*))
                  ~level
                  ~cause
-                 (or ~raw ~(dissoc props :level :cause ::logger ::raw)))
+                 (or ~raw ~(dissoc props :level :cause ::logger ::raw ::context)))
-    (let [props      (dissoc props :level :cause ::logger ::async ::raw)
+    (let [props      (dissoc props :level :cause ::logger ::async ::raw ::context)
           logger     (or logger (str *ns*))
           logger-sym (gensym "log")
           level-sym  (gensym "log")]
@@ -180,7 +175,7 @@
               `(->> (ThreadContext/getImmutableContext)
                     (send-off logging-agent
                               (fn [_# cdata#]
-                                (with-context (into {} cdata#)
+                                (with-context (-> {} (into cdata#) (into ~context))
                                   (->> (or ~raw (build-map-message ~props))
                                        (write-log! ~logger-sym ~level-sym ~cause))))))
 

common/src/app/common/spec.cljc

@@ -19,7 +19,7 @@
    [app.common.geom.point :as gpt]
    [app.common.uuid :as uuid]
    [cuerdas.core :as str]
-   [expound.alpha]))
+   [expound.alpha :as expound]))
 
 (s/check-asserts true)
 
@@ -270,3 +270,14 @@
                       (spec-assert* ~spec params# ~message mdata#)
                       (apply origf# params#)))))))
 
+(defn pretty-explain
+  ([data] (pretty-explain data nil))
+  ([data {:keys [max-problems] :or {max-problems 10}}]
+   (when (and (::s/problems data)
+              (::s/value data)
+              (::s/spec data))
+     (binding [s/*explain-out* expound/printer]
+       (with-out-str
+         (s/explain-out (update data ::s/problems #(take max-problems %))))))))
+
+