Possible recursive locking warning reported by lockdep

[mmakassikis]

Hello,

On a mainline kernel Linux 6.6-rc5 (commit id 94f6f0550c) compiled with lockdep, running some workloads triggers a "possible recursive locking detected" warning.

For example, running the smb2.rename test from Samba using the following command

../bin/smbtorture //192.168.1.30/testshare -U testuser%tespass smb2.rename

Partial dmesg log below with the ksmbd logs and the lockdep warning + backtrace.

The locking attempts are:

• filename_create+0xb6/0x260 => fs/namei.c:3882
• ksmbd_vfs_mkdir+0xe1/0x410 => smb/server/vfs.c:222

In both cases, these are calls to mnt_want_write(path.mnt) which locks sb_writers with sb_start_write

The call stack is as follows:

  ksmbd_vfs_mkdir()
    -> ksmbd_vfs_kern_path_create()
        -> kern_path_create()
          -> filename_create()
            -> mnt_want_write()
    -> mnt_want_write()

There is no call to mnt_done_write() (direct or through done_path_create()) so lockdep sees a recursion.

Reverting 40b268d38 ("ksmbd: add mnt_want_write to ksmbd vfs functions") silences lockdep

[   40.406489] ksmbd: connect success: accepted new connection
[   40.407180] ksmbd: RFC1002 header 232 bytes
[   40.407290] ksmbd: no length check for command
[   40.407300] ksmbd: SMB2 data length 0 offset 0
[   40.407308] ksmbd: SMB2 len 100
[   40.407317] ksmbd: client requested dialect 0x311
[   40.407325] ksmbd: selected \x02SMB 3.1.1 dialect
[   40.407333] ksmbd: conn->dialect 0x311
[   40.407355] ksmbd: Received negotiate request
[   40.407368] ksmbd: decoding 4 negotiate contexts
[   40.407375] ksmbd: deassemble SMB2_PREAUTH_INTEGRITY_CAPABILITIES context
[   40.407382] ksmbd: deassemble SMB2_ENCRYPTION_CAPABILITIES context
[   40.407389] ksmbd: Cipher ID = 0x2
[   40.407396] ksmbd: deassemble SMB2_SIGNING_CAPABILITIES context
[   40.407403] ksmbd: Signing Algorithm ID = 0x1
[   40.407410] ksmbd: deassemble SMB2_NETNAME_NEGOTIATE_CONTEXT_ID context
[   40.407433] ksmbd: assemble SMB2_PREAUTH_INTEGRITY_CAPABILITIES context
[   40.407447] ksmbd: assemble SMB2_ENCRYPTION_CAPABILITIES context
[   40.407454] ksmbd: assemble SMB2_SIGNING_CAPABILITIES context
[   40.407463] ksmbd: negotiate context offset 208, count 3
[   40.407472] ksmbd: credits: requested[31] granted[1] total_granted[1]
[   40.408275] ksmbd: RFC1002 header 162 bytes
[   40.408419] ksmbd: SMB2 data length 74 offset 88
[   40.408430] ksmbd: SMB2 len 162
[   40.408439] ksmbd: Received request for session setup
[   40.408497] ksmbd: negotiate phase
[   40.408536] ksmbd: NTLMSSP SecurityBufferLength 208
[   40.408563] ksmbd: credits: requested[31] granted[31] total_granted[31]
[   40.409423] ksmbd: RFC1002 header 574 bytes
[   40.409500] ksmbd: SMB2 data length 486 offset 88
[   40.409521] ksmbd: SMB2 len 574
[   40.409529] ksmbd: Received request for session setup
[   40.409571] ksmbd: authenticate phase
[   40.409593] ksmbd: session setup request for user freebox
[   40.410421] ksmbd: decode_ntlmssp_authenticate_blob dnameWORKGROUP
[   40.410535] ksmbd: dumping generated AES encryption keys
[   40.410543] ksmbd: Cipher type   2
[   40.410551] ksmbd: Session Id    1
[   40.410558] ksmbd: Session Key   68 fe 49 2b 2f 4b 55 01 75 7c 48 e0 0f f8 ed a1
[   40.410567] ksmbd: ServerIn Key  60 95 4c 46 f7 d7 68 c7 54 88 bd 07 49 48 67 34
[   40.410575] ksmbd: ServerOut Key df 55 54 20 8c 44 47 01 f0 4d 60 1f 1c c3 08 e7
[   40.410705] ksmbd: dumping generated AES signing keys
[   40.410714] ksmbd: Session Id    1
[   40.410721] ksmbd: Session Key   68 fe 49 2b 2f 4b 55 01 75 7c 48 e0 0f f8 ed a1
[   40.410730] ksmbd: Signing Key   85 c6 2c df e1 a0 ff 46 0c a9 e7 61 ec e4 57 6a
[   40.410750] ksmbd: credits: requested[1] granted[1] total_granted[31]
[   40.411512] ksmbd: RFC1002 header 116 bytes
[   40.411605] ksmbd: skip to check tree connect request
[   40.411615] ksmbd: SMB2 data length 44 offset 72
[   40.411623] ksmbd: SMB2 len 116
[   40.411667] ksmbd: tree connect request for tree testshare treename \\192.168.1.30\testshare
[   40.413510] ksmbd: credits: requested[1] granted[1] total_granted[31]
[   40.414458] ksmbd: RFC1002 header 130 bytes
[   40.414537] ksmbd: RFC1002 header 130 bytes
[   40.414593] ksmbd: RFC1002 header 130 bytes
[   40.414798] ksmbd: SMB2 data length 10 offset 120
[   40.414814] ksmbd: SMB2 len 130
[   40.414836] ksmbd: converted name = dir-0
[   40.415784] ksmbd: can not get linux path for dir-0, rc = -2
[   40.415802] ksmbd: file does not exist, so creating
[   40.415812] ksmbd: creating directory

