Hi,
I use rbd snap protect snapshot,but then can't unprotect this snapshot.
here is unprotect snapshot logs,
[root at n128045 ~]# rbd snap unprotect block/bar at bar_snap --debug-rbd 20
--debug-ms 1
2014-09-26 21:20:00.131377 7fd4dfdc1760 1 -- :/0 messenger.start
2014-09-26 21:20:00.132636 7fd4dfdc1760 1 -- :/1028228 -->
10.13.128.46:6789/0 -- auth(proto 0 30 bytes epoch 0) v1 -- ?+0
0x1263830 con 0x1263480
2014-09-26 21:20:00.133358 7fd4dc6ea700 1 -- 10.13.128.45:0/1028228
learned my addr 10.13.128.45:0/1028228
2014-09-26 21:20:00.134436 7fd4de4ed700 1 -- 10.13.128.45:0/1028228 <==
mon.1 10.13.128.46:6789/0 1 ==== mon_map v1 ==== 491+0+0 (1094526759 0
0) 0x7fd4c8000be0 con 0x1263480
2014-09-26 21:20:00.134560 7fd4de4ed700 1 -- 10.13.128.45:0/1028228 <==
mon.1 10.13.128.46:6789/0 2 ==== auth_reply(proto 2 0 (0) Success) v1
==== 33+0+0 (2043995474 0 0) 0x7fd4c8001090 con 0x1263480
2014-09-26 21:20:00.134773 7fd4de4ed700 1 -- 10.13.128.45:0/1028228 -->
10.13.128.46:6789/0 -- auth(proto 2 32 bytes epoch 0) v1 -- ?+0
0x7fd4cc0015b0 con 0x1263480
2014-09-26 21:20:00.135419 7fd4de4ed700 1 -- 10.13.128.45:0/1028228 <==
mon.1 10.13.128.46:6789/0 3 ==== auth_reply(proto 2 0 (0) Success) v1
==== 206+0+0 (1342307704 0 0) 0x7fd4c8001090 con 0x1263480
2014-09-26 21:20:00.135560 7fd4de4ed700 1 -- 10.13.128.45:0/1028228 -->
10.13.128.46:6789/0 -- auth(proto 2 165 bytes epoch 0) v1 -- ?+0
0x7fd4cc003760 con 0x1263480
2014-09-26 21:20:00.136173 7fd4de4ed700 1 -- 10.13.128.45:0/1028228 <==
mon.1 10.13.128.46:6789/0 4 ==== auth_reply(proto 2 0 (0) Success) v1
==== 393+0+0 (2934182569 0 0) 0x7fd4c80008c0 con 0x1263480
2014-09-26 21:20:00.136282 7fd4de4ed700 1 -- 10.13.128.45:0/1028228 -->
10.13.128.46:6789/0 -- mon_subscribe({monmap=0+}) v2 -- ?+0 0x1263b10
con 0x1263480
2014-09-26 21:20:00.136520 7fd4dfdc1760 1 -- 10.13.128.45:0/1028228 -->
10.13.128.46:6789/0 -- mon_subscribe({monmap=2+,osdmap=0}) v2 -- ?+0
0x1260bd0 con 0x1263480
2014-09-26 21:20:00.136541 7fd4dfdc1760 1 -- 10.13.128.45:0/1028228 -->
10.13.128.46:6789/0 -- mon_subscribe({monmap=2+,osdmap=0}) v2 -- ?+0
0x1265250 con 0x1263480
2014-09-26 21:20:00.136665 7fd4de4ed700 1 -- 10.13.128.45:0/1028228 <==
mon.1 10.13.128.46:6789/0 5 ==== mon_map v1 ==== 491+0+0 (1094526759 0
0) 0x7fd4c8001300 con 0x1263480
2014-09-26 21:20:00.136755 7fd4de4ed700 1 -- 10.13.128.45:0/1028228 <==
mon.1 10.13.128.46:6789/0 6 ==== mon_subscribe_ack(300s) v1 ==== 20+0+0
(2055130399 0 0) 0x7fd4c80015a0 con 0x1263480
2014-09-26 21:20:00.138572 7fd4de4ed700 1 -- 10.13.128.45:0/1028228 <==
mon.1 10.13.128.46:6789/0 7 ==== osd_map(1200..1200 src has 595..1200)
v3 ==== 31641+0+0 (4256497560 0 0) 0x7fd4c80008c0 con 0x1263480
2014-09-26 21:20:00.138924 7fd4de4ed700 1 -- 10.13.128.45:0/1028228 <==
mon.1 10.13.128.46:6789/0 8 ==== mon_subscribe_ack(300s) v1 ==== 20+0+0
(2055130399 0 0) 0x7fd4c8008fc0 con 0x1263480
2014-09-26 21:20:00.138956 7fd4dfdc1760 20 librbd: open_image: ictx =
0x1265800 name = 'bar' id = '' snap_name = ''
2014-09-26 21:20:00.139215 7fd4dfdc1760 1 -- 10.13.128.45:0/1028228 -->
10.13.128.51:6800/21932 -- osd_op(client.91831.0:1 bar.rbd [stat]
11.9f0efccd ack+read e1200) v4 -- ?+0 0x1266f10 con 0x1266bd0
2014-09-26 21:20:00.139977 7fd4de4ed700 1 -- 10.13.128.45:0/1028228 <==
mon.1 10.13.128.46:6789/0 9 ==== osd_map(1200..1200 src has 595..1200)
v3 ==== 31641+0+0 (4256497560 0 0) 0x7fd4c80008c0 con 0x1263480
2014-09-26 21:20:00.140025 7fd4de4ed700 1 -- 10.13.128.45:0/1028228 <==
mon.1 10.13.128.46:6789/0 10 ==== mon_subscribe_ack(300s) v1 ==== 20+0+0
(2055130399 0 0) 0x7fd4c8008fc0 con 0x1263480
2014-09-26 21:20:00.142412 7fd4de4ed700 1 -- 10.13.128.45:0/1028228 <==
osd.30 10.13.128.51:6800/21932 1 ==== osd_op_reply(1 bar.rbd [stat] v0'0
uv0 ack = -2 ((2) No such file or directory)) v6 ==== 174+0+0
(2354095215 0 0) 0x7fd4c4000aa0 con 0x1266bd0
2014-09-26 21:20:00.142690 7fd4dfdc1760 1 -- 10.13.128.45:0/1028228 -->
10.13.128.51:6810/13099 -- osd_op(client.91831.0:2 rbd_id.bar [stat]
11.d806c422 ack+read e1200) v4 -- ?+0 0x12676d0 con 0x1267390
2014-09-26 21:20:00.145636 7fd4de4ed700 1 -- 10.13.128.45:0/1028228 <==
osd.32 10.13.128.51:6810/13099 1 ==== osd_op_reply(2 rbd_id.bar [stat]
v0'0 uv2 ondisk = 0) v6 ==== 177+0+16 (289178973 0 1585620851)
0x7fd4bc000c10 con 0x1267390
2014-09-26 21:20:00.145747 7fd4dfdc1760 20 librbd: detect format of bar
: new
2014-09-26 21:20:00.145809 7fd4dfdc1760 1 -- 10.13.128.45:0/1028228 -->
10.13.128.51:6810/13099 -- osd_op(client.91831.0:3 rbd_id.bar [call
rbd.get_id] 11.d806c422 ack+read e1200) v4 -- ?+0 0x12676d0 con 0x1267390
2014-09-26 21:20:00.147081 7fd4de4ed700 1 -- 10.13.128.45:0/1028228 <==
osd.32 10.13.128.51:6810/13099 2 ==== osd_op_reply(3 rbd_id.bar [call]
v0'0 uv2 ondisk = 0) v6 ==== 177+0+17 (1211169836 0 3102563289)
0x7fd4bc000c10 con 0x1267390
2014-09-26 21:20:00.147377 7fd4dfdc1760 1 -- 10.13.128.45:0/1028228 -->
10.13.128.47:6800/643 -- osd_op(client.91831.0:4
rbd_header.1664a2ae8944a [call rbd.get_size,call rbd.get_object_prefix]
11.8f23562d ack+read e1200) v4 -- ?+0 0x12682c0 con 0x1268050
2014-09-26 21:20:00.150364 7fd4de4ed700 1 -- 10.13.128.45:0/1028228 <==
osd.11 10.13.128.47:6800/643 1 ==== osd_op_reply(4
rbd_header.1664a2ae8944a [call,call] v0'0 uv6 ondisk = 0) v6 ====
233+0+35 (3906836549 0 2759334685) 0x7fd4b4000c60 con 0x1268050
2014-09-26 21:20:00.150525 7fd4dfdc1760 1 -- 10.13.128.45:0/1028228 -->
10.13.128.47:6800/643 -- osd_op(client.91831.0:5
rbd_header.1664a2ae8944a [call rbd.get_stripe_unit_count] 11.8f23562d
ack+read e1200) v4 -- ?+0 0x12682c0 con 0x1268050
2014-09-26 21:20:00.151767 7fd4de4ed700 1 -- 10.13.128.45:0/1028228 <==
osd.11 10.13.128.47:6800/643 2 ==== osd_op_reply(5
rbd_header.1664a2ae8944a [call] v0'0 uv0 ondisk = -8 ((8) Exec format
error)) v6 ==== 191+0+0 (566057441 0 0) 0x7fd4b4000c60 con 0x1268050
2014-09-26 21:20:00.151885 7fd4dfdc1760 10 librbd::ImageCtx: init_layout
stripe_unit 4194304 stripe_count 1 object_size 4194304 prefix
rbd_data.1664a2ae8944a format rbd_data.1664a2ae8944a.%016llx
2014-09-26 21:20:00.151974 7fd4dfdc1760 1 -- 10.13.128.45:0/1028228 -->
10.13.128.47:6800/643 -- osd_op(client.91831.0:6
rbd_header.1664a2ae8944a [watch add cookie 1 ver 0] 11.8f23562d
ondisk+read+write e1200) v4 -- ?+0 0x1268b50 con 0x1268050
2014-09-26 21:20:00.169129 7fd4de4ed700 1 -- 10.13.128.45:0/1028228 <==
osd.11 10.13.128.47:6800/643 3 ==== osd_op_reply(6
rbd_header.1664a2ae8944a [watch add cookie 1 ver 0] v1200'8 uv6 ondisk =
0) v6 ==== 191+0+0 (3744227722 0 0) 0x7fd4b4000c60 con 0x1268050
2014-09-26 21:20:00.169240 7fd4dfdc1760 20 librbd: ictx_refresh 0x1265800
2014-09-26 21:20:00.169358 7fd4dfdc1760 1 -- 10.13.128.45:0/1028228 -->
10.13.128.47:6800/643 -- osd_op(client.91831.0:7
rbd_header.1664a2ae8944a [call rbd.get_size,call rbd.get_features,call
rbd.get_snapcontext,call rbd.get_parent,call lock.get_info] 11.8f23562d
ack+read e1200) v4 -- ?+0 0x12690d0 con 0x1268050
2014-09-26 21:20:00.171193 7fd4de4ed700 1 -- 10.13.128.45:0/1028228 <==
osd.11 10.13.128.47:6800/643 4 ==== osd_op_reply(7
rbd_header.1664a2ae8944a [call,call,call,call,call] v0'0 uv6 ondisk = 0)
v6 ==== 359+0+88 (4262803064 0 1395738668) 0x7fd4b4001140 con 0x1268050
2014-09-26 21:20:00.171404 7fd4dfdc1760 1 -- 10.13.128.45:0/1028228 -->
10.13.128.47:6800/643 -- osd_op(client.91831.0:8
rbd_header.1664a2ae8944a [call rbd.get_snapshot_name,call
rbd.get_size,call rbd.get_features,call rbd.get_parent,call
rbd.get_protection_status] 11.8f23562d ack+read e1200) v4 -- ?+0
0x126e100 con 0x1268050
2014-09-26 21:20:00.173220 7fd4de4ed700 1 -- 10.13.128.45:0/1028228 <==
osd.11 10.13.128.47:6800/643 5 ==== osd_op_reply(8
rbd_header.1664a2ae8944a [call,call,call,call,call] v0'0 uv6 ondisk = 0)
v6 ==== 359+0+66 (1166385789 0 3759898564) 0x7fd4b4001020 con 0x1268050
2014-09-26 21:20:00.173351 7fd4dfdc1760 20 librbd: new snapshot id=2
name=bar_snap size=1073741824 features=1
2014-09-26 21:20:00.173384 7fd4dfdc1760 20 librbd: snap_unprotect
0x1265800 bar_snap
2014-09-26 21:20:00.173391 7fd4dfdc1760 20 librbd: ictx_check 0x1265800
2014-09-26 21:20:00.173436 7fd4dfdc1760 1 -- 10.13.128.45:0/1028228 -->
10.13.128.47:6800/643 -- osd_op(client.91831.0:9
rbd_header.1664a2ae8944a [call rbd.set_protection_status] 11.8f23562d
ack+read e1200) v4 -- ?+0 0x1268ad0 con 0x1268050
2014-09-26 21:20:00.180347 7fd4de4ed700 1 -- 10.13.128.45:0/1028228 <==
osd.11 10.13.128.47:6800/643 6 ==== osd_op_reply(9
rbd_header.1664a2ae8944a [call] v1200'9 uv9 ack = 0) v6 ==== 191+0+0
(485243021 0 0) 0x7fd4b4001020 con 0x1268050
2014-09-26 21:20:00.180464 7fd4dfdc1760 20 librbd: notify_change
refresh_seq = 0 last_refresh = 0
2014-09-26 21:20:00.180546 7fd4dfdc1760 1 -- 10.13.128.45:0/1028228 -->
10.13.128.47:6800/643 -- osd_op(client.91831.0:10
rbd_header.1664a2ae8944a [notify 2~9] 11.8f23562d ondisk+read e1200) v4
-- ?+0 0x12697b0 con 0x1268050
2014-09-26 21:20:00.181569 7fd4de4ed700 1 -- 10.13.128.45:0/1028228 <==
osd.11 10.13.128.47:6800/643 7 ==== watch-notify(c=1 v=9 i=5153960755210
opcode=1) v1 ==== 30+0+0 (1020493109 0 0) 0x7fd4b4001780 con 0x1268050
2014-09-26 21:20:00.181616 7fd4de4ed700 1 -- 10.13.128.45:0/1028228 <==
osd.11 10.13.128.47:6800/643 8 ==== osd_op_reply(10
rbd_header.1664a2ae8944a [notify 2~9] v0'0 uv9 ondisk = 0) v6 ====
191+0+0 (1737907521 0 0) 0x7fd4b4001990 con 0x1268050
2014-09-26 21:20:00.181684 7fd4d6bfd700 1 librbd::WatchCtx: got
notification opcode=1 ver=9 cookie=1
2014-09-26 21:20:00.181976 7fd4d6bfd700 1 -- 10.13.128.45:0/1028228 -->
10.13.128.47:6800/643 -- osd_op(client.91831.0:11
rbd_header.1664a2ae8944a [notify-ack 5153960755210~9] 11.8f23562d read
e1200) v4 -- ?+0 0x7fd4a8002010 con 0x1268050
2014-09-26 21:20:00.183026 7fd4de4ed700 1 -- 10.13.128.45:0/1028228 <==
osd.11 10.13.128.47:6800/643 9 ==== watch-notify(c=2 v=9 i=5153960755210
opcode=1) v1 ==== 30+0+0 (3741423256 0 0) 0x7fd4b4001c50 con 0x1268050
2014-09-26 21:20:00.183064 7fd4de4ed700 1 -- 10.13.128.45:0/1028228 <==
osd.11 10.13.128.47:6800/643 10 ==== osd_op_reply(11
rbd_header.1664a2ae8944a [notify-ack 5153960755210~9] v0'0 uv9 ondisk =
0) v6 ==== 191+0+0 (4152747383 0 0) 0x7fd4b4000920 con 0x1268050
2014-09-26 21:20:00.183194 7fd4d6bfd700 1 -- 10.13.128.45:0/1028228 -->
10.13.128.47:6800/643 -- osd_op(client.91831.0:12
rbd_header.1664a2ae8944a [notify-ack 5153960755210~9] 11.8f23562d read
e1200) v4 -- ?+0 0x7fd4a80028d0 con 0x1268050
2014-09-26 21:20:00.183336 7fd4dfdc1760 1 -- 10.13.128.45:0/1028228 -->
10.13.128.46:6789/0 -- mon_subscribe({monmap=2+,osdmap=1201}) v2 -- ?+0
0x1269350 con 0x1263480
2014-09-26 21:20:00.183948 7fd4de4ed700 1 -- 10.13.128.45:0/1028228 <==
mon.1 10.13.128.46:6789/0 11 ==== mon_subscribe_ack(300s) v1 ==== 20+0+0
(2055130399 0 0) 0x7fd4c8008f80 con 0x1263480
2014-09-26 21:20:00.184207 7fd4de4ed700 1 -- 10.13.128.45:0/1028228 <==
osd.11 10.13.128.47:6800/643 11 ==== osd_op_reply(12
rbd_header.1664a2ae8944a [notify-ack 5153960755210~9] v0'0 uv9 ondisk =
0) v6 ==== 191+0+0 (4152747383 0 0) 0x7fd4b4000920 con 0x1268050
2014-09-26 21:20:05.136757 7fd4d75fe700 1 -- 10.13.128.45:0/1028228 -->
10.13.128.47:6800/643 -- ping v1 -- ?+0 0x7fd4a0000920 con 0x1268050
2014-09-26 21:20:10.136960 7fd4d75fe700 1 -- 10.13.128.45:0/1028228 -->
10.13.128.47:6800/643 -- ping v1 -- ?+0 0x7fd4a0000920 con 0x1268050
2014-09-26 21:20:15.137154 7fd4d75fe700 1 -- 10.13.128.45:0/1028228 -->
10.13.128.47:6800/643 -- ping v1 -- ?+0 0x7fd4a0000920 con 0x1268050
2014-09-26 21:20:20.137400 7fd4d75fe700 1 -- 10.13.128.45:0/1028228 -->
10.13.128.47:6800/643 -- ping v1 -- ?+0 0x7fd4a0000920 con 0x1268050
2014-09-26 21:20:25.137574 7fd4d75fe700 1 -- 10.13.128.45:0/1028228 -->
10.13.128.47:6800/643 -- ping v1 -- ?+0 0x7fd4a0000920 con 0x1268050
2014-09-26 21:20:30.137787 7fd4d75fe700 1 -- 10.13.128.45:0/1028228 -->
10.13.128.47:6800/643 -- ping v1 -- ?+0 0x7fd4a0000920 con 0x1268050
2014-09-26 21:20:35.137998 7fd4d75fe700 1 -- 10.13.128.45:0/1028228 -->
10.13.128.47:6800/643 -- ping v1 -- ?+0 0x7fd4a0000920 con 0x1268050
2014-09-26 21:20:40.138191 7fd4d75fe700 1 -- 10.13.128.45:0/1028228 -->
10.13.128.47:6800/643 -- ping v1 -- ?+0 0x7fd4a0000920 con 0x1268050
2014-09-26 21:20:45.138406 7fd4d75fe700 1 -- 10.13.128.45:0/1028228 -->
10.13.128.47:6800/643 -- ping v1 -- ?+0 0x7fd4a0000920 con 0x1268050
2014-09-26 21:20:50.138613 7fd4d75fe700 1 -- 10.13.128.45:0/1028228 -->
10.13.128.47:6800/643 -- ping v1 -- ?+0 0x7fd4a0000920 con 0x1268050
2014-09-26 21:20:55.138816 7fd4d75fe700 1 -- 10.13.128.45:0/1028228 -->
10.13.128.47:6800/643 -- ping v1 -- ?+0 0x7fd4a0000920 con 0x1268050
2014-09-26 21:21:00.138959 7fd4d75fe700 1 -- 10.13.128.45:0/1028228 -->
10.13.128.47:6800/643 -- ping v1 -- ?+0 0x7fd4a0000920 con 0x1268050
2014-09-26 21:21:05.139158 7fd4d75fe700 1 -- 10.13.128.45:0/1028228 -->
10.13.128.47:6800/643 -- ping v1 -- ?+0 0x7fd4a0000920 con 0x1268050
2014-09-26 21:21:10.139383 7fd4d75fe700 1 -- 10.13.128.45:0/1028228 -->
10.13.128.47:6800/643 -- ping v1 -- ?+0 0x7fd4a0000920 con 0x1268050
2014-09-26 21:21:15.139556 7fd4d75fe700 1 -- 10.13.128.45:0/1028228 -->
10.13.128.47:6800/643 -- ping v1 -- ?+0 0x7fd4a0000920 con 0x1268050
2014-09-26 21:21:20.139731 7fd4d75fe700 1 -- 10.13.128.45:0/1028228 -->
10.13.128.47:6800/643 -- ping v1 -- ?+0 0x7fd4a0000920 con 0x1268050
2014-09-26 21:21:25.139931 7fd4d75fe700 1 -- 10.13.128.45:0/1028228 -->
10.13.128.47:6800/643 -- ping v1 -- ?+0 0x7fd4a0000920 con 0x1268050
2014-09-26 21:21:30.140135 7fd4d75fe700 1 -- 10.13.128.45:0/1028228 -->
10.13.128.47:6800/643 -- ping v1 -- ?+0 0x7fd4a0000920 con 0x1268050
2014-09-26 21:21:35.140307 7fd4d75fe700 1 -- 10.13.128.45:0/1028228 -->
10.13.128.47:6800/643 -- ping v1 -- ?+0 0x7fd4a0000920 con 0x1268050
2014-09-26 21:21:40.140477 7fd4d75fe700 1 -- 10.13.128.45:0/1028228 -->
10.13.128.47:6800/643 -- ping v1 -- ?+0 0x7fd4a0000920 con 0x1268050
2014-09-26 21:21:45.140685 7fd4d75fe700 1 -- 10.13.128.45:0/1028228 -->
10.13.128.47:6800/643 -- ping v1 -- ?+0 0x7fd4a0000920 con 0x1268050
2014-09-26 21:21:50.140851 7fd4d75fe700 1 -- 10.13.128.45:0/1028228 -->
10.13.128.47:6800/643 -- ping v1 -- ?+0 0x7fd4a0000920 con 0x1268050
^C
here is ceph info:
[root at n128045 ~]# ceph -w
cluster 65f229c3-fe3c-4acc-b437-6e1b4545883b
health HEALTH_WARN clock skew detected on mon.n128046, mon.n128047
monmap e1: 3 mons at
{n128045=10.13.128.45:6789/0,n128046=10.13.128.46:6789/0,n128047=10.13.128.47:6789/0},
election epoch 48, quorum 0,1,2 n128045,n128046,n128047
osdmap e1200: 29 osds: 29 up, 29 in
pgmap v15045: 1280 pgs, 1 pools, 17 bytes data, 3 objects
3273 MB used, 8026 GB / 8029 GB avail
1280 active+clean
Thanks
