1760835 – processes reading the same file on a cifs share block indefinitely on cifsInodeInfo.lock_sem semaphore after a network disruption or smb restart

RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.

Bug 1760835 - processes reading the same file on a cifs share block indefinitely on cifsInodeInfo.lock_sem semaphore after a network disruption or smb restart

Summary: processes reading the same file on a cifs share block indefinitely on cifsIno...

Keywords:
Status:	CLOSED DUPLICATE of bug 1765979
Alias:	None
Product:	Red Hat Enterprise Linux 8
Classification:	Red Hat
Component:	kernel
Sub Component:
Version:	8.1
Hardware:	Unspecified
OS:	Unspecified
Priority:	unspecified
Severity:	medium
Target Milestone:	rc
Target Release:	---
Assignee:	Dave Wysochanski
QA Contact:	JianHong Yin
Docs Contact:
URL:
Whiteboard:
Depends On:	1757865 1767357
Blocks:
TreeView+	depends on / blocked

Reported:	2019-10-11 12:51 UTC by Dave Wysochanski
Modified:	2019-11-04 15:51 UTC (History)
CC List:	3 users (show)
Fixed In Version:
Doc Type:	If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:	2019-10-28 08:23:19 UTC
Type:	Bug
Target Upstream Version:
Embargoed:
Dependent Products:

Attachments	(Terms of Use)
python3 program to repeatedly open / read / close file (172 bytes, text/plain) 2019-10-11 13:54 UTC, Dave Wysochanski	no flags	Details
debug patch on top of 5.4-rc4 that adds simple cifs_dbg based tracing to lock_sem (10.58 KB, application/octet-stream) 2019-10-21 16:22 UTC, Dave Wysochanski	no flags	Details
patch posted on linux-cifs to fix this bug - ronnie suggested approach (5.20 KB, text/plain) 2019-10-24 12:20 UTC, Dave Wysochanski	no flags	Details
View All

Links
System	ID	Private	Priority	Status	Summary	Last Updated
Red Hat Knowledge Base (Solution)	4550781	0	None	None	None	2019-11-04 15:51:21 UTC

Description Dave Wysochanski 2019-10-11 12:51:28 UTC

Description of problem:
While testing the fix for bug 1757865, a separate problem can occur with the same testcase for bug 1757865 if we add a temporary network disruption with iptables "drop" rule on cifs traffic (tcp port 445)

Version-Release number of selected component (if applicable):
kernel 4.18.0-147.el7 plus commit e5fcebc5b02001671e0b3b23b56bf07b8a28674

How reproducible:
easy

Steps to Reproduce:
1. Run reproducer from bug 1757865 with a 100 or more instances of 'openloop.py' which open / read / close a single file on a cifs share

2. Temporarily block the port with iptables on samba server
date; iptables -A INPUT -p tcp --dport 445 -j DROP; sleep 120; date; iptables -D INPUT -p tcp --dport 445 -j DROP

3. Check existing processes to see if they are blocked indefinitely with backtraces indicating wait on a semaphore as shown below.

*NOTE: It may take a few iterations of blocking the port to see the processes become blocked indefinitely.


Actual results:
Once the network disruption clears, the cifs share is accessible again, including reading the file that the original processes were reading.  However, processes started before the network disruption and reading the file become blocked indefinitely with backtraces similar to the following:
The process causing the deadlock looks like this - blocked in cifs_reopen_file ... rwsem_down_read_failed:

PID: 5464   TASK: ffff9862640b2f80  CPU: 1   COMMAND: "python3-openloo"
 #0 [ffffbd2d81203a20] __schedule at ffffffff9aa629e3
 #1 [ffffbd2d81203ac0] schedule at ffffffff9aa62fe8
 #2 [ffffbd2d81203ac8] rwsem_down_read_failed at ffffffff9aa660cd
 #3 [ffffbd2d81203b58] cifs_reopen_file at ffffffffc0529dce [cifs]
 #4 [ffffbd2d81203c00] cifs_read.constprop.46 at ffffffffc052bbe0 [cifs]
 #5 [ffffbd2d81203ca8] cifs_readpage_worker at ffffffffc052c0a7 [cifs]
 #6 [ffffbd2d81203ce0] cifs_readpage at ffffffffc052c427 [cifs]
 #7 [ffffbd2d81203d20] generic_file_buffered_read at ffffffff9a40f2b1
 #8 [ffffbd2d81203e10] cifs_strict_readv at ffffffffc0533a7b [cifs]
 #9 [ffffbd2d81203e40] new_sync_read at ffffffff9a4b6e21
#10 [ffffbd2d81203ec8] vfs_read at ffffffff9a4b9671
#11 [ffffbd2d81203f00] ksys_read at ffffffff9a4b9aaf
#12 [ffffbd2d81203f38] do_syscall_64 at ffffffff9a2041cb



Many other processes look like this, either blocked in _cifsFileInfo_put ... rwsem_down_write_slowpath:

