Secure FTP - Socket closed before handshake is complete (2)

Question

Secure FTP - Socket closed before handshake is complete (2)

asked Jan 5, 2009 in .NET FTP by quimbo (1.1k points)

I connect to a secure FTP Server and cycle thru a series of folders:

          For Each folderLocation As BusinessObjects.ClientFolderLocation In folderLocations

                Try
                    Dim logDir As String = "\" & folderLocation.Folder & "\Logs\"
                    filesToLoad = Nothing

                        SFTPClose()
                        ConnectSecureFTP()
                        filesToLoad = sFTP.GetFiles(logDir)

For each folder, i close the connection and then reconnect and can pull back files without any problems.

I commented out the SFTPClose and ConnectSecureFTP lines to use the original connection. As i cycle thru each folder, when a folder has actual files in it, the line

filesToLoad = sFTP.GetFiles(logDir)

errors out with the error below

Module: FileRouter

Procedure: ResultsCheckForLogs

Error Message: Socket closed before handshake is complete (2)

Error Source: edtFTPnetPRO

Error Target: 2LR6xnNUd

Error Stack Trace: at Xy1OV7jLb6fBigTHdD4.nUXZ2rjy5nL5D6edJff.2LR6xnNUd(FNPZn2j7d1OwG5jNhoa )
at Xy1OV7jLb6fBigTHdD4.nUXZ2rjy5nL5D6edJff.xPuWluvci(SecureProtocol )
at YdUd3XsY6RQLgUn2Gr9.Pu8M4SstPWV378ScCU9.get_DataStream()
at EnterpriseDT.Net.ftp.FTPClient.VHSBN9SxZ(String )
at EnterpriseDT.Net.ftp.FTPClient.Dir(String dirname, Boolean full)
at EnterpriseDT.Net.ftp.FTPConnection.GetFiles(String directory, Boolean full)
at EnterpriseDT.Net.ftp.FTPConnection.GetFiles(String directory)
at CLPThunderFileRouter.FileRouter.ResultsCheckForLogs() in C:\Dotnet\Projects\CLPThunderFileRouter\CLPThunderFileRouter\FileRouter.vb:line 308

I have the logger set to ERROR:
EnterpriseDT.Util.Debug.Logger.CurrentLevel = EnterpriseDT.Util.Debug.Level.ERROR

If I change it to ALL, ther error goes away and I can successfully download from multiple folders without having to connects.

10 Answers

quimbo · Answer 1 · 2009-01-05T15:45:02+0000

