err is auth: revision in header is old in ETCD 3.4.16

[IamSatyaonline]

What happened?

We are facing an data inconsistency issue in ETCD-3.3.11 and 3.4.16. we found this issue after the upgrade in most of the cases.we have investigated the ETCD logs and found there were some issue with auth revision. Seems it had been changed after the restart of pod and impacting the data inconsistency. We saw, revision are different on one the pod.
POD-0
[{"Endpoint":"https://localhost:2379","Status":{"header":{"cluster_id":2104678578865624298,"member_id":4962605495301377754,"revision":1306,"raft_term":18},"version":"3.4.16","dbSize":1597440,"leader":12637332122132188569,"raftIndex":1446,"raftTerm":18,"raftAppliedIndex":1446,"dbSizeInUse":1413120}}]
POD-1
[{"Endpoint":"https://localhost:2379","Status":{"header":{"cluster_id":2104678578865624298,"member_id":12637332122132188569,"revision":1306,"raft_term":18},"version":"3.4.16","dbSize":1564672,"leader":12637332122132188569,"raftIndex":1446,"raftTerm":18,"raftAppliedIndex":1446,"dbSizeInUse":1404928}}]
POD-2
[{"Endpoint":"https://localhost:2379","Status":{"header":{"cluster_id":2104678578865624298,"member_id":16734156434475844917,"revision":1111,"raft_term":18},"version":"3.4.16","dbSize":1228800,"leader":12637332122132188569,"raftIndex":1446,"raftTerm":18,"raftAppliedIndex":1446,"dbSizeInUse":1228800}}]

What did you expect to happen?

Revision should be same across the pods.

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

We are able to reproduce it only after the upgrade from ETCD-3.3.11 to ETCD-3.4.16, but it is not easily reproducible.

POD-0
[{"Endpoint":"https://localhost:2379","Status":{"header":{"cluster_id":2104678578865624298,"member_id":4962605495301377754,"revision":1306,"raft_term":18},"version":"3.4.16","dbSize":1597440,"leader":12637332122132188569,"raftIndex":1446,"raftTerm":18,"raftAppliedIndex":1446,"dbSizeInUse":1413120}}]
POD-1
[{"Endpoint":"https://localhost:2379","Status":{"header":{"cluster_id":2104678578865624298,"member_id":12637332122132188569,"revision":1306,"raft_term":18},"version":"3.4.16","dbSize":1564672,"leader":12637332122132188569,"raftIndex":1446,"raftTerm":18,"raftAppliedIndex":1446,"dbSizeInUse":1404928}}]
POD-2
[{"Endpoint":"https://localhost:2379","Status":{"header":{"cluster_id":2104678578865624298,"member_id":16734156434475844917,"revision":1111,"raft_term":18},"version":"3.4.16","dbSize":1228800,"leader":12637332122132188569,"raftIndex":1446,"raftTerm":18,"raftAppliedIndex":1446,"dbSizeInUse":1228800}}]

Anything else we need to know?

No response

Etcd version (please run commands below)

bash-4.4$ etcd --version
etcd Version: 3.4.16
Git SHA: d19fbe541
Go Version: go1.12.17
Go OS/Arch: linux/amd64

bash-4.4$ etcd version
2022-04-25 05:26:24.463400 E | etcdmain: error verifying flags, 'version' is not a valid flag. See 'etcd --help'.
bash-4.4$

Etcd configuration (command line flags or environment variables)

paste your configuration here

