From 114928ea5f5f9e30656bb13e848670f33ab801f6 Mon Sep 17 00:00:00 2001 From: Andrey Antukh Date: Tue, 20 Oct 2026 15:33:37 +0000 Subject: [PATCH] :bug: 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 --- .serena/memories/prod-infra/core.md | 2 +- backend/src/app/redis.clj | 2 +- backend/test/backend_tests/redis_test.clj | 76 +++++++++++++++++++++++ 3 files changed, 78 insertions(+), 2 deletions(-) create mode 100644 backend/test/backend_tests/redis_test.clj diff --git a/.serena/memories/prod-infra/core.md b/.serena/memories/prod-infra/core.md index 5dfaeebed7..0ab9ecde8e 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`. +- **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. - **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/redis.clj b/backend/src/app/redis.clj index be9e331dda..fba9268193 100644 --- a/backend/src/app/redis.clj +++ b/backend/src/app/redis.clj @@ -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 diff --git a/backend/test/backend_tests/redis_test.clj b/backend/test/backend_tests/redis_test.clj new file mode 100644 index 0000000000..df3c8e15a8 --- /dev/null +++ b/backend/test/backend_tests/redis_test.clj @@ -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))))))