✨ Improve logging performance and format.

backend/deps.edn

@@ -32,7 +32,6 @@
   metosin/reitit-ring {:mvn/version "0.5.15"}
   org.postgresql/postgresql {:mvn/version "42.2.23"}
   com.zaxxer/HikariCP {:mvn/version "5.0.0"}
-
   funcool/datoteka {:mvn/version "2.0.0"}
 
   buddy/buddy-core {:mvn/version "1.10.1"}
@@ -49,9 +48,7 @@
   io.sentry/sentry {:mvn/version "5.1.2"}
 
   ;; Pretty Print specs
-  fipp/fipp {:mvn/version "0.6.24"}
   pretty-spec/pretty-spec {:mvn/version "0.1.4"}
-
   software.amazon.awssdk/s3 {:mvn/version "2.17.40"}}
 
  :paths ["src" "resources"]

backend/dev/user.clj

@@ -95,3 +95,10 @@
    [{:v1 (alength (blob/encode data {:version 1}))
      :v2 (alength (blob/encode data {:version 2}))
      :v3 (alength (blob/encode data {:version 3}))}]))
+
+
+(defonce debug-tap
+  (do
+    (add-tap #(locking debug-tap
+                (prn "tap debug:" %)))
+    1))

backend/resources/error-report.tmpl

@@ -130,10 +130,10 @@
       </div>
       {% endif %}
 
-      {% if error %}
+      {% if hint %}
       <div class="table-row">
         <div class="table-key">HINT: </div>
-        <div class="table-val">{{error.message}}</div>
+        <div class="table-val">{{hint}}</div>
       </div>
       {% endif %}
 
@@ -163,25 +163,39 @@
       </div>
       {% endif %}
 
-      {% if explain %}
-      <div id="explain" class="table-row multiline">
-        <div class="table-key">EXPLAIN: </div>
-        <div class="table-val">
-          <pre>{{explain}}</pre>
-        </div>
-      </div>
-      {% endif %}
-
       {% if data %}
       <div id="edata" class="table-row multiline">
-        <div class="table-key">EDATA: </div>
+        <div class="table-key">ERROR DATA: </div>
         <div class="table-val">
           <pre>{{data}}</pre>
         </div>
       </div>
       {% endif %}
 
-      {% if error %}
+      {% if spec-problems %}
+      <div id="edata" class="table-row multiline">
+        <div class="table-key">SPEC PROBLEMS: </div>
+        <div class="table-val">
+          <pre>{{spec-problems}}</pre>
+        </div>
+      </div>
+      {% endif %}
+
+      {% if cause %}
+      <div id="trace" class="table-row multiline">
+        <div class="table-key">TRACE:</div>
+        <div class="table-val">
+          <pre>{{cause}}</pre>
+        </div>
+      </div>
+      {% elif trace %}
+      <div id="trace" class="table-row multiline">
+        <div class="table-key">TRACE:</div>
+        <div class="table-val">
+          <pre>{{trace}}</pre>
+        </div>
+      </div>
+      {% elif error %}
       <div id="trace" class="table-row multiline">
         <div class="table-key">TRACE:</div>
         <div class="table-val">

backend/resources/log4j2-devenv.xml

@@ -2,7 +2,7 @@
 <Configuration status="info" monitorInterval="30">
   <Appenders>
     <Console name="console" target="SYSTEM_OUT">
-      <PatternLayout pattern="[%d{YYYY-MM-dd HH:mm:ss.SSS}] [%t] %level{length=1} %logger{36} - %msg%n"/>
+      <PatternLayout pattern="[%d{YYYY-MM-dd HH:mm:ss.SSS}] %level{length=1} %logger{36} - %msg%n"/>
     </Console>
 
     <RollingFile name="main" fileName="logs/main.log" filePattern="logs/main-%i.log">

backend/scripts/repl

@@ -2,7 +2,6 @@
 
 export PENPOT_FLAGS="enable-asserts enable-audit-log $PENPOT_FLAGS"
 
-#-J-Dlog4j2.contextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
 
 export OPTIONS="
        -A:jmx-remote:dev \

backend/src/app/http/errors.clj

@@ -11,6 +11,7 @@
    [app.common.logging :as l]
    [app.common.uuid :as uuid]
    [clojure.pprint]
