Small File Upload Problem

Feb 4, 2013 at 4:11 PM
I am using the 1/4 release (file date) of the library and I am having an issue uploading files which are under 20k.

Could not properly upload file \APP03\ImportExport\NJ\180515\NJ_0615_UPL_130204_101618.exp to SFTP Server mft.amwater.com. Exception: Connection was lost
at Renci.SshNet.Sftp.SubsystemSession.WaitHandle(WaitHandle waitHandle, TimeSpan operationTimeout)
at Renci.SshNet.SftpClient.InternalUploadFile(Stream input, String path, SftpUploadAsyncResult asynchResult, Flags flags)
at Renci.SshNet.SftpClient.UploadFile(Stream input, String path, Boolean canOverride)
at RouteManager.General.SFTP.pushFileToFTP(String fullFileName)


Larger than 20k seem to work and I upload about a 150 files a day this way. I am doing a file.read and passing the stream to uploadFile.

Pushing the same file through FileZilla or other SFTP clients work fine.

What other steps can I take to diagnose the source of this problem?

Thanks for any suggesions
Rich
Coordinator
Feb 4, 2013 at 4:24 PM
Hi,

Can you download latest version of the source code that I have?
I recently discovered some bug there that I fixed when it comes to uploading huge files but may be it will help in your case as well.
Also, when you get an exception, can you use debug version so I could see what line cause this exception, this will help me to identify it.

Thanks,
Oleg
Feb 4, 2013 at 6:38 PM
The newest version of the code is hanging during the upload portion.
  using (Renci.SshNet.SftpClient sftp = new Renci.SshNet.SftpClient(host, uid, pwd))
        {
            using (Stream fin = File.OpenRead(fullFileName))
            {
                try
                {
                    sftp.ConnectionInfo.Timeout = new TimeSpan(0, 0, 30);


                    Logs.Info("Connecting:{0},{1},{2}", host,uid,pwd);
                    sftp.Connect();

                    Logs.Info("Connected, uploading file: {0}",fi.Name);
                    sftp.UploadFile(fin, hostPath + fi.Name);
                    Logs.Info("Uploaded {0} which was {1} bytes.", fi.Name, fi.Length);
                    Logs.Info("Transferred");
                    uploadSuccess = true;
                }
                catch (Exception e)
                {
                    Logs.Err("Could not properly upload file {1} to SFTP Server {0}. Exception: {2}\n{3}", host, fullFileName, e.Message,e.StackTrace);
                    return false;
                }
            }
        }
I see the message indicating Connected, uploading file.... but the process just hangs there. This is with a 19k file. With a 100k file the upload works perfectly.

Rich
Coordinator
Feb 4, 2013 at 6:46 PM
Hmm,
ok, I will look at it later tonight then.
I guess one small questions, does it happens with smaller files too? like 1K or 2K or only around 18K-19K ?

Thanks,
Oleg
Feb 4, 2013 at 6:51 PM
Just tried 2k and it worked just fine.

Rich
Coordinator
Feb 4, 2013 at 8:28 PM
Hmm,
Then it seems to be a specific size project,
Ok, I will test for that then and see what I can find.

Thanks,
Oleg
Coordinator
Feb 4, 2013 at 10:37 PM
Hi,

I just did a test with 18K, 19K and 20K and they all uploaded just fine here.

Can you may be provide me with a file that you trying to upload or its exact size in bytes so I could simulate the situation as close as possible?
Dont think you can attach files here in a forum so you can send file privately if needed.

Thanks,
Oleg
Feb 4, 2013 at 11:13 PM
I did some additional testing on my side as well, it appears that the issue does not occur with winsshd (our personal sftp) but does occur with our business partner's server which is Ipswitch MoveIT. Let me anonimize one of the files and I will PM it to you.

Rich
Feb 5, 2013 at 12:55 AM
Managed to get it to fail in debug mode. It is stuck on line 1499 in SFTPClient.cs.

