*: optimize auth/etcdserver logs to facilitate troubleshooting data inconsistency #11670

tangcong · 2020-03-03T09:59:06Z

There are three minor changes：

add warning log for troubleshooting when auth revision is inconsistent(current,no log is printed when node failed to apply command because of inconsistent auth revision).
for example.
17:04:56 etcd1 | {"level":"warn","ts":"2020-03-03T17:04:56.173+0800","caller":"auth/store.go:856","msg":"request auth revision is less than current node auth revision","auth store revision":23,"request auth revision":19,"request key":"hello","error":"auth: revision in header is old"}
no need to save consistentIndex in NewAuthStore(no command is executed) and it will cause the error log to be printed when starting an empty etcd cluster.
print warning log when failed to apply request.

auth/store.go

codecov-io · 2020-03-03T11:09:12Z

Codecov Report

Merging #11670 into master will decrease coverage by 0.81%.
The diff coverage is 71.42%.

@@            Coverage Diff             @@
##           master   #11670      +/-   ##
==========================================
- Coverage   66.65%   65.83%   -0.82%     
==========================================
  Files         402      402              
  Lines       36655    36673      +18     
==========================================
- Hits        24432    24145     -287     
- Misses      10734    11020     +286     
- Partials     1489     1508      +19

Impacted Files	Coverage Δ
etcdserver/util.go	`98.8% <100%> (+0.19%)`	⬆️
etcdserver/apply.go	`79.33% <100%> (+0.03%)`	⬆️
auth/store.go	`59.41% <14.28%> (-20.37%)`	⬇️
clientv3/txn.go	`77.77% <0%> (-22.23%)`	⬇️
client/members.go	`65.32% <0%> (-20.17%)`	⬇️
etcdserver/api/v3rpc/util.go	`51.61% <0%> (-16.13%)`	⬇️
client/client.go	`50% <0%> (-15.04%)`	⬇️
auth/jwt.go	`69.66% <0%> (-7.87%)`	⬇️
pkg/tlsutil/tlsutil.go	`86.2% <0%> (-6.9%)`	⬇️
... and 25 more

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update cb63341...526add1. Read the comment docs.

mitake

The content LGTM. The commit logs should be auth: .... etcd's commit log format is <package name>: <a short description of the commit>.

tangcong · 2020-03-10T03:51:45Z

we encounter another serious data inconsistency issue and can make sure that it has nothing to do with auth revision. we are striving to reproduce it but there is no valid information in etcd log, so it is better to print warning log when failed to apply request. i have added it in this pr.
@jingyih @mitake PTAL. thanks.

jingyih · 2020-03-10T14:29:21Z

etcdserver/apply.go

