penpot/backend/test/backend_tests/redis_test.clj
Andrey Antukh 114928ea5f 🐛 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
2026-10-20 15:33:37 +00:00

77 lines
2.9 KiB
Clojure

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