ERROR [SocketController] 5 Jan 2009 10:40:37.056 : OnReceive - caught exception - closing : System.IO.IOException: Socket closed before handshake is complete (2)
System.IO.IOException: Socket closed before handshake is complete (2)
at GgHteFvp7hl0tK2uDD6.9qHiSnv4PbeoG0oWEhQ.xPuWluvci(IAsyncResult )
ERROR [SocketController] 5 Jan 2009 10:40:37.056 : ResumeSending - caught exception - closing : System.IO.IOException: Socket already closed
System.IO.IOException: Socket already closed
at GgHteFvp7hl0tK2uDD6.9qHiSnv4PbeoG0oWEhQ.3eSSVYP8w()
ERROR [SecureSocket] 5 Jan 2009 10:40:37.056 : Exception during handshake: Socket closed before handshake is complete (2)
ERROR [FTPClient] 5 Jan 2009 10:40:37.056 : Exception in ValidateTransferOnError()) : EnterpriseDT.Net.Ftp.FTPException: SSL/TLS lib refuses to initiate secure data connection. (code=522)
EnterpriseDT.Net.Ftp.FTPException: SSL/TLS lib refuses to initiate secure data connection. (code=522)
at EnterpriseDT.Net.Ftp.FTPControlSocket.ValidateReply(FTPReply reply, String[] expectedReplyCodes)
at EnterpriseDT.Net.Ftp.FTPClient.ValidateTransfer()
at EnterpriseDT.Net.Ftp.FTPClient.ValidateTransferOnError()
ERROR [FTPClient] 5 Jan 2009 10:40:37.087 : SystemException in directory listing : System.IO.IOException: Socket closed before handshake is complete (2)
System.IO.IOException: Socket closed before handshake is complete (2)
at Xy1OV7jLb6fBigTHdD4.nUXZ2rjy5nL5D6edJff.2LR6xnNUd(FNPZn2j7d1OwG5jNhoa )
at Xy1OV7jLb6fBigTHdD4.nUXZ2rjy5nL5D6edJff.xPuWluvci(SecureProtocol )
at YdUd3XsY6RQLgUn2Gr9.Pu8M4SstPWV378ScCU9.get_DataStream()
at EnterpriseDT.Net.Ftp.FTPClient.VHSBN9SxZ(String )
at EnterpriseDT.Net.Ftp.FTPClient.Dir(String dirname, Boolean full)
ERROR [SocketController] 5 Jan 2009 10:40:37.118 : OnReceive - caught exception - closing : System.IO.IOException: Socket closed before handshake is complete (2)
System.IO.IOException: Socket closed before handshake is complete (2)
at GgHteFvp7hl0tK2uDD6.9qHiSnv4PbeoG0oWEhQ.xPuWluvci(IAsyncResult )
ERROR [SocketController] 5 Jan 2009 10:40:37.134 : ResumeSending - caught exception - closing : System.IO.IOException: Socket already closed
System.IO.IOException: Socket already closed
at GgHteFvp7hl0tK2uDD6.9qHiSnv4PbeoG0oWEhQ.3eSSVYP8w()
ERROR [SecureSocket] 5 Jan 2009 10:40:37.134 : Exception during handshake: Socket closed before handshake is complete (2)
ERROR [FTPClient] 5 Jan 2009 10:40:37.134 : Exception in ValidateTransferOnError()) : EnterpriseDT.Net.Ftp.FTPException: SSL/TLS lib refuses to initiate secure data connection. (code=522)
EnterpriseDT.Net.Ftp.FTPException: SSL/TLS lib refuses to initiate secure data connection. (code=522)
at EnterpriseDT.Net.Ftp.FTPControlSocket.ValidateReply(FTPReply reply, String[] expectedReplyCodes)
at EnterpriseDT.Net.Ftp.FTPClient.ValidateTransfer()
at EnterpriseDT.Net.Ftp.FTPClient.ValidateTransferOnError()
ERROR [FTPClient] 5 Jan 2009 10:40:37.134 : SystemException in directory listing : System.IO.IOException: Socket closed before handshake is complete (2)
System.IO.IOException: Socket closed before handshake is complete (2)
at Xy1OV7jLb6fBigTHdD4.nUXZ2rjy5nL5D6edJff.2LR6xnNUd(FNPZn2j7d1OwG5jNhoa )
at Xy1OV7jLb6fBigTHdD4.nUXZ2rjy5nL5D6edJff.xPuWluvci(SecureProtocol )
at YdUd3XsY6RQLgUn2Gr9.Pu8M4SstPWV378ScCU9.get_DataStream()
at EnterpriseDT.Net.Ftp.FTPClient.VHSBN9SxZ(String )
at EnterpriseDT.Net.Ftp.FTPClient.Dir(String dirname, Boolean full)
ERROR [SocketController] 5 Jan 2009 10:42:37.945 : OnReceive - caught exception - closing : System.IO.IOException: Socket closed before handshake is complete (2)
System.IO.IOException: Socket closed before handshake is complete (2)
at GgHteFvp7hl0tK2uDD6.9qHiSnv4PbeoG0oWEhQ.xPuWluvci(IAsyncResult )
ERROR [SocketController] 5 Jan 2009 10:42:37.960 : ResumeSending - caught exception - closing : System.IO.IOException: Socket already closed
System.IO.IOException: Socket already closed
at GgHteFvp7hl0tK2uDD6.9qHiSnv4PbeoG0oWEhQ.3eSSVYP8w()
ERROR [SecureSocket] 5 Jan 2009 10:42:37.960 : Exception during handshake: Socket closed before handshake is complete (2)
ERROR [FTPClient] 5 Jan 2009 10:42:37.960 : Exception in ValidateTransferOnError()) : EnterpriseDT.Net.Ftp.FTPException: SSL/TLS lib refuses to initiate secure data connection. (code=522)
EnterpriseDT.Net.Ftp.FTPException: SSL/TLS lib refuses to initiate secure data connection. (code=522)
at EnterpriseDT.Net.Ftp.FTPControlSocket.ValidateReply(FTPReply reply, String[] expectedReplyCodes)
at EnterpriseDT.Net.Ftp.FTPClient.ValidateTransfer()
at EnterpriseDT.Net.Ftp.FTPClient.ValidateTransferOnError()
ERROR [FTPClient] 5 Jan 2009 10:42:37.960 : SystemException in directory listing : System.IO.IOException: Socket closed before handshake is complete (2)
System.IO.IOException: Socket closed before handshake is complete (2)
at Xy1OV7jLb6fBigTHdD4.nUXZ2rjy5nL5D6edJff.2LR6xnNUd(FNPZn2j7d1OwG5jNhoa )
at Xy1OV7jLb6fBigTHdD4.nUXZ2rjy5nL5D6edJff.xPuWluvci(SecureProtocol )
at YdUd3XsY6RQLgUn2Gr9.Pu8M4SstPWV378ScCU9.get_DataStream()
at EnterpriseDT.Net.Ftp.FTPClient.VHSBN9SxZ(String )
at EnterpriseDT.Net.Ftp.FTPClient.Dir(String dirname, Boolean full)
ERROR [SocketController] 5 Jan 2009 10:42:37.991 : OnReceive - caught exception - closing : System.IO.IOException: Socket closed before handshake is complete (2)
System.IO.IOException: Socket closed before handshake is complete (2)
at GgHteFvp7hl0tK2uDD6.9qHiSnv4PbeoG0oWEhQ.xPuWluvci(IAsyncResult )
ERROR [SocketController] 5 Jan 2009 10:42:37.991 : ResumeSending - caught exception - closing : System.IO.IOException: Socket already closed
System.IO.IOException: Socket already closed
at GgHteFvp7hl0tK2uDD6.9qHiSnv4PbeoG0oWEhQ.3eSSVYP8w()
ERROR [SecureSocket] 5 Jan 2009 10:42:37.991 : Exception during handshake: Socket closed before handshake is complete (2)
ERROR [FTPClient] 5 Jan 2009 10:42:38.007 : Exception in ValidateTransferOnError()) : EnterpriseDT.Net.Ftp.FTPException: SSL/TLS lib refuses to initiate secure data connection. (code=522)
EnterpriseDT.Net.Ftp.FTPException: SSL/TLS lib refuses to initiate secure data connection. (code=522)
at EnterpriseDT.Net.Ftp.FTPControlSocket.ValidateReply(FTPReply reply, String[] expectedReplyCodes)
at EnterpriseDT.Net.Ftp.FTPClient.ValidateTransfer()
at EnterpriseDT.Net.Ftp.FTPClient.ValidateTransferOnError()
ERROR [FTPClient] 5 Jan 2009 10:42:38.007 : SystemException in directory listing : System.IO.IOException: Socket closed before handshake is complete (2)
System.IO.IOException: Socket closed before handshake is complete (2)
at Xy1OV7jLb6fBigTHdD4.nUXZ2rjy5nL5D6edJff.2LR6xnNUd(FNPZn2j7d1OwG5jNhoa )
at Xy1OV7jLb6fBigTHdD4.nUXZ2rjy5nL5D6edJff.xPuWluvci(SecureProtocol )
at YdUd3XsY6RQLgUn2Gr9.Pu8M4SstPWV378ScCU9.get_DataStream()
at EnterpriseDT.Net.Ftp.FTPClient.VHSBN9SxZ(String )
at EnterpriseDT.Net.Ftp.FTPClient.Dir(String dirname, Boolean full)

