🎉 Add profile activity registry logger.

backend/resources/log4j2-devenv.xml

@@ -32,6 +32,10 @@
       <AppenderRef ref="main" level="trace" />
     </Logger>
 
+    <Logger name="penpot" level="fatal" additivity="false">
+      <AppenderRef ref="main" level="fatal" />
+    </Logger>
+
     <Logger name="user" level="trace" additivity="false">
       <AppenderRef ref="main" level="trace" />
     </Logger>

backend/resources/log4j2.xml

@@ -14,6 +14,10 @@
       <AppenderRef ref="console" />
     </Logger>
 
+    <Logger name="penpot" level="fatal" additivity="false">
+      <AppenderRef ref="console" />
+    </Logger>
+
     <Root level="info">
       <AppenderRef ref="console" />
     </Root>

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)}]]]]))

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)))))

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)]
+      (let [events-ch (::events-ch cfg)]
-        (a/>!! ech id)
+        (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/<! (update-sessions cfg batch))]
           (mcnt :inc)
           (if (ex/exception? result)
-            (l/error :mod "updater"
+            (l/error :task "updater"
                      :hint "unexpected error on update sessions"
                      :cause result)
-            (l/debug :mod "updater"
+            (l/debug :task "updater"
                      :action "update sessions"
                      :reason (name reason)
                      :count result))
@@ -213,7 +214,7 @@
       (let [interval (db/interval max-age)
             result   (db/exec-one! conn [sql:delete-expired interval])
             result   (:next.jdbc/update-count result)]
-        (l/debug :mod "gc-task"
+        (l/debug :task "gc"
                  :action "clean http sessions"
                  :count result)
         result))))

backend/src/app/worker.clj

@@ -90,10 +90,9 @@
 
 (defmethod ig/init-key ::worker
   [_ {:keys [pool poll-interval name queue] :as cfg}]
-  (l/log :level :info
+  (l/info :action "start worker"
-         :msg "start"
+          :name (d/name name)
-         :name (d/name name)
+          :queue (d/name queue))
-         :queue (d/name queue))
   (let [close-ch (a/chan 1)
         poll-ms  (inst-ms poll-interval)]
     (a/go-loop []
@@ -102,32 +101,31 @@
           ;; Terminate the loop if close channel is closed or
           ;; event-loop-fn returns nil.
           (or (= port close-ch) (nil? val))
-          (l/log :level :debug :msg "stop condition found")
+          (l/debug :msg "stop condition found")
 
           (db/pool-closed? pool)
           (do
-            (l/log :level :debug :msg "eventloop aboirted because pool is closed")
+            (l/debug :msg "eventloop aborted because pool is closed")
             (a/close! close-ch))
 
           (and (instance? java.sql.SQLException val)
                (contains? #{"08003" "08006" "08001" "08004"} (.getSQLState ^java.sql.SQLException val)))
           (do
-            (l/log :level :error :hint "connection error, trying resume in some instants")
+            (l/error :hint "connection error, trying resume in some instants")
             (a/<! (a/timeout poll-interval))
             (recur))
 
           (and (instance? java.sql.SQLException val)
                (= "40001" (.getSQLState ^java.sql.SQLException val)))
           (do
-            (l/log :level :debug :msg "serialization failure (retrying in some instants)")
+            (l/debug :msg "serialization failure (retrying in some instants)")
             (a/<! (a/timeout poll-ms))
             (recur))
 
           (instance? Exception val)
           (do
-            (l/log :level :error
+            (l/error :cause val
-                   :cause val
+                     :hint "unexpected error ocurried on polling the database (will resume in some instants)")
-                   :hint "unexpected error ocurried on polling the database (will resume in some instants)")
             (a/<! (a/timeout poll-ms))
             (recur))
 
@@ -185,15 +183,14 @@
         interval  (db/interval duration)
         props     (-> options extract-props db/tjson)
         id        (uuid/next)]
-    (l/log :level :debug
+    (l/debug :action "submit task"
-           :action "submit task"
+             :name (d/name task)
-           :name (d/name task)
+             :in duration)
-           :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
+      (l/warn :msg "no task handler found"
-             :msg "no task handler found"
+              :name (d/name name)))
-             :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
+        (l/error :cause error
-               :cause error
+                 :hint "unhandled exception on task"
-               :hint "unhandled exception on task"
+                 :id (:id cdata))
-               :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
+      (l/debug :action "start task"
-             :action "start task"
+               :name name
-             :name name
+               :id (:id item)
-             :id (:id item)
+               :retry (:retry-num item))
-             :retry (:retry-num item))
 
       (handle-task tasks item)
       (catch Exception e
         (handle-exception e item))
       (finally
-        (l/log :level :debug
+        (l/debug :action "end task"
-               :action "start task"
+                 :name name
-               :name name
+                 :id (:id item)
-               :id (:id item)
+                 :retry (:retry-num 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)
+  (let [cron (str cron)]
-        id   (name id)]
+    (l/debug :action "initialize scheduled task" :id id :cron cron)
-    (l/log :level :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
+                (l/debug :action "execute scheduled task" :id id)
-                       :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
+                  (l/error :cause result
-                         :cause result
+                           :hint "unhandled exception on scheduled task"
-                         :hint "unhandled exception on scheduled task"
+                           :id id)))))]
-                         :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
+                   (l/debug :action "register task" :name tname)
-                          :action "register task"
-                          :name tname)
                    (assoc res k (mtx/wrap-summary v mobj [tname]))))
                {}
                tasks)))