The Progress Request That Never Arrived

#

How two silent bugs in a Rust etcd-compatible KV store caused thousands of errors per minute in a near-idle k3s cluster — and the 14-hour investigation that found them.

Table of Contents

#

1. Background: The Idle Cluster That Wasn’t
2. Bug 0: The ZFS Eviction Spam
3. The Real Problem: “Error Getting Keys”
4. Bug 1: The Version That Didn’t Count
5. Bug 2: The Watch ID That Went Nowhere
6. How The Pipeline Actually Works
7. The Fix
8. Key Lessons

Background: The Idle Cluster That Wasn’t

#

A 30-pod k3s cluster running on Kudurru — a purpose-built etcd v3 gRPC server in Rust — was consuming ~35% of a CPU core on the control-plane node. For context, the previous kine+SQLite stack used 17% of a core, and Kudurru alone uses 0.10%. Something was very wrong.

The CPU profile pointed at kube-apiserver, not the storage layer:

Category                     Share
─────────────────────────────────────────
kube-apiserver               ~35%
  ├─ eviction checks         ~15%
  ├─ "Error getting keys"    ~10%
  ├─ garbage collection      ~5%
  └─ everything else         ~5%
Kudurru                      ~0.1%

Two distinct problems, one obvious and one subtle.

Bug 0: The ZFS Eviction Spam

#

The obvious problem: kubelet was logging containerfs.inodesFree every 10 seconds — a ZFS filesystem error. ZFS doesn’t have inodes, so reading /sys/fs/cgroup inode counters returns MaxUint64, which underflows through the eviction threshold check and prints errors.

This was a well-known upstream issue (containerfs.inodesFree eviction logs on ZFS, fixed upstream but not yet in K3s v1.36).

Fix: Two-part patch to pkg/kubelet/eviction/helpers.go:

1. Guard the inode check: only run containerfs.inodesFree if the filesystem reports inodes
2. Suppress the log: wrap the error with filesystem info so the threshold can identify false positives

After deploying the patched K3s binary, CPU dropped from ~35% to ~11%. The eviction spam was gone, but the real problem remained.

The Real Problem: “Error Getting Keys”

#

kube-apiserver was logging 207 “Error getting keys” errors every 2 minutes — a steady stream of Timeout errors from the etcd3 storage layer:

I0706 22:24:45.123456   12345 stats.go:119] "Error getting keys" err="Too large resource version: 1234567, current: 1234516"

The error originates in cleanKeysIfNeeded — a function in kube-apiserver’s resourceSizeEstimator that runs every ~60 seconds to estimate the total size of all stored objects (for API Priority & Fairness cost estimation). The call chain:

SizeBasedListCostEstimate (feature gate, Beta, default-on since v1.34)
  └─ resourceSizeEstimator.cleanKeysIfNeeded()
       └─ GetCurrentResourceVersion()   → reads the **global** store revision
       └─ WaitUntilFreshAndGetKeys(globalRev)
            └─ waitUntilFreshAndBlock(ctx, 3s timeout)
                 → TooLargeResourceVersionError after 3s

The core problem: GetCurrentResourceVersion() returns the global key-value store revision (from header.revision in the etcd protocol). But waitUntilFreshAndBlock then checks whether the prefix-scoped watch cache has caught up to that revision. The watch cache only has visibility into its own key prefix, and its resourceVersion is updated only when bookmark events arrive via the watch stream. A global revision from a Range response header will almost certainly be ahead of any prefix-scoped watch cache — the gap was observed to be 200–560 revisions.

So the watch cache waits 3 seconds for a bookmark event that would update its revision to match the global revision. If no bookmark arrives within 3 seconds, it times out with TooLargeResourceVersionError.

The bookmark events come from progress notifications — periodic responses from the storage backend that tell the watch client “you’re still connected, and the current revision is X.” The watch cache uses these to keep its resourceVersion in sync. But here’s the thing: Kubernetes wasn’t sending progress requests at all.

Bug 1: The Version That Didn’t Count

#

Kubernetes’ etcd client checks whether the server supports RequestWatchProgress before it ever sends one:

// vendor/k8s.io/apiserver/pkg/storage/etcd3/feature_support_checker.go
v3_5_0  = version.MustParseSemantic("3.5.0")
v3_5_13 = version.MustParseSemantic("3.5.13")

if ver.AtLeast(v3_5_0) && ver.LessThan(v3_5_13) {
    return false, nil  // RequestWatchProgress NOT supported
}

This blacklist exists because real etcd had bugs with progress notifications in versions [3.5.0, 3.5.13). If your server reports a version in that range, Kubernetes assumes progress notifications are broken and never requests them.

Kudurru’s Status endpoint reported:

// src/server/maintenance.rs
version: "3.5.0".into(),

3.5.0 falls squarely in the blacklist. Supports(RequestWatchProgress) returned false. Kubernetes never sent a single WatchProgressRequest. Without progress requests, the only bookmark events came from Kudurru’s automatic 300-second periodic timer — far too slow for the 3-second blockTimeout.

We added tracing::debug! logging to Kudurru’s progress handler, restarted, and confirmed: zero WatchProgressRequest logs despite the errors relentlessly firing. The version check was silently starving the entire pipeline.

Bug 2: The Watch ID That Went Nowhere

#

We fixed the version string to "3.5.14", restarted, and the progress requests started flowing — 87,390 in 2 minutes. But the errors didn’t stop. Something else was wrong.

