Data inconsistency in etcd version 3.3.11

[rahulbapumore]

etcdctl get command returns values sometimes and sometimes it does not return a value even if key value is present in etcd. You can see following command output executed immediately one by one.

bash-4.4$ etcdctl put /test thisistestvalue
OK
bash-4.4$ etcdctl get /test
bash-4.4$
bash-4.4$ etcdctl get /test
bash-4.4$ etcdctl get /test
/test
thisistestvalue
bash-4.4$ etcdctl get /test
/test
thisistestvalue

From below command, we can see that the inconsistence happens. We can see each time we query using etcdctl get and create_revision is different sometimes giving different values.

bash-4.4$ ETCDCTL_API=3 etcdctl get /test --write-out json --consistency="s"
{"header":{"cluster_id":10661059405016682411,"member_id":7511149175418186860,"revision":36793,"raft_term":16}}
bash-4.4$ ETCDCTL_API=3 etcdctl get /test --write-out json --consistency="s"

{"header":{"cluster_id":10661059405016682411,"member_id":14491470182485552592,"revision":10495,"raft_term":16}
,"kvs":[{"key":"L3Rlc3Q=","create_revision":6830,"mod_revision":6830,"version":1,"value":"dGVzdHZhbHVl"}],"count":1}
bash-4.4$ ETCDCTL_API=3 etcdctl get /test --write-out json --consistency="s"
{"header":{"cluster_id":10661059405016682411,"member_id":12240595110633392601,"revision":36802,"raft_term":16}}
bash-4.4$

bash-4.4$ ETCDCTL_API=3 etcdctl get /test1 --prefix=true --write-out json

{"header":{"cluster_id":10661059405016682411,"member_id":12240595110633392601,"revision":36818,"raft_term":16}
,"kvs":[{"key":"L2VyaWMtY2Nlcy1leHRlbnNpb24tbWFuYWdlci90ZXN0","create_revision":33064,"mod_revision":33064,"version":1,"value":"dmFsdWV0ZXN0"}],"count":1}
bash-4.4$
bash-4.4$ ETCDCTL_API=3 etcdctl get /test1 --prefix=true --write-out json

{"header":{"cluster_id":10661059405016682411,"member_id":14491470182485552592,"revision":10511,"raft_term":16}
,"kvs":[{"key":"L2VyaWMtY2Nlcy1leHRlbnNpb24tbWFuYWdlci90ZXN0","create_revision":3641,"mod_revision":3641,"version":1,"value":"bXl0ZXN0dmFsdWU="}],"count":1}
bash-4.4$ ETCDCTL_API=3 etcdctl get /test1 --prefix=true --write-out json

{"header":{"cluster_id":10661059405016682411,"member_id":7511149175418186860,"revision":36819,"raft_term":16}
,"kvs":[{"key":"L2VyaWMtY2Nlcy1leHRlbnNpb24tbWFuYWdlci90ZXN0","create_revision":33064,"mod_revision":33064,"version":1,"value":"dmFsdWV0ZXN0"}],"count":1}

Check the operation test as below: After performing Delete operation also we are able to get value for the deleted key.

bash-4.4$ etcdctl put /temp/test mytestvalue
OK
bash-4.4$ etcdctl get /temp/test
/temp/test
mytestvalue
bash-4.4$
bash-4.4$ etcdctl del /temp/test
1
bash-4.4$ etcdctl get /temp/test
/temp/test
mytestvalue
bash-4.4$ etcdctl get /temp/test
bash-4.4$ etcdctl get /temp/test
bash-4.4$ etcdctl get /temp/test
/temp/test
mytestvalue
bash-4.4$ etcdctl get /temp/test
bash-4.4$ etcdctl get /temp/test
/temp/test
mytestvalue
bash-4.4$ etcdctl get /temp/test
bash-4.4$ etcdctl get /temp/test
bash-4.4$ etcdctl get /temp/test
/temp/test
mytestvalue
bash-4.4$ etcdctl del /temp/test
0
bash-4.4$ etcdctl get /temp/test
/temp/test
mytestvalue
bash-4.4$ etcdctl del /temp/test
0
bash-4.4$ etcdctl get /temp/test
bash-4.4$ etcdctl get /temp/test
bash-4.4$ etcdctl get /temp/test
bash-4.4$ etcdctl get /temp/test
bash-4.4$ etcdctl get /temp/test
bash-4.4$ etcdctl get /temp/test
/temp/test
mytestvalue

These kind of data inconsistency is seen in etcd . ETCD guarantees Data consistency. Could you please help understanding the issue here.? whats happening exactly?

[ahrtr]

Please try ETCDCTL_API=2 etcdctl get /test

[rahulbapumore]

