cls/rgw: rgw_dir_suggest_changes detects race with completion by cbodley · Pull Request #45345 · ceph/ceph

cbodley · 2022-03-10T20:56:36Z

if bucket listing races with a pending index transaction, its suggested removal may be mistakenly applied if that index transaction completes before the osd receives this suggestion

in rgw_dir_suggest_changes(), the sole condition for applying a suggested change is that the cur_disk.pending_map is empty. this is true after rgw_bucket_complete_op()

on index completion, rgw_bucket_dir_entry::index_ver is updated to match the new value of rgw_bucket_dir_header::ver. because most of struct rgw_bucket_dir_entry makes the round trip through bucket listing -> dir_suggest, we have access to the index_ver of the suggested entry. by comparing this against the stored entry, we can ignore any suggestions that were sent before the most recent completion

Fixes: https://tracker.ceph.com/issues/54528

Show available Jenkins commands

jenkins retest this please
jenkins test classic perf
jenkins test crimson perf
jenkins test signed
jenkins test make check
jenkins test make check arm64
jenkins test submodules
jenkins test dashboard
jenkins test dashboard cephadm
jenkins test api
jenkins test docs
jenkins render docs
jenkins test ceph-volume all
jenkins test ceph-volume tox
jenkins test windows

mattbenjamin

mirabile dictu

mattbenjamin · 2022-03-10T21:01:17Z

src/cls/rgw/cls_rgw.cc

    }