Here is the debug message trace
SshNet.Logging Verbose: 1 : Initiating connect to 'XXX.XXX.XXXX:22'.
SshNet.Logging Verbose: 1 : Server version '2.0' on '9.99 sshlib: 7.0.0.0'.
SshNet.Logging Verbose: 1 : ReceiveMessage from server: 'KeyExchangeInitMessage': 'SSH_MSG_KEXINIT'.
'SFTPTest.vshost.exe' (Managed (v4.0.30319)): Loaded 'C:\Windows\Microsoft.Net\assembly\GAC_MSIL\System.Dynamic\v4.0_4.0.0.0__b03f5f7f11d50a3a\System.Dynamic.dll', Skipped loading symbols. Module is optimized and the debugger option 'Just My Code' is enabled.
'SFTPTest.vshost.exe' (Managed (v4.0.30319)): Loaded 'Anonymously Hosted DynamicMethods Assembly'
SshNet.Logging Verbose: 1 : SendMessage to server 'KeyExchangeInitMessage': 'SSH_MSG_KEXINIT'.
SshNet.Logging Verbose: 1 : SendMessage to server 'KeyExchangeDhGroupExchangeRequest': 'SSH_MSG_KEX_DH_GEX_REQUEST'.
SshNet.Logging Verbose: 1 : ReceiveMessage from server: 'KeyExchangeDhGroupExchangeGroup': 'SSH_MSG_KEX_DH_GEX_GROUP'.
SshNet.Logging Verbose: 1 : SendMessage to server 'KeyExchangeDhGroupExchangeInit': 'SSH_MSG_KEX_DH_GEX_INIT'.
SshNet.Logging Verbose: 1 : ReceiveMessage from server: 'KeyExchangeDhGroupExchangeReply': 'SSH_MSG_KEX_DH_GEX_REPLY'.
SshNet.Logging Verbose: 1 : SendMessage to server 'NewKeysMessage': 'SSH_MSG_NEWKEYS'.
SshNet.Logging Verbose: 1 : ReceiveMessage from server: 'NewKeysMessage': 'SSH_MSG_NEWKEYS'.
SshNet.Logging Verbose: 1 : SendMessage to server 'ServiceRequestMessage': 'SSH_MSG_SERVICE_REQUEST'.
SshNet.Logging Verbose: 1 : ReceiveMessage from server: 'ServiceAcceptMessage': 'SSH_MSG_SERVICE_ACCEPT'.
SshNet.Logging Verbose: 1 : SendMessage to server 'RequestMessageNone': 'SSH_MSG_USERAUTH_REQUEST'.
SshNet.Logging Verbose: 1 : ReceiveMessage from server: 'FailureMessage': 'SSH_MSG_USERAUTH_FAILURE'.
SshNet.Logging Verbose: 1 : SendMessage to server 'RequestMessagePassword': 'SSH_MSG_USERAUTH_REQUEST'.
SshNet.Logging Verbose: 1 : ReceiveMessage from server: 'SuccessMessage': 'SSH_MSG_USERAUTH_SUCCESS'.
SshNet.Logging Verbose: 1 : SendMessage to server 'ChannelOpenMessage': 'SSH_MSG_CHANNEL_OPEN : #0'.
SshNet.Logging Verbose: 1 : ReceiveMessage from server: 'ChannelOpenConfirmationMessage': 'SSH_MSG_CHANNEL_OPEN_CONFIRMATION : #0'.
SshNet.Logging Verbose: 1 : SendMessage to server 'ChannelRequestMessage': 'SSH_MSG_CHANNEL_REQUEST : #0'.
SshNet.Logging Verbose: 1 : ReceiveMessage from server: 'ChannelSuccessMessage': 'SSH_MSG_CHANNEL_SUCCESS : #0'.
SshNet.Logging Verbose: 1 : SendMessage to server 'ChannelDataMessage': 'SSH_MSG_CHANNEL_DATA : #0'.
SshNet.Logging Verbose: 1 : ReceiveMessage from server: 'ChannelDataMessage': 'SSH_MSG_CHANNEL_DATA : #0'.
SshNet.Logging Verbose: 1 : SendMessage to server 'ChannelDataMessage': 'SSH_MSG_CHANNEL_DATA : #0'.
SshNet.Logging Verbose: 1 : ReceiveMessage from server: 'ChannelDataMessage': 'SSH_MSG_CHANNEL_DATA : #0'.
Connected, uploading file: NJ_0615_UPL_130204_101620.expSshNet.Logging Verbose: 1 : SendMessage to server 'ChannelDataMessage': 'SSH_MSG_CHANNEL_DATA : #0'.
SshNet.Logging Verbose: 1 : ReceiveMessage from server: 'ChannelDataMessage': 'SSH_MSG_CHANNEL_DATA : #0'.
SshNet.Logging Verbose: 1 : SendMessage to server 'ChannelDataMessage': 'SSH_MSG_CHANNEL_DATA : #0'.
SshNet.Logging Verbose: 1 : ReceiveMessage from server: 'ChannelDataMessage': 'SSH_MSG_CHANNEL_DATA : #0'.
SshNet.Logging Verbose: 1 : SendMessage to server 'ChannelDataMessage': 'SSH_MSG_CHANNEL_DATA : #0'.
SshNet.Logging Verbose: 1 : ReceiveMessage from server: 'ChannelDataMessage': 'SSH_MSG_CHANNEL_DATA : #0'.
SshNet.Logging Verbose: 1 : SendMessage to server 'ChannelDataMessage': 'SSH_MSG_CHANNEL_DATA : #0'.
SshNet.Logging Verbose: 1 : SendMessage to server 'ChannelDataMessage': 'SSH_MSG_CHANNEL_DATA : #0'.
SshNet.Logging Verbose: 1 : ReceiveMessage from server: 'DisconnectMessage': 'SSH_MSG_DISCONNECT'.
SshNet.Logging Verbose: 1 : Disconnect received: ProtocolError data exceeds negative window tolerance

