Ceph » rbd

Client:

# ceph --version
ceph version 10.2.7 (50e863e0f4bc8f4b9e31156de690d765af245185)

Cluster:

# ceph --version
ceph version 11.2.0 (f223e27eeb35991352ebc1f67423d4ebc252adb7)

Problem summary:
rbd import hangs indefinitely.

Debug log (@debug rbd = 20):

# rbd -p images import cirros-0.3.5-x86_64-disk.raw &
[1] 18265
root@control02-glance-container-0413e606:~# rbd: --pool is deprecated for import, use --dest-pool
2017-05-09 14:35:06.158971 7f7524944100 10 librbd: create name=cirros-0.3.5-x86_64-disk.raw, size=41126400, opts=[format=2, features=61, order=22, stripe_unit=0, stripe_count=0]
2017-05-09 14:35:06.158988 7f7524944100 20 librbd: create 0x7ffedda92ea0 name = cirros-0.3.5-x86_64-disk.raw size = 41126400 old_format = 0 features = 61 order = 22 stripe_unit = 0 stripe_count = 0
2017-05-09 14:35:06.167722 7f7524944100  2 librbd: adding rbd image to directory...
2017-05-09 14:35:06.176910 7f7524944100  2 librbd: done.
2017-05-09 14:35:06.177046 7f7524944100  5 librbd::AioImageRequestWQ: 0x55b00253a520 : ictx=0x55b002539340
2017-05-09 14:35:06.177059 7f7524944100 20 librbd::ImageState: 0x55b00253e890 open
2017-05-09 14:35:06.177062 7f7524944100 10 librbd::ImageState: 0x55b00253e890 0x55b00253e890 send_open_unlock
2017-05-09 14:35:06.177071 7f7524944100 10 librbd::image::OpenRequest: 0x55b00253acc0 send_v2_detect_header
2017-05-09 14:35:06.177691 7f750668b700 10 librbd::image::OpenRequest: handle_v2_detect_header: r=0
2017-05-09 14:35:06.177710 7f750668b700 10 librbd::image::OpenRequest: 0x55b00253acc0 send_v2_get_id
2017-05-09 14:35:06.178218 7f750668b700 10 librbd::image::OpenRequest: handle_v2_get_id: r=0
2017-05-09 14:35:06.178227 7f750668b700 10 librbd::image::OpenRequest: 0x55b00253acc0 send_v2_get_immutable_metadata
2017-05-09 14:35:06.179038 7f750668b700 10 librbd::image::OpenRequest: handle_v2_get_immutable_metadata: r=0
2017-05-09 14:35:06.179045 7f750668b700 10 librbd::image::OpenRequest: 0x55b00253acc0 send_v2_get_stripe_unit_count
2017-05-09 14:35:06.179714 7f750668b700 10 librbd::image::OpenRequest: handle_v2_get_stripe_unit_count: r=-8
2017-05-09 14:35:06.179725 7f750668b700 10 librbd::ImageCtx: init_layout stripe_unit 4194304 stripe_count 1 object_size 4194304 prefix rbd_data.8798238e1f29 format rbd_data.8798238e1f29.%016llx
2017-05-09 14:35:06.179728 7f750668b700 10 librbd::image::OpenRequest: 0x55b00253acc0 send_v2_apply_metadata: start_key=conf_
2017-05-09 14:35:06.180279 7f750668b700 10 librbd::image::OpenRequest: 0x55b00253acc0 handle_v2_apply_metadata: r=0
2017-05-09 14:35:06.180300 7f750668b700 20 librbd::ImageCtx: apply_metadata
2017-05-09 14:35:06.180460 7f750668b700 20 librbd::ImageCtx: enabling caching...
2017-05-09 14:35:06.180465 7f750668b700 20 librbd::ImageCtx: Initial cache settings: size=33554432 num_objects=10 max_dirty=25165824 target_dirty=16777216 max_dirty_age=1
2017-05-09 14:35:06.180547 7f750668b700 10 librbd::ImageCtx:  cache bytes 33554432 -> about 855 objects
2017-05-09 14:35:06.181094 7f750668b700 10 librbd::image::OpenRequest: 0x55b00253acc0 send_register_watch
2017-05-09 14:35:06.181196 7f750668b700 10 librbd::ImageWatcher: 0x7f74d40033d0 registering image watcher
2017-05-09 14:35:06.183279 7f750668b700 10 librbd::image::OpenRequest: 0x55b00253acc0 handle_register_watch: r=0
2017-05-09 14:35:06.183291 7f750668b700 10 librbd::image::OpenRequest: 0x55b00253acc0 send_refresh
2017-05-09 14:35:06.183294 7f750668b700 10 librbd::image::RefreshRequest: 0x7f74d40055e0 send_v2_get_mutable_metadata
2017-05-09 14:35:06.184324 7f750668b700 10 librbd::image::RefreshRequest: 0x7f74d40055e0 handle_v2_get_mutable_metadata: r=0
2017-05-09 14:35:06.184340 7f750668b700 10 librbd::image::RefreshRequest: 0x7f74d40055e0 send_v2_get_flags
2017-05-09 14:35:06.184847 7f750668b700 10 librbd::image::RefreshRequest: 0x7f74d40055e0 handle_v2_get_flags: r=0
2017-05-09 14:35:06.184862 7f750668b700 10 librbd::image::RefreshRequest: 0x7f74d40055e0 send_v2_init_exclusive_lock
2017-05-09 14:35:06.184870 7f750668b700 10 librbd::ExclusiveLock: 0x7f74d4007e80 init
2017-05-09 14:35:06.184874 7f750668b700  5 librbd::AioImageRequestWQ: block_writes: 0x55b002539340, num=1
2017-05-09 14:35:06.184892 7f7505281700 10 librbd::ExclusiveLock: 0x7f74d4007e80 handle_init_complete
2017-05-09 14:35:06.184898 7f7505281700 10 librbd::image::RefreshRequest: 0x7f74d40055e0 handle_v2_init_exclusive_lock: r=0
2017-05-09 14:35:06.184900 7f7505281700 10 librbd::image::RefreshRequest: 0x7f74d40055e0 send_v2_apply
2017-05-09 14:35:06.184904 7f7505281700 10 librbd::image::RefreshRequest: 0x7f74d40055e0 handle_v2_apply
2017-05-09 14:35:06.184910 7f7505281700 20 librbd::image::RefreshRequest: 0x7f74d40055e0 apply
2017-05-09 14:35:06.184919 7f7505281700 10 librbd::image::OpenRequest: handle_refresh: r=0
2017-05-09 14:35:06.184922 7f7505281700 10 librbd::ImageState: 0x55b00253e890 0x55b00253e890 handle_open: r=0
2017-05-09 14:35:06.192073 7f7524944100 20 librbd::AioImageRequestWQ: aio_write: ictx=0x55b002539340, completion=0x55b00253ae90, off=0, len=4194304, flags=72
2017-05-09 14:35:06.192092 7f7524944100 20 librbd::AioImageRequestWQ: queue: ictx=0x55b002539340, req=0x55b00253b1d0
2017-05-09 14:35:06.192096 7f7524944100 20 librbd::ExclusiveLock: 0x7f74d4007e80 is_lock_owner=0
2017-05-09 14:35:06.192103 7f7524944100 10 librbd::ExclusiveLock: 0x7f74d4007e80 request_lock
2017-05-09 14:35:06.192106 7f7524944100 10 librbd::ExclusiveLock: 0x7f74d4007e80 send_acquire_lock
2017-05-09 14:35:06.192146 7f7505281700 10 librbd::exclusive_lock::AcquireRequest: send_prepare_lock
2017-05-09 14:35:06.192152 7f7505281700 10 librbd::ImageState: 0x55b00253e890 prepare_lock
2017-05-09 14:35:06.192155 7f7505281700 10 librbd::ImageState: 0x55b00253e890 0x55b00253e890 send_prepare_lock_unlock
2017-05-09 14:35:06.192157 7f7505281700 10 librbd::exclusive_lock::AcquireRequest: handle_prepare_lock: r=0
2017-05-09 14:35:06.192159 7f7505281700 10 librbd::exclusive_lock::AcquireRequest: send_flush_notifies
2017-05-09 14:35:06.192162 7f7505281700 10 librbd::exclusive_lock::AcquireRequest: handle_flush_notifies
2017-05-09 14:35:06.192163 7f7505281700 10 librbd::exclusive_lock::AcquireRequest: send_get_locker
2017-05-09 14:35:06.192165 7f7505281700 10 librbd::exclusive_lock::GetLockerRequest: 0x7f74d0001a90 send_get_lockers: 
2017-05-09 14:35:06.192711 7f750668b700 10 librbd::exclusive_lock::GetLockerRequest: 0x7f74d0001a90 handle_get_lockers: r=0
2017-05-09 14:35:06.192724 7f750668b700 20 librbd::exclusive_lock::GetLockerRequest: 0x7f74d0001a90 handle_get_lockers: no lockers detected
2017-05-09 14:35:06.192727 7f750668b700 10 librbd::exclusive_lock::GetLockerRequest: 0x7f74d0001a90 finish: r=-2
2017-05-09 14:35:06.192730 7f750668b700 10 librbd::exclusive_lock::AcquireRequest: handle_get_locker: r=-2
2017-05-09 14:35:06.192732 7f750668b700 20 librbd::exclusive_lock::AcquireRequest: no lockers detected
2017-05-09 14:35:06.192733 7f750668b700 10 librbd::exclusive_lock::AcquireRequest: send_lock
Importing image: 10% complete...2017-05-09 14:35:06.194990 7f750668b700 10 librbd::exclusive_lock::AcquireRequest: handle_lock: r=0
2017-05-09 14:35:06.194999 7f750668b700 10 librbd::exclusive_lock::AcquireRequest: send_open_object_map
2017-05-09 14:35:06.195005 7f750668b700 20 librbd::object_map::RefreshRequest: 0x7f74d40075b0 send: object_count=10
2017-05-09 14:35:06.195009 7f750668b700 10 librbd::object_map::RefreshRequest: 0x7f74d40075b0 send_lock: oid=rbd_object_map.8798238e1f29
2017-05-09 14:35:06.195012 7f750668b700 10 librbd::object_map::LockRequest: 0x7f74d4004b70 send_lock: oid=rbd_object_map.8798238e1f29
2017-05-09 14:35:06.197201 7f750668b700 10 librbd::object_map::LockRequest: 0x7f74d4004b70 handle_lock: r=0
2017-05-09 14:35:06.197215 7f750668b700 10 librbd::object_map::RefreshRequest: 0x7f74d40075b0 handle_lock
2017-05-09 14:35:06.197218 7f750668b700 10 librbd::object_map::RefreshRequest: 0x7f74d40075b0 send_load: oid=rbd_object_map.8798238e1f29
2017-05-09 14:35:06.197566 7f7524944100 20 librbd::AioImageRequestWQ: aio_write: ictx=0x55b002539340, completion=0x55b00253eaf0, off=4194304, len=4194304, flags=72
2017-05-09 14:35:06.197577 7f7524944100 20 librbd::AioImageRequestWQ: queue: ictx=0x55b002539340, req=0x55b00253edf0
2017-05-09 14:35:06.197585 7f7524944100 20 librbd::ExclusiveLock: 0x7f74d4007e80 is_lock_owner=0
2017-05-09 14:35:06.197591 7f7524944100 10 librbd::ExclusiveLock: 0x7f74d4007e80 request_lock
2017-05-09 14:35:06.197805 7f750668b700 10 librbd::object_map::RefreshRequest: 0x7f74d40075b0 handle_load: r=0
2017-05-09 14:35:06.197824 7f750668b700 20 librbd::object_map::RefreshRequest: refreshed object map: num_objs=10
2017-05-09 14:35:06.197830 7f750668b700 10 librbd::exclusive_lock::AcquireRequest: handle_open_object_map: r=0
2017-05-09 14:35:06.197834 7f750668b700 10 librbd::ExclusiveLock: 0x7f74d4007e80 handle_acquiring_lock
2017-05-09 14:35:06.197838 7f750668b700 10 librbd::ImageState: 0x55b00253e890 handle_prepare_lock_complete
2017-05-09 14:35:06.197857 7f7505281700 10 librbd::ExclusiveLock: 0x7f74d4007e80 handle_acquire_lock: r=0
2017-05-09 14:35:06.197865 7f7505281700  5 librbd::ExclusiveLock: successfully acquired exclusive lock
2017-05-09 14:35:06.197867 7f7505281700 10 librbd::ImageWatcher: 0x7f74d40033d0 notify acquired lock
2017-05-09 14:35:06.197870 7f7505281700 10 librbd::ImageWatcher: 0x7f74d40033d0 current lock owner: [34712,140139749723232]
2017-05-09 14:35:06.197888 7f7505281700 20 librbd::image_watcher::Notifier: notify: pending=1
2017-05-09 14:35:06.197966 7f7505281700 20 librbd::AioImageRequestWQ: clear_require_lock_on_read
2017-05-09 14:35:06.197975 7f7505281700  5 librbd::AioImageRequestWQ: unblock_writes: 0x55b002539340, num=0
2017-05-09 14:35:06.197980 7f7505281700 20 librbd::AsyncOperation: 0x55b00253afe0 start_op
2017-05-09 14:35:06.197982 7f7505281700 20 librbd::AioImageRequestWQ: process: ictx=0x55b002539340, req=0x55b00253b1d0
2017-05-09 14:35:06.197986 7f7505281700 20 librbd::AioImageRequest: aio_write: ictx=0x55b002539340, completion=0x55b00253ae90
2017-05-09 14:35:06.198002 7f7505281700 20 librbd::AioCompletion: 0x55b00253ae90 set_request_count: pending=1
2017-05-09 14:35:06.198524 7f750668b700 10 librbd::ImageWatcher: 0x7f74d4004b70 C_NotifyAck start: id=322122547202, handle=140139749723232
2017-05-09 14:35:06.198531 7f750668b700 10 librbd::ImageWatcher: 0x7f74d40033d0 image exclusively locked announcement
2017-05-09 14:35:06.198533 7f750668b700 10 librbd::ImageWatcher: 0x7f74d40033d0 current lock owner: [34712,140139749723232]
2017-05-09 14:35:06.198537 7f750668b700 10 librbd::ImageWatcher: 0x7f74d4004b70 C_NotifyAck finish: id=322122547202, handle=140139749723232
2017-05-09 14:35:06.199067 7f750668b700 20 librbd::image_watcher::Notifier: handle_notify: pending=0
Importing image: 20% complete...2017-05-09 14:35:06.200414 7f7505281700 20 librbd::AsyncOperation: 0x55b00253ec40 start_op
2017-05-09 14:35:06.200422 7f7505281700 20 librbd::AioImageRequestWQ: process: ictx=0x55b002539340, req=0x55b00253edf0
2017-05-09 14:35:06.200424 7f7505281700 20 librbd::AioImageRequest: aio_write: ictx=0x55b002539340, completion=0x55b00253eaf0
2017-05-09 14:35:06.200431 7f7505281700 20 librbd::AioCompletion: 0x55b00253eaf0 set_request_count: pending=1
2017-05-09 14:35:06.200504 7f7504a80700 20 librbd::AioCompletion: 0x55b00253ae90 complete_request: cb=1, pending=0
2017-05-09 14:35:06.200517 7f7504a80700 20 librbd::AioCompletion: 0x55b00253ae90 finalize: r=0, read_buf=0, real_bl=0
2017-05-09 14:35:06.200751 7f7504a80700 20 librbd::AsyncOperation: 0x55b00253afe0 finish_op
2017-05-09 14:35:06.202054 7f7524944100 20 librbd::AioImageRequestWQ: aio_write: ictx=0x55b002539340, completion=0x55b00253ae90, off=8388608, len=4194304, flags=72
2017-05-09 14:35:06.202065 7f7524944100 20 librbd::AioImageRequestWQ: queue: ictx=0x55b002539340, req=0x55b00253b1d0
2017-05-09 14:35:06.202067 7f7524944100 20 librbd::ExclusiveLock: 0x7f74d4007e80 is_lock_owner=1
2017-05-09 14:35:06.202802 7f7505281700 20 librbd::AsyncOperation: 0x55b00253afe0 start_op
2017-05-09 14:35:06.202808 7f7505281700 20 librbd::AioImageRequestWQ: process: ictx=0x55b002539340, req=0x55b00253b1d0
2017-05-09 14:35:06.202812 7f7505281700 20 librbd::AioImageRequest: aio_write: ictx=0x55b002539340, completion=0x55b00253ae90
2017-05-09 14:35:06.202811 7f7504a80700 20 librbd::AioCompletion: 0x55b00253eaf0 complete_request: cb=1, pending=0
2017-05-09 14:35:06.202817 7f7504a80700 20 librbd::AioCompletion: 0x55b00253eaf0 finalize: r=0, read_buf=0, real_bl=0
2017-05-09 14:35:06.202819 7f7505281700 20 librbd::AioCompletion: 0x55b00253ae90 set_request_count: pending=1
2017-05-09 14:35:06.203130 7f7504a80700 20 librbd::AsyncOperation: 0x55b00253ec40 finish_op
Importing image: 30% complete...2017-05-09 14:35:06.205064 7f7504a80700 20 librbd::AioCompletion: 0x55b00253ae90 complete_request: cb=1, pending=0
2017-05-09 14:35:06.205078 7f7504a80700 20 librbd::AioCompletion: 0x55b00253ae90 finalize: r=0, read_buf=0, real_bl=0
2017-05-09 14:35:06.205268 7f7504a80700 20 librbd::AsyncOperation: 0x55b00253afe0 finish_op
2017-05-09 14:35:06.206464 7f7524944100 20 librbd::AioImageRequestWQ: aio_write: ictx=0x55b002539340, completion=0x55b00253eaf0, off=12582912, len=4194304, flags=72
2017-05-09 14:35:06.206474 7f7524944100 20 librbd::AioImageRequestWQ: queue: ictx=0x55b002539340, req=0x55b00253b1d0
2017-05-09 14:35:06.206476 7f7524944100 20 librbd::ExclusiveLock: 0x7f74d4007e80 is_lock_owner=1
2017-05-09 14:35:06.206522 7f7505281700 20 librbd::AsyncOperation: 0x55b00253ec40 start_op
2017-05-09 14:35:06.206531 7f7505281700 20 librbd::AioImageRequestWQ: process: ictx=0x55b002539340, req=0x55b00253b1d0
2017-05-09 14:35:06.206533 7f7505281700 20 librbd::AioImageRequest: aio_write: ictx=0x55b002539340, completion=0x55b00253eaf0
2017-05-09 14:35:06.206543 7f7505281700 20 librbd::AioCompletion: 0x55b00253eaf0 set_request_count: pending=1
Importing image: 40% complete...2017-05-09 14:35:06.208632 7f7504a80700 20 librbd::AioCompletion: 0x55b00253eaf0 complete_request: cb=1, pending=0
2017-05-09 14:35:06.208642 7f7504a80700 20 librbd::AioCompletion: 0x55b00253eaf0 finalize: r=0, read_buf=0, real_bl=0
2017-05-09 14:35:06.208649 7f7504a80700 20 librbd::AsyncOperation: 0x55b00253ec40 finish_op
2017-05-09 14:35:06.210388 7f7524944100 20 librbd::AioImageRequestWQ: aio_write: ictx=0x55b002539340, completion=0x55b00253eaf0, off=16777216, len=4194304, flags=72
2017-05-09 14:35:06.210397 7f7524944100 20 librbd::AioImageRequestWQ: queue: ictx=0x55b002539340, req=0x55b00253edf0
2017-05-09 14:35:06.210398 7f7524944100 20 librbd::ExclusiveLock: 0x7f74d4007e80 is_lock_owner=1
2017-05-09 14:35:06.210450 7f7505281700 20 librbd::AsyncOperation: 0x55b00253ec40 start_op
2017-05-09 14:35:06.210460 7f7505281700 20 librbd::AioImageRequestWQ: process: ictx=0x55b002539340, req=0x55b00253edf0
2017-05-09 14:35:06.210465 7f7505281700 20 librbd::AioImageRequest: aio_write: ictx=0x55b002539340, completion=0x55b00253eaf0
2017-05-09 14:35:06.210480 7f7505281700 20 librbd::AioCompletion: 0x55b00253eaf0 set_request_count: pending=1
Importing image: 50% complete...2017-05-09 14:35:06.212620 7f7504a80700 20 librbd::AioCompletion: 0x55b00253eaf0 complete_request: cb=1, pending=0
2017-05-09 14:35:06.212630 7f7504a80700 20 librbd::AioCompletion: 0x55b00253eaf0 finalize: r=0, read_buf=0, real_bl=0
2017-05-09 14:35:06.212637 7f7504a80700 20 librbd::AsyncOperation: 0x55b00253ec40 finish_op
2017-05-09 14:35:06.212754 7f74cffff700 20 librbdwriteback: write will wait for result 0x7f74c00009e0
2017-05-09 14:35:06.212849 7f74cffff700 10 librbd::ImageCtx: prune_parent_extents image overlap 0, object overlap 0 from image extents []
2017-05-09 14:35:06.212856 7f74cffff700 20 librbd::AioObjectRequest: send write 0x7f74c0000ee0 rbd_data.8798238e1f29.0000000000000000 0~4194304
2017-05-09 14:35:06.212859 7f74cffff700 20 librbd::ExclusiveLock: 0x7f74d4007e80 is_lock_owner=1
2017-05-09 14:35:06.212865 7f74cffff700 20 librbd::ObjectMap: 0x7f74d4007110 object_may_exist: object_no=0 r=0
2017-05-09 14:35:06.212868 7f74cffff700 20 librbd::AioObjectRequest: send_pre 0x7f74c0000ee0 rbd_data.8798238e1f29.0000000000000000 0~4194304
2017-05-09 14:35:06.212870 7f74cffff700 20 librbd::ObjectMap: 0x7f74d4007110 detained_aio_update: 
2017-05-09 14:35:06.212872 7f74cffff700 20 librbd::BlockGuard: 0x7f74d40072e0 detain: block_start=0, block_end=1, free_slots=0
2017-05-09 14:35:06.212875 7f74cffff700 20 librbd::BlockGuard: 0x7f74d40072e0 detain: no free detained block cells
2017-05-09 14:35:06.212876 7f74cffff700 20 librbd::ObjectMap: 0x7f74d4007110 detained_aio_update: in-flight update cell: 0x7f74d40073f0
2017-05-09 14:35:06.212879 7f74cffff700 20 librbd::ExclusiveLock: 0x7f74d4007e80 is_lock_owner=1
2017-05-09 14:35:06.212880 7f74cffff700 20 librbd::ObjectMap: 0x7f74d4007110 aio_update: start=0, end=1, ->1
2017-05-09 14:35:06.212885 7f74cffff700 20 librbd::object_map::UpdateRequest: 0x7f74c0001e40 updating object map: ictx=0x55b002539340, oid=rbd_object_map.8798238e1f29, [0,1) = ->1
2017-05-09 14:35:06.214363 7f7524944100 20 librbd::AioImageRequestWQ: aio_write: ictx=0x55b002539340, completion=0x55b00253eaf0, off=20971520, len=4194304, flags=72
2017-05-09 14:35:06.214372 7f7524944100 20 librbd::AioImageRequestWQ: queue: ictx=0x55b002539340, req=0x55b00253b1d0
2017-05-09 14:35:06.214374 7f7524944100 20 librbd::ExclusiveLock: 0x7f74d4007e80 is_lock_owner=1
2017-05-09 14:35:06.214391 7f7505281700 20 librbd::AsyncOperation: 0x55b00253ec40 start_op
2017-05-09 14:35:06.214399 7f7505281700 20 librbd::AioImageRequestWQ: process: ictx=0x55b002539340, req=0x55b00253b1d0
2017-05-09 14:35:06.214402 7f7505281700 20 librbd::AioImageRequest: aio_write: ictx=0x55b002539340, completion=0x55b00253eaf0
2017-05-09 14:35:06.214413 7f7505281700 20 librbd::AioCompletion: 0x55b00253eaf0 set_request_count: pending=1
2017-05-09 14:35:06.215281 7f750668b700 20 librbd::object_map::Request: 0x7f74c0001e40 should_complete: r=0
2017-05-09 14:35:06.215302 7f750668b700 20 librbd::object_map::UpdateRequest: 0x7f74c0001e40 on-disk object map updated
2017-05-09 14:35:06.215310 7f750668b700 20 librbd::ObjectMap: 0x7f74d4007110 handle_detained_aio_update: cell=0x7f74d40073f0, r=0
2017-05-09 14:35:06.215317 7f750668b700 20 librbd::BlockGuard: 0x7f74d40072e0 release: block_start=0, block_end=1, pending_ops=0
2017-05-09 14:35:06.215327 7f750668b700 20 librbd::AioObjectRequest: write 0x7f74c0000ee0 rbd_data.8798238e1f29.0000000000000000 0~4194304 should_complete: r = 0
2017-05-09 14:35:06.215332 7f750668b700 20 librbd::AioObjectRequest: WRITE_PRE
2017-05-09 14:35:06.215335 7f750668b700 20 librbd::AioObjectRequest: send_write 0x7f74c0000ee0 rbd_data.8798238e1f29.0000000000000000 0~4194304 object exist 0 write_full 1
Importing image: 61% complete...2017-05-09 14:35:06.216662 7f74cffff700 20 librbdwriteback: write will wait for result 0x7f74c0007090
2017-05-09 14:35:06.216677 7f74cffff700 10 librbd::ImageCtx: prune_parent_extents image overlap 0, object overlap 0 from image extents []
2017-05-09 14:35:06.216681 7f74cffff700 20 librbd::AioObjectRequest: send write 0x7f74c00020d0 rbd_data.8798238e1f29.0000000000000001 0~4194304
2017-05-09 14:35:06.216684 7f74cffff700 20 librbd::ExclusiveLock: 0x7f74d4007e80 is_lock_owner=1
2017-05-09 14:35:06.216689 7f74cffff700 20 librbd::ObjectMap: 0x7f74d4007110 object_may_exist: object_no=1 r=0
2017-05-09 14:35:06.216691 7f74cffff700 20 librbd::AioObjectRequest: send_pre 0x7f74c00020d0 rbd_data.8798238e1f29.0000000000000001 0~4194304
2017-05-09 14:35:06.216693 7f74cffff700 20 librbd::ObjectMap: 0x7f74d4007110 detained_aio_update: 
2017-05-09 14:35:06.216696 7f74cffff700 20 librbd::BlockGuard: 0x7f74d40072e0 detain: block_start=1, block_end=2, free_slots=1
2017-05-09 14:35:06.216698 7f74cffff700 20 librbd::ObjectMap: 0x7f74d4007110 detained_aio_update: in-flight update cell: 0x7f74d40073f0
2017-05-09 14:35:06.216700 7f74cffff700 20 librbd::ExclusiveLock: 0x7f74d4007e80 is_lock_owner=1
2017-05-09 14:35:06.216702 7f74cffff700 20 librbd::ObjectMap: 0x7f74d4007110 aio_update: start=1, end=2, ->1
2017-05-09 14:35:06.216707 7f74cffff700 20 librbd::object_map::UpdateRequest: 0x7f74c0002050 updating object map: ictx=0x55b002539340, oid=rbd_object_map.8798238e1f29, [1,2) = ->1
2017-05-09 14:35:06.216876 7f74cffff700 20 librbdwriteback: write will wait for result 0x7f74c0006950
2017-05-09 14:35:06.216879 7f74cffff700 10 librbd::ImageCtx: prune_parent_extents image overlap 0, object overlap 0 from image extents []
2017-05-09 14:35:06.216882 7f74cffff700 20 librbd::AioObjectRequest: send write 0x7f74c00089d0 rbd_data.8798238e1f29.0000000000000002 0~4194304
2017-05-09 14:35:06.216885 7f74cffff700 20 librbd::ExclusiveLock: 0x7f74d4007e80 is_lock_owner=1
2017-05-09 14:35:06.216891 7f74cffff700 20 librbd::ObjectMap: 0x7f74d4007110 object_may_exist: object_no=2 r=0
2017-05-09 14:35:06.216893 7f74cffff700 20 librbd::AioObjectRequest: send_pre 0x7f74c00089d0 rbd_data.8798238e1f29.0000000000000002 0~4194304
2017-05-09 14:35:06.216895 7f74cffff700 20 librbd::ObjectMap: 0x7f74d4007110 detained_aio_update: 
2017-05-09 14:35:06.216896 7f74cffff700 20 librbd::BlockGuard: 0x7f74d40072e0 detain: block_start=2, block_end=3, free_slots=0
2017-05-09 14:35:06.216898 7f74cffff700 20 librbd::BlockGuard: 0x7f74d40072e0 detain: no free detained block cells
2017-05-09 14:35:06.216899 7f74cffff700 20 librbd::ObjectMap: 0x7f74d4007110 detained_aio_update: in-flight update cell: 0x7f74d4007448
2017-05-09 14:35:06.216901 7f74cffff700 20 librbd::ExclusiveLock: 0x7f74d4007e80 is_lock_owner=1
2017-05-09 14:35:06.216903 7f74cffff700 20 librbd::ObjectMap: 0x7f74d4007110 aio_update: start=2, end=3, ->1
2017-05-09 14:35:06.216906 7f74cffff700 20 librbd::object_map::UpdateRequest: 0x7f74c0009790 updating object map: ictx=0x55b002539340, oid=rbd_object_map.8798238e1f29, [2,3) = ->1
2017-05-09 14:35:06.216977 7f7524944100 20 librbd::AioImageRequestWQ: aio_write: ictx=0x55b002539340, completion=0x55b00253fad0, off=25165824, len=4194304, flags=72
2017-05-09 14:35:06.216981 7f7524944100 20 librbd::AioImageRequestWQ: queue: ictx=0x55b002539340, req=0x55b00253b1d0
2017-05-09 14:35:06.216984 7f7524944100 20 librbd::ExclusiveLock: 0x7f74d4007e80 is_lock_owner=1
2017-05-09 14:35:06.216998 7f7505281700 20 librbd::AsyncOperation: 0x55b00253fc20 start_op
2017-05-09 14:35:06.217004 7f7505281700 20 librbd::AioImageRequestWQ: process: ictx=0x55b002539340, req=0x55b00253b1d0
2017-05-09 14:35:06.217007 7f7505281700 20 librbd::AioImageRequest: aio_write: ictx=0x55b002539340, completion=0x55b00253fad0
2017-05-09 14:35:06.217017 7f7505281700 20 librbd::AioCompletion: 0x55b00253fad0 set_request_count: pending=1
Importing image: 71% complete...2017-05-09 14:35:06.219064 7f750668b700 20 librbd::object_map::Request: 0x7f74c0002050 should_complete: r=0
2017-05-09 14:35:06.219081 7f750668b700 20 librbd::object_map::UpdateRequest: 0x7f74c0002050 on-disk object map updated
2017-05-09 14:35:06.219086 7f750668b700 20 librbd::ObjectMap: 0x7f74d4007110 handle_detained_aio_update: cell=0x7f74d40073f0, r=0
2017-05-09 14:35:06.219086 7f74cffff700 20 librbdwriteback: write will wait for result 0x7f74c0006c70
2017-05-09 14:35:06.219089 7f750668b700 20 librbd::BlockGuard: 0x7f74d40072e0 release: block_start=1, block_end=2, pending_ops=0
2017-05-09 14:35:06.219091 7f74cffff700 10 librbd::ImageCtx: prune_parent_extents image overlap 0, object overlap 0 from image extents []
2017-05-09 14:35:06.219095 7f750668b700 20 librbd::AioObjectRequest: write 0x7f74c00020d0 rbd_data.8798238e1f29.0000000000000001 0~4194304 should_complete: r = 0
2017-05-09 14:35:06.219096 7f74cffff700 20 librbd::AioObjectRequest: send write 0x7f74c00035a0 rbd_data.8798238e1f29.0000000000000003 0~4194304
2017-05-09 14:35:06.219098 7f750668b700 20 librbd::AioObjectRequest: WRITE_PRE
2017-05-09 14:35:06.219100 7f74cffff700 20 librbd::ExclusiveLock: 0x7f74d4007e80 is_lock_owner=1
2017-05-09 14:35:06.219100 7f750668b700 20 librbd::AioObjectRequest: send_write 0x7f74c00020d0 rbd_data.8798238e1f29.0000000000000001 0~4194304 object exist 0 write_full 1
2017-05-09 14:35:06.219103 7f74cffff700 20 librbd::ObjectMap: 0x7f74d4007110 object_may_exist: object_no=3 r=0
2017-05-09 14:35:06.219106 7f74cffff700 20 librbd::AioObjectRequest: send_pre 0x7f74c00035a0 rbd_data.8798238e1f29.0000000000000003 0~4194304
2017-05-09 14:35:06.219108 7f74cffff700 20 librbd::ObjectMap: 0x7f74d4007110 detained_aio_update: 
2017-05-09 14:35:06.219110 7f74cffff700 20 librbd::BlockGuard: 0x7f74d40072e0 detain: block_start=3, block_end=4, free_slots=1
2017-05-09 14:35:06.219114 7f74cffff700 20 librbd::ObjectMap: 0x7f74d4007110 detained_aio_update: in-flight update cell: 0x7f74d40073f0
2017-05-09 14:35:06.219116 7f74cffff700 20 librbd::ExclusiveLock: 0x7f74d4007e80 is_lock_owner=1
2017-05-09 14:35:06.219119 7f74cffff700 20 librbd::ObjectMap: 0x7f74d4007110 aio_update: start=3, end=4, ->1
2017-05-09 14:35:06.219123 7f74cffff700 20 librbd::object_map::UpdateRequest: 0x7f74c0007120 updating object map: ictx=0x55b002539340, oid=rbd_object_map.8798238e1f29, [3,4) = ->1
2017-05-09 14:35:06.220848 7f750668b700 20 librbd::object_map::Request: 0x7f74c0009790 should_complete: r=0
2017-05-09 14:35:06.220864 7f750668b700 20 librbd::object_map::UpdateRequest: 0x7f74c0009790 on-disk object map updated
2017-05-09 14:35:06.220869 7f750668b700 20 librbd::ObjectMap: 0x7f74d4007110 handle_detained_aio_update: cell=0x7f74d4007448, r=0
2017-05-09 14:35:06.220871 7f750668b700 20 librbd::BlockGuard: 0x7f74d40072e0 release: block_start=2, block_end=3, pending_ops=0
2017-05-09 14:35:06.220876 7f750668b700 20 librbd::AioObjectRequest: write 0x7f74c00089d0 rbd_data.8798238e1f29.0000000000000002 0~4194304 should_complete: r = 0
2017-05-09 14:35:06.220879 7f750668b700 20 librbd::AioObjectRequest: WRITE_PRE
2017-05-09 14:35:06.220881 7f750668b700 20 librbd::AioObjectRequest: send_write 0x7f74c00089d0 rbd_data.8798238e1f29.0000000000000002 0~4194304 object exist 0 write_full 1
2017-05-09 14:35:06.221081 7f7524944100 20 librbd::AioImageRequestWQ: aio_write: ictx=0x55b002539340, completion=0x55b0025400b0, off=29360128, len=4194304, flags=72
2017-05-09 14:35:06.221092 7f7524944100 20 librbd::AioImageRequestWQ: queue: ictx=0x55b002539340, req=0x55b00253b1d0
2017-05-09 14:35:06.221095 7f7524944100 20 librbd::ExclusiveLock: 0x7f74d4007e80 is_lock_owner=1
2017-05-09 14:35:06.221109 7f7505281700 20 librbd::AsyncOperation: 0x55b002540200 start_op
2017-05-09 14:35:06.221116 7f7505281700 20 librbd::AioImageRequestWQ: process: ictx=0x55b002539340, req=0x55b00253b1d0
2017-05-09 14:35:06.221119 7f7505281700 20 librbd::AioImageRequest: aio_write: ictx=0x55b002539340, completion=0x55b0025400b0
2017-05-09 14:35:06.221139 7f7505281700 20 librbd::AioCompletion: 0x55b0025400b0 set_request_count: pending=1
2017-05-09 14:35:06.222425 7f750668b700 20 librbd::object_map::Request: 0x7f74c0007120 should_complete: r=0
2017-05-09 14:35:06.222440 7f750668b700 20 librbd::object_map::UpdateRequest: 0x7f74c0007120 on-disk object map updated
2017-05-09 14:35:06.222444 7f750668b700 20 librbd::ObjectMap: 0x7f74d4007110 handle_detained_aio_update: cell=0x7f74d40073f0, r=0
2017-05-09 14:35:06.222447 7f750668b700 20 librbd::BlockGuard: 0x7f74d40072e0 release: block_start=3, block_end=4, pending_ops=0
2017-05-09 14:35:06.222451 7f750668b700 20 librbd::AioObjectRequest: write 0x7f74c00035a0 rbd_data.8798238e1f29.0000000000000003 0~4194304 should_complete: r = 0
2017-05-09 14:35:06.222454 7f750668b700 20 librbd::AioObjectRequest: WRITE_PRE
2017-05-09 14:35:06.222455 7f750668b700 20 librbd::AioObjectRequest: send_write 0x7f74c00035a0 rbd_data.8798238e1f29.0000000000000003 0~4194304 object exist 0 write_full 1
2017-05-09 14:35:06.223467 7f74cffff700 20 librbdwriteback: write will wait for result 0x7f74c00068b0
2017-05-09 14:35:06.223483 7f74cffff700 10 librbd::ImageCtx: prune_parent_extents image overlap 0, object overlap 0 from image extents []
2017-05-09 14:35:06.223487 7f74cffff700 20 librbd::AioObjectRequest: send write 0x7f74c00072f0 rbd_data.8798238e1f29.0000000000000004 0~4194304
2017-05-09 14:35:06.223490 7f74cffff700 20 librbd::ExclusiveLock: 0x7f74d4007e80 is_lock_owner=1
2017-05-09 14:35:06.223495 7f74cffff700 20 librbd::ObjectMap: 0x7f74d4007110 object_may_exist: object_no=4 r=0
2017-05-09 14:35:06.223497 7f74cffff700 20 librbd::AioObjectRequest: send_pre 0x7f74c00072f0 rbd_data.8798238e1f29.0000000000000004 0~4194304
2017-05-09 14:35:06.223500 7f74cffff700 20 librbd::ObjectMap: 0x7f74d4007110 detained_aio_update: 
2017-05-09 14:35:06.223501 7f74cffff700 20 librbd::BlockGuard: 0x7f74d40072e0 detain: block_start=4, block_end=5, free_slots=2
2017-05-09 14:35:06.223504 7f74cffff700 20 librbd::ObjectMap: 0x7f74d4007110 detained_aio_update: in-flight update cell: 0x7f74d4007448
2017-05-09 14:35:06.223506 7f74cffff700 20 librbd::ExclusiveLock: 0x7f74d4007e80 is_lock_owner=1
Importing image: 81% complete...ffff700 20 librbd::ObjectMap: 0x7f74d4007110 aio_update: start=4, end=5, ->1
2017-05-09 14:35:06.223513 7f74cffff700 20 librbd::object_map::UpdateRequest: 0x7f74c0003080 updating object map: ictx=0x55b002539340, oid=rbd_object_map.8798238e1f29, [4,5) = ->1
2017-05-09 14:35:06.225880 7f750668b700 20 librbd::object_map::Request: 0x7f74c0003080 should_complete: r=0
2017-05-09 14:35:06.225895 7f750668b700 20 librbd::object_map::UpdateRequest: 0x7f74c0003080 on-disk object map updated
2017-05-09 14:35:06.225900 7f750668b700 20 librbd::ObjectMap: 0x7f74d4007110 handle_detained_aio_update: cell=0x7f74d4007448, r=0
2017-05-09 14:35:06.225903 7f750668b700 20 librbd::BlockGuard: 0x7f74d40072e0 release: block_start=4, block_end=5, pending_ops=0
2017-05-09 14:35:06.225908 7f750668b700 20 librbd::AioObjectRequest: write 0x7f74c00072f0 rbd_data.8798238e1f29.0000000000000004 0~4194304 should_complete: r = 0
2017-05-09 14:35:06.225911 7f750668b700 20 librbd::AioObjectRequest: WRITE_PRE
2017-05-09 14:35:06.225919 7f750668b700 20 librbd::AioObjectRequest: send_write 0x7f74c00072f0 rbd_data.8798238e1f29.0000000000000004 0~4194304 object exist 0 write_full 1
Importing image: 91% complete...2017-05-09 14:35:06.248034 7f750668b700 20 librbd::AioObjectRequest: write 0x7f74c00089d0 rbd_data.8798238e1f29.0000000000000002 0~4194304 should_complete: r = 0
2017-05-09 14:35:06.248053 7f750668b700 20 librbd::AioObjectRequest: WRITE_FLAT
2017-05-09 14:35:06.248056 7f750668b700 20 librbd::AioObjectRequest: complete 0x7f74c00089d0
2017-05-09 14:35:06.248059 7f750668b700 20 librbdwriteback: C_OrderedWrite completing 0x7f74c0006950
2017-05-09 14:35:06.248070 7f750668b700 20 librbdwriteback: complete_writes() oid rbd_data.8798238e1f29.0000000000000002
2017-05-09 14:35:06.248073 7f750668b700 20 librbdwriteback: complete_writes() completing 0x7f74c0006950
2017-05-09 14:35:06.248087 7f750668b700 20 librbdwriteback: C_OrderedWrite finished 0x7f74c0006950
2017-05-09 14:35:07.248234 7f74cffff700 20 librbdwriteback: write will wait for result 0x7f74c0006950
2017-05-09 14:35:07.248251 7f74cffff700 10 librbd::ImageCtx: prune_parent_extents image overlap 0, object overlap 0 from image extents []
2017-05-09 14:35:07.248267 7f74cffff700 20 librbd::AioObjectRequest: send write 0x7f74c00080b0 rbd_data.8798238e1f29.0000000000000005 0~4194304
2017-05-09 14:35:07.248270 7f74cffff700 20 librbd::ExclusiveLock: 0x7f74d4007e80 is_lock_owner=1
2017-05-09 14:35:07.248275 7f74cffff700 20 librbd::ObjectMap: 0x7f74d4007110 object_may_exist: object_no=5 r=0
2017-05-09 14:35:07.248278 7f74cffff700 20 librbd::AioObjectRequest: send_pre 0x7f74c00080b0 rbd_data.8798238e1f29.0000000000000005 0~4194304
2017-05-09 14:35:07.248280 7f74cffff700 20 librbd::ObjectMap: 0x7f74d4007110 detained_aio_update: 
2017-05-09 14:35:07.248284 7f74cffff700 20 librbd::BlockGuard: 0x7f74d40072e0 detain: block_start=5, block_end=6, free_slots=2
2017-05-09 14:35:07.248287 7f74cffff700 20 librbd::ObjectMap: 0x7f74d4007110 detained_aio_update: in-flight update cell: 0x7f74d40073f0
2017-05-09 14:35:07.248289 7f74cffff700 20 librbd::ExclusiveLock: 0x7f74d4007e80 is_lock_owner=1
2017-05-09 14:35:07.248290 7f74cffff700 20 librbd::ObjectMap: 0x7f74d4007110 aio_update: start=5, end=6, ->1
2017-05-09 14:35:07.248295 7f74cffff700 20 librbd::object_map::UpdateRequest: 0x7f74c0006d00 updating object map: ictx=0x55b002539340, oid=rbd_object_map.8798238e1f29, [5,6) = ->1
2017-05-09 14:35:07.248434 7f74cffff700 20 librbdwriteback: write will wait for result 0x7f74c0008480
2017-05-09 14:35:07.248438 7f74cffff700 10 librbd::ImageCtx: prune_parent_extents image overlap 0, object overlap 0 from image extents []
2017-05-09 14:35:07.248441 7f74cffff700 20 librbd::AioObjectRequest: send write 0x7f74c000d2f0 rbd_data.8798238e1f29.0000000000000006 0~4194304
2017-05-09 14:35:07.248444 7f74cffff700 20 librbd::ExclusiveLock: 0x7f74d4007e80 is_lock_owner=1
2017-05-09 14:35:07.248446 7f74cffff700 20 librbd::ObjectMap: 0x7f74d4007110 object_may_exist: object_no=6 r=0
2017-05-09 14:35:07.248448 7f74cffff700 20 librbd::AioObjectRequest: send_pre 0x7f74c000d2f0 rbd_data.8798238e1f29.0000000000000006 0~4194304
2017-05-09 14:35:07.248450 7f74cffff700 20 librbd::ObjectMap: 0x7f74d4007110 detained_aio_update: 
2017-05-09 14:35:07.248451 7f74cffff700 20 librbd::BlockGuard: 0x7f74d40072e0 detain: block_start=6, block_end=7, free_slots=1
2017-05-09 14:35:07.248453 7f74cffff700 20 librbd::ObjectMap: 0x7f74d4007110 detained_aio_update: in-flight update cell: 0x7f74d4007448
2017-05-09 14:35:07.248455 7f74cffff700 20 librbd::ExclusiveLock: 0x7f74d4007e80 is_lock_owner=1
2017-05-09 14:35:07.248457 7f74cffff700 20 librbd::ObjectMap: 0x7f74d4007110 aio_update: start=6, end=7, ->1
2017-05-09 14:35:07.248471 7f74cffff700 20 librbd::object_map::UpdateRequest: 0x7f74c000dfb0 updating object map: ictx=0x55b002539340, oid=rbd_object_map.8798238e1f29, [6,7) = ->1
2017-05-09 14:35:07.248536 7f74cffff700 20 librbdwriteback: write will wait for result 0x7f74c0013220
2017-05-09 14:35:07.248541 7f74cffff700 10 librbd::ImageCtx: prune_parent_extents image overlap 0, object overlap 0 from image extents []
2017-05-09 14:35:07.248544 7f74cffff700 20 librbd::AioObjectRequest: send write 0x7f74c0013700 rbd_data.8798238e1f29.0000000000000007 0~4194304
2017-05-09 14:35:07.248546 7f74cffff700 20 librbd::ExclusiveLock: 0x7f74d4007e80 is_lock_owner=1
2017-05-09 14:35:07.248550 7f74cffff700 20 librbd::ObjectMap: 0x7f74d4007110 object_may_exist: object_no=7 r=0
2017-05-09 14:35:07.248552 7f74cffff700 20 librbd::AioObjectRequest: send_pre 0x7f74c0013700 rbd_data.8798238e1f29.0000000000000007 0~4194304
2017-05-09 14:35:07.248553 7f74cffff700 20 librbd::ObjectMap: 0x7f74d4007110 detained_aio_update: 
2017-05-09 14:35:07.248558 7f74cffff700 20 librbd::BlockGuard: 0x7f74d40072e0 detain: block_start=7, block_end=8, free_slots=0
2017-05-09 14:35:07.248559 7f74cffff700 20 librbd::BlockGuard: 0x7f74d40072e0 detain: no free detained block cells
2017-05-09 14:35:07.248561 7f74cffff700 20 librbd::ObjectMap: 0x7f74d4007110 detained_aio_update: in-flight update cell: 0x7f74d40074a0
2017-05-09 14:35:07.248563 7f74cffff700 20 librbd::ExclusiveLock: 0x7f74d4007e80 is_lock_owner=1
2017-05-09 14:35:07.248564 7f74cffff700 20 librbd::ObjectMap: 0x7f74d4007110 aio_update: start=7, end=8, ->1
2017-05-09 14:35:07.248567 7f74cffff700 20 librbd::object_map::UpdateRequest: 0x7f74c0014470 updating object map: ictx=0x55b002539340, oid=rbd_object_map.8798238e1f29, [7,8) = ->1

After the librbd::object_map::UpdateRequest line, the client just hangs.

In the RBD pool, all that is created are the ID and header objects, the object map, and a single data object:

# rados -p images ls | grep -E "(8798238e1f29|cirros-0.3.5-x86_64-disk.raw)" 
rbd_header.8798238e1f29
rbd_data.8798238e1f29.0000000000000002
rbd_object_map.8798238e1f29
rbd_id.cirros-0.3.5-x86_64-disk.raw

This means that if a user first upgrades their cluster to Kraken (or Luminous, presumably, though I haven't been able to test that), and leaves their client libraries at Jewel to update them later (as recommended in http://docs.ceph.com/docs/master/install/upgrading-ceph/#upgrading-a-client), they're left with non-functional clients during the transition period.

Since OpenStack Glance relies on rbd import-equivalent functionality, OpenStack upgrades are particularly affected by this problem.