Project

General

Profile

Actions
Copy link

Bug #58740

closed

"rbd feature disable" remote request hangs when proxied to rbd-nbd

Added by Ilya Dryomov over 1 year ago. Updated 3 months ago.

Status:
Resolved
Priority:
Normal
Assignee:
Prasanna Kumar Kalever
Target version:
-
% Done:

0%

Source:
Tags:
backport_processed
Backport:
pacific,quincy,reef
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Pull request ID:
50593
Crash signature (v1):
Crash signature (v2):

Description

This came up with the jounaling feature but happens with e.g. object-map as well:

$ rbd create --size 10 img
$ sudo rbd device map -t nbd img
$ rbd feature enable img journaling
$ sudo blkdiscard -o 0 -l 4096 /dev/nbd0
$ rbd feature disable img journaling
<hangs in an infinite loop>

Remote request ETIMEDOUT handling logic appears to be involved:
2023-02-15T18:45:20.334-0500 7fb7e21bc740  5 librbd::Operations: 0x562e6436dfb0 update_features: features=64, enabled=0
2023-02-15T18:45:20.334-0500 7fb7e21bc740 20 librbd::ManagedLock: 0x7fb7a8001d48 is_lock_owner: =0
2023-02-15T18:45:20.334-0500 7fb7e21bc740 20 librbd::Operations: send_acquire_exclusive_lock
2023-02-15T18:45:20.334-0500 7fb7e21bc740 10 librbd::ManagedLock: 0x7fb7a8001d48 try_acquire_lock: 
2023-02-15T18:45:20.334-0500 7fb7e21bc740 10 librbd::ManagedLock: 0x7fb7a8001d48 send_acquire_lock: 
2023-02-15T18:45:20.334-0500 7fb7dacdd700 10 librbd::ExclusiveLock: 0x7fb7a8001d30 pre_acquire_lock_handler
2023-02-15T18:45:20.334-0500 7fb7dacdd700 10 librbd::exclusive_lock::PreAcquireRequest: 0x7fb7d4004aa0 send_prepare_lock: 
2023-02-15T18:45:20.334-0500 7fb7dacdd700 10 librbd::ImageState: 0x7fb7cc004b80 prepare_lock
2023-02-15T18:45:20.334-0500 7fb7dacdd700 10 librbd::ImageState: 0x7fb7cc004b80 0x7fb7cc004b80 send_prepare_lock_unlock
2023-02-15T18:45:20.334-0500 7fb7dacdd700 10 librbd::exclusive_lock::PreAcquireRequest: 0x7fb7d4004aa0 handle_prepare_lock: r=0
2023-02-15T18:45:20.334-0500 7fb7dacdd700 10 librbd::exclusive_lock::PreAcquireRequest: 0x7fb7d4004aa0 send_flush_notifies: 
2023-02-15T18:45:20.334-0500 7fb7dacdd700 10 librbd::exclusive_lock::PreAcquireRequest: 0x7fb7d4004aa0 handle_flush_notifies: 
2023-02-15T18:45:20.334-0500 7fb7dacdd700 10 librbd::ManagedLock: 0x7fb7a8001d48 handle_pre_acquire_lock: r=0
2023-02-15T18:45:20.334-0500 7fb7dacdd700 10 librbd::managed_lock::AcquireRequest: 0x7fb7a80023e0 send_get_locker: 
2023-02-15T18:45:20.334-0500 7fb7dacdd700 10 librbd::managed_lock::GetLockerRequest: 0x7fb7a8002bc0 send_get_lockers: 
2023-02-15T18:45:20.334-0500 7fb7db4de700 10 librbd::managed_lock::GetLockerRequest: 0x7fb7a8002bc0 handle_get_lockers: r=0
2023-02-15T18:45:20.334-0500 7fb7db4de700 10 librbd::managed_lock::GetLockerRequest: 0x7fb7a8002bc0 handle_get_lockers: retrieved exclusive locker: client.4447@172.21.9.34:0/856653073
2023-02-15T18:45:20.334-0500 7fb7db4de700 10 librbd::managed_lock::GetLockerRequest: 0x7fb7a8002bc0 finish: r=0
2023-02-15T18:45:20.334-0500 7fb7db4de700 10 librbd::managed_lock::AcquireRequest: 0x7fb7a80023e0 handle_get_locker: r=0
2023-02-15T18:45:20.334-0500 7fb7db4de700 10 librbd::managed_lock::AcquireRequest: 0x7fb7a80023e0 send_lock: entity=client.4451, cookie=auto 140426774332400
2023-02-15T18:45:20.338-0500 7fb7dacdd700 10 librbd::managed_lock::AcquireRequest: 0x7fb7a80023e0 handle_lock: r=-16
2023-02-15T18:45:20.338-0500 7fb7dacdd700 10 librbd::managed_lock::AcquireRequest: 0x7fb7a80023e0 send_break_lock: 
2023-02-15T18:45:20.338-0500 7fb7dacdd700 10 librbd::managed_lock::BreakRequest: 0x7fb7a8004b50 send_get_watchers: 
2023-02-15T18:45:20.338-0500 7fb7db4de700 10 librbd::managed_lock::BreakRequest: 0x7fb7a8004b50 handle_get_watchers: r=0
2023-02-15T18:45:20.338-0500 7fb7db4de700 20 librbd::managed_lock::BreakRequest: 0x7fb7a8004b50 handle_get_watchers: watcher=[addr=172.21.9.34:0/1604494228, entity=client.4451]
2023-02-15T18:45:20.338-0500 7fb7db4de700 20 librbd::managed_lock::BreakRequest: 0x7fb7a8004b50 handle_get_watchers: watcher=[addr=172.21.9.34:0/856653073, entity=client.4447]
2023-02-15T18:45:20.338-0500 7fb7db4de700 10 librbd::managed_lock::BreakRequest: 0x7fb7a8004b50 handle_get_watchers: lock owner is still alive
2023-02-15T18:45:20.338-0500 7fb7db4de700 10 librbd::managed_lock::BreakRequest: 0x7fb7a8004b50 finish: r=-11
2023-02-15T18:45:20.338-0500 7fb7db4de700 10 librbd::managed_lock::AcquireRequest: 0x7fb7a80023e0 handle_break_lock: r=-11
2023-02-15T18:45:20.338-0500 7fb7db4de700  5 librbd::managed_lock::AcquireRequest: 0x7fb7a80023e0 handle_break_lock: lock owner is still alive
2023-02-15T18:45:20.338-0500 7fb7db4de700 10 librbd::ManagedLock: 0x7fb7a8001d48 handle_acquire_lock: r=-11
2023-02-15T18:45:20.338-0500 7fb7db4de700  5 librbd::ManagedLock: 0x7fb7a8001d48 handle_acquire_lock: unable to acquire exclusive lock
2023-02-15T18:45:20.338-0500 7fb7db4de700 10 librbd::ExclusiveLock: 0x7fb7a8001d30 post_acquire_lock_handler: r=-11
2023-02-15T18:45:20.338-0500 7fb7db4de700 10 librbd::ImageState: 0x7fb7cc004b80 handle_prepare_lock_complete
2023-02-15T18:45:20.338-0500 7fb7db4de700 10 librbd::ManagedLock: 0x7fb7a8001d48 handle_post_acquire_lock: r=0
2023-02-15T18:45:20.338-0500 7fb7db4de700 20 librbd::Operations: handle_acquire_exclusive_lock: r=0
2023-02-15T18:45:20.338-0500 7fb7db4de700 20 librbd::ManagedLock: 0x7fb7a8001d48 is_lock_owner: =0
2023-02-15T18:45:20.338-0500 7fb7db4de700 20 librbd::Operations: send_remote_request
2023-02-15T18:45:20.338-0500 7fb7db4de700 20 librbd::ManagedLock: 0x7fb7a8001d48 is_lock_owner: =0
2023-02-15T18:45:20.338-0500 7fb7db4de700 10 librbd::ImageWatcher: 0x7fb7ac008710 async request: [4451,140426774332400,1]
2023-02-15T18:45:20.338-0500 7fb7db4de700 20 librbd::ImageWatcher: scheduling async request time out: [4451,140426774332400,1]
2023-02-15T18:45:20.338-0500 7fb7db4de700 20 librbd::image_watcher::NotifyLockOwner: 0x7fb7d4023000 send_notify
2023-02-15T18:45:20.338-0500 7fb7db4de700 20 librbd::watcher::Notifier: 0x7fb7ac0087d0 notify: pending=1
2023-02-15T18:45:20.342-0500 7fb7dacdd700  5 librbd::Watcher: 0x7fb7ac008710 notifications_blocked: blocked=0
2023-02-15T18:45:20.342-0500 7fb7dacdd700 10 librbd::Watcher::C_NotifyAck 0x7fb7ac017cb0 C_NotifyAck: id=94489543918, handle=140426774332400
2023-02-15T18:45:20.342-0500 7fb7dacdd700 10 librbd::ImageWatcher: 0x7fb7ac008710 remote update_features request: [4451,140426774332400,1] 64 disabled
2023-02-15T18:45:20.342-0500 7fb7dacdd700 20 librbd::ExclusiveLock: 0x7fb7a8001d30 accept_request=0 (request_type=0)
2023-02-15T18:45:20.342-0500 7fb7dacdd700 10 librbd::Watcher::C_NotifyAck 0x7fb7ac017cb0 finish: r=0
2023-02-15T18:45:20.342-0500 7fb7db4de700 20 librbd::watcher::Notifier: 0x7fb7ac0087d0 handle_notify: r=0
2023-02-15T18:45:20.342-0500 7fb7db4de700 20 librbd::watcher::Notifier: 0x7fb7ac0087d0 handle_notify: pending=0
2023-02-15T18:45:20.342-0500 7fb7db4de700 20 librbd::image_watcher::NotifyLockOwner: 0x7fb7d4023000 handle_notify: r=0
2023-02-15T18:45:20.342-0500 7fb7db4de700 20 librbd::image_watcher::NotifyLockOwner: 0x7fb7d4023000 handle_notify client responded with r=0
2023-02-15T18:45:20.390-0500 7fb7db4de700  5 librbd::Watcher: 0x7fb7ac008710 notifications_blocked: blocked=0
2023-02-15T18:45:20.390-0500 7fb7db4de700 10 librbd::Watcher::C_NotifyAck 0x7fb7a8002bc0 C_NotifyAck: id=94489543919, handle=140426774332400
2023-02-15T18:45:20.390-0500 7fb7db4de700 10 librbd::ImageWatcher: 0x7fb7ac008710 image header updated
2023-02-15T18:45:20.390-0500 7fb7db4de700 20 librbd::ImageState: 0x7fb7cc004b80 handle_update_notification: refresh_seq = 1, last_refresh = 0
2023-02-15T18:45:20.390-0500 7fb7db4de700 20 librbd::ImageState: 0x562e64503870 ImageUpdateWatchers::notify
2023-02-15T18:45:20.390-0500 7fb7db4de700 20 librbd::ImageState: 0x7fb7cc004b80 flush_update_watchers
2023-02-15T18:45:20.390-0500 7fb7db4de700 20 librbd::ImageState: 0x562e64503870 ImageUpdateWatchers::flush
2023-02-15T18:45:20.390-0500 7fb7db4de700 20 librbd::ImageState: 0x562e64503870 ImageUpdateWatchers::flush: completing flush
2023-02-15T18:45:20.390-0500 7fb7db4de700 10 librbd::ImageWatcher: 0x7fb7d4004690 C_ResponseMessage: r=0
2023-02-15T18:45:20.390-0500 7fb7db4de700 10 librbd::Watcher::C_NotifyAck 0x7fb7a8002bc0 finish: r=0
2023-02-15T18:45:25.390-0500 7fb7dacdd700  5 librbd::Watcher: 0x7fb7ac008710 notifications_blocked: blocked=0
2023-02-15T18:45:25.390-0500 7fb7dacdd700 10 librbd::Watcher::C_NotifyAck 0x7fb794002da0 C_NotifyAck: id=94489543920, handle=140426774332400
2023-02-15T18:45:25.390-0500 7fb7dacdd700 20 librbd::ImageWatcher: remove_async_request: [4451,140426774332400,1]
2023-02-15T18:45:25.390-0500 7fb7dacdd700 10 librbd::ImageWatcher: 0x7fb7ac008710 request finished: [4451,140426774332400,1]=-110
2023-02-15T18:45:25.390-0500 7fb7dacdd700 10 librbd::Watcher::C_NotifyAck 0x7fb794002da0 finish: r=0
2023-02-15T18:45:25.390-0500 7fb7dacdd700 20 librbd::Operations: handle_remote_request: r=-110
2023-02-15T18:45:25.390-0500 7fb7dacdd700  5 librbd::Operations: update features timed out notifying lock owner

