Liberal file locking in 5.11.3

Advertisement

andrew_h
Joined:
Posts:
2

Liberal file locking in 5.11.3

I am writing an application that uses WinSCP's .NET client to get files via SFTP, then bundles them into .tar.gz files, then uploads them using an HTTP API to another server.

When a new Session object starts up, it seems to acquire locks on .tar.gz files in my upload directory. These files do not pertain to the Session's current download target, but they do contain data that was previously downloaded via another WinSCP SFTP Session object. As far as I can tell, this old Session was correctly Disposed. I'm verifying this with the following bit of debug logging:
// from WinSCPSessionFacade.cs 
        private readonly Session _session;

        public WinScpSessionFacade()
        {
            _guid = Guid.NewGuid();
            _logger.Info($"Creating session {_guid.ToString()} ");
            _session = new Session();


        }

        public void Dispose()
        {
            _session.Dispose();
            _logger.Info($"Disposed WinScpSession {_guid.ToString()}");
        }

These locks persist for as long as the new Session is downloading. The instant the Session is finished and Disposes, the lock is released. I see this in procmon as winscp.exe sends a CloseFile to that path.

Has anyone got any suggestions? :-) How does WinSCP decide what files to lock when a Session starts up?

Reply with quote

Advertisement

martin
Site Admin
martin avatar
Joined:
Posts:
28,658
Location:
Prague, Czechia

Re: Liberal file locking in 5.11.3

The Session nor WinSCP do not lock any random files.

If you still believe it does, please provide some evidence.

Reply with quote

andrew_h
Joined:
Posts:
2

Thanks very much Martin for your attention! :-)

If you have time, please let me know what you think of these logs.

