Project

General

Profile

Bug #55485

[rbd-mirror] image force promote operation doesn't complete

Added by Christopher Hoffman almost 2 years ago. Updated 8 months ago.

Status:
In Progress
Priority:
Normal
Target version:
-
% Done:

0%

Source:
Tags:
Backport:
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Pull request ID:
Crash signature (v1):
Crash signature (v2):

Description

Force promote fails to complete and indefinitely loops with scheduler ticks/timeout occurring.

Steps to reproduce:

./bin/ceph --cluster site-a osd unset noup --debug-ms 0 --debug-rbd 0
./bin/ceph --cluster site-a osd in 0 --debug-ms 0 --debug-rbd 0
./bin/rbd --cluster site-a mirror image disable pool1/test-demote-sb --force --debug-ms 0 --debug-rbd 0
./bin/rbd --cluster site-a rm pool1/test-demote-sb --debug-ms 0 --debug-rbd 0
./bin/rbd --cluster site-b mirror image promote pool1/test-demote-sb --force --debug-ms 0 --debug-rbd 0
./bin/rbd --cluster site-a mirror image disable pool1/test-demote-sb --force --debug-ms 0 --debug-rbd 0
./bin/rbd --cluster site-b rm pool1/test-demote-sb --debug-ms 0 --debug-rbd 0
./bin/rbd --cluster site-a create pool1/test-demote-sb --size 100G --image-feature layering --image-feature exclusive-lock --image-feature object-map --image-feature fast-diff --debug-ms 0 --debug-rbd 0
./bin/rbd --cluster site-a mirror image enable pool1/test-demote-sb snapshot --debug-ms 0 --debug-rbd 0
./bin/rbd --cluster site-a mirror snapshot schedule add --pool pool1 --image test-demote-sb 1m --debug-ms 0 --debug-rbd 0
./bin/rbd --cluster site-a bench --io-type write --io-size 64K --io-threads 2 --io-total 3G --io-pattern seq pool1/test-demote-sb --debug-ms 0 --debug-rbd 0
sleep 75s
./bin/ceph --cluster site-a osd set noup --debug-ms 0 --debug-rbd 0
./bin/ceph --cluster site-a osd down 0 --debug-ms 0 --debug-rbd 0
./bin/ceph --cluster site-a osd out 0 --debug-ms 0 --debug-rbd 0
./bin/rbd --cluster site-b  mirror image promote pool1/test-demote-sb --force --debug-ms 1

The logs for a failed occurrence that keeps repeating:

