From 827c2140b761fd91144f41f2ad52ae17d305a30b Mon Sep 17 00:00:00 2001 From: Andrey Antukh Date: Wed, 9 Feb 2022 17:45:45 +0100 Subject: [PATCH] :recycle: 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 | 1 - backend/src/app/http.clj | 10 ++++---- backend/src/app/http/debug.clj | 31 +++++++++++----------- backend/src/app/http/errors.clj | 41 +++++++++++------------------- backend/src/app/loggers/sentry.clj | 2 -- backend/src/app/srepl/main.clj | 2 +- backend/src/app/util/time.clj | 12 ++++++++- backend/src/app/worker.clj | 20 ++++++++++----- common/src/app/common/logging.cljc | 27 ++++++++------------ common/src/app/common/spec.cljc | 13 +++++++++- 10 files changed, 84 insertions(+), 75 deletions(-) diff --git a/backend/src/app/cli/manage.clj b/backend/src/app/cli/manage.clj index d20758196..dad68fc6b 100644 --- a/backend/src/app/cli/manage.clj +++ b/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} diff --git a/backend/src/app/http.clj b/backend/src/app/http.clj index d55028199..d053786bb 100644 --- a/backend/src/app/http.clj +++ b/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" - :query-string (:query-string request) - :cause e) - {:status 500 :body "internal server error"})))))) + (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"}))))) ;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;; ;; Http Router diff --git a/backend/src/app/http/debug.clj b/backend/src/app/http/debug.clj index 2098cd084..8e021fcd8 100644 --- a/backend/src/app/http/debug.clj +++ b/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,21 +147,20 @@ (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)) - :hint (:hint report) - :spec-explain (:spec-explain report) - :spec-problems (:spec-problems report) - :spec-value (:spec-value report) - :data (:data report) - :trace (or (:trace report) - (some-> report :error :trace)) - :params (:params report)}] - (-> (io/resource "templates/error-report.tmpl") - (tmpl/render params))))) + (let [context (dissoc report + :trace :cause :params :data :spec-problems + :spec-explain :spec-value :error :explain :hint) + params {:context (with-out-str (fpp/pprint context {:width 300})) + :hint (:hint report) + :spec-explain (:spec-explain report) + :spec-problems (:spec-problems report) + :spec-value (:spec-value report) + :data (:data report) + :trace (or (:trace report) + (some-> report :error :trace)) + :params (:params report)}] + (-> (io/resource "templates/error-report.tmpl") + (tmpl/render params)))) ] (when-not (authorized? pool request) diff --git a/backend/src/app/http/errors.clj b/backend/src/app/http/errors.clj index b49df8e46..a53637849 100644 --- a/backend/src/app/http/errors.clj +++ b/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] - [expound.alpha :as expound])) + [cuerdas.core :as str])) (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] - (with-out-str - (s/explain-out (update data ::s/problems #(take 10 %)))))})))) + {:spec-explain (us/pretty-explain data)})))) (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) :cause error)) + (l/error ::l/raw (ex-message 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) :cause error)) - + (l/error ::l/raw (ex-message 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/with-context (get-error-context request error) - (l/error ::l/raw (ex-message error) :cause error)) - + (l/error ::l/raw (ex-message error) + ::l/context (get-error-context request error) + :cause error) (cond (= state "57014") {:status 504 diff --git a/backend/src/app/loggers/sentry.clj b/backend/src/app/loggers/sentry.clj index 78ac1ee39..5f4b93898 100644 --- a/backend/src/app/loggers/sentry.clj +++ b/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] diff --git a/backend/src/app/srepl/main.clj b/backend/src/app/srepl/main.clj index 08ea82a9b..111f46e32 100644 --- a/backend/src/app/srepl/main.clj +++ b/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])) diff --git a/backend/src/app/util/time.clj b/backend/src/app/util/time.clj index ed8f809e0..42d6ca64b 100644 --- a/backend/src/app/util/time.clj +++ b/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 ;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;; diff --git a/backend/src/app/worker.clj b/backend/src/app/worker.clj index 7d532f5e0..3bd8461fc 100644 --- a/backend/src/app/worker.clj +++ b/backend/src/app/worker.clj @@ -249,10 +249,16 @@ (defn get-error-context [error item] - (let [edata (ex-data error)] - {:id (uuid/next) - :data edata - :params item})) + (let [data (ex-data error)] + (merge + {:id (uuid/next) + :hint (ex-message error) + :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) - (l/error :cause error :hint "unhandled exception on task") + (do + (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}))))) diff --git a/common/src/app/common/logging.cljc b/common/src/app/common/logging.cljc index aea40b935..8cead52ed 100644 --- a/common/src/app/common/logging.cljc +++ b/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] - (-> (with-out-str (pprint val)) - (simple-prune (* 1024 1024 3)))) + (binding [*print-level* 5 + *print-length* 20] + (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))) - (let [props (dissoc props :level :cause ::logger ::async ::raw) + (or ~raw ~(dissoc props :level :cause ::logger ::raw ::context))) + (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)))))) diff --git a/common/src/app/common/spec.cljc b/common/src/app/common/spec.cljc index 85c4a6912..1742b6f62 100644 --- a/common/src/app/common/spec.cljc +++ b/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 %)))))))) + +