Attempt to connect to an SFTP server results in exception

Question

- The error is the same regardless of whether we use active mode or passive mode.
- We attempt to connect using username + password (works fine when using the Filezilla client)

Any idea about what it is that we are doing wrong? Here is the log:

DEBUG [SFTPMessageStore] 27 Mar 2014 23:11:27.685 : Set timeout=10000
INFO [LicenseProperties] 27 Mar 2014 23:11:27.707 : Licence expiry date: 31/12/9999
INFO [LicenseProperties] 27 Mar 2014 23:11:27.707 : Production license
DEBUG [FTPConnection] 27 Mar 2014 23:11:27.711 : Set LocalDirectory='[...]'
DEBUG [SecureFTPConnection] 27 Mar 2014 23:11:27.712 : Set LocalDirectory to [...]
INFO [LicenseProperties] 27 Mar 2014 23:11:27.720 : Licence expiry date: 31/12/9999
INFO [LicenseProperties] 27 Mar 2014 23:11:27.721 : Production license
DEBUG [SSHSCPClient] 27 Mar 2014 23:11:27.723 : Setting up fallback kbi prompt based on supplied password
DEBUG [HostNameResolver] 27 Mar 2014 23:11:27.933 : Resolving [censored]
DEBUG [HostNameResolver] 27 Mar 2014 23:11:28.462 : Obtained 1 addresses
DEBUG [HostNameResolver] 27 Mar 2014 23:11:28.474 : IP address: [censored]
DEBUG [HostNameResolver] 27 Mar 2014 23:11:28.474 : portal.conformis.com resolved to [censored]
DEBUG [SSHSCPClient] 27 Mar 2014 23:11:28.474 : Connecting directly to SFTP server [censored]:22
INFO [BaseSocket] 27 Mar 2014 23:11:28.480 : Connecting to [censored]:22 with timeout 10000 ms
DEBUG [BaseSocket] 27 Mar 2014 23:11:28.700 : Successfully connected to [censored]:22
DEBUG [SSHSCPClient] 27 Mar 2014 23:11:28.700 : Connected successfully to SFTP server [censored]:22
DEBUG [SSHConnection] 27 Mar 2014 23:11:28.702 : Beginning protocol negotiation
DEBUG [PlainSocket] 27 Mar 2014 23:11:28.815 : FTPConnection.1RepeatCallback received 33 bytes
DEBUG [ProtocolNegotiationHandler] 27 Mar 2014 23:11:28.819 : FTPConnection.1offset=0,length=33
DEBUG [ProtocolNegotiationHandler] 27 Mar 2014 23:11:28.819 : FTPConnection.1Read: 'SSH-2.0-GoAnywhereServices3.4.2
'
INFO [ProtocolNegotiationHandler] 27 Mar 2014 23:11:28.819 : FTPConnection.1Server version = 'SSH-2.0-GoAnywhereServices3.4.2'
DEBUG [SSHUtil] 27 Mar 2014 23:11:28.822 : FTPConnection.1Major string = '2'
DEBUG [SSHUtil] 27 Mar 2014 23:11:28.822 : FTPConnection.1Minor string = '0'
DEBUG [SSHUtil] 27 Mar 2014 23:11:28.822 : FTPConnection.1Version 2.0
DEBUG [SSHUtil] 27 Mar 2014 23:11:28.822 : FTPConnection.1Protocol compatible
DEBUG [SSHConnection] 27 Mar 2014 23:11:28.825 : Server version=SSH-2.0-GoAnywhereServices3.4.2
DEBUG [SSH2Connection] 27 Mar 2014 23:11:28.829 : Timeout=10000
DEBUG [SSHConnection] 27 Mar 2014 23:11:28.832 : Sending client version=SSH-2.0-edtFTPnet/PRO-8.5.0.20
DEBUG [SSH2Connection] 27 Mar 2014 23:11:28.840 : Starting key exchange
DEBUG [AbstractKeyExchanger] 27 Mar 2014 23:11:28.857 : Sending SSH_MSG_KEXINIT
DEBUG [AbstractKeyExchanger] 27 Mar 2014 23:11:28.866 : key exchange method=diffie-hellman-group1-sha1,diffie-hellman-group14-sha1
DEBUG [AbstractKeyExchanger] 27 Mar 2014 23:11:28.869 : hostkey algorithms=ssh-dss,ssh-rsa
DEBUG [AbstractKeyExchanger] 27 Mar 2014 23:11:28.873 : ciphers=blowfish-cbc,aes128-cbc,aes192-cbc,aes256-cbc,3des-cbc,aes128-ctr,aes192-ctr,aes256-ctr
DEBUG [AbstractKeyExchanger] 27 Mar 2014 23:11:28.873 : ciphers=blowfish-cbc,aes128-cbc,aes192-cbc,aes256-cbc,3des-cbc,aes128-ctr,aes192-ctr,aes256-ctr
DEBUG [AbstractKeyExchanger] 27 Mar 2014 23:11:28.875 : MACs=hmac-sha1,hmac-md5
DEBUG [AbstractKeyExchanger] 27 Mar 2014 23:11:28.875 : MACs=hmac-sha1,hmac-md5
DEBUG [AbstractKeyExchanger] 27 Mar 2014 23:11:28.879 : compression algorithms=none,zlib
DEBUG [AbstractKeyExchanger] 27 Mar 2014 23:11:28.879 : compression algorithms=none,zlib
DEBUG [AbstractKeyExchanger] 27 Mar 2014 23:11:28.886 : Sent SSH_MSG_KEXINIT
DEBUG [ClientKeyExchanger] 27 Mar 2014 23:11:28.886 : Reading SSH_MSG_KEXINIT reply
DEBUG [SSH2Connection] 27 Mar 2014 23:11:28.890 : Waiting for packet
DEBUG [PlainSocket] 27 Mar 2014 23:11:28.985 : FTPConnection.1RepeatCallback received 336 bytes
DEBUG [SSH2Connection] 27 Mar 2014 23:11:28.993 : Packet arrived
DEBUG [AbstractKeyExchanger] 27 Mar 2014 23:11:28.997 : Processing SSH_MSG_KEXINIT reply
DEBUG [AbstractKeyExchanger] 27 Mar 2014 23:11:28.999 : Remote kex alg=diffie-hellman-group1-sha1,diffie-hellman-group14-sha1,diffie-hellman-group-exchange-sha1,diffie-hellman-group-exchange-sha256
DEBUG [AbstractKeyExchanger] 27 Mar 2014 23:11:29.001 : Decided kex alg= DiffieHellmanGroup1Sha1
DEBUG [AbstractKeyExchanger] 27 Mar 2014 23:11:29.001 : Remote hostkey alg=ssh-dss,ssh-rsa
DEBUG [AbstractKeyExchanger] 27 Mar 2014 23:11:29.002 : Decided hostkey alg= DSA
DEBUG [ClientKeyExchanger] 27 Mar 2014 23:11:29.005 : Remote Cipher CS=aes256-cbc,aes192-cbc,aes128-cbc,3des-cbc
DEBUG [ClientKeyExchanger] 27 Mar 2014 23:11:29.006 : Decided Cipher C->S= AES128
DEBUG [ClientKeyExchanger] 27 Mar 2014 23:11:29.006 : Remote Cipher SC=aes256-cbc,aes192-cbc,aes128-cbc,3des-cbc
DEBUG [ClientKeyExchanger] 27 Mar 2014 23:11:29.006 : Decided Cipher S->C= AES128
DEBUG [ClientKeyExchanger] 27 Mar 2014 23:11:29.006 : Remote MAC CS=hmac-sha1
DEBUG [ClientKeyExchanger] 27 Mar 2014 23:11:29.007 : Decided MAC C->S= HMACSHA1
DEBUG [ClientKeyExchanger] 27 Mar 2014 23:11:29.007 : Remote MAC SC=hmac-sha1
DEBUG [ClientKeyExchanger] 27 Mar 2014 23:11:29.007 : Decided MAC S->C= HMACSHA1
DEBUG [ClientKeyExchanger] 27 Mar 2014 23:11:29.007 : Remote Comp CS=none,zlib
DEBUG [ClientKeyExchanger] 27 Mar 2014 23:11:29.008 : Decided Comp C->S=None
DEBUG [ClientKeyExchanger] 27 Mar 2014 23:11:29.008 : Remote Comp SC=none,zlib
DEBUG [ClientKeyExchanger] 27 Mar 2014 23:11:29.008 : Decided Comp S->C=None
DEBUG [ClientKeyExchanger] 27 Mar 2014 23:11:29.008 : first_kex_packet_follows=False
DEBUG [AbstractKeyExchanger] 27 Mar 2014 23:11:29.008 : Processed SSH_MSG_KEXINIT reply
DEBUG [ClientKeyExchanger] 27 Mar 2014 23:11:29.009 : Sending SSH_MSG_KEXDH_INIT
DEBUG [AbstractKeyExchanger] 27 Mar 2014 23:11:29.010 : DH_PRIME_GROUP1
DEBUG [AbstractKeyExchanger] 27 Mar 2014 23:11:29.029 : DH_PRIME_GROUP1
DEBUG [ClientKeyExchanger] 27 Mar 2014 23:11:29.071 : Sent SSH_MSG_KEXDH_INIT
DEBUG [ClientKeyExchanger] 27 Mar 2014 23:11:29.071 : Reading SSH_MSG_KEXDH_INIT reply
DEBUG [SSH2Connection] 27 Mar 2014 23:11:29.071 : Waiting for packet
DEBUG [PlainSocket] 27 Mar 2014 23:11:29.238 : FTPConnection.1RepeatCallback received 56 bytes
DEBUG [SSH2Connection] 27 Mar 2014 23:11:29.238 : Packet arrived
DEBUG [PlainSocket] 27 Mar 2014 23:11:29.239 : FTPConnection.1RepeatCallback received 0 bytes
DEBUG [ClientKeyExchanger] 27 Mar 2014 23:11:29.243 : Processing SSH_MSG_KEXDH_INIT reply
ERROR [SSHFTPClient] 27 Mar 2014 23:11:29.314 : Failed to connect - closing connection
ERROR [SSHFTPClient] 27 Mar 2014 23:11:29.314 : EnterpriseDT.Net.Ftp.Ssh.SFTPException: KeyExchange response is not KEXDH_REPLY but SSH_MSG_DISCONNECT
ERROR [SSHFTPClient] 27 Mar 2014 23:11:29.314 : at EnterpriseDT.Net.Ftp.Ssh.SSHFTPClient.Connect()