2023-02-15T18:45:25.390-0500 7fb7dacdd700 20 librbd::Operations: send_refresh_image
2023-02-15T18:45:25.390-0500 7fb7dacdd700 20 librbd::ImageState: 0x7fb7cc004b80 refresh
2023-02-15T18:45:25.390-0500 7fb7dacdd700 10 librbd::ImageState: 0x7fb7cc004b80 0x7fb7cc004b80 send_refresh_unlock
2023-02-15T18:45:25.390-0500 7fb7dacdd700 10 librbd::image::RefreshRequest: 0x7fb7ac00f040 send_v2_get_mutable_metadata
2023-02-15T18:45:25.394-0500 7fb7db4de700 10 librbd::image::RefreshRequest: 0x7fb7ac00f040 handle_v2_get_mutable_metadata: r=0
2023-02-15T18:45:25.394-0500 7fb7db4de700 10 librbd::image::RefreshRequest: 0x7fb7ac00f040 send_v2_get_parent: legacy=0
2023-02-15T18:45:25.394-0500 7fb7dacdd700 10 librbd::image::RefreshRequest: 0x7fb7ac00f040 handle_v2_get_parent: r=0
2023-02-15T18:45:25.394-0500 7fb7dacdd700 10 librbd::image::RefreshRequest: 0x7fb7ac00f040 send_v2_get_metadata
2023-02-15T18:45:25.394-0500 7fb7dacdd700 15 librbd::image::GetMetadataRequest: 0x7fb7d4024040 metadata_list: start_key=conf_
2023-02-15T18:45:25.394-0500 7fb7db4de700 15 librbd::image::GetMetadataRequest: 0x7fb7d4024040 handle_metadata_list: r=0
2023-02-15T18:45:25.394-0500 7fb7db4de700 15 librbd::image::GetMetadataRequest: 0x7fb7d4024040 finish: r=0
2023-02-15T18:45:25.394-0500 7fb7db4de700 10 librbd::image::RefreshRequest: 0x7fb7ac00f040 handle_v2_get_metadata: r=0
2023-02-15T18:45:25.394-0500 7fb7db4de700 10 librbd::image::RefreshRequest: 0x7fb7ac00f040 send_v2_get_pool_metadata
2023-02-15T18:45:25.394-0500 7fb7db4de700 15 librbd::image::GetMetadataRequest: 0x7fb7ac019ff0 metadata_list: start_key=conf_
2023-02-15T18:45:25.394-0500 7fb7dacdd700 15 librbd::image::GetMetadataRequest: 0x7fb7ac019ff0 handle_metadata_list: r=0
2023-02-15T18:45:25.394-0500 7fb7dacdd700 15 librbd::image::GetMetadataRequest: 0x7fb7ac019ff0 finish: r=0
2023-02-15T18:45:25.394-0500 7fb7dacdd700 10 librbd::image::RefreshRequest: 0x7fb7ac00f040 handle_v2_get_pool_metadata: r=0
2023-02-15T18:45:25.394-0500 7fb7dacdd700 20 librbd::ImageCtx: apply_metadata
2023-02-15T18:45:25.394-0500 7fb7dacdd700 10 librbd::image::RefreshRequest: 0x7fb7ac00f040 send_v2_get_group
2023-02-15T18:45:25.398-0500 7fb7db4de700 10 librbd::image::RefreshRequest: 0x7fb7ac00f040 handle_v2_get_group: r=0
2023-02-15T18:45:25.398-0500 7fb7db4de700 20 librbd::ManagedLock: 0x7fb7a8001d48 is_lock_owner: =0
2023-02-15T18:45:25.398-0500 7fb7db4de700 10 librbd::image::RefreshRequest: 0x7fb7ac00f040 send_v2_apply
2023-02-15T18:45:25.398-0500 7fb7db4de700 10 librbd::image::RefreshRequest: 0x7fb7ac00f040 handle_v2_apply
2023-02-15T18:45:25.398-0500 7fb7db4de700 20 librbd::image::RefreshRequest: 0x7fb7ac00f040 apply
2023-02-15T18:45:25.398-0500 7fb7db4de700 10 librbd::ImageState: 0x7fb7cc004b80 0x7fb7cc004b80 handle_refresh: r=0
2023-02-15T18:45:25.398-0500 7fb7db4de700 20 librbd::Operations: handle_refresh_image: r=0
2023-02-15T18:45:25.398-0500 7fb7db4de700 20 librbd::ManagedLock: 0x7fb7a8001d48 is_lock_owner: =0
2023-02-15T18:45:25.398-0500 7fb7db4de700 20 librbd::Operations: send_acquire_exclusive_lock
2023-02-15T18:45:25.398-0500 7fb7db4de700 10 librbd::ManagedLock: 0x7fb7a8001d48 try_acquire_lock: 
2023-02-15T18:45:25.398-0500 7fb7db4de700 10 librbd::ManagedLock: 0x7fb7a8001d48 send_acquire_lock: 
2023-02-15T18:45:25.398-0500 7fb7db4de700 10 librbd::ExclusiveLock: 0x7fb7a8001d30 pre_acquire_lock_handler
2023-02-15T18:45:25.398-0500 7fb7db4de700 10 librbd::exclusive_lock::PreAcquireRequest: 0x7fb7d4032000 send_prepare_lock: 
2023-02-15T18:45:25.398-0500 7fb7db4de700 10 librbd::ImageState: 0x7fb7cc004b80 prepare_lock
2023-02-15T18:45:25.398-0500 7fb7db4de700 10 librbd::ImageState: 0x7fb7cc004b80 0x7fb7cc004b80 send_prepare_lock_unlock
2023-02-15T18:45:25.398-0500 7fb7db4de700 10 librbd::exclusive_lock::PreAcquireRequest: 0x7fb7d4032000 handle_prepare_lock: r=0
2023-02-15T18:45:25.398-0500 7fb7db4de700 10 librbd::exclusive_lock::PreAcquireRequest: 0x7fb7d4032000 send_flush_notifies: 
2023-02-15T18:45:25.398-0500 7fb7db4de700 10 librbd::exclusive_lock::PreAcquireRequest: 0x7fb7d4032000 handle_flush_notifies: 
2023-02-15T18:45:25.398-0500 7fb7db4de700 10 librbd::ManagedLock: 0x7fb7a8001d48 handle_pre_acquire_lock: r=0
2023-02-15T18:45:25.398-0500 7fb7db4de700 10 librbd::managed_lock::AcquireRequest: 0x7fb7a80023e0 send_get_locker: 
2023-02-15T18:45:25.398-0500 7fb7db4de700 10 librbd::managed_lock::GetLockerRequest: 0x7fb7ac019580 send_get_lockers: 
2023-02-15T18:45:25.398-0500 7fb7dacdd700 10 librbd::managed_lock::GetLockerRequest: 0x7fb7ac019580 handle_get_lockers: r=0
2023-02-15T18:45:25.398-0500 7fb7dacdd700 10 librbd::managed_lock::GetLockerRequest: 0x7fb7ac019580 handle_get_lockers: retrieved exclusive locker: client.4447@172.21.9.34:0/856653073
2023-02-15T18:45:25.398-0500 7fb7dacdd700 10 librbd::managed_lock::GetLockerRequest: 0x7fb7ac019580 finish: r=0
2023-02-15T18:45:25.398-0500 7fb7dacdd700 10 librbd::managed_lock::AcquireRequest: 0x7fb7a80023e0 handle_get_locker: r=0
2023-02-15T18:45:25.398-0500 7fb7dacdd700 10 librbd::managed_lock::AcquireRequest: 0x7fb7a80023e0 send_lock: entity=client.4451, cookie=auto 140426774332400
2023-02-15T18:45:25.406-0500 7fb7db4de700 10 librbd::managed_lock::AcquireRequest: 0x7fb7a80023e0 handle_lock: r=-16
2023-02-15T18:45:25.406-0500 7fb7db4de700 10 librbd::managed_lock::AcquireRequest: 0x7fb7a80023e0 send_break_lock: 
2023-02-15T18:45:25.406-0500 7fb7db4de700 10 librbd::managed_lock::BreakRequest: 0x7fb7a8012db0 send_get_watchers: 
2023-02-15T18:45:25.406-0500 7fb7dacdd700 10 librbd::managed_lock::BreakRequest: 0x7fb7a8012db0 handle_get_watchers: r=0
2023-02-15T18:45:25.406-0500 7fb7dacdd700 20 librbd::managed_lock::BreakRequest: 0x7fb7a8012db0 handle_get_watchers: watcher=[addr=172.21.9.34:0/1604494228, entity=client.4451]
2023-02-15T18:45:25.406-0500 7fb7dacdd700 20 librbd::managed_lock::BreakRequest: 0x7fb7a8012db0 handle_get_watchers: watcher=[addr=172.21.9.34:0/856653073, entity=client.4447]
2023-02-15T18:45:25.406-0500 7fb7dacdd700 10 librbd::managed_lock::BreakRequest: 0x7fb7a8012db0 handle_get_watchers: lock owner is still alive
2023-02-15T18:45:25.406-0500 7fb7dacdd700 10 librbd::managed_lock::BreakRequest: 0x7fb7a8012db0 finish: r=-11
2023-02-15T18:45:25.406-0500 7fb7dacdd700 10 librbd::managed_lock::AcquireRequest: 0x7fb7a80023e0 handle_break_lock: r=-11
2023-02-15T18:45:25.406-0500 7fb7dacdd700  5 librbd::managed_lock::AcquireRequest: 0x7fb7a80023e0 handle_break_lock: lock owner is still alive
2023-02-15T18:45:25.406-0500 7fb7dacdd700 10 librbd::ManagedLock: 0x7fb7a8001d48 handle_acquire_lock: r=-11
2023-02-15T18:45:25.406-0500 7fb7dacdd700  5 librbd::ManagedLock: 0x7fb7a8001d48 handle_acquire_lock: unable to acquire exclusive lock
2023-02-15T18:45:25.406-0500 7fb7dacdd700 10 librbd::ExclusiveLock: 0x7fb7a8001d30 post_acquire_lock_handler: r=-11
2023-02-15T18:45:25.406-0500 7fb7dacdd700 10 librbd::ImageState: 0x7fb7cc004b80 handle_prepare_lock_complete
2023-02-15T18:45:25.406-0500 7fb7dacdd700 10 librbd::ManagedLock: 0x7fb7a8001d48 handle_post_acquire_lock: r=0
2023-02-15T18:45:25.406-0500 7fb7dacdd700 20 librbd::Operations: handle_acquire_exclusive_lock: r=0
2023-02-15T18:45:25.406-0500 7fb7dacdd700 20 librbd::ManagedLock: 0x7fb7a8001d48 is_lock_owner: =0
2023-02-15T18:45:25.406-0500 7fb7dacdd700 20 librbd::Operations: send_remote_request
2023-02-15T18:45:25.406-0500 7fb7dacdd700 20 librbd::ManagedLock: 0x7fb7a8001d48 is_lock_owner: =0
2023-02-15T18:45:25.406-0500 7fb7dacdd700 10 librbd::ImageWatcher: 0x7fb7ac008710 async request: [4451,140426774332400,1]
2023-02-15T18:45:25.406-0500 7fb7dacdd700 20 librbd::ImageWatcher: scheduling async request time out: [4451,140426774332400,1]
2023-02-15T18:45:25.406-0500 7fb7dacdd700 20 librbd::image_watcher::NotifyLockOwner: 0x7fb7d4037000 send_notify
2023-02-15T18:45:25.406-0500 7fb7dacdd700 20 librbd::watcher::Notifier: 0x7fb7ac0087d0 notify: pending=1
2023-02-15T18:45:25.406-0500 7fb7db4de700  5 librbd::Watcher: 0x7fb7ac008710 notifications_blocked: blocked=0
2023-02-15T18:45:25.406-0500 7fb7db4de700 10 librbd::Watcher::C_NotifyAck 0x7fb7a8010870 C_NotifyAck: id=94489543921, handle=140426774332400
2023-02-15T18:45:25.406-0500 7fb7db4de700 10 librbd::ImageWatcher: 0x7fb7ac008710 remote update_features request: [4451,140426774332400,1] 64 disabled
2023-02-15T18:45:25.406-0500 7fb7db4de700 20 librbd::ExclusiveLock: 0x7fb7a8001d30 accept_request=0 (request_type=0)
2023-02-15T18:45:25.406-0500 7fb7db4de700 10 librbd::Watcher::C_NotifyAck 0x7fb7a8010870 finish: r=0
2023-02-15T18:45:25.406-0500 7fb7dacdd700 20 librbd::watcher::Notifier: 0x7fb7ac0087d0 handle_notify: r=0
2023-02-15T18:45:25.406-0500 7fb7dacdd700 20 librbd::watcher::Notifier: 0x7fb7ac0087d0 handle_notify: pending=0
2023-02-15T18:45:25.406-0500 7fb7dacdd700 20 librbd::image_watcher::NotifyLockOwner: 0x7fb7d4037000 handle_notify: r=0
2023-02-15T18:45:25.406-0500 7fb7dacdd700 20 librbd::image_watcher::NotifyLockOwner: 0x7fb7d4037000 handle_notify client responded with r=-110
2023-02-15T18:45:25.406-0500 7fb7dacdd700 20 librbd::ImageWatcher: remove_async_request: [4451,140426774332400,1]
2023-02-15T18:45:25.406-0500 7fb7dacdd700 20 librbd::Operations: handle_remote_request: r=-110
2023-02-15T18:45:25.406-0500 7fb7dacdd700  5 librbd::Operations: update features timed out notifying lock owner

