From 1c7ed722f63a8eb92404e3d28a709d29c8d4383b Mon Sep 17 00:00:00 2001 From: Andrey Antukh Date: Tue, 3 Feb 2026 15:57:52 +0100 Subject: [PATCH] WIP --- .../app/templates/error-report.v4.tmpl | 46 +++++ backend/src/app/http/debug.clj | 9 +- backend/src/app/loggers/audit.clj | 72 +++---- backend/src/app/loggers/database.clj | 187 ++++++++++++------ backend/src/app/loggers/mattermost.clj | 83 +++++--- backend/src/app/main.clj | 5 +- backend/src/app/rpc/commands/audit.clj | 68 +++---- backend/src/app/util/template.clj | 3 +- .../src/app/main/ui/dashboard/projects.cljs | 1 + 9 files changed, 311 insertions(+), 163 deletions(-) create mode 100644 backend/resources/app/templates/error-report.v4.tmpl diff --git a/backend/resources/app/templates/error-report.v4.tmpl b/backend/resources/app/templates/error-report.v4.tmpl new file mode 100644 index 0000000000..136f898d52 --- /dev/null +++ b/backend/resources/app/templates/error-report.v4.tmpl @@ -0,0 +1,46 @@ + {% extends "app/templates/base.tmpl" %} + +{% block title %} +Report: {{hint|abbreviate:150}} - {{id}} - Penpot Error Report (v3) +{% endblock %} + +{% block content %} + +
+
+
+ +
+

Hint:
{{hint}}

+

Reported at:
{{created-at}}

+

Report ID:
{{id}}

