diff --git a/.serena/memories/backend/rpc-db-worker-subtleties.md b/.serena/memories/backend/rpc-db-worker-subtleties.md index 2ba9389310..d72868e00a 100644 --- a/.serena/memories/backend/rpc-db-worker-subtleties.md +++ b/.serena/memories/backend/rpc-db-worker-subtleties.md @@ -8,6 +8,9 @@ - The wrapper stack does auth before params validation, then auditing/rate/concurrency/metrics/retry/condition handling, with DB transaction handling inside that stack. `::db/transaction` metadata controls transaction wrapping. - Params with `::sm/params` are decoded/conformed through the JSON transformer and successful IObj results get `:encode/json` metadata. Legacy spec conforming only applies when no Malli params schema exists. - Nil RPC bodies become HTTP 204 unless explicit status metadata is present. Stream bodies default to `application/octet-stream` when no content type is set. +- `::climit/id` is either a plain keyword, which gives one shared limiter per process, or the vector form `[[id key-fn]]`, which gives one limiter per key. `climit/wrap` takes the key only from that positional `key-fn` (`climit/get-limits` maps a plain keyword to a single-element vector), so `::climit/key-fn` is metadata that nothing reads: a command declaring `::climit/id :x/by-profile` next to it ends up with a single shared limiter, and the missing key is visible in the `app.rpc.climit` log lines, whose `id` carries no key suffix. That is what happened to `push-audit-events`, the last user of the dead metadata, from `a5c6d78ee5` (2024-01-27, "fix some fundamental bugs on climit module", which moved the key to the vector form without updating it) until it was fixed; nothing declares `::climit/key-fn` any more, so keep using the vector form for anything that must be per profile. +- The `penpot_rpc_climit_queue`/`permits` gauges carry only the limiter name, never the key, so every per-profile limiter of the same name collapses into one series and the last call wins: a per-key pile-up is invisible there and a healthy looking `cola=0` proves nothing. A stuck limiter does show up in `penpot_rpc_climit_timing_count` (the acquired path), which is a counter: compare the same limiter name across instances and the stuck one reads 0 acquisitions while its peer reads thousands. +- Nothing in the limiter path has a timeout unless the config sets one, and `psm/acquire` then calls `Semaphore.acquire`, which parks the calling thread forever. That is what turns a wait into a lost worker thread: a permanently parked thread still counts as in-system for every outer limiter of its chain, so the outermost one (the method's own by-profile limiter) stops granting permits and answers 429 to everything. A limiter without `:queue` in the config gets an unlimited queue and therefore never rejects: its pile-up is silent, with no 429 and no log line except the WARN `enqueued`/`acquired` lines of the keyed id, and its per-key nature is invisible in the metrics. Note that a request whose profile limit is exhausted parks *inside* the outer limiter while holding its permit, and handlers that assign `::climit/id` dynamically (media, profile) re-acquire the same keyed limiters, so a chain of such waits can close into a cycle that no timeout ever breaks. ## DB helpers diff --git a/backend/src/app/rpc/commands/audit.clj b/backend/src/app/rpc/commands/audit.clj index 69777a1ddd..ea1d3e3d03 100644 --- a/backend/src/app/rpc/commands/audit.clj +++ b/backend/src/app/rpc/commands/audit.clj @@ -157,8 +157,7 @@ [:events [:vector schema:frontend-event]]]) (sv/defmethod ::push-audit-events - {::climit/id :submit-audit-events/by-profile - ::climit/key-fn ::rpc/profile-id + {::climit/id [[:submit-audit-events/by-profile ::rpc/profile-id]] ::sm/params schema:push-audit-events ::audit/skip true ::doc/skip true diff --git a/backend/test/backend_tests/rpc_audit_test.clj b/backend/test/backend_tests/rpc_audit_test.clj index 2fd3a43c62..2dea7e2149 100644 --- a/backend/test/backend_tests/rpc_audit_test.clj +++ b/backend/test/backend_tests/rpc_audit_test.clj @@ -12,10 +12,13 @@ [app.config :as cf] [app.db :as db] [app.loggers.audit :as audit] + [app.metrics :as mtx] [app.rpc :as-alias rpc] + [app.rpc.climit :as climit] [app.util.services :as sv] [backend-tests.helpers :as th] [clojure.test :as t] + [integrant.core :as ig] [yetti.request])) (t/use-fixtures :once th/state-init) @@ -35,6 +38,62 @@ "x-forwarded-for" "127.0.0.44" "x-real-ip" "127.0.0.43")))) +(t/deftest push-audit-events-limit-is-keyed-by-profile + ;; Regression guard. This command asks for a per-profile limit, but it used + ;; to declare it as a plain keyword next to `::climit/key-fn`, metadata that + ;; `climit/wrap` does not read: it takes the key only from the positional + ;; `key-fn` of the vector form. That silently turned the limit into a single + ;; shared one, so one stuck call ended up rejecting the audit batches of + ;; every profile on the instance. Two profiles must not share a limiter. + (let [config (doto (java.io.File/createTempFile "climit" ".edn") + (.deleteOnExit)) + _ (spit config "{:submit-audit-events/by-profile {:permits 1 :queue 1}}") + + ;; The limiter only uses the metrics instance to measure, and with a + ;; stub collector every `run!` is a no-op. + metrics (reify mtx/IMetrics + (get-handler [_] nil) + (get-collector [_ _] nil) + (get-registry [_] nil)) + + climit (ig/init-key ::rpc/climit + {::climit/enabled true + ::climit/config (.getAbsolutePath config) + ::mtx/metrics metrics}) + + ;; The metadata declared by the command itself, that is what the test + ;; has to cover. + mdata (meta (ns-resolve 'app.rpc.commands.audit 'sm$push-audit-events)) + + gate (promise) + entered (promise) + calls (atom 0) + handler (fn [_ _] + (when (= 1 (swap! calls inc)) + (deliver entered true) + @gate) + :ok) + wrapped (climit/wrap {::rpc/climit climit} handler mdata) + call (fn [profile-id] + (wrapped {::rpc/climit climit} {::rpc/profile-id profile-id})) + pid-a (uuid/next) + pid-b (uuid/next) + holder (future (call pid-a))] + + ;; The first call stays inside the handler holding the only permit. + (t/is (true? (deref entered 2000 false))) + + ;; Another call from the SAME profile shares the limiter, so it waits. + (let [same (future (call pid-a))] + (t/is (= :waiting (deref same 300 :waiting)))) + + ;; A different profile owns a different limiter and is served right away. + ;; With the shared limiter (the bug) this one waits too and times out. + (t/is (= :ok (deref (future (call pid-b)) 2000 :timeout))) + + (deliver gate true) + (t/is (= :ok (deref holder 2000 :timeout))))) + (t/deftest prepare-context-initiator-is-plain-string ;; The initiator must always be a plain string, never a keyword: shared-key ;; authenticated callers (exporter, admin-console) arrive as keywords on