In debug the error seems inconsistent, it failed 2 out of 3 tries where in release it fails far more often.

Hope this helps.

Rich
Coordinator
Feb 5, 2013 at 1:38 AM
Hmm,

Now it actually gives me a little bit more information "ProtocolError data exceeds negative window tolerance".

What is exact file size in bytes that you trying to upload, is it 18848, the one you sent me or different?

Also, I will try to investigate now that "ProtocolError data exceeds negative window tolerance" error since I never saw it before but have one idea where it might be coming from.
I just want to get to situation where I can recreate this issue locally so I wont have to ask you to try things.

Thanks,
Oleg
Feb 5, 2013 at 2:29 AM
<div>Yes it was the same size file.</div> <div><br> </div> <div>Rich</div> <div><br> On Feb 4, 2013, at 8:38 PM, &quot;olegkap&quot; &lt;<a href="mailto:notifications@codeplex.com">notifications@codeplex.com</a>&gt; wrote:<br> <br> </div> <div><span></span></div> <blockquote type="cite"> <div> <p>From: olegkap</p> <div id="ThreadNotificationPostBody">Hmm, Now it actually gives me a little bit more information &quot;ProtocolError data exceeds negative window tolerance&quot;. What is exact file size in bytes that you trying to upload, is it 18848, the one you sent me or different? Also, I will try to investigate now that &quot;ProtocolError data exceeds negative window tolerance&quot; error since I never saw it before but have one idea where it might be coming from. I just want to get to situation where I can recreate this issue locally so I wont have to ask you to try things. Thanks, Oleg</div> </div> </blockquote>
Coordinator
Feb 5, 2013 at 3:18 AM
ok, thanks,
I will try to see if I can recreate it and find the problem.

Thanks,
Oleg
Coordinator
Feb 7, 2013 at 2:30 PM
Hey,

Just wanted to give you a little update.
Unfortunately it takes a little bit longer then expected.
Every time I think I got a fix, I found another issue, and usually it has to do with multithreading and operation synchronization.

Hope it resolve it as soon as possible.
Thanks,
Oleg
Feb 7, 2013 at 2:32 PM
Edited Feb 7, 2013 at 8:03 PM
Hey thank you very much for the update, and for the time you are taking on this.
Rich
Coordinator
Feb 7, 2013 at 7:54 PM
Hi Rich,