Answer 1

The server disconnected you. Try changing the preferred host key algorithm to RSA for starters.

Passive/active mode is not used for SFTP.

Answer 2

Thank you for the prompt response. Two things:

- Setting PreferredHostKeyAlgorithms to AllPreferRSA indeed solved the problem. But we are really qurious as to why the server closes the connection upon attempting to negotiate the fallback from DSA to RSA (which if we are not mistaken is the default behaviour for edtFTPnet when it comes to host key algorithms).

- Moreover, is it conceivable that there are SFTP servers out there with the opposite pet peeve that this SFTP server has? (that is when we try to negotiate RSA and then DSA we will end up having the connection getting closed again). Why would an SFTP server do that anyways? Is it a security feature?

Answer 3

One more thing:

We are attempting to connect using FTP + TLS (implicit) however when we attempt to get a listing of the folders we get:

ftpConnection.GetFileInfos(): PORT IP is not same as 192.168.5.24. (code=501)

Here are the logs:

DEBUG [SFTPMessageStore] 28 Mar 2014 21:02:13.144 : Set timeout=10000
INFO [LicenseProperties] 28 Mar 2014 21:02:13.171 : Licence expiry date: 31/12/9999
INFO [LicenseProperties] 28 Mar 2014 21:02:13.171 : Production license
DEBUG [FTPConnection] 28 Mar 2014 21:02:13.175 : Set LocalDirectory='C:\Users\Dominick\Documents\Visual Studio 2010\Projects\WinAutomation\trunk\bin\Debug'
DEBUG [SecureFTPConnection] 28 Mar 2014 21:02:13.177 : Set LocalDirectory to C:\Users\Dominick\Documents\Visual Studio 2010\Projects\WinAutomation\trunk\bin\Debug
INFO [LicenseProperties] 28 Mar 2014 21:02:13.180 : Licence expiry date: 31/12/9999
INFO [LicenseProperties] 28 Mar 2014 21:02:13.181 : Production license
DEBUG [SSLFTPClient] 28 Mar 2014 21:02:13.181 : Connecting to portal.conformis.com:990
DEBUG [SSLFTPControlSocket] 28 Mar 2014 21:02:13.183 : waitOnShutdownSSL=True
DEBUG [HostNameResolver] 28 Mar 2014 21:02:13.418 : Resolving portal.conformis.com
DEBUG [HostNameResolver] 28 Mar 2014 21:02:13.457 : Obtained 1 addresses
DEBUG [HostNameResolver] 28 Mar 2014 21:02:13.462 : IP address: 209.104.242.15
DEBUG [HostNameResolver] 28 Mar 2014 21:02:13.462 : portal.conformis.com resolved to 209.104.242.15
DEBUG [ExFTPControlSocket] 28 Mar 2014 21:02:13.462 : Connecting directly to ftp-server portal.conformis.com:990
INFO [SSLFTPSocket] 28 Mar 2014 21:02:13.465 : Connecting to 209.104.242.15:990 with timeout 10000 ms
DEBUG [SSLFTPControlSocket] 28 Mar 2014 21:02:13.674 : Beginning Tls1 handshake.
DEBUG [SocketController] 28 Mar 2014 21:02:13.945 : FTPConnection.1Processing hello
DEBUG [SecureSocket] 28 Mar 2014 21:02:14.238 : FTPConnection.1OnHandshakeComplete(True,null)
DEBUG [SSLFTPControlSocket] 28 Mar 2014 21:02:14.238 : Tls1 handshake complete.
DEBUG [FTPControlSocket] 28 Mar 2014 21:02:14.239 : Setting socket timeout=10000
ALL [TransferBuffer] 28 Mar 2014 21:02:14.242 : TransferBuffer timeout=10000
ALL [SocketController] 28 Mar 2014 21:02:14.242 : SocketController timeout=10000
ALL [SecureSocket] 28 Mar 2014 21:02:14.242 : SecureSocket timeout=10000
ALL [TransferBuffer] 28 Mar 2014 21:02:14.242 : TransferBuffer timeout=10000
ALL [SocketController] 28 Mar 2014 21:02:14.242 : SocketController timeout=10000
ALL [SecureSocket] 28 Mar 2014 21:02:14.242 : SecureSocket timeout=10000
INFO [FTPControlSocket] 28 Mar 2014 21:02:14.246 : Command encoding=System.Text.UTF8Encoding
DEBUG [ExFTPControlSocket] 28 Mar 2014 21:02:14.247 : Created control-socket: SocksContext=, ProxySettings=NoProxy, RemoteHost=portal.conformis.com, controlPort=990, timeout=10000
DEBUG [FTPControlSocket] 28 Mar 2014 21:02:14.252 : StrictReturnCodes=False
ALL [AsyncResult] 28 Mar 2014 21:02:14.265 : Notify setting completed: null 0
ALL [AsyncResult] 28 Mar 2014 21:02:14.265 : Notify setting wait: 0
DEBUG [FTPControlSocket] 28 Mar 2014 21:02:14.272 : 220 Connected to the Conformis Portal - FTPS Server
DEBUG [FTPControlSocket] 28 Mar 2014 21:02:14.281 : ---> PBSZ 0
ALL [AsyncResult] 28 Mar 2014 21:02:14.286 : FTPConnection.1Notify setting completed: null 1
ALL [AsyncResult] 28 Mar 2014 21:02:14.286 : FTPConnection.1Notify setting wait: 1
ALL [SocketController] 28 Mar 2014 21:02:14.289 : FTPConnection.1WaitUntilCompleted(1, EndSend)
ALL [TransferBuffer] 28 Mar 2014 21:02:14.291 : FTPConnection.1Wait begin: TransferBuffer.Read (timeout=10000)
ALL [AsyncResult] 28 Mar 2014 21:02:14.443 : FTPConnection.1Notify setting completed: null 2
ALL [TransferBuffer] 28 Mar 2014 21:02:14.443 : FTPConnection.1Wait end: TransferBuffer.Read
DEBUG [FTPControlSocket] 28 Mar 2014 21:02:14.443 : FTPConnection.1200 Command PBSZ okay.
ALL [AsyncResult] 28 Mar 2014 21:02:14.443 : FTPConnection.1Notify setting wait: 2
DEBUG [FTPControlSocket] 28 Mar 2014 21:02:14.444 : FTPConnection.1---> PROT P
ALL [SocketController] 28 Mar 2014 21:02:14.445 : FTPConnection.1WaitUntilCompleted(3, EndSend)
ALL [AsyncResult] 28 Mar 2014 21:02:14.445 : FTPConnection.1Notify setting completed: null 3
ALL [AsyncResult] 28 Mar 2014 21:02:14.445 : FTPConnection.1Notify setting wait: 3
ALL [AsyncResult] 28 Mar 2014 21:02:14.447 : FTPConnection.1WaitOne completed: 3
ALL [TransferBuffer] 28 Mar 2014 21:02:14.447 : FTPConnection.1Wait begin: TransferBuffer.Read (timeout=10000)
ALL [AsyncResult] 28 Mar 2014 21:02:14.600 : FTPConnection.1Notify setting completed: null 4
ALL [AsyncResult] 28 Mar 2014 21:02:14.601 : FTPConnection.1Notify setting wait: 4
ALL [TransferBuffer] 28 Mar 2014 21:02:14.600 : FTPConnection.1Wait end: TransferBuffer.Read
DEBUG [FTPControlSocket] 28 Mar 2014 21:02:14.601 : FTPConnection.1200 Command PROT okay.
DEBUG [ExFTPConnection] 28 Mar 2014 21:02:14.620 : Starting KeepAlive thread with period 30s
DEBUG [FTPControlSocket] 28 Mar 2014 21:02:14.624 : FTPConnection.1---> USER PPDGroup
ALL [SocketController] 28 Mar 2014 21:02:14.625 : FTPConnection.1WaitUntilCompleted(5, EndSend)
ALL [AsyncResult] 28 Mar 2014 21:02:14.625 : FTPConnection.1WaitOne begin: 200 5
ALL [AsyncResult] 28 Mar 2014 21:02:14.625 : FTPConnection.1Notify setting completed: null 5
ALL [AsyncResult] 28 Mar 2014 21:02:14.625 : FTPConnection.1Notify setting wait: 5
ALL [AsyncResult] 28 Mar 2014 21:02:14.625 : FTPConnection.1WaitOne end: True 5
ALL [TransferBuffer] 28 Mar 2014 21:02:14.625 : FTPConnection.1Wait begin: TransferBuffer.Read (timeout=10000)
ALL [AsyncResult] 28 Mar 2014 21:02:14.780 : FTPConnection.1Notify setting completed: null 6
ALL [TransferBuffer] 28 Mar 2014 21:02:14.780 : FTPConnection.1Wait end: TransferBuffer.Read
DEBUG [FTPControlSocket] 28 Mar 2014 21:02:14.780 : FTPConnection.1331 User name okay, need password for PPDGroup.
ALL [AsyncResult] 28 Mar 2014 21:02:14.780 : FTPConnection.1Notify setting wait: 6
DEBUG [FTPControlSocket] 28 Mar 2014 21:02:14.781 : FTPConnection.1---> PASS ********
ALL [SocketController] 28 Mar 2014 21:02:14.781 : FTPConnection.1WaitUntilCompleted(7, EndSend)
ALL [AsyncResult] 28 Mar 2014 21:02:14.781 : FTPConnection.1WaitOne begin: 200 7
ALL [AsyncResult] 28 Mar 2014 21:02:14.781 : FTPConnection.1Notify setting completed: null 7
ALL [AsyncResult] 28 Mar 2014 21:02:14.782 : FTPConnection.1Notify setting wait: 7
ALL [AsyncResult] 28 Mar 2014 21:02:14.782 : FTPConnection.1WaitOne end: True 7
ALL [TransferBuffer] 28 Mar 2014 21:02:14.782 : FTPConnection.1Wait begin: TransferBuffer.Read (timeout=10000)
ALL [AsyncResult] 28 Mar 2014 21:02:14.945 : FTPConnection.1Notify setting completed: null 8
ALL [AsyncResult] 28 Mar 2014 21:02:14.945 : FTPConnection.1Notify setting wait: 8
ALL [TransferBuffer] 28 Mar 2014 21:02:14.945 : FTPConnection.1Wait end: TransferBuffer.Read
DEBUG [FTPControlSocket] 28 Mar 2014 21:02:14.945 : FTPConnection.1230 User logged in, proceed.
DEBUG [FTPConnection] 28 Mar 2014 21:02:15.083 : FTPConnection.1ChangeWorkingDirectory('/')
DEBUG [FTPControlSocket] 28 Mar 2014 21:02:15.091 : FTPConnection.1---> CWD /
ALL [SocketController] 28 Mar 2014 21:02:15.092 : FTPConnection.1WaitUntilCompleted(9, EndSend)
ALL [AsyncResult] 28 Mar 2014 21:02:15.092 : FTPConnection.1WaitOne begin: 200 9
ALL [AsyncResult] 28 Mar 2014 21:02:15.092 : FTPConnection.1Notify setting completed: null 9
ALL [AsyncResult] 28 Mar 2014 21:02:15.092 : FTPConnection.1Notify setting wai

Answer 4

This is a bug in the server - it shouldn't offer the DSA algorithm for negotiation with the client if it isn't prepared to use it. There is no fallback from RSA to DSA. It is possible you'll encounter servers that do the opposite (again buggy).

The problem in your second post is this. The server sees your IP as 192.168.5.24. But in the PORT command you are sending 192.168.0.22 (a different interface). You need to set the PublicIPAddress (used in the PORT command) to 192.168.5.24.