Actions
Bug #19889
closedrbd/compatibility: rbd import fails with Jewel client, Kraken OSDs (breaks rolling upgrade)
Status:
Closed
Priority:
Normal
Assignee:
Jason Dillaman
Target version:
-
% Done:
0%
Source:
Tags:
Backport:
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Pull request ID:
Crash signature (v1):
Crash signature (v2):
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.
Actions