0 votes
by (150 points)

Hi,

I am trying to use SFTP to connect to a host. It works the first time. If I try to reconnect (without restarting the application) the connect fails with the exception:

Timeout exceeded while waiting for welcome message. 
Make sure you are connecting to an SSH or SFTP server.

Here is the log. One weird thing about the log is that the fact that logging has begun is not logged the second time I start LogWriter, but it is the first time I start it.

2017-09-26 09:50:33.366 INFO Sftp(3)[12] Info: Connecting to xxxxx:22 using Sftp.
2017-09-26 09:50:33.366 INFO Sftp(3)[12] Info: Assembly: Rebex.Sftp 2017 R3 for .NET 4.0-4.7
2017-09-26 09:50:33.366 DEBUG Sftp(3)[12] Info: Platform: Windows 6.1.7601 64-bit; CLR: 4.0.30319.42000
2017-09-26 09:50:33.366 DEBUG Sftp(3)[12] Info: Culture: en; Windows-1252
2017-09-26 09:50:33.366 INFO Sftp(3)[12] Info: Using proxy HTTP CONNECT proxy:8080.
2017-09-26 09:50:33.366 DEBUG ProxySocket(2)[12] Proxy: Resolving 'proxy'.
2017-09-26 09:50:33.368 DEBUG ProxySocket(2)[13] Proxy: Connecting to proxy at xxxxx:8080.
2017-09-26 09:50:33.543 DEBUG ProxySocket(2)[10] Proxy: Connection initialized successfully.
2017-09-26 09:50:35.566 ERROR Sftp(3)[12] SSH: Rebex.Net.SshException: Timeout exceeded while waiting for welcome message. Make sure you are connecting to an SSH or SFTP server.
   at Rebex.Net.SshSession.GNV()
   at Rebex.Net.SshSession.Negotiate()
2017-09-26 09:50:35.567 ERROR Sftp(3)[12] Info: Rebex.Net.SshException: Timeout exceeded while waiting for welcome message. Make sure you are connecting to an SSH or SFTP server.
   at Rebex.Net.SshSession.GNV()
   at Rebex.Net.SshSession.Negotiate()
   at Rebex.Net.Sftp.EOG.NNV(TUG C, Boolean V)
   at Rebex.Net.Sftp.HJ(String C, Int32 V, SshParameters Z, TUG N)
Applies to: Rebex SFTP

1 Answer

0 votes
by (70.2k points)
selected by
 
Best answer

This is very probably caused by the HTTP proxy you are using.

I tried to connect to your server with our HTTP proxy more than 10 times in a row and it worked well.

You can try it for yourself using just plain ProxySocket:

private static string WaitForWelcomeMessage(string host, int port, string proxyHost, int proxyPort)
{
    // initialize proxy socket
    var proxy = new Rebex.Net.Proxy(Rebex.Net.ProxyType.HttpConnect, proxyHost, proxyPort);
    proxy.LogWriter = new Rebex.ConsoleLogWriter(Rebex.LogLevel.Verbose);
    var socket = new Rebex.Net.ProxySocket(proxy);
    socket.Timeout = 5000;
    try
    {
        // connect to host using specified proxy
        socket.Connect(host, port);

        // read bytes until welcome message is received
        int total = 0;
        byte[] buffer = new byte[1024];
        while (true)
        {
            int n = socket.Receive(buffer, total, buffer.Length - total);
            if (n <= 0)
            {
                // log connection closure
                proxy.LogWriter.Write(Rebex.LogLevel.Verbose, socket.GetType(), 0, "Socket", "Connection closed.");
                return null;
            }

            // log received data
            proxy.LogWriter.Write(Rebex.LogLevel.Verbose, socket.GetType(), 0, "Socket", "Received data:", buffer, total, n);

            total += n;

            // find new line in received data
            int newLine = Array.IndexOf<byte>(buffer, (byte)'\n', 0, total);
            if (newLine >= 0)
                return Encoding.ASCII.GetString(buffer, 0, newLine).TrimEnd();

            // this should never arise
            if (total == buffer.Length)
            {
                proxy.LogWriter.Write(Rebex.LogLevel.Error, socket.GetType(), 0, "Socket", "No new line in 1KB.");
                return null;
            }
        }
    }
    catch (Exception ex)
    {
        proxy.LogWriter.Write(Rebex.LogLevel.Error, socket.GetType(), 0, "Socket", ex.ToString());
        return null;
    }
    finally
    {
        socket.Close();
    }
}

Use the method like this:

string host = "xxxxx";
int port = 22;
string proxyHost = "xxxxx";
int proxyPort = 8080;

