We have a customer who is having an intermittent error connecting to an SFTP server. They periodically receive "Protocol negotiation timeout ". Here is the log snippet from the failed attempt:
DEBUG [SSHSCPClient] 12 Jan 2019 07:18:28.203 : FTPConnection.8 Connecting directly to SFTP server x.y.z.w:22
INFO [BaseSocket] 12 Jan 2019 07:18:28.203 : FTPConnection.8 Connecting to x.y.z.w:22 with timeout 120000 ms
DEBUG [BaseSocket] 12 Jan 2019 07:18:28.250 : FTPConnection.8 Successfully connected to x.y.z.w:22
DEBUG [SSHSCPClient] 12 Jan 2019 07:18:28.250 : FTPConnection.8 Connected successfully to SFTP server x.y.z.w:22
DEBUG [SSHConnection] 12 Jan 2019 07:18:28.250 : FTPConnection.8 Beginning protocol negotiation
ERROR [SSHConnection] 12 Jan 2019 07:20:28.261 : FTPConnection.8 Protocol negotiation timeout
ERROR [SSHFTPClient] 12 Jan 2019 07:20:28.261 : FTPConnection.8 Failed to connect - closing connection
ERROR [SSHFTPClient] 12 Jan 2019 07:20:28.261 : FTPConnection.8 EnterpriseDT.Net.Ftp.Ssh.SFTPException: Protocol negotiation timeout
ERROR [SSHFTPClient] 12 Jan 2019 07:20:28.261 : FTPConnection.8 at EnterpriseDT.Net.Ftp.Ssh.SSHFTPClient.Connect()
INFO [FTPConnection] 12 Jan 2019 07:20:28.261 : FTPConnection.8 OS: 6.1.7601.65536, CLR: 4.0.30319.42000, DLL: 9.1.3.20
INFO [FTPConnection] 12 Jan 2019 07:20:28.261 : FTPConnection.8 Built: 26-Oct-2017 21:06:13 BST
Here is the log snippet from a successful connection:
DEBUG [SSHSCPClient] 12 Jan 2019 07:20:32.956 : Connecting directly to SFTP server x.y.z.w:22
INFO [BaseSocket] 12 Jan 2019 07:20:32.956 : Connecting to x.y.z.w:22 with timeout 120000 ms
DEBUG [BaseSocket] 12 Jan 2019 07:20:33.003 : Successfully connected to x.y.z.w:22
DEBUG [SSHSCPClient] 12 Jan 2019 07:20:33.034 : Connected successfully to SFTP server x.y.z.w:22
DEBUG [SSHConnection] 12 Jan 2019 07:20:33.034 : Beginning protocol negotiation
DEBUG [PlainSocket] 12 Jan 2019 07:20:33.050 : FTPConnection.16 RepeatCallback received 23 bytes
DEBUG [ProtocolNegotiationHandler] 12 Jan 2019 07:20:33.050 : FTPConnection.16 offset=0,length=23
INFO [ProtocolNegotiationHandler] 12 Jan 2019 07:20:33.050 : FTPConnection.16 Server version = 'SSH-2.0-Maverick_SSHD'
DEBUG [SSHUtil] 12 Jan 2019 07:20:33.050 : FTPConnection.16 Major string = '2'
DEBUG [SSHUtil] 12 Jan 2019 07:20:33.050 : FTPConnection.16 Minor string = '0'
DEBUG [SSHUtil] 12 Jan 2019 07:20:33.050 : FTPConnection.16 Version 2.0
DEBUG [SSHUtil] 12 Jan 2019 07:20:33.050 : FTPConnection.16 Protocol compatible
DEBUG [SSHConnection] 12 Jan 2019 07:20:33.050 : Server version=SSH-2.0-Maverick_SSHD
DEBUG [SSH2Connection] 12 Jan 2019 07:20:33.050 : Timeout=120000
DEBUG [SSHConnection] 12 Jan 2019 07:20:33.050 : Sending client version=SSH-2.0-edtFTPnet/PRO_9.1.3.20
DEBUG [SSH2Connection] 12 Jan 2019 07:20:33.050 : Starting key exchange
The customer says using WinSCP they always get the connection to work when they uncheck "Optimize connection buffer size". Per the WinSCP docs: "The Optimize connection buffer size enables optimization of socket buffer size. It greatly improves transfer speed. Disable it only when experiencing problems."
Any suggestions for diagnosing/fixing this issue with edtFTPnet/PRO?
- Paul -