2023-02-15T18:45:25.406-0500 7fb7dacdd700 20 librbd::ManagedLock: 0x7fb7a8001d48 is_lock_owner: =0
2023-02-15T18:45:25.406-0500 7fb7dacdd700 20 librbd::Operations: send_acquire_exclusive_lock
2023-02-15T18:45:25.406-0500 7fb7dacdd700 10 librbd::ManagedLock: 0x7fb7a8001d48 try_acquire_lock: 
2023-02-15T18:45:25.406-0500 7fb7dacdd700 10 librbd::ManagedLock: 0x7fb7a8001d48 send_acquire_lock: 
2023-02-15T18:45:25.406-0500 7fb7dacdd700 10 librbd::ExclusiveLock: 0x7fb7a8001d30 pre_acquire_lock_handler
2023-02-15T18:45:25.406-0500 7fb7dacdd700 10 librbd::exclusive_lock::PreAcquireRequest: 0x7fb7a8004e40 send_prepare_lock: 
2023-02-15T18:45:25.406-0500 7fb7dacdd700 10 librbd::ImageState: 0x7fb7cc004b80 prepare_lock
2023-02-15T18:45:25.406-0500 7fb7dacdd700 10 librbd::ImageState: 0x7fb7cc004b80 0x7fb7cc004b80 send_prepare_lock_unlock
2023-02-15T18:45:25.406-0500 7fb7dacdd700 10 librbd::exclusive_lock::PreAcquireRequest: 0x7fb7a8004e40 handle_prepare_lock: r=0
2023-02-15T18:45:25.406-0500 7fb7dacdd700 10 librbd::exclusive_lock::PreAcquireRequest: 0x7fb7a8004e40 send_flush_notifies: 
2023-02-15T18:45:25.406-0500 7fb7dacdd700 10 librbd::exclusive_lock::PreAcquireRequest: 0x7fb7a8004e40 handle_flush_notifies: 
2023-02-15T18:45:25.406-0500 7fb7dacdd700 10 librbd::ManagedLock: 0x7fb7a8001d48 handle_pre_acquire_lock: r=0
2023-02-15T18:45:25.406-0500 7fb7dacdd700 10 librbd::managed_lock::AcquireRequest: 0x7fb7a80023e0 send_get_locker: 
2023-02-15T18:45:25.406-0500 7fb7dacdd700 10 librbd::managed_lock::GetLockerRequest: 0x7fb7a8012840 send_get_lockers: 
2023-02-15T18:45:25.406-0500 7fb7db4de700 10 librbd::managed_lock::GetLockerRequest: 0x7fb7a8012840 handle_get_lockers: r=0
2023-02-15T18:45:25.406-0500 7fb7db4de700 10 librbd::managed_lock::GetLockerRequest: 0x7fb7a8012840 handle_get_lockers: retrieved exclusive locker: client.4447@172.21.9.34:0/856653073
2023-02-15T18:45:25.406-0500 7fb7db4de700 10 librbd::managed_lock::GetLockerRequest: 0x7fb7a8012840 finish: r=0
2023-02-15T18:45:25.406-0500 7fb7db4de700 10 librbd::managed_lock::AcquireRequest: 0x7fb7a80023e0 handle_get_locker: r=0
2023-02-15T18:45:25.406-0500 7fb7db4de700 10 librbd::managed_lock::AcquireRequest: 0x7fb7a80023e0 send_lock: entity=client.4451, cookie=auto 140426774332400
2023-02-15T18:45:25.414-0500 7fb7dacdd700 10 librbd::managed_lock::AcquireRequest: 0x7fb7a80023e0 handle_lock: r=-16
2023-02-15T18:45:25.414-0500 7fb7dacdd700 10 librbd::managed_lock::AcquireRequest: 0x7fb7a80023e0 send_break_lock: 
2023-02-15T18:45:25.414-0500 7fb7dacdd700 10 librbd::managed_lock::BreakRequest: 0x7fb7a8012db0 send_get_watchers: 
2023-02-15T18:45:25.418-0500 7fb7db4de700 10 librbd::managed_lock::BreakRequest: 0x7fb7a8012db0 handle_get_watchers: r=0
2023-02-15T18:45:25.418-0500 7fb7db4de700 20 librbd::managed_lock::BreakRequest: 0x7fb7a8012db0 handle_get_watchers: watcher=[addr=172.21.9.34:0/1604494228, entity=client.4451]
2023-02-15T18:45:25.418-0500 7fb7db4de700 20 librbd::managed_lock::BreakRequest: 0x7fb7a8012db0 handle_get_watchers: watcher=[addr=172.21.9.34:0/856653073, entity=client.4447]
2023-02-15T18:45:25.418-0500 7fb7db4de700 10 librbd::managed_lock::BreakRequest: 0x7fb7a8012db0 handle_get_watchers: lock owner is still alive
2023-02-15T18:45:25.418-0500 7fb7db4de700 10 librbd::managed_lock::BreakRequest: 0x7fb7a8012db0 finish: r=-11
2023-02-15T18:45:25.418-0500 7fb7db4de700 10 librbd::managed_lock::AcquireRequest: 0x7fb7a80023e0 handle_break_lock: r=-11
2023-02-15T18:45:25.418-0500 7fb7db4de700  5 librbd::managed_lock::AcquireRequest: 0x7fb7a80023e0 handle_break_lock: lock owner is still alive
2023-02-15T18:45:25.418-0500 7fb7db4de700 10 librbd::ManagedLock: 0x7fb7a8001d48 handle_acquire_lock: r=-11
2023-02-15T18:45:25.418-0500 7fb7db4de700  5 librbd::ManagedLock: 0x7fb7a8001d48 handle_acquire_lock: unable to acquire exclusive lock
2023-02-15T18:45:25.418-0500 7fb7db4de700 10 librbd::ExclusiveLock: 0x7fb7a8001d30 post_acquire_lock_handler: r=-11
2023-02-15T18:45:25.418-0500 7fb7db4de700 10 librbd::ImageState: 0x7fb7cc004b80 handle_prepare_lock_complete
2023-02-15T18:45:25.418-0500 7fb7db4de700 10 librbd::ManagedLock: 0x7fb7a8001d48 handle_post_acquire_lock: r=0
2023-02-15T18:45:25.418-0500 7fb7db4de700 20 librbd::Operations: handle_acquire_exclusive_lock: r=0
2023-02-15T18:45:25.418-0500 7fb7db4de700 20 librbd::ManagedLock: 0x7fb7a8001d48 is_lock_owner: =0
2023-02-15T18:45:25.418-0500 7fb7db4de700 20 librbd::Operations: send_remote_request
2023-02-15T18:45:25.418-0500 7fb7db4de700 20 librbd::ManagedLock: 0x7fb7a8001d48 is_lock_owner: =0
2023-02-15T18:45:25.418-0500 7fb7db4de700 10 librbd::ImageWatcher: 0x7fb7ac008710 async request: [4451,140426774332400,1]
2023-02-15T18:45:25.418-0500 7fb7db4de700 20 librbd::ImageWatcher: scheduling async request time out: [4451,140426774332400,1]
2023-02-15T18:45:25.418-0500 7fb7db4de700 20 librbd::image_watcher::NotifyLockOwner: 0x7fb7d403f000 send_notify
2023-02-15T18:45:25.418-0500 7fb7db4de700 20 librbd::watcher::Notifier: 0x7fb7ac0087d0 notify: pending=1
2023-02-15T18:45:25.418-0500 7fb7dacdd700  5 librbd::Watcher: 0x7fb7ac008710 notifications_blocked: blocked=0
2023-02-15T18:45:25.418-0500 7fb7dacdd700 10 librbd::Watcher::C_NotifyAck 0x7fb7ac013e40 C_NotifyAck: id=94489543922, handle=140426774332400
2023-02-15T18:45:25.418-0500 7fb7dacdd700 10 librbd::ImageWatcher: 0x7fb7ac008710 remote update_features request: [4451,140426774332400,1] 64 disabled
2023-02-15T18:45:25.418-0500 7fb7dacdd700 20 librbd::ExclusiveLock: 0x7fb7a8001d30 accept_request=0 (request_type=0)
2023-02-15T18:45:25.418-0500 7fb7dacdd700 10 librbd::Watcher::C_NotifyAck 0x7fb7ac013e40 finish: r=0
2023-02-15T18:45:25.418-0500 7fb7dacdd700 20 librbd::watcher::Notifier: 0x7fb7ac0087d0 handle_notify: r=0
2023-02-15T18:45:25.418-0500 7fb7dacdd700 20 librbd::watcher::Notifier: 0x7fb7ac0087d0 handle_notify: pending=0
2023-02-15T18:45:25.418-0500 7fb7dacdd700 20 librbd::image_watcher::NotifyLockOwner: 0x7fb7d403f000 handle_notify: r=0
2023-02-15T18:45:25.418-0500 7fb7dacdd700 20 librbd::image_watcher::NotifyLockOwner: 0x7fb7d403f000 handle_notify client responded with r=-110
2023-02-15T18:45:25.418-0500 7fb7dacdd700 20 librbd::ImageWatcher: remove_async_request: [4451,140426774332400,1]
2023-02-15T18:45:25.418-0500 7fb7dacdd700 20 librbd::Operations: handle_remote_request: r=-110
2023-02-15T18:45:25.418-0500 7fb7dacdd700  5 librbd::Operations: update features timed out notifying lock owner

