linearizableReadLoop can block indefinitely on log I/O, hanging all linearizable reads while the member reports healthy

[clement-ac9]

What happened?

On a single-member etcd (observed on both 3.6.7 and 3.6.12, as bundled in RKE2 v1.35.4/v1.35.6), when the filesystem backing etcd's log output became very slow, etcd entered a state where:

• all linearizable reads hung indefinitely (Range, MemberList, Txn → context deadline exceeded)
• serializable reads (--consistency=s) returned instantly
• etcd_server_has_leader 1, etcd_server_is_leader 1
• etcd_server_read_indexes_failed_total 0 — reads never failed, they simply never returned
• etcd_server_health_failures 0
• the process was in state S, consuming no CPU
• /metrics on the client port still answered in ~11 ms

A goroutine dump shows the cause. The single linearizableReadLoop goroutine is blocked acquiring zap's lockedWriteSyncer mutex, while emitting a slow-read trace:

go.uber.org/zap/zapcore.(*lockedWriteSyncer).Write(...)
	zapcore/write_syncer.go:65
	→ sync.Mutex.Lock                                        <-- BLOCKED
go.uber.org/zap/zapcore.(*ioCore).Write(...)                 zapcore/core.go:99
go.uber.org/zap.(*Logger).Info(...)                          logger.go:247
go.etcd.io/etcd/pkg/v3/traceutil.(*Trace).LogWithStepThreshold(...)  traceutil/trace.go:172
go.etcd.io/etcd/pkg/v3/traceutil.(*Trace).LogAllStepsIfLong(...)     traceutil/trace.go:164
go.etcd.io/etcd/server/v3/etcdserver.(*EtcdServer).linearizableReadLoop(...)  v3_server.go:950
go.etcd.io/etcd/server/v3/etcdserver.(*EtcdServer).GoAttach.func1()  server.go:2558

The goroutine holding that mutex is blocked in an uninterruptible write(2) on the log fd:

syscall.write(...)
internal/poll.(*FD).Write(...)                       internal/poll/fd_unix.go:374
os.(*File).Write(...)                                os/file.go:215
go.uber.org/zap/zapcore.(*lockedWriteSyncer).Write(...)  zapcore/write_syncer.go:66
go.uber.org/zap.(*Logger).Warn(...)                  logger.go:255
go.etcd.io/etcd/server/v3/etcdserver/api/v3rpc.logExpensiveRequestStats(...)
	v3rpc/interceptor.go:202
... _KV_Txn_Handler → grpc processUnaryRPC

Because linearizableReadLoop is the only goroutine that services read-index requests, parking it means every linearizableReadNotify waiter blocks forever. Serializable reads bypass the read loop entirely, which is why they stayed instant — and which is what makes this look like a raft/consistency problem when it is not.

Goroutine state histogram during the hang (3364 goroutines total):

state	count
select	2185
sync.Mutex.Lock	877
IO wait	286
syscall	2
running	1

Across three dumps taken ~25 min apart, goroutines blocked in linearizableReadNotify grew 95 → 68 → 803, while serverWatchStream stayed constant at 534. The pileup is blocked readers, not watchers.

Underlying trigger, for completeness

In our case the log writes were slow because the underlying storage was saturated — we measured 589 ms per 4 KiB O_DSYNC write inside the VM (164 ms on the hypervisor) caused by another workload sharing the disk array. That was our own infrastructure problem and we have since fixed it.

We're filing this anyway because the amplification looks like a genuine design issue: a latency problem in the log sink is converted into a total, permanent availability loss for linearizable reads, on a member that continues to report itself healthy. Any slow or stalled log sink should be able to produce this — a full or slow log filesystem, a paused/blocked log consumer on a pipe, or a stalled remote syslog.

What made it expensive to diagnose:

• no metric surfaces it — read_indexes_failed_total stays 0, health_failures stays 0, has_leader stays 1
• restarting etcd clears it, then it returns once enough slow-request traces accumulate again, which reads like a data/raft-state problem
• it presents as a raft or consistency bug, so we spent significant time on --cluster-reset, a snapshot restore, a 3-member expansion, and an etcd version bump before reading the dump
• --log-level=error is an effective workaround, because zap returns a nil CheckedEntry for filtered levels so neither the Info (read-loop trace) nor the Warn (expensive-request) path reaches the write syncer — but that also throws away the diagnostics you actually want when the disk is slow

