#7962·rustfs

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

Author: stevappleCreated Sep 17, 2026Updated Sep 17, 2026
LabelsS-confirming

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 out lines per second on one client (max 2,524/s), all with addr = 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_verdict suppresses eviction while last_success is younger than two deadlines, and detached RPCs that complete late refresh last_success. Zero evictions across ~11 M timeouts means the verdict was PeerRecentlyServed every 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 k distributed unlock failed … remote lock RPC release on …/mnt/rustfs11 after 3s (we see attempt: 6), ~2 k distributed 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_quorum grants, so a lock is held on exactly quorum-many lockers (3 of 4 here), and quorum_valid_until then needs every held entry to keep refreshing — with entries == refresh_quorum it returns the earliest deadline. One slow locker is fine at acquire time and fatal at refresh time. The scanner leader logged lock refresh lost quorum (refreshed 1, entries 3, refresh_quorum 3) on leader.lock 30 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

  1. 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.
  2. 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.
  3. Rate-limit the timeout WARN the way HTTP 5xx lines already are (suppressed_errors), keyed by addr + op.
  4. 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.
  5. 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, git d47f54bfb2f39f48bd1adda334bd27e151fe85b8; 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.