2023-02-15T18:45:25.418-0500 7fb7dacdd700 20 librbd::ManagedLock: 0x7fb7a8001d48 is_lock_owner: =0
2023-02-15T18:45:25.418-0500 7fb7dacdd700 20 librbd::Operations: send_acquire_exclusive_lock
2023-02-15T18:45:25.418-0500 7fb7dacdd700 10 librbd::ManagedLock: 0x7fb7a8001d48 try_acquire_lock: 
2023-02-15T18:45:25.418-0500 7fb7dacdd700 10 librbd::ManagedLock: 0x7fb7a8001d48 send_acquire_lock: 
2023-02-15T18:45:25.418-0500 7fb7dacdd700 10 librbd::ExclusiveLock: 0x7fb7a8001d30 pre_acquire_lock_handler
2023-02-15T18:45:25.418-0500 7fb7dacdd700 10 librbd::exclusive_lock::PreAcquireRequest: 0x7fb7a8002df0 send_prepare_lock: 
2023-02-15T18:45:25.418-0500 7fb7dacdd700 10 librbd::ImageState: 0x7fb7cc004b80 prepare_lock
2023-02-15T18:45:25.418-0500 7fb7dacdd700 10 librbd::ImageState: 0x7fb7cc004b80 0x7fb7cc004b80 send_prepare_lock_unlock
2023-02-15T18:45:25.418-0500 7fb7dacdd700 10 librbd::exclusive_lock::PreAcquireRequest: 0x7fb7a8002df0 handle_prepare_lock: r=0
2023-02-15T18:45:25.418-0500 7fb7dacdd700 10 librbd::exclusive_lock::PreAcquireRequest: 0x7fb7a8002df0 send_flush_notifies: 
2023-02-15T18:45:25.418-0500 7fb7dacdd700 10 librbd::exclusive_lock::PreAcquireRequest: 0x7fb7a8002df0 handle_flush_notifies: 
2023-02-15T18:45:25.418-0500 7fb7dacdd700 10 librbd::ManagedLock: 0x7fb7a8001d48 handle_pre_acquire_lock: r=0
2023-02-15T18:45:25.418-0500 7fb7dacdd700 10 librbd::managed_lock::AcquireRequest: 0x7fb7a80025d0 send_get_locker: 
2023-02-15T18:45:25.418-0500 7fb7dacdd700 10 librbd::managed_lock::GetLockerRequest: 0x7fb7a8012f70 send_get_lockers: 
2023-02-15T18:45:25.418-0500 7fb7db4de700 10 librbd::managed_lock::GetLockerRequest: 0x7fb7a8012f70 handle_get_lockers: r=0
2023-02-15T18:45:25.418-0500 7fb7db4de700 10 librbd::managed_lock::GetLockerRequest: 0x7fb7a8012f70 handle_get_lockers: retrieved exclusive locker: client.4447@172.21.9.34:0/856653073
2023-02-15T18:45:25.418-0500 7fb7db4de700 10 librbd::managed_lock::GetLockerRequest: 0x7fb7a8012f70 finish: r=0
2023-02-15T18:45:25.418-0500 7fb7db4de700 10 librbd::managed_lock::AcquireRequest: 0x7fb7a80025d0 handle_get_locker: r=0
2023-02-15T18:45:25.418-0500 7fb7db4de700 10 librbd::managed_lock::AcquireRequest: 0x7fb7a80025d0 send_lock: entity=client.4451, cookie=auto 140426774332400
2023-02-15T18:45:25.422-0500 7fb7dacdd700 10 librbd::managed_lock::AcquireRequest: 0x7fb7a80025d0 handle_lock: r=-16
2023-02-15T18:45:25.422-0500 7fb7dacdd700 10 librbd::managed_lock::AcquireRequest: 0x7fb7a80025d0 send_break_lock: 
2023-02-15T18:45:25.422-0500 7fb7dacdd700 10 librbd::managed_lock::BreakRequest: 0x7fb7a8002fb0 send_get_watchers: 
2023-02-15T18:45:25.422-0500 7fb7db4de700 10 librbd::managed_lock::BreakRequest: 0x7fb7a8002fb0 handle_get_watchers: r=0
2023-02-15T18:45:25.422-0500 7fb7db4de700 20 librbd::managed_lock::BreakRequest: 0x7fb7a8002fb0 handle_get_watchers: watcher=[addr=172.21.9.34:0/1604494228, entity=client.4451]
2023-02-15T18:45:25.422-0500 7fb7db4de700 20 librbd::managed_lock::BreakRequest: 0x7fb7a8002fb0 handle_get_watchers: watcher=[addr=172.21.9.34:0/856653073, entity=client.4447]
2023-02-15T18:45:25.422-0500 7fb7db4de700 10 librbd::managed_lock::BreakRequest: 0x7fb7a8002fb0 handle_get_watchers: lock owner is still alive
2023-02-15T18:45:25.422-0500 7fb7db4de700 10 librbd::managed_lock::BreakRequest: 0x7fb7a8002fb0 finish: r=-11
2023-02-15T18:45:25.422-0500 7fb7db4de700 10 librbd::managed_lock::AcquireRequest: 0x7fb7a80025d0 handle_break_lock: r=-11
2023-02-15T18:45:25.422-0500 7fb7db4de700  5 librbd::managed_lock::AcquireRequest: 0x7fb7a80025d0 handle_break_lock: lock owner is still alive
2023-02-15T18:45:25.422-0500 7fb7db4de700 10 librbd::ManagedLock: 0x7fb7a8001d48 handle_acquire_lock: r=-11
2023-02-15T18:45:25.422-0500 7fb7db4de700  5 librbd::ManagedLock: 0x7fb7a8001d48 handle_acquire_lock: unable to acquire exclusive lock
2023-02-15T18:45:25.422-0500 7fb7db4de700 10 librbd::ExclusiveLock: 0x7fb7a8001d30 post_acquire_lock_handler: r=-11
2023-02-15T18:45:25.422-0500 7fb7db4de700 10 librbd::ImageState: 0x7fb7cc004b80 handle_prepare_lock_complete
2023-02-15T18:45:25.422-0500 7fb7db4de700 10 librbd::ManagedLock: 0x7fb7a8001d48 handle_post_acquire_lock: r=0
2023-02-15T18:45:25.422-0500 7fb7db4de700 20 librbd::Operations: handle_acquire_exclusive_lock: r=0
2023-02-15T18:45:25.422-0500 7fb7db4de700 20 librbd::ManagedLock: 0x7fb7a8001d48 is_lock_owner: =0
2023-02-15T18:45:25.422-0500 7fb7db4de700 20 librbd::Operations: send_remote_request
2023-02-15T18:45:25.422-0500 7fb7db4de700 20 librbd::ManagedLock: 0x7fb7a8001d48 is_lock_owner: =0
2023-02-15T18:45:25.422-0500 7fb7db4de700 10 librbd::ImageWatcher: 0x7fb7ac008710 async request: [4451,140426774332400,1]
2023-02-15T18:45:25.422-0500 7fb7db4de700 20 librbd::ImageWatcher: scheduling async request time out: [4451,140426774332400,1]
2023-02-15T18:45:25.422-0500 7fb7db4de700 20 librbd::image_watcher::NotifyLockOwner: 0x7fb7d4046000 send_notify
2023-02-15T18:45:25.422-0500 7fb7db4de700 20 librbd::watcher::Notifier: 0x7fb7ac0087d0 notify: pending=1
2023-02-15T18:45:25.426-0500 7fb7dacdd700  5 librbd::Watcher: 0x7fb7ac008710 notifications_blocked: blocked=0
2023-02-15T18:45:25.426-0500 7fb7dacdd700 10 librbd::Watcher::C_NotifyAck 0x7fb7ac013950 C_NotifyAck: id=94489543923, handle=140426774332400
2023-02-15T18:45:25.426-0500 7fb7dacdd700 10 librbd::ImageWatcher: 0x7fb7ac008710 remote update_features request: [4451,140426774332400,1] 64 disabled
2023-02-15T18:45:25.426-0500 7fb7dacdd700 20 librbd::ExclusiveLock: 0x7fb7a8001d30 accept_request=0 (request_type=0)
2023-02-15T18:45:25.426-0500 7fb7dacdd700 10 librbd::Watcher::C_NotifyAck 0x7fb7ac013950 finish: r=0
2023-02-15T18:45:25.426-0500 7fb7dacdd700 20 librbd::watcher::Notifier: 0x7fb7ac0087d0 handle_notify: r=0
2023-02-15T18:45:25.426-0500 7fb7dacdd700 20 librbd::watcher::Notifier: 0x7fb7ac0087d0 handle_notify: pending=0
2023-02-15T18:45:25.426-0500 7fb7dacdd700 20 librbd::image_watcher::NotifyLockOwner: 0x7fb7d4046000 handle_notify: r=0
2023-02-15T18:45:25.426-0500 7fb7dacdd700 20 librbd::image_watcher::NotifyLockOwner: 0x7fb7d4046000 handle_notify client responded with r=-110
2023-02-15T18:45:25.426-0500 7fb7dacdd700 20 librbd::ImageWatcher: remove_async_request: [4451,140426774332400,1]
2023-02-15T18:45:25.426-0500 7fb7dacdd700 20 librbd::Operations: handle_remote_request: r=-110
2023-02-15T18:45:25.426-0500 7fb7dacdd700  5 librbd::Operations: update features timed out notifying lock owner

