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