+
+
+ +
+
CONTEXT:
+ +
+ 
{{context}}
+
+
+ + {% if report %} +
+
REPORT:
+
+ 
{{report}}
+
+
+ {% endif %} +
+
+{% endblock %} diff --git a/backend/src/app/http/debug.clj b/backend/src/app/http/debug.clj index 6df4398116..acc8ed1de5 100644 --- a/backend/src/app/http/debug.clj +++ b/backend/src/app/http/debug.clj @@ -227,6 +227,12 @@ (render-template-v3 [{:keys [content id created-at]}] (-> (io/resource "app/templates/error-report.v3.tmpl") + (tmpl/render (-> content + (assoc :id id) + (assoc :created-at (ct/format-inst created-at :rfc1123)))))) + + (render-template-v4 [{:keys [content id created-at]}] + (-> (io/resource "app/templates/error-report.v4.tmpl") (tmpl/render (-> content (assoc :id id) (assoc :created-at (ct/format-inst created-at :rfc1123))))))] @@ -235,7 +241,8 @@ (let [result (case (:version report) 1 (render-template-v1 report) 2 (render-template-v2 report) - 3 (render-template-v3 report))] + 3 (render-template-v3 report) + 4 (render-template-v4 report))] {::yres/status 200 ::yres/body result ::yres/headers {"content-type" "text/html; charset=utf-8" diff --git a/backend/src/app/loggers/audit.clj b/backend/src/app/loggers/audit.clj index 7d64b768b0..74c01e219a 100644 --- a/backend/src/app/loggers/audit.clj +++ b/backend/src/app/loggers/audit.clj @@ -112,6 +112,8 @@ ;; COLLECTOR API ;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;; +(declare ^:private prepare-context-from-request) + ;; Defines a service that collects the audit/activity log using ;; internal database. Later this audit log can be transferred to ;; an external storage and data cleared. @@ -125,6 +127,8 @@ [::props {:optional true} [:map-of :keyword :any]] [::context {:optional true} [:map-of :keyword :any]] [::tracked-at {:optional true} ::ct/inst] + [::created-at {:optional true} ::ct/inst] + [::source {:optional true} ::sm/text] [::webhooks/event? {:optional true} ::sm/boolean] [::webhooks/batch-timeout {:optional true} ::ct/duration] [::webhooks/batch-key {:optional true} @@ -133,32 +137,8 @@ (def ^:private check-event (sm/check-fn schema:event)) -(defn- prepare-context-from-request - [request] - (let [client-event-origin (get-client-event-origin request) - client-version (get-client-version request) - client-user-agent (get-client-user-agent request) - session-id (get-external-session-id request) - token-id (::actoken/id request)] - (d/without-nils - {:external-session-id session-id - :access-token-id (some-> token-id str) - :client-event-origin client-event-origin - :client-user-agent client-user-agent - :client-version client-version - :version (:full cf/version)}))) - -(defn event-from-rpc-params - "Create a base event skeleton with pre-filled some important - data that can be extracted from RPC params object" - [params] - (let [context (some-> params meta ::http/request prepare-context-from-request) - event {::type "action" - ::profile-id (or (::rpc/profile-id params) uuid/zero) - ::ip-addr (::rpc/ip-addr params)}] - (cond-> event - (some? context) - (assoc ::context context)))) +(def valid-event? + (sm/validator schema:event)) (defn prepare-event [cfg mdata params result] @@ -207,6 +187,33 @@ (::webhooks/event? resultm) false)})) +(defn- prepare-context-from-request + [request] + (let [client-event-origin (get-client-event-origin request) + client-version (get-client-version request) + client-user-agent (get-client-user-agent request) + session-id (get-external-session-id request) + token-id (::actoken/id request)] + (d/without-nils + {:external-session-id session-id + :access-token-id (some-> token-id str) + :client-event-origin client-event-origin + :client-user-agent client-user-agent + :client-version client-version + :version (:full cf/version)}))) + +(defn event-from-rpc-params + "Create a base event skeleton with pre-filled some important + data that can be extracted from RPC params object" + [params] + (let [context (some-> params meta ::http/request prepare-context-from-request) + event {::type "action" + ::profile-id (or (::rpc/profile-id params) uuid/zero) + ::ip-addr (::rpc/ip-addr params)}] + (cond-> event + (some? context) + (assoc ::context context)))) + (defn- event->params [event] (let [params {:id (uuid/next) @@ -233,17 +240,16 @@ (defn- handle-event! [cfg event] - (let [params (event->params event) - tnow (ct/now)] + (let [tnow (ct/now) + params (-> (event->params event) + (assoc :created-at tnow) + (update :tracked-at #(or % tnow)))] (when (contains? cf/flags :audit-log) ;; NOTE: this operation may cause primary key conflicts on inserts ;; because of the timestamp precission (two concurrent requests), in ;; this case we just retry the operation. - (let [params (-> params - (assoc :created-at tnow) - (update :tracked-at #(or % tnow)))] - (append-audit-entry! cfg params))) + (append-audit-entry! cfg params)) (when (and (or (contains? cf/flags :telemetry) (cf/get :telemetry-enabled)) @@ -254,8 +260,6 @@ ;; ;; NOTE: this is only executed when general audit log is disabled (let [params (-> params - (assoc :created-at tnow) - (update :tracked-at #(or % tnow)) (assoc :props {}) (assoc :context {}))] (append-audit-entry! cfg params))) diff --git a/backend/src/app/loggers/database.clj b/backend/src/app/loggers/database.clj index ca2549d666..d771bc40c0 100644 --- a/backend/src/app/loggers/database.clj +++ b/backend/src/app/loggers/database.clj @@ -15,6 +15,7 @@ [app.config :as cf] [app.db :as db] [clojure.spec.alpha :as s] + [app.loggers.audit :as audit] [integrant.core :as ig] [promesa.exec :as px] [promesa.exec.csp :as sp])) @@ -28,69 +29,107 @@ (defonce enabled (atom true)) (defn- persist-on-database! - [pool id report] + [pool id version report] (when-not (db/read-only? pool) (db/insert! pool :server-error-report {:id id - :version 3 + :version version :content (db/tjson report)}))) +(defn- concurrent-exception? + [cause] + (or (instance? java.util.concurrent.CompletionException cause) + (instance? java.util.concurrent.ExecutionException cause))) + (defn record->report [{:keys [::l/context ::l/message ::l/props ::l/logger ::l/level ::l/cause] :as record}] (assert (l/valid-record? record) "expectd valid log record") - (if (or (instance? java.util.concurrent.CompletionException cause) - (instance? java.util.concurrent.ExecutionException cause)) - (-> record - (assoc ::trace (ex/format-throwable cause :data? true :explain? false :header? false :summary? false)) - (assoc ::l/cause (ex-cause cause)) - (record->report)) + (let [data (if (concurrent-exception? cause) + (ex-data (ex-cause cause)) + (ex-data cause)) - (let [data (ex-data cause) - ctx (-> context - (assoc :tenant (cf/get :tenant)) - (assoc :host (cf/get :host)) - (assoc :public-uri (str (cf/get :public-uri))) - (assoc :logger/name logger) - (assoc :logger/level level) - (dissoc :request/params :value :params :data))] + ctx (-> context + (assoc :tenant (cf/get :tenant)) + (assoc :host (cf/get :host)) + (assoc :public-uri (str (cf/get :public-uri))) + (assoc :version/backend (:full cf/version)) + (assoc :logger/name logger) + (assoc :logger/level level) + (dissoc :request/params :value :params :data))] - (merge - {:context (-> (into (sorted-map) ctx) - (pp/pprint-str :length 50)) - :props (pp/pprint-str props :length 50) - :hint (or (when-let [message (ex-message cause)] - (if-let [props-hint (:hint props)] - (str props-hint ": " message) - message)) - @message) - :trace (or (::trace record) - (some-> cause (ex/format-throwable :data? true :explain? false :header? false :summary? false)))} + (merge + {:context (-> (into (sorted-map) ctx) + (pp/pprint-str :length 50)) + :props (pp/pprint-str props :length 50) + :hint (or (when-let [message (ex-message cause)] + (if-let [props-hint (:hint props)] + (str props-hint ": " message) + message)) + @message) + :trace (or (::trace record) + (some-> cause (ex/format-throwable :data? true :explain? false :header? false :summary? false)))} - (when-let [params (or (:request/params context) (:params context))] - {:params (pp/pprint-str params :length 20 :level 20)}) + (when-let [params (or (:request/params context) (:params context))] + {:params (pp/pprint-str params :length 20 :level 20)}) - (when-let [value (:value context)] - {:value (pp/pprint-str value :length 30 :level 13)}) + (when-let [value (:value context)] + {:value (pp/pprint-str value :length 30 :level 13)}) - (when-let [data (some-> data (dissoc ::s/problems ::s/value ::s/spec ::sm/explain :hint))] - {:data (pp/pprint-str data :length 30 :level 13)}) + (when-let [data (some-> data (dissoc ::s/problems ::s/value ::s/spec ::sm/explain :hint))] + {:data (pp/pprint-str data :length 30 :level 13)}) - (when-let [explain (ex/explain data :length 30 :level 13)] - {:explain explain}))))) + (when-let [explain (ex/explain data :length 30 :level 13)] + {:explain explain})))) -(defn error-record? - [{:keys [::l/level]}] - (= :error level)) - -(defn- handle-event +(defn- handle-log-record + "Convert the log record into a report object and persist it on the database" [{:keys [::db/pool]} {:keys [::l/id] :as record}] (try (let [uri (cf/get :public-uri) report (-> record record->report d/without-nils)] - (l/debug :hint "registering error on database" :id id - :uri (str uri "/dbg/error/" id)) + (l/dbg :hint "registering error on database" + :src "logging" + :id id + :uri (str uri "/dbg/error/" id)) + (persist-on-database! pool id 3 report)) + (catch Throwable cause + (l/warn :hint "unexpected exception on database error logger" :cause cause)))) - (persist-on-database! pool id report)) +(defn event->report + [{:keys [::audit/context ::audit/props ::audit/id ::audit/ip-addr] :as record}] + (let [context + (reduce-kv (fn [context k v] + (let [k' (keyword "frontend" (name k))] + (-> context + (dissoc k) + (assoc k' v)))) + context + context) + + context + (-> context + (assoc :backend/tenant (cf/get :tenant)) + (assoc :backend/host (cf/get :host)) + (assoc :backend/public-uri (str (cf/get :public-uri))) + (assoc :frontend/ip-addr ip-addr))] + + {:context (-> (into (sorted-map) ctx) + (pp/pprint-str :length 50)) + :props (pp/pprint-str props :length 50) + :hint (get props :hint) + :report (get props :report)})) + +(defn- handle-audit-event + "Convert the log record into a report object and persist it on the database" + [{:keys [::db/pool]} {:keys [::audit/id] :as event}] + (try + (let [uri (cf/get :public-uri) + report (-> event event->report d/without-nils)] + (l/dbg :hint "registering error on database" + :id id + :src "audit-log" + :uri (str uri "/dbg/error/" id)) + (persist-on-database! pool id 4 report)) (catch Throwable cause (l/warn :hint "unexpected exception on database error logger" :cause cause)))) @@ -100,26 +139,48 @@ (defmethod ig/init-key ::reporter [_ cfg] - (let [input (sp/chan :buf (sp/sliding-buffer 64) - :xf (filter error-record?))] - (add-watch l/log-record ::reporter #(sp/put! input %4)) + (let [input (sp/chan :buf (sp/sliding-buffer 256)) + thread (px/thread + {:name "penpot/reporter/database"} + (l/info :hint "initializing database error persistence") + (try + (loop [] + (when-let [item (sp/take! input)] + (cond + (::l/id item) + (handle-log-record cfg item) - (px/thread {:name "penpot/database-reporter"} - (l/info :hint "initializing database error persistence") - (try - (loop [] - (when-let [record (sp/take! input)] - (handle-event cfg record) - (recur))) - (catch InterruptedException _ - (l/debug :hint "reporter interrupted")) - (catch Throwable cause - (l/error :hint "unexpected error" :cause cause)) - (finally - (sp/close! input) - (remove-watch l/log-record ::reporter) - (l/info :hint "reporter terminated")))))) + (::audit/id item) + (handle-audit-event cfg item) + + :else + (l/warn :hint "received unexpected item" :item item)) + + (recur))) + + (catch InterruptedException _ + (l/debug :hint "reporter interrupted")) + (catch Throwable cause + (l/error :hint "unexpected error" :cause cause)) + (finally + (l/info :hint "reporter terminated"))))] + + (add-watch l/log-record ::reporter + (fn [_ _ _ record] + (when (= :error (::l/level record)) + (sp/put! input record)))) + + {::input input + ::thread thread})) (defmethod ig/halt-key! ::reporter - [_ thread] - (some-> thread px/interrupt!)) + [_ {:keys [::input ::thread]}] + (remove-watch l/log-record ::reporter) + (sp/close! input) + (px/interrupt! thread)) + +(defn emit + "Emit an event/report into the database reporter" + [cfg event] + (when-let [{:keys [::input]} (get cfg ::reporter)] + (sp/put! input event))) diff --git a/backend/src/app/loggers/mattermost.clj b/backend/src/app/loggers/mattermost.clj index 530eb4a0a1..2fd4a84ee1 100644 --- a/backend/src/app/loggers/mattermost.clj +++ b/backend/src/app/loggers/mattermost.clj @@ -11,7 +11,7 @@ [app.common.logging :as l] [app.config :as cf] [app.http.client :as http] - [app.loggers.database :as ldb] + [app.loggers.audit :as audit] [app.util.json :as json] [integrant.core :as ig] [promesa.exec :as px] @@ -50,7 +50,7 @@ (l/warn :hint "error on sending data" :response (pr-str resp))))) -(defn record->report +(defn- record->report [{:keys [::l/context ::l/id ::l/cause] :as record}] (assert (l/valid-record? record) "expectd valid log record") {:id id @@ -64,14 +64,21 @@ :logger (::l/logger record) :trace (ex/format-throwable cause :detail? false :header? false)}) -(defn handle-event +(defn- handle-log-record [cfg record] - (when @enabled - (try - (let [report (record->report record)] - (send-mattermost-notification! cfg report)) - (catch Throwable cause - (l/warn :hint "unhandled error" :cause cause))))) + (try + (let [report (record->report record)] + (send-mattermost-notification! cfg report)) + (catch Throwable cause + (l/warn :hint "unhandled error" :cause cause)))) + +(defn- handle-audit-event + [cfg record] + #_(try + (let [report (audit-event->report record)] + (send-mattermost-notification! cfg report)) + (catch Throwable cause + (l/warn :hint "unhandled error" :cause cause)))) (defmethod ig/assert-key ::reporter [_ params] @@ -80,27 +87,43 @@ (defmethod ig/init-key ::reporter [_ cfg] (when-let [uri (cf/get :error-report-webhook)] - (px/thread - {:name "penpot/mattermost-reporter" - :virtual true} - (l/info :hint "initializing error reporter" :uri uri) - (let [input (sp/chan :buf (sp/sliding-buffer 128) - :xf (filter ldb/error-record?))] - (add-watch l/log-record ::reporter #(sp/put! input %4)) - (try - (loop [] - (when-let [msg (sp/take! input)] - (handle-event cfg msg) - (recur))) - (catch InterruptedException _ - (l/debug :hint "reporter interrupted")) - (catch Throwable cause - (l/error :hint "unexpected error" :cause cause)) - (finally - (sp/close! input) - (remove-watch l/log-record ::reporter) - (l/info :hint "reporter terminated"))))))) + (let [input (sp/chan :buf (sp/sliding-buffer 256)) + thread (px/thread + {:name "penpot/reporter/mattermost"} + (l/info :hint "initializing error reporter" :uri uri) + + (try + (loop [] + (when-let [item (sp/take! input)] + (when @enabled + (cond + (::l/id item) + (handle-log-record cfg item) + + (::audit/id item) + (handle-audit-event cfg item) + + :else + (l/warn :hint "received unexpected item" :item item))) + + (recur))) + (catch InterruptedException _ + (l/debug :hint "reporter interrupted")) + (catch Throwable cause + (l/error :hint "unexpected error" :cause cause)) + (finally + (l/info :hint "reporter terminated"))))] + + (add-watch l/log-record ::reporter + (fn [_ _ _ record] + (when (= :error (::l/level record)) + (sp/put! input record)))) + + {::input input + ::thread thread}))) (defmethod ig/halt-key! ::reporter - [_ thread] + [_ {:keys [::input ::thread]}] + (remove-watch l/log-record ::reporter) + (some-> input sp/close!) (some-> thread px/interrupt!)) diff --git a/backend/src/app/main.clj b/backend/src/app/main.clj index 1fa26fabe1..9de565c043 100644 --- a/backend/src/app/main.clj +++ b/backend/src/app/main.clj @@ -337,7 +337,10 @@ ::setup/props (ig/ref ::setup/props) ::email/blacklist (ig/ref ::email/blacklist) - ::email/whitelist (ig/ref ::email/whitelist)} + ::email/whitelist (ig/ref ::email/whitelist) + + :app.loggers.database/reporter + (ig/ref :app.loggers.database/reporter)} :app.rpc/management-methods {::http.client/client (ig/ref ::http.client/client) diff --git a/backend/src/app/rpc/commands/audit.clj b/backend/src/app/rpc/commands/audit.clj index 9cfdf934bd..37d2187175 100644 --- a/backend/src/app/rpc/commands/audit.clj +++ b/backend/src/app/rpc/commands/audit.clj @@ -16,6 +16,7 @@ [app.db :as db] [app.http :as-alias http] [app.loggers.audit :as-alias audit] + [app.loggers.database :as loggers.db] [app.rpc :as-alias rpc] [app.rpc.climit :as-alias climit] [app.rpc.doc :as-alias doc] @@ -36,42 +37,35 @@ :context]) (defn- event->row [event] - [(uuid/next) - (:name event) - (:source event) - (:type event) - (:timestamp event) - (:created-at event) - (:profile-id event) - (db/inet (:ip-addr event)) - (db/tjson (:props event)) - (db/tjson (d/without-nils (:context event)))]) + [(::audit/id event) + (::audit/name event) + (::audit/source event) + (::audit/type event) + (::audit/tracked-at event) + (::audit/created-at event) + (::audit/profile-id event) + (db/inet (::audit/ip-addr event)) + (db/tjson (::audit/props event)) + (db/tjson (d/without-nils (::audit/context event)))]) (defn- adjust-timestamp - [{:keys [timestamp created-at] :as event}] - (let [margin (inst-ms (ct/diff timestamp created-at))] + [{:keys [::audit/tracked-at ::audit/created-at] :as event}] + (let [margin (inst-ms (ct/diff tracked-at created-at))] (if (or (neg? margin) (> margin 3600000)) ;; If event is in future or lags more than 1 hour, we reasign - ;; timestamp to the server creation date + ;; tracked-at to the server creation date (-> event - (assoc :timestamp created-at) - (update :context assoc :original-timestamp timestamp)) + (assoc ::audit/tracked-at created-at) + (update ::audit/context assoc :original-tracked-at tracked-at)) event))) - -(defn- excepition-event? - [{:keys [type name]}] +(defn- exception-event? + [{:keys [::audit/type ::audit/name] :as ev}] (and (= "action" type) (or (= "unhandled-exception" name) (= "exception-page" name)))) - -(defn persist-report - [{:keys [::db/pool]} event] - ) - - (def ^:private xf:map-event-row (comp (map adjust-timestamp) @@ -81,12 +75,18 @@ [{:keys [::rpc/request-at ::rpc/profile-id events] :as params}] (let [request (-> params meta ::http/request) ip-addr (inet/parse-request request) + xform (map (fn [event] - (-> event - (assoc :created-at request-at) - (assoc :profile-id profile-id) - (assoc :ip-addr ip-addr) - (assoc :source "frontend"))))] + {::audit/id (uuid/next) + ::audit/type (:type event) + ::audit/name (:name event) + ::audit/props (:props event) + ::audit/context (:context event) + ::audit/profile-id profile-id + ::audit/ip-addr ip-addr + ::audit/source "frontend" + ::audit/tracked-at (:timestamp event) + ::audit/created-at request-at}))] (sequence xform events))) @@ -95,8 +95,9 @@ (let [events (get-events params)] ;; Look for error reports and save them on internal reports table - (->> (filter excepition-event? events) - (run! (partial persist-report cfg))) + (->> events + (sequence (filter exception-event?)) + (run! (partial loggers.db/emit cfg))) ;; Process and save events (when (seq events) @@ -106,7 +107,7 @@ (def ^:private valid-event-types #{"action" "identify"}) -(def ^:private schema:event +(def ^:private schema:frontend-event [:map {:title "Event"} [:name [:and {:gen/elements ["update-file", "get-profile"]} @@ -118,12 +119,13 @@ [::sm/one-of {:format "string"} valid-event-types]]] [:props [:map-of :keyword ::sm/any]] + [:timestamp ::ct/inst] [:context {:optional true} [:map-of :keyword ::sm/any]]]) (def ^:private schema:push-audit-events [:map {:title "push-audit-events"} - [:events [:vector schema:event]]]) + [:events [:vector schema:frontend-event]]]) (sv/defmethod ::push-audit-events {::climit/id :submit-audit-events/by-profile diff --git a/backend/src/app/util/template.clj b/backend/src/app/util/template.clj index 2365423349..5fa96df582 100644 --- a/backend/src/app/util/template.clj +++ b/backend/src/app/util/template.clj @@ -11,7 +11,8 @@ [selmer.filters :as sf] [selmer.parser :as sp])) -;; (sp/cache-off!) + +(sp/cache-off!) (sf/add-filter! :abbreviate (fn [s n] diff --git a/frontend/src/app/main/ui/dashboard/projects.cljs b/frontend/src/app/main/ui/dashboard/projects.cljs index 04ca802352..1127cbc65b 100644 --- a/frontend/src/app/main/ui/dashboard/projects.cljs +++ b/frontend/src/app/main/ui/dashboard/projects.cljs @@ -181,6 +181,7 @@ (fn [origin] (let [mdata {:on-success on-file-created} params {:project-id project-id}] + (assert (= 1 2) "foo") (st/emit! (-> (dd/create-file (with-meta params mdata)) (with-meta {::ev/origin origin :has-files (> file-count 0)}))))))