Antitheiss found "consistent_index isn't equal to snapshot index"

[serathius]

Bug report criteria

• This bug report is not security related, security issues should be disclosed privately via security@etcd.io.
• This is not a support request or question, support requests or questions should be raised in the etcd discussion forums.
• You have read the etcd bug reporting guidelines.
• Existing open issues along with etcd frequently asked questions have been checked and this is not a duplicate.

What happened?

Verify from

etcd/server/etcdserver/server.go

Line 1166 in 58cc32b

verify.Verify("consistent_index isn't equal to snapshot index", func() (bool, map[string]any) {

failed

message: "consistent_index isn't equal to snapshot index", 
file: client/pkg/verify/verify.go, 
line: 74, 
class: go.etcd.io/etcd/client/pkg/v3/verify, 
function: Verify
details: {consistent_index:193,snapshot_index:192}

https://linuxfoundation.antithesis.com/report/w5wGC8KVKcOaw6LCgcKRBAlgwq5lwrvCokHCvw/RG12kJ6VEErIyyusSvvX5M_3qdhpHQkObFFZ1wh88_g.html?auth=v2.public.eyJzY29wZSI6eyJSZXBvcnRTY29wZVYxIjp7ImFzc2V0IjoiUkcxMmtKNlZFRXJJeXl1c1N2dlg1TV8zcWRocEhRa09iRkZaMXdoODhfZy5odG1sIiwicmVwb3J0X2lkIjoidzV3R0M4S1ZLY09hdzZMQ2djS1JCQWxnd3E1bHdydkNva0hDdncifX0sIm5iZiI6IjIwMjUtMDctMzFUMDY6MDU6MjkuNzIyMjAyNDI2WiJ9f2Zss8naZWeeaWQXmeRfjomSDmTKeTX5jwu14MObBa9WJAr88XCMMc6WjE5E4mBpgSCCD0tD1tClGmqXU1NuAQ

What did you expect to happen?

No failures for verifies

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

Contact @marcus-hodgson-antithesis to access Antithesis environment

Anything else we need to know?

No response

Etcd version (please run commands below)

main branch

Etcd configuration (command line flags or environment variables)

paste your configuration here

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

$ etcdctl member list -w table
# paste output here

$ etcdctl --endpoints=<member list> endpoint status -w table
# paste output here

Relevant log output

[serathius]

/cc @ahrtr @fuweid @siyuanfoundation

[serathius]

@marcus-hodgson-antithesis the Antithesis report doesn't include dump. Could you fetch it and upload here?

[marcus-hodgson-antithesis]

var_report_dump (12).tar.gz

[ahrtr]

This issue is actually the same issue as #20434. Both of them were caused by the same reason: etcd1 received a bad snapshot.

The snapshot.Index was 106,

etcd/server/etcdserver/snapshot_merge.go

Lines 44 to 51 in 13cda0d

	snapshot := raftpb.Snapshot{
	Metadata: raftpb.SnapshotMetadata{
	Index: snapi,
	Term: snapt,
	ConfState: confState,
	},
	Data: d,
	}

But the real consistent_index/appliedIndex in the db sent was somehow 100,

etcd/server/etcdserver/snapshot_merge.go

Line 38 in 13cda0d

dbsnap := s.be.Snapshot()

What kind of fault did Antithesis inject on the snapshot (bbolt snapshot) or on the network transportation? Note I also see 0 consistent_index while the snapshot_index was 107, it might also be caused by the fault Antithesis injected.

BTW, I raised similar question in #20271, but haven't got response so far. If no further feedback provided, we can do nothing but to close the issues. I don't see much value for such test if there is no close collaboration.

Assertion
Always
message: "consistent_index isn't equal to snapshot index", 
file: client/pkg/verify/verify.go, 
line: 74, 
class: go.etcd.io/etcd/client/pkg/v3/verify, 
function: Verify
details: {consistent_index:0,snapshot_index:107}

[        94.257] [               etcd1] [err] {"level":"info","ts":"2025-08-02T00:16:25.574541Z","caller":"etcdserver/server.go:1001","msg":"applying snapshot","current-snapshot-index":102,"current-applied-index":105,"incoming-leader-snapshot-index":106,"incoming-leader-snapshot-term":6}
[        94.260] [               etcd0] [err] {"level":"info","ts":"2025-08-02T00:16:25.577193Z","caller":"rafthttp/snapshot_sender.go:131","msg":"sent database snapshot","snapshot-index":106,"remote-peer-id":"99eab3685d8363a1","bytes":99119,"size":"99 kB"}
[        94.280] [               etcd1] [err] {"level":"info","ts":"2025-08-02T00:16:25.597881Z","caller":"etcdserver/raft.go:276","msg":"applied incoming Raft snapshot","snapshot-index":106}
[        94.300] [               etcd1] [err] {"level":"info","ts":"2025-08-02T00:16:25.617134Z","logger":"bbolt","caller":"backend/backend.go:203","msg":"Opening db file (/var/etcd/data/member/snap/db) with mode -rw------- and with options: {Timeout: 0s, NoGrowSync: false, NoFreelistSync: true, PreLoadFreelist: false, FreelistType: hashmap, ReadOnly: false, MmapFlags: 8000, InitialMmapSize: 10737418240, PageSize: 0, NoSync: false, OpenFile: 0x0, Mlock: false, Logger: 0xc001944250}"}
[        94.300] [               etcd1] [err] {"level":"info","ts":"2025-08-02T00:16:25.617144Z","logger":"bbolt","caller":"bbolt@v1.4.2/db.go:321","msg":"Opening bbolt db (/var/etcd/data/member/snap/db) successfully"}
[        94.304] [               etcd1] [err] {"level":"info","ts":"2025-08-02T00:16:25.621190Z","caller":"storage/backend.go:80","msg":"opened backend db","path":"/var/etcd/data/member/snap/db","took":"12.609125ms"}
[        94.308] [                etcd] [   ]  - {"antithesis_assert":{"assert_type":"always","condition":false,"details":{"consistent_index":100,"snapshot_index":106},"display_type":"Always","hit":true,"id":"consistent_index isn't equal to snapshot index","location":{"begin_column":0,"begin_line":74,"class":"go.etcd.io/etcd/client/pkg/v3/verify","file":"client/pkg/verify/verify.go","function":"Verify"},"message":"consistent_index isn't equal to snapshot index","must_hit":true}}
[        94.309] [               etcd1] [err] {"level":"info","ts":"2025-08-02T00:16:25.626130Z","caller":"etcdserver/server.go:1049","msg":"restoring lease store"}
[        94.398] [               etcd1] [err] {"level":"info","ts":"2025-08-02T00:16:25.715407Z","caller":"etcdserver/server.go:1053","msg":"restored lease store"}
[        94.398] [               etcd1] [err] {"level":"info","ts":"2025-08-02T00:16:25.715915Z","caller":"etcdserver/server.go:1056","msg":"restoring mvcc store"}
[        94.415] [               etcd1] [err] {"level":"info","ts":"2025-08-02T00:16:25.732174Z","caller":"mvcc/kvstore.go:334","msg":"restored last compact revision","meta-bucket-name-key":"finishedCompactRev","restored-compact-revision":22}
[        94.418] [               etcd0] [err] {"level":"info","ts":"2025-08-02T00:16:25.735229Z","logger":"raft","caller":"v3@v3.6.0/raft.go:988","msg":"2c6c7b8d0d0933f7 is starting a new election at term 7"}
[        94.418] [               etcd0] [err] {"level":"info","ts":"2025-08-02T00:16:25.735234Z","logger":"raft","caller":"v3@v3.6.0/raft.go:930","msg":"2c6c7b8d0d0933f7 became pre-candidate at term 7"}
[        94.418] [               etcd0] [err] {"level":"info","ts":"2025-08-02T00:16:25.735236Z","logger":"raft","caller":"v3@v3.6.0/raft.go:1064","msg":"2c6c7b8d0d0933f7 [logterm: 7, index: 107] sent MsgPreVote request to 99eab3685d8363a1 at term 7"}
[        94.418] [               etcd0] [err] {"level":"info","ts":"2025-08-02T00:16:25.735238Z","logger":"raft","caller":"v3@v3.6.0/raft.go:1064","msg":"2c6c7b8d0d0933f7 [logterm: 7, index: 107] sent MsgPreVote request to dcb68c82481661be at term 7"}
[        94.419] [               etcd0] [err] {"level":"info","ts":"2025-08-02T00:16:25.735792Z","logger":"raft","caller":"v3@v3.6.0/raft.go:1077","msg":"2c6c7b8d0d0933f7 received MsgPreVoteResp from 2c6c7b8d0d0933f7 at term 7"}
[        94.419] [               etcd0] [err] {"level":"info","ts":"2025-08-02T00:16:25.735796Z","logger":"raft","caller":"v3@v3.6.0/raft.go:1693","msg":"2c6c7b8d0d0933f7 has received 1 MsgPreVoteResp votes and 0 vote rejections"}
[        94.419] [               etcd1] [err] {"level":"info","ts":"2025-08-02T00:16:25.736354Z","logger":"raft","caller":"v3@v3.6.0/raft.go:1101","msg":"99eab3685d8363a1 [logterm: 6, index: 106, vote: 2c6c7b8d0d0933f7] ignored MsgPreVote from 2c6c7b8d0d0933f7 [logterm: 7, index: 107] at term 7: lease is not expired (remaining ticks: 9)"}
[        94.419] [               etcd2] [err] {"level":"info","ts":"2025-08-02T00:16:25.736474Z","logger":"raft","caller":"v3@v3.6.0/raft.go:1101","msg":"dcb68c82481661be [logterm: 7, index: 107, vote: 2c6c7b8d0d0933f7] ignored MsgPreVote from 2c6c7b8d0d0933f7 [logterm: 7, index: 107] at term 7: lease is not expired (remaining ticks: 1)"}
[        94.428] [                etcd] [   ]  - {"antithesis_assert":{"assert_type":"always","condition":true,"details":{"previous revision":1,"revision":5},"display_type":"Always","hit":true,"id":"revision shouldn't be less than the previous revision","location":{"begin_column":0,"begin_line":74,"class":"go.etcd.io/etcd/client/pkg/v3/verify","file":"client/pkg/verify/verify.go","function":"Verify"},"message":"revision shouldn't be less than the previous revision","must_hit":true}}
[        94.499] [               etcd1] [err] {"level":"info","ts":"2025-08-02T00:16:25.816933Z","caller":"mvcc/kvstore.go:408","msg":"kvstore restored","current-rev":57}
[        94.505] [               etcd1] [err] {"level":"info","ts":"2025-08-02T00:16:25.822464Z","caller":"etcdserver/server.go:1064","msg":"restored mvcc store","consistent-index":100}
[        94.506] [               etcd1] [err] {"level":"info","ts":"2025-08-02T00:16:25.822995Z","caller":"etcdserver/server.go:1072","msg":"closing old backend file"}
[        94.506] [               etcd1] [err] {"level":"info","ts":"2025-08-02T00:16:25.823012Z","caller":"etcdserver/server.go:1084","msg":"restoring alarm store"}
[        94.508] [                etcd] [   ]  - {"antithesis_assert":{"assert_type":"always","condition":false,"details":{"currentIndex":100,"previousIndex":105},"display_type":"Always","hit":true,"id":"update of consistent index not advancing","location":{"begin_column":0,"begin_line":74,"class":"go.etcd.io/etcd/client/pkg/v3/verify","file":"client/pkg/verify/verify.go","function":"Verify"},"message":"update of consistent index not advancing","must_hit":true}}
[        94.510] [               etcd1] [err] {"level":"info","ts":"2025-08-02T00:16:25.827047Z","caller":"etcdserver/server.go:1074","msg":"closed old backend file"}
[        94.519] [               etcd1] [err] {"level":"info","ts":"2025-08-02T00:16:25.836507Z","caller":"etcdserver/server.go:1090","msg":"restored alarm store"}
[        94.520] [               etcd1] [err] {"level":"info","ts":"2025-08-02T00:16:25.837063Z","caller":"etcdserver/server.go:1093","msg":"restoring auth store"}
[        94.531] [               etcd1] [err] {"level":"info","ts":"2025-08-02T00:16:25.848474Z","caller":"etcdserver/server.go:1097","msg":"restored auth store"}
[        94.532] [               etcd1] [err] {"level":"info","ts":"2025-08-02T00:16:25.848983Z","caller":"etcdserver/server.go:1100","msg":"restoring v2 store"}

[serathius]

Thanks for investigation, I will try to work with @marcus-hodgson-antithesis to debug what is happening with wrong snapshot.

[marcus-hodgson-antithesis]

@ahrtr we have documentation that outlines the types of faults we are able to perform.

The Antithesis <> etcd setup currently include the following faults (basically all other than CPU modulation):

1. Thread pausing
2. All the network faults
3. Node throttling
4. Node hanging
5. Clock jitter
6. Node termination

We are working on a visualization tool for the fault injector for customers to be able to see what is going on within the test, but it is under development. I've created a log viewer for a "consistent_index isn't equal to snapshot index" property failure which includes our fault injector logs. They are noisy and might not make much sense. If you'd find a bug report helpful, I can create one of those as well!

If you are interested in how Antithesis implements network faults, we use iptables to route the network traffic to a Netfilter Queue. When we get packets in, we get the source and destination and if either of those matches an exclusion (which we do not have for etcd's case), we automatically let the packet go through with no faults. (If neither matches the exclusion, we may or may not apply a fault, depending on what the fault injector is doing right then.)

Let me know if you have any more questions about the network faults!

[serathius]

I think @ahrtr is asking about translating the exact failures that were simulated that lead to this bug. So translating the antithesis logs to something any person can understand. I myself don't understand what is Antithesis doing here.

235.899 containers_meta [host] {event:init,id:1fe6af69cd9a131a18fcf43377177628a7c9d958b30271ec857cb8e3bbb21336,image:us-central1-docker.pkg.dev/molten-verve-216720/linuxfoundation-repository/etcd-server:main_1eb4d3cd0a835ae810a1989e36d6a1ac21f292b8,name:etcd0}
235.899 containers_meta [host] {event:start,id:1fe6af69cd9a131a18fcf43377177628a7c9d958b30271ec857cb8e3bbb21336,image:us-central1-docker.pkg.dev/molten-verve-216720/linuxfoundation-repository/etcd-server:main_1eb4d3cd0a835ae810a1989e36d6a1ac21f292b8,name:etcd0}
236.298 antithesis_test_composer [host] received new input after waiting 1.1346955299377441 seconds
236.302 antithesis_test_composer [host] {composer_lifecycle:randomizer_new_input,event_rate:50,max_cpu_limit:30}
236.302 antithesis_test_composer [host]custom_command_weights: {}
236.302 antithesis_test_composer [host] set parallelism limit to inf
236.836 antithesis_test_composer [host] received new input after waiting 0.1910257339477539 seconds
236.837 antithesis_test_composer [host] {composer_lifecycle:randomizer_new_input,event_rate:50,max_cpu_limit:30}
236.837 antithesis_test_composer [host] custom_command_weights: {}
236.837 antithesis_test_composer [host] set parallelism limit to inf
244.837 antithesis_test_composer [host] received new input after waiting 0.5504186153411865 seconds
244.838 antithesis_test_composer [host] {composer_lifecycle:randomizer_new_input,event_rate:50,max_cpu_limit:30}
244.838 antithesis_test_composer [host] custom_command_weights: {}
244.838 antithesis_test_composer [host] set parallelism limit to inf
250.904 antithesis_test_composer [host] received new input after waiting 0.3283498287200928 seconds
250.905 antithesis_test_composer [host] {composer_lifecycle:randomizer_new_input,event_rate:50,max_cpu_limit:30}
250.906 antithesis_test_composer [host] custom_command_weights: {}
250.906 antithesis_test_composer [host] set parallelism limit to inf
254.346 antithesis_test_composer [host] received new input after waiting 1.7076671123504639 seconds
254.350 antithesis_test_composer [host] {composer_lifecycle:randomizer_new_input,event_rate:50,max_cpu_limit:30}
254.350 antithesis_test_composer [host] custom_command_weights: {}
254.350 antithesis_test_composer [host] set parallelism limit to inf
255.889 antithesis_test_composer [host] received new input after waiting 1.5389690399169922 seconds
255.892 antithesis_test_composer [host] {composer_lifecycle:randomizer_new_input,event_rate:50,max_cpu_limit:30}
255.893 antithesis_test_composer [host] custom_command_weights: {}
255.893 antithesis_test_composer [host] generating weights for rollout
255.893 antithesis_test_composer [host] {command:/opt/antithesis/test/v1/robustness/singleton_driver_traffic,weight:0.16666666666666666,weight_type:configured}
255.893 antithesis_test_composer [host] {command:/opt/antithesis/test/v1/robustness/finally_validation,weight:0.16666666666666666,weight_type:configured}
255.893 antithesis_test_composer [host] {command:/opt/antithesis/test/v1/robustness/singleton_driver_traffic,weight:0.23125181000783077,weight_type:masked_for_rollout}
255.893 antithesis_test_composer [host] {command:/opt/antithesis/test/v1/robustness/finally_validation,weight:0.16666666666666666,weight_type:masked_for_rollout}
255.893 antithesis_test_composer [host] set parallelism limit to inf
256.709 etcd etcd1 Assertion Always
  message: "consistent_index isn't equal to snapshot index", 
  file: client/pkg/verify/verify.go, 
  line: 74, 
  class: go.etcd.io/etcd/client/pkg/v3/verify, 
  function: Verify
  details: {consistent_index:193,snapshot_index:192}

[ahrtr]

the exact failures

Agreed.

First can you confirm if this is a deterministic test? If yes, then we need to discuss based on the exact test step and all the exact fault being injected in the process. More questions & discussions will be followed when we are getting more and more details.