From 1e8226a3fcc1bb97fe1f17be7113a87f79bb99ba Mon Sep 17 00:00:00 2001 From: Andrey Antukh Date: Fri, 1 Sep 2023 13:55:23 +0200 Subject: [PATCH 1/3] :bug: Fix log level setting on file migrations ns --- common/src/app/common/pages/migrations.cljc | 16 ++++++++-------- 1 file changed, 8 insertions(+), 8 deletions(-) diff --git a/common/src/app/common/pages/migrations.cljc b/common/src/app/common/pages/migrations.cljc index 14492b32e..4cfee92b6 100644 --- a/common/src/app/common/pages/migrations.cljc +++ b/common/src/app/common/pages/migrations.cljc @@ -12,7 +12,7 @@ [app.common.geom.shapes :as gsh] [app.common.geom.shapes.path :as gsp] [app.common.geom.shapes.text :as gsht] - [app.common.logging :as log] + [app.common.logging :as l] [app.common.math :as mth] [app.common.pages :as cp] [app.common.pages.helpers :as cph] @@ -25,7 +25,7 @@ (defmulti migrate :version) -(log/set-level! :info) +#?(:cljs (l/set-level! :info)) (defn migrate-data ([data] (migrate-data data cp/file-version)) @@ -33,7 +33,7 @@ (if (= (:version data) to-version) data (let [migrate-fn #(do - (log/trace :hint "migrate file" :id (:id %) :version-from %2 :version-to (inc %2)) + (l/trc :hint "migrate file" :id (:id %) :version-from %2 :version-to (inc %2)) (migrate (assoc %1 :version (inc %2))))] (reduce migrate-fn data (range (:version data 0) to-version)))))) @@ -450,11 +450,11 @@ ;; If we cannot find any we let the frame-id as it was before frame-id)] (when (not= frame-id calculated-frame-id) - (log/info :hint "Fix wrong frame-id" - :shape (:name object) - :id (:id object) - :current (dm/get-in objects [frame-id :name]) - :calculated (get-in objects [calculated-frame-id :name]))) + (l/trc :hint "Fix wrong frame-id" + :shape (:name object) + :id (:id object) + :current (dm/get-in objects [frame-id :name]) + :calculated (get-in objects [calculated-frame-id :name]))) (assoc object :frame-id calculated-frame-id))) (update-container [container] From a23d1908e907043f3d99e819e280e4310ad514a3 Mon Sep 17 00:00:00 2001 From: Andrey Antukh Date: Fri, 1 Sep 2023 13:56:45 +0200 Subject: [PATCH 2/3] :sparkles: Improve worker logging --- backend/src/app/worker.clj | 154 +++++++++++++++++++------------------ 1 file changed, 79 insertions(+), 75 deletions(-) diff --git a/backend/src/app/worker.clj b/backend/src/app/worker.clj index 8bafe3a8a..448fbaaec 100644 --- a/backend/src/app/worker.clj +++ b/backend/src/app/worker.clj @@ -87,10 +87,10 @@ (defmethod ig/init-key ::registry [_ {:keys [::mtx/metrics ::tasks]}] - (l/info :hint "registry initialized" :tasks (count tasks)) + (l/inf :hint "registry initialized" :tasks (count tasks)) (reduce-kv (fn [registry k v] (let [tname (name k)] - (l/trace :hint "register task" :name tname) + (l/trc :hint "register task" :name tname) (assoc registry tname (wrap-task-handler metrics tname v)))) {} tasks)) @@ -141,18 +141,18 @@ (px/thread {:name "penpot/executors-monitor" :virtual true} - (l/info :hint "monitor: started" :name name) + (l/inf :hint "monitor: started" :name name) (try (loop [steals 0] (when-not (px/shutdown? executor) (px/sleep interval) (recur (long (monitor! executor steals))))) (catch InterruptedException _cause - (l/debug :hint "monitor: interrupted" :name name)) + (l/trc :hint "monitor: interrupted" :name name)) (catch Throwable cause - (l/error :hint "monitor: unexpected error" :name name :cause cause)) + (l/err :hint "monitor: unexpected error" :name name :cause cause)) (finally - (l/info :hint "monitor: terminated" :name name)))))) + (l/inf :hint "monitor: terminated" :name name)))))) (defmethod ig/halt-key! ::monitor [_ thread] @@ -207,7 +207,7 @@ (db/create-array conn "uuid" ids)]] (db/exec-one! conn sql) - (l/dbg :hist "dispatcher: queue tasks" + (l/trc :hist "dispatcher: queue tasks" :queue queue :tasks (count ids) :queued res))) @@ -225,35 +225,35 @@ (cond (rds/exception? cause) (do - (l/warn :hint "dispatcher: redis exception (will retry in an instant)" :cause cause) + (l/wrn :hint "dispatcher: redis exception (will retry in an instant)" :cause cause) (px/sleep (::rds/timeout rconn))) (db/sql-exception? cause) (do - (l/warn :hint "dispatcher: database exception (will retry in an instant)" :cause cause) + (l/wrn :hint "dispatcher: database exception (will retry in an instant)" :cause cause) (px/sleep (::rds/timeout rconn))) :else (do - (l/error :hint "dispatcher: unhandled exception (will retry in an instant)" :cause cause) + (l/err :hint "dispatcher: unhandled exception (will retry in an instant)" :cause cause) (px/sleep (::rds/timeout rconn))))))) (dispatcher [] - (l/info :hint "dispatcher: started") + (l/inf :hint "dispatcher: started") (try (dm/with-open [rconn (rds/connect redis)] (loop [] (run-batch! rconn) (recur))) (catch InterruptedException _ - (l/trace :hint "dispatcher: interrupted")) + (l/trc :hint "dispatcher: interrupted")) (catch Throwable cause - (l/error :hint "dispatcher: unexpected exception" :cause cause)) + (l/err :hint "dispatcher: unexpected exception" :cause cause)) (finally - (l/info :hint "dispatcher: terminated"))))] + (l/inf :hint "dispatcher: terminated"))))] (if (db/read-only? pool) - (l/warn :hint "dispatcher: not started (db is read-only)") + (l/wrn :hint "dispatcher: not started (db is read-only)") (px/fn->thread dispatcher :name "penpot/worker/dispatcher" :virtual true)))) (defmethod ig/halt-key! ::dispatcher @@ -286,7 +286,7 @@ (let [queue (d/name queue) cfg (assoc cfg ::queue queue)] (if (db/read-only? pool) - (l/warn :hint "worker: not started (db is read-only)" :queue queue :parallelism parallelism) + (l/wrn :hint "worker: not started (db is read-only)" :queue queue :parallelism parallelism) (doall (->> (range parallelism) (map #(assoc cfg ::worker-id %)) @@ -300,7 +300,7 @@ [{:keys [::rds/redis ::worker-id ::queue] :as cfg}] (px/thread {:name (format "penpot/worker/runner:%s" worker-id)} - (l/info :hint "worker: started" :worker-id worker-id :queue queue) + (l/inf :hint "worker: started" :worker-id worker-id :queue queue) (try (dm/with-open [rconn (rds/connect redis)] (let [tenant (cf/get :tenant "main") @@ -320,14 +320,14 @@ :worker-id worker-id :queue queue)) (catch Throwable cause - (l/error :hint "worker: unexpected exception" - :worker-id worker-id - :queue queue - :cause cause)) + (l/err :hint "worker: unexpected exception" + :worker-id worker-id + :queue queue + :cause cause)) (finally - (l/info :hint "worker: terminated" - :worker-id worker-id - :queue queue))))) + (l/inf :hint "worker: terminated" + :worker-id worker-id + :queue queue))))) (defn- run-worker-loop! [{:keys [::db/pool ::rds/rconn ::timeout ::queue ::registry ::worker-id]}] @@ -368,19 +368,19 @@ (let [task-id (t/decode payload)] (if (uuid? task-id) task-id - (l/error :hint "worker: received unexpected payload (uuid expected)" - :payload task-id))) + (l/err :hint "worker: received unexpected payload (uuid expected)" + :payload task-id))) (catch Throwable cause - (l/error :hint "worker: unable to decode payload" - :payload payload - :length (alength payload) - :cause cause)))) + (l/err :hint "worker: unable to decode payload" + :payload payload + :length (alength payload) + :cause cause)))) (handle-task [{:keys [name] :as task}] (let [task-fn (get registry name)] (if task-fn (task-fn task) - (l/warn :hint "no task handler found" :name name)) + (l/wrn :hint "no task handler found" :name name)) {:status :completed :task task})) (handle-task-exception [cause task] @@ -395,9 +395,9 @@ (= ::noop (:strategy edata)) (assoc :inc-by 0)) (do - (l/error :hint "worker: unhandled exception on task" - ::l/context (get-error-context cause task) - :cause cause) + (l/err :hint "worker: unhandled exception on task" + ::l/context (get-error-context cause task) + :cause cause) (if (>= (:retry-num task) (:max-retries task)) {:status :failed :task task :error cause} {:status :retry :task task :error cause}))))) @@ -414,26 +414,26 @@ (if (or (db/connection-error? task) (db/serialization-error? task)) (do - (l/warn :hint "worker: connection error on retrieving task from database (retrying in some instants)" - :worker-id worker-id - :cause task) + (l/wrn :hint "worker: connection error on retrieving task from database (retrying in some instants)" + :worker-id worker-id + :cause task) (px/sleep (::rds/timeout rconn)) (recur (get-task task-id))) (do - (l/error :hint "worker: unhandled exception on retrieving task from database (retrying in some instants)" - :worker-id worker-id - :cause task) + (l/err :hint "worker: unhandled exception on retrieving task from database (retrying in some instants)" + :worker-id worker-id + :cause task) (px/sleep (::rds/timeout rconn)) (recur (get-task task-id)))) (nil? task) - (l/warn :hint "worker: no task found on the database" - :worker-id worker-id - :task-id task-id) + (l/wrn :hint "worker: no task found on the database" + :worker-id worker-id + :task-id task-id) :else (try - (l/dbg :hint "worker: executing task" + (l/trc :hint "executing task" :name (:name task) :id (str (:id task)) :queue queue @@ -459,13 +459,13 @@ (if (or (db/connection-error? cause) (db/serialization-error? cause)) (do - (l/warn :hint "worker: database exeption on processing task result (retrying in some instants)" - :cause cause) + (l/wrn :hint "worker: database exeption on processing task result (retrying in some instants)" + :cause cause) (px/sleep (::rds/timeout rconn)) (recur result)) (do - (l/error :hint "worker: unhandled exception on processing task result (retrying in some instants)" - :cause cause) + (l/err :hint "worker: unhandled exception on processing task result (retrying in some instants)" + :cause cause) (px/sleep (::rds/timeout rconn)) (recur result))))))] @@ -481,12 +481,12 @@ (catch Exception cause (if (rds/timeout-exception? cause) (do - (l/error :hint "worker: redis pop operation timeout, consider increasing redis timeout (will retry in some instants)" - :timeout timeout - :cause cause) + (l/err :hint "worker: redis pop operation timeout, consider increasing redis timeout (will retry in some instants)" + :timeout timeout + :cause cause) (px/sleep timeout)) - (l/error :hint "worker: unhandled exception" :cause cause)))))) + (l/err :hint "worker: unhandled exception" :cause cause)))))) (defn- get-error-context [_ item] @@ -517,7 +517,7 @@ (defmethod ig/init-key ::cron [_ {:keys [::entries ::registry ::db/pool] :as cfg}] (if (db/read-only? pool) - (l/warn :hint "cron: not started (db is read-only)") + (l/wrn :hint "cron: not started (db is read-only)") (let [running (atom #{}) entries (->> entries (filter some?) @@ -540,22 +540,22 @@ cfg (assoc cfg ::entries entries ::running running)] - (l/info :hint "cron: started" :tasks (count entries)) - (synchronize-cron-entries! cfg) + (l/inf :hint "cron: started" :tasks (count entries)) + (synchronize-cron-entries! cfg) - (->> (filter some? entries) - (run! (partial schedule-cron-task cfg))) + (->> (filter some? entries) + (run! (partial schedule-cron-task cfg))) - (reify - clojure.lang.IDeref - (deref [_] @running) + (reify + clojure.lang.IDeref + (deref [_] @running) - java.lang.AutoCloseable - (close [_] - (l/info :hint "cron: terminated") - (doseq [item @running] - (when-not (.isDone ^Future item) - (.cancel ^Future item true)))))))) + java.lang.AutoCloseable + (close [_] + (l/inf :hint "cron: terminated") + (doseq [item @running] + (when-not (.isDone ^Future item) + (.cancel ^Future item true)))))))) (defmethod ig/halt-key! ::cron [_ instance] @@ -571,7 +571,7 @@ [{:keys [::db/pool ::entries]}] (db/with-atomic [conn pool] (doseq [{:keys [id cron]} entries] - (l/trace :hint "register cron task" :id id :cron (str cron)) + (l/trc :hint "register cron task" :id id :cron (str cron)) (db/exec-one! conn [sql:upsert-cron-task id (str cron) (str cron)])))) (defn- lock-scheduled-task! @@ -589,7 +589,7 @@ (db/exec-one! conn ["SET statement_timeout=0;"]) (db/exec-one! conn ["SET idle_in_transaction_session_timeout=0;"]) (when (lock-scheduled-task! conn id) - (l/trace :hint "cron: execute task" :task-id id) + (l/dbg :hint "cron: execute task" :task-id id) ((:fn task) task)) (db/rollback! conn)) @@ -598,9 +598,9 @@ (catch Throwable cause (binding [l/*context* (get-error-context cause task)] - (l/error :hint "cron: unhandled exception on running task" - :task-id id - :cause cause))) + (l/err :hint "cron: unhandled exception on running task" + :task-id id + :cause cause))) (finally (when-not (px/interrupted? :current) (schedule-cron-task cfg task)))))) @@ -610,12 +610,16 @@ (s/assert dt/cron? cron) (let [now (dt/now) next (dt/next-valid-instant-from cron now)] - (inst-ms (dt/diff now next)))) + (dt/diff now next))) (defn- schedule-cron-task - [{:keys [::running] :as cfg} {:keys [cron] :as task}] - (let [ft (px/schedule! (ms-until-valid cron) - (partial execute-cron-task cfg task))] + [{:keys [::running] :as cfg} {:keys [cron id] :as task}] + (let [ts (ms-until-valid cron) + ft (px/schedule! ts (partial execute-cron-task cfg task))] + + (l/dbg :hint "cron: schedule task" :task-id id + :ts (dt/format-duration ts) + :at (dt/format-instant (dt/in-future ts))) (swap! running #(into #{ft} (filter p/pending?) %)))) From 903f064e87deab1b6591edd334b701a32dc47a0f Mon Sep 17 00:00:00 2001 From: Andrey Antukh Date: Mon, 4 Sep 2023 10:55:57 +0200 Subject: [PATCH 3/3] :sparkles: Decrease slightly argon2id cost for improve usability The previous values are set too high. The current value are still valid under current recomendation but improves a little bit the time of password verification. --- backend/src/app/auth.clj | 9 ++++----- 1 file changed, 4 insertions(+), 5 deletions(-) diff --git a/backend/src/app/auth.clj b/backend/src/app/auth.clj index 0037e6900..5bde8aa79 100644 --- a/backend/src/app/auth.clj +++ b/backend/src/app/auth.clj @@ -8,14 +8,13 @@ (:require [app.config :as cf] [buddy.hashers :as hashers] - [cuerdas.core :as str] - [promesa.exec :as px])) + [cuerdas.core :as str])) (def default-params {:alg :argon2id - :memory (* 32768 2) ;; 64 MiB - :iterations 7 - :parallelism (px/get-available-processors)}) + :memory 32768 ;; 32 MiB + :iterations 3 + :parallelism 2}) (defn derive-password [password]