The etcd client library’s dispatchEvent function (in the Go clientv3 library) handles progress responses with two paths:

// go.etcd.io/etcd/client/v3/watch.go
if wr.IsProgressNotify() && pbresp.WatchId == InvalidWatchID {  // InvalidWatchID = -1
    return w.broadcastResponse(wr)   // send to ALL watchers
}
return w.unicastResponse(wr, pbresp.WatchId)  // send to ONE watcher

If WatchId == -1, the response is broadcast to every watcher on the stream. Otherwise, it’s unicast to a single watcher by ID.

Kudurru’s ProgressRequest handler sent:

// src/server/watch.rs (before fix)
watch_id: 0,  // AutoWatchID

0 is AutoWatchID — not -1 (InvalidWatchID). So the etcd client called unicastResponse(wr, 0), which looks up a watcher with ID 0:

func (w *watchGRPCStream) unicastResponse(wr *WatchResponse, watchID int64) bool {
    ws, ok := w.substreams[watchID]
    if !ok {
        return false  // no watcher has ID 0 → silently dropped
    }
    // ...
}

Kudurru assigns watch IDs starting from 1 (AtomicI64::new(1) at line 14). No watcher ever has ID 0. Every progress notification was silently dropped into a void, never reaching any watcher’s channel.

The periodic 300-second timer worked because it used the correct per-watcher watch_id — unicastResponse found the substream and delivered. But 300 seconds is useless when the blockTimeout is 3 seconds.

How The Pipeline Actually Works

#

The full chain, now that both bugs are fixed:

ConditionalProgressRequester (every 100ms while watchers are waiting)
  └─ etcd3 store.RequestProgress()
       └─ gRPC WatchRequest { ProgressRequest }
            └─ Kudurru sends WatchResponse {
                   watch_id: -1,   // Broadcast to ALL watchers
                   header.revision: current_revision()
               }
                   └─ clientv3 dispatchEvent: WatchId == -1 → broadcastResponse
                        └─ Every watcher's channel receives a BookmarkEvent
                             └─ watchCache.resourceVersion = bookmark.revision
                                  └─ w.notFresh(globalRev) → false → wait succeeds

With watch_id: -1, the progress notification is broadcast to every watcher on the gRPC stream. Every cacher’s watch cache updates its resourceVersion to the current global revision. When WaitUntilFreshAndGetKeys checks w.notFresh(globalRev), it returns false — the cache is already fresh. No timeout, no error.

The Fix

#

Two two-character changes in Kudurru ("0" → "4" and 0 → -1):

// src/server/maintenance.rs — pass the version blacklist check
- version: "3.5.0".into(),
+ version: "3.5.14".into(),

// src/server/watch.rs — broadcast, not unicast
- watch_id: 0,
+ watch_id: -1,

After deploying both fixes and re-enabling SizeBasedListCostEstimate=true: zero “Error getting keys” in 2+ minutes where there were previously 207.

Key Lessons

#

1. The version string is more than metadata

#

Kubernetes uses the etcd version string from StatusResponse to gate features via semver blacklists. A version string chosen for convenience ("3.5.0" because that’s what etcd was at when we started) silently disabled an entire feature pipeline. The version string is a protocol-level signal — treat it as such.

2. A progress notification that isn’t broadcast isn’t a notification

#

The etcd protocol specifies that WatchProgressRequest (which has no target watch_id) should result in progress notifications for all active watchers. The InvalidWatchID = -1 convention triggers broadcast dispatch in the Go client library. Any other value gets unicast — and if the target doesn’t exist, it’s silently dropped. The Rust etcd client creates separate gRPC streams per watcher, so this bug only manifests in the Go client — which is exactly what k3s/kube-apiserver uses.

3. The right tool for the wrong job

#

Even with progress notifications working, there’s a deeper design question: why does GetCurrentResourceVersion() return the global revision when the caller only needs to synchronize a prefix-scoped watch cache? The two concepts are fundamentally incomparable — the global revision advances on writes to any key, while the watch cache only cares about its own prefix. A per-prefix revision would be a more natural fit. But that’s not how the etcd protocol works: ResponseHeader.revision is explicitly “the key-value store revision when the request was applied” — global by design.

The workaround (progress notifications to periodically update the watch cache) is the correct approach per the etcd protocol, but it requires every piece of the chain to work. Two silent bugs broke the chain.

4. Every layer matters

#

• Kudurru (Rust): wrong version string + wrong watch ID
• etcd client library (Go): silent drop on unicast miss
• Kubernetes (Go): aggressive blacklist + 3-second timeout

Each layer behaved correctly according to its own logic. The interaction of all of them produced a failure mode that no unit test, no integration test, and no single-layer analysis could have predicted.

5. Add tracing before you need it

#

The turning point was adding tracing::debug! to Kudurru’s progress handler. Without those two log lines, we would have been guessing — “the pipeline should work, why doesn’t it?” The debug logs immediately showed that progress requests were never arriving (Bug 1) and then that responses were being sent but not received by watchers (Bug 2). Add observability to the critical path before you start debugging — it saves hours.

This debugging journey was assisted by DeepSeek V4 Flash on OpenCode — an interactive CLI agent that performed the codebase exploration, root cause analysis, and code transformations described above. From initial symptom to final fix: approximately 14 hours of investigation across two distinct production issues, with two two-character fixes that eliminated 207 errors per 2 minutes.