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

kvserver: lease expiration warnings are either wrong or overly eager #97209

Closed
erikgrinaker opened this issue Feb 15, 2023 · 3 comments · Fixed by #105519
Closed

kvserver: lease expiration warnings are either wrong or overly eager #97209

erikgrinaker opened this issue Feb 15, 2023 · 3 comments · Fixed by #105519
Assignees
@erikgrinaker
Labels
A-kv-replication Relating to Raft, consensus, and coordination. C-bug Code not up to spec/doc, specs & docs deemed correct. Solution expected to change code/behavior.

Comments

@erikgrinaker
Copy link
Contributor

erikgrinaker commented Feb 15, 2023 •
edited by cockroach-jira-scripts
Loading

Over in #97141, we're seeing lots of messages like these about a minute apart, for a bunch of different ranges:

W230215 15:05:25.397825 438 kv/kvserver/replica_proposal.go:504 ⋮ [T1,n1,s1,r208/1:‹/Table/114/1/7{16/1/…-28/3/…}›,raft] 1186  lease repl=(n1,s1):1 seq=8 start=1676473525.388300956,0 exp=1676473531.388236519,0 pro=1676473525.388236519,0 expired before being followed by lease repl=(n1,s1):1 seq=9 start=1676473525.388300956,0 epo=1 pro=1676473525.389899605,0; foreground traffic may have been impacted
W230215 15:05:25.399483 389 kv/kvserver/replica_proposal.go:504 ⋮ [T1,n1,s1,r202/1:‹/Table/114/1/7{04/2/…-16/1/…}›,raft] 1187  lease repl=(n1,s1):1 seq=8 start=1676473525.392789979,0 exp=1676473531.392713495,0 pro=1676473525.392713495,0 expired before being followed by lease repl=(n1,s1):1 seq=9 start=1676473525.392789979,0 epo=1 pro=1676473525.395106219,0; foreground traffic may have been impacted
W230215 15:05:25.401462 393 kv/kvserver/replica_proposal.go:504 ⋮ [T1,n1,s1,r316/1:‹/Table/114/1/8{35/10…-47/9/…}›,raft] 1188  lease repl=(n1,s1):1 seq=8 start=1676473525.394871000,0 exp=1676473531.394811451,0 pro=1676473525.394811451,0 expired before being followed by lease repl=(n1,s1):1 seq=9 start=1676473525.394871000,0 epo=1 pro=1676473525.397471476,0; foreground traffic may have been impacted
W230215 15:05:25.402589 465 kv/kvserver/replica_proposal.go:504 ⋮ [T1,n1,s1,r295/1:‹/Table/114/1/{41/3/-…-53/7/-…}›,raft] 1189  lease repl=(n1,s1):1 seq=8 start=1676473525.397320365,0 exp=1676473531.397258820,0 pro=1676473525.397258820,0 expired before being followed by lease repl=(n1,s1):1 seq=9 start=1676473525.397320365,0 epo=1 pro=1676473525.398718792,0; foreground traffic may have been impacted
W230215 15:05:25.403898 394 kv/kvserver/replica_proposal.go:504 ⋮ [T1,n1,s1,r157/1:‹/Table/114/1/{28/8/-…-41/3/-…}›,raft] 1190  lease repl=(n1,s1):1 seq=8 start=1676473525.398777759,0 exp=1676473531.398716723,0 pro=1676473525.398716723,0 expired before being followed by lease repl=(n1,s1):1 seq=9 start=1676473525.398777759,0 epo=1 pro=1676473525.400299666,0; foreground traffic may have been impacted
W230215 15:05:25.405819 414 kv/kvserver/replica_proposal.go:504 ⋮ [T1,n1,s1,r311/1:‹/Table/114/1/4{74/4/…-86/3/…}›,raft] 1191  lease repl=(n1,s1):1 seq=12 start=1676473525.400304925,0 exp=1676473531.400169005,0 pro=1676473525.400169005,0 expired before being followed by lease repl=(n1,s1):1 seq=13 start=1676473525.400304925,0 epo=1 pro=1676473525.402156568,0; foreground traffic may have been impacted

Notice how the lease was in fact taken over by the same leaseholder. I think something's off with the condition for that log message. It was added back in #96257. We should get this fixed asap, since it was backported to 22.2 and 22.1.

Entire log: cockroach.log

Jira issue: CRDB-24572
@erikgrinaker erikgrinaker added C-bug Code not up to spec/doc, specs & docs deemed correct. Solution expected to change code/behavior. A-kv-replication Relating to Raft, consensus, and coordination. T-kv-replication labels Feb 15, 2023
@blathers-crl
Copy link

blathers-crl bot commented Feb 15, 2023

cc @cockroachdb/replication

@erikgrinaker
Copy link
Contributor Author

Also seeing this on a fresh roachprod cluster:

lease <empty> expired before being followed by lease repl=(n1,s1):1 seq=1 start=0,0 epo=1 pro=1676721595.187206664,0; foreground traffic may have been impacted

@tbg tbg mentioned this issue Feb 20, 2023
Merged
craig bot pushed a commit that referenced this issue Feb 20, 2023
@tbg
Merge #97358
8124f66 
97358: kvserver: disable overeager slow lease warning r=erikgrinaker a=tbg

Touches #97209.

Epic: none
Release note (bug fix): the following spammy log message was removed:
> lease [...] expired before being followed by lease [...]; foreground traffic may have been impacted


Co-authored-by: Tobias Grieger <[email protected]>
This was referenced Feb 21, 2023
Merged
Merged
@erikgrinaker
Copy link
Contributor Author

I can pick this up, since I'm working in this area anyway.

@erikgrinaker erikgrinaker mentioned this issue Jun 25, 2023
Merged
@craig craig bot closed this as completed in 987249b Jun 26, 2023
@blathers-crl blathers-crl bot mentioned this issue Jun 26, 2023
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@erikgrinaker erikgrinaker

Labels
A-kv-replication Relating to Raft, consensus, and coordination. C-bug Code not up to spec/doc, specs & docs deemed correct. Solution expected to change code/behavior.
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

kvserver: fix and re-enable slow lease application logging erikgrinaker/cockroach
2 participants
@erikgrinaker @tbg