Hiii @ahrtr ,
Is there a known bug/issue with using ETCDCTL_API=3?

[ahrtr]

Note that any key that was created using the v2 API will not be able to be queried via the v3 API. A v3 API etcdctl get of a v2 key will exit with 0 and no key data, this is the expected behaviour.

By default, etcdctl on master (3.4) uses the v3 API and earlier versions (3.3 and earlier) default to the v2 API.

FYI. https://etcd.io/docs/v3.3/dev-guide/interacting_v3/

[rahulbapumore]

Hi @ahrtr ,
We are using 3.3.11 version. And we are using etcdctl get/etcdctl put/etcdctl del commands. It will default to v2 API.
So behavior is unexpected right.
See this command output -

bash-4.4$ etcdctl put /test thisistestvalue
OK
bash-4.4$ etcdctl get /test
bash-4.4$
bash-4.4$ etcdctl get /test
bash-4.4$ etcdctl get /test
/test
thisistestvalue
bash-4.4$ etcdctl get /test
/test
thisistestvalue

we are not using ETCDCTL_API=3 before commands, still issue is seen.

[ahrtr]

Please double check whether you set he environment variable ETCDCTL_API=3.
If yes, then you need to set it as ETCDCTL_API=2 or unset it.

[rahulbapumore]

bash-4.4$ ETCDCTL_API=2 etcdctl get /test
Error: client: etcd cluster is unavailable or misconfigured; error #0: unsupported protocol scheme "microservice name

error #0: unsupported protocol scheme "microservice name"

This error comes while working with ETCDCTL_API=2.

[rahulbapumore]

Hii @ahrtr ,
We are using ETCDCTL_API=3 to put as well as get key value. Data inconsistency is still there. Once we delete some key, we are able to get same Key with multiple etcdctl get commands. Please can you help
following is output of this command etcdctl --write-out=table endpoint status. We have 3 etcd members
bash-4.4$ etcdctl --write-out=table endpoint status
+---------------------------------------------------+------------------+---------+---------+-----------+-----------+------------+
| ENDPOINT | ID | VERSION | DB SIZE | IS LEADER | RAFT TERM | RAFT INDEX |
+---------------------------------------------------+------------------+---------+---------+-----------+-----------+------------+
| eric-data-distributed-coordinator-ed.zmorrah:2379 | 91362b77b262b2d7 | 3.3.11 | 938 kB | false | 7 | 7155 |
+---------------------------------------------------+------------------+---------+---------+-----------+-----------+------------+
bash-4.4$ etcdctl --write-out=table endpoint status
+---------------------------------------------------+------------------+---------+---------+-----------+-----------+------------+
| ENDPOINT | ID | VERSION | DB SIZE | IS LEADER | RAFT TERM | RAFT INDEX |
+---------------------------------------------------+------------------+---------+---------+-----------+-----------+------------+
| eric-data-distributed-coordinator-ed.zmorrah:2379 | bf6c922d66eede48 | 3.3.11 | 152 kB | true | 7 | 7157 |
+---------------------------------------------------+------------------+---------+---------+-----------+-----------+------------+
bash-4.4$ etcdctl --write-out=table endpoint status
+---------------------------------------------------+------------------+---------+---------+-----------+-----------+------------+
| ENDPOINT | ID | VERSION | DB SIZE | IS LEADER | RAFT TERM | RAFT INDEX |
+---------------------------------------------------+------------------+---------+---------+-----------+-----------+------------+
| eric-data-distributed-coordinator-ed.zmorrah:2379 | d711b56b01a0feec | 3.3.11 | 152 kB | false | 7 | 7157 |
+---------------------------------------------------+------------------+---------+---------+-----------+-----------+------------+

[rahulbapumore]

Hi @ahrtr ,
We have our microservice named etcd-micro where we are using etcd for storing data. When we install our microservice standalone this issue is not reproducible. But if we upgrade between 2 versions of our microservice , this data inconsistency issue is seen. We are not changing anything betwee our version related to etcd. But dont know why we are seeing this behavior. @ahrtr what might be going wrong?

Thanks

[rahulbapumore]

Hiii,
Any comment on this?

[ahrtr]

Sorry, I have no knowledge on your micro-service, so I can't provide any comments here. I suggest you to raise an issue to the engineering team of the micro-service.

[rahulbapumore]

Hi @ahrtr ,
actually etcdctl client is internal to etcd container. So microservice upgrade can not impact etcdctl, But etcd is behaving wrongly and giving data inconsistency. We checked etcd documentation as well, there it is mentioned that it is impossible for etcd to ensure strict consistency and Etcd does not guarantee that it will return to read most recent value. .
So @ahrtr is there any work around or way to achievie strict consistency in etcd. If you could help us on that then it will be helpful.
We found some of threads where one way to handle this was setting quorum=true, but we did not understand how to set that flag. So if you can give some way to avoid data inconsistency in etcd then it will be helpful.

