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.

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

mvcc: avoid double decrement of watcher gauge on close/cancel race #19600

Open
wants to merge 1 commit into
base: main
Choose a base branch
from

Conversation

kjgorman
Copy link

This occurs specifically when the watch is for a compacted revision, as there's a possible interleaving of cancel/close that invokes the cancelWatch function twice.

It's fairly difficult to provoke the race condition but it is possible to observe on main the racing test can fail with a negative gauge:

$ go test ./...  -run TestNewWatcherCountGauge/compacted_watch,_close/cancel_race
--- FAIL: TestNewWatcherCountGauge (0.34s)
    watchable_store_test.go:86:  # HELP etcd_debugging_mvcc_watcher_total Total number of watchers.
         # TYPE etcd_debugging_mvcc_watcher_total gauge
        -etcd_debugging_mvcc_watcher_total -1
        +etcd_debugging_mvcc_watcher_total 0

FAIL
FAIL    go.etcd.io/etcd/server/v3/storage/mvcc  0.830s
?       go.etcd.io/etcd/server/v3/storage/mvcc/testutil [no test files]
FAIL

It seems as though it is partially expected for the cancel function to be invoked multiple times and to handle that safely (i.e., the existing ch == nil check) - the bug here is that in the if/else if branches it comes "too late", and multiple invocations where wa.compacted is true will both decrement the counter. Shifting the case up one ensures that we can't follow that decrement branch multiple times.

In fact, it seems logically more sensible to put this wa.ch == nil case first, as a guard for the function being invoked multiple times, but moving i before the sync/unsynced watch set delete functions could have a greater inadvertent functional impact (i.e., if we never deleted cancelled watches from these sets it would presumably introduce a leak), so from an abundance of caution I've made the smallest change I think will fix my issue.

Please read https://github.com/etcd-io/etcd/blob/main/CONTRIBUTING.md#contribution-flow.

@k8s-ci-robot
Copy link

[APPROVALNOTIFIER] This PR is NOT APPROVED

This pull-request has been approved by: kjgorman
Once this PR has been reviewed and has the lgtm label, please assign serathius for approval. For more information see the Code Review Process.

The full list of commands accepted by this bot can be found here.

Needs approval from an approver in each of these files:

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

@k8s-ci-robot
Copy link

Hi @kjgorman. Thanks for your PR.

I'm waiting for a etcd-io member to verify that this patch is reasonable to test. If it is, they should reply with /ok-to-test on its own line. Until that is done, I will not automatically test new commits in this PR, but the usual testing commands by org members will still work. Regular contributors should join the org to skip this step.

Once the patch is verified, the new status will be reflected by the ok-to-test label.

I understand the commands that are listed here.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes-sigs/prow repository.

This occurs specifically when the watch is for a compacted revision, as there's
a possible interleaving of cancel/close that invokes the `cancelWatch` function
twice.

It's fairly difficult to provoke the race condition but it is possible to
observe on `main` the racing test can fail with a negative gauge:

```
$ go test ./...  -run TestNewWatcherCountGauge/compacted_watch,_close/cancel_race
--- FAIL: TestNewWatcherCountGauge (0.34s)
    watchable_store_test.go:86:  # HELP etcd_debugging_mvcc_watcher_total Total number of watchers.
         # TYPE etcd_debugging_mvcc_watcher_total gauge
        -etcd_debugging_mvcc_watcher_total -1
        +etcd_debugging_mvcc_watcher_total 0

FAIL
FAIL    go.etcd.io/etcd/server/v3/storage/mvcc  0.830s
?       go.etcd.io/etcd/server/v3/storage/mvcc/testutil [no test files]
FAIL
```

It seems as though it is partially expected for the cancel function to be
invoked multiple times and to handle that safely (i.e., the existing `ch == nil`
check) - the bug here is that in the `if/else if` branches it comes "too late",
and multiple invocations where `wa.compacted` is true will both decrement the
counter. Shifting the case up one ensures that we can't follow that decrement
branch multiple times.

In fact, it seems logically more sensible to put this `wa.ch == nil` case
_first_, as a guard for the function being invoked multiple times, but moving i
before the sync/unsynced watch set delete functions could have a greater
inadvertent functional impact (i.e., if we never deleted cancelled watches from
these sets it would presumably introduce a leak), so from an abundance of
caution I've made the smallest change I think will fix my issue.

Signed-off-by: Kieran Gorman <[email protected]>
@kjgorman kjgorman force-pushed the mvcc-double-decrement-watcher-gauge branch from 41c0e72 to 395a038 Compare March 14, 2025 10:01
@kjgorman kjgorman marked this pull request as ready for review March 14, 2025 10:29
@ivanvc
Copy link
Member

ivanvc commented Mar 14, 2025

I verified your test case against the main branch, with stress (refer to our deflaking documentation). And I confirm that it does have an issue, without the change:

15m0s: 33798 runs so far, 84 failures (0.25%), 8 active

With the change:

30m0s: 67547 runs so far, 0 failures, 8 active

/ok-to-test

Copy link

codecov bot commented Mar 14, 2025

Codecov Report

All modified and coverable lines are covered by tests ✅

Project coverage is 68.79%. Comparing base (a5bef1b) to head (395a038).
Report is 16 commits behind head on main.

Additional details and impacted files
Files with missing lines Coverage Δ
server/storage/mvcc/watchable_store.go 93.89% <100.00%> (ø)

... and 20 files with indirect coverage changes

@@            Coverage Diff             @@
##             main   #19600      +/-   ##
==========================================
- Coverage   68.85%   68.79%   -0.07%     
==========================================
  Files         421      421              
  Lines       35897    35897              
==========================================
- Hits        24717    24694      -23     
- Misses       9753     9778      +25     
+ Partials     1427     1425       -2     

Continue to review full report in Codecov by Sentry.

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

🚀 New features to boost your workflow:
  • Test Analytics: Detect flaky tests, report on failures, and find test suite problems.

Copy link
Member

@ivanvc ivanvc left a comment

Choose a reason for hiding this comment

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

This solution looks good to me, but it's not my area of expertise.

/cc @fuweid @ahrtr @serathius

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Development

Successfully merging this pull request may close these issues.

3 participants