Add more logging for gossiper::lock_endpoint and storage_service::handle_state_normal
#16733
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
In a longevity test reported in scylladb#16668 we observed that NORMAL state is not being properly handled for a node that replaced another node. Either handle_state_normal is not being called, or it is but getting stuck in the middle. Which is the case couldn't be determined from the logs, and attempts at creating a local reproducer failed. Improve the INFO level logging in handle_state_normal to aid debugging in the future. The amount of logs is still constant per-node. Even though some log messages report all tokens owned by a node, handle_state_normal calls are still rare. The most "spammy" situation is when a node starts and calls handle_state_normal for every other node in the cluster, but it is a once-per-startup event.
The original code extracted only the function_name from the source_location for logging. We'll use more information from the source_location in later commits.
2 tasks
🟢 CI State: SUCCESS✅ - Build Build Details:
|
bhalevy
reviewed
Jan 11, 2024
bhalevy
reviewed
Jan 11, 2024
bhalevy
reviewed
Jan 11, 2024
In a longevity test reported in scylladb#16668 we observed that NORMAL state is not being properly handled for a node that replaced another node. Either handle_state_normal is not being called, or it is but getting stuck in the middle. Which is the case couldn't be determined from the logs, and attempts at creating a local reproducer failed. One hypothesis is that `gossiper` is stuck on `lock_endpoint`. We dealt with gossiper deadlocks in the past (e.g. scylladb#7127). Modify the code so it reports an error if `lock_endpoint` waits for the lock for more than a minute. When the issue reproduces again in longevity, we will see if `lock_endpoint` got stuck.
kbr-scylla
force-pushed
the
improve-gossiper-logging
branch
from
a8fd5d0
to
cf64602
Compare
|
v2: reverse conditions in |
bhalevy
approved these changes
Jan 11, 2024
🟢 CI State: SUCCESS✅ - Build Build Details:
|
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
In a longevity test reported in #16668 we observed that
NORMAL state is not being properly handled for a node that replaced
another node. Either handle_state_normal is not being called, or it is
but getting stuck in the middle. Which is the case couldn't be
determined from the logs, and attempts at creating a local reproducer
failed.
Thus the plan is to continue debugging using the longevity test, but we need
more logs. To check whether
handle_state_normalwas called and which brancheswere taken, include some INFO level logs there. Also, detect deadlocks inside
gossiper::lock_endpointby reporting an error message iflock_endpointwaits for the lock for too long.
Ref: #16668