Project

General

Profile

Actions
Copy link

Bug #40950

closed

rbd: removing snaps failed: (2) No such file or directory

Added by Konstantin Shalygin almost 5 years ago. Updated over 4 years ago.

Status:
Closed
Priority:
Normal
Assignee:
-
Target version:
-
% Done:

0%

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

Description

I have some, perhaps ancient images:

# rbd info replicated_rbd/volume-0720f58e-69cf-4728-b6f4-1fd8bce43c14.deleted
rbd image 'volume-0720f58e-69cf-4728-b6f4-1fd8bce43c14.deleted':
        size 15GiB in 3840 objects
        order 22 (4MiB objects)
        block_name_prefix: rbd_data.2765c3226ec1b8
        format: 2
        features: layering, striping, exclusive-lock, object-map, fast-diff
        flags: 
        stripe unit: 4MiB
        stripe count: 1

# rbd snap ls replicated_rbd/volume-0720f58e-69cf-4728-b6f4-1fd8bce43c14.deleted
SNAPID NAME                                                    SIZE TIMESTAMP 
    16 volume-10e16c30-17ad-41ab-af11-6e9e5ee4fb03.clone_snap 15GiB

# rados -p replicated_rbd listomapvals rbd_header.2765c3226ec1b8                                                                                                                    
features
value (8 bytes) :
00000000  1f 00 00 00 00 00 00 00                           |........|
00000008

flags
value (8 bytes) :
00000000  00 00 00 00 00 00 00 00                           |........|
00000008

object_prefix
value (27 bytes) :
00000000  17 00 00 00 72 62 64 5f  64 61 74 61 2e 32 37 36  |....rbd_data.276|
00000010  35 63 33 32 32 36 65 63  31 62 38                 |5c3226ec1b8|
0000001b

order
value (1 bytes) :
00000000  16                                                |.|
00000001

size
value (8 bytes) :
00000000  00 00 00 c0 03 00 00 00                           |........|
00000008

snap_seq
value (8 bytes) :
00000000  10 00 00 00 00 00 00 00                           |........|
00000008

snapshot_0000000000000010
value (149 bytes) :
00000000  06 01 8f 00 00 00 10 00  00 00 00 00 00 00 36 00  |..............6.|
00000010  00 00 76 6f 6c 75 6d 65  2d 31 30 65 31 36 63 33  |..volume-10e16c3|
00000020  30 2d 31 37 61 64 2d 34  31 61 62 2d 61 66 31 31  |0-17ad-41ab-af11|
00000030  2d 36 65 39 65 35 65 65  34 66 62 30 33 2e 63 6c  |-6e9e5ee4fb03.cl|
00000040  6f 6e 65 5f 73 6e 61 70  00 00 00 c0 03 00 00 00  |one_snap........|
00000050  03 00 00 00 00 00 00 00  01 01 1c 00 00 00 ff ff  |................|
00000060  ff ff ff ff ff ff 00 00  00 00 fe ff ff ff ff ff  |................|
00000070  ff ff 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
00000080  00 00 00 01 01 04 00 00  00 ff ff ff ff 00 00 00  |................|
00000090  00 00 00 00 00                                    |.....|
00000095