EDT Support · Answer 2 · 2009-01-05T23:55:09+0000

What server are you connecting to? Is it Serv-U?

The server is reporting that "SSL/TLS lib refuses to initiate secure data connection". Are you able to view the server logs? That error should appear in there; perhaps there's some additional information that will provide a clue.

Also, does this happen for all directories or only particular ones (e.g. empty directories)?

- Hans (EnterpriseDT)

quimbo · Answer 3 · 2009-01-06T13:37:17+0000

It is indeed Serv-U, version 6.4.0.6

It only happens when a directory contains a file.

Later today I will enable Serv-U logging and run another test.

quimbo · Answer 4 · 2009-01-08T15:44:16+0000

sorry, bigger fires yesterday; here is the log.

The error occurs when looking at folder \EBOMC\Logs\ which is 25 lines down

the line of code that causes this error is:

filesToLoad = sFTP.GetFiles(logDir)

[2] Thu 08Jan09 10:37:46 - (001050) NLST \FAIMC\Logs\
[6] Thu 08Jan09 10:37:46 - (001050) 550 \FAIMC\Logs\: No such file or directory.
[7] Thu 08Jan09 10:37:46 - Sock ID=1998 RB_READ Stat=OK
[7] Thu 08Jan09 10:37:46 - Sock ID=1998 SSL_read(0x00C144B0,0x04E34008,2048) --> -1 (SSL_ERROR_WANT_READ)
[7] Thu 08Jan09 10:37:46 - Sock ID=1998 RB_WRITE Stat=OK
[7] Thu 08Jan09 10:37:46 - Sock ID=1998 SSL_write(0x00C144B0,0x00C58FA8,46) --> 46 (OK)
[7] Thu 08Jan09 10:37:46 - Sock ID=2010 WSAAsyncSelect(16824,018F00D0,0,<<NONE>>) --> 0 (OK)
[7] Thu 08Jan09 10:37:46 - Sock ID=2010 setsockopt(16824,SOL_SOCKET,SO_LINGER,0x00ADF518,4) --> 0 (OK)
[7] Thu 08Jan09 10:37:46 - Sock ID=2010 shutdown(16824,0) --> 0 (OK)
[7] Thu 08Jan09 10:37:46 - Sock ID=2010 shutdown(16824,1) --> 0 (OK)
[7] Thu 08Jan09 10:37:46 - Sock ID=2010 closesocket(16824) --> 0 (OK)
[7] Thu 08Jan09 10:37:46 - Sock ID=2011 FD_WRITE Stat=OK
[7] Thu 08Jan09 10:37:46 - Sock ID=2011 FD_CLOSE Stat=OK
[7] Thu 08Jan09 10:37:46 - Sock ID=1998 FD_READ Stat=OK
[7] Thu 08Jan09 10:37:46 - Sock ID=1998 SSL_read(0x00C144B0,0x04E34008,2048) --> 6 (OK)
[7] Thu 08Jan09 10:37:46 - Sock ID=2011 RB_READ Stat=OK
[2] Thu 08Jan09 10:37:46 - (001050) PASV
[6] Thu 08Jan09 10:37:46 - (001050) 227 Entering Passive Mode (204,130,8,3,13,177)
[7] Thu 08Jan09 10:37:46 - Sock ID=1998 RB_READ Stat=OK
[7] Thu 08Jan09 10:37:46 - Sock ID=1998 SSL_read(0x00C144B0,0x04E34008,2048) --> -1 (SSL_ERROR_WANT_READ)
[7] Thu 08Jan09 10:37:46 - Sock ID=1998 RB_WRITE Stat=OK
[7] Thu 08Jan09 10:37:46 - Sock ID=1998 SSL_write(0x00C144B0,0x00C58FA8,48) --> 48 (OK)
[7] Thu 08Jan09 10:37:46 - Sock ID=1998 FD_READ Stat=OK
[7] Thu 08Jan09 10:37:46 - Sock ID=1998 SSL_read(0x00C144B0,0x04E34008,2048) --> 19 (OK)
[2] Thu 08Jan09 10:37:46 - (001050) NLST \EBOMC\Logs\
[6] Thu 08Jan09 10:37:46 - (001050) 150 Opening ASCII mode data connection for /bin/ls.
[7] Thu 08Jan09 10:37:46 - Sock ID=2011 setsockopt(17328,SOL_SOCKET,SO_OOBINLINE,0x00ADBD93,1) --> 0 (OK)
[7] Thu 08Jan09 10:37:46 - Sock ID=2011 setsockopt(17328,SOL_SOCKET,SO_KEEPALIVE,0x00ADBD93,1) --> 0 (OK)
[7] Thu 08Jan09 10:37:46 - Sock ID=2011 setsockopt(17328,IPPROTO_TCP,TCP_NODELAY,0x00ADBD93,1) --> 0 (OK)
[7] Thu 08Jan09 10:37:46 - Sock ID=2011 setsockopt(17328,SOL_SOCKET,SO_SNDBUF,0x00ADBD9C,4) --> 0 (OK)
[7] Thu 08Jan09 10:37:46 - Sock ID=2011 setsockopt(17328,SOL_SOCKET,SO_RCVBUF,0x00ADBD9C,4) --> 0 (OK)
[7] Thu 08Jan09 10:37:46 - Sock ID=2011 setsockopt(17328,IPPROTO_TCP,TCP_NODELAY,0x00ADBD8F,1) --> 0 (OK)
[7] Thu 08Jan09 10:37:46 - Sock ID=2011 SSL_set_accept_state(0x00C1EEC8)
[7] Thu 08Jan09 10:37:46 - Sock ID=2011 SSL_accept(0x00C1EEC8) --> 0 (SSL_ERROR_SYSCALL)
[7] Thu 08Jan09 10:37:46 - Sock ID=2011 SSL_free(0x00C1EEC8)
[7] Thu 08Jan09 10:37:46 - Sock ID=2011 WSAAsyncSelect(17328,018F00D0,0,<<NONE>>) --> 0 (OK)
[7] Thu 08Jan09 10:37:46 - Sock ID=2011 setsockopt(17328,SOL_SOCKET,SO_LINGER,0x00ADA318,4) --> 0 (OK)
[7] Thu 08Jan09 10:37:46 - Sock ID=2011 shutdown(17328,0) --> 0 (OK)
[7] Thu 08Jan09 10:37:46 - Sock ID=2011 shutdown(17328,1) --> 0 (OK)
[7] Thu 08Jan09 10:37:46 - Sock ID=2011 closesocket(17328) --> 0 (OK)
[6] Thu 08Jan09 10:37:46 - (001050) 522 SSL/TLS lib refuses to initiate secure data connection.
[7] Thu 08Jan09 10:37:46 - Sock ID=1998 RB_READ Stat=OK
[7] Thu 08Jan09 10:37:46 - Sock ID=1998 SSL_read(0x00C144B0,0x04E34008,2048) --> -1 (SSL_ERROR_WANT_READ)
[7] Thu 08Jan09 10:37:46 - Sock ID=1998 RB_WRITE Stat=OK
[7] Thu 08Jan09 10:37:46 - Sock ID=1998 SSL_write(0x00C144B0,0x00C58FA8,53) --> 53 (OK)
[7] Thu 08Jan09 10:37:46 - Sock ID=1998 RB_WRITE Stat=OK
[7] Thu 08Jan09 10:37:46 - Sock ID=1998 SSL_write(0x00C144B0,0x00C58FA8,61) --> 61 (OK)
[7] Thu 08Jan09 10:37:46 - Sock ID=1998 FD_READ Stat=OK
[7] Thu 08Jan09 10:37:46 - Sock ID=1998 SSL_read(0x00C144B0,0x04E34008,2048) --> 6 (OK)
[2] Thu 08Jan09 10:37:46 - (001050) PASV
[6] Thu 08Jan09 10:37:46 - (001050) 227 Entering Passive Mode (204,130,8,3,13,178)
[7] Thu 08Jan09 10:37:46 - Sock ID=1998 RB_READ Stat=OK
[7] Thu 08Jan09 10:37:46 - Sock ID=1998 SSL_read(0x00C144B0,0x04E34008,2048) --> -1 (SSL_ERROR_WANT_READ)
[7] Thu 08Jan09 10:37:46 - Sock ID=1998 RB_WRITE Stat=OK
[7] Thu 08Jan09 10:37:46 - Sock ID=1998 SSL_write(0x00C144B0,0x00C58FA8,48) --> 48 (OK)
[7] Thu 08Jan09 10:37:46 - Sock ID=1998 FD_READ Stat=OK
[7] Thu 08Jan09 10:37:46 - Sock ID=1998 SSL_read(0x00C144B0,0x04E34008,2048) --> 19 (OK)
[2] Thu 08Jan09 10:37:46 - (001050) NLST \DUBMC\Logs\
[6] Thu 08Jan09 10:37:46 - (001050) 550 \DUBMC\Logs\: No such file or directory.

