From a63f28a2e50af78314359f6c1d48b715eb11b0f7 Mon Sep 17 00:00:00 2001
From: Andrey Antukh <niwi@niwi.nz>
Date: Mon, 22 Feb 2021 12:39:55 +0100
Subject: [PATCH] :sparkles: Normalize logging messages on backend.

---
 backend/src/app/cli/fixtures.clj          |  2 +-
 backend/src/app/http/awsns.clj            | 10 +++++-----
 backend/src/app/http/errors.clj           |  4 ++--
 backend/src/app/loggers/loki.clj          |  8 ++++----
 backend/src/app/loggers/mattermost.clj    | 10 +++++-----
 backend/src/app/loggers/zmq.clj           |  2 +-
 backend/src/app/main.clj                  |  2 +-
 backend/src/app/notifications.clj         |  2 +-
 backend/src/app/rpc.clj                   |  4 ++--
 backend/src/app/rpc/mutations/ldap.clj    |  2 +-
 backend/src/app/rpc/mutations/profile.clj |  1 -
 backend/src/app/tasks/delete_object.clj   |  2 +-
 backend/src/app/tasks/delete_profile.clj  |  2 +-
 backend/src/app/tasks/file_media_gc.clj   |  2 +-
 backend/src/app/telemetry.clj             |  4 ++--
 backend/src/app/worker.clj                | 22 +++++++++++-----------
 16 files changed, 39 insertions(+), 40 deletions(-)

diff --git a/backend/src/app/cli/fixtures.clj b/backend/src/app/cli/fixtures.clj
index 4400654c6..ed986d36d 100644
--- a/backend/src/app/cli/fixtures.clj
+++ b/backend/src/app/cli/fixtures.clj
@@ -237,6 +237,6 @@
     (try
       (run-in-system system preset)
       (catch Exception e
-        (log/errorf e "Unhandled exception."))
+        (log/errorf e "unhandled exception"))
       (finally
         (ig/halt! system)))))
diff --git a/backend/src/app/http/awsns.clj b/backend/src/app/http/awsns.clj
index 9443b90eb..8a776477d 100644
--- a/backend/src/app/http/awsns.clj
+++ b/backend/src/app/http/awsns.clj
@@ -42,7 +42,7 @@
         (= mtype "SubscriptionConfirmation")
         (let [surl   (get body "SubscribeURL")
               stopic (get body "TopicArn")]
-          (log/infof "Subscription received (topic=%s, url=%s)" stopic surl)
+          (log/infof "subscription received (topic=%s, url=%s)" stopic surl)
           (http/send! {:uri surl :method :post :timeout 10000}))
 
         (= mtype "Notification")
@@ -52,7 +52,7 @@
             (process-report cfg notification)))
 
         :else
-        (log/warn (str "Unexpected data received.\n"
+        (log/warn (str "unexpected data received\n"
                        (pprint-report body))))
 
       {:status 200 :body ""})))