Thanks,
Rahul

[rahulbapumore]

hi @ahrtr ,
Any updates?

[ahrtr]

bash-4.4$ ETCDCTL_API=2 etcdctl get /test Error: client: etcd cluster is unavailable or misconfigured; error #0: unsupported protocol scheme "microservice name

error #0: unsupported protocol scheme "microservice name"

This error comes while working with ETCDCTL_API=2.

You need to resolve this issue firstly. It looks like related to your micro-service. Please also make sure you are using the matched versions between etcd and etcdctl.

Again, Please consult with the engineering/dev team of the micro-service.

[rahulbapumore]

Hi @ahrtr ,
We are getting this issue in etcd version 3.4.16 as well, there we are using ETCDCTL_API=3.
Please could you help with this issue

Thanks

[ahrtr]

Please check the following info,

1. The exact etcd and etcdctl version;
2. Run "etcdctl member list -w table";
3. Run "etcdctl --endpoints=xxxx endpoint status -w table"

[rahulbapumore]

bash-4.4$ etcdctl version
etcdctl version: 3.4.16
API version: 3.4

bash-4.4$ etcdctl member list -w table
+------------------+---------+----------------------------------------+----------------------------------------------------------------------------------------------------------------------------+-----------------------------------------------------------------------------------------------------+------------+
| ID | STATUS | NAME | PEER ADDRS | CLIENT ADDRS | IS LEARNER |
+------------------+---------+----------------------------------------+----------------------------------------------------------------------------------------------------------------------------+-----------------------------------------------------------------------------------------------------+------------+
| 4494f41c14b6a3cd | started | eric-data-distributed-coordinator-ed-2 | https://eric-data-distributed-coordinator-ed-2.eric-data-distributed-coordinator-ed-peer.cces-ci-ns.svc.cluster.local:2380 | https://eric-data-distributed-coordinator-ed-2.eric-data-distributed-coordinator-ed.cces-ci-ns:2379 | false |
| 682d8d91e309c6bc | started | eric-data-distributed-coordinator-ed-1 | https://eric-data-distributed-coordinator-ed-1.eric-data-distributed-coordinator-ed-peer.cces-ci-ns.svc.cluster.local:2380 | https://eric-data-distributed-coordinator-ed-1.eric-data-distributed-coordinator-ed.cces-ci-ns:2379 | false |
| 683cf66117c4ec6c | started | eric-data-distributed-coordinator-ed-0 | https://eric-data-distributed-coordinator-ed-0.eric-data-distributed-coordinator-ed-peer.cces-ci-ns.svc.cluster.local:2380 | https://eric-data-distributed-coordinator-ed-0.eric-data-distributed-coordinator-ed.cces-ci-ns:2379 | false |
+------------------+---------+----------------------------------------+----------------------------------------------------------------------------------------------------------------------------+-----------------------------------------------------------------------------------------------------+------------+

bash-4.4$ echo $ETCDCTL_ENDPOINTS
eric-data-distributed-coordinator-ed.cces-ci-ns:2379

bash-4.4$ etcdctl --endpoints=eric-data-distributed-coordinator-ed.cces-ci-ns:2379 endpoint status -w table 2022-01-07 09:47:46.580220 C | pkg/flags: conflicting environment variable "ETCDCTL_ENDPOINTS" is shadowed by corresponding command-line flag (either unset environment variable or disable flag)

bash-4.4$ ETCDCTL_API=3 etcdctl get /test --prefix=true --write-out json
{"header":{"cluster_id":10661059405016682411,"member_id":7506811811615327932,"revision":5010,"raft_term":7}}
bash-4.4$ ETCDCTL_API=3 etcdctl get /test --prefix=true --write-out json
{"header":{"cluster_id":10661059405016682411,"member_id":7511149175418186860,"revision":5010,"raft_term":7}}
bash-4.4$ ETCDCTL_API=3 etcdctl get /test --prefix=true --write-out json
{"level":"warn","ts":"2022-01-07T09:50:34.275Z","caller":"clientv3/retry_interceptor.go:62","msg":"retrying of unary invoker failed","target":"endpoint://client-007dbea6-ac22-4ef0-9533-a9b62a53d183/eric-data-distributed-coordinator-ed.cces-ci-ns:2379","attempt":0,"error":"rpc error: code = DeadlineExceeded desc = context deadline exceeded"}
Error: context deadline exceeded

[rahulbapumore]

Hi @ahrtr ,
This is the output for commands you suggested.
Is this information helpful?

