Saw possible lock dependency problem (once) running cifs/102 test -
ran multiple times but only saw once. It may be fixed by later
patches from Shyam, but I was doing some tests with only his first
two.
This is on on 5.17-rc3 + the 3 patches below.
52492ff5c583 cifs: call helper functions for marking channels for reconnect
a81da65fbae6 cifs: call cifs_reconnect when a connection is marked
d0cbe56a7d5a [smb3] improve error message when mount options conflict with posix
dfd42facf1e4 (tag: v5.17-rc3, origin/master, origin/HEAD,
linus/master, master) Linux 5.17-rc3
[ 6566.222316] run fstests cifs/102 at 2022-02-12 02:27:53
[ 6567.213971] ======================================================
[ 6567.214280] WARNING: possible circular locking dependency detected
[ 6567.214496] 5.17.0-rc3 #1 Not tainted
[ 6567.214851] ------------------------------------------------------
[ 6567.214851] cifsd/5791 is trying to acquire lock:
[ 6567.214851] ffffffffc0b296f8 (&cifs_tcp_ses_lock){+.+.}-{2:2}, at:
smb2_find_smb_tcon+0x24/0xc0 [cifs]
[ 6567.215501]
but task is already holding lock:
[ 6567.215501] ffffffffc0b29698 (&GlobalMid_Lock){+.+.}-{2:2}, at:
cifs_mid_q_entry_release+0x22/0x610 [cifs]
[ 6567.216247]
which lock already depends on the new lock.
[ 6567.216661]
the existing dependency chain (in reverse order) is:
[ 6567.217496]
-> #1 (&GlobalMid_Lock){+.+.}-{2:2}:
[ 6567.217991] _raw_spin_lock+0x2f/0x40
[ 6567.217991] cifs_debug_data_proc_show+0x50c/0x9b0 [cifs]
[ 6567.217991] seq_read_iter+0xd3/0x440
[ 6567.217991] proc_reg_read_iter+0x46/0x60
[ 6567.219094] new_sync_read+0x10e/0x180
[ 6567.219094] vfs_read+0x171/0x1a0
[ 6567.219560] ksys_read+0x87/0xc0
[ 6567.219585] do_syscall_64+0x3a/0x80
[ 6567.219585] entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 6567.219585]
-> #0 (&cifs_tcp_ses_lock){+.+.}-{2:2}:
[ 6567.220786] __lock_acquire+0x1302/0x18d0
[ 6567.220786] lock_acquire+0x267/0x330
[ 6567.221479] _raw_spin_lock+0x2f/0x40
[ 6567.221479] smb2_find_smb_tcon+0x24/0xc0 [cifs]
[ 6567.221479] smb2_handle_cancelled_mid+0x3e/0x90 [cifs]
[ 6567.221479] cifs_mid_q_entry_release+0x28a/0x610 [cifs]
[ 6567.223102] cifs_demultiplex_thread+0x848/0xf70 [cifs]
[ 6567.223102] kthread+0xe8/0x110
[ 6567.223642] ret_from_fork+0x22/0x30
[ 6567.223642]
other info that might help us debug this:
[ 6567.223642] Possible unsafe locking scenario:
[ 6567.225550] CPU0 CPU1
[ 6567.225550] ---- ----
[ 6567.225550] lock(&GlobalMid_Lock);
[ 6567.225550] lock(&cifs_tcp_ses_lock);
[ 6567.228648] lock(&GlobalMid_Lock);
[ 6567.228648] lock(&cifs_tcp_ses_lock);
[ 6567.229647]
*** DEADLOCK ***
[ 6567.230447] 1 lock held by cifsd/5791:
[ 6567.231573] #0: ffffffffc0b29698 (&GlobalMid_Lock){+.+.}-{2:2},
at: cifs_mid_q_entry_release+0x22/0x610 [cifs]
[ 6567.232498]
stack backtrace:
[ 6567.232630] CPU: 3 PID: 5791 Comm: cifsd Not tainted 5.17.0-rc3 #1
[ 6567.232630] Hardware name: Red Hat KVM, BIOS 0.5.1 01/01/2011
[ 6567.234451] Call Trace:
[ 6567.234451] <TASK>
[ 6567.234451] dump_stack_lvl+0x58/0x71
[ 6567.234451] check_noncircular+0xe7/0x100
[ 6567.234451] ? __lock_acquire+0xb7e/0x18d0
[ 6567.234451] ? __lock_acquire+0x1302/0x18d0
[ 6567.234451] __lock_acquire+0x1302/0x18d0
[ 6567.234451] lock_acquire+0x267/0x330
[ 6567.234451] ? smb2_find_smb_tcon+0x24/0xc0 [cifs]
[ 6567.234451] _raw_spin_lock+0x2f/0x40
[ 6567.234451] ? smb2_find_smb_tcon+0x24/0xc0 [cifs]
[ 6567.234451] smb2_find_smb_tcon+0x24/0xc0 [cifs]
[ 6567.240749] smb2_handle_cancelled_mid+0x3e/0x90 [cifs]
[ 6567.240749] ? _raw_spin_lock+0x2f/0x40
[ 6567.240749] cifs_mid_q_entry_release+0x28a/0x610 [cifs]
[ 6567.240749] ? lock_release+0x1db/0x2b0
[ 6567.240749] cifs_demultiplex_thread+0x848/0xf70 [cifs]
[ 6567.240749] ? cifs_handle_standard+0x210/0x210 [cifs]
[ 6567.240749] kthread+0xe8/0x110
[ 6567.240749] ? kthread_complete_and_exit+0x20/0x20
[ 6567.240749] ret_from_fork+0x22/0x30
[ 6567.240749] </TASK>
[ 6567.252563] CIFS: VFS: \\win16.vm.test\Share Close unmatched open for MID:404
[ 6567.256753] CIFS: VFS: \\win16.vm.test\Share Close unmatched open for MID:405
[ 6567.269283] CIFS: VFS: \\win16.vm.test\Share Close unmatched open for MID:407
[ 6567.271962] CIFS: VFS: \\win16.vm.test\Share Close unmatched open for MID:408
--
Thanks,
Steve
