diff --git a/backend/resources/log4j2-devenv.xml b/backend/resources/log4j2-devenv.xml index 7f7ba7b1f..eb38cb183 100644 --- a/backend/resources/log4j2-devenv.xml +++ b/backend/resources/log4j2-devenv.xml @@ -32,6 +32,10 @@ + + + + diff --git a/backend/resources/log4j2.xml b/backend/resources/log4j2.xml index 660f8075a..96750c045 100644 --- a/backend/resources/log4j2.xml +++ b/backend/resources/log4j2.xml @@ -14,6 +14,10 @@ + + + + diff --git a/backend/src/app/http.clj b/backend/src/app/http.clj index dacd4d050..011cd391f 100644 --- a/backend/src/app/http.clj +++ b/backend/src/app/http.clj @@ -127,7 +127,10 @@ (rr/router [["/metrics" {:get (:handler metrics)}] ["/assets" {:middleware [[middleware/format-response-body] - [middleware/errors errors/handle]]} + [middleware/errors errors/handle] + [middleware/cookies] + (:middleware session) + middleware/activity-logger]} ["/by-id/:id" {:get (:objects-handler assets)}] ["/by-file-media-id/:id" {:get (:file-objects-handler assets)}] ["/by-file-media-id/:id/thumbnail" {:get (:file-thumbnails-handler assets)}]] @@ -161,6 +164,8 @@ ["/github" {:post (get-in oauth [:github :handler])}] ["/github/callback" {:get (get-in oauth [:github :callback-handler])}]] - ["/rpc" {:middleware [(:middleware session)]} + ["/rpc" {:middleware [(:middleware session) + middleware/activity-logger]} + ["/query/:type" {:get (:query-handler rpc)}] ["/mutation/:type" {:post (:mutation-handler rpc)}]]]])) diff --git a/backend/src/app/http/middleware.clj b/backend/src/app/http/middleware.clj index 1cfc7459d..c281a4bf0 100644 --- a/backend/src/app/http/middleware.clj +++ b/backend/src/app/http/middleware.clj @@ -11,6 +11,7 @@ (:require [app.metrics :as mtx] [app.util.json :as json] + [app.util.logging :as l] [app.util.transit :as t] [buddy.core.codecs :as bc] [buddy.core.hash :as bh] @@ -165,3 +166,18 @@ (def etag {:name ::etag :compile (constantly wrap-etag)}) + +(defn activity-logger + [handler] + (let [logger "penpot.profile-activity"] + (fn [{:keys [headers] :as request}] + (let [ip-addr (get headers "x-forwarded-for") + profile-id (:profile-id request) + qstring (:query-string request)] + (l/info ::l/async true + ::l/logger logger + :ip-addr ip-addr + :profile-id profile-id + :uri (str (:uri request) (if qstring (str "?" qstring))) + :method (name (:request-method request))) + (handler request))))) diff --git a/backend/src/app/http/session.clj b/backend/src/app/http/session.clj index 8eb09eb9d..1c0dca885 100644 --- a/backend/src/app/http/session.clj +++ b/backend/src/app/http/session.clj @@ -65,8 +65,8 @@ [cfg handler] (fn [request] (if-let [{:keys [id profile-id] :as session} (retrieve-from-request cfg request)] - (let [ech (::events-ch cfg)] - (a/>!! ech id) + (let [events-ch (::events-ch cfg)] + (a/>!! events-ch id) (l/update-thread-context! {:profile-id profile-id}) (handler (assoc request :profile-id profile-id))) (handler request)))) @@ -109,6 +109,7 @@ [_ data] (a/close! (::events-ch data))) + ;; --- STATE INIT: SESSION UPDATER (declare batch-events) @@ -145,10 +146,10 @@ (let [result (a/ options extract-props db/tjson) id (uuid/next)] - (l/log :level :debug - :action "submit task" - :name (d/name task) - :in duration) + (l/debug :action "submit task" + :name (d/name task) + :in duration) (db/exec-one! conn [sql:insert-new-task id (d/name task) props (d/name queue) priority max-retries interval]) id)) -;; --- RUNNER +;; --- RUNNER (def ^:private sql:mark-as-retry @@ -249,9 +246,8 @@ (let [task-fn (get tasks name)] (if task-fn (task-fn item) - (l/log :level :warn - :msg "no task handler found" - :name (d/name name))) + (l/warn :msg "no task handler found" + :name (d/name name))) {:status :completed :task item})) (defn get-error-context @@ -276,10 +272,9 @@ (let [cdata (get-error-context error item)] (l/update-thread-context! cdata) - (l/log :level :error - :cause error - :hint "unhandled exception on task" - :id (:id cdata)) + (l/error :cause error + :hint "unhandled exception on task" + :id (:id cdata)) (if (>= (:retry-num item) (:max-retries item)) {:status :failed :task item :error error} @@ -289,21 +284,19 @@ [{:keys [tasks]} item] (let [name (d/name (:name item))] (try - (l/log :level :debug - :action "start task" - :name name - :id (:id item) - :retry (:retry-num item)) + (l/debug :action "start task" + :name name + :id (:id item) + :retry (:retry-num item)) (handle-task tasks item) (catch Exception e (handle-exception e item)) (finally - (l/log :level :debug - :action "start task" - :name name - :id (:id item) - :retry (:retry-num item)))))) + (l/debug :action "end task" + :name name + :id (:id item) + :retry (:retry-num item)))))) (def sql:select-next-tasks "select * from task as t @@ -407,12 +400,8 @@ (defn- synchronize-schedule-item [conn {:keys [id cron]}] - (let [cron (str cron) - id (name id)] - (l/log :level :debug - :action "initialize scheduled task" - :id id - :cron cron) + (let [cron (str cron)] + (l/debug :action "initialize scheduled task" :id id :cron cron) (db/exec-one! conn [sql:upsert-scheduled-task id cron cron]))) (defn- synchronize-schedule @@ -433,9 +422,7 @@ (letfn [(run-task [conn] (try (when (db/exec-one! conn [sql:lock-scheduled-task (d/name id)]) - (l/log :level :debug - :action "execute scheduled task" - :id id) + (l/debug :action "execute scheduled task" :id id) ((:fn task) task)) (catch Throwable e e))) @@ -444,10 +431,9 @@ (db/with-atomic [conn pool] (let [result (run-task conn)] (when (ex/exception? result) - (l/log :level :error - :cause result - :hint "unhandled exception on scheduled task" - :id id)))))] + (l/error :cause result + :hint "unhandled exception on scheduled task" + :id id)))))] (try (px/run! executor handle-task) @@ -520,9 +506,7 @@ :help "Background task execution timing."})] (reduce-kv (fn [res k v] (let [tname (name k)] - (l/log :level :debug - :action "register task" - :name tname) + (l/debug :action "register task" :name tname) (assoc res k (mtx/wrap-summary v mobj [tname])))) {} tasks)))