Thanks,
Rahul

[ahrtr]

You do not input the correct endpoints when executing etcdctl --endpoints=${endpoints} endpoint status -w table. You need to get all etcd endpoints included with comma separated.

Please format the output in code.

[rahulbapumore]

[rahulbapumore]

Hi @ahrtr ,
Does this help?

Thanks,
Rahul

[rahulbapumore]

Hi @ahrtr ,
Any updates?

Thanks,
Rahul

[rahulbapumore]

Hi @ahrtr
Any updates?

Thanks

[ahrtr]

Please execute the following commands and provide feedbacks (AGAIN PLEASE FORMAT ALL YOUR INPUTs IN CODE).

etcdctl version
etcd --version
export ENDPOINTS=https://eric-data-distributed-coordinator-ed-0.eric-data-distributed-coordinator-ed.cces-ci-ns:2379,https://eric-data-distributed-coordinator-ed-1.eric-data-distributed-coordinator-ed.cces-ci-ns:2379,https://eric-data-distributed-coordinator-ed-2.eric-data-distributed-coordinator-ed.cces-ci-ns:2379
ETCDCTL_API=3 etcdctl --endpoint $ENDPOINTS member list -w table
ETCDCTL_API=3 etcdctl --endpoint $ENDPOINTS endpoint status -w table

Please also provide the complete logs of your etcd instances.

[rahulbapumore]

Hi @ahrtr ,

bash-4.4$ ETCDCTL_API=3 etcdctl --endpoints $ENDPOINTS member list -w table
2022-01-17 15:19:12.929634 C | pkg/flags: conflicting environment variable "ETCDCTL_ENDPOINTS" is shadowed by corresponding command-line flag (either unset environment variable or disable flag)

bash-4.4$ ETCDCTL_API=3 etcdctl --endpoints $ENDPOINTS endpoint status -w table
2022-01-17 15:20:31.771346 C | pkg/flags: conflicting environment variable "ETCDCTL_ENDPOINTS" is shadowed by corresponding command-line flag (either unset environment variable or disable flag)

I am getting this output for last 2 commands.

[ahrtr]

Please check the environment variables, you either configure the ETCDCTL_ENDPOINTS environment variable or provide the --endpoints flag when executing etcdctl command.

[rahulbapumore]

Hi @ahrtr ,
We have configured the ETCDCTL_ENDPOINTS environment variable.

bash-4.4$ echo $ETCDCTL_ENDPOINTS
eric-data-distributed-coordinator-ed.zwadmoh:2379

still getting same error when tried with ETCDCTL_ENDPOINTS environment variable.

bash-4.4$ ETCDCTL_API=3 etcdctl --endpoints $ETCDCTL_ENDPOINTS member list -w table
2022-01-18 05:06:40.262652 C | pkg/flags: conflicting environment variable "ETCDCTL_ENDPOINTS" is shadowed by corresponding command-line flag (either unset environment variable or disable flag)

still getting same error when tried with steps in your comment(exporting endpoints, then running command.).

bash-4.4$ export ENDPOINTS=https://eric-data-distributed-coordinator-ed-0.eric-data-distributed-coordinator-ed.cces-ci-ns:2379,https://eric-data-distributed-coordinator-ed-1.eric-data-distributed-coordinator-ed.cces-ci-ns:2379,https://eric-data-distributed-coordinator-ed-2.eric-data-distributed-coordinator-ed.cces-ci-ns:2379
bash-4.4$ ETCDCTL_API=3 etcdctl --endpoints $ENDPOINTS member list -w table 2022-01-18 05:08:44.416940 C | pkg/flags: conflicting environment variable "ETCDCTL_ENDPOINTS" is shadowed by corresponding command-line flag (either unset environment variable or disable flag)

Thanks,
Rahul

[ahrtr]

How many members are in your etcd cluster? Why there is only one endpoint in the environment variable ETCDCTL_ENDPOINTS?

Note that you have two choices to run etcdctl:

1. Configure correctly the environment variable ETCDCTL_ENDPOINTS, then you can execute "etcdctl endpoint status -w table";
2. Or unset the environment variable ETCDCTL_ENDPOINTS, and follow my previous guide to execute "etcdctl --endpoints xxx endpoint status -w table"

I suggest you to read through the official guide to get more understandings on etcd.

[rahulbapumore]

logs.txt
Hi, @ahrtr ,
Sorry for delay.
I have attached file here which is having output of all commands you asked.
Please have look, and do you find anything suspecious?
Please do reply

Thanks,
Rahul

[rahulbapumore]

