github/penpot
1
0
Fork 0
mirror of https://github.com/penpot/penpot.git synced 2026-10-29 14:00:37 +00:00
Code Issues Packages Projects Releases Wiki Activity

🐛 Invalidate the file-summary cache off the request thread

Browse Source 
`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
This commit is contained in:
Andrey Antukh 2026-10-20 18:05:54 +00:00
parent 114928ea5f
commit 4da27392f0
4 changed files with 209 additions and 3 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

6
.serena/memories/backend/subtleties.md
View File

@ -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.<file-id>` (`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`.

2
.serena/memories/prod-infra/core.md
View File

@ -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:<tenant>:<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:<tenant>:<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`.

24
backend/src/app/rpc/commands/files_update.clj
View File

@ -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."

180
backend/test/backend_tests/files_update_cache_invalidation_test.clj Normal file
View File

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