🐛 Fix the key reported when a redis DEL times out

`app.redis/del` logged `:key key`, but `key` is not bound in that
`let`: it resolved to `clojure.core/key`, so the line carried
`#object[clojure.core$key ...]` instead of the keys that failed to be
deleted. Log `:keys keys`, which is always the normalized vector, so a
single key and a collection report the same shape.

The tests pin the line: the keys, the hint, the error level, the logger
and the timeout as cause, plus the `nil` the caller gets.

The prod-infra memory now notes that client-side redis timeouts mean the
JVM is paused, not that the server is slow.

AI-assisted-by: deepseek-v4.1-flash
This commit is contained in:
Andrey Antukh 2026-10-20 15:33:37 +00:00
parent 534d46c7b3
commit 114928ea5f
3 changed files with 78 additions and 2 deletions

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`.
- **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.
- **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`.

View File

@ -375,7 +375,7 @@
(try
(-del conn keys)
(catch RedisCommandTimeoutException cause
(l/err :hint "timeout on del redis key" :key key :cause cause)
(l/err :hint "timeout on del redis key" :keys keys :cause cause)
nil))))
(defn ping

View File

@ -0,0 +1,76 @@
;; 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.redis-test
"The redis wrapper swallows a command timeout and returns nil, so the log
line is the only trace of the command that did not reach the server. These
tests pin what that line has to carry."
(:require
[app.common.logging :as l]
[app.redis :as rds]
[clojure.test :as t])
(:import
io.lettuce.core.RedisCommandTimeoutException))
(def ^:private timeout-hint "timeout on del redis key")
(defn- timeout-connection
"A connection whose DEL always exceeds the command timeout, the way Lettuce
answers when the response does not arrive in time."
[]
(reify rds/IDefaultConnection
(-del [_ _keys]
(throw (RedisCommandTimeoutException. "DEL. Command timed out after 2 second(s)")))))
(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- timeout-record
"Wait until the record that reports a timed out DEL is captured."
[records timeout]
(let [deadline (+ (System/currentTimeMillis) timeout)]
(loop []
(or (some (fn [record]
(when (= timeout-hint (get (::l/props record) :hint))
record))
@records)
(when (<= (System/currentTimeMillis) deadline)
(Thread/sleep 10)
(recur))))))
(t/deftest del-logs-the-keys-that-timed-out
;; The server never saw the command, so the operator has no other way to know
;; which key stayed behind.
(capture-records
(fn [records]
(t/is (nil? (rds/del (timeout-connection) ["file-summary:1" "file-summary:2"])))
(let [record (timeout-record records 2000)]
(t/is (some? record) "a timed out DEL must leave a log line")
(t/is (= ["file-summary:1" "file-summary:2"]
(get (::l/props record) :keys)))
(t/is (instance? RedisCommandTimeoutException (::l/cause record)))
(t/is (= :error (::l/level record)))
(t/is (= "app.redis" (::l/logger record)))))))
(t/deftest del-logs-a-single-key-as-a-collection
;; `del` accepts one key or a collection and always hands a collection to the
;; driver; the log keeps the same shape so it does not depend on the call.
(capture-records
(fn [records]
(rds/del (timeout-connection) "file-summary:1")
(t/is (= ["file-summary:1"]
(get (::l/props (timeout-record records 2000)) :keys))))))