+   [clojure.spec.alpha :as s]
    [cuerdas.core :as str]))
 
 (defn- parse-client-ip
@@ -23,22 +24,20 @@
   [request error]
   (let [data (ex-data error)]
     (merge
-     {:id         (uuid/next)
+     {:id            (uuid/next)
-      :path       (:uri request)
+      :path          (:uri request)
-      :method     (:request-method request)
+      :method        (:request-method request)
-      :hint       (or (:hint data) (ex-message error))
+      :hint          (or (:hint data) (ex-message error))
-      :params     (l/stringify-data (:params request))
+      :params        (l/stringify-data (:params request))
-      :data       (l/stringify-data (dissoc data :explain))
+      :spec-problems (some-> data ::s/problems)
-      :ip-addr    (parse-client-ip request)
+      :ip-addr       (parse-client-ip request)
-      :profile-id (:profile-id 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 (map? data)
+     (dissoc data ::s/problems))))
-       {:error-type (:type data)
-        :error-code (:code data)}))))
 
 (defmulti handle-exception
   (fn [err & _rest]
@@ -66,17 +65,17 @@
                   (:explain edata)
                   "</pre>\n")}
       {:status 400
-       :body   (dissoc edata :data)})))
+       :body   (dissoc edata ::s/problems)})))
 
 (defmethod handle-exception :assertion
   [error request]
   (let [edata (ex-data error)]
     (l/with-context (get-error-context request error)
-      (l/error :hint "internal error: assertion" :cause error))
+      (l/error :hint (ex-message error) :cause error))
     {:status 500
      :body {:type :server-error
             :code :assertion
-            :data (dissoc edata :data)}}))
+            :data (dissoc edata ::s/problems)}}))
 
 (defmethod handle-exception :not-found
   [err _]

backend/src/app/loggers/database.clj

@@ -36,7 +36,7 @@
     (db/insert! conn :server-error-report
                 {:id id :content (db/tjson event)})))
 