[   40.416288] ============================================
[   40.417150] WARNING: possible recursive locking detected
[   40.418028] 6.6.0-rc5 #775 Not tainted
[   40.418662] --------------------------------------------
[   40.419534] kworker/1:1/32 is trying to acquire lock:
[   40.420371] ffff888005ac83f8 (sb_writers#5){.+.+}-{0:0}, at: ksmbd_vfs_mkdir+0xe1/0x410
[   40.421726] 
               but task is already holding lock:
[   40.422680] ffff888005ac83f8 (sb_writers#5){.+.+}-{0:0}, at: filename_create+0xb6/0x260
[   40.424004] 
               other info that might help us debug this:
[   40.425071]  Possible unsafe locking scenario:

[   40.426043]        CPU0
[   40.426466]        ----
[   40.426889]   lock(sb_writers#5);
[   40.427461]   lock(sb_writers#5);
[   40.428058] 
                *** DEADLOCK ***

[   40.429108]  May be due to missing lock nesting notation

[   40.430218] 4 locks held by kworker/1:1/32:
[   40.430922]  #0: ffff8880064e4138 ((wq_completion)ksmbd-io){+.+.}-{0:0}, at: process_one_work+0x40e/0x980
[   40.432525]  #1: ffff888005b0fdd0 ((work_completion)(&work->work)){+.+.}-{0:0}, at: process_one_work+0x40e/0x980
[   40.434185]  #2: ffff888005ac83f8 (sb_writers#5){.+.+}-{0:0}, at: filename_create+0xb6/0x260
[   40.435591]  #3: ffff8880057ce760 (&type->i_mutex_dir_key#3/1){+.+.}-{3:3}, at: filename_create+0x123/0x260
[   40.437200] 
               stack backtrace:
[   40.437959] CPU: 1 PID: 32 Comm: kworker/1:1 Not tainted 6.6.0-rc5 #775
[   40.439060] Workqueue: ksmbd-io handle_ksmbd_work
[   40.439870] Call Trace:
[   40.440320]  <TASK>
[   40.440700]  dump_stack_lvl+0x4f/0x90
[   40.441357]  dump_stack+0x14/0x20
[   40.441934]  print_deadlock_bug+0x2f0/0x410
[   40.442626]  check_deadlock+0x26b/0x3b0
[   40.443287]  __lock_acquire+0xce2/0x1060
[   40.443970]  ? mark_lock.part.0+0xff/0x720
[   40.444688]  ? __pfx___lock_acquire+0x10/0x10
[   40.445494]  ? mark_held_locks+0x6b/0x90
[   40.446176]  lock_acquire.part.0+0x125/0x2d0
[   40.446906]  ? ksmbd_vfs_mkdir+0xe1/0x410
[   40.447593]  ? __pfx_lock_acquire.part.0+0x10/0x10
[   40.448413]  ? __kmem_cache_free+0x179/0x280
[   40.449154]  ? ____kasan_slab_free+0x15b/0x1d0
[   40.449926]  ? __kasan_slab_free+0x16/0x20
[   40.450626]  ? slab_free_freelist_hook+0xbc/0x180
[   40.451426]  lock_acquire+0x93/0x160
[   40.452054]  ? ksmbd_vfs_mkdir+0xe1/0x410
[   40.452743]  mnt_want_write+0x49/0x220
[   40.453404]  ? ksmbd_vfs_mkdir+0xe1/0x410
[   40.454091]  ksmbd_vfs_mkdir+0xe1/0x410
[   40.454755]  ? __pfx__printk+0x10/0x10
[   40.455413]  ? __pfx_ksmbd_vfs_mkdir+0x10/0x10
[   40.456192]  smb2_open+0x1064/0x38b0
[   40.456830]  ? __pfx___lock_acquire+0x10/0x10
[   40.457585]  ? __pfx_smb2_open+0x10/0x10
[   40.458263]  ? __lock_release+0x13f/0x290
[   40.458950]  ? smb2_validate_credit_charge+0x25d/0x360
[   40.459814]  ? __pfx___lock_release+0x10/0x10
[   40.460574]  ? do_raw_spin_lock+0x127/0x1c0
[   40.461326]  ? __pfx_do_raw_spin_lock+0x10/0x10
[   40.462152]  ? do_raw_spin_unlock+0xac/0x110
[   40.462888]  ? _raw_spin_unlock+0x22/0x50
[   40.463581]  ? smb2_validate_credit_charge+0x25d/0x360
[   40.464467]  ? ksmbd_smb2_check_message+0x3be/0x400
[   40.465282]  ? __pfx_ksmbd_smb2_check_message+0x10/0x10
[   40.466156]  __process_request+0x151/0x310
[   40.466854]  __handle_ksmbd_work+0x33c/0x520
[   40.467583]  ? __pfx___handle_ksmbd_work+0x10/0x10
[   40.468395]  handle_ksmbd_work+0x4a/0xd0
[   40.469016]  process_one_work+0x4a7/0x980
[   40.469672]  ? __pfx_process_one_work+0x10/0x10
[   40.470391]  ? assign_work+0xe1/0x120
[   40.470982]  worker_thread+0x365/0x570
[   40.471589]  ? __pfx_worker_thread+0x10/0x10
[   40.472269]  kthread+0x18d/0x1d0
[   40.472802]  ? __pfx_kthread+0x10/0x10
[   40.473403]  ret_from_fork+0x38/0x70
[   40.473969]  ? __pfx_kthread+0x10/0x10
[   40.474566]  ret_from_fork_asm+0x1b/0x30
[   40.475203]  </TASK>
[   40.476304] ksmbd: inherit posix acl failed : -2
[   40.477115] ksmbd: credits: requested[1] granted[1] total_granted[31]
[   40.478209] ksmbd: SMB2 data length 10 offset 120
[   40.479020] ksmbd: SMB2 len 130

[namjaejeon]

@mmakassikis Good catch! We need to remove all mnt_want_write/mnt_done_write() anywhere ksmbd_vfs_kern_path_create is used as well as ksmbd_vfs_mkdir(). Can you send the patch to the list for this ?

[mmakassikis]

After removing the mnt_want_write/mnt_drop_write calls in vfs helpers that use ksmbd_vfs_kern_path_create, I tested a simple mkdir using smbclient and I see a different lockdep warning.

I'm not sure what the issue is this time though. Removing the mnt_want_write in ksmbd_vfs_setxattr silences the warning, but it looks like sweeping the issue under the rug.

Any idea what may be wrong ?

addr2line conversions:

• ksmbd_vfs_setxattr+0x38/0xd0 => fs/vfs.c:923 (mnt_want_write())
• ksmbd_vfs_path_lookup_locked+0x163/0x2f0 => smb/server/vfs.c:101 (lookup_one_qstr_excl(&last, parent_path->dentry, 0);)

lockdep warning:

ksmbd: SMB2 data length 10 offset 120
ksmbd: SMB2 len 130
ksmbd: converted name = dir-0
ksmbd: can not get linux path for dir-0, rc = -2
ksmbd: file does not exist, so creating
ksmbd: creating directory
ksmbd: inherit posix acl failed : -2
======================================================
WARNING: possible circular locking dependency detected
6.6.0-rc5+ #798 Not tainted
------------------------------------------------------
kworker/1:0/22 is trying to acquire lock:
ffff8880063163f8 (sb_writers#5){.+.+}-{0:0}, at: ksmbd_vfs_setxattr+0x38/0xd0

but task is already holding lock:
ffff8880057ca1d0 (&type->i_mutex_dir_key#3/1){+.+.}-{3:3}, at: ksmbd_vfs_path_lookup_locked+0x163/0x2f0

which lock already depends on the new lock.

the existing dependency chain (in reverse order) is:

-> #1 (&type->i_mutex_dir_key#3/1){+.+.}-{3:3}:
       lock_acquire.part.0+0x125/0x2d0
       lock_acquire+0x93/0x160
       down_write_nested+0x84/0x190
       do_rmdir+0x1ad/0x2d0
       __x64_sys_rmdir+0x63/0x80
       do_syscall_64+0x3c/0x90
       entry_SYSCALL_64_after_hwframe+0x6e/0xd8

-> #0 (sb_writers#5){.+.+}-{0:0}:
       check_prev_add+0x1c7/0x1500
       __lock_acquire+0xecc/0x1060
       lock_acquire.part.0+0x125/0x2d0
       lock_acquire+0x93/0x160
       mnt_want_write+0x49/0x220
       ksmbd_vfs_setxattr+0x38/0xd0
       ksmbd_vfs_set_dos_attrib_xattr+0xc7/0x110
       smb2_new_xattrs+0x186/0x1d0
       smb2_open+0x316a/0x3740
       __process_request+0x151/0x310
       __handle_ksmbd_work+0x33c/0x520
       handle_ksmbd_work+0x4a/0xd0
       process_one_work+0x4a7/0x980
       worker_thread+0x365/0x570
       kthread+0x18d/0x1d0
       ret_from_fork+0x38/0x70
       ret_from_fork_asm+0x1b/0x30

other info that might help us debug this:

 Possible unsafe locking scenario:

       CPU0                    CPU1
       ----                    ----
  lock(&type->i_mutex_dir_key#3/1);
                               lock(sb_writers#5);
                               lock(&type->i_mutex_dir_key#3/1);
  rlock(sb_writers#5);

 *** DEADLOCK ***

3 locks held by kworker/1:0/22:
 #0: ffff8880063e4938 ((wq_completion)ksmbd-io){+.+.}-{0:0}, at: process_one_work+0x40e/0x980
 #1: ffff8880052efdd0 ((work_completion)(&work->work)){+.+.}-{0:0}, at: process_one_work+0x40e/0x980
 #2: ffff8880057ca1d0 (&type->i_mutex_dir_key#3/1){+.+.}-{3:3}, at: ksmbd_vfs_path_lookup_locked+0x163/0x2f0

stack backtrace:
CPU: 1 PID: 22 Comm: kworker/1:0 Not tainted 6.6.0-rc5+ #798
Workqueue: ksmbd-io handle_ksmbd_work
Call Trace:
 <TASK>
 dump_stack_lvl+0x4f/0x90
 dump_stack+0x14/0x20
 print_circular_bug+0x138/0x160
 check_noncircular+0x292/0x2f0
 ? __pfx_check_noncircular+0x10/0x10
 ? mark_held_locks+0x6b/0x90
 ? __stack_depot_save+0x266/0x370
 ? add_chain_block+0x2a2/0x4a0
 check_prev_add+0x1c7/0x1500
 ? check_deadlock+0x169/0x3b0
 __lock_acquire+0xecc/0x1060
 ? smb2_open+0x316a/0x3740
 ? __handle_ksmbd_work+0x33c/0x520
 ? handle_ksmbd_work+0x4a/0xd0
 ? __pfx___lock_acquire+0x10/0x10
 ? __lock_release+0x13f/0x290
 ? __pfx___lock_release+0x10/0x10
 ? __pfx_do_raw_spin_lock+0x10/0x10
 lock_acquire.part.0+0x125/0x2d0
 ? ksmbd_vfs_setxattr+0x38/0xd0
 ? __pfx_lock_acquire.part.0+0x10/0x10
 ? kasan_set_track+0x29/0x40
 ? kasan_save_alloc_info+0x1f/0x30
 ? strlen+0x13/0x50
 lock_acquire+0x93/0x160
 ? ksmbd_vfs_setxattr+0x38/0xd0
 mnt_want_write+0x49/0x220
 ? ksmbd_vfs_setxattr+0x38/0xd0
 ksmbd_vfs_setxattr+0x38/0xd0
 ksmbd_vfs_set_dos_attrib_xattr+0xc7/0x110
 ? __pfx_ksmbd_vfs_set_dos_attrib_xattr+0x10/0x10
 ? generic_fillattr+0x269/0x2f0
 smb2_new_xattrs+0x186/0x1d0
 ? __pfx_smb2_new_xattrs+0x10/0x10
 ? __pfx_ksmbd_UnixTimeToNT+0x10/0x10
 ? vfs_getattr+0x36/0x50
 smb2_open+0x316a/0x3740
 ? __pfx_smb2_open+0x10/0x10
 ? __lock_release+0x13f/0x290
 ? smb2_validate_credit_charge+0x25d/0x360
 ? __pfx___lock_release+0x10/0x10
 ? do_raw_spin_lock+0x127/0x1c0
 ? __pfx_do_raw_spin_lock+0x10/0x10
 ? do_raw_spin_unlock+0xac/0x110
 ? _raw_spin_unlock+0x22/0x50
 __process_request+0x151/0x310
 __handle_ksmbd_work+0x33c/0x520
 ? __pfx___handle_ksmbd_work+0x10/0x10
 handle_ksmbd_work+0x4a/0xd0
 process_one_work+0x4a7/0x980
 ? __pfx_process_one_work+0x10/0x10
 ? assign_work+0xe1/0x120
 worker_thread+0x365/0x570
 ? __pfx_worker_thread+0x10/0x10
 kthread+0x18d/0x1d0
 ? __pfx_kthread+0x10/0x10
 ret_from_fork+0x38/0x70
 ? __pfx_kthread+0x10/0x10
 ret_from_fork_asm+0x1b/0x30
 </TASK>

[namjaejeon]

I'm not sure but smb2_open call inode lock and ksmbd_vfs_setxattr is called in smb2_open. So I think that you can create __ksmbd_vfs_setxattr() not to call mnt_want_write().

ksmbd_vfs_setxattr()
{
mnt_want_write()
  __ksmbd_vfs_setxattr()
mnt_done_write
}

[namjaejeon]

@mmakassikis I have checked your patch in mailing list. You will send the patch for ksmbd_vfs_setxattr() ?

[namjaejeon]

@mmakassikis Can you check if problem is improved ?

git clone https://github.com/namjaejeon/ksmbd --branch=lockdep_warn

[namjaejeon]

I think that problem is fixed now. Let me know if you find it.