@@ -132,6 +132,9 @@ func (a *applierV3backend) Apply(r *pb.InternalRaftRequest) *applyResult {
 	ar := &applyResult{}
 	defer func(start time.Time) {
 		warnOfExpensiveRequest(a.s.getLogger(), start, &pb.InternalRaftStringer{Request: r}, ar.resp, ar.err)
+		if ar.err != nil {


Wondering how much does this affect server throughput. Maybe use debug level to print?

The logging overhead will be introduced only for failed requests, so I feel adding the warning log would help troubleshooting.

yes ,i agree with @mitake. if there are too much failed log,something may be wrong with the cluster and users can also adjust the log leve to error. @jingyih

jingyih · 2020-03-10T14:30:40Z

we encounter another serious data inconsistency issue and can make sure that it has nothing to do with auth revision. we are striving to reproduce it but there is no valid information in etcd log, so it is better to print warning log when failed to apply request. i have added it in this pr.
@jingyih @mitake PTAL. thanks.

FYI, there is a known data inconsistency bug which is fixed by #11613.

auth/store.go

tangcong · 2020-03-10T15:21:49Z

we encounter another serious data inconsistency issue and can make sure that it has nothing to do with auth revision. we are striving to reproduce it but there is no valid information in etcd log, so it is better to print warning log when failed to apply request. i have added it in this pr.
@jingyih @mitake PTAL. thanks.

FYI, there is a known data inconsistency bug which is fixed by #11613.

We have excluded this bug and have reproduced it, and we are investigating further.

tangcong · 2020-03-11T16:10:32Z

#11689 @jingyih

we encounter another serious data inconsistency issue and can make sure that it has nothing to do with auth revision. we are striving to reproduce it but there is no valid information in etcd log, so it is better to print warning log when failed to apply request. i have added it in this pr.
@jingyih @mitake PTAL. thanks.

FYI, there is a known data inconsistency bug which is fixed by #11613.

mitake

LGTM, defer to @jingyih

jingyih

LGTM

…io#11735

…io#11735,etcd-io#11659

#11670-#11710-origin-release-3.3 Automated cherry pick of #11652 #11670 #11710

#11670-#11710-origin-release-3.4 Automated cherry pick of #11652 #11670 #11710

CHANGELOG: update for #11699,#11670,#11652,#11735,#11659

tangcong force-pushed the optimize-auth-store-log branch from be3177e to d688e97 Compare March 3, 2020 10:17

jingyih reviewed Mar 3, 2020

View reviewed changes

auth/store.go Outdated Show resolved Hide resolved

tangcong force-pushed the optimize-auth-store-log branch from d688e97 to d17dca1 Compare March 3, 2020 11:48

mitake suggested changes Mar 3, 2020

View reviewed changes

auth: print warning log when error is ErrAuthOldRevision

ebe256d

tangcong force-pushed the optimize-auth-store-log branch from d17dca1 to e9d2b42 Compare March 3, 2020 15:22

tangcong closed this Mar 3, 2020

tangcong reopened this Mar 3, 2020

tangcong changed the title ~~auth/store: optimize auth store log~~ auth: optimize auth store log Mar 3, 2020

tangcong mentioned this pull request Mar 9, 2020

Automated cherry pick of #11652 #11670 #11686

Closed

auth: cleanup saveConsistentIndex in NewAuthStore

0d084d3

tangcong force-pushed the optimize-auth-store-log branch from e9d2b42 to 0d084d3 Compare March 10, 2020 02:07

tangcong changed the title ~~auth: optimize auth store log~~ *: optimize auth/etcdserver logs to facilitate troubleshooting data inconsistency problem Mar 10, 2020

tangcong changed the title *: optimize auth/etcdserver logs to facilitate troubleshooting data inconsistency problem *: optimize auth/etcdserver logs to facilitate troubleshooting data inconsistency Mar 10, 2020

jingyih reviewed Mar 10, 2020

View reviewed changes

mitake reviewed Mar 10, 2020

View reviewed changes

auth/store.go Show resolved Hide resolved

tangcong force-pushed the optimize-auth-store-log branch from 526add1 to e811990 Compare March 10, 2020 15:00

etcdserver: print warn log when failed to apply request

5a17367

tangcong force-pushed the optimize-auth-store-log branch from e811990 to 5a17367 Compare March 10, 2020 15:14

mitake approved these changes Mar 15, 2020

View reviewed changes

jingyih reviewed Mar 15, 2020

View reviewed changes

jingyih merged commit 193e60e into etcd-io:master Mar 15, 2020

tangcong mentioned this pull request Apr 5, 2020

Automated cherry pick of #11652 #11670 #11699 #11710 #11748

Closed

tangcong added a commit to tangcong/etcd that referenced this pull request Apr 5, 2020

changelog: update for etcd-io#11699,etcd-io#11670,etcd-io#11652,etcd-…

c28807f

…io#11735

tangcong added a commit to tangcong/etcd that referenced this pull request Apr 5, 2020

changelog: update for etcd-io#11699,etcd-io#11670,etcd-io#11652,etcd-…

0ab10a1

…io#11735

tangcong added a commit to tangcong/etcd that referenced this pull request Apr 5, 2020

CHANGELOG: update for etcd-io#11699,etcd-io#11670,etcd-io#11652,etcd-…

b93ba91

…io#11735

tangcong added a commit to tangcong/etcd that referenced this pull request Apr 5, 2020

CHANGELOG: update for etcd-io#11699,etcd-io#11670,etcd-io#11652,etcd-…

75c3e12

…io#11735,etcd-io#11659

This was referenced Apr 6, 2020

Automated cherry pick of #11652 #11670 #11710 origin release 3.4 #11751

Closed

Automated cherry pick of #11652 #11670 #11710 #11752

Merged

Automated cherry pick of #11652 #11670 #11710 #11753

Merged

tangcong added a commit to tangcong/etcd that referenced this pull request Apr 6, 2020

CHANGELOG: update for etcd-io#11699,etcd-io#11670,etcd-io#11652,etcd-…

b2ebf6e

…io#11735,etcd-io#11659

jingyih added a commit that referenced this pull request Apr 10, 2020

Merge pull request #11753 from tangcong/automated-cherry-pick-of-#11652-

7e20b9f

#11670-#11710-origin-release-3.3 Automated cherry pick of #11652 #11670 #11710

jingyih added a commit that referenced this pull request Apr 10, 2020

Merge pull request #11752 from tangcong/automated-cherry-pick-of-#11652-

f1eca4e

#11670-#11710-origin-release-3.4 Automated cherry pick of #11652 #11670 #11710

jingyih added a commit that referenced this pull request Apr 10, 2020

Merge pull request #11750 from tangcong/changelog

c8d3e99

CHANGELOG: update for #11699,#11670,#11652,#11735,#11659

This was referenced Jul 21, 2020

Bug 1859196: bump etcd v3.4.9 openshift/etcd#52

Merged

Bug 1859201: bump etcd v3.4.9 openshift/etcd#54

Merged

tangcong deleted the optimize-auth-store-log branch February 26, 2021 18:59

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

*: optimize auth/etcdserver logs to facilitate troubleshooting data inconsistency #11670

*: optimize auth/etcdserver logs to facilitate troubleshooting data inconsistency #11670

tangcong commented Mar 3, 2020 •

edited

Loading

codecov-io commented Mar 3, 2020 •

edited

Loading

mitake left a comment

tangcong commented Mar 10, 2020 •

edited

Loading

jingyih Mar 10, 2020

mitake Mar 10, 2020

tangcong Mar 10, 2020 •

edited

Loading

jingyih commented Mar 10, 2020

tangcong commented Mar 10, 2020 •

edited

Loading

tangcong commented Mar 11, 2020 •

edited

Loading

mitake left a comment

jingyih left a comment

*: optimize auth/etcdserver logs to facilitate troubleshooting data inconsistency #11670

*: optimize auth/etcdserver logs to facilitate troubleshooting data inconsistency #11670

Conversation

tangcong commented Mar 3, 2020 • edited Loading

codecov-io commented Mar 3, 2020 • edited Loading

Codecov Report

mitake left a comment

Choose a reason for hiding this comment

tangcong commented Mar 10, 2020 • edited Loading

jingyih Mar 10, 2020

Choose a reason for hiding this comment

mitake Mar 10, 2020

Choose a reason for hiding this comment

tangcong Mar 10, 2020 • edited Loading

Choose a reason for hiding this comment

jingyih commented Mar 10, 2020

tangcong commented Mar 10, 2020 • edited Loading

tangcong commented Mar 11, 2020 • edited Loading

mitake left a comment

Choose a reason for hiding this comment

jingyih left a comment

Choose a reason for hiding this comment

tangcong commented Mar 3, 2020 •

edited

Loading

codecov-io commented Mar 3, 2020 •

edited

Loading

tangcong commented Mar 10, 2020 •

edited

Loading

tangcong Mar 10, 2020 •

edited

Loading

tangcong commented Mar 10, 2020 •

edited

Loading

tangcong commented Mar 11, 2020 •

edited

Loading