Application log:

    2018-01-22 16:12:28.9363 [15][MyApp.SftpConnector.SftpSessionFactory.Create] INFO: Creating an SFTP session 
    2018-01-22 16:12:28.9363 [15][MyApp.SftpConnector.WinScpSessionFacade..ctor] INFO: Creating session 6796e145-81d0-4eae-96f4-80841e250c16  
    2018-01-22 16:12:28.9473 [15][MyApp.SftpConnector.SftpSession..ctor] INFO: SftpSession construction complete 
    2018-01-22 16:12:28.9773 [15][MyApp.SftpConnector.WinScpSessionFacade.Open] INFO: Opening WinScpSession 6796e145-81d0-4eae-96f4-80841e250c16 
    2018-01-22 16:12:32.2539 [16][ExporterCommon.Retries.CancellableRetry.Log] WARN: System.IO.IOException (0x80070020): (32) The process cannot access the file because it is being used by another process: [\\?\D:\myApp\upload\im_1516664680_20d80c05a51494c892_2-2_sup.tar.gz]. 
    2018-01-22 16:12:32.2539 [16][ExporterCommon.Retries.CancellableRetry.Log] WARN: Retrying in 60000 ms (attempt 1 of 5). 
    2018-01-22 16:12:44.3714 [15][MyApp.SftpConnector.WinScpSessionFacade.Open] INFO: Opened WinScpSession 6796e145-81d0-4eae-96f4-80841e250c16 
    2018-01-22 16:12:44.3714 [15][MyApp.SftpConnector.SftpSession.DownloadFiles] INFO: Downloading [1] Files. 
    2018-01-22 16:12:44.3714 [15][MyApp.SftpConnector.SftpSession.DownloadFiles] INFO: File [/opt/foo.txt] -> [D:\myApp\temp\im\im\20180106\11\1516384238458_UZG_TXT-2018-01-19T09-51-55@0-BF3C] downloading. 
    2018-01-22 16:13:26.8613 [15][MyApp.SftpConnector.SftpSession.DownloadFiles] INFO: File [/opt/foo.txt] -> [D:\myApp\temp\im\im\20180106\11\1516384238458_UZG_TXT-2018-01-19T09-51-55@0-BF3C downloaded. 
    2018-01-22 16:13:26.8613 [15][MyApp.SftpConnector.SftpSession.DownloadFiles] INFO: Files Downloaded [1]. 
    2018-01-22 16:13:28.1696 [15][MyApp.SftpConnector.WinScpSessionFacade.Dispose] INFO: Disposed WinScpSession 6796e145-81d0-4eae-96f4-80841e250c16

Handle.exe output:

    D:\myApp\upload>handle D:\myApp\upload\im_1516664680_20d80c05a51494c892_2-2_sup.tar.gz

    Nthandle v4.11 - Handle viewer
    Copyright (C) 1997-2017 Mark Russinovich
    Sysinternals - www.sysinternals.com

    WinSCP.exe         pid: 22492  type: File           898: D:\myApp\upload\im_1516664680_20d80c05a51494c892_2-2_sup.tar.gz


procmon output:

    4:12:29.1498595 PM  myapp.exe   16816   ReadFile    D:\myApp\upload\im_1516664680_20d80c05a51494c892_2-2_sup.tar.gz  SUCCESS Offset: 6,635,520, Length: 4,096
    4:12:29.1549040 PM  myapp.exe   16816   ReadFile    D:\myApp\upload\im_1516664680_20d80c05a51494c892_2-2_sup.tar.gz  SUCCESS Offset: 6,639,616, Length: 2,133
    4:12:29.1549373 PM  myapp.exe   16816   ReadFile    D:\myApp\upload\im_1516664680_20d80c05a51494c892_2-2_sup.tar.gz  END OF FILE Offset: 6,641,749, Length: 4,096
    4:12:29.1594655 PM  myapp.exe   16816   CreateFile  D:\myApp\upload\im_1516664680_20d80c05a51494c892_2-2_sup.tar.gz  SHARING VIOLATION   Desired Access: Generic Read/Write, Disposition: OpenIf, Options: Synchronous IO Non-Alert, Non-Directory File, Attributes: N, ShareMode: Read, AllocationSize: 0
    4:13:26.9279050 PM  winscp.exe  21020   CloseFile   D:\myApp\upload\im_1516664680_20d80c05a51494c892_2-2_sup.tar.gz  SUCCESS 
    4:13:32.2741555 PM  myapp.exe   16816   CreateFile  D:\myApp\upload\im_1516664680_20d80c05a51494c892_2-2_sup.tar.gz  SUCCESS Desired Access: Generic Read, Disposition: Open, Options: Synchronous IO Non-Alert, Non-Directory File, Attributes: N, ShareMode: Read, AllocationSize: n/a, OpenResult: Opened

The timeline to notice in these logfiles goes like this.

At 16:12:28 a new SFTP session starts. It immediately locks the file, D:\myApp\upload\im_1516664680_20d80c05a51494c892_2-2_sup.tar.gz, that was there from a previous run of my application.

The lock persists while the session downloads its current, unrelated file to D:\myApp\temp\im\im\20180106\11\1516384238458_UZG_TXT-2018-01-19T09-51-55@0-BF3C. At 4:12:29.1594655 PM my application tries to read the file and encounters a Sharing Violation as a result of this lock. This is logged in Procmon. We see it also in the myapp log three seconds later, at 2018-01-22 16:12:32.2539 (The three-second gap is probably the result of my taking that amount of time to hit Continue in my VS debugger)

At 4:13:26.9279050 WinSCP.exe sends a CloseFile to :\myApp\upload\im_1516664680_20d80c05a51494c892_2-2_sup.tar.gz.
At 16:13:28.1696, the Session is disposed and this gets logged in the application log.
Now my app can read this file for its upload.

It does this four seconds later, at 4:13:32 and this is logged in the procmon log.

Reply with quote

Guest

https://github.com/adrianmander/SessionFileLocking/blob/master/SessionFileLocking/Program.cs

I reproduced the problem with a very small code example!

Sample output:
Starting file IO
SFTP Session created
Ending file IO
Starting file IO
Couldn't open the file. Another executable (WinSCP, I'm looking at you) has locked it
(32) The process cannot access the file because it is being used by another process: [\\?\C:\Users\andrew.h\documents\visual studio 2017\Projects\SessionFileLocking\SessionFileLocking\bin\Debug\FileForFileIo_NotSFTP.txt]
Ending file IO

And WinSCP is definitely locking that file:
[code]
C:\Users\andrew.hartline>handle -p WinSCP.exe