...

Related issues 4 (1 open — 3 closed)

Related to rbd - Bug #59563: busy looping caused by remote request ETIMEDOUT handling logicIn ProgressPrasanna Kumar Kalever

Actions
Copied to rbd - Backport #63349: quincy: "rbd feature disable" remote request hangs when proxied to rbd-nbdResolvedPrasanna Kumar KaleverActions
Copied to rbd - Backport #63350: reef: "rbd feature disable" remote request hangs when proxied to rbd-nbdResolvedPrasanna Kumar KaleverActions
Copied to rbd - Backport #63351: pacific: "rbd feature disable" remote request hangs when proxied to rbd-nbdResolvedPrasanna Kumar KaleverActions
Actions
Copy link
 #1

Updated by Ilya Dryomov about 1 year ago

  • Status changed from New to In Progress
  • Assignee set to Prasanna Kumar Kalever
Actions
Copy link
 #2

Updated by Prasanna Kumar Kalever about 1 year ago

  • Pull request ID set to 50593
Actions
Copy link
 #3

Updated by Ilya Dryomov about 1 year ago

  • Related to Bug #59563: busy looping caused by remote request ETIMEDOUT handling logic added
Actions
Copy link
 #4

Updated by Ilya Dryomov 7 months ago

  • Status changed from In Progress to Pending Backport
  • Backport set to pacific,quincy,reef
Actions
Copy link
 #5

Updated by Ilya Dryomov 7 months ago

  • Copied to Backport #63349: quincy: "rbd feature disable" remote request hangs when proxied to rbd-nbd added
Actions
Copy link
 #6

Updated by Ilya Dryomov 7 months ago

  • Copied to Backport #63350: reef: "rbd feature disable" remote request hangs when proxied to rbd-nbd added
Actions
Copy link
 #7

Updated by Ilya Dryomov 7 months ago

  • Copied to Backport #63351: pacific: "rbd feature disable" remote request hangs when proxied to rbd-nbd added
Actions
Copy link
 #8

Updated by Ilya Dryomov 7 months ago

  • Tags set to backport_processed
Actions
Copy link
 #9

Updated by Backport Bot 3 months ago

  • Status changed from Pending Backport to Resolved

While running with --resolve-parent, the script "backport-create-issue" noticed that all backports of this issue are in status "Resolved" or "Rejected".

Actions
Copy link

Also available in: Atom PDF