I just committed some fixes where I improved server window management, which I think causes you a problem.
But, my suspicion it still might not work, and this is due to server specific implementation of window management.
My suspicion that it waits for window to be 0 before expanding it but I couldn't manage to handle this situation properly so far, I think, since all implementation that I have access to handle it differently.

If you think it would be possible for me to get an access to this device with some test credentials, I probably could see if I could handle this situation a little better.
But I guess for now, see if current commit fixes it, and if not I would just log it as an Issue so other people could see that and I could get back to it later.
May be someone could get me access to one of such devises in case you can not.

Thanks,
Oleg
Feb 7, 2013 at 8:02 PM
It is not my server so I will need to request it. Let me see if IPSWITCH has a demo version of their server as well.

Rich
Coordinator
Feb 7, 2013 at 8:13 PM
ok,
Thanks,
Yea let me know if it does and where to get it, I could install it then on one of VMs here.

Thanks,
Oleg
Feb 21, 2013 at 9:07 AM
Hello, Oleg!
Now I have same problem... File is really have uploaded but the process just hangs there.
Can I see your solve for testing?
Feb 21, 2013 at 11:58 AM
In last Source code problem is solved!

Thanks!
Apr 3 at 3:52 PM
Edited Apr 3 at 5:04 PM
I had the exact same problem as rdominelli, i.e. getting "Connection was lost" intermittently when sending files to a MoveIt server.
I upgraded to the latest version of SSH.NET but this caused the program to hang and then time out in Session.cs WaitHandle(), except it's not intermittent, i can reproduce the problem every time by making sure the FIRST file to transfer is > 16K in size.

After some debugging i found that the problem is due to the initial server window size being 16K, and that the SFTP buffer size is set in SftpClient.cs SftpClient() to 16K so we get a situation only with the FIRST file.
I reduced the buffer size to 8K and that fixed it.

N.B. The window size adjust message doesnt get processed for some reason but i didnt dig deep enough to figure out why. May be because during initialization we haven't yet entered the message loop ?
Coordinator
Apr 6 at 4:57 PM
Edited Apr 6 at 4:57 PM
@flapster:
Can you try to reproduce the problem you described with the 2014.4.6-beta1 release ?
This issue should be fixed.
Let me know if it works for you.
Apr 10 at 12:48 PM

Hello,

First of all, I want to say I really appreciate the work you do and what you are doing with this project.

I updated to the 2014.4.6-beta1 release and the problem is fixed.

However, I have noticed that the time to connect to some servers is now taking longer.

My process connects to various servers every 2 minutes.

With the previous version 2013.1.27 with my own fix (change buffer size to 8K) the time it takes to connect to our MoveIt server is typically from 3-7 seconds.

But with the beta version I am now seeing fluctuating times e.g. 80,3,51,3,3,36,2,75,2,73,8,3,6,74,3,75,2

I also see the same behaviour with some Linux servers.

But not all servers. We have another MoveIt server and also some Linux servers which are connecting quickly, just as they did before.

So I don’t think it’s related to the type of server, it must be related to settings on the servers.

I appreciate there is now some additional logic in the beta version which negotiates tcp window size, do you have an explanation why the time to connect is longer than before, but it seems to fluctuate between each connection attempt, and also is OK on some servers but not on others ?

Thank You

Phillip Strong

Sep 24 at 12:06 PM
Hi,

I am getting this problem with version 2014.4.6-beta1 when running my code on Windows Server 2008 R2, but not when running on Windows 7.

I can connect to the server, and the destination file is created, but the destination file remains empty.

Not sure what kind of SFTP server I am connecting to; it is a cloud based service.

Regards

/ Otto Dandenell
Sep 24 at 12:43 PM
Edited Sep 24 at 1:05 PM
Hi again.

It turns out that the problem I had was caused by a full disk on the SFTP server. But I didn't get a proper error message saying this. In certain scenarios I would get a proper error message if I specified a buffer size (8K) for the client. Otherwise the connection would just time out.