022-04-19T14:57:12.024+0000 7f87f3fff700 15 librbd::mirror::snapshot::PromoteRequest: 0x7f87e4016ce0 unregister_update_watcher: ^M
2022-04-19T14:57:12.024+0000 7f87f3fff700 20 librbd::ImageState: 0x557e4dd13430 unregister_update_watcher: handle=0^M
2022-04-19T14:57:12.024+0000 7f87f3fff700 20 librbd::ImageState: 0x557e4db841a0 ImageUpdateWatchers::unregister_watcher: handle=0^M
2022-04-19T14:57:12.024+0000 7f87f3fff700 20 librbd::ImageState: 0x557e4db841a0 ImageUpdateWatchers::unregister_watcher: completing unregister^M
2022-04-19T14:57:12.024+0000 7f87f3fff700 15 librbd::mirror::snapshot::PromoteRequest: 0x7f87e4016ce0 handle_unregister_update_watcher: r=0^M
2022-04-19T14:57:12.024+0000 7f87f3fff700 15 librbd::mirror::snapshot::PromoteRequest: 0x7f87e4016ce0 list_watchers: ^M
2022-04-19T14:57:12.024+0000 7f87f3fff700 20 librbd::image::ListWatchersRequest: 0x7f87f8034000 send: ^M
2022-04-19T14:57:12.024+0000 7f87f3fff700 20 librbd::image::ListWatchersRequest: 0x7f87f8034000 list_image_watchers: ^M
2022-04-19T14:57:12.024+0000 7f87f3fff700  1 -- 172.17.0.4:0/2834779798 --> [v2:192.168.122.61:6800/1040034008,v1:192.168.122.61:6801/1040034008] -- osd_op(unknown.0.0:36 2.14 2:2b6ef884:::rbd_header.111787236b0f:head [list-watchers] snapc 0=[] ondisk+read+known_if_redirected e26945) v8 -- 0x7f87e40153c0 con 0x557e4dd18130^M
2022-04-19T14:57:12.027+0000 7f8802e2e700  1 -- 172.17.0.4:0/2834779798 <== osd.0 v2:192.168.122.61:6800/1040034008 45 ==== osd_op_reply(36 rbd_header.111787236b0f [list-watchers out=134b] v0'0 uv4864 ondisk = 0) v8 ==== 167+0+134 (crc 0 0 0) 0x7f87f801f040 con 0x557e4dd18130^M
2022-04-19T14:57:12.027+0000 7f8800e2a700 20 librbd::image::ListWatchersRequest: 0x7f87f8034000 handle_list_image_watchers: r=0^M
2022-04-19T14:57:12.027+0000 7f8800e2a700 20 librbd::image::ListWatchersRequest: 0x7f87f8034000 handle_list_image_watchers: object_watchers={addr=192.168.122.61:0/623435185, watcher_id=4375, cookie=94785482893568},{addr=172.17.0.4:0/2834779798, watcher_id=169021, cookie=140221622612720}^M
2022-04-19T14:57:12.027+0000 7f8800e2a700 20 librbd::image::ListWatchersRequest: 0x7f87f8034000 list_mirror_watchers: ^M
2022-04-19T14:57:12.027+0000 7f8800e2a700  1 -- 172.17.0.4:0/2834779798 --> [v2:192.168.122.61:6800/1040034008,v1:192.168.122.61:6801/1040034008] -- osd_op(unknown.0.0:37 2.6 2:67cae2ed:::rbd_mirroring:head [list-watchers] snapc 0=[] ondisk+read+known_if_redirected e26945) v8 -- 0x7f87e8009740 con 0x557e4dd18130^M
2022-04-19T14:57:12.028+0000 7f8802e2e700  1 -- 172.17.0.4:0/2834779798 <== osd.0 v2:192.168.122.61:6800/1040034008 46 ==== osd_op_reply(37 rbd_mirroring [list-watchers out=320b] v0'0 uv58821 ondisk = 0) v8 ==== 157+0+320 (crc 0 0 0) 0x7f87f801f040 con 0x557e4dd18130^M
2022-04-19T14:57:12.028+0000 7f87f3fff700 20 librbd::image::ListWatchersRequest: 0x7f87f8034000 handle_list_mirror_watchers: r=0^M
2022-04-19T14:57:12.028+0000 7f87f3fff700 20 librbd::image::ListWatchersRequest: 0x7f87f8034000 handle_list_mirror_watchers: mirror_watchers={addr=192.168.122.61:0/2817384518, watcher_id=4214, cookie=94469034345600},{addr=192.168.122.222:0/3622013109, watcher_id=4399, cookie=94552591622144},{addr=192.168.122.222:0/3622013109, watcher_id=4399, cookie=94552591627904},{addr=192.168.122.61:0/623435185, watcher_id=4375, cookie=94785438688384},{addr=192.168.122.61:0/623435185, watcher_id=4375, cookie=94785438694144}^M
2022-04-19T14:57:12.028+0000 7f87f3fff700 20 librbd::image::ListWatchersRequest: 0x7f87f8034000 finish: r=0^M
2022-04-19T14:57:12.028+0000 7f87f3fff700 20 librbd::image::ListWatchersRequest: 0x7f87f8034000 finish: filtering out my instance: {addr=172.17.0.4:0/2834779798, watcher_id=169021, cookie=140221622612720}^M
2022-04-19T14:57:12.028+0000 7f87f3fff700 15 librbd::mirror::snapshot::PromoteRequest: 0x7f87e4016ce0 handle_list_watchers: r=0^M
2022-04-19T14:57:12.028+0000 7f87f3fff700 15 librbd::mirror::snapshot::PromoteRequest: 0x7f87e4016ce0 wait_update_notify: ^M
2022-04-19T14:57:12.028+0000 7f87f3fff700 20 librbd::ImageState: 0x557e4dd13430 register_update_watcher^M
2022-04-19T14:57:12.028+0000 7f87f3fff700 20 librbd::ImageState: 0x557e4db841a0 ImageUpdateWatchers::register_watcher: watcher=0x7f87e4016d28^M
2022-04-19T14:57:12.028+0000 7f87f3fff700 20 librbd::ImageState: 0x557e4dd13430 register_update_watcher: handle=1^M
2022-04-19T14:57:12.028+0000 7f87f3fff700 15 librbd::mirror::snapshot::PromoteRequest: 0x7f87e4016ce0 scheduler_unregister_update_watcher: scheduler_ticks=5^M
2022-04-19T14:57:13.029+0000 7f87f0ff9700 15 librbd::mirror::snapshot::PromoteRequest: 0x7f87e4016ce0 scheduler_unregister_update_watcher: scheduler_ticks=4^M
2022-04-19T14:57:14.029+0000 7f87f0ff9700 15 librbd::mirror::snapshot::PromoteRequest: 0x7f87e4016ce0 scheduler_unregister_update_watcher: scheduler_ticks=3^M
2022-04-19T14:57:15.030+0000 7f87f0ff9700 15 librbd::mirror::snapshot::PromoteRequest: 0x7f87e4016ce0 scheduler_unregister_update_watcher: scheduler_ticks=2^M
2022-04-19T14:57:16.035+0000 7f87f0ff9700 15 librbd::mirror::snapshot::PromoteRequest: 0x7f87e4016ce0 scheduler_unregister_update_watcher: scheduler_ticks=1^M
2022-04-19T14:57:16.358+0000 7f87f37fe700  1 -- 172.17.0.4:0/2834779798 --> [v2:192.168.122.61:6800/1040034008,v1:192.168.122.61:6801/1040034008] -- osd_op(unknown.0.0:38 2.14 2:2b6ef884:::rbd_header.111787236b0f:head [watch ping cookie 140221622612720] snapc 0=[] ondisk+write+known_if_redirected e26945) v8 -- 0x7f87cc001190 con 0x557e4dd18130^M
2022-04-19T14:57:16.358+0000 7f87f37fe700  1 -- 172.17.0.4:0/2834779798 --> [v2:192.168.122.61:3300/0,v1:192.168.122.61:6789/0] -- mon_subscribe({osdmap=26946}) v3 -- 0x7f87cc002db0 con 0x557e4dc10aa0^M
2022-04-19T14:57:16.358+0000 7f87f37fe700  1 -- 172.17.0.4:0/2834779798 --> [v2:192.168.122.61:6800/1040034008,v1:192.168.122.61:6801/1040034008] -- ping magic: 0 v1 -- 0x7f87cc0030b0 con 0x557e4dd18130^M
2022-04-19T14:57:16.360+0000 7f8802e2e700  1 -- 172.17.0.4:0/2834779798 <== osd.0 v2:192.168.122.61:6800/1040034008 47 ==== osd_op_reply(38 rbd_header.111787236b0f [watch ping cookie 140221622612720] v0'0 uv4864 ondisk = 0) v8 ==== 167+0+0 (crc 0 0 0) 0x7f87f803c040 con 0x557e4dd18130^M
2022-04-19T14:57:17.035+0000 7f87f0ff9700 15 librbd::mirror::snapshot::PromoteRequest: 0x7f87e4016ce0 scheduler_unregister_update_watcher: scheduler_ticks=0^M

History

#1 Updated by Deepika Upadhyay almost 2 years ago

WIP update:
It appears in the failing case the replayer never goes idle and last updated status was :

debug 2022-04-19T12:57:41.618+0000 7f68b7515700 20 librbd::watcher::Notifier: 0x5634f724cc80 notify: pending=1
debug 2022-04-19T12:57:41.618+0000 7f68b7515700  1 -- 192.168.122.61:0/623435185 --> [v2:192.168.122.61:6800/1040034008,v1:192.168.122.61:6801/1040034008] -- osd_op(unknown.0.0:1068783 2.1b 2:de02d232:::rbd_header.11174dfcc329:head [notify
debug 2022-04-19T12:57:41.618+0000 7f68a94f9700 20 librbd::ImageState: 0x5634f73fb420 ImageUpdateWatchers::handle_notify: handle=0, watcher=0x5634f4ff76f0
debug 2022-04-19T12:57:41.618+0000 7f68a94f9700 10 rbd::mirror::image_replayer::snapshot::Replayer: 0x5634f4865000 handle_image_update_notify:
debug 2022-04-19T12:57:41.618+0000 7f68a94f9700 15 rbd::mirror::image_replayer::snapshot::Replayer: 0x5634f4865000 handle_image_update_notify: flagging snapshot rescan required
debug 2022-04-19T12:57:41.621+0000 7f68b9519700  1 -- 192.168.122.61:0/623435185 <== osd.0 v2:192.168.122.61:6800/1040034008 1501568 ==== watch-notify(notify (1) cookie 94785438701056 notify 114048561869066 bl_val ^G^A^D^@^@^@^C^@^@^@ ret 0
debug 2022-04-19T12:57:41.621+0000 7f68a94f9700 10 rbd::mirror::image_replayer::snapshot::Replayer: 0x5634f4865000 handle_image_update_notify:

void Replayer<I>::handle_image_update_notify() {
  dout(10) << dendl;

  std::unique_lock locker{m_lock};
  if (m_state == STATE_REPLAYING) {
    dout(15) << "flagging snapshot rescan required" << dendl;
    m_image_updated = true;
  } else if (m_state == STATE_IDLE) {
    m_state = STATE_REPLAYING;
    locker.unlock();

    dout(15) << "restarting idle replayer" << dendl;
    load_local_image_meta();
  }
}

if Ideal state is never reached we never get to load_local_image_meta() and hence no eventual process of scanning the orphan snapshot.

There is no activity from `rbd::mirror::image_replayer::snapshot::Replayer` `handle_image_update_notify`

#2 Updated by Christopher Hoffman almost 2 years ago

Hit this issue when primary cluster is still available and healthy.

Steps to reproduce:
-Create 100 images
-Run rbd bench to 100 of those images
-force promote pool on secondary cluster

#3 Updated by Ilya Dryomov over 1 year ago

  • Status changed from New to In Progress
  • Assignee set to Christopher Hoffman

#4 Updated by Christopher Hoffman over 1 year ago

  • Pull request ID set to 47685

#5 Updated by Christopher Hoffman over 1 year ago

  • Status changed from In Progress to Fix Under Review

#6 Updated by Ilya Dryomov 11 months ago

  • Status changed from Fix Under Review to In Progress

#7 Updated by Christopher Hoffman 8 months ago

Steps to reproduce is in the description.

Thoughts for a further discussion:
-One can argue https://github.com/ceph/ceph/pull/51540 seems to handle this issue and is more straight forward.
-What sort of use cases or scenarios would an immediate "cancel ops" be a stronger approach?
-Priority versus other work

Also available in: Atom PDF