-(defn- parse-context
+(defn- parse-event-data
   [event]
   (reduce-kv
    (fn [acc k v]
@@ -46,12 +46,11 @@
        (str/blank? v)    acc
        :else             (assoc acc k v)))
    {}
-   (:context event)))
+   event))
 
 (defn parse-event
   [event]
-  (-> (parse-context event)
+  (-> (parse-event-data event)
-      (merge (dissoc event :context))
       (assoc :tenant (cf/get :tenant))
       (assoc :host (cf/get :host))
       (assoc :public-uri (cf/get :public-uri))
@@ -62,6 +61,7 @@
   (aa/with-thread executor
     (try
       (let [event (parse-event event)]
+        (l/debug :hint "registering error on database" :id (:id event))
         (persist-on-database! cfg event))
       (catch Exception e
         (l/warn :hint "unexpected exception on database error logger"
@@ -74,7 +74,8 @@
   [_ {:keys [receiver] :as cfg}]
   (l/info :msg "initializing database error persistence")
   (let [output (a/chan (a/sliding-buffer 128)
-                       (filter #(= (:level %) "error")))]
+                       (filter (fn [event]
+                                 (= (:logger/level event) "error"))))]
     (receiver :sub output)
     (a/go-loop []
       (let [msg (a/<! output)]

backend/src/app/loggers/zmq.clj

@@ -92,19 +92,15 @@
 (defn- prepare
   [event]
   (if (s/valid? ::log4j-event event)
-    (merge
+    (merge {:message      (:message event)
-     {:logger     (:logger-name event)
+            :created-at   (dt/instant (:time-millis event))
-      :level      (str/lower (:level event))
+            :logger/name  (:logger-name event)
-      :thread     (:thread event)
+            :logger/level (str/lower (:level event))}
-      :created-at (dt/instant (:time-millis event))
+
-      :message    (:message event)}
+           (when-let [thrown (:thrown event)]
-     (when-let [ctx (:context-map event)]
+             {:trace (:extended-stack-trace thrown)})
-       {:context ctx})
+
-     (when-let [thrown (:thrown event)]
+           (:context-map event))
-       {:error
-        {:class (:name thrown)
-         :message (:message thrown)
-         :trace (:extended-stack-trace thrown)}}))
     (do
       (l/warn :hint "invalid event" :event event)
       nil)))

common/deps.edn

@@ -33,6 +33,7 @@
   com.sun.mail/jakarta.mail {:mvn/version "2.0.1"}
 
   ;; exception printing
+  fipp/fipp {:mvn/version "0.6.24"}
   io.aviso/pretty {:mvn/version "0.1.37"}
   environ/environ {:mvn/version "1.2.0"}}
  :paths ["src"]

common/src/app/common/logging.cljc

@@ -9,6 +9,7 @@
    [app.common.exceptions :as ex]
    [clojure.pprint :refer [pprint]]
    [cuerdas.core :as str]
+   #?(:clj [io.aviso.exception :as ie])
    #?(:cljs [goog.log :as glog]))
   #?(:cljs (:require-macros [app.common.logging]))
   #?(:clj
@@ -21,6 +22,10 @@
       org.apache.logging.log4j.message.MapMessage
       org.apache.logging.log4j.spi.LoggerContext)))
 
+;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;
+;; CLJ Specific
+;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;
+
 #?(:clj (set! *warn-on-reflection* true))
 
 #?(:clj
@@ -37,6 +42,59 @@
   (def logging-agent
     (agent nil :error-mode :continue)))
 
+(defn- simple-prune
+  ([s] (simple-prune s (* 1024 1024)))
+  ([s max-length]
+   (if (> (count s) max-length)
+     (str (subs s 0 max-length) " [...]")
+     s)))
+
+#?(:clj
+   (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
+
+       (coll? val)
+       (binding [clojure.pprint/*print-right-margin* 120]
+         (-> (with-out-str (pprint val))
+             (simple-prune (* 1024 1024 3))))
+
+       :else
+       (str val))))
+
+#?(:clj
+   (defn data->context-map
+     ^java.util.Map
+     [data]
+     (into {}
+           (comp (filter second)
+                 (map (fn [[key val]]
+                        [(stringify-data key)
+                         (stringify-data val)])))
+           data)))
+
+#?(:clj
+   (defmacro with-context
+     [data & body]
+     `(let [data# (data->context-map ~data)]
+        (with-open [closeable# (CloseableThreadContext/putAll data#)]
+          ~@body))))
+
+;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;
+;; Common
+;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;
+
 (defn get-logger
   [lname]
   #?(:clj  (.getLogger ^LoggerContext logger-context ^String lname)
@@ -89,7 +147,7 @@
      :cljs
      (when glog/ENABLED
        (when-let [l (get-logger logger)]
-         (let [level  (get-level level)
+         (let [level (get-level level)
                record (glog/LogRecord. level message (.getName ^js l))]
            (when exception (.setException record exception))
            (glog/publishLogRecord l record))))))
@@ -100,7 +158,7 @@
      (.isEnabled ^Logger logger ^Level level)))
 
 (defmacro log
-  [& {:keys [level cause ::logger ::async ::raw] :as props}]
+  [& {:keys [level cause ::logger ::async ::raw] :or {async true} :as props}]
   (if (:ns &env) ; CLJS
     `(write-log! ~(or logger (str *ns*))
                  ~level
@@ -114,10 +172,12 @@
              ~level-sym  (get-level ~level)]
          (if (enabled? ~logger-sym ~level-sym)
            ~(if async
-              `(send-off logging-agent
+              `(let [cdata# (ThreadContext/getImmutableContext)]
-                         (fn [_#]
+                 (send-off logging-agent
-                           (let [message# (or ~raw (build-map-message ~props))]
+                           (fn [_#]
-                             (write-log! ~logger-sym ~level-sym ~cause message#))))
+                             (with-context (into {:cause ~cause} cdata#)
+                               (->> (or ~raw (build-map-message ~props))
+                                    (write-log! ~logger-sym ~level-sym ~cause))))))
               `(let [message# (or ~raw (build-map-message ~props))]
                  (write-log! ~logger-sym ~level-sym ~cause message#))))))))
 
@@ -149,52 +209,6 @@
    (when (:ns &env)
      `(set-level* ~n ~level))))
 
-;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;
-;; CLJ Specific
-;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;
-
-(defn- simple-prune
-  ([s] (simple-prune s (* 1024 1024)))
-  ([s max-length]
-   (if (> (count s) max-length)
-     (str (subs s 0 max-length) " [...]")
-     s)))
-
-#?(:clj
-   (defn stringify-data
-     [val]
-     (cond
-       (instance? clojure.lang.Named val)
-       (name val)
-
-       (string? val)
-       val
-
-       (coll? val)
-       (binding [clojure.pprint/*print-right-margin* 120]
-         (-> (with-out-str (pprint val))
-             (simple-prune (* 1024 1024 3))))
-
-       :else
-       (str val))))
-
-#?(:clj
-   (defn data->context-map
-     ^java.util.Map
-     [data]
-     (into {}
-           (comp (filter second)
-                 (map (fn [[key val]]
-                        [(stringify-data key)
-                         (stringify-data val)])))
-           data)))
-
-#?(:clj
-   (defmacro with-context
-     [data & body]
-     `(with-open [instance# (CloseableThreadContext/putAll (data->context-map ~data))]
-        ~@body)))
-
 ;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;
 ;; CLJS Specific
 ;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;
@@ -243,7 +257,6 @@
      (some-> (get-logger name)
              (glog/setLevel (get-level lvl)))))
 
-
 #?(:cljs
    (defn set-levels!
      [lvls]

common/src/app/common/spec.cljc

@@ -208,28 +208,30 @@
 ;; --- Macros
 
 (defn spec-assert*
-  [spec x message context]
+  [spec val hint ctx]
-  (if (s/valid? spec x)
+  (if (s/valid? spec val)
-    x
+    val
-    (let [data (s/explain-data spec x)]
+    (let [data (s/explain-data spec val)]
       (ex/raise :type :assertion
                 :code :spec-validation
-                :hint message
+                :hint hint
-                :data data
+                :ctx  ctx
-                :context context
+                ::s/problems (::s/problems data)))))
-                #?@(:cljs [:stack (.-stack (ex-info message {}))])))))
-
 
 (defmacro assert
   "Development only assertion macro."
   [spec x]
   (when *assert*
     (let [nsdata  (:ns &env)
-          context (when nsdata
+          context (if nsdata
                     {:ns (str (:name nsdata))
                      :name (pr-str spec)
                      :line (:line &env)
-                     :file (:file (:meta nsdata))})
+                     :file (:file (:meta nsdata))}
+                    (let [mdata (meta &form)]
+                      {:ns   (str (ns-name *ns*))
+                       :name (pr-str spec)
+                       :line (:line mdata)}))
           message (str "spec assert: '" (pr-str spec) "'")]
       `(spec-assert* ~spec ~x ~message ~context))))