Hi @ahrtr ,
In one of the ETCD deployment , worker nodes were rebooted and it caused same data inconsistency issue, all pods were having different values for same keys.
Do you know any work around for syncing data across 3 pods?
If you could provide us WA that will be helpful

Thanks

[ahrtr]

You can remove the member, which is out of sync, from the cluster, and remove the local data of the member as well. Afterwards, join the member to the cluster again, then etcd will sync data automatically.

Another solution is to follow the https://etcd.io/docs/v3.5/op-guide/recovery/ . But it may cause some downtime on the application.

Please backup all data before any actions!

[rahulbapumore]

statefulset.txt
configmap.txt
Hi @ahrtr ,
I am attaching statefulset and configmap file to give you idea exactly how we are configuring etcd.
Configmap contains 2 scripts add-member.sh which is getting called in init container which will exit after running.
then entrypoint.sh script will run in our main DCED container.
other internal scripts are also there which are called from add-member.sh and entrypoint.sh
etcdrunner.sh script is there which starts etcd process.
We hope that will help to find out any wrong configuration things

Thanks.

[rahulbapumore]

@ahrtr

[rahulbapumore]

@ahrtr any updates

[sanjitp]

We want to understand the root cause of this problem where data is being inconsistent and revisions are different across pods, we're suspecting this could the reason:
Failure could be introduced by the consistentIndex, and consistenIindex in fact rely on the mvcc too.
When etcd is restarted during consistentIndex change, revision problem will be introduced.
Please let us know your view on this, if this is not the case , could you please share the root cause

We found multiple tickets for the same issue:
#9630
#10407
#10594
#11643

Hope this might help:
#11699

[ahrtr]

I am a little busy this week, will have a deep dive sometime next week on this.

[sanjitp]

Hi
Any updates on this

[sanjitp]

Hi
Could you please provide the solution to the above queries as it is blocking many applications releases and this issue is highly escalated and customers are expecting the Root cause analysis for this data inconsistency in ETCD

[ahrtr]

Most likely you are running into the same issue as 11651. You can double check the values of authRevision, consistent_index and term using the tool etcd-dump-db.

I just submitted a PR pull/13834 to enhance the print format.

The issue 11651 has already been fixed in 3.3.21, 3.4.8 and 3.5.0, so you should be good because you are already on 3.4.16.

But we still see data inconsistency issue raised on 3.5.1, and the root cause isn't clear yet.

etcd is an open source project, everyone, including you, feel free to dig into whatever issue they are interested in. Note that nobody get paid, any issues raised by your customers should be escalated to the management team in your company instead of the community. Of course, any issue is welcome to be raised in the community; but it depends on all contributors, including you, to resolve all issues.

[rahulbapumore]

Hi @ahrtr ,
We have seen one more data inconsistency issue and cause is different and we think its similar to #11651. You said this was fixed in 3.4.8 and we are using 3.4.16 etcd version still we are facing this issue.