-    CLS_LOG(20, "cur_disk.pending_map.empty()=%d op=%d cur_disk.exists=%d cur_change.pending_map.size()=%d cur_change.exists=%d",
+    CLS_LOG(20, "cur_disk.pending_map.empty()=%d op=%d cur_disk.exists=%d "


it's amazing this step was missed before (or maybe got removed?); it seems clearly part of the design

I think the dir_suggest code path might not have been tested much

I'm guessing this will merge before my instrumentation PR, which it should. Then I can convert this to the instrumented version.

mattbenjamin · 2022-03-10T21:01:27Z

src/cls/rgw/cls_rgw.cc

+            (int)cur_disk.index_ver, cur_change.exists,
+            (int)cur_change.index_ver);
+
+    if (cur_change.index_ver < cur_disk.index_ver) {


cbodley · 2022-03-10T21:54:25Z

added a simple test case that passes with this fix:

[ RUN      ] cls_rgw.index_suggest_complete
[       OK ] cls_rgw.index_suggest_complete (6 ms)

..and fails against master:

[ RUN      ] cls_rgw.index_suggest_complete
/home/cbodley/ceph/src/test/cls_rgw/test_cls_rgw.cc:430: Failure
Expected equality of these values:
  1
  entries.size()
    Which is: 0
[  FAILED  ] cls_rgw.index_suggest_complete (7 ms)

if bucket listing races with a pending index transaction, its suggested removal may be mistakenly applied if that index transaction completes before the osd receives this suggestion in `rgw_dir_suggest_changes()`, the sole condition for applying a suggested change is that the `cur_disk.pending_map` is empty. this is true after rgw_bucket_complete_op() on index completion, `rgw_bucket_dir_entry::index_ver` is updated to match the new value of `rgw_bucket_dir_header::ver`. because most of `struct rgw_bucket_dir_entry` makes the round trip through bucket listing -> dir_suggest, we have access to the index_ver of the suggested entry. by comparing this against the stored entry, we can ignore any suggestions that were sent before the most recent completion Fixes: https://tracker.ceph.com/issues/54528 Signed-off-by: Casey Bodley <cbodley@redhat.com>

Signed-off-by: Casey Bodley <cbodley@redhat.com>

yehudasa · 2022-03-10T22:09:17Z

@cbodley the fact that we get dir_suggest happening on listing before completion is called and is effective makes me think we have an issue with the time delta calculation, as it really should only happen after a very long period of time (hours). I remember seeing such a bug relatively recently.

mattbenjamin · 2022-03-10T22:15:44Z

@cbodley the fact that we get dir_suggest happening on listing before completion is called and is effective makes me think we have an issue with the time delta calculation, as it really should only happen after a very long period of time (hours). I remember seeing such a bug relatively recently.

The hard-coded timeout has been 120s, and we just made it configurable. I assumed it would be some value in hours, as well. But also, that's the "tag timeout" and from what I understand, this path isn't even covered by it?

cbodley · 2022-03-10T22:19:46Z

@cbodley the fact that we get dir_suggest happening on listing before completion is called and is effective makes me think we have an issue with the time delta calculation, as it really should only happen after a very long period of time (hours).

are you talking about timing with respect to the tag timeout? we were also expecting that to prevent these racing suggestions from being applied to the index

but the tag timeout only applies to pending transactions in pending_map - in this case, we get the call to rgw_bucket_complete_op() first, which clears its pending entry. and once pending_map is empty, rgw_dir_suggest_changes() will apply any changes it gets

yehudasa · 2022-03-10T22:25:39Z

@cbodley the fact that we get dir_suggest happening on listing before completion is called and is effective makes me think we have an issue with the time delta calculation, as it really should only happen after a very long period of time (hours).

are you talking about timing with respect to the tag timeout? we were also expecting that to prevent these racing suggestions from being applied to the index

but the tag timeout only applies to pending transactions in pending_map - in this case, we get the call to rgw_bucket_complete_op() first, which clears its pending entry. and once pending_map is empty, rgw_dir_suggest_changes() will apply any changes it gets

Ah, I see. Yeah, makes sense.

And apparently I changed the tag timeout to 120 seconds from 24 hours here: 99efdc6.

cbodley · 2022-03-10T22:32:20Z

And apparently I changed the tag timeout to 120 seconds from 24 hours here: 99efdc6.

oh cool. there were some conversations recently about raising that default, but it's good to see your explanation for why it should stay relatively small - at least in multisite

mattbenjamin · 2022-03-10T23:21:54Z

And apparently I changed the tag timeout to 120 seconds from 24 hours here: 99efdc6.

oh cool. there were some conversations recently about raising that default, but it's good to see your explanation for why it should stay relatively small - at least in multisite

I don't feel convinced. 120s is just 2 * the most common client timeout for S3 requests. It seems completely unreasonable to have a timeout based mechanism that changes the apparent result of operations acked to clients on the basis of such a timeout.

mkogan1

ACK, tested on the reproducer environment and the BZ no longer reproduces
(rhbz2042585 -- Client uploaded S3 object not listed but can be downloaded)

mkogan1 · 2022-03-13T11:05:05Z

jenkins test make check

cbodley · 2022-03-17T21:12:48Z

passed qa in https://pulpito.ceph.com/cbodley-2022-03-17_18:05:42-rgw-wip-cbodley-testing-distro-default-smithi/

cbodley added bug-fix rgw needs-test labels Mar 10, 2022

cbodley requested review from ivancich, mattbenjamin, mkogan1 and yehudasa March 10, 2022 20:56

mattbenjamin approved these changes Mar 10, 2022

View reviewed changes

github-actions bot added the tests label Mar 10, 2022

cbodley removed the needs-test label Mar 10, 2022

cbodley added 2 commits March 10, 2022 17:04

test/cls/rgw: test dir_suggest after successful completion

a350888

Signed-off-by: Casey Bodley <cbodley@redhat.com>

cbodley force-pushed the wip-cls-rgw-suggest-version branch from e756e91 to a350888 Compare March 10, 2022 22:04

mkogan1 approved these changes Mar 11, 2022

View reviewed changes

cbodley added the needs-qa label Mar 14, 2022

mkogan1 mentioned this pull request Mar 16, 2022

rgw: fix PUT on versioned bucket fails with NoSuchKey #38705

Closed

3 tasks

ivancich approved these changes Mar 16, 2022

View reviewed changes

cbodley added the wip-cbodley-testing label Mar 17, 2022

cbodley merged commit 26cc3fd into ceph:master Mar 18, 2022

cbodley mentioned this pull request Mar 18, 2022

rgw: fix list op raced with put op maybe cause index delete (copy + fix) #41978

Closed

ivancich mentioned this pull request Apr 13, 2022

pacific: cls/rgw: rgw_dir_suggest_changes detects race with completion #45900

Merged

This was referenced Apr 13, 2022

quincy: cls/rgw: rgw_dir_suggest_changes detects race with completion #45901

Merged

octopus: cls/rgw: rgw_dir_suggest_changes detects race with completion #45902

Merged

Dreamyu20xx mentioned this pull request Jun 29, 2022

rgw: add 'rgw_suggested_removal_wait_time' option when deleting object key. #41435

Closed

3 tasks

Conversation

cbodley commented Mar 10, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

mattbenjamin left a comment

Choose a reason for hiding this comment

Uh oh!

mattbenjamin Mar 10, 2022

Choose a reason for hiding this comment

Uh oh!

yehudasa Mar 10, 2022

Choose a reason for hiding this comment

Uh oh!

ivancich Mar 16, 2022

Choose a reason for hiding this comment

Uh oh!

mattbenjamin Mar 10, 2022

Choose a reason for hiding this comment

Uh oh!

cbodley commented Mar 10, 2022

Uh oh!

yehudasa commented Mar 10, 2022

Uh oh!

mattbenjamin commented Mar 10, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

cbodley commented Mar 10, 2022

Uh oh!

yehudasa commented Mar 10, 2022

Uh oh!

cbodley commented Mar 10, 2022

Uh oh!

mattbenjamin commented Mar 10, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

mkogan1 left a comment

Choose a reason for hiding this comment

Uh oh!

mkogan1 commented Mar 13, 2022

Uh oh!

cbodley commented Mar 17, 2022

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

5 participants

cbodley commented Mar 10, 2022 •

edited

Loading

mattbenjamin commented Mar 10, 2022 •

edited

Loading

mattbenjamin commented Mar 10, 2022 •

edited

Loading