PID: 14206  TASK: ffff8ac1f336dac0  CPU: 6   COMMAND: "python3-openloo"
 #0 [ffff9cfc41cc3c20] __schedule at ffffffff9f9d2d29
 #1 [ffff9cfc41cc3cb0] schedule at ffffffff9f9d31a9
 #2 [ffff9cfc41cc3cc8] rwsem_down_write_slowpath at ffffffff9f131b0a
 #3 [ffff9cfc41cc3d98] _cifsFileInfo_put at ffffffffc06596eb [cifs]
 #4 [ffff9cfc41cc3e78] cifs_close at ffffffffc0659a0f [cifs]
 #5 [ffff9cfc41cc3e88] __fput at ffffffff9f2f6981
 #6 [ffff9cfc41cc3ed0] task_work_run at ffffffff9f0fc897
 #7 [ffff9cfc41cc3f08] exit_to_usermode_loop at ffffffff9f003f83
 #8 [ffff9cfc41cc3f38] do_syscall_64 at ffffffff9f0043c2
 #9 [ffff9cfc41cc3f50] entry_SYSCALL_64_after_hwframe at ffffffff9fa0008c



or in cifs_new_fileinfo ... rwsem_down_write_slowpath:

PID: 14207  TASK: ffff8ac1f3369e40  CPU: 6   COMMAND: "python3-openloo"
 #0 [ffff9cfc41ccb990] __schedule at ffffffff9f9d2d29
 #1 [ffff9cfc41ccba20] schedule at ffffffff9f9d31a9
 #2 [ffff9cfc41ccba38] rwsem_down_write_slowpath at ffffffff9f131b0a
 #3 [ffff9cfc41ccbb08] cifs_new_fileinfo at ffffffffc065833a [cifs]
 #4 [ffff9cfc41ccbb78] cifs_open at ffffffffc0658a8c [cifs]
 #5 [ffff9cfc41ccbcd0] do_dentry_open at ffffffff9f2f09ca
 #6 [ffff9cfc41ccbd00] path_openat at ffffffff9f3050ad
 #7 [ffff9cfc41ccbdd8] do_filp_open at ffffffff9f307431
 #8 [ffff9cfc41ccbee0] do_sys_open at ffffffff9f2f2154
 #9 [ffff9cfc41ccbf38] do_syscall_64 at ffffffff9f0042bb
#10 [ffff9cfc41ccbf50] entry_SYSCALL_64_after_hwframe at ffffffff9fa0008c


Expected results:
Processes do not become blocked indefinitely.


Additional info:
We have vmcores and some analysis on the blockage, but no fix.  The problem can be reproduced on latest kernel.org 5.4-rc1 + commit e5fcebc5b02001671e0b3b23b56bf07b8a28674

Marking as 'medium' severity because it is not a full hang, and believed to be a corner case that only can happen during a network disruption and multiple processes reading the same file.

Comment 1 Frank Sorenson 2019-10-11 13:37:21 UTC

in the vmcore mentioned, the rwsem is 0xffff986265932658

crash> rw_semaphore.count.counter,owner 0xffff986265932658
  count.counter = 0xffffffff00000003
  owner = 0xffff9862640b2f83

crash> kmem -s 0xffff9862640b2f83 | tail -1
  [ffff9862640b2f80]

crash> ps -m ffff9862640b2f80
[0 02:50:12.936] [UN]  PID: 5464   TASK: ffff9862640b2f80  CPU: 1   COMMAND: "python3-openloo"


crash> rw_semaphore.wait_list 0xffff986265932658 -ox
struct rw_semaphore {
  [ffff986265932660] struct list_head wait_list;

crash> list -H ffff986265932660 -o rwsem_waiter.list -s rwsem_waiter.type,task | paste - - - | awk '{print $1,$4,$7}' | egrep -n ffff9862640b2f80 -B2 -A2

23-ffffbd2d80fdfa90 RWSEM_WAITING_FOR_WRITE 0xffff9862788fdf00
24-ffffbd2d81253a90 RWSEM_WAITING_FOR_WRITE 0xffff98625aa15f00
25:ffffbd2d81203af0 RWSEM_WAITING_FOR_READ 0xffff9862640b2f80
26-ffffbd2d810eba90 RWSEM_WAITING_FOR_WRITE 0xffff98625687af80
27-ffffbd2d811b3a90 RWSEM_WAITING_FOR_WRITE 0xffff9862586c5f00


The process causing the deadlock is trying to take an rwsem for a second time, and is stuck in the wait list behind some write waiters:

PID: 5464   TASK: ffff9862640b2f80  CPU: 1   COMMAND: "python3-openloo"
 #0 [ffffbd2d81203a20] __schedule at ffffffff9aa629e3
 #1 [ffffbd2d81203ac0] schedule at ffffffff9aa62fe8
 #2 [ffffbd2d81203ac8] rwsem_down_read_failed at ffffffff9aa660cd
 #3 [ffffbd2d81203b58] cifs_reopen_file at ffffffffc0529dce [cifs]
 #4 [ffffbd2d81203c00] cifs_read.constprop.46 at ffffffffc052bbe0 [cifs]
 #5 [ffffbd2d81203ca8] cifs_readpage_worker at ffffffffc052c0a7 [cifs]
 #6 [ffffbd2d81203ce0] cifs_readpage at ffffffffc052c427 [cifs]
 #7 [ffffbd2d81203d20] generic_file_buffered_read at ffffffff9a40f2b1
 #8 [ffffbd2d81203e10] cifs_strict_readv at ffffffffc0533a7b [cifs]
 #9 [ffffbd2d81203e40] new_sync_read at ffffffff9a4b6e21
#10 [ffffbd2d81203ec8] vfs_read at ffffffff9a4b9671
#11 [ffffbd2d81203f00] ksys_read at ffffffff9a4b9aaf
#12 [ffffbd2d81203f38] do_syscall_64 at ffffffff9a2041cb


the first time in cifs_strict_readv:
 
        down_read(&cinode->lock_sem);
        if (!cifs_find_lock_conflict(cfile, iocb->ki_pos, iov_iter_count(to),
                                     tcon->ses->server->vals->shared_lock_type,
                                     0, NULL, CIFS_READ_OP))
                rc = generic_file_read_iter(iocb, to);                          <<<<
        up_read(&cinode->lock_sem);


which calls into cifs_read(), which needs to reopen the file:
                        if (open_file->invalidHandle) {
                                rc = cifs_reopen_file(open_file, true);  <<<<
                                if (rc != 0)
                                        break;
                        }


     static int
     cifs_reopen_file(struct cifsFileInfo *cfile, bool can_flush)
     {
...
(near the end of the function)
 
             server->ops->set_fid(cfile, &cfile->fid, oplock);
             if (oparms.reconnect)
                    cifs_relock_file(cfile);


static int
cifs_relock_file(struct cifsFileInfo *cfile)
{
        struct cifs_sb_info *cifs_sb = CIFS_SB(cfile->dentry->d_sb);
        struct cifsInodeInfo *cinode = CIFS_I(d_inode(cfile->dentry));
        struct cifs_tcon *tcon = tlink_tcon(cfile->tlink);
        int rc = 0;
 
        down_read_nested(&cinode->lock_sem, SINGLE_DEPTH_NESTING);  <<<<
        if (cinode->can_cache_brlcks) {

^^^^ trying to take the rwsem for read here as well

Comment 3 Dave Wysochanski 2019-10-11 13:54:24 UTC

Created attachment 1624736 [details]
python3 program to repeatedly open / read / close file

Comment 4 Frank Sorenson 2019-10-11 13:55:54 UTC

quick reminder of the obvious: this bug will not manifest unless/until the aforementioned BZs regarding crashes in is_size_safe_to_change have been resolved, since the system will crash with those bugs before this bug will reproduce

Comment 5 Dave Wysochanski 2019-10-14 15:45:53 UTC

FWIW, I'm pretty sure this will also occur on RHEL7, at least 1062.el7 + patches to fix https://bugzilla.redhat.com/show_bug.cgi?id=1757872
I'll have to test this again on 7.8 candidate plus the patches in that bug, then dup this bug to rhel7 if it reproduces (which I cannot imagine why it would not, since we know this repro's on upstream).

Comment 6 Frank Sorenson 2019-10-15 16:28:13 UTC

this does reproduce in RHEL 7

Comment 7 Dave Wysochanski 2019-10-21 01:28:18 UTC

Of the waiters, there is another process blocked almost 6 hours on the same semaphore from comment #1:

[0 02:50:12.935] [UN]  PID: 5455   TASK: ffff9862586c5f00  CPU: 3   COMMAND: "python3-openloo"
[0 02:50:12.935] [UN]  PID: 5431   TASK: ffff98625687af80  CPU: 1   COMMAND: "python3-openloo"
[0 02:50:12.936] [UN]  PID: 5464   TASK: ffff9862640b2f80  CPU: 1   COMMAND: "python3-openloo"
[0 02:50:12.936] [UN]  PID: 5474   TASK: ffff98625aa15f00  CPU: 0   COMMAND: "python3-openloo"
[0 02:50:12.937] [UN]  PID: 5415   TASK: ffff9862788fdf00  CPU: 2   COMMAND: "python3-openloo"


crash> ps -m | grep UN | tail
[0 02:50:12.939] [UN]  PID: 5473   TASK: ffff98625aa12f80  CPU: 1   COMMAND: "python3-openloo"
[0 02:50:12.940] [UN]  PID: 5401   TASK: ffff986277c5c740  CPU: 3   COMMAND: "python3-openloo"
[0 02:50:12.940] [UN]  PID: 5437   TASK: ffff986258730000  CPU: 1   COMMAND: "python3-openloo"
[0 02:50:12.940] [UN]  PID: 5427   TASK: ffff98625a8217c0  CPU: 2   COMMAND: "python3-openloo"
[0 02:50:12.940] [UN]  PID: 5481   TASK: ffff98625aa8c740  CPU: 3   COMMAND: "python3-openloo"
[0 02:50:12.940] [UN]  PID: 5486   TASK: ffff98625afddf00  CPU: 0   COMMAND: "python3-openloo"
[0 02:50:12.941] [UN]  PID: 5480   TASK: ffff98625879df00  CPU: 0   COMMAND: "python3-openloo"
[0 02:50:13.017] [UN]  PID: 5484   TASK: ffff98625aa8df00  CPU: 3   COMMAND: "python3-openloo"
[0 02:50:13.017] [UN]  PID: 5467   TASK: ffff98625f8ac740  CPU: 0   COMMAND: "python3-openloo"
[0 05:49:42.208] [UN]  PID: 5411   TASK: ffff9862788fc740  CPU: 3   COMMAND: "python3-openloo"
crash> ps -m | grep "05:49:42"
[0 05:49:42.208] [UN]  PID: 5411   TASK: ffff9862788fc740  CPU: 3   COMMAND: "python3-openloo"
crash> bt 5411
PID: 5411   TASK: ffff9862788fc740  CPU: 3   COMMAND: "python3-openloo"
 #0 [ffffbd2d80fbfc60] __schedule at ffffffff9aa629e3
 #1 [ffffbd2d80fbfd00] schedule at ffffffff9aa62fe8
 #2 [ffffbd2d80fbfd08] rwsem_down_write_failed at ffffffff9aa65dbc
 #3 [ffffbd2d80fbfda8] down_write at ffffffff9aa65be9
 #4 [ffffbd2d80fbfdb8] _cifsFileInfo_put at ffffffffc052da65 [cifs]
 #5 [ffffbd2d80fbfe98] cifs_close at ffffffffc052dd3f [cifs]
 #6 [ffffbd2d80fbfea8] __fput at ffffffff9a4ba5c7
 #7 [ffffbd2d80fbfee8] task_work_run at ffffffff9a2d1c5a
 #8 [ffffbd2d80fbff20] exit_to_usermode_loop at ffffffff9a203b4b
 #9 [ffffbd2d80fbff38] do_syscall_64 at ffffffff9a2042f2
#10 [ffffbd2d80fbff50] entry_SYSCALL_64_after_hwframe at ffffffff9ac000ad
    RIP: 00007fb09ace8bb5  RSP: 00007ffd61588078  RFLAGS: 00000246
    RAX: 0000000000000000  RBX: 0000564c12d30230  RCX: 00007fb09ace8bb5
    RDX: 00007fb09b41ed08  RSI: 00007fb09b4179d0  RDI: 0000000000000003
    RBP: 00007fb09b4179d0   R8: 00007fb09b3f6000   R9: 0000000000000005
    R10: 00007fb09b3dc3a4  R11: 0000000000000246  R12: 0000000000000003
    R13: 0000000000000000  R14: 00007fb09b072650  R15: 00007ffd615881a0
    ORIG_RAX: 0000000000000003  CS: 0033  SS: 002b


crash> print _cifsFileInfo_put
$8 = {void (struct cifsFileInfo *, bool)} 0xffffffffc052d880 <_cifsFileInfo_put>
crash> dis -r ffffffffc052dd3f | tail
0xffffffffc052dd20 <cifs_close>:        data32 data32 data32 xchg %ax,%ax [FTRACE NOP]
0xffffffffc052dd25 <cifs_close+0x5>:    mov    0xc8(%rsi),%rdi
0xffffffffc052dd2c <cifs_close+0xc>:    test   %rdi,%rdi
0xffffffffc052dd2f <cifs_close+0xf>:    je     0xffffffffc052dd4e <cifs_close+0x2e>
0xffffffffc052dd31 <cifs_close+0x11>:   push   %rbx
0xffffffffc052dd32 <cifs_close+0x12>:   mov    %rsi,%rbx
0xffffffffc052dd35 <cifs_close+0x15>:   mov    $0x1,%esi
0xffffffffc052dd3a <cifs_close+0x1a>:   callq  0xffffffffc052d880 <_cifsFileInfo_put>
0xffffffffc052dd3f <cifs_close+0x1f>:   xor    %eax,%eax
crash> dis _cifsFileInfo_put | head
0xffffffffc052d880 <_cifsFileInfo_put>: data32 data32 data32 xchg %ax,%ax [FTRACE NOP]
0xffffffffc052d885 <_cifsFileInfo_put+0x5>:     push   %rbp
0xffffffffc052d886 <_cifsFileInfo_put+0x6>:     mov    %rsp,%rbp
0xffffffffc052d889 <_cifsFileInfo_put+0x9>:     push   %r15
0xffffffffc052d88b <_cifsFileInfo_put+0xb>:     push   %r14
0xffffffffc052d88d <_cifsFileInfo_put+0xd>:     push   %r13
0xffffffffc052d88f <_cifsFileInfo_put+0xf>:     push   %r12
0xffffffffc052d891 <_cifsFileInfo_put+0x11>:    push   %rbx
0xffffffffc052d892 <_cifsFileInfo_put+0x12>:    mov    %rdi,%rbx
0xffffffffc052d895 <_cifsFileInfo_put+0x15>:    lea    0xa4(%rbx),%r15
crash> bt -f | grep cifs_close
 #5 [ffffbd2d80fbfe98] cifs_close at ffffffffc052dd3f [cifs]
crash> px (0xffffbd2d80fbfe98 - 6*8)
$9 = 0xffffbd2d80fbfe68
crash> rd 0xffffbd2d80fbfe68
ffffbd2d80fbfe68:  ffff9862770ebf00                    ...wb...
crash> px (0xffff9862770ebf00 + 0xc8)
$10 = 0xffff9862770ebfc8
crash> rd 0xffff9862770ebfc8
ffff9862770ebfc8:  ffff98627ae64e00                    .N.zb...
crash> p (struct cifsFileInfo *)0xffff98627ae64e00
$11 = (struct cifsFileInfo *) 0xffff98627ae64e00
crash> kmem 0xffff98627ae64e00
CACHE             OBJSIZE  ALLOCATED     TOTAL  SLABS  SSIZE  NAME
ffff986247c02c00      512       1355      1744    109     8k  kmalloc-512
  SLAB              MEMORY            NODE  TOTAL  ALLOCATED  FREE
  ffffdefb44eb9900  ffff98627ae64000     0     16         14     2
  FREE / [ALLOCATED]
  [ffff98627ae64e00]

      PAGE       PHYSICAL      MAPPING       INDEX CNT FLAGS
ffffdefb44eb9900 13ae64000 ffff986247c02c00 ffff98627ae64400  1 17ffffc0008100 slab,head
crash> struct -o cifsInodeInfo.vfs_inode
struct cifsInodeInfo {
   [0xa0] struct inode vfs_inode;
}
crash> p $11->dentry->d_inode
$12 = (struct inode *) 0xffff9862659326e0
crash> px (0xffff9862659326e0 - 0xa0)
$13 = 0xffff986265932640
crash> p (struct cifsInodeInfo *)0xffff986265932640
$14 = (struct cifsInodeInfo *) 0xffff986265932640
crash> p $14->lock_sem
$15 = {
  count = {
    counter = 0xffffffff00000003
  },
  wait_list = {
    next = 0xffffbd2d80fbfd40,
    prev = 0xffffbd2d80f37a90
  },
  wait_lock = {
    raw_lock = {
      { 
        val = {
          counter = 0x0
        },
        { 
          locked = 0x0,
          pending = 0x0
        },
        { 
          locked_pending = 0x0,
          tail = 0x0
        }
      }
    }
  },
  osq = {
    tail = {
      counter = 0x0
    }
  },
  owner = 0xffff9862640b2f83
}
crash> p & $14->lock_sem
$16 = (struct rw_semaphore *) 0xffff986265932658
crash>

Comment 8 Dave Wysochanski 2019-10-21 15:25:09 UTC

 I can reproduce this trivially on the very latest upstream 5.4.0-rc4 (just released yesterday) and reproducer does not need a port block / unblock.

On client:

mount -vvvv -t cifs -osec=ntlmssp,hard,vers=3.1.1,user=shares //192.168.122.44/example /mnt/example
cd /mnt/example
for i in `seq 1 20`; do ./python3-openloop.py & done

On server (restart smb in a loop):
for i in $(seq 1 100); do for j in $(seq 1 50); do echo "$(date): iteration i=$i j=$j"; echo "$(date): restarting" ; systemctl restart smb.service ; sleep 5 ; done; sleep 200; done | tee /var/tmp/smb_restart_log.out


After a few minutes, a few of the processes exit, and others are blocked indefinitely, even if you stop the server disruption.  The share is fine, it is not hung.

Comment 9 Dave Wysochanski 2019-10-21 15:57:49 UTC

Ok I think I see what is wrong here.

crash> ps -m | grep UN
[0 01:54:10.166] [UN]  PID: 13271  TASK: ffff93b8a7349e40  CPU: 2   COMMAND: "python3-openloo"
[0 01:54:10.167] [UN]  PID: 13273  TASK: ffff93b8b3310000  CPU: 2   COMMAND: "python3-openloo"
[0 01:54:10.169] [UN]  PID: 13269  TASK: ffff93b8a734dac0  CPU: 0   COMMAND: "python3-openloo"
[0 01:54:10.208] [UN]  PID: 13272  TASK: ffff93b8a7348000  CPU: 7   COMMAND: "python3-openloo"
[0 01:54:10.216] [UN]  PID: 13265  TASK: ffff93b8a7358000  CPU: 6   COMMAND: "python3-openloo"
[0 01:54:10.172] [UN]  PID: 13263  TASK: ffff93b8b3313c80  CPU: 2   COMMAND: "python3-openloo"
[0 01:54:10.229] [UN]  PID: 13267  TASK: ffff93b8a7359e40  CPU: 5   COMMAND: "python3-openloo"
[0 01:54:10.234] [UN]  PID: 13277  TASK: ffff93b8a7dddac0  CPU: 3   COMMAND: "python3-openloo"
[0 01:54:10.235] [UN]  PID: 13270  TASK: ffff93b8a734bc80  CPU: 1   COMMAND: "python3-openloo"
[0 01:54:10.244] [UN]  PID: 13276  TASK: ffff93b8a7dd8000  CPU: 6   COMMAND: "python3-openloo"
[0 01:54:10.260] [UN]  PID: 13264  TASK: ffff93b8b3315ac0  CPU: 6   COMMAND: "python3-openloo"
[0 01:54:10.257] [UN]  PID: 13274  TASK: ffff93b8a7ddbc80  CPU: 1   COMMAND: "python3-openloo"
[0 01:54:31.262] [UN]  PID: 13279  TASK: ffff93b8a7d90000  CPU: 1   COMMAND: "python3-openloo" <--- block same instant
[0 01:54:31.265] [UN]  PID: 13275  TASK: ffff93b8a7dd9e40  CPU: 4   COMMAND: "python3-openloo" <--- block same instant
crash> bt 13279
PID: 13279  TASK: ffff93b8a7d90000  CPU: 1   COMMAND: "python3-openloo"
 #0 [ffffaae1c0a77c20] __schedule at ffffffffa19d4239
 #1 [ffffaae1c0a77cb0] schedule at ffffffffa19d46b9
 #2 [ffffaae1c0a77cc8] rwsem_down_write_slowpath at ffffffffa1131ada <------------- T+1: pid 13279 down_write(... lock_sem); blocks due to pid 13275
 #3 [ffffaae1c0a77d98] _cifsFileInfo_put at ffffffffc0759818 [cifs]
 #4 [ffffaae1c0a77e78] cifs_close at ffffffffc0759b4f [cifs]
 #5 [ffffaae1c0a77e88] __fput at ffffffffa12f6e51
 #6 [ffffaae1c0a77ed0] task_work_run at ffffffffa10fc827
 #7 [ffffaae1c0a77f08] exit_to_usermode_loop at ffffffffa1003f83
 #8 [ffffaae1c0a77f38] do_syscall_64 at ffffffffa10043c2
 #9 [ffffaae1c0a77f50] entry_SYSCALL_64_after_hwframe at ffffffffa1a0008c
    RIP: 00007fc6caca1778  RSP: 00007ffed0c43de8  RFLAGS: 00000246
    RAX: 0000000000000000  RBX: 00007fc6bd5a5f30  RCX: 00007fc6caca1778
    RDX: 0000000000000000  RSI: 0000000000000000  RDI: 0000000000000003
    RBP: 0000558ebb9ca0d0   R8: 00007fc6cab941a8   R9: 0000000000000000
    R10: 0000558ebb9ca0d0  R11: 0000000000000246  R12: 0000000000000000
    R13: 0000000000000000  R14: 00007fc6cab4df0c  R15: 00007ffed0c43f10
    ORIG_RAX: 0000000000000003  CS: 0033  SS: 002b
crash> bt 13275
PID: 13275  TASK: ffff93b8a7dd9e40  CPU: 4   COMMAND: "python3-openloo"
 #0 [ffffaae1c0a57a00] __schedule at ffffffffa19d4239
 #1 [ffffaae1c0a57a90] schedule at ffffffffa19d46b9
 #2 [ffffaae1c0a57aa8] rwsem_down_read_slowpath at ffffffffa19d72b4
 #3 [ffffaae1c0a57b60] cifs_reopen_file at ffffffffc0755352 [cifs]    <------------- T+2: pid 13275 down_read(... lock_sem); blocks due to pid 13279
 #4 [ffffaae1c0a57c08] cifs_readpage_worker at ffffffffc07575f0 [cifs]
 #5 [ffffaae1c0a57cd0] cifs_readpage at ffffffffc0758096 [cifs]
 #6 [ffffaae1c0a57d08] generic_file_read_iter at ffffffffa123acd2
 #7 [ffffaae1c0a57e10] cifs_strict_readv at ffffffffc07606a5 [cifs]   <------------- T+0: pid 13275 down_read(... lock_sem); does not block
 #8 [ffffaae1c0a57e40] new_sync_read at ffffffffa12f336a
 #9 [ffffaae1c0a57ec8] vfs_read at ffffffffa12f5fad
#10 [ffffaae1c0a57f00] ksys_read at ffffffffa12f62df
#11 [ffffaae1c0a57f38] do_syscall_64 at ffffffffa10042bb
#12 [ffffaae1c0a57f50] entry_SYSCALL_64_after_hwframe at ffffffffa1a0008c
    RIP: 00007f6ed0b7c055  RSP: 00007ffeea637e68  RFLAGS: 00000246
    RAX: ffffffffffffffda  RBX: 00007f6ed05cd600  RCX: 00007f6ed0b7c055
    RDX: 000000000000001e  RSI: 00007f6ec3404c10  RDI: 0000000000000003
    RBP: 000000000000001e   R8: 00007f6ed0a6f1a8   R9: 0000000000000000
    R10: 00007f6ed090faf0  R11: 0000000000000246  R12: 00007f6ec3480f40
    R13: 0000000000000003  R14: 00007f6ec3404c10  R15: 000055c449ea60d0
    ORIG_RAX: 0000000000000000  CS: 0033  SS: 002b


This below patch looks wrong and lockdep was actually warning of a possible issue, maybe like this?  So how to fix this safely...


commit 560d388950ceda5e7c7cdef7f3d9a8ff297bbf9d
Author: Rabin Vincent <rabinv>
Date:   Wed May 3 17:17:21 2017 +0200

    CIFS: silence lockdep splat in cifs_relock_file()
    
    cifs_relock_file() can perform a down_write() on the inode's lock_sem even
    though it was already performed in cifs_strict_readv().  Lockdep complains
    about this.  AFAICS, there is no problem here, and lockdep just needs to be
    told that this nesting is OK.
    
     =============================================
     [ INFO: possible recursive locking detected ]
     4.11.0+ #20 Not tainted
     ---------------------------------------------
     cat/701 is trying to acquire lock:
      (&cifsi->lock_sem){++++.+}, at: cifs_reopen_file+0x7a7/0xc00
    
     but task is already holding lock:
      (&cifsi->lock_sem){++++.+}, at: cifs_strict_readv+0x177/0x310
    
     other info that might help us debug this:
      Possible unsafe locking scenario:
    
            CPU0
            ----
       lock(&cifsi->lock_sem);
       lock(&cifsi->lock_sem);
    
      *** DEADLOCK ***
    
      May be due to missing lock nesting notation
    
     1 lock held by cat/701:
      #0:  (&cifsi->lock_sem){++++.+}, at: cifs_strict_readv+0x177/0x310
    
     stack backtrace:
     CPU: 0 PID: 701 Comm: cat Not tainted 4.11.0+ #20
     Call Trace:
      dump_stack+0x85/0xc2
      __lock_acquire+0x17dd/0x2260
      ? trace_hardirqs_on_thunk+0x1a/0x1c
      ? preempt_schedule_irq+0x6b/0x80
      lock_acquire+0xcc/0x260
      ? lock_acquire+0xcc/0x260
      ? cifs_reopen_file+0x7a7/0xc00
      down_read+0x2d/0x70
      ? cifs_reopen_file+0x7a7/0xc00
      cifs_reopen_file+0x7a7/0xc00
      ? printk+0x43/0x4b
      cifs_readpage_worker+0x327/0x8a0
      cifs_readpage+0x8c/0x2a0
      generic_file_read_iter+0x692/0xd00
      cifs_strict_readv+0x29f/0x310
      generic_file_splice_read+0x11c/0x1c0
      do_splice_to+0xa5/0xc0
      splice_direct_to_actor+0xfa/0x350
      ? generic_pipe_buf_nosteal+0x10/0x10
      do_splice_direct+0xb5/0xe0
      do_sendfile+0x278/0x3a0
      SyS_sendfile64+0xc4/0xe0
      entry_SYSCALL_64_fastpath+0x1f/0xbe
    
    Signed-off-by: Rabin Vincent <rabinv>
    Acked-by: Pavel Shilovsky <pshilov>
    Signed-off-by: Steve French <smfrench>

Comment 10 Dave Wysochanski 2019-10-21 16:22:30 UTC

Created attachment 1627733 [details]
debug patch on top of 5.4-rc4 that adds simple cifs_dbg based tracing to lock_sem

Comment 11 Dave Wysochanski 2019-10-21 16:30:31 UTC

Actually according to my tracing, pid 13275 actually gets stuck at up_read, not the second down_read:

[  233.507515] CIFS VFS: file=fs/cifs/file.c line=3926 pid=13275 cifs_sem_op op=up_read sem=ffff93b8a7424bd8
[  233.523618] CIFS VFS: file=fs/cifs/file.c line=480 pid=13279 cifs_sem_op op=up_write sem=ffff93b8a7424bd8
[  233.524688] CIFS VFS: file=fs/cifs/file.c line=471 pid=13275 cifs_sem_op op=down_write sem=ffff93b8a7424bd8
[  233.528916] CIFS VFS: file=fs/cifs/file.c line=311 pid=13279 cifs_sem_op op=down_write sem=ffff93b8a7424bd8
[  233.531757] CIFS VFS: file=fs/cifs/file.c line=480 pid=13275 cifs_sem_op op=up_write sem=ffff93b8a7424bd8
[  233.539810] CIFS VFS: file=fs/cifs/file.c line=314 pid=13279 cifs_sem_op op=up_write sem=ffff93b8a7424bd8
[  233.541195] CIFS VFS: file=fs/cifs/file.c line=311 pid=13275 cifs_sem_op op=down_write sem=ffff93b8a7424bd8
[  233.543884] CIFS VFS: file=fs/cifs/file.c line=3920 pid=13279 cifs_sem_op op=down_read sem=ffff93b8a7424bd8
[  233.547882] CIFS VFS: file=fs/cifs/file.c line=314 pid=13275 cifs_sem_op op=up_write sem=ffff93b8a7424bd8
[  233.556035] CIFS VFS: file=fs/cifs/file.c line=3920 pid=13275 cifs_sem_op op=down_read sem=ffff93b8a7424bd8
[  233.556723] CIFS VFS: file=fs/cifs/file.c line=3926 pid=13279 cifs_sem_op op=up_read sem=ffff93b8a7424bd8
[  233.560111] CIFS VFS: file=fs/cifs/file.c line=3926 pid=13275 cifs_sem_op op=up_read sem=ffff93b8a7424bd8
[  233.564104] CIFS VFS: file=fs/cifs/file.c line=3920 pid=13279 cifs_sem_op op=down_read sem=ffff93b8a7424bd8
[  233.568114] CIFS VFS: file=fs/cifs/file.c line=3920 pid=13275 cifs_sem_op op=down_read sem=ffff93b8a7424bd8
[  233.572140] CIFS VFS: file=fs/cifs/file.c line=3926 pid=13279 cifs_sem_op op=up_read sem=ffff93b8a7424bd8
[  233.576184] CIFS VFS: file=fs/cifs/file.c line=3926 pid=13275 cifs_sem_op op=up_read sem=ffff93b8a7424bd8
[  233.576899] CIFS VFS: file=fs/cifs/file.c line=471 pid=13275 cifs_sem_op op=down_write sem=ffff93b8a7424bd8
[  233.580797] CIFS VFS: file=fs/cifs/file.c line=471 pid=13279 cifs_sem_op op=down_write sem=ffff93b8a7424bd8
[  233.584178] CIFS VFS: file=fs/cifs/file.c line=480 pid=13275 cifs_sem_op op=up_write sem=ffff93b8a7424bd8
[  233.585462] CIFS VFS: file=fs/cifs/file.c line=311 pid=13275 cifs_sem_op op=down_write sem=ffff93b8a7424bd8
[  233.588248] CIFS VFS: file=fs/cifs/file.c line=480 pid=13279 cifs_sem_op op=up_write sem=ffff93b8a7424bd8
[  233.589462] CIFS VFS: file=fs/cifs/file.c line=311 pid=13279 cifs_sem_op op=down_write sem=ffff93b8a7424bd8
[  233.592333] CIFS VFS: file=fs/cifs/file.c line=314 pid=13275 cifs_sem_op op=up_write sem=ffff93b8a7424bd8
[  233.612324] CIFS VFS: file=fs/cifs/file.c line=314 pid=13279 cifs_sem_op op=up_write sem=ffff93b8a7424bd8
[  233.612510] CIFS VFS: file=fs/cifs/file.c line=3920 pid=13275 cifs_sem_op op=down_read sem=ffff93b8a7424bd8
[  233.616487] CIFS VFS: file=fs/cifs/file.c line=3920 pid=13279 cifs_sem_op op=down_read sem=ffff93b8a7424bd8  T0: https://bugzilla.redhat.com/show_bug.cgi?id=1760835#c9
[  254.389458] CIFS VFS: Send error in read = -9
[  254.391943] CIFS VFS: file=fs/cifs/file.c line=3926 pid=13279 cifs_sem_op op=up_read sem=ffff93b8a7424bd8  
[  254.397453] CIFS VFS: file=fs/cifs/file.c line=471 pid=13279 cifs_sem_op op=down_write sem=ffff93b8a7424bd8  T1: https://bugzilla.redhat.com/show_bug.cgi?id=1760835#c9
[  254.399798] CIFS VFS: file=fs/cifs/file.c line=630 pid=13275 cifs_sem_op op=down_read sem=ffff93b8a7424bd8   T2: https://bugzilla.redhat.com/show_bug.cgi?id=1760835#c9

Comment 12 Dave Wysochanski 2019-10-21 16:32:12 UTC

(In reply to Dave Wysochanski from comment #11)
> Actually according to my tracing, pid 13275 actually gets stuck at up_read,
> not the second down_read:
> 

That's incorrect - problem is as stated in comment #9 and trace shows that.

[  233.616487] CIFS VFS: file=fs/cifs/file.c line=3920 pid=13279 cifs_sem_op op=down_read sem=ffff93b8a7424bd8  T0: https://bugzilla.redhat.com/show_bug.cgi?id=1760835#c9
[  254.389458] CIFS VFS: Send error in read = -9
[  254.391943] CIFS VFS: file=fs/cifs/file.c line=3926 pid=13279 cifs_sem_op op=up_read sem=ffff93b8a7424bd8 <-- ignore
[  254.397453] CIFS VFS: file=fs/cifs/file.c line=471 pid=13279 cifs_sem_op op=down_write sem=ffff93b8a7424bd8  T1: https://bugzilla.redhat.com/show_bug.cgi?id=1760835#c9
[  254.399798] CIFS VFS: file=fs/cifs/file.c line=630 pid=13275 cifs_sem_op op=down_read sem=ffff93b8a7424bd8   T2: https://bugzilla.redhat.com/show_bug.cgi?id=1760835#c9

Comment 13 Dave Wysochanski 2019-10-21 16:40:45 UTC

Opening this up so I can post to linux-cifs

Comment 14 Dave Wysochanski 2019-10-24 02:13:38 UTC

Patch has been posted upstream based on initial approach / feedback and Ronnie's suggested approach.

Comment 15 Dave Wysochanski 2019-10-24 12:20:29 UTC

Created attachment 1628852 [details]
patch posted on linux-cifs to fix this bug - ronnie suggested approach

Comment 16 Dave Wysochanski 2019-10-28 08:23:19 UTC


*** This bug has been marked as a duplicate of bug 1765979 ***

Comment 17 Dave Wysochanski 2019-11-04 15:42:39 UTC

Fixed by
d46b0da7a33d cifs: Fix cifsInodeInfo lock_sem deadlock when reconnect occurs

Note You need to log in before you can comment on or make changes to this bug.