Forum » .NET assembly / COM library »

Post a reply

Options
Add an Attachment

If you do not want to add an Attachment to your Post, please leave the Fields blank.

(maximum 10 MB; please compress large files; only common media, archive, text and programming file formats are allowed)

Options

Topic review

martin

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.
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.
andrew_h

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.
martin

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.
andrew_h

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?

Documentation

Support

Associations

Follow Us