From 4da27392f090d85cb22d149f610469b6b7be80ac Mon Sep 17 00:00:00 2001 From: Andrey Antukh Date: Tue, 20 Oct 2026 18:05:54 +0000 Subject: [PATCH] :bug: Invalidate the file-summary cache off the request thread `update-file` deleted the file-summary cache key with a synchronous redis `DEL` on the request thread, inside the database transaction and holding the file lock. A slow redis added up to the 2s command timeout to every save, and any error other than a command timeout (a refused connection, for example) rolled the whole transaction back and lost the change batch. Hand the deletion to the worker executor with `px/exec`, keep nothing but the redis pool in the task, and swallow every failure there with a WARN that carries the file id. The save no longer waits for the cache and can not fail because of it; a lost invalidation only leaves a stale summary until its TTL expires. Closes #12495 AI-assisted-by: deepseek-v4.1-flash --- .serena/memories/backend/subtleties.md | 6 + .serena/memories/prod-infra/core.md | 2 +- backend/src/app/rpc/commands/files_update.clj | 24 ++- .../files_update_cache_invalidation_test.clj | 180 ++++++++++++++++++ 4 files changed, 209 insertions(+), 3 deletions(-) create mode 100644 backend/test/backend_tests/files_update_cache_invalidation_test.clj diff --git a/.serena/memories/backend/subtleties.md b/.serena/memories/backend/subtleties.md index b6db941801..e06e911fc5 100644 --- a/.serena/memories/backend/subtleties.md +++ b/.serena/memories/backend/subtleties.md @@ -61,6 +61,12 @@ - `app.loggers.metrics/reporter` counts the log records the application emits and publishes them as `penpot_log_events_total{logger, level}` (counter), so the error panels do not have to count text in Loki. It is a component that hooks `add-watch` on `app.common.logging/log-record`, like `app.loggers.database`, but with no thread and no channel: the increment is in memory, so it goes straight in the watcher. Only `warn`, `error` and `fatal` are counted, and only the records that go through `app.common.logging` (the application's own logs; a library writing straight to log4j2 is not counted, and today that is one line in a thousand). The body of the watcher is wrapped in a `try/catch` that swallows the error on purpose: the watcher fires from the `swap!` of the log record, inside the logging path. With `::l/sync?` (`app.binfile.v1`, `app.msgbus`) an exception there would reach whoever was logging; on the async path it escapes to the logging executor worker, whose trace goes to the thread's uncaught handler -- outside the application's logging -- and the pool replaces the dead worker, so logging continues and that line is lost. The catch also makes a publication that fails every time invisible: `penpot_log_events_total` stays flat and nothing is written about it. The published `level` values are lowercase (`warn`), unlike the `level` label of the Loki logs (`ERROR`), so a panel that moves from one source to the other has to change it. Cardinality is `logger` (fixed names taken from the code) times `level`; a logger built from a dynamic value would break that. +## File-summary cache + +- `get-file-summary` and `get-team-shared-files` cache a file's library summary under the key `penpot.library-summary.` (`app.rpc.commands.files/file-summary-cache-key-prefix`), with a 30 day TTL and only when the `:redis-cache` flag is on; without the flag both always compute from the database. +- `update-file` invalidates that entry best effort: it only hands the deletion to the worker executor (`::wrk/executor`) and returns, so a slow, unavailable or failing redis never delays nor fails a save. Failures are logged at WARN with the file id and counted by `penpot_log_events_total`; a lost invalidation leaves the summary stale until the TTL expires. +- Nothing else invalidates. Paths that rewrite a file's local library without going through the `update-file` RPC (library absorption into referencing files, snapshot restore, binfile import) leave the cached summary stale for up to the TTL: a wrong summary is an entry to delete, not a bug in the reader. + ## Storage and media - Storage abstraction, backend configuration, logical buckets, object lifecycle, deduplication, access rules, and garbage collection: `mem:backend/storage`. diff --git a/.serena/memories/prod-infra/core.md b/.serena/memories/prod-infra/core.md index 0ab9ecde8e..73d50687c2 100644 --- a/.serena/memories/prod-infra/core.md +++ b/.serena/memories/prod-infra/core.md @@ -5,7 +5,7 @@ Backend (`app.config`, `PENPOT_*` env vars) is parameterized; deployments choose ## Services - **PostgreSQL**: durable store. Profiles, teams, files, sessions, audit, `storage_object` metadata, the `task` queue, `scheduled_task` cron registry, migrations. File-data also lives here when the file-data backend is `legacy-db`/`db`. One shared DB across all backends. -- **Redis (Valkey-compatible)**: per-backend message bus and cache. Concrete uses: msgbus Pub/Sub for collaborative-editing broadcasts and team/profile-org notifications fired by RPC handlers (`app.rpc.notifications`, `files_update`, `teams`, `websocket`); file-summary cache gated by `enable-redis-cache`; rate-limit counters; and the dispatcher→runner work hand-off list `penpot.worker.queue::`. `PENPOT_REDIS_URI`. A burst of client-side `RedisCommandTimeoutException` (2s on `DEL`/`SET`, 10s on `BLPOP`) with the exporter healthy is the JVM paused or starved, not Redis: the timeout fires because nothing reads the reply. +- **Redis (Valkey-compatible)**: per-backend message bus and cache. Concrete uses: msgbus Pub/Sub for collaborative-editing broadcasts and team/profile-org notifications fired by RPC handlers (`app.rpc.notifications`, `files_update`, `teams`, `websocket`); file-summary cache gated by `enable-redis-cache` and invalidated best effort from the worker executor by `update-file`; rate-limit counters; and the dispatcher→runner work hand-off list `penpot.worker.queue::`. `PENPOT_REDIS_URI`. A burst of client-side `RedisCommandTimeoutException` (2s on `DEL`/`SET`, 10s on `BLPOP`) with the exporter healthy is the JVM paused or starved, not Redis: the timeout fires because nothing reads the reply. - **Object storage**: backends `:s3` and `:fs`. S3 in prod; devenv uses RustFS. Holds uploaded media, file-data when the file-data backend is `storage`, exports. Backend-side details (resolve, dedup, bucket set, object lifecycle, and file-data backends): `mem:backend/storage`. - **SMTP mailer**: invitations, password resets, email verification (sent via the `:sendmail` worker task). - **LDAP** (optional auth provider): helpers in `app.auth.*`, gated by `enable-login-with-ldap`. diff --git a/backend/src/app/rpc/commands/files_update.clj b/backend/src/app/rpc/commands/files_update.clj index 12d7aa63d6..eeb2c838db 100644 --- a/backend/src/app/rpc/commands/files_update.clj +++ b/backend/src/app/rpc/commands/files_update.clj @@ -37,7 +37,9 @@ [app.util.blob :as blob] [app.util.pointer-map :as pmap] [app.util.services :as sv] - [clojure.set :as set])) + [app.worker :as-alias wrk] + [clojure.set :as set] + [promesa.exec :as px])) (declare ^:private get-lagged-changes) (declare ^:private send-notifications!) @@ -46,6 +48,7 @@ (declare ^:private process-changes-and-validate) (declare ^:private take-snapshot?) (declare ^:private invalidate-caches!) +(declare ^:private schedule-cache-invalidation) ;; PUBLIC API; intended to be used outside of this module (declare update-file!) @@ -307,8 +310,10 @@ (persist-file! cfg file) + ;; Best effort: a slow, unavailable or failing cache must never delay + ;; nor fail the save, so the invalidation runs outside of this request. (when (contains? cf/flags :redis-cache) - (invalidate-caches! cfg file)) + (schedule-cache-invalidation cfg (:id file))) ;; Send asynchronous notifications (send-notifications! cfg params file) @@ -356,6 +361,21 @@ (let [key (str files/file-summary-cache-key-prefix id)] (rds/del conn key))))) +(defn- schedule-cache-invalidation + "Schedule a best effort invalidation of the file-summary cache entry of the + file id. The task runs on the worker executor because a slow, unavailable + or failing redis must never delay nor fail an `update-file` request; a lost + invalidation only leaves a stale summary until the cache TTL expires." + [{:keys [::wrk/executor] :as cfg} id] + (px/exec executor + (fn [] + (try + (invalidate-caches! (select-keys cfg [::rds/pool]) {:id id}) + (catch Throwable cause + (l/warn :hint "unable to invalidate file-summary cache" + :file-id (str id) + :cause cause)))))) + (defn- attach-snapshot "Attach snapshot data to the file. This should be called before the upcoming file operations are applied to the file." diff --git a/backend/test/backend_tests/files_update_cache_invalidation_test.clj b/backend/test/backend_tests/files_update_cache_invalidation_test.clj new file mode 100644 index 0000000000..bea9d71648 --- /dev/null +++ b/backend/test/backend_tests/files_update_cache_invalidation_test.clj @@ -0,0 +1,180 @@ +;; This Source Code Form is subject to the terms of the Mozilla Public +;; License, v. 2.0. If a copy of the MPL was not distributed with this +;; file, You can obtain one at http://mozilla.org/MPL/2.0/. +;; +;; Copyright (c) KALEIDOS INC Sucursal en España SL + +(ns backend-tests.files-update-cache-invalidation-test + "The file-summary cache entry of a file is invalidated best effort. + + `update-file` only hands the invalidation to the worker executor, so a + slow, unavailable or failing redis never delays a save and never fails the + transaction. A lost invalidation leaves a stale summary until the cache TTL + expires; the log line is the only trace of it." + (:require + [app.common.logging :as l] + [app.common.uuid :as uuid] + [app.config :as cf] + [app.db :as db] + [app.redis :as rds] + [app.rpc.commands.files :as files] + [app.rpc.commands.files-update :as files-update] + [app.worker :as-alias wrk] + [backend-tests.helpers :as th] + [clojure.test :as t]) + (:import + io.lettuce.core.RedisConnectionException + java.util.concurrent.Executor)) + +(t/use-fixtures :once th/state-init) +(t/use-fixtures :each th/database-reset) + +(def ^:private warn-hint "unable to invalidate file-summary cache") + +;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;; +;; Helpers +;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;; + +(defn- capturing-executor + "An executor that keeps the task instead of running it, so the test can + check what the caller thread did and did not do." + [captured] + (reify Executor + (execute [_ f] + (reset! captured f)))) + +(defn- inline-executor + "An executor that runs the task in the calling thread. Keeps the tests that + go through `update-file` deterministic: no sleeps, no waiting." + [] + (reify Executor + (execute [_ f] + (.run ^Runnable f)))) + +(defn- capture-records + "Run `f` with every log record collected, newest last. The logging API emits + asynchronously, so a record may land after `f` returns; callers wait for the + one they need." + [f] + (let [records (atom [])] + (add-watch l/log-record ::capture + (fn [_ _ _ record] + (swap! records conj record))) + (try + (f records) + (finally + (remove-watch l/log-record ::capture))))) + +(defn- warn-record + "Wait until the record that reports a failed invalidation is captured." + [records timeout] + (let [deadline (+ (System/currentTimeMillis) timeout)] + (loop [] + (or (some (fn [record] + (when (= warn-hint (get (::l/props record) :hint)) + record)) + @records) + (when (<= (System/currentTimeMillis) deadline) + (Thread/sleep 10) + (recur)))))) + +(defn- add-page + [] + [{:type :add-page + :name "page" + :id (uuid/next)}]) + +(defn- create-file + [] + (let [profile (th/create-profile* 1 {:is-active true}) + file (th/create-file* 1 {:profile-id (:id profile) + :project-id (:default-project-id profile)})] + {:profile profile :file file})) + +(defn- update-file + [{:keys [profile file]} id->executor] + (binding [cf/flags (conj cf/flags :redis-cache)] + (th/update-file* (assoc th/*system* ::wrk/executor id->executor) + {:file-id (:id file) + :profile-id (:id profile) + :changes (add-page)}))) + +;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;; +;; Tests +;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;; + +(t/deftest hands-the-invalidation-to-the-executor + ;; The request thread must not reach redis: it only hands the task over, and + ;; the task keeps nothing from the request but the pool it needs. + (let [captured (atom nil) + calls (atom []) + file-id (uuid/next) + cfg {::wrk/executor (capturing-executor captured) + ::rds/pool ::pool + ::db/conn ::request-connection}] + + (with-redefs [rds/run! (fn [cfg f] + (swap! calls conj cfg) + (f {::rds/conn ::connection})) + rds/del (constantly nil)] + (#'files-update/schedule-cache-invalidation cfg file-id) + + (t/is (fn? @captured) "the invalidation must be handed to the executor") + (t/is (empty? @calls) "nothing may run on the caller thread") + + (@captured) + + (t/is (= 1 (count @calls))) + (t/is (= [::pool] (mapv ::rds/pool @calls))) + (t/is (nil? (::db/conn (first @calls))) + "the task must not keep the connection of the request")))) + +(t/deftest logs-and-swallows-errors-from-redis + ;; A refused connection is not a command timeout, so `rds/del` lets it + ;; through. The task has to absorb it: an exception here would reach the + ;; executor and kill its worker thread. + (let [captured (atom nil) + file-id (uuid/next) + cfg {::wrk/executor (capturing-executor captured) + ::rds/pool ::pool}] + + (capture-records + (fn [records] + (with-redefs [rds/run! (fn [_ _] + (throw (RedisConnectionException. "connection refused")))] + (#'files-update/schedule-cache-invalidation cfg file-id) + + (t/is (nil? (try (@captured) + nil + (catch Throwable _ + ::escaped))) + "a failing invalidation must not escape the task") + + (let [record (warn-record records 2000)] + (t/is (some? record) "a failed invalidation must leave a log line") + (t/is (= (str file-id) (get (::l/props record) :file-id))) + (t/is (instance? RedisConnectionException (::l/cause record))) + (t/is (= :warn (::l/level record))))))))) + +(t/deftest update-file-commits-when-redis-is-down + ;; The whole point: a broken cache can not take the save down with it. + (let [{:keys [file] :as data} (create-file)] + + (with-redefs [rds/del (fn [_ _] + (throw (RedisConnectionException. "connection refused")))] + (let [result (update-file data (inline-executor))] + (t/is (map? result)) + (t/is (= 1 (:revn (th/db-get :file {:id (:id file)}))) + "the transaction must commit"))))) + +(t/deftest update-file-invalidates-the-file-summary-key + (let [{:keys [file] :as data} (create-file) + deleted (atom [])] + + (with-redefs [rds/del (fn [conn key] + (swap! deleted conj [conn key]))] + (update-file data (inline-executor)) + + (t/is (= 1 (count @deleted))) + (t/is (= (str files/file-summary-cache-key-prefix (:id file)) + (second (first @deleted)))))))