# rbd --debug_rbd=20 --debug_ms=1 snap unprotect replicated_rbd/volume-0720f58e-69cf-4728-b6f4-1fd8bce43c14.deleted@volume-10e16c30-17ad-41ab-af11-6e9e5ee4fb03.clone_snap
2019-07-25 16:00:05.020548 7f394b49ad40  1  Processor -- start
2019-07-25 16:00:05.020715 7f394b49ad40  1 -- - start start
2019-07-25 16:00:05.020944 7f394b49ad40  1 -- - --> 172.16.16.2:6789/0 -- auth(proto 0 34 bytes epoch 0) v1 -- 0x563a7a6cb920 con 0
2019-07-25 16:00:05.020957 7f394b49ad40  1 -- - --> 172.16.16.4:6789/0 -- auth(proto 0 34 bytes epoch 0) v1 -- 0x563a7a6cbc90 con 0
2019-07-25 16:00:05.021062 7f393b37b700  1 -- 172.16.16.2:0/387414038 learned_addr learned my addr 172.16.16.2:0/387414038
2019-07-25 16:00:05.021277 7f3923fff700  1 -- 172.16.16.2:0/387414038 <== mon.0 172.16.16.2:6789/0 1 ==== mon_map magic: 0 v1 ==== 433+0+0 (1676016757 0 0) 0x7f392c0012e0 con 0x563a7a6cd740
2019-07-25 16:00:05.021319 7f3923fff700  1 -- 172.16.16.2:0/387414038 <== mon.2 172.16.16.4:6789/0 1 ==== mon_map magic: 0 v1 ==== 433+0+0 (1676016757 0 0) 0x7f39300012a0 con 0x563a7a6d0d50
2019-07-25 16:00:05.021339 7f3923fff700  1 -- 172.16.16.2:0/387414038 <== mon.0 172.16.16.2:6789/0 2 ==== auth_reply(proto 2 0 (0) Success) v1 ==== 33+0+0 (2567299762 0 0) 0x7f392c001610 con 0x563a7a6cd740
2019-07-25 16:00:05.021422 7f3923fff700  1 -- 172.16.16.2:0/387414038 --> 172.16.16.2:6789/0 -- auth(proto 2 32 bytes epoch 0) v1 -- 0x7f3910001d40 con 0
2019-07-25 16:00:05.021432 7f3923fff700  1 -- 172.16.16.2:0/387414038 <== mon.2 172.16.16.4:6789/0 2 ==== auth_reply(proto 2 0 (0) Success) v1 ==== 33+0+0 (4193586236 0 0) 0x7f39300014c0 con 0x563a7a6d0d50
2019-07-25 16:00:05.021453 7f3923fff700  1 -- 172.16.16.2:0/387414038 --> 172.16.16.4:6789/0 -- auth(proto 2 32 bytes epoch 0) v1 -- 0x7f39100034b0 con 0
2019-07-25 16:00:05.021583 7f3923fff700  1 -- 172.16.16.2:0/387414038 <== mon.0 172.16.16.2:6789/0 3 ==== auth_reply(proto 2 0 (0) Success) v1 ==== 206+0+0 (801428586 0 0) 0x7f392c000eb0 con 0x563a7a6cd740
2019-07-25 16:00:05.021626 7f3923fff700  1 -- 172.16.16.2:0/387414038 --> 172.16.16.2:6789/0 -- auth(proto 2 165 bytes epoch 0) v1 -- 0x7f39100024a0 con 0
2019-07-25 16:00:05.021634 7f3923fff700  1 -- 172.16.16.2:0/387414038 <== mon.2 172.16.16.4:6789/0 3 ==== auth_reply(proto 2 0 (0) Success) v1 ==== 206+0+0 (1903611240 0 0) 0x7f3930000e00 con 0x563a7a6d0d50
2019-07-25 16:00:05.021668 7f3923fff700  1 -- 172.16.16.2:0/387414038 --> 172.16.16.4:6789/0 -- auth(proto 2 165 bytes epoch 0) v1 -- 0x7f39100029b0 con 0
2019-07-25 16:00:05.021812 7f3923fff700  1 -- 172.16.16.2:0/387414038 <== mon.0 172.16.16.2:6789/0 4 ==== auth_reply(proto 2 0 (0) Success) v1 ==== 580+0+0 (1130696846 0 0) 0x7f392c001430 con 0x563a7a6cd740
2019-07-25 16:00:05.021857 7f3923fff700  1 -- 172.16.16.2:0/387414038 >> 172.16.16.4:6789/0 conn(0x563a7a6d0d50 :-1 s=STATE_OPEN pgs=33039961 cs=1 l=1).mark_down
2019-07-25 16:00:05.021887 7f3923fff700  1 -- 172.16.16.2:0/387414038 --> 172.16.16.2:6789/0 -- mon_subscribe({monmap=0+}) v2 -- 0x563a7a6d75f0 con 0
2019-07-25 16:00:05.021923 7f394b49ad40  1 -- 172.16.16.2:0/387414038 --> 172.16.16.2:6789/0 -- mon_subscribe({mgrmap=0+}) v2 -- 0x563a7a6d75f0 con 0
2019-07-25 16:00:05.021979 7f394b49ad40  1 -- 172.16.16.2:0/387414038 --> 172.16.16.2:6789/0 -- mon_subscribe({osdmap=0}) v2 -- 0x563a7a6d75f0 con 0
2019-07-25 16:00:05.021990 7f3923fff700  1 -- 172.16.16.2:0/387414038 <== mon.0 172.16.16.2:6789/0 5 ==== mon_map magic: 0 v1 ==== 433+0+0 (1676016757 0 0) 0x7f392c001640 con 0x563a7a6cd740
2019-07-25 16:00:05.022069 7f3923fff700  1 -- 172.16.16.2:0/387414038 <== mon.0 172.16.16.2:6789/0 6 ==== mgrmap(e 829) v1 ==== 336+0+0 (1003204802 0 0) 0x7f392c001430 con 0x563a7a6cd740
2019-07-25 16:00:05.022108 7f3923fff700  1 -- 172.16.16.2:0/387414038 <== mon.0 172.16.16.2:6789/0 7 ==== osd_map(57003..57003 src has 56443..57003) v3 ==== 45964+0+0 (1221712999 0 0) 0x7f392c001fd0 con 0x563a7a6cd740
2019-07-25 16:00:05.022775 7f394b49ad40  5 librbd::io::ImageRequestWQ: 0x563a7a6d7c10 ImageRequestWQ: ictx=0x563a7a6d5ea0
2019-07-25 16:00:05.022823 7f394b49ad40 20 librbd::ImageState: 0x563a7a6cb900 open
2019-07-25 16:00:05.022833 7f394b49ad40 10 librbd::ImageState: 0x563a7a6cb900 0x563a7a6cb900 send_open_unlock
2019-07-25 16:00:05.022838 7f394b49ad40 10 librbd::image::OpenRequest: 0x563a7a6d8490 send_v2_detect_header
2019-07-25 16:00:05.022934 7f394b49ad40  1 -- 172.16.16.2:0/387414038 --> 172.16.16.11:6826/21514 -- osd_op(unknown.0.0:1 1.105 1:a0a19ee8:::rbd_id.volume-0720f58e-69cf-4728-b6f4-1fd8bce43c14.deleted:head [stat] snapc 0=[] ondisk+read+known_if_redirected+full_try e57003) v8 -- 0x563a7a6ddbb0 con 0
2019-07-25 16:00:05.023698 7f393a379700  1 -- 172.16.16.2:0/387414038 <== osd.9 172.16.16.11:6826/21514 1 ==== osd_op_reply(1 rbd_id.volume-0720f58e-69cf-4728-b6f4-1fd8bce43c14.deleted [stat] v0'0 uv44829207 ondisk = 0) v8 ==== 202+0+16 (1352357860 0 1175137936) 0x7f3924002180 con 0x563a7a6d9590
2019-07-25 16:00:05.023752 7f3920ff9700 10 librbd::image::OpenRequest: handle_v2_detect_header: r=0
2019-07-25 16:00:05.023757 7f3920ff9700 10 librbd::image::OpenRequest: 0x563a7a6d8490 send_v2_get_id
2019-07-25 16:00:05.023782 7f3920ff9700  1 -- 172.16.16.2:0/387414038 --> 172.16.16.11:6826/21514 -- osd_op(unknown.0.0:2 1.105 1:a0a19ee8:::rbd_id.volume-0720f58e-69cf-4728-b6f4-1fd8bce43c14.deleted:head [call rbd.get_id] snapc 0=[] ondisk+read+known_if_redirected+full_try e57003) v8 -- 0x7f3904002230 con 0
2019-07-25 16:00:05.024018 7f393a379700  1 -- 172.16.16.2:0/387414038 <== osd.9 172.16.16.11:6826/21514 2 ==== osd_op_reply(2 rbd_id.volume-0720f58e-69cf-4728-b6f4-1fd8bce43c14.deleted [call] v0'0 uv44829207 ondisk = 0) v8 ==== 202+0+18 (603017223 0 1109612034) 0x7f3924002ac0 con 0x563a7a6d9590
2019-07-25 16:00:05.024033 7f3920ff9700 10 librbd::image::OpenRequest: handle_v2_get_id: r=0
2019-07-25 16:00:05.024040 7f3920ff9700 10 librbd::image::OpenRequest: 0x563a7a6d8490 send_v2_get_immutable_metadata
2019-07-25 16:00:05.024075 7f3920ff9700  1 -- 172.16.16.2:0/387414038 --> 172.16.16.16:6808/8296 -- osd_op(unknown.0.0:3 1.13c 1:3cabb4b0:::rbd_header.2765c3226ec1b8:head [call rbd.get_size,call rbd.get_object_prefix] snapc 0=[] ondisk+read+known_if_redirected+full_try e57003) v8 -- 0x7f3904009a40 con 0
2019-07-25 16:00:05.025017 7f3939b78700  1 -- 172.16.16.2:0/387414038 <== osd.16 172.16.16.16:6808/8296 1 ==== osd_op_reply(3 rbd_header.2765c3226ec1b8 [call,call] v0'0 uv55663080 ondisk = 0) v8 ==== 211+0+36 (1373440895 0 1054985453) 0x7f3928002290 con 0x7f3904005420
2019-07-25 16:00:05.025034 7f3920ff9700 10 librbd::image::OpenRequest: handle_v2_get_immutable_metadata: r=0
2019-07-25 16:00:05.025037 7f3920ff9700 10 librbd::image::OpenRequest: 0x563a7a6d8490 send_v2_get_stripe_unit_count
2019-07-25 16:00:05.025052 7f3920ff9700  1 -- 172.16.16.2:0/387414038 --> 172.16.16.16:6808/8296 -- osd_op(unknown.0.0:4 1.13c 1:3cabb4b0:::rbd_header.2765c3226ec1b8:head [call rbd.get_stripe_unit_count] snapc 0=[] ondisk+read+known_if_redirected+full_try e57003) v8 -- 0x7f3904002d60 con 0
2019-07-25 16:00:05.025312 7f3939b78700  1 -- 172.16.16.2:0/387414038 <== osd.16 172.16.16.16:6808/8296 2 ==== osd_op_reply(4 rbd_header.2765c3226ec1b8 [call] v0'0 uv55663080 ondisk = 0) v8 ==== 169+0+16 (2430960890 0 74706562) 0x7f39280024a0 con 0x7f3904005420
2019-07-25 16:00:05.025324 7f3920ff9700 10 librbd::image::OpenRequest: handle_v2_get_stripe_unit_count: r=0
2019-07-25 16:00:05.025326 7f3920ff9700 10 librbd::image::OpenRequest: 0x563a7a6d8490 send_v2_get_create_timestamp
2019-07-25 16:00:05.025339 7f3920ff9700  1 -- 172.16.16.2:0/387414038 --> 172.16.16.16:6808/8296 -- osd_op(unknown.0.0:5 1.13c 1:3cabb4b0:::rbd_header.2765c3226ec1b8:head [call rbd.get_create_timestamp] snapc 0=[] ondisk+read+known_if_redirected+full_try e57003) v8 -- 0x7f39040020f0 con 0
2019-07-25 16:00:05.025543 7f3939b78700  1 -- 172.16.16.2:0/387414038 <== osd.16 172.16.16.16:6808/8296 3 ==== osd_op_reply(5 rbd_header.2765c3226ec1b8 [call] v0'0 uv55663080 ondisk = 0) v8 ==== 169+0+8 (2214946715 0 0) 0x7f39280026f0 con 0x7f3904005420
2019-07-25 16:00:05.025554 7f3920ff9700 10 librbd::image::OpenRequest: 0x563a7a6d8490 handle_v2_get_create_timestamp: r=0
2019-07-25 16:00:05.025557 7f3920ff9700 10 librbd::image::OpenRequest: 0x563a7a6d8490 send_v2_get_data_pool
2019-07-25 16:00:05.025571 7f3920ff9700  1 -- 172.16.16.2:0/387414038 --> 172.16.16.16:6808/8296 -- osd_op(unknown.0.0:6 1.13c 1:3cabb4b0:::rbd_header.2765c3226ec1b8:head [call rbd.get_data_pool] snapc 0=[] ondisk+read+known_if_redirected+full_try e57003) v8 -- 0x7f39040020f0 con 0
2019-07-25 16:00:05.025762 7f3939b78700  1 -- 172.16.16.2:0/387414038 <== osd.16 172.16.16.16:6808/8296 4 ==== osd_op_reply(6 rbd_header.2765c3226ec1b8 [call] v0'0 uv55663080 ondisk = 0) v8 ==== 169+0+8 (3146824961 0 3293575501) 0x7f3928002410 con 0x7f3904005420
2019-07-25 16:00:05.025774 7f3920ff9700 10 librbd::image::OpenRequest: 0x563a7a6d8490 handle_v2_get_data_pool: r=0
2019-07-25 16:00:05.025785 7f3920ff9700 10 librbd::ImageCtx: init_layout stripe_unit 4194304 stripe_count 1 object_size 4194304 prefix rbd_data.2765c3226ec1b8 format rbd_data.2765c3226ec1b8.%016llx
2019-07-25 16:00:05.025788 7f3920ff9700 10 librbd::image::OpenRequest: 0x563a7a6d8490 send_v2_apply_metadata: start_key=conf_
2019-07-25 16:00:05.025805 7f3920ff9700  1 -- 172.16.16.2:0/387414038 --> 172.16.16.16:6808/8296 -- osd_op(unknown.0.0:7 1.13c 1:3cabb4b0:::rbd_header.2765c3226ec1b8:head [call rbd.metadata_list] snapc 0=[] ondisk+read+known_if_redirected+full_try e57003) v8 -- 0x7f3904004720 con 0
2019-07-25 16:00:05.026086 7f3939b78700  1 -- 172.16.16.2:0/387414038 <== osd.16 172.16.16.16:6808/8296 5 ==== osd_op_reply(7 rbd_header.2765c3226ec1b8 [call] v0'0 uv55663080 ondisk = 0) v8 ==== 169+0+4 (2434945042 0 0) 0x7f3928002620 con 0x7f3904005420
2019-07-25 16:00:05.026099 7f3920ff9700 10 librbd::image::OpenRequest: 0x563a7a6d8490 handle_v2_apply_metadata: r=0
2019-07-25 16:00:05.026111 7f3920ff9700 20 librbd::ImageCtx: apply_metadata
2019-07-25 16:00:05.030140 7f3920ff9700 20 librbd::ImageCtx: enabling caching...
2019-07-25 16:00:05.030144 7f3920ff9700 20 librbd::ImageCtx: Initial cache settings: size=33554432 num_objects=10 max_dirty=25165824 target_dirty=16777216 max_dirty_age=1
2019-07-25 16:00:05.030192 7f3920ff9700 10 librbd::ImageCtx:  cache bytes 33554432 -> about 1048 objects
2019-07-25 16:00:05.030209 7f3920ff9700 10 librbd::image::OpenRequest: 0x563a7a6d8490 send_register_watch
2019-07-25 16:00:05.030260 7f3920ff9700 10 librbd::Watcher: 0x7f390400cb30 register_watch: 
2019-07-25 16:00:05.030302 7f3920ff9700  1 -- 172.16.16.2:0/387414038 --> 172.16.16.16:6808/8296 -- osd_op(unknown.0.0:8 1.13c 1:3cabb4b0:::rbd_header.2765c3226ec1b8:head [watch watch cookie 139882857030704] snapc 0=[] ondisk+write+known_if_redirected+full_try e57003) v8 -- 0x7f390400efb0 con 0
2019-07-25 16:00:05.031256 7f3939b78700  1 -- 172.16.16.2:0/387414038 <== osd.16 172.16.16.16:6808/8296 6 ==== osd_op_reply(8 rbd_header.2765c3226ec1b8 [watch watch cookie 139882857030704] v57003'68569264 uv55663080 ondisk = 0) v8 ==== 169+0+0 (3951113310 0 0) 0x7f3928002410 con 0x7f3904005420
2019-07-25 16:00:05.031272 7f3920ff9700 10 librbd::Watcher: 0x7f390400cb30 handle_register_watch: r=0
2019-07-25 16:00:05.031276 7f3920ff9700 10 librbd::image::OpenRequest: 0x563a7a6d8490 handle_register_watch: r=0
2019-07-25 16:00:05.031277 7f3920ff9700 10 librbd::image::OpenRequest: 0x563a7a6d8490 send_refresh
2019-07-25 16:00:05.031280 7f3920ff9700 10 librbd::image::RefreshRequest: 0x7f390400ecb0 send_v2_get_mutable_metadata
2019-07-25 16:00:05.031310 7f3920ff9700  1 -- 172.16.16.2:0/387414038 --> 172.16.16.16:6808/8296 -- osd_op(unknown.0.0:9 1.13c 1:3cabb4b0:::rbd_header.2765c3226ec1b8:head [call rbd.get_size,call rbd.get_features,call rbd.get_snapcontext,call rbd.get_parent,call lock.get_info] snapc 0=[] ondisk+read+known_if_redirected+full_try e57003) v8 -- 0x7f3904019370 con 0
2019-07-25 16:00:05.031802 7f3939b78700  1 -- 172.16.16.2:0/387414038 <== osd.16 172.16.16.16:6808/8296 7 ==== osd_op_reply(9 rbd_header.2765c3226ec1b8 [call,call,call,call,call] v0'0 uv55663080 ondisk = 0) v8 ==== 337+0+96 (2236300000 0 3525338307) 0x7f3928002620 con 0x7f3904005420
2019-07-25 16:00:05.031818 7f3920ff9700 10 librbd::image::RefreshRequest: 0x7f390400ecb0 handle_v2_get_mutable_metadata: r=0
2019-07-25 16:00:05.031830 7f3920ff9700 10 librbd::image::RefreshRequest: 0x7f390400ecb0 send_v2_get_metadata: start_key=
2019-07-25 16:00:05.031846 7f3920ff9700  1 -- 172.16.16.2:0/387414038 --> 172.16.16.16:6808/8296 -- osd_op(unknown.0.0:10 1.13c 1:3cabb4b0:::rbd_header.2765c3226ec1b8:head [call rbd.metadata_list] snapc 0=[] ondisk+read+known_if_redirected+full_try e57003) v8 -- 0x7f3904010a80 con 0
2019-07-25 16:00:05.032090 7f3939b78700  1 -- 172.16.16.2:0/387414038 <== osd.16 172.16.16.16:6808/8296 8 ==== osd_op_reply(10 rbd_header.2765c3226ec1b8 [call] v0'0 uv55663080 ondisk = 0) v8 ==== 169+0+4 (169796802 0 0) 0x7f3928002410 con 0x7f3904005420
2019-07-25 16:00:05.032103 7f3920ff9700 10 librbd::image::RefreshRequest: 0x7f390400ecb0 handle_v2_get_metadata: r=0
2019-07-25 16:00:05.032106 7f3920ff9700 20 librbd::ImageCtx: apply_metadata
2019-07-25 16:00:05.035732 7f3920ff9700 10 librbd::image::RefreshRequest: 0x7f390400ecb0 send_v2_get_flags
2019-07-25 16:00:05.035832 7f3920ff9700  1 -- 172.16.16.2:0/387414038 --> 172.16.16.16:6808/8296 -- osd_op(unknown.0.0:11 1.13c 1:3cabb4b0:::rbd_header.2765c3226ec1b8:head [call rbd.get_flags,call rbd.get_flags] snapc 0=[] ondisk+read+known_if_redirected+full_try e57003) v8 -- 0x7f39040120a0 con 0
2019-07-25 16:00:05.036109 7f3939b78700  1 -- 172.16.16.2:0/387414038 <== osd.16 172.16.16.16:6808/8296 9 ==== osd_op_reply(11 rbd_header.2765c3226ec1b8 [call,call] v0'0 uv55663080 ondisk = 0) v8 ==== 211+0+16 (1467156791 0 0) 0x7f3928003520 con 0x7f3904005420
2019-07-25 16:00:05.036123 7f3920ff9700 10 librbd::image::RefreshRequest: 0x7f390400ecb0 handle_v2_get_flags: r=0
2019-07-25 16:00:05.036128 7f3920ff9700 10 librbd::image::RefreshRequest: 0x7f390400ecb0 send_v2_get_group
2019-07-25 16:00:05.036142 7f3920ff9700  1 -- 172.16.16.2:0/387414038 --> 172.16.16.16:6808/8296 -- osd_op(unknown.0.0:12 1.13c 1:3cabb4b0:::rbd_header.2765c3226ec1b8:head [call rbd.image_get_group] snapc 0=[] ondisk+read+known_if_redirected+full_try e57003) v8 -- 0x7f390400f850 con 0
2019-07-25 16:00:05.036338 7f3939b78700  1 -- 172.16.16.2:0/387414038 <== osd.16 172.16.16.16:6808/8296 10 ==== osd_op_reply(12 rbd_header.2765c3226ec1b8 [call] v0'0 uv55663080 ondisk = 0) v8 ==== 169+0+18 (145133082 0 3089390191) 0x7f3928003730 con 0x7f3904005420
2019-07-25 16:00:05.036350 7f3920ff9700 10 librbd::image::RefreshRequest: 0x7f390400ecb0 handle_v2_get_group: r=0
2019-07-25 16:00:05.036355 7f3920ff9700 10 librbd::image::RefreshRequest: 0x7f390400ecb0 send_v2_get_snapshots
2019-07-25 16:00:05.036377 7f3920ff9700  1 -- 172.16.16.2:0/387414038 --> 172.16.16.16:6808/8296 -- osd_op(unknown.0.0:13 1.13c 1:3cabb4b0:::rbd_header.2765c3226ec1b8:head [call rbd.get_snapshot_name,call rbd.get_size,call rbd.get_parent,call rbd.get_protection_status] snapc 0=[] ondisk+read+known_if_redirected+full_try e57003) v8 -- 0x7f39040122d0 con 0
2019-07-25 16:00:05.036702 7f3939b78700  1 -- 172.16.16.2:0/387414038 <== osd.16 172.16.16.16:6808/8296 11 ==== osd_op_reply(13 rbd_header.2765c3226ec1b8 [call,call,call,call] v0'0 uv55663080 ondisk = 0) v8 ==== 295+0+96 (2895979804 0 302450594) 0x7f3928003c90 con 0x7f3904005420
2019-07-25 16:00:05.036717 7f3920ff9700 10 librbd::image::RefreshRequest: 0x7f390400ecb0 handle_v2_get_snapshots: r=0
2019-07-25 16:00:05.036723 7f3920ff9700 10 librbd::image::RefreshRequest: 0x7f390400ecb0 send_v2_get_snap_timestamps
2019-07-25 16:00:05.036737 7f3920ff9700  1 -- 172.16.16.2:0/387414038 --> 172.16.16.16:6808/8296 -- osd_op(unknown.0.0:14 1.13c 1:3cabb4b0:::rbd_header.2765c3226ec1b8:head [call rbd.get_snapshot_timestamp] snapc 0=[] ondisk+read+known_if_redirected+full_try e57003) v8 -- 0x7f390400fe20 con 0
2019-07-25 16:00:05.036937 7f3939b78700  1 -- 172.16.16.2:0/387414038 <== osd.16 172.16.16.16:6808/8296 12 ==== osd_op_reply(14 rbd_header.2765c3226ec1b8 [call] v0'0 uv55663080 ondisk = 0) v8 ==== 169+0+8 (2572060462 0 0) 0x7f39280036c0 con 0x7f3904005420
2019-07-25 16:00:05.036949 7f3920ff9700 10 librbd::image::RefreshRequest: 0x7f390400ecb0 handle_v2_get_snap_timestamps: r=0
2019-07-25 16:00:05.036951 7f3920ff9700 10 librbd::image::RefreshRequest: 0x7f390400ecb0 send_v2_get_snap_namespaces
2019-07-25 16:00:05.036964 7f3920ff9700  1 -- 172.16.16.2:0/387414038 --> 172.16.16.16:6808/8296 -- osd_op(unknown.0.0:15 1.13c 1:3cabb4b0:::rbd_header.2765c3226ec1b8:head [call rbd.get_snapshot_namespace] snapc 0=[] ondisk+read+known_if_redirected+full_try e57003) v8 -- 0x7f390400fe20 con 0
2019-07-25 16:00:05.037166 7f3939b78700  1 -- 172.16.16.2:0/387414038 <== osd.16 172.16.16.16:6808/8296 13 ==== osd_op_reply(15 rbd_header.2765c3226ec1b8 [call] v0'0 uv55663080 ondisk = 0) v8 ==== 169+0+10 (442448273 0 2850921400) 0x7f3928003c90 con 0x7f3904005420
2019-07-25 16:00:05.037179 7f3920ff9700 10 librbd::image::RefreshRequest: 0x7f390400ecb0 handle_v2_get_snap_namespaces: r=0
2019-07-25 16:00:05.037188 7f3920ff9700 10 librbd::image::RefreshRequest: 0x7f390400ecb0 send_v2_init_exclusive_lock
2019-07-25 16:00:05.037196 7f3920ff9700 10 librbd::ExclusiveLock: 0x7f3904012350 init
2019-07-25 16:00:05.037200 7f3920ff9700  5 librbd::io::ImageRequestWQ: 0x563a7a6d7c10 block_writes: 0x563a7a6d5ea0, num=1
2019-07-25 16:00:05.037214 7f3917fff700 10 librbd::ExclusiveLock: 0x7f3904012350 handle_init_complete: features=31
2019-07-25 16:00:05.037218 7f3917fff700 20 librbd::io::ImageRequestWQ: 0x563a7a6d7c10 set_require_lock: 
2019-07-25 16:00:05.037220 7f3917fff700 10 librbd::image::RefreshRequest: 0x7f390400ecb0 handle_v2_init_exclusive_lock: r=0
2019-07-25 16:00:05.037220 7f3917fff700 10 librbd::image::RefreshRequest: 0x7f390400ecb0 send_v2_apply
2019-07-25 16:00:05.037226 7f3917fff700 10 librbd::image::RefreshRequest: 0x7f390400ecb0 handle_v2_apply
2019-07-25 16:00:05.037227 7f3917fff700 20 librbd::image::RefreshRequest: 0x7f390400ecb0 apply
2019-07-25 16:00:05.037229 7f3917fff700 20 librbd::image::RefreshRequest: new snapshot id=16 name=volume-10e16c30-17ad-41ab-af11-6e9e5ee4fb03.clone_snap size=16106127360
2019-07-25 16:00:05.037241 7f3917fff700 10 librbd::image::RefreshRequest: 0x7f390400ecb0 send_flush_aio
2019-07-25 16:00:05.037244 7f3917fff700 10 librbd::image::RefreshRequest: 0x7f390400ecb0 handle_flush_aio: r=0
2019-07-25 16:00:05.037246 7f3917fff700 10 librbd::image::OpenRequest: handle_refresh: r=0
2019-07-25 16:00:05.037249 7f3917fff700 10 librbd::ImageState: 0x563a7a6cb900 0x563a7a6cb900 handle_open: r=0
2019-07-25 16:00:05.037260 7f394b49ad40 20 librbd: snap_is_protected 0x563a7a6d5ea0 volume-10e16c30-17ad-41ab-af11-6e9e5ee4fb03.clone_snap
rbd: unprotecting snap failed: (2) No such file or directory
2019-07-25 16:00:05.037275 7f394b49ad40 20 librbd::ImageState: 0x563a7a6cb900 close
2019-07-25 16:00:05.037277 7f394b49ad40 10 librbd::ImageState: 0x563a7a6cb900 0x563a7a6cb900 send_close_unlock
2019-07-25 16:00:05.037280 7f394b49ad40 10 librbd::image::CloseRequest: 0x563a7a635280 send_block_image_watcher
2019-07-25 16:00:05.037282 7f394b49ad40 10 librbd::ImageWatcher: 0x7f390400cb30 block_notifies
2019-07-25 16:00:05.037286 7f394b49ad40  5 librbd::Watcher: 0x7f390400cb30 block_notifies: blocked_count=1
2019-07-25 16:00:05.037289 7f394b49ad40 10 librbd::image::CloseRequest: 0x563a7a635280 handle_block_image_watcher: r=0
2019-07-25 16:00:05.037290 7f394b49ad40 10 librbd::image::CloseRequest: 0x563a7a635280 send_shut_down_update_watchers
2019-07-25 16:00:05.037291 7f394b49ad40 20 librbd::ImageState: 0x563a7a6cb900 shut_down_update_watchers
2019-07-25 16:00:05.037291 7f394b49ad40 20 librbd::ImageState: 0x563a7a6d6c70 ImageUpdateWatchers::shut_down
2019-07-25 16:00:05.037292 7f394b49ad40 20 librbd::ImageState: 0x563a7a6d6c70 ImageUpdateWatchers::shut_down: completing shut down
2019-07-25 16:00:05.037297 7f3917fff700 10 librbd::image::CloseRequest: 0x563a7a635280 handle_shut_down_update_watchers: r=0
2019-07-25 16:00:05.037298 7f3917fff700 10 librbd::image::CloseRequest: 0x563a7a635280 send_shut_down_io_queue
2019-07-25 16:00:05.037299 7f3917fff700  5 librbd::io::ImageRequestWQ: 0x563a7a6d7c10 shut_down: shut_down: in_flight=0
2019-07-25 16:00:05.037300 7f3917fff700 10 librbd::image::CloseRequest: 0x563a7a635280 handle_shut_down_io_queue: r=0
2019-07-25 16:00:05.037301 7f3917fff700 10 librbd::image::CloseRequest: 0x563a7a635280 send_shut_down_exclusive_lock
2019-07-25 16:00:05.037302 7f3917fff700 10 librbd::ExclusiveLock: 0x7f3904012350 shut_down
2019-07-25 16:00:05.037303 7f3917fff700 10 librbd::ManagedLock: 0x7f3904012350 shut_down
2019-07-25 16:00:05.037309 7f3917fff700 10 librbd::ManagedLock: 0x7f3904012350 send_shutdown
2019-07-25 16:00:05.037312 7f3917fff700 10 librbd::ExclusiveLock: 0x7f3904012350 shutdown_handler
2019-07-25 16:00:05.037313 7f3917fff700 20 librbd::io::ImageRequestWQ: 0x563a7a6d7c10 set_require_lock: 
2019-07-25 16:00:05.037314 7f3917fff700  5 librbd::io::ImageRequestWQ: 0x563a7a6d7c10 unblock_writes: 0x563a7a6d5ea0, num=0
2019-07-25 16:00:05.037318 7f3917fff700 10 librbd::ManagedLock: 0x7f3904012350 handle_shutdown: r=0
2019-07-25 16:00:05.037318 7f3917fff700 10 librbd::ManagedLock: 0x7f3904012350 wait_for_tracked_ops: r=0
2019-07-25 16:00:05.037319 7f3917fff700 10 librbd::ManagedLock: 0x7f3904012350 complete_shutdown: r=0
2019-07-25 16:00:05.037321 7f3917fff700 10 librbd::image::CloseRequest: 0x563a7a635280 handle_shut_down_exclusive_lock: r=0
2019-07-25 16:00:05.037326 7f3917fff700 10 librbd::image::CloseRequest: 0x563a7a635280 send_unregister_image_watcher
2019-07-25 16:00:05.037327 7f3917fff700 10 librbd::ImageWatcher: 0x7f390400cb30 unregistering image watcher
2019-07-25 16:00:05.037329 7f3917fff700 10 librbd::Watcher: 0x7f390400cb30 unregister_watch: 
2019-07-25 16:00:05.037351 7f3917fff700  1 -- 172.16.16.2:0/387414038 --> 172.16.16.16:6808/8296 -- osd_op(unknown.0.0:16 1.13c 1:3cabb4b0:::rbd_header.2765c3226ec1b8:head [watch unwatch cookie 139882857030704] snapc 0=[] ondisk+write+known_if_redirected+full_try e57003) v8 -- 0x7f390c0030a0 con 0
2019-07-25 16:00:05.038136 7f3939b78700  1 -- 172.16.16.2:0/387414038 <== osd.16 172.16.16.16:6808/8296 14 ==== osd_op_reply(16 rbd_header.2765c3226ec1b8 [watch unwatch cookie 139882857030704] v57003'68569265 uv55663080 ondisk = 0) v8 ==== 169+0+0 (2070309612 0 0) 0x7f3928003ea0 con 0x7f3904005420
2019-07-25 16:00:05.038174 7f3915ffb700 10 librbd::image::CloseRequest: 0x563a7a635280 handle_unregister_image_watcher: r=0
2019-07-25 16:00:05.038177 7f3915ffb700 10 librbd::image::CloseRequest: 0x563a7a635280 send_flush_readahead
2019-07-25 16:00:05.038186 7f3917fff700 10 librbd::image::CloseRequest: 0x563a7a635280 handle_flush_readahead: r=0
2019-07-25 16:00:05.038190 7f3917fff700 10 librbd::image::CloseRequest: 0x563a7a635280 send_shut_down_cache
2019-07-25 16:00:05.038212 7f3917fff700 10 librbd::image::CloseRequest: 0x563a7a635280 handle_shut_down_cache: r=0
2019-07-25 16:00:05.038214 7f3917fff700 10 librbd::image::CloseRequest: 0x563a7a635280 send_flush_op_work_queue
2019-07-25 16:00:05.038216 7f3917fff700 10 librbd::image::CloseRequest: 0x563a7a635280 handle_flush_op_work_queue: r=0
2019-07-25 16:00:05.038217 7f3917fff700 10 librbd::image::CloseRequest: 0x563a7a635280 handle_flush_image_watcher: r=0
2019-07-25 16:00:05.038231 7f3917fff700 10 librbd::ImageState: 0x563a7a6cb900 0x563a7a6cb900 handle_close: r=0
2019-07-25 16:00:05.038328 7f394b49ad40  1 -- 172.16.16.2:0/387414038 >> 172.16.16.11:6826/21514 conn(0x563a7a6d9590 :-1 s=STATE_OPEN pgs=293523 cs=1 l=1).mark_down
2019-07-25 16:00:05.038340 7f394b49ad40  1 -- 172.16.16.2:0/387414038 >> 172.16.16.16:6808/8296 conn(0x7f3904005420 :-1 s=STATE_OPEN pgs=32708 cs=1 l=1).mark_down
2019-07-25 16:00:05.038423 7f394b49ad40  1 -- 172.16.16.2:0/387414038 >> 172.16.16.2:6800/13270 conn(0x7f391000c000 :-1 s=STATE_OPEN pgs=25400478 cs=1 l=1).mark_down
2019-07-25 16:00:05.038434 7f394b49ad40  1 -- 172.16.16.2:0/387414038 >> 172.16.16.2:6789/0 conn(0x563a7a6cd740 :-1 s=STATE_OPEN pgs=29133480 cs=1 l=1).mark_down
2019-07-25 16:00:05.038445 7f393bb7c700  1 -- 172.16.16.2:0/387414038 reap_dead start
2019-07-25 16:00:05.038528 7f394b49ad40  1 -- 172.16.16.2:0/387414038 shutdown_connections 
2019-07-25 16:00:05.038731 7f394b49ad40  1 -- 172.16.16.2:0/387414038 shutdown_connections 
2019-07-25 16:00:05.038749 7f394b49ad40  1 -- 172.16.16.2:0/387414038 wait complete.
2019-07-25 16:00:05.038759 7f394b49ad40  1 -- 172.16.16.2:0/387414038 >> 172.16.16.2:0/387414038 conn(0x563a7a6bd170 :-1 s=STATE_NONE pgs=0 cs=0 l=0).mark_down

May be this affected old bug "Kraken release and Jewel client"? How to delete snapshot and then image if all compat options already set to Luminous?

Actions
Copy link
 #1

Updated by Jason Dillaman over 4 years ago

Sounds a lot like this issue: https://tracker.ceph.com/issues/19413

You will need to use a pre-Kraken client to remove that snapshot (or update the omap key to change the "FF FF FF FF"s in "00000080 00 00 00 01 01 04 00 00 00 ff ff ff ff 00 00 00 |................|" to "00 00 00 00".

Actions
Copy link
 #2

Updated by Jason Dillaman over 4 years ago

  • Status changed from New to Need More Info
Actions
Copy link
 #3

Updated by Konstantin Shalygin over 4 years ago

Thanks Jason.

I updated omap value like this, then snapshot will successfully deleted.

echo -en \\x06\\x01\\x8f\\x00\\x00\\x00\\x10\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x36\\x00\\x00\\x00\\x76\\x6f\\x6c\\x75\\x6d\\x65\\x2d\\x31\\x30\\x65\\x31\\x36\\x63\\x33\\x30\\x2d\\x31\\x37\\x61\\x64\\x2d\\x34\\x31\\x61\\x62\\x2d\\x61\\x66\\x31\\x31\\x2d\\x36\\x65\\x39\\x65\\x35\\x65\\x65\\x34\\x66\\x62\\x30\\x33\\x2e\\x63\\x6c\\x6f\\x6e\\x65\\x5f\\x73\\x6e\\x61\\x70\\x00\\x00\\x00\\xc0\\x03\\x00\\x00\\x00\\x03\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x01\\x01\\x1c\\x00\\x00\\x00\\xff\\xff\\xff\\xff\\xff\\xff\\xff\\xff\\x00\\x00\\x00\\x00\\xfe\\xff\\xff\\xff\\xff\\xff\\xff\\xff\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x01\\x01\\x04\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00 | rados -p replicated_rbd setomapval rbd_header.2765c3226ec1b8 snapshot_0000000000000010

Actions
Copy link
 #4

Updated by Jason Dillaman over 4 years ago

  • Status changed from Need More Info to Closed
Actions
Copy link
 #5

Updated by Konstantin Shalygin over 4 years ago

Wrote how-to deal with this, it may be help someone from Google - link.

Actions
Copy link

Also available in: Atom PDF