Multiple downloads, continue from earlier thread.

0 votes
asked Mar 18, 2010 by Martin (140 points)
edited Apr 1, 2011

I'm trying to download 3 files at the same time, and it works most of the times, but sometimes this error occur. about 26mins after the first download was done(at 13:48:15), the other connections was closed(at 14:14:53)? So now I'm wondering if its the server or client that closes it? client logging:

2010-03-18 13:14:52.744 INFO Ftp(2) Response: 227 Entering Passive Mode (***,143).
2010-03-18 13:14:52.744 INFO Ftp(3) Response: 227 Entering Passive Mode (***,144).
2010-03-18 13:14:52.744 INFO Ftp(1) Response: 227 Entering Passive Mode (***,145).
2010-03-18 13:14:52.760 DEBUG Ftp(3) Info: Establishing data connection to ***:61328.
2010-03-18 13:14:52.760 DEBUG Ftp(2) Info: Establishing data connection to ***:61327.
2010-03-18 13:14:52.760 DEBUG Ftp(1) Info: Establishing data connection to ***:61329.
2010-03-18 13:14:52.838 INFO Ftp(3) Command: RETR ***.wmv
2010-03-18 13:14:52.838 INFO Ftp(1) Command: RETR ***.wmv
2010-03-18 13:14:52.932 INFO Ftp(3) Response: 150 Opening BINARY mode data connection for ***.wmv (305216636 bytes).
2010-03-18 13:14:52.932 INFO Ftp(2) Response: 150 Opening BINARY mode data connection for ***.wmv (955444586 bytes).
2010-03-18 13:14:52.932 INFO Ftp(1) Response: 150 Opening BINARY mode data connection for ***.wmv (1176154131 bytes).
2010-03-18 13:48:15.716 DEBUG Ftp(3) Info: Data transfer ended.
2010-03-18 13:48:15.731 DEBUG Ftp(3) Info: Closing downloading data connection.
2010-03-18 13:48:15.731 DEBUG Ftp(3) Info: Waiting for data transfer ending message.
2010-03-18 13:48:15.731 INFO Ftp(3) Response: 226 Closing data connection. Transferred 305,216,636 bytes in 2003 seconds. 148KB/second.
2010-03-18 13:48:15.731 DEBUG Ftp(3) Info: Data transfer ended.
2010-03-18 13:48:15.731 DEBUG Ftp(3) Info: Transfer ended successfully.
2010-03-18 13:48:15.731 DEBUG Ftp(3) Info: Data connection closed.
**___2010-03-18 14:14:53.705 DEBUG Ftp(1) Info: Closing data connection.___ why closing?**
t2010-03-18 14:14:53.721 ERROR Ftp(1) Info: Error while reading data: Rebex.Net.FtpException: An existing connection was forcibly closed by the remote host. ---> System.Net.Sockets.SocketException: An existing connection was forcibly closed by the remote host
   at System.Net.Sockets.Socket.Receive(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)

Serverlogging:

2010-03-18 14:14:52 [2/660/984] Closed connection from IP address: ***, port: 4681
2010-03-18 14:14:53 [2/0/5ec] RESPONSE: 426 Connection closed; transfer aborted. Transferred 536,698,880 bytes in 3601 seconds. 145KB/second.
2010-03-18 14:14:53 [2/660/990] Closed connection from IP address: ***, port: 4682
2010-03-18 14:14:54 [2/0/3e98] RESPONSE: 426 Connection closed; transfer aborted. Transferred 547,831,808 bytes in 3602 seconds. 148KB/second.

It seems that the transfer ends after 60mins so maybe its network related?

Applies to: Rebex FTP/SSL

1 Answer

0 votes
answered Mar 18, 2010 by Lukas Pokorny (96,250 points)
edited Mar 18, 2010

I have filtered the log to only show the affected transfer:

2010-03-18 13:14:52.744 INFO Ftp(1) Response: 227 Entering Passive Mode (***,145).
2010-03-18 13:14:52.760 DEBUG Ftp(1) Info: Establishing data connection to ***:61329.
2010-03-18 13:14:52.838 INFO Ftp(1) Command: RETR ***.wmv
2010-03-18 13:14:52.932 INFO Ftp(1) Response: 150 Opening BINARY mode data connection for ***.wmv (1176154131 bytes).
2010-03-18 14:14:53.705 DEBUG Ftp(1) Info: Closing data connection.
2010-03-18 14:14:53.721 ERROR Ftp(1) Info: Error while reading data: Rebex.Net.FtpException: An existing connection was forcibly closed by the remote host. ---> System.Net.Sockets.SocketException: An existing connection was forcibly closed by the remote host
   at System.Net.Sockets.Socket.Receive(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)

The reason for "closing data connection" message is not apparent from the log in this case without some knowledge about Rebex FTP internals. We will surely enhance the log to make it more informative. For now, this is basically what's going on inside:

void ProcessResponse()
{
    try
    {
        ReadResponseIfAvailable(); // 1. The SocketException occured in this method.
    }
    catch (FtpException x) 
    {
        // 2. We catched it here

        if (x.Status == FtpExceptionStatus.ConnectionClosed)
        {
            // 3. The control connection is closed, let's shutdown the rest
            // and write "Closing data connection" message into the log.

            Log("Closing data connection.");
            CloseDataConnection();
        }

        // 4. Re-throw the original exception. At this point, it has not been logged yet.
        throw;
    }
}

void ReceiveData()
{
    try
    {
        ReadData();
        ProcessResponse();
    }
    catch (Exception x)
    {
        // 5. Here, the original exception is logged.
        Log("Error while reading data:", x);
        throw;
    }
}

What does this mean? The SocketException occured first. Then we reacted by closing the still-active data connection as well. The actual two messages in the log are reversed.

So what does this mean? You are probably right and this is network related. After 60mins, something closes the FTP control connection.

And this is something we have encoutered in the past - it sometimes happens with badly behaved firewalls or routers that silently close the main FTP connection because of inactivity, even though the main FTP connection is actually supposed to be inactive while the transfer is in progress (it uses a separate TCP connection).

Rebex FTP includes a workaround for this issue, but it doesn't work reliably with all FTP servers so it's disabled by default. To enable it, use this code:

client.Options |= FtpOptions.KeepAliveDuringTransfer;

This will cause a dummy NOOP command to be sent every 600 seconds (10 minutes) - you can also specify a longer interval by changing the value of Ftp object's KeepAliveDuringTransferInterval property.

Does enabling this option help?

commented Mar 18, 2010 by Martin (140 points)
Hi and thanks for this very well explained answer:) I have tried to set it to that option but it seems that I get another problem then, I will gather the new logs and post them tomorrow. Just gonna let it run for a bit more to be sure its nothing else that messing it up.
commented Mar 23, 2010 by Lukas Pokorny (96,250 points)
Hello, any news on this?
...