[{"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}}]
[{"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}}]
[{"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}}]

and following log lines states that -
2022-03-24 02:15:14.217423 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/cluster/feature-flags, err is auth: revision in header is old
2022-03-24 02:15:14.217439 W | etcdserver: failed to apply request "header:<ID:10203326865992843181 username:"mc-sec-key-management" auth_revision:15 > put:<key:"/shelter/core/cluster/feature-flags" value_size:69 >" with response "" took (4.149µs) to execute, err is auth: revision in header is old

etcd3.4.16 new added log also proved the apply requet has less auth-revision current node auth-revision, caused the data is not applied on the disk even raft if ok.

Could you confirm that issue is still there in 3.4.16 version?

Thanks,
Rahul

[rahulbapumore]

Hi @ahrtr ,
Any updates on last comment

[ahrtr]

Thanks @rahulbapumore for the info. Have you performed the the workaround previously after upgrading to 3.4.16? Please note that I am asking you to perform the workaround now!

The reason why I ask this is I need to understand whether the issue was carried over from old version to 3.4.16 or the issue is still reproducible on 3.4.16.

[rahulbapumore]

Hi @ahrtr ,
When we installed microservice with etcd 3.3.11 that time data inconsistency issue was not there and everything was working fine.
After upgrading to microservice with etcd 3.4.16 , we went into data inconsistency issue and revisions were different.
From this we can say right that issue existed in 3.4.16 as well.
After applying workaround issue will be resolved , so what exactly want us to try out?

Thanks,
Rahul

[rahulbapumore]

Hi @ahrtr

[ahrtr]

I started 2000 threads (using Jmeter) which concurrently send requests to an etcd cluster (3.4.16) with 3 members, and in the meanwhile occasionally kill the members, but couldn't reproduce this issue. I do not see any issue by checking the source code of release-3.4.

Note that in your previous comment , all members have the same endpoint https://localhost:2379; obviously it is not correct. Please double check your environment/configuration.

[rahulbapumore]

Hi @ahrtr ,
This we are not using this https://localhost:2379 for ETCDCTL_ENDPOINTS, by mistake we had added for testing purpose.
Its not the issue.
Issue could be something different.

Thanks

[rahulbapumore]

Hi @ahrtr ,
We could see some of the error logs where data inconsistency issue occurred.
Could you confirm these error logs are related to some known issue?

**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://eric-data-distributed-coordinator-ed-2.eric-data-distributed-coordinator-ed-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 eric-sec-key-management 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:\"eric-sec-key-management\" 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:\"eric-sec-key-management\" 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:\"eric-sec-key-management\" 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
2022-03-24 02:15:14.217211 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/core/lock/d997fb99eb3ff91, err is auth: revision in header is old
2022-03-24 02:15:14.217239 W | etcdserver: failed to apply request "header:<ID:10203326865992843156 username:\"eric-sec-key-management\" auth_revision:15 > txn:<compare:<target:CREATE key:\"/kms/core/lock/d997fb99eb3ff91\" create_revision:0 > success:<request_put:<key:\"/kms/core/lock/d997fb99eb3ff91\" lease:979954829138067345 >> failure:<>>" with response "" took (12.327µs) to execute, err is auth: revision in header is old
2022-03-24 02:15:14.217249 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/leader/dd6333b5-361d-feca-e0e1-705f79d02baf, err is auth: revision in header is old
2022-03-24 02:15:14.217274 W | etcdserver: failed to apply request "header:<ID:1070308296661102800 username:\"eric-sec-key-management\" auth_revision:15 > delete_range:<key:\"/shelter/core/leader/dd6333b5-361d-feca-e0e1-705f79d02baf\" > " with response "" took (7.386µs) to execute, err is auth: revision in header is old
2022-03-24 02:15:14.217280 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/core/leader/358aa84d-03ff-32fa-35b1-e597af763118, err is auth: revision in header is old
2022-03-24 02:15:14.217293 W | etcdserver: failed to apply request "header:<ID:1070308296661102801 username:\"eric-sec-key-management\" auth_revision:15 > delete_range:<key:\"/kms/core/leader/358aa84d-03ff-32fa-35b1-e597af763118\" > " with response "" took (4.155µs) to execute, err is auth: revision in header is old
2022-03-24 02:15:14.217299 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/eda7fb99d081ad9, err is auth: revision in header is old
2022-03-24 02:15:14.217312 W | etcdserver: failed to apply request "header:<ID:1070308296661102802 username:\"eric-sec-key-management\" auth_revision:15 > delete_range:<key:\"/shelter/core/lock/eda7fb99d081ad9\" > " with response "" took (4.091µs) to execute, err is auth: revision in header is old
2022-03-24 02:15:14.217317 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/core/lock/eda7fb99d081adb, err is auth: revision in header is old
2022-03-24 02:15:14.217330 W | etcdserver: failed to apply request "header:<ID:1070308296661102803 username:\"eric-sec-key-management\" auth_revision:15 > delete_range:<key:\"/kms/core/lock/eda7fb99d081adb\" > " with response "" took (4.027µs) to execute, err is auth: revision in header is old
2022-03-24 02:15:14.217339 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.217356 W | etcdserver: failed to apply request "header:<ID:10203326865992843159 username:\"eric-sec-key-management\" auth_revision:15 > put:<key:\"/shelter/core/lock/d997fb99eb3ff8a\" value_size:36 lease:979954829138067338 >" with response "" took (5.035µs) to execute, err is auth: revision in header is old
2022-03-24 02:15:14.217362 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/core/lock/d997fb99eb3ff91, err is auth: revision in header is old
2022-03-24 02:15:14.217375 W | etcdserver: failed to apply request "header:<ID:10203326865992843161 username:\"eric-sec-key-management\" auth_revision:15 > put:<key:\"/kms/core/lock/d997fb99eb3ff91\" value_size:36 lease:979954829138067345 >" with response "" took (4.078µs) to execute, err is auth: revision in header is old
2022-03-24 02:15:14.217385 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/leader/b5f8487c-ce11-a394-7122-4ddbccc3399c, err is auth: revision in header is old
2022-03-24 02:15:14.217398 W | etcdserver: failed to apply request "header:<ID:10203326865992843178 username:\"eric-sec-key-management\" auth_revision:15 > put:<key:\"/shelter/core/leader/b5f8487c-ce11-a394-7122-4ddbccc3399c\" value_size:1608 >" with response "" took (4.385µs) to execute, err is auth: revision in header is old
2022-03-24 02:15:14.217403 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/core/leader/da7d6abf-5261-d22f-4213-b11115faa115, err is auth: revision in header is old
2022-03-24 02:15:14.217417 W | etcdserver: failed to apply request "header:<ID:10203326865992843179 username:\"eric-sec-key-management\" auth_revision:15 > put:<key:\"/kms/core/leader/da7d6abf-5261-d22f-4213-b11115faa115\" value_size:1609 >" with response "" took (4.821µs) to execute, err is auth: revision in header is old
2022-03-24 02:15:14.217423 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/cluster/feature-flags, err is auth: revision in header is old
2022-03-24 02:15:14.217439 W | etcdserver: failed to apply request "header:<ID:10203326865992843181 username:\"eric-sec-key-management\" auth_revision:15 > put:<key:\"/shelter/core/cluster/feature-flags\" value_size:69 >" with response "" took (4.149µs) to execute, err is auth: revision in header is old
2022-03-24 02:15:14.217447 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/core/cluster/feature-flags, err is auth: revision in header is old
2022-03-24 02:15:14.217459 W | etcdserver: failed to apply request "header:<ID:10203326865992843183 username:\"eric-sec-key-management\" auth_revision:15 > put:<key:\"/kms/core/cluster/feature-flags\" value_size:69 >" with response "" took (4.032µs) to execute, err is auth: revision in header is old
2022-03-24 02:15:14.217466 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/logical/94a702ce-a10f-2931-94fd-e62d565eee60/casesensitivity, err is auth: revision in header is old
2022-03-24 02:15:14.217482 W | etcdserver: failed to apply request "header:<ID:10203326865992843226 username:\"eric-sec-key-management\" auth_revision:15 > put:<key:\"/shelter/logical/94a702ce-a10f-2931-94fd-e62d565eee60/casesensitivity\" value_size:69 >" with response "" took (4.1µs) to execute, err is auth: revision in header is old
2022-03-24 02:15:14.217488 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/logical/e4977d9c-9daf-6397-fef1-8c985643721f/casesensitivity, err is auth: revision in header is old
2022-03-24 02:15:14.217500 W | etcdserver: failed to apply request "header:<ID:10203326865992843244 username:\"eric-sec-key-management\" auth_revision:15 > put:<key:\"/kms/logical/e4977d9c-9daf-6397-fef1-8c985643721f/casesensitivity\" value_size:69 >" with response "" took (4.273µs) to execute, err is auth: revision in header is old
2022-03-24 02:15:14.217509 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/logical/94a702ce-a10f-2931-94fd-e62d565eee60/packer/buckets/4, err is auth: revision in header is old
2022-03-24 02:15:14.217522 W | etcdserver: failed to apply request "header:<ID:10203326865992843251 username:\"eric-sec-key-management\" auth_revision:15 > put:<key:\"/shelter/logical/94a702ce-a10f-2931-94fd-e62d565eee60/packer/buckets/4\" value_size:480 >" with response "" took (4.214µs) to execute, err is auth: revision in header is old
2022-03-24 02:15:14.217530 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/token/accessor/0ad5472062556c01aece0f5a735b0e243c83504e, err is auth: revision in header is old
2022-03-24 02:15:14.217543 W | etcdserver: failed to apply request "header:<ID:10203326865992843257 username:\"eric-sec-key-management\" auth_revision:15 > put:<key:\"/shelter/sys/token/accessor/0ad5472062556c01aece0f5a735b0e243c83504e\" value_size:138 >" with response "" took (4.351µs) to execute, err is auth: revision in header is old
2022-03-24 02:15:14.217550 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/token/id/hb6c0289ac4c999cf88e1c4d9cea317e5892d17fec06a5dbe599aefe7dc280d6e, err is auth: revision in header is old
2022-03-24 02:15:14.217568 W | etcdserver: failed to apply request "header:<ID:10203326865992843260 username:\"eric-sec-key-management\" auth_revision:15 > put:<key:\"/shelter/sys/token/id/hb6c0289ac4c999cf88e1c4d9cea317e5892d17fec06a5dbe599aefe7dc280d6e\" value_size:828 >" with response "" took (6.893µs) to execute, err is auth: revision in header is old
2022-03-24 02:15:14.217574 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/expire/id/auth/kubernetes/login/hb6c0289ac4c999cf88e1c4d9cea317e5892d17fec06a5dbe599aefe7dc280d6e, err is auth: revision in header is old
2022-03-24 02:15:14.217588 W | etcdserver: failed to apply request "header:<ID:10203326865992843261 username:\"eric-sec-key-management\" auth_revision:15 > put:<key:\"/shelter/sys/expire/id/auth/kubernetes/login/hb6c0289ac4c999cf88e1c4d9cea317e5892d17fec06a5dbe599aefe7dc280d6e\" value_size:1644 >" with response "" took (4.058µs) to execute, err is auth: revision in header is old
2022-03-24 02:15:14.217598 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/token/id/hd8f8461e4534812c6d951a00aca52f0865944f8d8f8feed028d5640ae34a92d6, err is auth: revision in header is old
2022-03-24 02:15:14.217624 W | etcdserver: failed to apply request "header:<ID:10203326865992843280 username:\"eric-sec-key-management\" auth_revision:15 > put:<key:\"/shelter/sys/token/id/hd8f8461e4534812c6d951a00aca52f0865944f8d8f8feed028d5640ae34a92d6\" value_size:871 >" with response "" took (21.234µs) to execute, err is auth: revision in header is old
2022-03-24 02:15:14.217630 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/expire/id/auth/kubernetes/login/hd8f8461e4534812c6d951a00aca52f0865944f8d8f8feed028d5640ae34a92d6, err is auth: revision in header is old
2022-03-24 02:15:14.217645 W | etcdserver: failed to apply request "header:<ID:10203326865992843284 username:\"eric-sec-key-management\" auth_revision:15 > delete_range:<key:\"/shelter/sys/expire/id/auth/kubernetes/login/hd8f8461e4534812c6d951a00aca52f0865944f8d8f8feed028d5640ae34a92d6\" > " with response "" took (4.364µs) to execute, err is auth: revision in header is old
2022-03-24 02:15:14.217651 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/token/accessor/a64aa78d1e78507b67e15a55fe466d7de086ed9f, err is auth: revision in header is old
2022-03-24 02:15:14.217665 W | etcdserver: failed to apply request "header:<ID:10203326865992843285 username:\"eric-sec-key-management\" auth_revision:15 > delete_range:<key:\"/shelter/sys/token/accessor/a64aa78d1e78507b67e15a55fe466d7de086ed9f\" > " with response "" took (4.522µs) to execute, err is auth: revision in header is old
2022-03-24 02:15:14.217670 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/token/id/hd8f8461e4534812c6d951a00aca52f0865944f8d8f8feed028d5640ae34a92d6, err is auth: revision in header is old
2022-03-24 02:15:14.217684 W | etcdserver: failed to apply request "header:<ID:10203326865992843286 username:\"eric-sec-key-management\" auth_revision:15 > delete_range:<key:\"/shelter/sys/token/id/hd8f8461e4534812c6d951a00aca52f0865944f8d8f8feed028d5640ae34a92d6\" > " with response "" took (4.133µs) to execute, err is auth: revision in header is old

[ahrtr]

@rahulbapumore Can you please format the pasted log using code? It's hard to read without proper formatting. Please read quoting-code

[serathius]

done :P

[ahrtr]

Thanks @serathius .

It seems that the etcd is too fragile once auth is enabled. Just raised another issue 13937

[rahulbapumore]

Hi @ahrtr ,
Do you mean to say that you are also able to reproduce data inconsistency issue?
We are actually facing data inconsistency issue and getting error logs as shared in my previous comment.
Could you confirm that you are also getting data inconsistency issue or not?

Thanks,
Rahul

[ahrtr]

This issue 13937 is only specific to 3.5 and main.

I can not reproduce the issue you pointed out in previous comment so far. It would be helpful if you can reproduce the issue (auth: revision in header is old) in a fresh etcd cluster (without your microservice).

[rahulbapumore]

Hi @ahrtr ,
Is there any way to avoid this issue that we are facing in 3.4.16?
Could you please suggest some work around to avoid this issue?

Thanks

[rahulbapumore]

Hi @ahrtr ,
One more question -
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://eric-data-distributed-coordinator-ed-2.eric-data-distributed-coordinator-ed-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 eric-sec-key-management 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)

In the above log lines , see bolded auth_revision count, from above lines we can say that 3 lines shows auth_revision=11
and immediate next line shows auth_revision=12 even though first 3 request failed to apply still auth_revision increased by 1.
How is that possible?
could you confirm this behavior expected?

Thanks

[rahulbapumore]

Hi @ahrtr ,
We have observed one thing in our 2 deployments, some of the error messages were same in pod2
ms-data-distributed-coordinator-ed-2_dced.txt
ms-data-distributed-coordinator-ed-2_dced.txt
I have attached pod2 logs for 2 different deployment, and if you could see line number 159 in both the files, from line number 159 similar messages are printed in both different deployment.
Could you confirm whether whats happening around that code , and its related to auth_revision only?
Could you please help in debugging the issue?

Thanks

[rahulbapumore]

Hi @ahrtr

[ahrtr]

Just raised a new issue to follow up 13976.