quimbo · Answer 5 · 2009-01-09T16:35:56+0000

i am using a SecureFTPConnection object

            sFTP = New SecureFTPConnection
            sFTP.LicenseOwner =******************
            sFTP.LicenseKey = ******************

            sFTP.ServerAddress = ftpServer
            sFTP.ServerPort = CType(ftpPort, Integer)
            sFTP.UserName = ftpUser
            sFTP.Password = ftpPassword

            sFTP.Protocol = FileTransferProtocol.FTPSExplicit

            sFTP.ServerValidation = SecureFTPServerValidationType.Automatic
            sFTP.ServerCommonName = ******************
            sFTP.SSLVersion = SSLFTPSSLVersion.SSL3

            sFTP.Connect()

This is internal to our network so security is set to Allow SSL/TLS and regular sessions

EDT Support · Answer 6 · 2009-01-10T01:34:42+0000

We're still looking for clues in the logs and will get back to you ASAP.

- Hans (EnterpriseDT)

EDT Support · Answer 7 · 2009-01-12T06:22:10+0000

We've tried to replicate the problem but have not been able to as yet. The version that you are using is rather old, the latest being 7.4.0.1 and yours being 6.4.0.6. Would you be able try it with a later version? They have a 30-day trial.

The only other thing I've thought of is to use TLS1 instead of SSL3:

ftp.SSLVersion = SSLFTPSSLVersion.TLS1

- Hans (EnterpriseDT)

quimbo · Answer 8 · 2009-01-12T12:05:37+0000

Changing it to TSL1 did not work.

We plan on upgrading within 30-60 days, many clients connect to this server so we can't just upgrade.

Will follow up when we do upgrade

EDT Support · Answer 9 · 2009-01-12T23:55:17+0000

I was thinking that you might like to install the trial version of Serv-U on a development machine and testing if you receive the same error when running your code against that server.

- Hans (EnterpriseDT)

Secure FTP - Socket closed before handshake is complete (2)

Please log in or register to add a comment.

Please log in or register to answer this question.

10 Answers

Please log in or register to add a comment.

Please log in or register to add a comment.

Please log in or register to add a comment.

Please log in or register to add a comment.

Please log in or register to add a comment.

Please log in or register to add a comment.

Please log in or register to add a comment.

Please log in or register to add a comment.

Please log in or register to add a comment.

Please log in or register to add a comment.

Categories