@@ -184,14 +184,14 @@
 
 (defn- process-report
   [cfg {:keys [type profile-id] :as report}]
-  (log/debug (str "Procesing report:\n" (pprint-report report)))
+  (log/debug (str "procesing report:\n" (pprint-report report)))
   (cond
     ;; In this case we receive a bounce/complaint notification without
     ;; confirmed identity, we just emit a warning but do nothing about
     ;; it because this is not a normal case. All notifications should
     ;; come with profile identity.
     (nil? profile-id)
-    (log/warn (str "A notification without identity recevied from AWS\n"
+    (log/warn (str "a notification without identity recevied from AWS\n"
                    (pprint-report report)))
 
     (= "bounce" type)
@@ -201,7 +201,7 @@
     (register-complaint-for-profile cfg report)
 
     :else
-    (log/warn (str "Unrecognized report received from AWS\n"
+    (log/warn (str "unrecognized report received from AWS\n"
                    (pprint-report report)))))
 
 
diff --git a/backend/src/app/http/errors.clj b/backend/src/app/http/errors.clj
index 020ebc921..72fa34a65 100644
--- a/backend/src/app/http/errors.clj
+++ b/backend/src/app/http/errors.clj
@@ -73,7 +73,7 @@
   (let [edata (ex-data error)
         cdata (get-error-context request error)]
     (update-thread-context! cdata)
-    (log/errorf error "Internal error: assertion (id: %s)" (str (:id cdata)))
+    (log/errorf error "internal error: assertion (id: %s)" (str (:id cdata)))
     {:status 500
      :body {:type :server-error
             :data (-> edata
@@ -88,7 +88,7 @@
   [error request]
   (let [cdata (get-error-context request error)]
     (update-thread-context! cdata)
-    (log/errorf error "Internal error: %s (id: %s)"
+    (log/errorf error "internal error: %s (id: %s)"
                 (ex-message error)
                 (str (:id cdata)))
     {:status 500
diff --git a/backend/src/app/loggers/loki.clj b/backend/src/app/loggers/loki.clj
index 32813e5ec..2514d5725 100644
--- a/backend/src/app/loggers/loki.clj
+++ b/backend/src/app/loggers/loki.clj
@@ -33,13 +33,13 @@
 (defmethod ig/init-key ::reporter
   [_ {:keys [receiver uri] :as cfg}]
   (when uri
-    (log/info "Intializing loki reporter.")
+    (log/info "intializing loki reporter")
     (let [output (a/chan (a/sliding-buffer 1024))]
       (receiver :sub output)
       (a/go-loop []
         (let [msg (a/<! output)]
           (if (nil? msg)
-            (log/info "Stoping error reporting loop.")
+            (log/info "stoping error reporting loop")
             (do
               (a/<! (handle-event cfg msg))
               (recur)))))
@@ -75,10 +75,10 @@
       (if (= (:status response) 204)
         true
         (do
-          (log/errorf "Error on sending log to loki (try %s).\n%s" i (pr-str response))
+          (log/errorf "error on sending log to loki (try %s)\n%s" i (pr-str response))
           false)))
     (catch Exception e
-      (log/errorf e "Error on sending message to loki (try %s)." i)
+      (log/errorf e "error on sending message to loki (try %s)" i)
       false)))
 
 (defn- handle-event
diff --git a/backend/src/app/loggers/mattermost.clj b/backend/src/app/loggers/mattermost.clj
index 2b95a0d3d..c2247e71e 100644
--- a/backend/src/app/loggers/mattermost.clj
+++ b/backend/src/app/loggers/mattermost.clj
@@ -43,14 +43,14 @@
 
 (defmethod ig/init-key ::reporter
   [_ {:keys [receiver] :as cfg}]
-  (log/info "Intializing mattermost error reporter.")
+  (log/info "intializing mattermost error reporter")
   (let [output (a/chan (a/sliding-buffer 128)
                        (filter #(= (:level %) "error")))]
     (receiver :sub output)
     (a/go-loop []
       (let [msg (a/<! output)]
         (if (nil? msg)
-          (log/info "Stoping error reporting loop.")
+          (log/info "stoping error reporting loop")
           (do
             (a/<! (handle-event cfg msg))
             (recur)))))
@@ -75,10 +75,10 @@
                               :headers {"content-type" "application/json"}
                               :body (json/encode-str {:text text})})]
       (when (not= (:status rsp) 200)
-        (log/errorf "Error on sending data to mattermost\n%s" (pr-str rsp))))
+        (log/errorf "error on sending data to mattermost\n%s" (pr-str rsp))))
 
     (catch Exception e
-      (log/error e "Unexpected exception on error reporter."))))
+      (log/error e "unexpected exception on error reporter"))))
 
 (defn- persist-on-database!
   [{:keys [pool] :as cfg} {:keys [id] :as cdata}]
@@ -116,7 +116,7 @@
           (send-mattermost-notification! cfg cdata))
         (persist-on-database! cfg cdata))
       (catch Exception e
-        (log/error e "Unexpected exception on error reporter.")))))
+        (log/error e "unexpected exception on error reporter")))))
 
 ;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;
 ;; Http Handler
diff --git a/backend/src/app/loggers/zmq.clj b/backend/src/app/loggers/zmq.clj
index 834212cc8..9f1b8287c 100644
--- a/backend/src/app/loggers/zmq.clj
+++ b/backend/src/app/loggers/zmq.clj
@@ -34,7 +34,7 @@
 
 (defmethod ig/init-key ::receiver
   [_ {:keys [endpoint] :as cfg}]
-  (log/infof "Intializing ZMQ receiver on '%s'." endpoint)
+  (log/infof "intializing ZMQ receiver on '%s'" endpoint)
   (let [buffer (a/chan 1)
         output (a/chan 1 (comp (filter map?)
                                (map prepare)))
diff --git a/backend/src/app/main.clj b/backend/src/app/main.clj
index c9bc23ce0..9ed384a8d 100644
--- a/backend/src/app/main.clj
+++ b/backend/src/app/main.clj
@@ -335,7 +335,7 @@
                                (-> system-config
                                    (ig/prep)
                                    (ig/init))))
-    (log/infof "Welcome to penpot! Version: '%s'."
+    (log/infof "welcome to penpot (version: '%s')"
                (:full cfg/version))))
 
 (defn stop
diff --git a/backend/src/app/notifications.clj b/backend/src/app/notifications.clj
index 4ff66aac8..4b9a72ce1 100644
--- a/backend/src/app/notifications.clj
+++ b/backend/src/app/notifications.clj
@@ -188,7 +188,7 @@
       (aa/<? (start-loop! ws))
       (aa/<? (handle-message ws {:type :disconnect}))
       (catch Throwable err
-        (log/errorf err "Unexpected exception on websocket handler.")
+        (log/errorf err "unexpected exception on websocket handler")
         (let [session (.getSession ^WebSocketAdapter conn)]
           (when session
             (.disconnect session)))))))