What did you expect to happen?

Diagnostic logging should not be able to block the read-index path. Emitting a "this read was slow" trace should never be able to make all linearizable reads hang forever.

Concretely, some combination of:

1. Emit the LogAllStepsIfLong trace from linearizableReadLoop off the hot path — a separate goroutine, or a bounded channel that drops on overflow.
2. Same treatment for logExpensiveRequestStats on the request path, which holds the identical mutex.
3. Consider a non-blocking WriteSyncer for etcd's default zap configuration, dropping log lines with a counter rather than blocking the process.
4. Add a metric for time since linearizableReadLoop last completed an iteration. That single gauge would have made this trivial to spot, and would surface any future stall in that goroutine regardless of cause.

How can we reproduce it (as minimally and precisely as possible)?

We did not reproduce this synthetically — it occurred in a live cluster. Based on the stacks, it should be reproducible by making etcd's log sink block while the server takes traffic slow enough to trigger the 100 ms trace threshold:

1. Start a single-member etcd with default logger: zap and default log level, with stderr/stdout redirected to a slow or blockable sink (e.g. a pipe whose reader is stopped with SIGSTOP, or a filesystem throttled to very high write latency).
2. Apply enough load that read traces exceed the 100 ms threshold in LogAllStepsIfLong, so linearizableReadLoop attempts to log.
3. Ensure the log sink is not draining, so one writer holds the lockedWriteSyncer mutex inside write(2).
4. Observe: linearizable get hangs indefinitely; get --consistency=s returns immediately; read_indexes_failed_total stays 0; has_leader stays 1.

Anything else we need to know?

• etcd 3.6.7 and 3.6.12 both affected (bundled in RKE2 v1.35.4+rke2r1 / v1.35.6+rke2r1). Behaviour identical on both, which is consistent with this being independent of the raft/version changes between them.
• Single-member cluster, logger: zap, default log level, running as a static pod under containerd on Linux.
• Related but a different mechanism: Etcd watch stream starvation under high read response load when sharing same connection and TLS is enabled #15402 is watch-driven; here the watch-stream count was flat at 534 across all dumps while blocked readers accumulated.

etcd version (please run commands below)

$ etcd --version
etcd Version: 3.6.12   (also reproduced on 3.6.7)
Go Version: go1.25.9 X:boringcrypto

$ etcdctl version
etcdctl version: 3.6.12
API version: 3.6

etcd configuration (command line flags or environment variables)

Relevant non-default settings at the time of the hang:

logger: zap
log-level: <default>        # setting this to "error" is an effective workaround
enable-pprof: true
max-concurrent-streams: 16
heartbeat-interval: 500
election-timeout: 5000

Single member, TLS on both peer and client ports, data dir on the same (heavily saturated) storage as the log output.

etcd debug information (please run commands below, feel free to obfuscate the IP address or FQDN in the output)

$ etcdctl endpoint status -w table
# hangs — this RPC requires a linearizable read

$ etcdctl endpoint health
# hangs

$ etcdctl get /registry/namespaces/default --consistency=s
# returns immediately

$ curl -s http://127.0.0.1:2381/metrics | grep -E 'has_leader|read_indexes_failed|health_failures'
etcd_server_has_leader 1
etcd_server_read_indexes_failed_total 0
etcd_server_health_failures 0

Relevant log output

With the default log level, the log sink itself was blocked, so the most recent lines never made it to disk — the goroutine dump above is the primary evidence. On the consumer side (kube-apiserver / RKE2) the visible symptoms were:

etcdserver: request timed out
[-]etcd failed: reason withheld
[-]etcd-readiness failed: reason withheld

Full goroutine dumps (3 captures, ~25 min apart, 1787 / 1786 / 3364 goroutines) were taken via enable-pprof=true on the client port and are available if useful.

[serathius]

@marcus-hodgson-antithesis @nwnt Would be interesting case to add availability checking to Antithesis to try to reproduce this.