Deadlock between remove device and acquire dev lock.

[sherlockxiao]

Hi,
tcmu ver:1.4.1
OS ver:centos7.6 kernel 3.10.0.957

We found a deadlock when use tcmu-runner like below:

Sep 20 03:36:09 b12 kernel: INFO: task tcmu-runner:2463938 blocked for more than 120 seconds.
Sep 20 03:36:09 b12 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Sep 20 03:36:09 b12 kernel: tcmu-runner D ffff892eabffc100 0 2463938 1 0x00000080
Sep 20 03:36:09 b12 kernel: Call Trace:
Sep 20 03:36:09 b12 kernel: [] ? security_inode_permission+0x22/0x30
Sep 20 03:36:09 b12 kernel: [] schedule_preempt_disabled+0x29/0x70
Sep 20 03:36:09 b12 kernel: [] __mutex_lock_slowpath+0xc7/0x1d0
Sep 20 03:36:09 b12 kernel: [] mutex_lock+0x1f/0x2f
Sep 20 03:36:09 b12 kernel: [] lookup_slow+0x33/0xa7
Sep 20 03:36:09 b12 kernel: [] path_lookupat+0x838/0x8b0
Sep 20 03:36:09 b12 kernel: [] ? try_to_wake_up+0x190/0x390
Sep 20 03:36:09 b12 kernel: [] ? kmem_cache_alloc+0x35/0x1f0
Sep 20 03:36:09 b12 kernel: [] ? getname_flags+0x4f/0x1a0
Sep 20 03:36:09 b12 kernel: [] filename_lookup+0x2b/0xc0
Sep 20 03:36:09 b12 kernel: [] user_path_at_empty+0x67/0xc0
Sep 20 03:36:09 b12 kernel: [] ? kmemdup+0x36/0x50
Sep 20 03:36:09 b12 kernel: [] user_path_at+0x11/0x20
Sep 20 03:36:09 b12 kernel: [] SyS_faccessat+0xb2/0x230
Sep 20 03:36:09 b12 kernel: [] SyS_access+0x18/0x20
Sep 20 03:36:09 b12 kernel: [] system_call_fastpath+0x22/0x27
Sep 20 03:36:09 b12 kernel: INFO: task rbd-target-api:2463993 blocked for more than 120 seconds.
Sep 20 03:36:09 b12 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Sep 20 03:36:10 b12 kernel: rbd-target-api D ffff892efdfeb0c0 0 2463993 1 0x00000080
Sep 20 03:36:10 b12 kernel: Call Trace:
Sep 20 03:36:10 b12 kernel: [] ? __wake_up_sync_key+0x4f/0x60
Sep 20 03:36:10 b12 kernel: [] schedule+0x29/0x70
Sep 20 03:36:10 b12 kernel: [] schedule_timeout+0x221/0x2d0
Sep 20 03:36:10 b12 kernel: [] ? netlink_broadcast_filtered+0x14c/0x3e0
Sep 20 03:36:10 b12 kernel: [] wait_for_completion+0xfd/0x140
Sep 20 03:36:10 b12 kernel: [] ? wake_up_state+0x20/0x20
Sep 20 03:36:10 b12 kernel: [] tcmu_netlink_event+0x334/0x4a0 [target_core_user]
Sep 20 03:36:10 b12 kernel: [] ? __cond_resched+0x26/0x30
Sep 20 03:36:10 b12 kernel: [] tcmu_destroy_device+0x5c/0x90 [target_core_user]
Sep 20 03:36:10 b12 kernel: [] target_free_device+0xb4/0x120 [target_core_mod]
Sep 20 03:36:10 b12 kernel: [] target_core_dev_release+0x15/0x20 [target_core_mod]
Sep 20 03:36:10 b12 kernel: [] config_item_release+0x6a/0xf0
Sep 20 03:36:10 b12 kernel: [] config_item_put+0x2c/0x30
Sep 20 03:36:10 b12 kernel: [] configfs_rmdir+0x1eb/0x310
Sep 20 03:36:10 b12 kernel: [] vfs_rmdir+0xdc/0x150
Sep 20 03:36:10 b12 kernel: [] do_rmdir+0x1f1/0x220
Sep 20 03:36:10 b12 kernel: [] ? SYSC_newstat+0x3e/0x60
Sep 20 03:36:10 b12 kernel: [] SyS_rmdir+0x16/0x20
Sep 20 03:36:10 b12 kernel: [] system_call_fastpath+0x22/0x27

Because the process is D status, can’t trace user mode stack,We use crash to find out which lock tcmu-runner want to request in kernel mode.It is a vfs dir lock, dir path is /sys/kernel/config/target/core/user_1/[lun_name]/，and tcmu runner request action file in this dir.
We think tcmu-runner in below code:

int tcmu_acquire_dev_lock(struct tcmu_device *dev, bool is_sync,
              uint16_t tag)
...
    pthread_mutex_lock(&rdev->state_lock);
    if (ret == TCMU_STS_OK)
        rdev->lock_state = TCMUR_DEV_LOCK_LOCKED;
    else
        rdev->lock_state = TCMUR_DEV_LOCK_UNLOCKED;
    tcmu_dev_dbg(dev, "lock call done. lock state %d\n", rdev->lock_state);
    tcmu_unblock_device(dev);

    pthread_cond_signal(&rdev->lock_cond);
    pthread_mutex_unlock(&rdev->state_lock);

    return ret;

