Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Merged
merged 3 commits into from
Mar 15, 2020
Merged

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

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
ebe256d
auth: print warning log when error is ErrAuthOldRevision
tangcong Mar 3, 2020
0d084d3
auth: cleanup saveConsistentIndex in NewAuthStore
tangcong Mar 3, 2020
5a17367
etcdserver: print warn log when failed to apply request
tangcong Mar 10, 2020
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
10 changes: 7 additions & 3 deletions auth/store.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -851,8 +851,13 @@ func (as *authStore) isOpPermitted(userName string, revision uint64, key, rangeE
if revision == 0 {
return ErrUserEmpty
}

if revision < as.Revision() {
rev := as.Revision()
if revision < rev {
as.lg.Warn("request auth revision is less than current node auth revision",
zap.Uint64("current node auth revision", rev),
zap.Uint64("request auth revision", revision),
zap.ByteString("request key", key),
zap.Error(ErrAuthOldRevision))
return ErrAuthOldRevision
}

Expand Down Expand Up @@ -1065,7 +1070,6 @@ func NewAuthStore(lg *zap.Logger, be backend.Backend, tp TokenProvider, bcryptCo

if as.Revision() == 0 {
as.commitRevision(tx)
as.saveConsistentIndex(tx)
mitake marked this conversation as resolved.
Show resolved Hide resolved
}

as.setupMetricsReporter()
Expand Down
3 changes: 3 additions & 0 deletions etcdserver/apply.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Contributor Author

@tangcong tangcong Mar 10, 2020 •
edited

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

warnOfFailedRequest(a.s.getLogger(), start, &pb.InternalRaftStringer{Request: r}, ar.resp, ar.err)
}
}(time.Now())

// call into a.s.applyV3.F instead of a.F so upper appliers can check individual calls
Expand Down
15 changes: 15 additions & 0 deletions etcdserver/util.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -111,6 +111,21 @@ func warnOfExpensiveRequest(lg *zap.Logger, now time.Time, reqStringer fmt.Strin
warnOfExpensiveGenericRequest(lg, now, reqStringer, "", resp, err)
}

func warnOfFailedRequest(lg *zap.Logger, now time.Time, reqStringer fmt.Stringer, respMsg proto.Message, err error) {
var resp string
if !isNil(respMsg) {
resp = fmt.Sprintf("size:%d", proto.Size(respMsg))
}
d := time.Since(now)
lg.Warn(
"failed to apply request",
zap.Duration("took", d),
zap.String("request", reqStringer.String()),
zap.String("response", resp),
zap.Error(err),
)
}

func warnOfExpensiveReadOnlyTxnRequest(lg *zap.Logger, now time.Time, r *pb.TxnRequest, txnResponse *pb.TxnResponse, err error) {
reqStringer := pb.NewLoggableTxnRequest(r)
var resp string
Expand Down