int TOTAL = 12;
int success = 0;
for (int i = 0; i < TOTAL; i++)
{
    Console.WriteLine("Waiting for welcome message ...");
    string message = WaitForWelcomeMessage(host, port, proxyHost, proxyPort);
    if (message != null)
    {
        Console.WriteLine("Welcome message received: {0}", message);
        success++;
    }
    else
    {
        Console.WriteLine("Welcome message not received.");
    }
}
Console.WriteLine("Total attempts: {0}", TOTAL);
Console.WriteLine("Success attempts: {0}", success);
Console.WriteLine("Failed attempts: {0}", TOTAL - success);

You can use some network analyzer such as Wireshark to ensure the welcome message was not received by network socket in case of failure.

If network analyzer shows, that the welcom message was sent by network, but the ProxySocket didn't receive it, it is a bug in the Rebex code. In this case, please send us the produced Verbose log (output of the program above) and network capture (created by e.g. Wireshark).

Alternatively, you can use Rebex.FileLogWriter instead of Rebex.ConsoleLogWriter for easier log creation.

by (150 points)
Hello, I made the WaitForServerWelcomeMessage true, and i think doing that has fixed the problem.

But I am now having another problem. In the middle of transferring a collection of  files, some of which are very large, I get the "operation has timed out" exception. I made a guess that this was happening because I was transferring too many files within a single "connection". I am now testing whether sending each file in its own connections fixes the problem. Hopefully it does.
by (150 points)
Bad new, I still get both exceptions...seemingly at random.

As you say, it probably has to do with the proxy.
by (70.2k points)
Since your server is accessible from the internet, you can test your application without proxy (from other network). If your application works well without proxy, but encounters timeouts using proxy, it is definitely caused by your proxy.

In this case, look at the proxy network capture and ensure that all incoming packets from server are forwarded to client.

If you receive timeouts even when using no proxy, let us know. We will suggest you other steps to diagnose the problem.

Also please look into server logs whether there is some useful information which can describe your issue.

And finally, I have an idea. Please ensure that the issue is not caused by an anti-virus software (or a firewall). We encountered anti-virus which tried to sniff secured transfer causing an issue. We also encountered anti-virus successfully performing man-in-the-middle attack...
by (150 points)
Hello,

I don't think anymore that there is a problem with the my network. Because Filezilla works fine.

I did notice something though. I see that we are using the method PutFile of the Sftp class. However, there is an Upload method in the Sftp class, which is an alternative to the PutFile method. I read that Upload will try to resume transmission if failure occurs. So maybe if I used Upload instead of PutFile I would be able to send the files successfully?
by (70.2k points)
Do you also use Filezilla with proxy? Can you please look into Filezilla log and check whether it performs reconnects? If yes, the issue is related to your network, but Filezilla masks this by auto-reconnects.

Where did you read that Upload resumes transmissions on failures? It is true, that there is possibility to call Upload method with ActionOnExistingFiles.ResumeIfPossible option, but this is not performed automatically. And even if you call the Upload method with ResumeIfPossible option and the transfer fails, an exception is raised and you have to reconnect and perform upload again manually. The auto-reconnect feature is not available yet.
by (150 points)
Hi, yes I do use Filezilla with proxy. I assume that Filezilla is reconnecting. I can't confirm this because Filezilla's logs aren't detailed enough, even at DEBUG level logging.

So assuming I can't fix the proxy, the only thing I can do is wrap my call to  PutFile in a try-catch-block, and should an exception be thrown, recall Putfile. I guess I will use your "resumeIfPossible" feature to upload only the remaining part of the file in the catch block.

"Where did you read that Upload resumes transmissions on failures? "

I got the impression that Upload resumed from reading this :
https://www.rebex.net/sftp.net/features/file-transfer.aspx#autoresume

Maybe you should edit the documentation so that it's explicit about what constitutes an "interrupted transfer".
by (150 points)
Hi,  I asked the network people to let me send to the host without going through the proxy. They set this up, and everything seems to work now.

So it was the proxy.
by (70.2k points)
Yes, calling Upload method with "ResumeIfPossible" should do the trick. However, the best solution in your case is not to use the proxy if possible.

Thank you for your suggestion, I will update the feature page.
by (150 points)
Hi, the problem has been fixed. For some reason, the Timeout property of the SFTP class was set to 1 second.
by (70.2k points)
Hi, great that you were able to locate the cause!

I suppose that you were setting Timeout to e.g. value 30. However, the Timeout is not in seconds but milliseconds. In your case the Timeout was set to minimal allowed value which is 1000 milliseconds, which is 1 second.

This XML doc for Sftp.Timeout:
Summary:
Gets or sets the length of time in milliseconds before the operation times out (specify -1 or 0 to indicate that the request does not time out).
Remarks:
... Minimal value is 1000. Setting this to a value lower than 1000 will set it to 1000.
...