Project

General

Profile

Bug #16360 » ls-l.log

rbd ls -l --debug-rbd=20 --debug-ms=1 - Alexandre Becholey, 06/17/2016 10:35 AM

 
# rbd ls libvirt --debug-rbd=20 --debug-ms=1
2016-06-17 11:38:39.851600 7fe28d8c6100 -1 WARNING: the following dangerous and experimental features are enabled: *
2016-06-17 11:38:39.851639 7fe28d8c6100 -1 WARNING: the following dangerous and experimental features are enabled: *
2016-06-17 11:38:39.853068 7fe28d8c6100 -1 WARNING: the following dangerous and experimental features are enabled: *
2016-06-17 11:38:39.853284 7fe28d8c6100 1 -- :/0 messenger.start
2016-06-17 11:38:39.853890 7fe28d8c6100 1 -- :/105872105 --> 172.16.1.20:6789/0 -- auth(proto 0 30 bytes epoch 0) v1 -- ?+0 0x556c0a1771c0 con 0x556c0a1763c0
2016-06-17 11:38:39.854967 7fe28d8b9700 1 -- 172.16.1.10:0/105872105 learned my addr 172.16.1.10:0/105872105
2016-06-17 11:38:39.856079 7fe272762700 1 -- 172.16.1.10:0/105872105 <== mon.1 172.16.1.20:6789/0 1 ==== mon_map magic: 0 v1 ==== 642+0+0 (1731561352 0 0) 0x7fe25c000c20 con 0x556c0a1763c0
2016-06-17 11:38:39.856165 7fe272762700 1 -- 172.16.1.10:0/105872105 <== mon.1 172.16.1.20:6789/0 2 ==== auth_reply(proto 2 0 (0) Success) v1 ==== 33+0+0 (1833081922 0 0) 0x7fe25c001110 con 0x556c0a1763c0
2016-06-17 11:38:39.856287 7fe272762700 1 -- 172.16.1.10:0/105872105 --> 172.16.1.20:6789/0 -- auth(proto 2 32 bytes epoch 0) v1 -- ?+0 0x7fe2600019b0 con 0x556c0a1763c0
2016-06-17 11:38:39.857215 7fe272762700 1 -- 172.16.1.10:0/105872105 <== mon.1 172.16.1.20:6789/0 3 ==== auth_reply(proto 2 0 (0) Success) v1 ==== 206+0+0 (3254212194 0 0) 0x7fe25c001110 con 0x556c0a1763c0
2016-06-17 11:38:39.857345 7fe272762700 1 -- 172.16.1.10:0/105872105 --> 172.16.1.20:6789/0 -- auth(proto 2 165 bytes epoch 0) v1 -- ?+0 0x7fe260001dd0 con 0x556c0a1763c0
2016-06-17 11:38:39.858237 7fe272762700 1 -- 172.16.1.10:0/105872105 <== mon.1 172.16.1.20:6789/0 4 ==== auth_reply(proto 2 0 (0) Success) v1 ==== 393+0+0 (1390221179 0 0) 0x7fe25c0008c0 con 0x556c0a1763c0
2016-06-17 11:38:39.858341 7fe272762700 1 -- 172.16.1.10:0/105872105 --> 172.16.1.20:6789/0 -- mon_subscribe({monmap=0+}) v2 -- ?+0 0x556c0a17b080 con 0x556c0a1763c0
2016-06-17 11:38:39.858513 7fe28d8c6100 1 -- 172.16.1.10:0/105872105 --> 172.16.1.20:6789/0 -- mon_subscribe({osdmap=0}) v2 -- ?+0 0x556c0a16eda0 con 0x556c0a1763c0
2016-06-17 11:38:39.858882 7fe272762700 1 -- 172.16.1.10:0/105872105 <== mon.1 172.16.1.20:6789/0 5 ==== mon_map magic: 0 v1 ==== 642+0+0 (1731561352 0 0) 0x7fe25c001460 con 0x556c0a1763c0
2016-06-17 11:38:39.859165 7fe272762700 1 -- 172.16.1.10:0/105872105 <== mon.1 172.16.1.20:6789/0 6 ==== osd_map(645..645 src has 1..645) v3 ==== 25017+0+0 (3930215128 0 0) 0x7fe25c000930 con 0x556c0a1763c0
2016-06-17 11:38:39.859486 7fe28d8c6100 20 librbd: list 0x7ffe821576c0
2016-06-17 11:38:39.859596 7fe28d8c6100 1 -- 172.16.1.10:0/105872105 --> 172.16.1.22:6808/15894 -- osd_op(client.82209.0:1 4.30a98c1c rbd_directory [read 0~0] snapc 0=[] ack+read+known_if_redirected e645) v7 -- ?+0 0x556c0a17dec0 con 0x556c0a17b110
2016-06-17 11:38:39.861528 7fe27055c700 1 -- 172.16.1.10:0/105872105 <== osd.28 172.16.1.22:6808/15894 1 ==== osd_op_reply(1 rbd_directory [read 0~0] v0'0 uv31 ondisk = 0) v7 ==== 133+0+0 (2767825306 0 0) 0x7fe258000a20 con 0x556c0a17b110
2016-06-17 11:38:39.861660 7fe28d8c6100 20 librbd: list_images_v2 0x7ffe821576c0
2016-06-17 11:38:39.861715 7fe28d8c6100 1 -- 172.16.1.10:0/105872105 --> 172.16.1.22:6808/15894 -- osd_op(client.82209.0:2 4.30a98c1c rbd_directory [call rbd.dir_list] snapc 0=[] ack+read+known_if_redirected e645) v7 -- ?+0 0x556c0a180450 con 0x556c0a17b110
2016-06-17 11:38:39.862816 7fe27055c700 1 -- 172.16.1.10:0/105872105 <== osd.28 172.16.1.22:6808/15894 2 ==== osd_op_reply(2 rbd_directory [call] v0'0 uv31 ondisk = 0) v7 ==== 133+0+189 (3514050152 0 1645138281) 0x7fe258000a20 con 0x556c0a17b110
2016-06-17 11:38:39.863064 7fe28d8c6100 5 librbd::AioImageRequestWQ: 0x556c0a17fa90 : ictx=0x556c0a17e5c0
2016-06-17 11:38:39.863077 7fe28d8c6100 20 librbd::ImageState: open
2016-06-17 11:38:39.863080 7fe28d8c6100 10 librbd::ImageState: 0x556c0a17ab50 send_open_unlock
2016-06-17 11:38:39.863083 7fe28d8c6100 10 librbd::image::OpenRequest: 0x556c0a1801c0 send_v2_detect_header
2016-06-17 11:38:39.863182 7fe28d8c6100 1 -- 172.16.1.10:0/105872105 --> 172.16.1.22:6820/20336 -- osd_op(client.82209.0:3 4.b91b7eda rbd_id._IMG_debian-8.5.0-openstack-amd64 [stat] snapc 0=[] ack+read+known_if_redirected e645) v7 -- ?+0 0x556c0a183a00 con 0x556c0a182610
2016-06-17 11:38:39.865029 7fe27035a700 1 -- 172.16.1.10:0/105872105 <== osd.34 172.16.1.22:6820/20336 1 ==== osd_op_reply(3 rbd_id._IMG_debian-8.5.0-openstack-amd64 [stat] v0'0 uv3 ondisk = 0) v7 ==== 160+0+16 (1844848111 0 895722328) 0x7fe244000b60 con 0x556c0a182610
2016-06-17 11:38:39.865094 7fe26affd700 10 librbd::image::OpenRequest: handle_v2_detect_header: r=0
2016-06-17 11:38:39.865103 7fe26affd700 10 librbd::image::OpenRequest: 0x556c0a1801c0 send_v2_get_id
2016-06-17 11:38:39.865150 7fe26affd700 1 -- 172.16.1.10:0/105872105 --> 172.16.1.22:6820/20336 -- osd_op(client.82209.0:4 4.b91b7eda rbd_id._IMG_debian-8.5.0-openstack-amd64 [call rbd.get_id] snapc 0=[] ack+read+known_if_redirected e645) v7 -- ?+0 0x7fe248002390 con 0x556c0a182610
2016-06-17 11:38:39.873625 7fe27035a700 1 -- 172.16.1.10:0/105872105 <== osd.34 172.16.1.22:6820/20336 2 ==== osd_op_reply(4 rbd_id._IMG_debian-8.5.0-openstack-amd64 [call] v0'0 uv3 ondisk = 0) v7 ==== 160+0+16 (1933166910 0 2740784517) 0x7fe244000b60 con 0x556c0a182610
2016-06-17 11:38:39.873698 7fe26affd700 10 librbd::image::OpenRequest: handle_v2_get_id: r=0
2016-06-17 11:38:39.873717 7fe26affd700 10 librbd::image::OpenRequest: 0x556c0a1801c0 send_v2_get_immutable_metadata
2016-06-17 11:38:39.873836 7fe26affd700 1 -- 172.16.1.10:0/105872105 --> 172.16.1.22:6802/13633 -- osd_op(client.82209.0:5 4.6a9a52e5 rbd_header.2d29238e1f29 [call rbd.get_size,call rbd.get_object_prefix] snapc 0=[] ack+read+known_if_redirected e645) v7 -- ?+0 0x7fe248007970 con 0x7fe248006580
2016-06-17 11:38:39.875812 7fe270158700 1 -- 172.16.1.10:0/105872105 <== osd.25 172.16.1.22:6802/13633 1 ==== osd_op_reply(5 rbd_header.2d29238e1f29 [call,call] v0'0 uv34 ondisk = 0) v7 ==== 185+0+34 (1115188448 0 1439672863) 0x7fe240000b90 con 0x7fe248006580
2016-06-17 11:38:39.875900 7fe26affd700 10 librbd::image::OpenRequest: handle_v2_get_immutable_metadata: r=0
2016-06-17 11:38:39.875922 7fe26affd700 10 librbd::image::OpenRequest: 0x556c0a1801c0 send_v2_get_stripe_unit_count
2016-06-17 11:38:39.875960 7fe26affd700 1 -- 172.16.1.10:0/105872105 --> 172.16.1.22:6802/13633 -- osd_op(client.82209.0:6 4.6a9a52e5 rbd_header.2d29238e1f29 [call rbd.get_stripe_unit_count] snapc 0=[] ack+read+known_if_redirected e645) v7 -- ?+0 0x7fe248002aa0 con 0x7fe248006580
2016-06-17 11:38:39.876874 7fe270158700 1 -- 172.16.1.10:0/105872105 <== osd.25 172.16.1.22:6802/13633 2 ==== osd_op_reply(6 rbd_header.2d29238e1f29 [call] v0'0 uv0 ondisk = -8 ((8) Exec format error)) v7 ==== 143+0+0 (2588767768 0 0) 0x7fe240000b90 con 0x7fe248006580
2016-06-17 11:38:39.876942 7fe26affd700 10 librbd::image::OpenRequest: handle_v2_get_stripe_unit_count: r=-8
2016-06-17 11:38:39.876958 7fe26affd700 10 librbd::ImageCtx: init_layout stripe_unit 4194304 stripe_count 1 object_size 4194304 prefix rbd_data.2d29238e1f29 format rbd_data.2d29238e1f29.%016llx
2016-06-17 11:38:39.876966 7fe26affd700 10 librbd::image::OpenRequest: 0x556c0a1801c0 send_v2_apply_metadata: start_key=conf_
2016-06-17 11:38:39.877003 7fe26affd700 1 -- 172.16.1.10:0/105872105 --> 172.16.1.22:6802/13633 -- osd_op(client.82209.0:7 4.6a9a52e5 rbd_header.2d29238e1f29 [call rbd.metadata_list] snapc 0=[] ack+read+known_if_redirected e645) v7 -- ?+0 0x7fe2480044a0 con 0x7fe248006580
2016-06-17 11:38:39.877761 7fe270158700 1 -- 172.16.1.10:0/105872105 <== osd.25 172.16.1.22:6802/13633 3 ==== osd_op_reply(7 rbd_header.2d29238e1f29 [call] v0'0 uv34 ondisk = 0) v7 ==== 143+0+4 (1943930712 0 0) 0x7fe240000b90 con 0x7fe248006580
2016-06-17 11:38:39.877827 7fe26affd700 10 librbd::image::OpenRequest: 0x556c0a1801c0 handle_v2_apply_metadata: r=0
2016-06-17 11:38:39.877848 7fe26affd700 20 librbd::ImageCtx: apply_metadata
2016-06-17 11:38:39.877992 7fe26affd700 20 librbd::ImageCtx: enabling caching...
2016-06-17 11:38:39.877994 7fe26affd700 20 librbd::ImageCtx: Initial cache settings: size=33554432 num_objects=10 max_dirty=25165824 target_dirty=16777216 max_dirty_age=1
2016-06-17 11:38:39.878079 7fe26affd700 10 librbd::ImageCtx: cache bytes 33554432 -> about 855 objects
2016-06-17 11:38:39.878146 7fe26affd700 10 librbd::image::OpenRequest: 0x556c0a1801c0 send_refresh
2016-06-17 11:38:39.878151 7fe26affd700 10 librbd::image::RefreshRequest: 0x7fe248001400 send_v2_get_mutable_metadata
2016-06-17 11:38:39.878229 7fe26affd700 1 -- 172.16.1.10:0/105872105 --> 172.16.1.22:6802/13633 -- osd_op(client.82209.0:8 4.6a9a52e5 rbd_header.2d29238e1f29 [call rbd.get_size,call rbd.get_features,call rbd.get_snapcontext,call rbd.get_parent,call lock.get_info] snapc 0=[] ack+read+known_if_redirected e645) v7 -- ?+0 0x7fe248011ea0 con 0x7fe248006580
2016-06-17 11:38:39.879307 7fe270158700 1 -- 172.16.1.10:0/105872105 <== osd.25 172.16.1.22:6802/13633 4 ==== osd_op_reply(8 rbd_header.2d29238e1f29 [call,call,call,call,call] v0'0 uv34 ondisk = 0) v7 ==== 311+0+96 (2158334193 0 2035280116) 0x7fe2400017e0 con 0x7fe248006580
2016-06-17 11:38:39.879365 7fe26affd700 10 librbd::image::RefreshRequest: 0x7fe248001400 handle_v2_get_mutable_metadata: r=0
2016-06-17 11:38:39.879381 7fe26affd700 10 librbd::image::RefreshRequest: 0x7fe248001400 send_v2_get_flags
2016-06-17 11:38:39.879425 7fe26affd700 1 -- 172.16.1.10:0/105872105 --> 172.16.1.22:6802/13633 -- osd_op(client.82209.0:9 4.6a9a52e5 rbd_header.2d29238e1f29 [call rbd.get_flags,call rbd.get_flags] snapc 0=[] ack+read+known_if_redirected e645) v7 -- ?+0 0x7fe24800ba00 con 0x7fe248006580
2016-06-17 11:38:39.880261 7fe270158700 1 -- 172.16.1.10:0/105872105 <== osd.25 172.16.1.22:6802/13633 5 ==== osd_op_reply(9 rbd_header.2d29238e1f29 [call,call] v0'0 uv34 ondisk = 0) v7 ==== 185+0+16 (3007966748 0 0) 0x7fe2400017e0 con 0x7fe248006580
2016-06-17 11:38:39.880325 7fe26affd700 10 librbd::image::RefreshRequest: 0x7fe248001400 handle_v2_get_flags: r=0
2016-06-17 11:38:39.880336 7fe26affd700 10 librbd::image::RefreshRequest: 0x7fe248001400 send_v2_get_snapshots
2016-06-17 11:38:39.880390 7fe26affd700 1 -- 172.16.1.10:0/105872105 --> 172.16.1.22:6802/13633 -- osd_op(client.82209.0:10 4.6a9a52e5 rbd_header.2d29238e1f29 [call rbd.get_snapshot_name,call rbd.get_size,call rbd.get_parent,call rbd.get_protection_status] snapc 0=[] ack+read+known_if_redirected e645) v7 -- ?+0 0x7fe24800be10 con 0x7fe248006580
2016-06-17 11:38:39.881399 7fe270158700 1 -- 172.16.1.10:0/105872105 <== osd.25 172.16.1.22:6802/13633 6 ==== osd_op_reply(10 rbd_header.2d29238e1f29 [call,call,call,call] v0'0 uv34 ondisk = 0) v7 ==== 269+0+46 (4152350397 0 3779758260) 0x7fe2400017e0 con 0x7fe248006580
2016-06-17 11:38:39.881464 7fe26affd700 10 librbd::image::RefreshRequest: 0x7fe248001400 handle_v2_get_snapshots: r=0
2016-06-17 11:38:39.881480 7fe26affd700 10 librbd::image::RefreshRequest: 0x7fe248001400 send_v2_apply
2016-06-17 11:38:39.881569 7fe26a7fc700 10 librbd::image::RefreshRequest: 0x7fe248001400 handle_v2_apply
2016-06-17 11:38:39.881582 7fe26a7fc700 20 librbd::image::RefreshRequest: 0x7fe248001400 apply
2016-06-17 11:38:39.881587 7fe26a7fc700 20 librbd::image::RefreshRequest: new snapshot id=10 name=snap size=2147483648
2016-06-17 11:38:39.881604 7fe26a7fc700 10 librbd::image::RefreshRequest: 0x7fe248001400 send_flush_aio
2016-06-17 11:38:39.881612 7fe26a7fc700 10 librbd::image::RefreshRequest: 0x7fe248001400 handle_flush_aio: r=0
2016-06-17 11:38:39.881618 7fe26a7fc700 10 librbd::image::OpenRequest: handle_refresh: r=0
2016-06-17 11:38:39.881622 7fe26a7fc700 10 librbd::ImageState: 0x556c0a17ab50 handle_open: r=0
2016-06-17 11:38:39.881682 7fe28d8c6100 20 librbd: info 0x556c0a17e5c0
2016-06-17 11:38:39.881696 7fe28d8c6100 20 librbd: list_locks on image 0x556c0a17e5c0
2016-06-17 11:38:39.881718 7fe28d8c6100 20 librbd: snap_list 0x556c0a17e5c0
2016-06-17 11:38:39.881723 7fe28d8c6100 20 librbd: snap_set 0x556c0a17e5c0 snap = snap
2016-06-17 11:38:39.881726 7fe28d8c6100 20 librbd::ImageState: snap_set: snap_name=snap
2016-06-17 11:38:39.881728 7fe28d8c6100 10 librbd::ImageState: 0x556c0a17ab50 send_set_snap_unlock: snap_name=snap
2016-06-17 11:38:39.881731 7fe28d8c6100 10 librbd::image::SetSnapRequest: send_block_writes
2016-06-17 11:38:39.881733 7fe28d8c6100 5 librbd::AioImageRequestWQ: block_writes: 0x556c0a17e5c0, num=1
2016-06-17 11:38:39.881815 7fe26a7fc700 10 librbd::image::SetSnapRequest: handle_block_writes: r=0
2016-06-17 11:38:39.881828 7fe26a7fc700 10 librbd::image::SetSnapRequest: send_open_object_map
2016-06-17 11:38:39.881832 7fe26a7fc700 20 librbd::object_map::RefreshRequest: 0x7fe24c001730 send: object_count=512
2016-06-17 11:38:39.881840 7fe26a7fc700 10 librbd::object_map::RefreshRequest: 0x7fe24c001730 send_load: oid=rbd_object_map.2d29238e1f29.000000000000000a
2016-06-17 11:38:39.881948 7fe26a7fc700 1 -- 172.16.1.10:0/105872105 --> 172.16.1.20:6820/2885 -- osd_op(client.82209.0:11 4.1eb3e019 rbd_object_map.2d29238e1f29.000000000000000a [call rbd.object_map_load] snapc 0=[] ack+read+known_if_redirected e645) v7 -- ?+0 0x7fe24c0061d0 con 0x7fe24c004d40
2016-06-17 11:38:39.884260 7fe268ef8700 1 -- 172.16.1.10:0/105872105 <== osd.10 172.16.1.20:6820/2885 1 ==== osd_op_reply(11 rbd_object_map.2d29238e1f29.000000000000000a [call] v0'0 uv2 ondisk = 0) v7 ==== 164+0+150 (2450507090 0 1095513446) 0x7fe238000be0 con 0x7fe24c004d40
2016-06-17 11:38:39.884361 7fe26affd700 10 librbd::object_map::RefreshRequest: 0x7fe24c001730 handle_load: r=0
2016-06-17 11:38:39.884391 7fe26affd700 20 librbd::object_map::RefreshRequest: refreshed object map: num_objs=512
2016-06-17 11:38:39.884397 7fe26affd700 10 librbd::image::SetSnapRequest: handle_open_object_map: r=0
2016-06-17 11:38:39.884399 7fe26affd700 10 librbd::image::SetSnapRequest: apply
2016-06-17 11:38:39.884403 7fe26affd700 5 librbd::AioImageRequestWQ: unblock_writes: 0x556c0a17e5c0, num=0
2016-06-17 11:38:39.884493 7fe26a7fc700 10 librbd::ImageState: 0x556c0a17ab50 handle_set_snap r=0
2016-06-17 11:38:39.884563 7fe28d8c6100 20 librbd: snap_is_protected 0x556c0a17e5c0 snap
2016-06-17 11:38:39.884592 7fe28d8c6100 20 librbd::ImageState: close
2016-06-17 11:38:39.884595 7fe28d8c6100 10 librbd::ImageState: 0x556c0a17ab50 send_close_unlock
2016-06-17 11:38:39.884598 7fe28d8c6100 10 librbd::image::CloseRequest: 0x556c0a180180 send_shut_down_aio_queue
2016-06-17 11:38:39.884600 7fe28d8c6100 5 librbd::AioImageRequestWQ: shut_down: in_flight=0
2016-06-17 11:38:39.884683 7fe26a7fc700 10 librbd::image::CloseRequest: 0x556c0a180180 handle_shut_down_aio_queue: r=0
2016-06-17 11:38:39.884700 7fe26a7fc700 10 librbd::image::CloseRequest: 0x556c0a180180 send_flush
2016-06-17 11:38:39.884708 7fe26a7fc700 10 librbd::image::CloseRequest: 0x556c0a180180 handle_flush: r=0
2016-06-17 11:38:39.884710 7fe26a7fc700 10 librbd::image::CloseRequest: 0x556c0a180180 send_flush_readahead
2016-06-17 11:38:39.884712 7fe26a7fc700 10 librbd::image::CloseRequest: 0x556c0a180180 handle_flush_readahead: r=0
2016-06-17 11:38:39.884714 7fe26a7fc700 10 librbd::image::CloseRequest: 0x556c0a180180 send_shut_down_cache
2016-06-17 11:38:39.884846 7fe26a7fc700 10 librbd::image::CloseRequest: 0x556c0a180180 handle_shut_down_cache: r=0
2016-06-17 11:38:39.884856 7fe26a7fc700 10 librbd::image::CloseRequest: 0x556c0a180180 send_flush_op_work_queue
2016-06-17 11:38:39.884861 7fe26a7fc700 10 librbd::image::CloseRequest: 0x556c0a180180 handle_flush_op_work_queue: r=0
2016-06-17 11:38:39.884876 7fe26a7fc700 10 librbd::ImageState: 0x556c0a17ab50 handle_close: r=0
2016-06-17 11:38:39.885143 7fe28d8c6100 5 librbd::AioImageRequestWQ: 0x556c0a17e0a0 : ictx=0x556c0a17e5c0
2016-06-17 11:38:39.885155 7fe28d8c6100 20 librbd::ImageState: open
2016-06-17 11:38:39.885158 7fe28d8c6100 10 librbd::ImageState: 0x556c0a17ab50 send_open_unlock
2016-06-17 11:38:39.885160 7fe28d8c6100 10 librbd::image::OpenRequest: 0x556c0a17adb0 send_v2_detect_header
2016-06-17 11:38:39.885248 7fe28d8c6100 1 -- 172.16.1.10:0/105872105 --> 172.16.1.20:6822/3637 -- osd_op(client.82209.0:12 4.12036e7d rbd_id._IMG_trusty-server-cloudimg-amd64 [stat] snapc 0=[] ack+read+known_if_redirected e645) v7 -- ?+0 0x556c0a187eb0 con 0x556c0a186ac0
2016-06-17 11:38:39.887008 7fe268cf6700 1 -- 172.16.1.10:0/105872105 <== osd.11 172.16.1.20:6822/3637 1 ==== osd_op_reply(12 rbd_id._IMG_trusty-server-cloudimg-amd64 [stat] v0'0 uv38 ondisk = 0) v7 ==== 160+0+16 (730101882 0 3704623946) 0x7fe230000b60 con 0x556c0a186ac0
2016-06-17 11:38:39.887117 7fe26affd700 10 librbd::image::OpenRequest: handle_v2_detect_header: r=0
2016-06-17 11:38:39.887125 7fe26affd700 10 librbd::image::OpenRequest: 0x556c0a17adb0 send_v2_get_id
2016-06-17 11:38:39.887166 7fe26affd700 1 -- 172.16.1.10:0/105872105 --> 172.16.1.20:6822/3637 -- osd_op(client.82209.0:13 4.12036e7d rbd_id._IMG_trusty-server-cloudimg-amd64 [call rbd.get_id] snapc 0=[] ack+read+known_if_redirected e645) v7 -- ?+0 0x7fe24800ba80 con 0x556c0a186ac0
2016-06-17 11:38:39.888202 7fe268cf6700 1 -- 172.16.1.10:0/105872105 <== osd.11 172.16.1.20:6822/3637 2 ==== osd_op_reply(13 rbd_id._IMG_trusty-server-cloudimg-amd64 [call] v0'0 uv38 ondisk = 0) v7 ==== 160+0+17 (2793360622 0 3785231748) 0x7fe230000b60 con 0x556c0a186ac0
2016-06-17 11:38:39.888262 7fe26affd700 10 librbd::image::OpenRequest: handle_v2_get_id: r=0
2016-06-17 11:38:39.888270 7fe26affd700 10 librbd::image::OpenRequest: 0x556c0a17adb0 send_v2_get_immutable_metadata
2016-06-17 11:38:39.888376 7fe26affd700 1 -- 172.16.1.10:0/105872105 --> 172.16.1.22:6806/23711 -- osd_op(client.82209.0:14 4.af0c7d8a rbd_header.127c9238e1f29 [call rbd.get_size,call rbd.get_object_prefix] snapc 0=[] ack+read+known_if_redirected e645) v7 -- ?+0 0x7fe24800e870 con 0x7fe248004220
2016-06-17 11:38:39.890376 7fe268af4700 1 -- 172.16.1.10:0/105872105 <== osd.27 172.16.1.22:6806/23711 1 ==== osd_op_reply(14 rbd_header.127c9238e1f29 [call,call] v0'0 uv13 ondisk = 0) v7 ==== 186+0+35 (1954590760 0 4240195165) 0x7fe228000b90 con 0x7fe248004220
2016-06-17 11:38:39.890473 7fe26affd700 10 librbd::image::OpenRequest: handle_v2_get_immutable_metadata: r=0
2016-06-17 11:38:39.890490 7fe26affd700 10 librbd::image::OpenRequest: 0x556c0a17adb0 send_v2_get_stripe_unit_count
2016-06-17 11:38:39.890529 7fe26affd700 1 -- 172.16.1.10:0/105872105 --> 172.16.1.22:6806/23711 -- osd_op(client.82209.0:15 4.af0c7d8a rbd_header.127c9238e1f29 [call rbd.get_stripe_unit_count] snapc 0=[] ack+read+known_if_redirected e645) v7 -- ?+0 0x7fe24800e870 con 0x7fe248004220
2016-06-17 11:38:39.891254 7fe268af4700 1 -- 172.16.1.10:0/105872105 <== osd.27 172.16.1.22:6806/23711 2 ==== osd_op_reply(15 rbd_header.127c9238e1f29 [call] v0'0 uv0 ondisk = -8 ((8) Exec format error)) v7 ==== 144+0+0 (3806671950 0 0) 0x7fe228000b90 con 0x7fe248004220
2016-06-17 11:38:39.891321 7fe26affd700 10 librbd::image::OpenRequest: handle_v2_get_stripe_unit_count: r=-8
2016-06-17 11:38:39.891334 7fe26affd700 10 librbd::ImageCtx: init_layout stripe_unit 4194304 stripe_count 1 object_size 4194304 prefix rbd_data.127c9238e1f29 format rbd_data.127c9238e1f29.%016llx
2016-06-17 11:38:39.891342 7fe26affd700 10 librbd::image::OpenRequest: 0x556c0a17adb0 send_v2_apply_metadata: start_key=conf_
2016-06-17 11:38:39.891379 7fe26affd700 1 -- 172.16.1.10:0/105872105 --> 172.16.1.22:6806/23711 -- osd_op(client.82209.0:16 4.af0c7d8a rbd_header.127c9238e1f29 [call rbd.metadata_list] snapc 0=[] ack+read+known_if_redirected e645) v7 -- ?+0 0x7fe24800e870 con 0x7fe248004220
2016-06-17 11:38:39.892106 7fe268af4700 1 -- 172.16.1.10:0/105872105 <== osd.27 172.16.1.22:6806/23711 3 ==== osd_op_reply(16 rbd_header.127c9238e1f29 [call] v0'0 uv13 ondisk = 0) v7 ==== 144+0+4 (1431680945 0 0) 0x7fe228000b90 con 0x7fe248004220
2016-06-17 11:38:39.892148 7fe26affd700 10 librbd::image::OpenRequest: 0x556c0a17adb0 handle_v2_apply_metadata: r=0
2016-06-17 11:38:39.892157 7fe26affd700 20 librbd::ImageCtx: apply_metadata
2016-06-17 11:38:39.892275 7fe26affd700 20 librbd::ImageCtx: enabling caching...
2016-06-17 11:38:39.892277 7fe26affd700 20 librbd::ImageCtx: Initial cache settings: size=33554432 num_objects=10 max_dirty=25165824 target_dirty=16777216 max_dirty_age=1
2016-06-17 11:38:39.892324 7fe26affd700 10 librbd::ImageCtx: cache bytes 33554432 -> about 855 objects
2016-06-17 11:38:39.892342 7fe26affd700 10 librbd::image::OpenRequest: 0x556c0a17adb0 send_refresh
2016-06-17 11:38:39.892345 7fe26affd700 10 librbd::image::RefreshRequest: 0x7fe248009c40 send_v2_get_mutable_metadata
2016-06-17 11:38:39.892413 7fe26affd700 1 -- 172.16.1.10:0/105872105 --> 172.16.1.22:6806/23711 -- osd_op(client.82209.0:17 4.af0c7d8a rbd_header.127c9238e1f29 [call rbd.get_size,call rbd.get_features,call rbd.get_snapcontext,call rbd.get_parent,call lock.get_info] snapc 0=[] ack+read+known_if_redirected e645) v7 -- ?+0 0x7fe248017ca0 con 0x7fe248004220
2016-06-17 11:38:39.893397 7fe268af4700 1 -- 172.16.1.10:0/105872105 <== osd.27 172.16.1.22:6806/23711 4 ==== osd_op_reply(17 rbd_header.127c9238e1f29 [call,call,call,call,call] v0'0 uv13 ondisk = 0) v7 ==== 312+0+96 (1811675994 0 1497135268) 0x7fe2280017e0 con 0x7fe248004220
2016-06-17 11:38:39.893443 7fe26affd700 10 librbd::image::RefreshRequest: 0x7fe248009c40 handle_v2_get_mutable_metadata: r=0
2016-06-17 11:38:39.893453 7fe26affd700 10 librbd::image::RefreshRequest: 0x7fe248009c40 send_v2_get_flags
2016-06-17 11:38:39.893491 7fe26affd700 1 -- 172.16.1.10:0/105872105 --> 172.16.1.22:6806/23711 -- osd_op(client.82209.0:18 4.af0c7d8a rbd_header.127c9238e1f29 [call rbd.get_flags,call rbd.get_flags] snapc 0=[] ack+read+known_if_redirected e645) v7 -- ?+0 0x7fe24800cd10 con 0x7fe248004220
2016-06-17 11:38:39.894471 7fe268af4700 1 -- 172.16.1.10:0/105872105 <== osd.27 172.16.1.22:6806/23711 5 ==== osd_op_reply(18 rbd_header.127c9238e1f29 [call,call] v0'0 uv13 ondisk = 0) v7 ==== 186+0+16 (176771434 0 0) 0x7fe2280017e0 con 0x7fe248004220
2016-06-17 11:38:39.894518 7fe26affd700 10 librbd::image::RefreshRequest: 0x7fe248009c40 handle_v2_get_flags: r=0
2016-06-17 11:38:39.894528 7fe26affd700 10 librbd::image::RefreshRequest: 0x7fe248009c40 send_v2_get_snapshots
2016-06-17 11:38:39.894571 7fe26affd700 1 -- 172.16.1.10:0/105872105 --> 172.16.1.22:6806/23711 -- osd_op(client.82209.0:19 4.af0c7d8a rbd_header.127c9238e1f29 [call rbd.get_snapshot_name,call rbd.get_size,call rbd.get_parent,call rbd.get_protection_status] snapc 0=[] ack+read+known_if_redirected e645) v7 -- ?+0 0x7fe248017190 con 0x7fe248004220
2016-06-17 11:38:39.895413 7fe268af4700 1 -- 172.16.1.10:0/105872105 <== osd.27 172.16.1.22:6806/23711 6 ==== osd_op_reply(19 rbd_header.127c9238e1f29 [call,call,call,call] v0'0 uv13 ondisk = 0) v7 ==== 270+0+46 (2502628872 0 95311170) 0x7fe2280017e0 con 0x7fe248004220
2016-06-17 11:38:39.895511 7fe26affd700 10 librbd::image::RefreshRequest: 0x7fe248009c40 handle_v2_get_snapshots: r=0
2016-06-17 11:38:39.895523 7fe26affd700 10 librbd::image::RefreshRequest: 0x7fe248009c40 send_v2_apply
2016-06-17 11:38:39.895584 7fe26a7fc700 10 librbd::image::RefreshRequest: 0x7fe248009c40 handle_v2_apply
2016-06-17 11:38:39.895596 7fe26a7fc700 20 librbd::image::RefreshRequest: 0x7fe248009c40 apply
2016-06-17 11:38:39.895600 7fe26a7fc700 20 librbd::image::RefreshRequest: new snapshot id=12 name=snap size=2361393152
2016-06-17 11:38:39.895607 7fe26a7fc700 10 librbd::image::RefreshRequest: 0x7fe248009c40 send_flush_aio
2016-06-17 11:38:39.895613 7fe26a7fc700 10 librbd::image::RefreshRequest: 0x7fe248009c40 handle_flush_aio: r=0
2016-06-17 11:38:39.895619 7fe26a7fc700 10 librbd::image::OpenRequest: handle_refresh: r=0
2016-06-17 11:38:39.895623 7fe26a7fc700 10 librbd::ImageState: 0x556c0a17ab50 handle_open: r=0
2016-06-17 11:38:39.895686 7fe28d8c6100 20 librbd: info 0x556c0a17e5c0
2016-06-17 11:38:39.895693 7fe28d8c6100 20 librbd: list_locks on image 0x556c0a17e5c0
2016-06-17 11:38:39.895710 7fe28d8c6100 20 librbd: snap_list 0x556c0a17e5c0
2016-06-17 11:38:39.895714 7fe28d8c6100 20 librbd: snap_set 0x556c0a17e5c0 snap = snap
2016-06-17 11:38:39.895717 7fe28d8c6100 20 librbd::ImageState: snap_set: snap_name=snap
2016-06-17 11:38:39.895720 7fe28d8c6100 10 librbd::ImageState: 0x556c0a17ab50 send_set_snap_unlock: snap_name=snap
2016-06-17 11:38:39.895722 7fe28d8c6100 10 librbd::image::SetSnapRequest: send_block_writes
2016-06-17 11:38:39.895723 7fe28d8c6100 5 librbd::AioImageRequestWQ: block_writes: 0x556c0a17e5c0, num=1
2016-06-17 11:38:39.895772 7fe26a7fc700 10 librbd::image::SetSnapRequest: handle_block_writes: r=0
2016-06-17 11:38:39.895779 7fe26a7fc700 10 librbd::image::SetSnapRequest: send_open_object_map
2016-06-17 11:38:39.895782 7fe26a7fc700 20 librbd::object_map::RefreshRequest: 0x7fe24c002b90 send: object_count=563
2016-06-17 11:38:39.895791 7fe26a7fc700 10 librbd::object_map::RefreshRequest: 0x7fe24c002b90 send_load: oid=rbd_object_map.127c9238e1f29.000000000000000c
2016-06-17 11:38:39.895898 7fe26a7fc700 1 -- 172.16.1.10:0/105872105 --> 172.16.1.20:6818/1878 -- osd_op(client.82209.0:20 4.e9586fcd rbd_object_map.127c9238e1f29.000000000000000c [call rbd.object_map_load] snapc 0=[] ack+read+known_if_redirected e645) v7 -- ?+0 0x7fe24c00abb0 con 0x7fe24c0097c0
2016-06-17 11:38:39.897983 7fe2688f2700 1 -- 172.16.1.10:0/105872105 <== osd.9 172.16.1.20:6818/1878 1 ==== osd_op_reply(20 rbd_object_map.127c9238e1f29.000000000000000c [call] v0'0 uv3 ondisk = 0) v7 ==== 165+0+163 (440415222 0 2694064583) 0x7fe220000bf0 con 0x7fe24c0097c0
2016-06-17 11:38:39.898118 7fe26affd700 10 librbd::object_map::RefreshRequest: 0x7fe24c002b90 handle_load: r=0
2016-06-17 11:38:39.898149 7fe26affd700 20 librbd::object_map::RefreshRequest: refreshed object map: num_objs=563
2016-06-17 11:38:39.898157 7fe26affd700 10 librbd::image::SetSnapRequest: handle_open_object_map: r=0
2016-06-17 11:38:39.898161 7fe26affd700 10 librbd::image::SetSnapRequest: apply
2016-06-17 11:38:39.898167 7fe26affd700 5 librbd::AioImageRequestWQ: unblock_writes: 0x556c0a17e5c0, num=0
2016-06-17 11:38:39.898275 7fe26a7fc700 10 librbd::ImageState: 0x556c0a17ab50 handle_set_snap r=0
2016-06-17 11:38:39.898409 7fe28d8c6100 20 librbd: snap_is_protected 0x556c0a17e5c0 snap
2016-06-17 11:38:39.898448 7fe28d8c6100 20 librbd::ImageState: close
2016-06-17 11:38:39.898451 7fe28d8c6100 10 librbd::ImageState: 0x556c0a17ab50 send_close_unlock
2016-06-17 11:38:39.898454 7fe28d8c6100 10 librbd::image::CloseRequest: 0x556c0a17fbc0 send_shut_down_aio_queue
2016-06-17 11:38:39.898456 7fe28d8c6100 5 librbd::AioImageRequestWQ: shut_down: in_flight=0
2016-06-17 11:38:39.898550 7fe26a7fc700 10 librbd::image::CloseRequest: 0x556c0a17fbc0 handle_shut_down_aio_queue: r=0
2016-06-17 11:38:39.898565 7fe26a7fc700 10 librbd::image::CloseRequest: 0x556c0a17fbc0 send_flush
2016-06-17 11:38:39.898573 7fe26a7fc700 10 librbd::image::CloseRequest: 0x556c0a17fbc0 handle_flush: r=0
2016-06-17 11:38:39.898575 7fe26a7fc700 10 librbd::image::CloseRequest: 0x556c0a17fbc0 send_flush_readahead
2016-06-17 11:38:39.898578 7fe26a7fc700 10 librbd::image::CloseRequest: 0x556c0a17fbc0 handle_flush_readahead: r=0
2016-06-17 11:38:39.898580 7fe26a7fc700 10 librbd::image::CloseRequest: 0x556c0a17fbc0 send_shut_down_cache
2016-06-17 11:38:39.898693 7fe26a7fc700 10 librbd::image::CloseRequest: 0x556c0a17fbc0 handle_shut_down_cache: r=0
2016-06-17 11:38:39.898705 7fe26a7fc700 10 librbd::image::CloseRequest: 0x556c0a17fbc0 send_flush_op_work_queue
2016-06-17 11:38:39.898711 7fe26a7fc700 10 librbd::image::CloseRequest: 0x556c0a17fbc0 handle_flush_op_work_queue: r=0
2016-06-17 11:38:39.898731 7fe26a7fc700 10 librbd::ImageState: 0x556c0a17ab50 handle_close: r=0
2016-06-17 11:38:39.898959 7fe28d8c6100 5 librbd::AioImageRequestWQ: 0x556c0a17e0a0 : ictx=0x556c0a17e5c0
2016-06-17 11:38:39.898975 7fe28d8c6100 20 librbd::ImageState: open
2016-06-17 11:38:39.898977 7fe28d8c6100 10 librbd::ImageState: 0x556c0a17ab50 send_open_unlock
2016-06-17 11:38:39.898980 7fe28d8c6100 10 librbd::image::OpenRequest: 0x556c0a184bc0 send_v2_detect_header
2016-06-17 11:38:39.899077 7fe28d8c6100 1 -- 172.16.1.10:0/105872105 --> 172.16.1.21:6800/31929 -- osd_op(client.82209.0:21 4.e52fbbb7 rbd_id._IMG_xenial-server-cloudimg-amd64 [stat] snapc 0=[] ack+read+known_if_redirected e645) v7 -- ?+0 0x556c0a18c250 con 0x556c0a18ae60
2016-06-17 11:38:39.901077 7fe2686f0700 1 -- 172.16.1.10:0/105872105 <== osd.12 172.16.1.21:6800/31929 1 ==== osd_op_reply(21 rbd_id._IMG_xenial-server-cloudimg-amd64 [stat] v0'0 uv1 ondisk = 0) v7 ==== 160+0+16 (2378082072 0 75716242) 0x7fe218000b60 con 0x556c0a18ae60
2016-06-17 11:38:39.901205 7fe26affd700 10 librbd::image::OpenRequest: handle_v2_detect_header: r=0
2016-06-17 11:38:39.901212 7fe26affd700 10 librbd::image::OpenRequest: 0x556c0a184bc0 send_v2_get_id
2016-06-17 11:38:39.901256 7fe26affd700 1 -- 172.16.1.10:0/105872105 --> 172.16.1.21:6800/31929 -- osd_op(client.82209.0:22 4.e52fbbb7 rbd_id._IMG_xenial-server-cloudimg-amd64 [call rbd.get_id] snapc 0=[] ack+read+known_if_redirected e645) v7 -- ?+0 0x7fe24800cc40 con 0x556c0a18ae60
2016-06-17 11:38:39.902494 7fe2686f0700 1 -- 172.16.1.10:0/105872105 <== osd.12 172.16.1.21:6800/31929 2 ==== osd_op_reply(22 rbd_id._IMG_xenial-server-cloudimg-amd64 [call] v0'0 uv1 ondisk = 0) v7 ==== 160+0+16 (2473675721 0 1783702614) 0x7fe218000b60 con 0x556c0a18ae60
2016-06-17 11:38:39.902591 7fe26affd700 10 librbd::image::OpenRequest: handle_v2_get_id: r=0
2016-06-17 11:38:39.902598 7fe26affd700 10 librbd::image::OpenRequest: 0x556c0a184bc0 send_v2_get_immutable_metadata
2016-06-17 11:38:39.902639 7fe26affd700 1 -- 172.16.1.10:0/105872105 --> 172.16.1.22:6806/23711 -- osd_op(client.82209.0:23 4.aa24a8bf rbd_header.2c69238e1f29 [call rbd.get_size,call rbd.get_object_prefix] snapc 0=[] ack+read+known_if_redirected e645) v7 -- ?+0 0x7fe248008190 con 0x7fe248004220
2016-06-17 11:38:39.903403 7fe268af4700 1 -- 172.16.1.10:0/105872105 <== osd.27 172.16.1.22:6806/23711 7 ==== osd_op_reply(23 rbd_header.2c69238e1f29 [call,call] v0'0 uv26 ondisk = 0) v7 ==== 185+0+34 (2600811346 0 2882197922) 0x7fe2280017e0 con 0x7fe248004220
2016-06-17 11:38:39.903518 7fe26affd700 10 librbd::image::OpenRequest: handle_v2_get_immutable_metadata: r=0
2016-06-17 11:38:39.903526 7fe26affd700 10 librbd::image::OpenRequest: 0x556c0a184bc0 send_v2_get_stripe_unit_count
2016-06-17 11:38:39.903561 7fe26affd700 1 -- 172.16.1.10:0/105872105 --> 172.16.1.22:6806/23711 -- osd_op(client.82209.0:24 4.aa24a8bf rbd_header.2c69238e1f29 [call rbd.get_stripe_unit_count] snapc 0=[] ack+read+known_if_redirected e645) v7 -- ?+0 0x7fe248008920 con 0x7fe248004220
2016-06-17 11:38:39.904330 7fe268af4700 1 -- 172.16.1.10:0/105872105 <== osd.27 172.16.1.22:6806/23711 8 ==== osd_op_reply(24 rbd_header.2c69238e1f29 [call] v0'0 uv0 ondisk = -8 ((8) Exec format error)) v7 ==== 143+0+0 (3474474405 0 0) 0x7fe2280017e0 con 0x7fe248004220
2016-06-17 11:38:39.904421 7fe26affd700 10 librbd::image::OpenRequest: handle_v2_get_stripe_unit_count: r=-8
2016-06-17 11:38:39.904430 7fe26affd700 10 librbd::ImageCtx: init_layout stripe_unit 4194304 stripe_count 1 object_size 4194304 prefix rbd_data.2c69238e1f29 format rbd_data.2c69238e1f29.%016llx
2016-06-17 11:38:39.904434 7fe26affd700 10 librbd::image::OpenRequest: 0x556c0a184bc0 send_v2_apply_metadata: start_key=conf_
2016-06-17 11:38:39.904468 7fe26affd700 1 -- 172.16.1.10:0/105872105 --> 172.16.1.22:6806/23711 -- osd_op(client.82209.0:25 4.aa24a8bf rbd_header.2c69238e1f29 [call rbd.metadata_list] snapc 0=[] ack+read+known_if_redirected e645) v7 -- ?+0 0x7fe24800cb30 con 0x7fe248004220
2016-06-17 11:38:39.905109 7fe268af4700 1 -- 172.16.1.10:0/105872105 <== osd.27 172.16.1.22:6806/23711 9 ==== osd_op_reply(25 rbd_header.2c69238e1f29 [call] v0'0 uv26 ondisk = 0) v7 ==== 143+0+4 (730062282 0 0) 0x7fe2280017e0 con 0x7fe248004220
2016-06-17 11:38:39.905202 7fe26affd700 10 librbd::image::OpenRequest: 0x556c0a184bc0 handle_v2_apply_metadata: r=0
2016-06-17 11:38:39.905208 7fe26affd700 20 librbd::ImageCtx: apply_metadata
2016-06-17 11:38:39.905328 7fe26affd700 20 librbd::ImageCtx: enabling caching...
2016-06-17 11:38:39.905330 7fe26affd700 20 librbd::ImageCtx: Initial cache settings: size=33554432 num_objects=10 max_dirty=25165824 target_dirty=16777216 max_dirty_age=1
2016-06-17 11:38:39.905367 7fe26affd700 10 librbd::ImageCtx: cache bytes 33554432 -> about 855 objects
2016-06-17 11:38:39.905383 7fe26affd700 10 librbd::image::OpenRequest: 0x556c0a184bc0 send_refresh
2016-06-17 11:38:39.905386 7fe26affd700 10 librbd::image::RefreshRequest: 0x7fe248012100 send_v2_get_mutable_metadata
2016-06-17 11:38:39.905440 7fe26affd700 1 -- 172.16.1.10:0/105872105 --> 172.16.1.22:6806/23711 -- osd_op(client.82209.0:26 4.aa24a8bf rbd_header.2c69238e1f29 [call rbd.get_size,call rbd.get_features,call rbd.get_snapcontext,call rbd.get_parent,call lock.get_info] snapc 0=[] ack+read+known_if_redirected e645) v7 -- ?+0 0x7fe248012760 con 0x7fe248004220
2016-06-17 11:38:39.906521 7fe268af4700 1 -- 172.16.1.10:0/105872105 <== osd.27 172.16.1.22:6806/23711 10 ==== osd_op_reply(26 rbd_header.2c69238e1f29 [call,call,call,call,call] v0'0 uv26 ondisk = 0) v7 ==== 311+0+96 (3468305 0 2478205783) 0x7fe2280023b0 con 0x7fe248004220
2016-06-17 11:38:39.906611 7fe26affd700 10 librbd::image::RefreshRequest: 0x7fe248012100 handle_v2_get_mutable_metadata: r=0
2016-06-17 11:38:39.906621 7fe26affd700 10 librbd::image::RefreshRequest: 0x7fe248012100 send_v2_get_flags
2016-06-17 11:38:39.906660 7fe26affd700 1 -- 172.16.1.10:0/105872105 --> 172.16.1.22:6806/23711 -- osd_op(client.82209.0:27 4.aa24a8bf rbd_header.2c69238e1f29 [call rbd.get_flags,call rbd.get_flags] snapc 0=[] ack+read+known_if_redirected e645) v7 -- ?+0 0x7fe248015440 con 0x7fe248004220
2016-06-17 11:38:39.907331 7fe268af4700 1 -- 172.16.1.10:0/105872105 <== osd.27 172.16.1.22:6806/23711 11 ==== osd_op_reply(27 rbd_header.2c69238e1f29 [call,call] v0'0 uv26 ondisk = 0) v7 ==== 185+0+16 (1781840302 0 0) 0x7fe2280023b0 con 0x7fe248004220
2016-06-17 11:38:39.907454 7fe26affd700 10 librbd::image::RefreshRequest: 0x7fe248012100 handle_v2_get_flags: r=0
2016-06-17 11:38:39.907462 7fe26affd700 10 librbd::image::RefreshRequest: 0x7fe248012100 send_v2_get_snapshots
2016-06-17 11:38:39.907510 7fe26affd700 1 -- 172.16.1.10:0/105872105 --> 172.16.1.22:6806/23711 -- osd_op(client.82209.0:28 4.aa24a8bf rbd_header.2c69238e1f29 [call rbd.get_snapshot_name,call rbd.get_size,call rbd.get_parent,call rbd.get_protection_status] snapc 0=[] ack+read+known_if_redirected e645) v7 -- ?+0 0x7fe2480155a0 con 0x7fe248004220
2016-06-17 11:38:39.908444 7fe268af4700 1 -- 172.16.1.10:0/105872105 <== osd.27 172.16.1.22:6806/23711 12 ==== osd_op_reply(28 rbd_header.2c69238e1f29 [call,call,call,call] v0'0 uv26 ondisk = 0) v7 ==== 269+0+46 (2263733788 0 95311170) 0x7fe2280025d0 con 0x7fe248004220
2016-06-17 11:38:39.908529 7fe26affd700 10 librbd::image::RefreshRequest: 0x7fe248012100 handle_v2_get_snapshots: r=0
2016-06-17 11:38:39.908540 7fe26affd700 10 librbd::image::RefreshRequest: 0x7fe248012100 send_v2_apply
2016-06-17 11:38:39.908605 7fe26a7fc700 10 librbd::image::RefreshRequest: 0x7fe248012100 handle_v2_apply
2016-06-17 11:38:39.908616 7fe26a7fc700 20 librbd::image::RefreshRequest: 0x7fe248012100 apply
2016-06-17 11:38:39.908620 7fe26a7fc700 20 librbd::image::RefreshRequest: new snapshot id=11 name=snap size=2361393152
2016-06-17 11:38:39.908628 7fe26a7fc700 10 librbd::image::RefreshRequest: 0x7fe248012100 send_flush_aio
2016-06-17 11:38:39.908635 7fe26a7fc700 10 librbd::image::RefreshRequest: 0x7fe248012100 handle_flush_aio: r=0
2016-06-17 11:38:39.908641 7fe26a7fc700 10 librbd::image::OpenRequest: handle_refresh: r=0
2016-06-17 11:38:39.908645 7fe26a7fc700 10 librbd::ImageState: 0x556c0a17ab50 handle_open: r=0
2016-06-17 11:38:39.908702 7fe28d8c6100 20 librbd: info 0x556c0a17e5c0
2016-06-17 11:38:39.908714 7fe28d8c6100 20 librbd: list_locks on image 0x556c0a17e5c0
2016-06-17 11:38:39.908732 7fe28d8c6100 20 librbd: snap_list 0x556c0a17e5c0
2016-06-17 11:38:39.908736 7fe28d8c6100 20 librbd: snap_set 0x556c0a17e5c0 snap = snap
2016-06-17 11:38:39.908739 7fe28d8c6100 20 librbd::ImageState: snap_set: snap_name=snap
2016-06-17 11:38:39.908741 7fe28d8c6100 10 librbd::ImageState: 0x556c0a17ab50 send_set_snap_unlock: snap_name=snap
2016-06-17 11:38:39.908743 7fe28d8c6100 10 librbd::image::SetSnapRequest: send_block_writes
2016-06-17 11:38:39.908745 7fe28d8c6100 5 librbd::AioImageRequestWQ: block_writes: 0x556c0a17e5c0, num=1
2016-06-17 11:38:39.908793 7fe26a7fc700 10 librbd::image::SetSnapRequest: handle_block_writes: r=0
2016-06-17 11:38:39.908800 7fe26a7fc700 10 librbd::image::SetSnapRequest: send_open_object_map
2016-06-17 11:38:39.908803 7fe26a7fc700 20 librbd::object_map::RefreshRequest: 0x7fe24c007a00 send: object_count=563
2016-06-17 11:38:39.908814 7fe26a7fc700 10 librbd::object_map::RefreshRequest: 0x7fe24c007a00 send_load: oid=rbd_object_map.2c69238e1f29.000000000000000b
2016-06-17 11:38:39.908854 7fe26a7fc700 1 -- 172.16.1.10:0/105872105 --> 172.16.1.21:6800/31929 -- osd_op(client.82209.0:29 4.8638db85 rbd_object_map.2c69238e1f29.000000000000000b [call rbd.object_map_load] snapc 0=[] ack+read+known_if_redirected e645) v7 -- ?+0 0x7fe24c00c880 con 0x556c0a18ae60
2016-06-17 11:38:39.909970 7fe2686f0700 1 -- 172.16.1.10:0/105872105 <== osd.12 172.16.1.21:6800/31929 3 ==== osd_op_reply(29 rbd_object_map.2c69238e1f29.000000000000000b [call] v0'0 uv3 ondisk = 0) v7 ==== 164+0+163 (4256008510 0 1880438835) 0x7fe218000b60 con 0x556c0a18ae60
2016-06-17 11:38:39.910061 7fe26affd700 10 librbd::object_map::RefreshRequest: 0x7fe24c007a00 handle_load: r=0
2016-06-17 11:38:39.910080 7fe26affd700 20 librbd::object_map::RefreshRequest: refreshed object map: num_objs=563
2016-06-17 11:38:39.910085 7fe26affd700 10 librbd::image::SetSnapRequest: handle_open_object_map: r=0
2016-06-17 11:38:39.910086 7fe26affd700 10 librbd::image::SetSnapRequest: apply
2016-06-17 11:38:39.910119 7fe26affd700 5 librbd::AioImageRequestWQ: unblock_writes: 0x556c0a17e5c0, num=0
2016-06-17 11:38:39.910286 7fe26a7fc700 10 librbd::ImageState: 0x556c0a17ab50 handle_set_snap r=0
2016-06-17 11:38:39.910307 7fe28d8c6100 20 librbd: snap_is_protected 0x556c0a17e5c0 snap
2016-06-17 11:38:39.910335 7fe28d8c6100 20 librbd::ImageState: close
2016-06-17 11:38:39.910338 7fe28d8c6100 10 librbd::ImageState: 0x556c0a17ab50 send_close_unlock
2016-06-17 11:38:39.910340 7fe28d8c6100 10 librbd::image::CloseRequest: 0x556c0a180550 send_shut_down_aio_queue
2016-06-17 11:38:39.910342 7fe28d8c6100 5 librbd::AioImageRequestWQ: shut_down: in_flight=0
2016-06-17 11:38:39.910362 7fe26a7fc700 10 librbd::image::CloseRequest: 0x556c0a180550 handle_shut_down_aio_queue: r=0
2016-06-17 11:38:39.910370 7fe26a7fc700 10 librbd::image::CloseRequest: 0x556c0a180550 send_flush
2016-06-17 11:38:39.910376 7fe26a7fc700 10 librbd::image::CloseRequest: 0x556c0a180550 handle_flush: r=0
2016-06-17 11:38:39.910378 7fe26a7fc700 10 librbd::image::CloseRequest: 0x556c0a180550 send_flush_readahead
2016-06-17 11:38:39.910380 7fe26a7fc700 10 librbd::image::CloseRequest: 0x556c0a180550 handle_flush_readahead: r=0
2016-06-17 11:38:39.910381 7fe26a7fc700 10 librbd::image::CloseRequest: 0x556c0a180550 send_shut_down_cache
2016-06-17 11:38:39.910524 7fe26a7fc700 10 librbd::image::CloseRequest: 0x556c0a180550 handle_shut_down_cache: r=0
2016-06-17 11:38:39.910533 7fe26a7fc700 10 librbd::image::CloseRequest: 0x556c0a180550 send_flush_op_work_queue
2016-06-17 11:38:39.910538 7fe26a7fc700 10 librbd::image::CloseRequest: 0x556c0a180550 handle_flush_op_work_queue: r=0
2016-06-17 11:38:39.910552 7fe26a7fc700 10 librbd::ImageState: 0x556c0a17ab50 handle_close: r=0
2016-06-17 11:38:39.910825 7fe28d8c6100 5 librbd::AioImageRequestWQ: 0x556c0a17e0a0 : ictx=0x556c0a17e5c0
2016-06-17 11:38:39.910842 7fe28d8c6100 20 librbd::ImageState: open
2016-06-17 11:38:39.910851 7fe28d8c6100 10 librbd::ImageState: 0x556c0a17ab50 send_open_unlock
2016-06-17 11:38:39.910853 7fe28d8c6100 10 librbd::image::OpenRequest: 0x556c0a188210 send_v2_detect_header
2016-06-17 11:38:39.910882 7fe28d8c6100 1 -- 172.16.1.10:0/105872105 --> 172.16.1.20:6822/3637 -- osd_op(client.82209.0:30 4.55bd76d3 rbd_id.test1 [stat] snapc 0=[] ack+read+known_if_redirected e645) v7 -- ?+0 0x556c0a18d750 con 0x556c0a186ac0
2016-06-17 11:38:39.911595 7fe268cf6700 1 -- 172.16.1.10:0/105872105 <== osd.11 172.16.1.20:6822/3637 3 ==== osd_op_reply(30 rbd_id.test1 [stat] v0'0 uv0 ack = -2 ((2) No such file or directory)) v7 ==== 132+0+0 (2316701749 0 0) 0x7fe230000b60 con 0x556c0a186ac0
2016-06-17 11:38:39.911728 7fe26affd700 10 librbd::image::OpenRequest: handle_v2_detect_header: r=-2
2016-06-17 11:38:39.911837 7fe26affd700 1 -- 172.16.1.10:0/105872105 --> 172.16.1.21:6808/10860 -- osd_op(client.82209.0:31 4.2bc09b0b test1.rbd [stat] snapc 0=[] ack+read+known_if_redirected e645) v7 -- ?+0 0x7fe248010670 con 0x7fe248011140
2016-06-17 11:38:39.913789 7fe2684ee700 1 -- 172.16.1.10:0/105872105 <== osd.15 172.16.1.21:6808/10860 1 ==== osd_op_reply(31 test1.rbd [stat] v0'0 uv0 ack = -2 ((2) No such file or directory)) v7 ==== 129+0+0 (1021193307 0 0) 0x7fe210000a20 con 0x7fe248011140
2016-06-17 11:38:39.913948 7fe26affd700 10 librbd::image::OpenRequest: handle_v1_detect_header: r=-2
2016-06-17 11:38:39.913958 7fe26affd700 10 librbd::image::OpenRequest: 0x556c0a188210 send_close_image
2016-06-17 11:38:39.913961 7fe26affd700 10 librbd::image::CloseRequest: 0x7fe248003d80 send_shut_down_aio_queue
2016-06-17 11:38:39.913964 7fe26affd700 5 librbd::AioImageRequestWQ: shut_down: in_flight=0
2016-06-17 11:38:39.914024 7fe26a7fc700 10 librbd::image::CloseRequest: 0x7fe248003d80 handle_shut_down_aio_queue: r=0
2016-06-17 11:38:39.914031 7fe26a7fc700 10 librbd::image::CloseRequest: 0x7fe248003d80 send_flush
2016-06-17 11:38:39.914036 7fe26a7fc700 10 librbd::image::CloseRequest: 0x7fe248003d80 handle_flush: r=0
2016-06-17 11:38:39.914038 7fe26a7fc700 10 librbd::image::CloseRequest: 0x7fe248003d80 send_flush_readahead
2016-06-17 11:38:39.914040 7fe26a7fc700 10 librbd::image::CloseRequest: 0x7fe248003d80 handle_flush_readahead: r=0
2016-06-17 11:38:39.914041 7fe26a7fc700 10 librbd::image::CloseRequest: 0x7fe248003d80 send_shut_down_cache
2016-06-17 11:38:39.914042 7fe26a7fc700 10 librbd::image::CloseRequest: 0x7fe248003d80 handle_shut_down_cache: r=0
2016-06-17 11:38:39.914044 7fe26a7fc700 10 librbd::image::CloseRequest: 0x7fe248003d80 send_flush_op_work_queue
2016-06-17 11:38:39.914046 7fe26a7fc700 10 librbd::image::CloseRequest: 0x7fe248003d80 handle_flush_op_work_queue: r=0
2016-06-17 11:38:39.914049 7fe26a7fc700 10 librbd::image::OpenRequest: handle_close_image: r=0
2016-06-17 11:38:39.914054 7fe26a7fc700 10 librbd::ImageState: 0x556c0a17ab50 handle_open: r=-2
NAME SIZE PARENT FMT PROT LOCK
_IMG_debian-8.5.0-openstack-amd64 2048M 2
_IMG_debian-8.5.0-openstack-amd64@snap 2048M 2 yes
_IMG_trusty-server-cloudimg-amd64 2252M 2
_IMG_trusty-server-cloudimg-amd64@snap 2252M 2 yes
_IMG_xenial-server-cloudimg-amd64 2252M 2
_IMG_xenial-server-cloudimg-amd64@snap 2252M 2 yes
rbd: list: (2) No such file or directory
2016-06-17 11:38:39.914790 7fe28d8c6100 1 -- 172.16.1.10:0/105872105 mark_down 0x7fe24c0097c0 -- 0x7fe24c0084b0
2016-06-17 11:38:39.914846 7fe28d8c6100 1 -- 172.16.1.10:0/105872105 mark_down 0x7fe24c004d40 -- 0x7fe24c003a30
2016-06-17 11:38:39.914878 7fe28d8c6100 1 -- 172.16.1.10:0/105872105 mark_down 0x556c0a186ac0 -- 0x556c0a1857e0
2016-06-17 11:38:39.914925 7fe28d8c6100 1 -- 172.16.1.10:0/105872105 mark_down 0x556c0a18ae60 -- 0x556c0a189b80
2016-06-17 11:38:39.914976 7fe28d8c6100 1 -- 172.16.1.10:0/105872105 mark_down 0x7fe248011140 -- 0x7fe24800f390
2016-06-17 11:38:39.915129 7fe28d8c6100 1 -- 172.16.1.10:0/105872105 mark_down 0x7fe248006580 -- 0x7fe2480052a0
2016-06-17 11:38:39.915180 7fe28d8c6100 1 -- 172.16.1.10:0/105872105 mark_down 0x7fe248004220 -- 0x7fe24800d590
2016-06-17 11:38:39.915212 7fe28d8c6100 1 -- 172.16.1.10:0/105872105 mark_down 0x556c0a17b110 -- 0x556c0a17b980
2016-06-17 11:38:39.915245 7fe28d8c6100 1 -- 172.16.1.10:0/105872105 mark_down 0x556c0a182610 -- 0x556c0a181330
2016-06-17 11:38:39.915297 7fe28d8c6100 1 -- 172.16.1.10:0/105872105 mark_down 0x556c0a1763c0 -- 0x556c0a1750e0
2016-06-17 11:38:39.916020 7fe28d8c6100 1 -- 172.16.1.10:0/105872105 mark_down_all
2016-06-17 11:38:39.916420 7fe28d8c6100 1 -- 172.16.1.10:0/105872105 shutdown complete.
(3-3/4)