Nthandle v4.11 - Handle viewer
Copyright (C) 1997-2017 Mark Russinovich
Sysinternals - www.sysinternals.com

------------------------------------------------------------------------------
WinSCP.exe pid: 9264 OFFICE\andrew.hartline
3C: File C:\Windows
7C: File C:\Users\andrew.hartline\Documents\Visual Studio 2017\Projects\SessionFileLocking\SessionFileLocking\bin\Debug
A4: File C:\Windows\WinSxS\x86_microsoft.windows.common-controls_6595b64144ccf1df_6.0.16299.192_none_5d760485a7e0eb41
B4: Section \Windows\Theme2392821440
C4: Section \Sessions\1\Windows\Theme3908030276
304: Section \BaseNamedObjects\__ComCatalogCache__
308: File C:\Windows\SysWOW64\en-US\user32.dll.mui
310: File C:\Windows\WinSxS\x86_microsoft.windows.common-controls_6595b64144ccf1df_6.0.16299.192_none_5d760485a7e0eb41
31C: Section \Sessions\1\BaseNamedObjects\windows_shell_global_counters
330: Section \Sessions\1\BaseNamedObjects\NLS_CodePage_437_3_2_0_0
348: Section \BaseNamedObjects\__ComCatalogCache__
34C: File C:\Windows\Registration\R00000000000d.clb
370: File C:\Windows\WinSxS\x86_microsoft.windows.c..-controls.resources_6595b64144ccf1df_6.0.16299.192_en-us_73814d6ad4871d2e
374: File C:\Windows\WinSxS\x86_microsoft.windows.c..-controls.resources_6595b64144ccf1df_6.0.16299.192_en-us_73814d6ad4871d2e\comctl32.dll.mui
388: Section \BaseNamedObjects\windows_shell_global_counters
3E0: File C:\Users\andrew.h\Documents\Visual Studio

vvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvv
2017\Projects\SessionFileLocking\SessionFileLocking\bin\Debug\FileForFileIo_NotSFTP.txt
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^


4EC: Section \Sessions\1\BaseNamedObjects\C:*ProgramData*Microsoft*Windows*Caches*cversions.2.ro
4F4: Section \Sessions\1\BaseNamedObjects\C:*ProgramData*Microsoft*Windows*Caches*{6AF0698E-D558-4F6E-9B3C-3716689AF493}.2.ver0x0000000000000002.db
4F8: Section \Sessions\1\BaseNamedObjects\C:*ProgramData*Microsoft*Windows*Caches*cversions.2.ro
4FC: Section \Sessions\1\BaseNamedObjects\C:*ProgramData*Microsoft*Windows*Caches*{DDF571F2-BE98-426D-8288-1A9A39C3FDA2}.2.ver0x0000000000000001.db
54C: Section \Sessions\1\BaseNamedObjects\WinSCPConsoleMapping_25648_12289376_826
550: File C:\Users\andrew.h\AppData\Local\Temp\wscp6430.02BF8098.tmp[code]



Weirdly, it appears to be the product of interaction between WinSCP and AlphaFS!
https://www.nuget.org/packages/AlphaFS/

Here is my packages.config:
<package id="AlphaFS" version="2.1.3" targetFramework="net461" />
<package id="WinSCP" version="5.11.3" targetFramework="net461" />
If I use the regular .NET File API, no problem.

Reply with quote

martin
Site Admin
martin avatar
Joined:
Posts:
28,658
Location:
Prague, Czechia

Thanks for all the details.

andrew_h wrote:

At 16:12:28 a new SFTP session starts. It immediately locks the file, D:\myApp\upload\im_1516664680_20d80c05a51494c892_2-2_sup.tar.gz, that was there from a previous run of my application.
What logs do show that?

https://github.com/adrianmander/SessionFileLocking/blob/master/SessionFileLocking/Program.cs

I reproduced the problem with a very small code example!
I'm not sure I'm following.
Your code does not reproduce the problem for me.

Starting file IO
SFTP Session created
SFTP Session is opened!
Got files
Ending file IO
Starting file IO
Ending file IO

And I do not get how a download to FileFromSftp.txt can prevent opening of FileForFileIo_NotSFTP.txt.

Reply with quote

Advertisement

You can post new topics in this forum