A slow lock endpoint produces hours of sustained lock-RPC timeouts (~1,300/s per client) with no backoff, failed releases, and lost held locks
Describe the bug
#7363 reported that lock-RPC timeouts against one slow lock endpoint spiralled into an RST_STREAM / GOAWAY too_many_resets / re-dial loop. #7473 fixed that loop: on 1.0.0 we see zero GoAway and zero Evicting cached remote lock connection lines. But the underlying condition — one endpoint answering lock RPCs slower than the 3 s deadline — now persists for hours instead of about one, at a much higher rate, and nothing in the client slows down in response:
- Every peer retries against the slow endpoint at full speed. Median 1,307
Remote lock RPC timed outlines per second on one client (max 2,524/s), all withaddr = https://node3…:9000/mnt/rustfs11,timeout_ms = 3000; 3.5–5.0 M per hour per node, on all three peers, continuously since 09:01:36 (+08:00) — three and a half hours and still running when this was written (a re-measurement at 12:33 showed ~775/s on another client, 99.9 % of it against the same endpoint) — after a first window 04:52:33–~06:00. On rc.5 the same storm was 5–10 k per hour. - The endpoint is slow, not gone — and that is what keeps it in rotation.
eviction_verdictsuppresses eviction whilelast_successis younger than two deadlines, and detached RPCs that complete late refreshlast_success. Zero evictions across ~11 M timeouts means the verdict wasPeerRecentlyServedevery time: the endpoint keeps completing some RPCs, mostly after their callers gave up. That is correct as a channel policy, but there is no request policy behind it: no backoff, no per-endpoint circuit breaker, no "skip this locker, quorum is reachable without it". - Late grants turn into orphans. Per client per hour: ~23 k
Could not release every remote lock granted after its caller timed out; the server lease will expire it, ~12 kdistributed unlock failed … remote lock RPC release on …/mnt/rustfs11 after 3s(we seeattempt: 6), ~2 kdistributed unlock abandoned entries after deferred retry. The releases go to the same slow endpoint and time out the same way. Each abandoned entry then holds its key on that locker until the lease expires. The timed-out resources are dominated by keys every mutation takes (.rustfs.sys/buckets/<bucket>/.bucket-incarnation,.rustfs.sys/bucket-targets/<bucket>/transaction.lock,.rustfs.sys/buckets/<bucket>/.metadata.bin,.rustfs.sys/pool.bin), so we suspect — but cannot prove at our log level — a self-sustaining loop: late grant → failed release → key held for a lease → next acquirers wait past 3 s → more late grants. It would explain why the storm no longer ends by itself. - Even
ping(no lock wait involved) times out against that endpoint (242–380 per hour per client). - Held locks are lost to it, because holding a lock tolerates less than acquiring it. Acquisition stops at
required_quorumgrants, so a lock is held on exactly quorum-many lockers (3 of 4 here), andquorum_valid_untilthen needs every held entry to keep refreshing — withentries == refresh_quorumit returns the earliest deadline. One slow locker is fine at acquire time and fatal at refresh time. The scanner leader loggedlock refresh lost quorum(refreshed 1, entries 3, refresh_quorum 3) onleader.lock30 s into the first window, lost its cycle lock six seconds later, and a multi-day scanner cycle restarted from zero. - Log volume: 1.9–2.6 GB per hour per node (normal: 4–7 MB), one WARN line per timed-out RPC with no rate limiting. With our 32 GiB log-directory cap this shrinks retention from days to about four hours, which destroys the evidence of whatever started it.
Client traffic is still served (the other three lockers make quorum), readiness stays 200 on all nodes, RSS is flat (5.6–9.7 GiB) and max active_requests on the slow node is 387 — so this is not yet the in-flight pile-up we reported before; it is a permanent tax plus lost held locks.
To Reproduce
We cannot make the endpoint slow on demand. A fault-injection repro should work: delay responses of one node's lock service for one endpoint to > RUSTFS_OBJECT_LOCK_RPC_TIMEOUT_MS under a write-heavy workload, and watch the peers' timeout rate, the release failures, and any long-held lock (scanner leader) on the other nodes.
What we can say about the slow endpoint: it is the same one (node3:/mnt/rustfs11) in every storm of this kind we have had (two windows on 09-07 on rc.5, two on 09-17 on 1.0.0). The node's own log is quiet: no lock errors, no slow inbound NodeService/Lock (its 5 s in-flight threshold is above the 3 s client deadline), only slow inbound NodeService/ReadVersion (3.6–5.4 k per hour, the same before and during the storm). No dmesg entries, NVMe at 25 %, load 12–18 on all four nodes alike. node3 reaches its own rustfs11 locker locally without trouble (0–4 lock timeouts per hour in its own log).
Expected behavior
- Request-level backoff / circuit breaker per lock endpoint. Keeping the channel is right; sending 1,300 doomed RPCs per second down it is not. After N consecutive timeouts, skip the endpoint for a short, growing interval (quorum permitting) and probe it with a single request.
- Don't let late grants become orphans on the slow endpoint. Either bound server-side lock wait by the caller's remaining deadline (so a grant can never arrive after the caller left), or have the server drop a grant whose stream is no longer awaited.
- Rate-limit the timeout WARN the way HTTP 5xx lines already are (
suppressed_errors), keyed byaddr+op. - Make the slow side visible at WARN: a periodic per-endpoint summary on the server (inbound lock RPC count, p99, queue depth, entries held/expired by lease) — today the node that is the problem logs nothing about it.
- Let a held lock survive what acquisition survives. Either keep acquiring past quorum so a held lock has a spare entry, or re-acquire on a healthy locker when one entry stops refreshing, so that one slow endpoint cannot take a lock away from a healthy holder while a quorum of lockers is still reachable.
Environment
- RustFS
1.0.0, gitd47f54bfb2f39f48bd1adda334bd27e151fe85b8; 4 nodes × 12 NVMe, 3 erasure sets, EC 12+4, TLS internode (h2); lock RPC timeout, eviction cooldown and detached limit at defaults (3000 ms / 5000 ms / 256);RUSTFS_OBJECT_LOCK_ACQUIRE_TIMEOUT=30;RUSTFS_OBS_LOGGER_LEVEL=warn. - Workload: five JuiceFS filesystems, continuous small-object write + delete.
Additional context
Related: #7363 (the reset loop, fixed by #7473), #7361 (the write latch the rc.5 storm caused). Happy to run a debug-level capture of rustfs_ecstore::cluster::rpc::remote_locker and the lock service on node3 during the next window if you tell us which targets are most useful.
Source: rustfs/rustfs