Bug #19889
closedrbd/compatibility: rbd import fails with Jewel client, Kraken OSDs (breaks rolling upgrade)
0%
Description
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.
Updated by Florian Haas almost 7 years ago
Additional update: good news and bad news.
The good news is that upgrading the client to Kraken fixes rbd import
.
The bad news is that if an image was created (abortively) with Jewel, then a Jewel client can still delete the image. Post-upgrade, that no longer works. Here's what happens if you try (and fail) to import an image with a Jewel librbd, then upgrade that to Kraken, then try to remove with a Kraken librbd:
rbd -p images rm cirros-test 2017-05-09 14:56:55.106173 7f9ac93023c0 20 librbd: remove 0x7fff52af0d50 cirros-test 2017-05-09 14:56:55.106327 7f9ac93023c0 5 librbd::AioImageRequestWQ: 0x561b23ad2a90 : ictx=0x561b23ad1650 2017-05-09 14:56:55.106341 7f9ac93023c0 20 librbd::ImageState: 0x561b23a363d0 open 2017-05-09 14:56:55.106346 7f9ac93023c0 10 librbd::ImageState: 0x561b23a363d0 0x561b23a363d0 send_open_unlock 2017-05-09 14:56:55.106350 7f9ac93023c0 10 librbd::image::OpenRequest: 0x561b23ad3750 send_v2_detect_header 2017-05-09 14:56:55.107838 7f9aa27fc700 10 librbd::image::OpenRequest: handle_v2_detect_header: r=-2 2017-05-09 14:56:55.109122 7f9aa27fc700 10 librbd::image::OpenRequest: handle_v1_detect_header: r=-2 2017-05-09 14:56:55.109135 7f9aa27fc700 10 librbd::image::OpenRequest: 0x561b23ad3750 send_close_image 2017-05-09 14:56:55.109139 7f9aa27fc700 10 librbd::image::CloseRequest: 0x7f9a98000f40 send_shut_down_update_watchers 2017-05-09 14:56:55.109141 7f9aa27fc700 20 librbd::ImageState: 0x561b23a363d0 shut_down_update_watchers 2017-05-09 14:56:55.109143 7f9aa27fc700 20 librbd::ImageState: 0x561b23ad20c0 ImageUpdateWatchers::shut_down 2017-05-09 14:56:55.109146 7f9aa27fc700 20 librbd::ImageState: 0x561b23ad20c0 ImageUpdateWatchers::shut_down: completing shut down 2017-05-09 14:56:55.109186 7f9aa1ffb700 10 librbd::image::CloseRequest: 0x7f9a98000f40 handle_shut_down_update_watchers: r=0 2017-05-09 14:56:55.109197 7f9aa1ffb700 10 librbd::image::CloseRequest: 0x7f9a98000f40 send_shut_down_aio_queue 2017-05-09 14:56:55.109206 7f9aa1ffb700 5 librbd::AioImageRequestWQ: shut_down: in_flight=0 2017-05-09 14:56:55.109221 7f9aa1ffb700 10 librbd::image::CloseRequest: 0x7f9a98000f40 handle_shut_down_aio_queue: r=0 2017-05-09 14:56:55.109224 7f9aa1ffb700 10 librbd::image::CloseRequest: 0x7f9a98000f40 send_flush 2017-05-09 14:56:55.109228 7f9aa1ffb700 10 librbd::image::CloseRequest: 0x7f9a98000f40 handle_flush: r=0 2017-05-09 14:56:55.109230 7f9aa1ffb700 10 librbd::image::CloseRequest: 0x7f9a98000f40 send_flush_readahead 2017-05-09 14:56:55.109233 7f9aa1ffb700 10 librbd::image::CloseRequest: 0x7f9a98000f40 handle_flush_readahead: r=0 2017-05-09 14:56:55.109235 7f9aa1ffb700 10 librbd::image::CloseRequest: 0x7f9a98000f40 send_shut_down_cache 2017-05-09 14:56:55.109237 7f9aa1ffb700 10 librbd::image::CloseRequest: 0x7f9a98000f40 handle_shut_down_cache: r=0 2017-05-09 14:56:55.109238 7f9aa1ffb700 10 librbd::image::CloseRequest: 0x7f9a98000f40 send_flush_op_work_queue 2017-05-09 14:56:55.109241 7f9aa1ffb700 10 librbd::image::CloseRequest: 0x7f9a98000f40 handle_flush_op_work_queue: r=0 2017-05-09 14:56:55.109243 7f9aa1ffb700 10 librbd::image::OpenRequest: handle_close_image: r=0 2017-05-09 14:56:55.109256 7f9aa1ffb700 10 librbd::ImageState: 0x561b23a363d0 0x561b23a363d0 handle_open: r=-2 2017-05-09 14:56:55.109293 7f9ac93023c0 2 librbd: error opening image: (2) No such file or directory 2017-05-09 14:56:55.109333 7f9ac93023c0 2 librbd: removing rbd image from v1 directory... 2017-05-09 14:56:55.112120 7f9ac93023c0 5 librbd: attempting to determine image id 2017-05-09 14:56:55.112784 7f9ac93023c0 2 librbd: removing id object... 2017-05-09 14:56:55.114962 7f9ac93023c0 2 librbd: removing rbd image from v2 directory... Removing image: 0% complete...failed. rbd: delete error: (2) No such file or directory
Updated by Florian Haas almost 7 years ago
I should add (on the last comment) that I only saw this deletion issue with one image out of three where import previously failed. The other two did correctly get removed. So maybe that part was a spurious issue.
Updated by Jason Dillaman almost 7 years ago
- Status changed from New to In Progress
- Assignee set to Jason Dillaman
Updated by Jason Dillaman almost 7 years ago
For some reason, the calls to update the object map never completed (even though they had worked a few milliseconds beforehand):
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.215302 7f750668b700 20 librbd::object_map::UpdateRequest: 0x7f74c0001e40 on-disk object map updated ... 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.219081 7f750668b700 20 librbd::object_map::UpdateRequest: 0x7f74c0002050 on-disk object map updated ... 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.220864 7f750668b700 20 librbd::object_map::UpdateRequest: 0x7f74c0009790 on-disk object map updated ... 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.222440 7f750668b700 20 librbd::object_map::UpdateRequest: 0x7f74c0007120 on-disk object map updated ... 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.225895 7f750668b700 20 librbd::object_map::UpdateRequest: 0x7f74c0003080 on-disk object map updated ... 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.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.248567 7f74cffff700 20 librbd::object_map::UpdateRequest: 0x7f74c0014470 updating object map: ictx=0x55b002539340, oid=rbd_object_map.8798238e1f29, [7,8) = ->1
I suspect examining the blocked ops would reveal that the OSDs stopped responding.
Updated by Florian Haas almost 7 years ago
OK, any clues as to why this would only occur in combination between a Jewel client and a Kraken cluster?
Updated by Jason Dillaman almost 7 years ago
- Status changed from In Progress to Need More Info
Updated by Jason Dillaman over 6 years ago
- Status changed from Need More Info to Closed
Closing due to lack of input. Please re-open if data can be provided.