Etcd debug information (please run commands blow, 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
POD-0:
{"header":{"cluster_id":2104678578865624298,"member_id":4962605495301377754,"raft_term":18},"members":[{"ID":4962605495301377754,"name":"dced-0","peerURLs":["
https://dced-0.dced-peer.eiffelesc.svc.cluster.local:2380"],"clientURLs":["https://dced-0.dced.eiffelesc:2379"]},{"ID":12637332122132188569,"name":"dced-1","peerURLs":["https://dced-1.dced-peer.eiffelesc.svc.cluster.local:2380"],"clientURLs":["https://dced-1.dced.eiffelesc:2379"]},{"ID":16734156434475844917,"name":"dced-2","peerURLs":["https://dced-2.dced-peer.eiffelesc.svc.cluster.local:2380"],"clientURLs":["https://dced-2.dced.eiffelesc:2379"]}]}

POD-1:
{"header":{"cluster_id":2104678578865624298,"member_id":12637332122132188569,"raft_term":18},"members":[{"ID":4962605495301377754,"name":"dced-0","peerURLs":["https://dced-0.dced-peer.eiffelesc.svc.cluster.local:2380"],"clientURLs":["https://dced-0.dced.eiffelesc:2379"]},{"ID":12637332122132188569,"name":"dced-1","peerURLs":["https://dced-1.dced-peer.eiffelesc.svc.cluster.local:2380"],"clientURLs":["https://dced-1.dced.eiffelesc:2379"]},{"ID":16734156434475844917,"name":"dced-2","peerURLs":["https://dced-2.dced-peer.eiffelesc.svc.cluster.local:2380"],"clientURLs":["https://dced-2.dced.eiffelesc:2379"]}]}

POD-2
{"header":{"cluster_id":2104678578865624298,"member_id":16734156434475844917,"raft_term":18},"members":[{"ID":4962605495301377754,"name":"dced-0","peerURLs":["https://dced-0.dced-peer.eiffelesc.svc.cluster.local:2380"],"clientURLs":["https://dced-0.dced.eiffelesc:2379"]},{"ID":12637332122132188569,"name":"dced-1","peerURLs":["https://dced-1.dced-peer.eiffelesc.svc.cluster.local:2380"],"clientURLs":["https://dced-1.dced.eiffelesc:2379"]},{"ID":16734156434475844917,"name":"dced-2","peerURLs":["https://dced-2.dced-peer.eiffelesc.svc.cluster.local:2380"],"clientURLs":["https://dced-2.dced.eiffelesc:2379"]}]}

Relevant log output

022-03-24 02:15:14.024542 I | etcdserver: starting server... [version: 3.4.16, cluster version: to_be_decided]
raft2022/03/24 02:15:14 INFO: e83baa9da4c00535 switched to configuration voters=(4962605495301377754)
2022-03-24 02:15:14.025296 I | etcdserver/membership: added member 44deb767abd70eda [https://etcd-service-0.etcd-service-peer.eiffelesc.svc.cluster.local:2380] to cluster 1d35520433a8d4ea
2022-03-24 02:15:14.025326 I | rafthttp: starting peer 44deb767abd70eda...
2022-03-24 02:15:14.025356 I | rafthttp: started HTTP pipelining with peer 44deb767abd70eda
2022-03-24 02:15:14.025812 I | rafthttp: started streaming with peer 44deb767abd70eda (writer)
2022-03-24 02:15:14.026463 I | rafthttp: started streaming with peer 44deb767abd70eda (writer)
2022-03-24 02:15:14.029041 I | rafthttp: started peer 44deb767abd70eda
2022-03-24 02:15:14.029092 I | rafthttp: added peer 44deb767abd70eda
2022-03-24 02:15:14.029100 I | rafthttp: started streaming with peer 44deb767abd70eda (stream MsgApp v2 reader)
2022-03-24 02:15:14.029162 I | rafthttp: started streaming with peer 44deb767abd70eda (stream Message reader)
2022-03-24 02:15:14.029262 N | etcdserver/membership: set the initial cluster version to 3.3
2022-03-24 02:15:14.029308 I | etcdserver/api: enabled capabilities for version 3.3
raft2022/03/24 02:15:14 INFO: e83baa9da4c00535 switched to configuration voters=(4962605495301377754 12637332122132188569)
2022-03-24 02:15:14.030271 I | etcdserver/membership: added member af60d29c10528d99 [https://etcd-service-1.etcd-service-peer.eiffelesc.svc.cluster.local:2380] to cluster 1d35520433a8d4ea
2022-03-24 02:15:14.030294 I | rafthttp: starting peer af60d29c10528d99...
2022-03-24 02:15:14.030325 I | rafthttp: started HTTP pipelining with peer af60d29c10528d99
2022-03-24 02:15:14.034114 I | rafthttp: started streaming with peer af60d29c10528d99 (writer)
2022-03-24 02:15:14.034213 I | rafthttp: started streaming with peer af60d29c10528d99 (writer)
2022-03-24 02:15:14.036934 I | rafthttp: started streaming with peer af60d29c10528d99 (stream MsgApp v2 reader)
2022-03-24 02:15:14.037145 I | rafthttp: started streaming with peer af60d29c10528d99 (stream Message reader)
2022-03-24 02:15:14.037246 I | rafthttp: started peer af60d29c10528d99
2022-03-24 02:15:14.037286 I | rafthttp: added peer af60d29c10528d99
raft2022/03/24 02:15:14 INFO: e83baa9da4c00535 switched to configuration voters=(4962605495301377754 12637332122132188569 16734156434475844917)
2022-03-24 02:15:14.037486 I | etcdserver/membership: added member e83baa9da4c00535 [https://etcd-service-2.etcd-service-peer.eiffelesc.svc.cluster.local:2380] to cluster 1d35520433a8d4ea
2022-03-24 02:15:14.038398 W | etcdserver: failed to apply request "header:<ID:1070308296661102795 username:"root" auth_revision:11 > lease_revoke:id:0d997fb99eb3f316" with response "size:28" took (112.397µs) to execute, err is lease not found
2022-03-24 02:15:14.038441 W | etcdserver: failed to apply request "header:<ID:1070308296661102796 username:"root" auth_revision:11 > lease_revoke:id:0d997fb99eb3f314" with response "size:28" took (18.443µs) to execute, err is lease not found
2022-03-24 02:15:14.038796 W | etcdserver: failed to apply request "header:<ID:10203326865992843127 username:"root" auth_revision:11 > auth_role_revoke_permission:<role:"kms_role" key:"/kms/" range_end:"\000" > " with response "" took (7.084µs) to execute, err is auth: permission is not granted to the role
2022-03-24 02:15:14.038829 W | etcdserver: failed to apply request "header:<ID:10203326865992843128 username:"root" auth_revision:12 > auth_role_revoke_permission:<role:"kms_role" key:"/shelter/" range_end:"\000" > " with response "" took (3.462µs) to execute, err is auth: permission is not granted to the role
2022-03-24 02:15:14.038923 N | auth: role kms_role's permission of key /kms/ is updated as READWRITE
2022-03-24 02:15:14.039001 N | auth: role kms_role's permission of key /shelter/ is updated as READWRITE
2022-03-24 02:15:14.039060 W | auth: user key-service is already granted role kms_role
2022-03-24 02:15:14.041660 I | embed: ClientTLS: cert = /run/sec/certs/server/srvcert.pem, key = /run/sec/certs/server/srvprivkey.pem, trusted-ca = /data/combinedca/cacertbundle.pem, client-cert-auth = true, crl-file =
2022-03-24 02:15:14.041741 I | embed: listening for peers on [::]:2380
2022-03-24 02:15:14.089214 I | rafthttp: peer 44deb767abd70eda became active
2022-03-24 02:15:14.089282 I | rafthttp: established a TCP streaming connection with peer 44deb767abd70eda (stream Message reader)
raft2022/03/24 02:15:14 INFO: raft.node: e83baa9da4c00535 elected leader 44deb767abd70eda at term 4
2022-03-24 02:15:14.167093 I | rafthttp: established a TCP streaming connection with peer 44deb767abd70eda (stream MsgApp v2 reader)
2022-03-24 02:15:14.167519 I | rafthttp: peer af60d29c10528d99 became active
2022-03-24 02:15:14.167548 I | rafthttp: established a TCP streaming connection with peer af60d29c10528d99 (stream MsgApp v2 reader)
2022-03-24 02:15:14.169870 I | rafthttp: established a TCP streaming connection with peer af60d29c10528d99 (stream Message reader)
2022-03-24 02:15:14.175822 I | etcdserver: e83baa9da4c00535 initialized peer connection; fast-forwarding 8 ticks (election ticks 10) with 2 active peer(s)
2022-03-24 02:15:14.216796 W | auth: request auth revision is less than current node auth revision,current node auth revision is 17,request auth revision is 15,request key is /shelter/sys/counters/requests/2022/03, err is auth: revision in header is old
2022-03-24 02:15:14.216948 W | etcdserver: failed to apply request "header:<ID:1070308296661102798 username:"key-service" auth_revision:15 > put:<key:"/shelter/sys/counters/requests/2022/03" value_size:47 >" with response "" took (40.243µs) to execute, err is auth: revision in header is old
2022-03-24 02:15:14.216959 W | auth: request auth revision is less than current node auth revision,current node auth revision is 17,request auth revision is 15,request key is /kms/sys/counters/requests/2022/03, err is auth: revision in header is old
2022-03-24 02:15:14.216975 W | etcdserver: failed to apply request "header:<ID:1070308296661102799 username:"key-service" auth_revision:15 > put:<key:"/kms/sys/counters/requests/2022/03" value_size:47 >" with response "" took (5.927µs) to execute, err is auth: revision in header is old
2022-03-24 02:15:14.217077 W | auth: request auth revision is less than current node auth revision,current node auth revision is 17,request auth revision is 15,request key is /shelter/core/lock/d997fb99eb3ff8a, err is auth: revision in header is old
2022-03-24 02:15:14.217138 W | etcdserver: failed to apply request "header:<ID:10203326865992843149 username:"key-service" auth_revision:15 > txn:<compare:<target:CREATE key:"/shelter/core/lock/d997fb99eb3ff8a" create_revision:0 > success:<request_put:<key:"/shelter/core/lock/d997fb99eb3ff8a" lease:979954829138067338 >> failure:<>>" with response "" took (21.485µs) to execute, err is auth: revision in header is old

[IamSatyaonline]

Hi @ahrtr
Could you please help us to find the possible work around to fix this issue. Seems it was fixed in etcd-3.4.8 , but we have reproduced it in 3.4.16.

[ahrtr]

I suspect the you ran into the same issue as 11651.
You can follow the guide to restore the inconsistent member.

Please feedback if you still see the issue after the restoring. Please also try to reproduce this issue in 3.5.4.

[IamSatyaonline]

Hi @ahrtr
is there any work around to prevent this issue at run time before issue comes up ? guide is only applicable post the issue reproduction. I am able to reproduce it in 3.4.16. I will try later to reproduce it in 3.5.4.

[ahrtr]

FYI. issuecomment-1109823894

[ahrtr]

This is a duplicate to 13976. Let's track this issue there.