1. Tcmu-runner hold state_lock and exec unblock_device, in this func will call access syscall.We call it A.
2. In another hand, rbd-target-api exec rmdir, it’s hold LUN_NAME dir lock, callback TCMU_CMD_REMOVED_DEVICE through netlink, and wait completion when use v2 protocol.We call it B
3. Tcmu-runner main loop receive netlink event, exec removed_device, but can’t get state_lock because tcmu acquire lock thread A hold the state lock and wait vfs dir lock.But the rmdir kernel path B doesn’t release dir lock until it get completion.We call it C.

The interesting thing is why A access syscall enter lookup_slow and request dir lock at last, because kernel will cache action(file) dentry after first lookup.We sure that in our system deadlock didn’t occur in first access action file, access syscall can get this cache dentry through lookup_fast usually.We think that is B rmdir（LUN_NAME）, before it delete dir dentry, it will delete child file dentry cache in this dir by use shrink_dcache_parent.

int vfs_rmdir(struct inode *dir, struct dentry *dentry)
{
...
    shrink_dcache_parent(dentry);
    error = dir->i_op->rmdir(dir, dentry);
    if (error)
        goto out;

    dentry->d_inode->i_flags |= S_DEAD;
    dont_mount(dentry);
    detach_mounts(dentry);

out:
    mutex_unlock(&dentry->d_inode->i_mutex);
    dput(dentry);
    if (!error)
        d_delete(dentry);
    return error;

We guess in this deadlock scene, B remove action file dentry cache and hold dir lock(LUN_NAME), so A can’t get it by call lookup_fast.Then A request dir lock in lookup_slow func and hold state mutex lock.C wait mutext lock to complete REMOVE DEV and let B release dir lock.
The newest code remove access syscall, and only exec open and write value to /sys/kernel/.../action file.But open syscall also have the opportunity to enter the lookup_slow func, so a deadlock scenario may exist.

[mikechristie]

Nice debugging! Thanks for doing all the work.

There is no reason for us to hold the state_lock while calling tcmu_unblock_device. We can just move the tcmu_unblock_device call to after we have dropped the state_lock. Did you try this already? Do you want me to make a patch or have you already done something similar?

[sherlockxiao]

Ok, i'm not try this because not clearly affect move unblock out of unlock, thank you very much for giving me a patch.I'll patch it to my code and try reproduce this deadlock.
BTW,I'm not familiar with whole process, I feel a little dangerous hold a vfs lock and wait a completion but it seems can't release vfs lock before all clean action completion.Vfs lock is transparency to tcmu layer, and sometimes lock sometimes use rcu and other.I'm not sure than same problem will be exist if mainloop is exec ADD_DEVICE(it's also have open file action), and REMOVE_DEVICE is send to mainloop.At this time, mainloop will can't return to handle REMOVE_DEVICE because ADD_DEVICE may block on vfs lock?

[mikechristie]

Ok, i'm not try this because not clearly affect move unblock out of unlock, thank you very much for giving me a patch.I'll patch it to my code and try reproduce this deadlock.
BTW,I'm not familiar with whole process, I feel a little dangerous hold a vfs lock and wait a completion but it seems can't release vfs lock before all clean action completion.Vfs lock is transparency to tcmu layer, and sometimes lock sometimes use rcu and other.I'm not sure than same problem will be exist if mainloop is exec ADD_DEVICE(it's also have open file action), and REMOVE_DEVICE is send to mainloop.At this time, mainloop will can't return to handle REMOVE_DEVICE because ADD_DEVICE may block on vfs lock?

Yeah, in general I need to audit the code and check where user space is holding a lock and we can end up in these deadlocks. We had only been considering the user space locking ordering and not taking into account the kernel. I am going to review them and will post a patch with the fix for this specific issue and whatever else I find.

[sherlockxiao]

Thank you!！

[mikechristie]

Just a FYI, I can replicate this bug. I just added some sleep() calls to force the timing.

There seem to be a couple other places this can happen. I am testing a patch now. I should be done tomorrow.

[mikechristie]

PR for fix:

#596

[sherlockxiao]

Hi,
We patched fix, and reproduce it again after a few days testing.
Config multi-path with RR, and two target host, one initiator.Host A and Host B will in RBD lock competition when receive IO.At this time, remove RBD mapping from LIO, trigger tcmu_runner remove_device.
1.Rbd-target-api trap in kernel, and hold dir lock waiting for tcmu_runner finish device_remove.
2.Main loop execute remove_device->tcmur_stop_device->tcmu_cancel_lock_thread->pthread_cond_wait(when lock status is TCMUR_DEV_LOCK_LOCKING)，so remove will wait status change but not wait lock.
3.On other hand, alua_implicit_transition set status equal TCMUR_DEV_LOCK_LOCKING and exec tcmu_acquire_dev_lock, it will block dev before signal pthread_cond_wait wake up.This tcmu_block_device will try get kernel dir lock but hold with Rbd-target-api in kernel.
The debug log attached, and reproduce log at end.
2019-11-12 13:49:46.192 3471493 [DEBUG] handle_netlink:198: cmd 2. Got header version 2. Supported 2.（mainloop remove device）
2019-11-12 13:49:46.192 3471493 [DEBUG] tcmu_cancel_lock_thread:257 rbd/p1.lun2: waiting for lock thread to exit（mainloop remove device）
2019-11-12 13:49:46.377 3471493 [WARN] tcmu_rbd_lock:761 rbd/p1.lun2: Acquired exclusive lock.（another thread get rbd lock，but blocked in tcmu_block_dev, and no more log dump）
tcmu_log.log

[mikechristie]

Nice debugging. I am looking into a fix.