diff --git a/backend/src/app/rpc.clj b/backend/src/app/rpc.clj
index 297d6008f..e768315f2 100644
--- a/backend/src/app/rpc.clj
+++ b/backend/src/app/rpc.clj
@@ -66,7 +66,7 @@
         (ex/raise :type :internal
                   :code :rlimit-not-configured
                   :hint (str/fmt "%s rlimit not configured" key)))
-      (log/tracef "Adding rlimit to '%s' rpc handler." (::sv/name mdata))
+      (log/tracef "adding rlimit to '%s' rpc handler" (::sv/name mdata))
       (fn [cfg params]
         (rlm/execute rlinst (f cfg params))))
     f))
@@ -76,7 +76,7 @@
   (let [f     (wrap-with-rlimits cfg f mdata)
         f     (wrap-with-metrics cfg f mdata)
         spec  (or (::sv/spec mdata) (s/spec any?))]
-    (log/tracef "Registering '%s' command to rpc service." (::sv/name mdata))
+    (log/tracef "registering '%s' command to rpc service" (::sv/name mdata))
     (fn [params]
       (when (and (:auth mdata true) (not (uuid? (:profile-id params))))
         (ex/raise :type :authentication
diff --git a/backend/src/app/rpc/mutations/ldap.clj b/backend/src/app/rpc/mutations/ldap.clj
index e8edfc879..704e49a2d 100644
--- a/backend/src/app/rpc/mutations/ldap.clj
+++ b/backend/src/app/rpc/mutations/ldap.clj
@@ -30,7 +30,7 @@
       (try
         (ldap/connect params)
         (catch Exception e
-          (log/errorf e "Cannot connect to LDAP %s:%s"
+          (log/errorf e "cannot connect to LDAP %s:%s"
                       (get-in params [:host :address])
                       (get-in params [:host :port])))))))
 
diff --git a/backend/src/app/rpc/mutations/profile.clj b/backend/src/app/rpc/mutations/profile.clj
index 339738d57..2c63e6ef6 100644
--- a/backend/src/app/rpc/mutations/profile.clj
+++ b/backend/src/app/rpc/mutations/profile.clj
@@ -143,7 +143,6 @@
   (try
     (hashers/verify attempt password)
     (catch Exception e
-      (log/warnf e "Error on verify password (only informative, nothing affected to user).")
       {:update false
        :valid false})))
 
diff --git a/backend/src/app/tasks/delete_object.clj b/backend/src/app/tasks/delete_object.clj
index a65a75b1e..602c7182c 100644
--- a/backend/src/app/tasks/delete_object.clj
+++ b/backend/src/app/tasks/delete_object.clj
@@ -47,7 +47,7 @@
 
 (defmethod handle-deletion :default
   [_conn {:keys [type]}]
-  (log/warnf "no handler found for %s" type))
+  (log/warnf "no handler found for '%s'" type))
 
 (defmethod handle-deletion :file
   [conn {:keys [id] :as props}]
diff --git a/backend/src/app/tasks/delete_profile.clj b/backend/src/app/tasks/delete_profile.clj
index 2f8a2a668..f2b2030a6 100644
--- a/backend/src/app/tasks/delete_profile.clj
+++ b/backend/src/app/tasks/delete_profile.clj
@@ -80,7 +80,7 @@
 
 (defn- delete-profile-data
   [conn profile-id]
-  (log/infof "Proceding to delete all data related to profile id = %s" profile-id)
+  (log/debugf "proceding to delete all data related to profile '%s'" profile-id)
   (delete-teams conn profile-id)
   (delete-profile conn profile-id)
   true)
diff --git a/backend/src/app/tasks/file_media_gc.clj b/backend/src/app/tasks/file_media_gc.clj
index dd9939e0f..f13f244c0 100644
--- a/backend/src/app/tasks/file_media_gc.clj
+++ b/backend/src/app/tasks/file_media_gc.clj
@@ -98,7 +98,7 @@
         unused (->> (db/query conn :file-media-object {:file-id id})
                     (remove #(contains? used (:id %))))]
 
-    (log/infof "processing file: id='%s' age='%s' to-delete=%s" id age (count unused))
+    (log/debugf "processing file: id='%s' age='%s' to-delete=%s" id age (count unused))
 
     ;; Mark file as trimmed
     (db/update! conn :file
diff --git a/backend/src/app/telemetry.clj b/backend/src/app/telemetry.clj
index a8e5edae7..a5268ef23 100644
--- a/backend/src/app/telemetry.clj
+++ b/backend/src/app/telemetry.clj
@@ -88,7 +88,7 @@
     (catch Exception e
       ;; We don't want notify user of a error, just log it for posible
       ;; future investigation.
-      (log/warn e (str "Unexpected error on telemetry:\n"
+      (log/warn e (str "unexpected error on telemetry:\n"
                        (when-let [edata (ex-data e)]
                          (str "ex-data: \n"
                               (with-out-str (pprint edata))))
@@ -118,4 +118,4 @@
                         data
                         data])))
     (catch Exception e
-      (log/errorf e "Error on procesing request."))))
+      (log/errorf e "error on procesing request"))))
diff --git a/backend/src/app/worker.clj b/backend/src/app/worker.clj
index 306604b81..9b7cdc478 100644
--- a/backend/src/app/worker.clj
+++ b/backend/src/app/worker.clj
@@ -94,7 +94,7 @@
 
 (defmethod ig/init-key ::worker
   [_ {:keys [pool poll-interval name queue] :as cfg}]
-  (log/infof "Starting worker '%s' on queue '%s'." name queue)
+  (log/infof "starting worker '%s' on queue '%s'" name queue)
   (let [cch     (a/chan 1)
         poll-ms (inst-ms poll-interval)]
     (a/go-loop []
@@ -103,30 +103,30 @@
           ;; Terminate the loop if close channel is closed or
           ;; event-loop-fn returns nil.
           (or (= port cch) (nil? val))
-          (log/infof "Stop condition found. Shutdown worker: '%s'" name)
+          (log/infof "stop condition found; shutdown worker: '%s'" name)
 
           (db/pool-closed? pool)
           (do
-            (log/info "Worker eventloop is aborted because pool is closed.")
+            (log/info "worker eventloop is aborted because pool is closed")
             (a/close! cch))
 
           (and (instance? java.sql.SQLException val)
                (contains? #{"08003" "08006" "08001" "08004"} (.getSQLState ^java.sql.SQLException val)))
           (do
-            (log/error "Connection error, trying resume in some instants.")
+            (log/error "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
-            (log/debug "Serialization failure (retrying in some instants).")
+            (log/debug "serialization failure (retrying in some instants)")
             (a/<! (a/timeout poll-ms))
             (recur))
 
           (instance? Exception val)
           (do
-            (log/errorf val "Unexpected error ocurried on polling the database (will resume in some instants).")
+            (log/errorf val "unexpected error ocurried on polling the database (will resume in some instants)")
             (a/<! (a/timeout poll-ms))
             (recur))
 
@@ -202,7 +202,7 @@
   (let [task-fn (get tasks name)]
     (if task-fn
       (task-fn item)
-      (log/warn "no task handler found for" (pr-str name)))
+      (log/warnf "no task handler found for '%s'" (pr-str name)))
     {:status :completed :task item}))
 
 (defn get-error-context
@@ -227,7 +227,7 @@
 
       (let [cdata (get-error-context error item)]
         (update-thread-context! cdata)
-        (log/errorf error "Unhandled exception on task (id: %s)" (:id cdata))
+        (log/errorf error "unhandled exception on task (id: '%s')" (:id cdata))
         (if (>= (:retry-num item) (:max-retries item))
           {:status :failed :task item :error error}
           {:status :retry :task item :error error})))))
@@ -235,12 +235,12 @@
 (defn- run-task
   [{:keys [tasks]} item]
   (try
-    (log/debugf "Started task '%s/%s/%s'." (:name item) (:id item) (:retry-num item))
+    (log/debugf "started task '%s/%s/%s'" (:name item) (:id item) (:retry-num item))
     (handle-task tasks item)
     (catch Exception e
       (handle-exception e item))
     (finally
-      (log/debugf "Finished task '%s/%s/%s'." (:name item) (:id item) (:retry-num item)))))
+      (log/debugf "finished task '%s/%s/%s'" (:name item) (:id item) (:retry-num item)))))
 
 (def sql:select-next-tasks
   "select * from task as t
@@ -330,7 +330,7 @@
 (defn- synchronize-schedule-item
   [conn {:keys [id cron]}]
   (let [cron (str cron)]
-    (log/debugf "initialize scheduled task '%s' (cron: '%s')." id cron)
+    (log/infof "initialize scheduled task '%s' (cron: '%s')" id cron)
     (db/exec-one! conn [sql:upsert-scheduled-task id cron cron])))
 
 (defn- synchronize-schedule