Skip to content

New joiner stuck in etcdserver: too many requests caused by idle cluster #22528

Open
#22529
Open
New joiner stuck in etcdserver: too many requests caused by idle cluster#22528
#22529
Labels
type/bug

Description

@tkren
tkren
opened on Oct 5, 2026

Bug report criteria

What happened?

A new member joining an idle cluster catches up via a leader database snapshot, then rejects every write (including its own publish) with etcdserver: too many requests, indefinitely.

The problematic log messages start with

{"level":"warn","ts":"2026-10-01T14:29:33.260395Z","caller":"etcdserver/server.go:1838","msg":"failed to publish local member to cluster through raft","local-member-id":"bbcf7589173ff1eb","local-member-attributes":"{Name:new-joiner ClientURLs:[https://etcd.example.net:2379]}","publish-timeout":"7s","error":"etcdserver: request timed out, possibly due to connection lost"

Then the following warnings repeat without backoff, hundreds of lines per second of the form

{"level":"warn","ts":"2026-10-01T14:29:33.260454Z","caller":"etcdserver/server.go:1838","msg":"failed to publish local member to cluster through raft","local-member-id":"bbcf7589173ff1eb","local-member-attributes":"{Name:new-joiner ClientURLs:[https://etcd.example.net:2379]}","publish-timeout":"7s","error":"etcdserver: too many requests"}
{"level":"warn","ts":"2026-10-01T14:29:33.260469Z","caller":"etcdserver/server.go:1838","msg":"failed to publish local member to cluster through raft","local-member-id":"bbcf7589173ff1eb","local-member-attributes":"{Name:new-joiner ClientURLs:[https://etcd.example.net:2379]}","publish-timeout":"7s","error":"etcdserver: too many requests"}
{"level":"warn","ts":"2026-10-01T14:29:33.260481Z","caller":"etcdserver/server.go:1838","msg":"failed to publish local member to cluster through raft","local-member-id":"bbcf7589173ff1eb","local-member-attributes":"{Name:new-joiner ClientURLs:[https://etcd.example.net:2379]}","publish-timeout":"7s","error":"etcdserver: too many requests"}
...

The member never becomes ready, so its client API never starts serving. Only an etcd process restart clears it.

This was observed multiple times in 2 weeks on the same cluster, each time when refreshing member instances. Every occurrence was on a fresh, empty data directory (member-initialized: false).

The setup is as follows:

  1. A three node etcd cluster (etcd v3.7.1) is for extended periods idle
  2. Cluster raft index > 11000, snapshot-count is 10000, and snapshot-catchup-entries is set to DefaultSnapshotCatchUpEntries (5000)
  3. Then, adding a new empty member to the cluster, which will receive a full snapshot

This issue here may relate to the bug described in apecloud/kubeblocks#10917 (with etcd v3.6.1), where one cluster recovered after ~13 minutes and another stayed stuck.

Further log lines before we end up stuck are as follows (they also provide some ideas about where we are index-wise):

[...]

Oct 01 14:29:26 new-joiner etcd[4157]: {"level":"info","ts":"2026-10-01T14:29:26.203391Z","caller":"etcdmain/etcd.go:63","msg":"Running: ","args":["/usr/local/bin/etcd","--config-file=/usr/local/etc/etcd/etcd.conf"]}
Oct 01 14:29:26 new-joiner etcd[4157]: {"level":"info","ts":"2026-10-01T14:29:26.203461Z","caller":"etcdmain/etcd.go:122","msg":"Initialize and start etcd server","data-dir":"/var/lib/etcd/new-joiner.etcd","dir-type":"empty"}

[...]

Oct 01 14:29:26 new-joiner etcd[4157]: {"level":"info","ts":"2026-10-01T14:29:26.288539Z","caller":"rafthttp/http.go:268","msg":"receiving database snapshot","local-member-id":"bbcf7589173ff1eb","remote-snapshot-sender-id":"52e0fa513085ba38","incoming-snapshot-index":11476,"incoming-snapshot-message-size-bytes":28455,"incoming-snapshot-message-size":"28 kB"}
Oct 01 14:29:26 new-joiner etcd[4157]: {"level":"info","ts":"2026-10-01T14:29:26.293538Z","caller":"snap/db.go:65","msg":"saved database snapshot to disk","path":"/var/lib/etcd/new-joiner.etcd/member/snap/0000000000002cd4.snap.db","bytes":286720,"size":"287 kB"}
Oct 01 14:29:26 new-joiner etcd[4157]: {"level":"info","ts":"2026-10-01T14:29:26.293599Z","caller":"rafthttp/http.go:297","msg":"received and saved database snapshot","local-member-id":"bbcf7589173ff1eb","remote-snapshot-sender-id":"52e0fa513085ba38","incoming-snapshot-index":11476,"incoming-snapshot-size-bytes":286720,"incoming-snapshot-size":"287 kB","download-took":"5.277909ms"}
Oct 01 14:29:26 new-joiner etcd[4157]: {"level":"info","ts":"2026-10-01T14:29:26.293770Z","logger":"raft","caller":"v3@v3.7.0/log.go:467","msg":"log [committed=0, applied=0, applying=0, unstable.offset=1, unstable.offsetInProgress=1, len(unstable.Entries)=0] starts to restore snapshot [index: 11476, term: 39]"}
Oct 01 14:29:26 new-joiner etcd[4157]: {"level":"info","ts":"2026-10-01T14:29:26.293862Z","logger":"raft","caller":"v3@v3.7.0/raft.go:1985","msg":"bbcf7589173ff1eb switched to configuration voters=(52e0fa513085ba38 81705a3f4c4d4826 af2da7516853ba68 bbcf7589173ff1eb)"}
Oct 01 14:29:26 new-joiner etcd[4157]: {"level":"info","ts":"2026-10-01T14:29:26.293907Z","logger":"raft","caller":"v3@v3.7.0/raft.go:1939","msg":"bbcf7589173ff1eb [commit: 11476, lastindex: 11476, lastterm: 39] restored snapshot [index: 11476, term: 39]"}
Oct 01 14:29:26 new-joiner etcd[4157]: {"level":"info","ts":"2026-10-01T14:29:26.293931Z","logger":"raft","caller":"v3@v3.7.0/raft.go:1847","msg":"bbcf7589173ff1eb [commit: 11476] restored snapshot [index: 11476, term: 39]"}
Oct 01 14:29:26 new-joiner etcd[4157]: {"level":"info","ts":"2026-10-01T14:29:26.294156Z","caller":"etcdserver/server.go:1002","msg":"applying snapshot","current-snapshot-index":0,"current-applied-index":0,"incoming-leader-snapshot-index":11476,"incoming-leader-snapshot-term":39}
Oct 01 14:29:26 new-joiner etcd[4157]: {"level":"info","ts":"2026-10-01T14:29:26.299079Z","caller":"etcdserver/raft.go:278","msg":"applied incoming Raft snapshot","snapshot-index":11476}

[...]

Oct 01 14:29:26 new-joiner etcd[4157]: {"level":"info","ts":"2026-10-01T14:29:26.308162Z","caller":"etcdserver/server.go:1133","msg":"added peers from new cluster configuration"}
Oct 01 14:29:26 new-joiner etcd[4157]: {"level":"info","ts":"2026-10-01T14:29:26.308180Z","caller":"etcdserver/server.go:1010","msg":"applied snapshot","current-snapshot-index":11476,"current-applied-index":11476,"incoming-leader-snapshot-index":11476,"incoming-leader-snapshot-term":39}

[...]

Oct 01 14:29:26 new-joiner etcd[4157]: {"level":"info","ts":"2026-10-01T14:29:26.361607Z","caller":"etcdserver/server.go:509","msg":"initialized peer connections; fast-forwarding election ticks","local-member-id":"bbcf7589173ff1eb","forward-ticks":8,"forward-duration":"800ms","election-ticks":10,"election-timeout":"1s","active-remote-members":3}

[...]

Oct 01 14:29:26 new-joiner etcd[4157]: {"level":"info","ts":"2026-10-01T14:29:26.369281Z","caller":"rafthttp/stream.go:253","msg":"set message encoder","from":"bbcf7589173ff1eb","to":"af2da7516853ba68","stream-type":"stream MsgApp v2"}
Oct 01 14:29:26 new-joiner etcd[4157]: {"level":"info","ts":"2026-10-01T14:29:26.369317Z","caller":"rafthttp/stream.go:278","msg":"established TCP streaming connection with remote peer","stream-writer-type":"stream MsgApp v2","local-member-id":"bbcf7589173ff1eb","remote-peer-id":"af2da7516853ba68"}
Oct 01 14:29:26 new-joiner etcd[4157]: {"level":"info","ts":"2026-10-01T14:29:26.370149Z","caller":"rafthttp/stream.go:253","msg":"set message encoder","from":"bbcf7589173ff1eb","to":"af2da7516853ba68","stream-type":"stream Message"}
Oct 01 14:29:26 new-joiner etcd[4157]: {"level":"info","ts":"2026-10-01T14:29:26.370219Z","caller":"rafthttp/stream.go:278","msg":"established TCP streaming connection with remote peer","stream-writer-type":"stream Message","local-member-id":"bbcf7589173ff1eb","remote-peer-id":"af2da7516853ba68"}
Oct 01 14:29:33 new-joiner etcd[4157]: {"level":"warn","ts":"2026-10-01T14:29:33.260395Z","caller":"etcdserver/server.go:1838","msg":"failed to publish local member to cluster through raft","local-member-id":"bbcf7589173ff1eb","local-member-attributes":"{Name:new-joiner ClientURLs:[https://etcd.example.net:2379]}","publish-timeout":"7s","error":"etcdserver: request timed out, possibly due to connection lost"}
Oct 01 14:29:33 new-joiner etcd[4157]: {"level":"warn","ts":"2026-10-01T14:29:33.260454Z","caller":"etcdserver/server.go:1838","msg":"failed to publish local member to cluster through raft","local-member-id":"bbcf7589173ff1eb","local-member-attributes":"{Name:new-joiner ClientURLs:[https://etcd.example.net:2379]}","publish-timeout":"7s","error":"etcdserver: too many requests"}
Oct 01 14:29:33 new-joiner etcd[4157]: {"level":"warn","ts":"2026-10-01T14:29:33.260469Z","caller":"etcdserver/server.go:1838","msg":"failed to publish local member to cluster through raft","local-member-id":"bbcf7589173ff1eb","local-member-attributes":"{Name:new-joiner ClientURLs:[https://etcd.example.net:2379]}","publish-timeout":"7s","error":"etcdserver: too many requests"}
Oct 01 14:29:33 new-joiner etcd[4157]: {"level":"warn","ts":"2026-10-01T14:29:33.260481Z","caller":"etcdserver/server.go:1838","msg":"failed to publish local member to cluster through raft","local-member-id":"bbcf7589173ff1eb","local-member-attributes":"{Name:new-joiner ClientURLs:[https://etcd.example.net:2379]}","publish-timeout":"7s","error":"etcdserver: too many requests"}

[...]

# now we stay stuck in "etcdserver: too many requests" until we restart etcd

The loop causing these logs is in publishV3(), which means raftRequest() returns errors.ErrTooManyRequests. And this leads us this call to exceedsRequestLimit() in processInternalRaftRequestOnce‎(). As no feature-gates are enabled, we will pass by this check in exceedsRequestLimit(), where committedIndex <= appliedIndex+maxNormalGap is false, thus we return true and processInternalRaftRequestOnce‎() returns an errors.ErrTooManyRequests.

Now, as maxNormalGap is set to maxGapBetweenApplyAndCommitIndex (which is hard-coded to 5000), we obtain that committedIndex - appliedIndex > 5000 holds. Hence, appliedIndex must be way behind (or even 0) of committedIndex.

Note that the committedIndex is at 11476 from the snapshot metadata due to updateCommittedIndex(), which gives us a range of 0 to 6476 for the appliedIndex at the joining node.

This leads to the following observation: on the new cluster joiner, the applySnapshot() call in applyAll() will only update the etcdProgress for ep.appliedi and ep.appliedt to the index toApply.snapshot.Metadata.GetIndex() (which is > 5000) and the term toApply.snapshot.Metadata.GetTerm(), resp., right after the following log
line:

Oct 01 14:29:26 new-joiner etcd[4157]: {"level":"info","ts":"2026-10-01T14:29:26.308162Z","caller":"etcdserver/server.go:1133","msg":"added peers from new cluster configuration"}

But we do not call s.setAppliedIndex() in applySnapshot(), the only place where we can update s.appliedIndex is in apply() when receiving raft entries.

But since the cluster is idle and without writes, the new joiner then receives no raft entries for a long time, hence nothing advances the applied index/term in apply().

Thus, s.appliedIndex stays 0 indefinitely, and as a result the exceedsRequestLimit() check for committedIndex <= appliedIndex+maxNormalGap cannot be true and thus we will then always end up in
errors.ErrTooManyRequests (potentially indefinitely or for a prolonged time due to no raft entries to consume in apply()), even though we are actually starving for input.

The deadlock is as now follows:

   publishV3 → processInternalRaftRequestOnce → ErrTooManyRequests (ai=0, ci=11476)
       ↑                                              │
       │                                              ↓
   needs an applied entry                   readych never closes
       ↑                                              │
       └──────── only write pending is publish ←──────┘
                                                      │
                                                      ↓
                                      client API never serves
                                      → etcdctl unreachable

appliedIndex is only ever advanced by apply(), while committedIndex can be advanced by a snapshot alone. A member that catches up purely from a snapshot therefore ends up with a permanent phantom gap. To sum up, we have that

  1. updateCommittedIndex() raises committedIndex to the snapshot index
  2. applySnapshot() updates only the local etcdProgress struct and never calls setAppliedIndex()
  3. setAppliedIndex() has exactly two calls, both inside apply()
  4. The gap check in exceedsRequestLimit() uses s.getAppliedIndex() (stays initialized at 0) and s.getCommittedIndex() (was updated to the snapshot index 11476). With maxNormalGap = 5000, 11476 > 0 + 5000 is now true forever.

As long as the cluster stays idle, we cannot close the gap by calling setAppliedIndex() from apply(). The only pending write of this member is its own publish, which was rejected. An ordinary workload would have some write traffic with unrelated entries in apply() and thus nobody notices this.

The only way out is to restart etcd: the snapshot is already on disk and raft will resume from it. This time no ci will be set in updateCommittedIndex and thus we stay ci = 0 as committedEntries (idle cluster) and rd.Snapshot is empty.

As a result, committedIndex stays 0 and so will be the appliedIndex. exceedsRequestLimit() will evaluate 0 > 0 + 5000 to false, and publish will succeed. The client API will become reachable after publishV3() closes s.readych.

What did you expect to happen?

A member that has fully restored a leader snapshot should have appliedIndex equal to the snapshot index, and should be able to propose its publish immediately.

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

  1. 3-member cluster, --snapshot-count=10000, default --snapshot-catchup-entries=5000
  2. Advance the raft index past 10000
  3. Stop all writes, the cluster must be idle
  4. etcdctl member add a new member with an empty --data-dir

The joiner logs applying snapshot, then fails publish with too many requests indefinitely. The client API never comes up.

Anything else we need to know?

I'm about to open a PR for this, the fix I would like to propose is essentially to add the following code block

     s.setAppliedIndex(ep.appliedi)
     s.setTerm(ep.appliedt)

to applySnapshot right after this block

etcd/server/etcdserver/server.go

Lines 1140 to 1144 in 91703b3

ep.appliedt = toApply.snapshot.Metadata.GetTerm()
ep.appliedi = toApply.snapshot.Metadata.GetIndex()
ep.diskSnapshotIndex = ep.appliedi
ep.memorySnapshotIndex = ep.appliedi
ep.confState = toApply.snapshot.Metadata.ConfState

Etcd version (please run commands below)

Details 
etcd Version: 3.7.1
Git SHA: 5e7fd0d
Go Version: go1.26.5
Go OS/Arch: linux/amd64
cluster version: 3.7
storage version: 3.7.0

Etcd configuration (command line flags or environment variables)

Details 
snapshot-count: 10000
snapshot-catchup-entries: 5000
quota-backend-bytes: 2147483648
auto-compaction-mode: periodic
auto-compaction-retention: 1h0m0s
heartbeat-interval: 100ms
election-timeout: 1s
initial-cluster-state: existing
max-learners: 1
v2-deprecation: write-only
feature-gates: ""        # all defaults
max-cpu-available: 2

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

Details

Cluster when healthy: idle and well past the 5000 threshold:

ID                VERSION  DB SIZE  IN USE  RAFT TERM  RAFT INDEX  RAFT APPLIED INDEX
52e0fa513085ba38  3.7.1    287 kB   74 kB   39         11476       11476
81705a3f4c4d4826  3.7.1    287 kB   74 kB   39         11476       11476
af2da7516853ba68  3.7.1    287 kB   74 kB   39         11476       11476

SIGQUIT dump from the stuck member (full dump attached). Nothing is blocked, publishV3 is spinning.

etcd-sigquit-new-joiner.txt

Relevant log output

{"level":"warn","ts":"2026-10-01T14:29:33.260395Z","caller":"etcdserver/server.go:1838","msg":"failed to publish local member to cluster through raft","local-member-id":"bbcf7589173ff1eb","local-member-attributes":"{Name:new-joiner ClientURLs:[https://etcd.example.net:2379]}","publish-timeout":"7s","error":"etcdserver: request timed out, possibly due to connection lost"
{"level":"warn","ts":"2026-10-01T14:29:33.260454Z","caller":"etcdserver/server.go:1838","msg":"failed to publish local member to cluster through raft","local-member-id":"bbcf7589173ff1eb","local-member-attributes":"{Name:new-joiner ClientURLs:[https://etcd.example.net:2379]}","publish-timeout":"7s","error":"etcdserver: too many requests"}
{"level":"warn","ts":"2026-10-01T14:29:33.260469Z","caller":"etcdserver/server.go:1838","msg":"failed to publish local member to cluster through raft","local-member-id":"bbcf7589173ff1eb","local-member-attributes":"{Name:new-joiner ClientURLs:[https://etcd.example.net:2379]}","publish-timeout":"7s","error":"etcdserver: too many requests"}
{"level":"warn","ts":"2026-10-01T14:29:33.260481Z","caller":"etcdserver/server.go:1838","msg":"failed to publish local member to cluster through raft","local-member-id":"bbcf7589173ff1eb","local-member-attributes":"{Name:new-joiner ClientURLs:[https://etcd.example.net:2379]}","publish-timeout":"7s","error":"etcdserver: too many requests"}
...

Activity

  1. tkren
    added
    type/bug
    on Oct 5, 2026
  2. tkren
    added 2 commits that reference this issue on Oct 5, 2026

    etcdserver: advance appliedIndex and term when applying a leader snap…

    56a564f

    etcdserver: advance appliedIndex and term when applying a leader snap…

    cdaa4d7

  3. tkren commented on Oct 5, 2026

    @tkren
    tkren
    on Oct 5, 2026
    Author

    omg, this is a duplicate of #22516 I think

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    type/bug

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions