Hi Frank,
I have just posted 3 patches to the list to address remaining handle leaks:
CIFS: Close open handle after interrupted close (2nd version of my
original patch to handle interrupted closes)
CIFS: Fix NULL pointer dereference in mid callback (not a handle leak
fix but the kernel kept crashing on my system during intensive testing
for handle leaks)
CIFS: Do not miss cancelled OPEN responses (fix to handle some
unmatched opens that are not processed right now due to races)
Could you please test them in your environment? I ran a script similar
to what you use for repro (just more iterations) and Samba didn't show
leaked handles afterwards.
--
Best regards,
Pavel Shilovsky
вс, 17 нояб. 2019 г. в 08:29, Frank Sorenson <sorenson@xxxxxxxxxx>:
>
> On 11/13/19 7:39 PM, Ronnie Sahlberg wrote:
> > ----- Original Message -----
> >> From: "Frank Sorenson" <sorenson@xxxxxxxxxx>
> >> To: "Ronnie Sahlberg" <lsahlber@xxxxxxxxxx>, "Pavel Shilovsky" <piastryyy@xxxxxxxxx>
> >> Cc: "linux-cifs" <linux-cifs@xxxxxxxxxxxxxxx>
> >> Sent: Thursday, 14 November, 2019 8:15:46 AM
> >> Subject: Re: A process killed while opening a file can result in leaked open handle on the server
> >>
> >> On 11/13/19 12:49 AM, Ronnie Sahlberg wrote:
> >>> Steve, Pavel
> >>>
> >>> This patch goes ontop of Pavels patch.
> >>> Maybe it should be merged with Pavels patch since his patch changes from
> >>> "we only send a close() on an interrupted open()"
> >>> to now "we send a close() on either interrupted open() or interrupted
> >>> close()" so both comments as well as log messages are updates.
> >>>
> >>> Additionally it adds logging of the MID that failed in the case of an
> >>> interrupted Open() so that it is easy to find it in wireshark
> >>> and check whether that smb2 file handle was indeed handles by a SMB_Close()
> >>> or not.
> >>>
> >>>
> >>> From testing it appears Pavels patch works. When the close() is interrupted
> >>> we don't leak handles as far as I can tell.
> >>> We do have a leak in the Open() case though and it seems that eventhough we
> >>> set things up and flags the MID to be cancelled we actually never end up
> >>> calling smb2_cancelled_close_fid() and thus we never send a SMB2_Close().
> >>> I haven't found the root cause yet but I suspect we mess up mid flags or
> >>> state somewhere.
> >>>
> >>>
> >>> It did work in the past though when Sachin provided the initial
> >>> implementation so we have regressed I think.
> >>> I have added a new test 'cifs/102' to the buildbot that checks for this
> >>> but have not integrated into the cifs-testing run yet since we still fail
> >>> this test.
> >>> At least we will not have further regressions once we fix this and enable
> >>> the test in the future.
> >>>
> >>> ronnie s
> >>
> >> The patches do indeed improve it significantly.
> >>
> >> I'm still seeing some leak as well, and I'm removing ratelimiting so
> >> that I can see what the added debugging is trying to tell us. I'll
> >> report if I find more details.
>
> > We are making progress.
>
> Agreed. We're definitely making progress.
>
> > Can you test this patch if it improves even more for you?
> > It fixes most but not all the leaks I see for interrupted open():
> >
> > I will post this to the list too as a separate mail/patch.
>
>
> Sorry to be slow on the testing.
>
>
> I might be seeing some small improvement with this one, but I'm still seeing some mismatches:
>
> # for i in {1..100} ; do cat /mnt/vm3/foo.$i >/dev/null 2>&1 & sleep 0.0001 ; kill -9 $! ; done
> ...
>
> This ended up with 2 open on the server side:
>
> 21842 501 DENY_NONE 0x120089 RDONLY LEASE(RWH) /home/user1 foo.32 Sun Nov 17 09:13:38 2019
> 21842 501 DENY_NONE 0x120089 RDONLY LEASE(RWH) /home/user1 foo.48 Sun Nov 17 09:13:38 2019
>
>
> the packet capture shows the same mismatch pattern for these two:
>
> 102 Create Request File: foo.32;GetInfo Request FILE_INFO/SMB2_FILE_ALL_INFO;Close Request
> 103 Create Response File: foo.32;GetInfo Response;Close Response
> 104 Create Request File: foo.32
> 105 Create Response File: foo.32
>
>
> 148 Create Request File: foo.48;GetInfo Request FILE_INFO/SMB2_FILE_ALL_INFO;Close Request
> 149 Create Response File: foo.48;GetInfo Response;Close Response
> 150 Create Request File: foo.48
> 151 Create Response File: foo.48
>
> with no close for those two.
>
>
> the messages are also similar, and show transmitting the second open request and cancelling the wait immediately afterward:
> [9006] cifs:cifs_lookup:669: fs/cifs/dir.c: CIFS VFS: in cifs_lookup as Xid: 1091 with uid: 0
> [9006] cifs:cifs_lookup:672: fs/cifs/dir.c: parent inode = 0x000000008f9424fe name is: foo.32 and dentry = 0x0000000053e436bf
> [9006] cifs:build_path_from_dentry_optional_prefix:143: fs/cifs/dir.c: name: \foo.32
> [9006] cifs:cifs_lookup:704: fs/cifs/dir.c: NULL inode in lookup
> [9006] cifs:cifs_lookup:707: fs/cifs/dir.c: Full path: \foo.32 inode = 0x000000004667ea0b
> [9006] cifs:cifs_get_inode_info:753: fs/cifs/inode.c: Getting info on \foo.32
> [9006] cifs:__smb_send_rqst:368: fs/cifs/transport.c: Sending smb: smb_len=356
> [9006] cifs:cifs_sync_mid_result:859: fs/cifs/transport.c: cifs_sync_mid_result: cmd=5 mid=113 state=4
> [9006] cifs:cifs_sync_mid_result:859: fs/cifs/transport.c: cifs_sync_mid_result: cmd=16 mid=114 state=4
> [9006] cifs:cifs_sync_mid_result:859: fs/cifs/transport.c: cifs_sync_mid_result: cmd=6 mid=115 state=4
> [9006] cifs:cifs_small_buf_release:222: fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
> [9006] cifs:cifs_small_buf_release:222: fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
> [9006] cifs:cifs_small_buf_release:222: fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
> [9006] cifs:cifs_iget:1030: fs/cifs/inode.c: looking for uniqueid=5934909
> [9006] cifs:cifs_revalidate_cache:100: fs/cifs/inode.c: cifs_revalidate_cache: revalidating inode 5934909
> [9006] cifs:cifs_revalidate_cache:124: fs/cifs/inode.c: cifs_revalidate_cache: invalidating inode 5934909 mapping
> [9006] cifs:cifs_lookup:734: fs/cifs/dir.c: CIFS VFS: leaving cifs_lookup (xid = 1091) rc = 0
> [9006] cifs:cifs_open:512: fs/cifs/file.c: CIFS VFS: in cifs_open as Xid: 1092 with uid: 0
> [9006] cifs:build_path_from_dentry_optional_prefix:143: fs/cifs/dir.c: name: \foo.32
> [9006] cifs:cifs_open:530: fs/cifs/file.c: inode = 0x000000001a16a2ae file flags are 0x8000 for \foo.32
> [9006] cifs:SMB2_open:2581: fs/cifs/smb2pdu.c: create/open
> [9006] cifs:__smb_send_rqst:368: fs/cifs/transport.c: Sending smb: smb_len=284
> CIFS VFS: \\vm3 Cancelling wait for mid 116 cmd: 5
> [9006] cifs:cifs_open:618: fs/cifs/file.c: CIFS VFS: leaving cifs_open (xid = 1092) rc = -512
>
>
>
> [9039] cifs:cifs_lookup:669: fs/cifs/dir.c: CIFS VFS: in cifs_lookup as Xid: 1109 with uid: 0
> [9039] cifs:cifs_lookup:672: fs/cifs/dir.c: parent inode = 0x000000008f9424fe name is: foo.48 and dentry = 0x0000000040aea0d9
> [9039] cifs:build_path_from_dentry_optional_prefix:143: fs/cifs/dir.c: name: \foo.48
> [9039] cifs:cifs_lookup:704: fs/cifs/dir.c: NULL inode in lookup
> [9039] cifs:cifs_lookup:707: fs/cifs/dir.c: Full path: \foo.48 inode = 0x000000004667ea0b
> [9039] cifs:cifs_get_inode_info:753: fs/cifs/inode.c: Getting info on \foo.48
> [9039] cifs:__smb_send_rqst:368: fs/cifs/transport.c: Sending smb: smb_len=356
> [9039] cifs:cifs_sync_mid_result:859: fs/cifs/transport.c: cifs_sync_mid_result: cmd=5 mid=158 state=4
> [9039] cifs:cifs_sync_mid_result:859: fs/cifs/transport.c: cifs_sync_mid_result: cmd=16 mid=159 state=4
> [9039] cifs:cifs_sync_mid_result:859: fs/cifs/transport.c: cifs_sync_mid_result: cmd=6 mid=160 state=4
> [9039] cifs:cifs_small_buf_release:222: fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
> [9039] cifs:cifs_small_buf_release:222: fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
> [9039] cifs:cifs_small_buf_release:222: fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
> [9039] cifs:cifs_iget:1030: fs/cifs/inode.c: looking for uniqueid=21857488
> [9039] cifs:cifs_revalidate_cache:100: fs/cifs/inode.c: cifs_revalidate_cache: revalidating inode 21857488
> [9039] cifs:cifs_revalidate_cache:124: fs/cifs/inode.c: cifs_revalidate_cache: invalidating inode 21857488 mapping
> [9039] cifs:cifs_lookup:734: fs/cifs/dir.c: CIFS VFS: leaving cifs_lookup (xid = 1109) rc = 0
> [9039] cifs:cifs_open:512: fs/cifs/file.c: CIFS VFS: in cifs_open as Xid: 1110 with uid: 0
> [9039] cifs:build_path_from_dentry_optional_prefix:143: fs/cifs/dir.c: name: \foo.48
> [9039] cifs:cifs_open:530: fs/cifs/file.c: inode = 0x00000000001a4f79 file flags are 0x8000 for \foo.48
> [9039] cifs:SMB2_open:2581: fs/cifs/smb2pdu.c: create/open
> [9039] cifs:__smb_send_rqst:368: fs/cifs/transport.c: Sending smb: smb_len=284
> CIFS VFS: \\vm3 Cancelling wait for mid 161 cmd: 5
> [9039] cifs:cifs_open:618: fs/cifs/file.c: CIFS VFS: leaving cifs_open (xid = 1110) rc = -512
>
>
> Frank
>
